Duplicate log4j Logging

Question

I have the following log4j.xml file in my classpath:

<appender class="org.apache.log4j.ConsoleAppender" name="Console">
    <param name="Threshold" value="info" />
    <layout class="org.apache.log4j.PatternLayout">
        <param value="%d %-5p [%t] %C (%F:%L) - %m%n" name="ConversionPattern"/>
    </layout>
    <filter class="org.apache.log4j.varia.LevelRangeFilter">
      <param value="info" name="LevelMax"/>
      <param value="info" name="LevelMin"/>
    </filter>
</appender>

<logger name="de.scm.cci.importer">
    <level value="info"/>
</logger>

<logger name="com.mchange">
    <level value="info"/>
</logger>
<logger name="jdbc">
    <level value="error"/>
</logger>
<logger name="org.hibernate">
    <level value="info"/>
</logger>
<logger name="org.springframework">
    <level value="info"/>
</logger>

<root>
    <level value="INFO"/>
    <appender-ref ref="Console"/>
</root>

Here are the first few lines of output:

log4j: Trying to find [log4j.xml] using context classloader sun.misc.Launcher$AppClassLoader@7220722.
log4j: Using URL [file:/opt/app/cci/CCIImporter/jar/log4j.xml] for automatic log4j configuration.
log4j: Preferred configurator class: org.apache.log4j.xml.DOMConfigurator
log4j: System property is :null
log4j: Standard DocumentBuilderFactory search succeded.
log4j: DocumentBuilderFactory is: org.apache.xerces.jaxp.DocumentBuilderFactoryImpl
log4j: debug attribute= "true".
log4j: reset attribute= "false".
log4j: Threshold ="null".
log4j: Retreiving an instance of org.apache.log4j.Logger.
log4j: Setting [de.scm.cci.importer] additivity to [true].
log4j: Level value for de.scm.cci.importer is  [info].
log4j: de.scm.cci.importer level set to INFO
log4j: Retreiving an instance of org.apache.log4j.Logger.
log4j: Setting [com.mchange] additivity to [true].
log4j: Level value for com.mchange is  [info].
log4j: com.mchange level set to INFO
log4j: Retreiving an instance of org.apache.log4j.Logger.
log4j: Setting [jdbc] additivity to [true].
log4j: Level value for jdbc is  [error].
log4j: jdbc level set to ERROR
log4j: Retreiving an instance of org.apache.log4j.Logger.
log4j: Setting [org.hibernate] additivity to [true].
log4j: Level value for org.hibernate is  [info].
log4j: org.hibernate level set to INFO
log4j: Retreiving an instance of org.apache.log4j.Logger.
log4j: Setting [org.springframework] additivity to [true].
log4j: Level value for org.springframework is  [info].
log4j: org.springframework level set to INFO
log4j: Level value for root is  [INFO].
log4j: root level set to INFO
log4j: Class name: [org.apache.log4j.ConsoleAppender]
log4j: Setting property [threshold] to [INFO].
log4j: Parsing layout of class: "org.apache.log4j.PatternLayout"
log4j: Setting property [conversionPattern] to [%d %-5p [%t] %C (%F:%L) - %m%n].
log4j: Setting property [levelMax] to [INFO].
log4j: Setting property [levelMin] to [INFO].
log4j: Adding filter of type [class org.apache.log4j.varia.LevelRangeFilter] to appender named [Console].
log4j: Adding appender named [Console] to category [root].
2014-02-25 13:20:25,534 INFO  [main] de.scm.cci.importer.RunTest (RunTest.java:21) - Starting loop mode
2014-02-25 13:20:25,537 INFO  [main] de.scm.cci.importer.RunTest (RunTest.java:24) - Started...
PERSISTENCE LOADING
2014-02-25 13:20:25,767 INFO  [main] org.springframework.context.support.AbstractApplicationContext (AbstractApplicationContext.java:513) - Refreshing org.springframework.context.support.ClassPathXmlApplicationContext@52545254: startup date [Tue Feb 25 13:20:25 CET 2014]; root of context hierarchy
233 [main] INFO org.springframework.context.support.ClassPathXmlApplicationContext  - Refreshing org.springframework.context.support.ClassPathXmlApplicationContext@52545254: startup date [Tue Feb 25 13:20:25 CET 2014]; root of context hierarchy
2014-02-25 13:20:25,877 INFO  [main] org.springframework.beans.factory.xml.XmlBeanDefinitionReader (XmlBeanDefinitionReader.java:316) - Loading XML bean definitions from class path resource [de/scm/cci/backend/public/spring-config.xml]

As soon as spring starts loading, each line of the output is being doubled:

2014-02-25 13:20:25,767 INFO  [main] org.springframework.context.support.AbstractApplicationContext (AbstractApplicationContext.java:513) - Refreshing org.springframework.context.support.ClassPathXmlApplicationContext@52545254: startup date [Tue Feb 25 13:20:25 CET 2014]; root of context hierarchy
233 [main] INFO org.springframework.context.support.ClassPathXmlApplicationContext  - Refreshing org.springframework.context.support.ClassPathXmlApplicationContext@52545254: startup date [Tue Feb 25 13:20:25 CET 2014]; root of context hierarchy

I am totally clueless, where the second line comes from.

EDIT: Weird enough: I am getting WARN Messages despite the fact i set all possible threasholds and stuffs to INFO only...?

Answer 1

Because you only have one appender declared, and the formats of the duplicated logs are not the same, it seems clear that you have multiple logging frameworks going at the same time:

• log4j in your own code
• commons-logging inside of Spring

What you need to do is:

• Remove the commons-logging dependency from your classpath. If you are using maven, you have to exclude the commons-logging jar from every Spring module.
• Add jcl-over-slf4j to your classpath

Maven example (how to remove commons-logging): Note: You need this exclusion syntax in every single Spring dependency

<dependency>
  <groupId>org.springframework</groupId>
  <artifactId>spring-web</artifactId>
  <version>${spring.version}</version>
  <exclusions>
    <exclusion>
      <artifactId>commons-logging</artifactId>
      <groupId>commons-logging</groupId>
    </exclusion>
  </exclusions>
</dependency>

Maven example (how to add slf4j, you may already be doing this):

<dependency>
  <groupId>org.slf4j</groupId>
  <artifactId>slf4j-api</artifactId>
  <version>1.7.7</version>
</dependency>

<dependency>
  <groupId>org.slf4j</groupId>
  <artifactId>jcl-over-slf4j</artifactId>
  <version>1.7.7</version>
</dependency>

If you are not using Maven, let me know and I'll try to help with your specific environment.