Month: September 2008

Logging has long been a pet peeve of mine. I find it intensely irritating to arrive at a tomcat installation and see a catalina.out file hundreds of megs large because some fool of a developer thought that System.out.println() was a good logging tool. I recently gave a presentation at work about logging, and this is the contents that it was based on (mildly rewritten).

Why use logging?

Well, you could use System.out.println(). But as alluded to above, this is a very coarse tool. There’s no way to turn it off without altering the code. With a logging system, you get much greater control, including the ability to control what gets logged and where it ends up. And you get to control it at runtime without altering your code.

Generally, proper logging gives you better visibility into your project and its behaviour.

Perhaps most importantly you should do it in order to not piss off your sysadmins by generating a very large non-rotateable file.

Which logging system to use?

There are quite a few out there.

• log4j
• JDK logging

In addition, there are “abstraction libraries,” which allow you to choose different logging systems to actually use. For example:

• commons-logging
• slf4j

My advice is that unless you’re writing a library that you expect 3rd parties to use (over whom you have no control), then you should stick to log4j. It’s extremely widely used and well known. It works very well. It’s also wonderfully configurable.

If you do have to write a library for 3rd parties, then commons-logging is the more popular choice. Whilst it certainly has it’s flaws, it does appear to work for me. Caveat emptor.

But what about JDK Logging?

JDK Logging was patterned after log4j. Only they made the configuration a lot less flexible. The main flaw (as I see it) is that you can only configure it via a system property, which means it’s inherently global. When you’re running several webapps in the same JVM (via tomcat), this is a fatal flaw.

Actually, I’ve since learned that tomcat works around this by providing it’s own replacement implementation of LogManager. Regardless, the configuration is still very anaemic when compared with log4j.

What should I log?

• At DEBUG, log whatever the hell you like so you know you’ve been down a particular code path, or what a certain piece of data looks like.
• At INFO, support should be able to trace through transactions and figure out what’s going on.
• At WARN, note things that could constitute a problem.
• At ERROR, note things are are a problem.
• At FATAL, note why you cannot continue (“my CPU is on fire”).

All messages above DEBUG must be readable by non-developers — plain English, please!

Remember to include as much context as possible. Don’t just note that something failed. Say what the conditions were that caused that failure.

Beginning log4j

First, create a very simple log4j.properties (you can use log4j.xml but it’s more verbose and the extra features it makes available are rarely needed).

  log4j.rootLogger=WARN, stdout
  log4j.appender.stdout=org.apache.log4j.ConsoleAppender
  log4j.appender.stdout.layout=org.apache.log4j.SimpleLayout
  log4j.logger.com.me=INFO

NB: I set the default logging level to WARN and left our code logging at INFO. This is in order to reduce junk output from 3rd party libraries like Spring and Hibernate. Of course, you can always enable that if needed.

Place this somewhere it will end up at the root of your classpath.

• For maven, put it in src/main/resources/log4j.properties.
• For an ant project, put it in src/log4j.properties.

Now, create a logger and use it.

  package com.me;
  public class Foo {
    // Non-static allows use of getClass().
    private Logger LOG = Logger.getLogger(getClass());

    public void logSomething() {
      LOG.info("something");
    }
  }

That should end up on your console. Hurrah!

NB: Always using a consistent field name for your logger makes it much easier to grep for log messages later on. It’s a good candidate for an Eclipse template.

How do I enable DEBUG for a single class/package?

Add this to log4j.properties.

 log4j.logger.org.springframework=DEBUG

Everything else will continue to be logged at the level of the rootLogger, but Spring stuff will come out more verbosely.

To understand how this works, you have to understand the idea of “logger hierarchies.” If you have configured the rootLogger as WARN and the “com.me.proj2” logger as INFO, this is how the logger hierarchy could end up looking.

How do I customize the output format?

Configure a different Layout in log4j.properties. e.g. PatternLayout.

 log4j.appender.stdout=org.apache.log4j.ConsoleAppender
 log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
 log4j.appender.stdout.layout.conversionPattern=%d{ISO8601} %c{2} %p %m%n

That configures each line with the following fields:

• The date & time in standard ISO 8601 format.
• The last two components of the classname which made the log message.
• The priority level.
• The message itself.
• A newline.

How does log4j get configured?

The configuration process is fairly simple. The first time you call log4j, it looks on the classpath for log4j.xml and then log4j.properties. That’s all there is to it, unless you change it.

There are several ways to impose your own order on things.

• You can specify a log4j.configuration system property pointing a file. But as we discussed earlier, system properties are generally best avoided.
• You can use the log4j API (PropertyConfigurator or DOMConfigurator) to find the config file in the location you want. You have to execute this code before the rest of your app starts up.

