why does log4j not log to the files I configured it to with a log4j.xml file?

Question

I've run into this in various environments and have never found a consistent explanation. I've heard comments about the Tomcat container being 'messy', with different logging implementations possibly in there, and then my app or the classloader doesn't know which configuration to use.

This is one of those maddening scenarios when the logging worked once, and then doesn't log an hour later, with no changes to the log4j.xml file. I've got my log4j.xml file in the root of my /src directory, so it gets deployed to the root of the /WEB-INF/classes directory. I'm using Java 6, Tomcat 6, and it's a GWT 2.3 app, running from inside Eclipse Helios on a Windows 7 box.

For what it's worth, here's the log4j.xml

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd" >
<log4j:configuration>
    <appender name="stdout" class="org.apache.log4j.ConsoleAppender">
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d{ABSOLUTE}
      %5p %c{1}:%L - %m%n"/>
        </layout>
    </appender>
    <appender name="fileAppender" class="org.apache.log4j.DailyRollingFileAppender">
        <param name="File" value="${catalina.home}/logs/log4j.log"/>
        <param name="DatePattern" value="'.'yyyy-MM-dd"/>
        <param name="Append" value="true"/>
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d
                %-5p  [%c{1}] %m %n" />
        </layout>
    </appender>
    <root>
        <priority value="debug"></priority>
        <appender-ref ref="fileAppender"/>
    </root>
</log4j:configuration>

here's how I get the logger in my class that's doing the logging

protected static Logger m_logger = Logger.getLogger(RemoteLoggingServiceImpl.class);

and then to actually log I just do

m_logger.debug("my log message");

Using the above code, it doesn't write to the logj4.log file.

Then I tried the following, which got it logging to the log4j.log file, but not to the otherFile.log file as I expected. Here's the updated log4j.xml file :

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd" >
<log4j:configuration>
    <appender name="stdout" class="org.apache.log4j.ConsoleAppender">
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d{ABSOLUTE}
      %5p %c{1}:%L - %m%n"/>
        </layout>
    </appender>
    <appender name="fileAppender" class="org.apache.log4j.DailyRollingFileAppender">
        <param name="File" value="${catalina.home}/logs/log4j.log"/>
        <param name="DatePattern" value="'.'yyyy-MM-dd"/>
        <param name="Append" value="true"/>
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d
                %-5p  [%c{1}] %m %n" />
        </layout>
    </appender>
    <appender name="otherFileAppender" class="org.apache.log4j.DailyRollingFileAppender">
        <param name="File" value="${catalina.home}/logs/otherFile.log"/>
        <param name="DatePattern" value="'.'yyyy-MM-dd"/>
        <param name="Append" value="true"/>
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d
                %-5p  [%c{1}] %m %n" />
        </layout>
    </appender>
    <root>
        <priority value="debug"></priority>
        <appender-ref ref="fileAppender"/>
    </root>
    <logger name="com.mypackage.myLoggingClass">
        <level value="debug"/>
        <appender-ref ref="otherfileAppender"/>
    </logger>
</log4j:configuration>

and I create this logger with this instead :

protected static Logger m_logger = Logger.getLogger("com.mypackage.myLoggingClass");

Can anyone explain why it doesn't log at all in the first scenario, and/or why it logs to log4j.log but not otherFile.log in the 2nd scenario?

Answer 1

Your JRE uses a file named logging.properties to set the handlers and log levels and a few other settings to be shared globally across all Java commands.
Many a times its seen that default is handlers= java.util.logging.ConsoleHandler, you can try appending java.util.logging.FileHandler like below.

handlers= java.util.logging.FileHandler, java.util.logging.ConsoleHandler

Also try settng the file formatter to SimpleFormatter instead of XML formatter

java.util.logging.FileHandler.formatter = java.util.logging.SimpleFormatter

Answer 2

First off, you didn't list what version of Log4j you are using, so I'm assuming you're using a relatively recent version of Log4j.

In the first block of example code you provided:

    <root>
        <priority value="debug"></priority>
        <appender-ref ref="fileAppender"/>
    </root>

You have not modified the logging level of the root appender. Per the log4j 2.x documentation

    If no configuration files are present logback will default to the 
    DefaultConfiguration which will set up a minimal logging environment
    consisting of a ConsoleAppender attached to the root logger. The output
    will be formatted using a PatternLayout set to the pattern 
    "%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n".

    Note that by default, the root logger is assigned to Level.ERROR.

In order have the logger output to the file in the first example you need to change your root logger to:

    <root level="debug">
        <appender-ref ref="fileAppender"/>
    </root>    

A good indicator that the debug logging wasn't working is that you wouldn't have seen any output on the console either since the default logging level was set to "error". I always like to have a console appender on my loggers, so that I can see that my application is actually logging.

    <appender-ref ref="Console"/>

In the second example, the root logger does not log to the file for precisely the same reason as in the first example. However you managed to set the "com.mypackage.myLoggingClass" logger up correctly, which is why your application has debug output when you use the "com.mypackage.myLoggingClass" class based logger.

Answer 3

As far as I can see all your original assumptions are correct and the log should be printed, so here's a few things I'd check in this case:

• Check your classpath, did you import other logging library jars causing conflicts (slf4j, common-logging etc)?
• Check your imports, was it really org.apache.log4j.*, not other logging libraries
• Check gwt logging guide, does it conflicts with log4j?
• Check the file system lock on log4j.log, is there any other process locking it causing writes to fail?
• Check your war/ear file, was log4j.xml really placed on WEB-INF/classes?
• Check ${catalina.home} does resolve to the path you intended