Monday, October 15, 2007

How I Use log4j

Log4j is a 3rd party Java library that solves the huge (and under appreciated) problem that is application logging. I use log4j in all but the smallest applications as it is an invaluable tool to track down problems and recreate error conditions. As a general rule of thumb, I will use log4j in any program I write that somebody else is likely install and run. I absolutely love log4j and in my opinion it is the single most valuable tool for providing application visibility.

Even with simple console tools, it pays off to use log4j. Occasionally, I will get a question like "hey, tool X didn't work quite right a few days ago - what happened?". No problem, tool X was configured to send warnings and errors to the DailyRollingFileAppender. If I implemented logging correctly in tool X, I will have enough visibility to discover the problem and fix it.

Loading log4j properties

The first problem I run into is how configure log4j. I have the option to compile in configuration parameters, however by doing so I lose much log4j's vast flexibility. For most non-trivial applications I want to create a log4j properties file and load it when your application starts. For these reasons I prefer to pass the location of a log4j properties file into my program dynamically as a system property:

java -Dlog4jconfig=config/log4j.properties -cp "program.jar" Main arg1 ...

This solution is only acceptable for programs that are not executed by directly invoking the JVM. Things like setting the classpath and specifying system properties are a terrible burden on a user; therefore I recommend using a script or commons-launcher to handle the details of application startup. Further, by setting the log4j properties file name in a system property, I do not impact command line arguments specified by the user.

When it comes to the actual initialization of log4j, I generally have a block of code at the beginning of my program that looks like this:


String log4jConfig = System.getProperty("log4jconfig");

if (log4jConfig != null) {
PropertyConfigurator.configure(log4jConfig);
log.info("log4j initialized using properties file [" + log4jConfig + "]");
} else {
System.err.println("You must set system property log4jConfig");
System.exit(1);
}

When my program knows how to find the log4j properties file, I are now free to configure logging without having to recompile my application. My typical configuration looks like:

log4j.debug=false
log4j.rootLogger=debug, A1, A2

log4j.appender.A1=org.apache.log4j.ConsoleAppender
log4j.appender.A1.Threshold=INFO
log4j.appender.A1.layout=org.apache.log4j.PatternLayout
log4j.appender.A1.layout.ConversionPattern=%p %d [%t] %c - %m%n

log4j.appender.A2=org.apache.log4j.DailyRollingFileAppender
log4j.appender.A2.Threshold=INFO
log4j.appender.A2.DatePattern=.yyyy-MM-dd
log4j.appender.A2.layout=org.apache.log4j.PatternLayout
log4j.appender.A2.File=logs/application.log
log4j.appender.A2.layout.ConversionPattern=%p %d [%t] %c - %m%n

What to Log?

This is the real question. It is often difficult to decide what level of detail to send to your application logs. One of the most common logging statements in your program sends a caught exception to the logger. At this point I ask myself if the exception and stack trace will be enough to reproduce the error. If the answer is no, then I will log relevant inputs that caused the exception.

Assertions are another good place to add logging. Typically when my application is in the hands of users, assertions will be turned off. The only way to gain visibility into what happened is to log details of the assertion and what inputs caused the failure. Even if the assertion failure causes my program to terminate, a log can save me minuets to months when tracking down the problem.

Finally, I acknowledge there is always an else. Whenever I have an if without an else or a switch with an empty default condition, I consider the implications if my code hit the unhandled else/default. It often pays down the road to log "impossible" or "assumed" conditions such as these.

How?

Simply put, at the beginning of any class that supports logging, I will crate a static Logger object named log:

private static Logger log = Logger.getLogger(MyClassName.class);

One note of caution: I will undoubtedly copy/paste similar Logger initialization code throughout my program. I must make sure I change MyClassName to the actual name of my class. Forgetting to do so may not be caught by the compiler and may only show up months or years down the road when I actually need accurate information from the logs.

Lastly, when writing information to the log, I always enclose a concatenated string between braces. This makes empty strings more obvious and whitespace more readable:

log.error("Illegal condition [" + illegalCondition + "] occured");

Conclusion

I have barely scratched the surface of log4j's capabilities. For more information I highly recommend purchasing the log4j book for $19.67 USD. This text is an excellent reference and has proven to be quite useful to me. I am very interested in how others use log4j; I would appreciate a comment if you feel you have your own noteworthy log4j tips.

4 comments:

Chuck said...

You should check out Commons Logging at http://commons.apache.org/logging/ instead of using Log4J directly. Your code will be much cleaner that way. All you do is include commons-logging-1.1.jar, log4j-1.2.15.jar, and your log4j properties file in your classpath and in your Java class, get a logger by using the code:
private static final Log log = LogFactory.getLog(MyClass.class);
and then
log.info("this is my message");
Make sure to import:
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
That is all the code you need, end of story. Commons logging is smart enough to find the log4j properties file on your classpath and use it as the logging implementation. Now you don't need all that messy Log4J initialization in your code. As an added bonus, if you decide to use a different implementation such as Java Logging, you don't need to make any changes to your code.

Hung Tang said...

Log4j is missing varargs and support for parameterized string construction based on priority level that's found in modern logging APIs like SLF4J and Seam. No big deal really--you could add these features behind Log4j. Otherwise, it's a stable and productive tool.

If you are a believer in annotations, then the cut-and-paste problem can be rectified by having some "container" help you inject an appropriate logger.

David said...

Hi,

to get arround the copy paste problem I use the following eclipse template:

private static Logger logger = Logger.getLogger(${enclosing_type}.class);

JustGettingBy said...

Commons Logging is not the way to go!

<rant>
Realistically how often will you swap out your logging infrastructure? Logging is there for your debugging of application state at your user's location. Important activity that the customer is interested in should be going into an audit/reporting 'log'.

Google "commons logging issues" to get a feel for deployment issues associated with the simplicity of commons logging or start with this entry. Wrappers are meant for one thing...to be tossed in the trash ;)
</rant>

As a side note on usage of juli or log4j, I've used the approach of hierarchical naming to get categorized capabilities (nb: not the first person to use this). For example if I want to perform some type of audit on security operations, I create a root logger named Security. All classes append their class name to these operations e.g. Security.org.foo.users.CreateUserOperation. This approach provides a channel based mechanism for auditing/reporting with granularity via configuration.