java logging nightmare and log4j not behaving as expected with spring + tomcat6

Question

I have a spring application that has configured log4j (via xml) and that runs on Tomcat6 that was working fine until we add a bunch of dependencies via Maven. At some point the whole application just started logging part of what it was supposed to be declared into the log4.xml

"a small rant here" Why logging has to be that hard in java world? why suddenly an application that was just fine start behaving so weird and why it's so freaking hard to debug?

I've been reading and trying to solve this issue for days but so far no luck, hopefully some expert here can give me some insights on this

I've added log4j debug option to check whether log4j is taking reading the config file and its values and this is what part of it shows

log4j: Level value for org.springframework.web is  [debug].
log4j: org.springframework.web level set to DEBUG
log4j: Retreiving an instance of org.apache.log4j.Logger.
log4j: Setting [org.compass] additivity to [true].
log4j: Level value for org.compass is  [debug].
log4j: org.compass level set to DEBUG

As you can see debug is enabled for compass and spring.web but it only shows "INFO" level for both packages. My log4j config file has nothing out of extraordinary just a plain ConsoleAppender

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/"&gt;

 <!-- Appenders -->
 <appender name="console" class="org.apache.log4j.ConsoleAppender">
  <param name="Target" value="System.out" />
  <layout class="org.apache.log4j.PatternLayout">
   <param name="ConversionPattern" value="%-5p: %c - %m%n" />
  </layout>
 </appender>

What's the trick to make this work? What it's my misunderstanding here? Can someone point me in the right direction and explain how can I make this logging mess more bullet proof?

Answer 1

As it was working until you loaded a number of dependencies via Maven, perhaps there's a Log4j configuration loaded inadvertently via these dependencies ?

Run mvn dependency:tree to see what's being loaded, and then see if any of these dependencies has a Log4j configuration.

Answer 2

It might not be log4j that is doing the logging, and hence your log4j config would be ignored. Spring logs using Commons Logging, which is an api that can delegate to various logging frameworks, including log4j. To decide which implementation to use, commons logging looks into the classpath.

If you have added a dependency that dragged its own logging implementation into the classpath, commons logging might now use the other implementation.

I recommend to set a breakpoint at a call to the logging facility, and trace the execution to see which logging implementation is used.

Answer 3

I think your problem is that you're not setting the threshold param on your appenders, and (maybe) because you're not assigning those appenders to your loggers.

Try adding param name="threshold" value="debug" to your appenders and then explicitly adding them to the specific (or root) loggers like so:

<appender name="console" class="org.apache.log4j.ConsoleAppender">
    <param name="threshold" value="debug" />
    <param name="Target" value="System.out" />
    <layout class="org.apache.log4j.PatternLayout">
        <param name="ConversionPattern" value="%-5p: %c - %m%n" />
    </layout>
</appender>

<logger name="org.springframework.web">
    <level value="debug" />
    <appender-ref ref="console" />
</logger>

Also, this page says "This appender will not log any messages with priority lower than the one specified here even if the category's priority is set lower" which is probably the source of your problem.

Answer 4

This seems like a good thread for you to read: http://forum.springsource.org/showthread.php?t=88250

Cutting to the chase, it seem that the poster had a problem with a Tomcat security setting. An updated Tomcat policy file fixed the issue.

Probably has something do with reading outside of the webapp for your log4j.xml file.