Friday, September 17, 2010

Log4j observation and best practice

Just today I realized that setting the Threshold value for logging level at appender has no effect on checking if lower levels are enabled for particular category.

For example consider the log4j.xml config file as shown below

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

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/"
debug="false">
<appender name="CONSOLE" class="org.apache.log4j.ConsoleAppender">
<param name="Target" value="System.out" />
<param name="Threshold" value="INFO" />

<layout class="org.apache.log4j.PatternLayout">
<!-- The default pattern: Date Priority [Category] Message\n -->
<param name="ConversionPattern" value="%d{ABSOLUTE} %-5p [%c{1}] %m%n" />
</layout>
</appender>

<!-- A time/date based rolling appender -->
<appender name="FILE" class="org.apache.log4j.RollingFileAppender">
<!-- ADD HOME VAR HERE? -->
<param name="File" value="../log/server.log" />
<param name="Append" value="false" />
<param name="Threshold" value="INFO" />
<layout class="org.apache.log4j.PatternLayout">
<!--
The default pattern: Date Priority [Category] (Thread) Message\n
-->
<param name="ConversionPattern" value="%d %-5p [%c{1}] (%t) %m%n" />

<!--
The full pattern: Date MS Priority [Category] (Thread:NDC) Message\n
<param name="ConversionPattern" value="%d %-5r %-5p [%c] (%t:%x)
%m%n"/>
-->
</layout>
</appender>

<category name="org.mobicents.media.server">
<priority value="INFO"/>
</category>
<category name="org.mobicents.media.server.impl.rtp">
<priority value="TRACE"/>
</category>

<root>
<appender-ref ref="CONSOLE" />
<appender-ref ref="FILE" />
</root>

</log4j:configuration>



And in org.mobicents.media.server.impl.rtp.JitterBuffer class I have a check

if (logger.isTraceEnabled()) {
logger.trace("Receive " + packet);
}


What would you expect the 'isTraceEnabled()' to return? false? I too assumed same. But I was wrong. It returns true. So log4j will still create StringBuffer and appends objects to it to create the log statement and call .toString() on StringBuffer only to realize the appender has Threshold logging level higher than TRACE and it will drop this log message :(


So setting Threshold value only doesn't help in production environment. Make sure that you change logging level of individual Category too.

2 comments:

EDUARDO MARTINS said...

2 additional tips on logging for Mobicents or JBoss AS:

a) The methods to check for level also have a perf cost if you don't define a specific category for the logger name, which means than in case of very extensive logging it may be good to check just once for the level, save it in boolean var and possibly pass it through methods. SLEE Tracers in Mobicents does not suffer from this since it caches such results, that is, it's always like checking a boolean.

b) With the default log4j configuration all you need to change root level (which is applied to all undefined categories, such as Mobicents) is pass -Djboss.server.log.threshold=LEVEL in JBoss AS run.sh invocation

EDUARDO MARTINS said...

btw, the new blog design is much better :)