If it still doesn’t seem to be doing what you expect, you can (as a one-off) specify the log4j.debug system property on the command line. That will show you where log4j is looking for its configuration on stderr.

How do I configure logging in my tests?

Generally you don’t want logging in tests. They’re verbose enough already, and JUnit will let you know when something’s wrong. You can enforce this by creating a second log4j.properties that lives in the classpath of your tests, which sets the rootLogger to WARN (and nothing else more detailed).

• For maven, put it in src/test/resources/log4j.properties.
• For an ant project, put it in test/log4j.properties.

How should I configure log4j in a webapp?

As early as possible. This lets you see debug output from the rest of your app starting up.

That is, in a special ServletContextListener. Trying to configure log4j from within a Spring applicationContext is far, far too late (this appears to be a common mistake).

Spring has a special purpose Log4jConfigListener for this purpose. You can write your own, however. Here’s an example of the web.xml configuration.

  
    log4jConfigLocation
    /WEB-INF/log4j.properties
  
  
    org.springframework.web.util.Log4jConfigListener
  

How should log4j be setup for development / production in a webapp?

Don’t have a default /log4j.properties on the classpath. Instead, have the Log4jConfigListener set up in the web.xml, pointing at /WEB-INF/log4j.properties (as shown above). That file should contain your development logging setup (INFO level output to the console) as well as commented out examples of production logging setup (WARN level output to a rotated file).

Create a file META-INF/context.xml (for tomcat), which contains a commented out override for the log4jConfigLocation context-param. e.g.

 
   <!--
   
   -->
 

When packaged as a war, the two files are easily extracted and can be used to override the logging behaviour.

 % unzip -p ~/foo.war META-INF/context.xml > $sitecode/conf/Catalina/localhost/foo.xml
 % vi $CATALINA_BASE/conf/Catalina/localhost/foo.xml
 % unzip -p ~/foo.war WEB-INF/log4j.properties > /etc/myapp/log4j.properties
 % vi /etc/myapp/log4j.properties

This is probably the most flexible solution. It means that you can deploy the same war file anywhere, and just have a small amount of one-time setup to get it going.

How do I get my log files rotated?

Log4j comes with a builtin DailyRollingFileAppender which will give you a new log file every day. However, I’ve tended to prefer the DatedFileAppender addon, which works in a very similar manner to cronolog. That is, each log file is named with the current date in it.

This is how it’s configured in log4j.properties.

log4j.rootLogger = WARN, logfile
log4j.appender.logfile=biz.minaret.log4j.DatedFileAppender
log4j.appender.logfile.Directory=${catalina.base}/logs
log4j.appender.logfile.Prefix=myapp.
log4j.appender.logfile.Suffix=.txt
log4j.appender.logfile.layout=org.apache.log4j.PatternLayout
log4j.appender.logfile.layout.ConversionPattern=%d{ISO8601} %p %c{2} - %m%n

What about exceptions?

Lots of people tend to log that an exception occurred and then move on as if nothing happened.

  // FAIL
  try {
    someOperation();
  } catch (SomeNastyException e) {
    LOG.error(e.getMessage());
  }

This is bad because it loses all the context associated with the exception, as well as failing to stop the course of the program. As I noted before, you’re much better off rethrowing it for something higher up to deal with.

  try {
    someOperation();
  } catch (SomeNastyException e) {
    throw new RuntimeException(e);
  }

Whilst this doesn’t work in all cases, it’s a far better default stance to take.

You might also want to look at Best Practises For Exception Handling.

How do I get a unique per-request ID in my logs?

Tools like postfix and sendmail include the message-id in the log files. This is invaluable for tracing a message over several lines of a log file. I needed to do this in a webapp and found log4j’s Nested Diagnostic Context. This is how I implemented it.

  public class AddIdListener implements ServletRequestListener {
    private static long requestNum = 0;
    private static synchronized long getNextRequestNum() {
      return requestNum++;
    }
    public void requestInitialized(ServletRequestEvent sre) {
      NDC.push(String.valueOf(getNextRequestNum()));
    }
    public void requestDestroyed(ServletRequestEvent sre) {
      NDC.pop();
    }
  }

With this configured in the web.xml, you need to use the PatternLayout to get it into the logs.

 log4j.appender.stdout.layout.conversionPattern=%d{ISO8601} %x %c{2} %p %m%n

Now, all requests with the same value in the %x field belong to the same request.

This may not be a perfect solution, but it works quite well for me.

A performance tip

Sometimes, a call to a logger can be expensive. Particularly in the middle of a tight loop. For this, you can ask log4j if it’s even going to bother using the output, which is quicker.

  for (BigHairyObject bho : bigHairyObjects) {
    if (LOG.isDebugEnabled()) {
      LOG.debug("here, bho=" + bho);
    }
  }