Log4j logging twice with different formats

Question

I can't figure out why log4j is appending twice with different formats. Anyone come across this before?

Here is my log4j.xml file:

<log4j:configuration>

    <appender name="async" class="org.apache.log4j.AsyncAppender">
    <!-- this parameter need to be set to false to avoid application from hanging. -->
        <param name="Blocking" value="false" />
        <appender-ref ref="myAppender" />
    </appender>

    <appender name="myAppender" class="org.apache.log4j.ConsoleAppender">
        <param name="Threshold" value="INFO" />
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%-5p %d{ISO8601} [%t] %c %x - %m%n" />
        </layout>
    </appender>

    <logger name="com.server">
        <level value="INFO" />
    </logger>

    <logger name="org.springframework">
        <level value="INFO" />
    </logger>

    <logger name="org.hibernate.LazyInitializationException" additivity="false">
       <level value="off" />
       <appender-ref ref="async" />
    </logger>

    <logger name="net.sf.ehcache">
        <level value="INFO" />
    </logger>

     <logger name="com.mchange">
         <level value="INFO" />
     </logger>

     <root>
         <priority value="INFO" />
         <appender-ref ref="async" />
     </root>

</log4j:configuration>

And here is some sample output:

INFO  2016-08-26 11:01:38,353 [main] com.server.Server  - Server started successfully...
11:01:38,353 INFO :  Server started successfully...

EDIT: When I change the "myAppender" appender threshold to "ERROR", the second log message shown (The one starting with the time, not "INFO") is still being generated. Is there some default logger that I need to disable? It seems that something is still logging those "INFO" level messages, even though the specified appender is for "ERROR" level messages. Also, if I comment out the entire log4j.xml file, the second log message (and all like it) are still being logged. How can I prevent this? Thanks!

Answer 1

I am not familiar with XML syntax of log4j (I use log4j.properties for configuration) so here are my 2 cents to try to help you debug and fix the code.

Firstly try using below root logger configuration instead of yours <appender-ref ref="async" /> -

<logger name="org.hibernate.LazyInitializationException" additivity="false">
   <level value="off" />
   <appender-ref ref="myAppender" />
</logger>
..............
...........
 <root>
     <priority value="INFO" />
     <appender-ref ref="myAppender" />
 </root>

If above doesn't work then, try putting <param name="Threshold" value="ERROR" /> both in async and myAppender, and I guess no Server started successfully log will be printed (I think you have already tried with myAppender)

If this helps then it means the way you are trying to reference/inherit the logger isn't working or using correctly, so you have think from that direction and correct the issue, you need to read more about appender-ref element and AsyncAppender logger.

Whether above works or not, I am guessing that you are trying to achieve following -

1. Print on your standard input/output i.e. your terminal window
2. Print in file as well for prod environment

I would do this in log4j.properties as follow:

log4j.logger.com.sks.cs50=DEBUG, CS50GlobalFileAppender, stdout

#####CS50 Web log##########
log4j.appender.CS50GlobalFileAppender=org.apache.log4j.RollingFileAppender
log4j.appender.CS50GlobalFileAppender.File=${logDir}cs50.log
log4j.appender.CS50GlobalFileAppender.MaxBackupIndex=50
log4j.appender.CS50GlobalFileAppender.Threshold=DEBUG
log4j.appender.CS50GlobalFileAppender.layout=org.apache.log4j.PatternLayout
log4j.appender.CS50GlobalFileAppender.layout.ConversionPattern=%C %d [%t] [%X{randomNumber}] %-5p - %m%n
log4j.appender.CS50GlobalFileAppender.MaxFileSize=500000KB

# Log format to standard output
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.target=System.out
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d [%X{randomNumber}] %-5p - %m%n

log4j.logger.org.apache = INFO
log4j.logger.com.sun = INFO
log4j.logger.sun = INFO
log4j.logger.javax.xml.bind = INFO
log4j.logger.org.springframework = INFO
log4j.logger.com.cgi = DEBUG

So, I guess you can do something as below.

<log4j:configuration>

    <appender name="async" class="org.apache.log4j.AsyncAppender">
    <!-- this parameter need to be set to false to avoid application from hanging. -->
        <param name="Blocking" value="false" />
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%-5p %d{ISO8601} [%t] %c %x - %m%n" />
        </layout>
    </appender>

    <appender name="myAppender" class="org.apache.log4j.ConsoleAppender">
        <param name="Threshold" value="INFO" />
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%-5p %d{ISO8601} [%t] %c %x - %m%n" />
        </layout>
    </appender>

    <logger name="com.server">
        <level value="INFO" />
    </logger>

    <logger name="org.springframework">
        <level value="INFO" />
    </logger>

    <logger name="org.hibernate.LazyInitializationException" additivity="false">
       <level value="off" />
       <appender-ref ref="async" />
    </logger>

    <logger name="net.sf.ehcache">
        <level value="INFO" />
    </logger>

     <logger name="com.mchange">
         <level value="INFO" />
     </logger>

     <root>
         <priority value="INFO" />
         <appender-ref ref="async" />
         <appender-ref ref="myAppender" />
     </root>

</log4j:configuration>

Please note that above XML configuration is with assumption that org.apache.log4j.AsyncAppender prints in some log file, but if it doesn't (which I am guessing that it doesn't) then above will not work (you can still use above XML configuration to achieve file + console logging if you replace AsyncAppender with a org.apache.log4j.RollingFileAppender) and I would wonder why you are just can't use org.apache.log4j.AsyncAppender directly because it already prints to console, so may be just use:

<appender name="async" class="org.apache.log4j.AsyncAppender">
<!-- this parameter need to be set to false to avoid application from hanging. -->
    <param name="Blocking" value="false" />
    <layout class="org.apache.log4j.PatternLayout">
        <param name="ConversionPattern" value="%-5p %d{ISO8601} [%t] %c %x - %m%n" />
    </layout>
</appender>