Log4j logging twice with different formats

10
votes

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!

6
javalog4j
I think that's because you are using 2 appenders for the same thing. Try commenting out the "async" appender and change root child to <appender-ref ref="myAppender" /> – Federico Piazza
Doesn't help, same duplicated output is generated – holtc
try commenting out the full logger with name="org.hibernate.LazyInitializationException" – Federico Piazza
Same problem happening – holtc
hum, then I would recommend you to comment out all the loggers and appenders and add one by one from the root – Federico Piazza

6 Answers

5
votes

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>
2
votes

why Log4j logging twice?

  • Log4j logs to all loggers in the hierarchy unless you ask it not to ( by setting additivity to false ), so you are seeing output from your com.server logger and the default ROOT logger which always exists.

solution for above problem

  • This is happening, because you have not defined the additivity="false" attribute on your com.server logger. now i fixed it, you can try.

    <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" additivity="false">
    <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>

1
votes

My guess is that somewhere in your application another appender is added programmatically, maybe like this:

package de.scrum_master.app;

import java.io.OutputStreamWriter;

import org.apache.log4j.ConsoleAppender;
import org.apache.log4j.Logger;
import org.apache.log4j.PatternLayout;

public class Application {
    private static Logger log = Logger.getLogger(Application.class);

    public static void main(String[] args) throws InterruptedException {
        //log.setAdditivity(false);
        ConsoleAppender ca = new ConsoleAppender();
        ca.setWriter(new OutputStreamWriter(System.out));
        ca.setLayout(new PatternLayout("%-5p [%t]: %m%n"));
        log.addAppender(ca);
        log.info("Hello world");
        log.info("Bye world");
        Thread.sleep(1000);
    }
}

This in addition to a log4j.xml or log4j.properties file found on the classpath causes the effect you see in your logs.

Update: Or maybe even something like Logger.getRootLogger().addAppender(ca) gets called, affecting the root logger and not just a sepecific one.

Using your config file for me this yields the following log output:

INFO  [main]: Hello world
INFO  [main]: Bye world
INFO  2016-09-04 13:48:25,887 [main] de.scrum_master.app.Application  - Hello world
INFO  2016-09-04 13:48:25,889 [main] de.scrum_master.app.Application  - Bye world
1
votes

There have been some answers already so I just went ahead and created a program to prove that this indeed works unless there is some problem in your code - See my two simple classes below and try to find out the difference between these and yours.

import org.apache.log4j.xml.DOMConfigurator;

import com.server.Test;

public class MyListener {
public static void main(String[] args) {

    DOMConfigurator.configure("/home/sanjeevd/depot/bas/projects/xxx.1/yyy/src/log4j.xml");

    Test test = new Test();
}

}

package com.server;

import org.apache.log4j.Logger;

public class Test {

private static Logger logger = Logger.getLogger(Test.class);

public Test() {
    logger.info("PRINTTTTTTTTTTTT");
}

}

Also add these two lines on the top of your log4j.xml -

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

Having said this, I'm mostly sure that there is some other logger getting initialized or there are more than one lo4j.xml in your application etc. Please note, I didn't change anything in your log4j.xml other than adding headers.

The output is below (and it prints just onces) -

INFO  2016-09-06 10:57:37,506 [main] com.server.Test  - PRINTTTTTTTTTTTT

Another thing you should do is to set "system property" for bootstrap debugging to see what's going on at log4j level i.e. put 

System.setProperty("log4j.debug", "true");

just before configuring log4j. If you are deploying it onto some servlet container (tomcat etc) then pass -Dlog4j.debug=true parameter during startup.

The output in my case was - 

log4j: Trying to find [log4j.xml] using context classloader   sun.misc.Launcher$AppClassLoader@42a57993.
log4j: Using URL [file:/home/sanjeevd/depot/bas/projects/xxx.1/yyy/bin/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: com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl
log4j: debug attribute= "null".
log4j: Ignoring debug attribute.
log4j: reset attribute= "false".
log4j: Threshold ="null".
log4j: Retreiving an instance of org.apache.log4j.Logger.
log4j: Setting [com.server] additivity to [true].
log4j: Level value for com.server is  [INFO].
log4j: com.server 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: Retreiving an instance of org.apache.log4j.Logger.
log4j: Setting [org.hibernate.LazyInitializationException] additivity to [false].
log4j: Level value for org.hibernate.LazyInitializationException is  [off].
log4j: org.hibernate.LazyInitializationException level set to OFF
log4j: Class name: [org.apache.log4j.AsyncAppender]
log4j: Attaching appender named [myAppender] to appender named [async].
log4j: Class name: [org.apache.log4j.ConsoleAppender]
log4j: Setting property [threshold] to [INFO].
log4j: Setting property [target] to [System.out].
log4j: Parsing layout of class: "org.apache.log4j.PatternLayout"
log4j: Setting property [conversionPattern] to [%-5p %d{ISO8601} [%t] %c %x - %m%n].
log4j: Adding appender named [async] to category [org.hibernate.LazyInitializationException].
log4j: Retreiving an instance of org.apache.log4j.Logger.
log4j: Setting [net.sf.ehcache] additivity to [true].
log4j: Level value for net.sf.ehcache is  [INFO].
log4j: net.sf.ehcache 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: Level value for root is  [INFO].
log4j: root level set to INFO
log4j: Adding appender named [async] to category [root].
log4j: System property is :null
log4j: Standard DocumentBuilderFactory search succeded.
log4j: DocumentBuilderFactory is: com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl
log4j: debug attribute= "null".
log4j: Ignoring debug attribute.
log4j: reset attribute= "false".
log4j: Threshold ="null".
log4j: Retreiving an instance of org.apache.log4j.Logger.
log4j: Setting [com.server] additivity to [true].
log4j: Level value for com.server is  [INFO].
log4j: com.server 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: Retreiving an instance of org.apache.log4j.Logger.
log4j: Setting [org.hibernate.LazyInitializationException] additivity to [false].
log4j: Level value for org.hibernate.LazyInitializationException is  [off].
log4j: org.hibernate.LazyInitializationException level set to OFF
log4j: Class name: [org.apache.log4j.AsyncAppender]
log4j: Attaching appender named [myAppender] to appender named [async].
log4j: Class name: [org.apache.log4j.ConsoleAppender]
log4j: Setting property [threshold] to [INFO].
log4j: Setting property [target] to [System.out].
log4j: Parsing layout of class: "org.apache.log4j.PatternLayout"
log4j: Setting property [conversionPattern] to [%-5p %d{ISO8601} [%t] %c %x - %m%n].
log4j: Adding appender named [async] to category [org.hibernate.LazyInitializationException].
log4j: Retreiving an instance of org.apache.log4j.Logger.
log4j: Setting [net.sf.ehcache] additivity to [true].
log4j: Level value for net.sf.ehcache is  [INFO].
log4j: net.sf.ehcache 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: Level value for root is  [INFO].
log4j: root level set to INFO
log4j: Adding appender named [async] to category [root].
0
votes

I think adding additivity="false" to your com.server logger will solve the issue.

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

https://logging.apache.org/log4j/2.x/manual/configuration.html#Additivity

0
votes

Problem solved, I had to do:

<logger name="com.server" additivity="false">
    <level value="INFO" />
    <appender-ref ref="async" />
</logger>