Effective Logging

When I started programming, in BASIC, in the late 1970s, the only way to debug was to insert PRINT statements in your code. As I moved into assembly and various compiled languages, I left that habit behind. It wasted valuable memory space, and the time taken for a compile-link cycle meant that I'd have to know everything that I needed to log well in advance. Instead, I learned interactive debugging, first at the front panel of the PDP-11, and then through various debuggers. With a debugger I could decide what was important ad hoc, and often discover that what I thought was unimportant was in fact critical. Plus, I could stop the program and walk away, knowing that it would be in the same state when I returned.

Twenty years later I took my first Java job, and I learned that my new colleagues almost never used debuggers. And after one session with jdb, I knew why. But it wasn't just that the tools were poor; they turned to logging because it's Java's dynamic loading and linking meant adding a log statements was a matter of seconds. And more important, they were working with a multi-threaded application, and often logging is the only way to debug such apps. You can't simply pause and walk away, because another thread might change your data in the interim.

I still believe in using a debugger. But now I find that it's usually relegated to working out issues during test-driven development. For large-scale applications, I rely almost entirely on log messages. And ironically, it's because attaching a debugger to a modern app-server and running to the failure point is now the time-consuming option. The better choice is to insert logging statements, exercise the code, and change those statements if needed.

I also believe that effective logging requires skill, just like using a debugger. In fact, the skills required are remarkably similar: trying to analyze a multi-megabyte logfile is as difficult as single-stepping through a long program. The key is to focus your efforts; to separate the important information from its surrounding mass of data. This article is an attempt to distill what I've learned in the eight years that I've been using logging as my primary means of examining running programs.

Logging Frameworks

While System.out.println is easy, it's not very useful in a real-world application. For one thing, you might not even have a place to view the output: consider an applet running within a browser. For another, the application might want to use System.out for its own purposes, like most Unix-style utility programs. Aside from such practical considerations, logging to System.out doesn't provide context — timestamps, thread names, the running method, and so on — unless you explicitly write them to the log. And then there's the question of how you turn it off: the level of logging needed to debug a problem is far greater than normal application monitoring, and could easily fill up available disk from running in production.

All of these problems can be solved: you can write to a file rather than System.out; you can add all the contextual information, or better, create a “log this” method; you can use variables to control which logging calls actually write to the log. And if you do this, and pay attention to the design, you'll end up with a logging framework. And in many of the older (started prior to 2000) applications that I've worked with, there's just such a home-grown framework.

But today, there's no need to write such a framework yourself. Logging has been part of the Java API since version 1.4. There are also several open-source frameworks, with Log4J arguably being the most popular (partly due to its age, and partly due to its inclusion in the Apache library).

Both frameworks provide a similar set of features, including:

Named “logger” objects (typically named after the class that uses them), which may be individually enabled or disabled. Messages written to a particular logger will be identified as such in the log output.
Assignment of loggers to a hierarchy based on name (normally following the Java package hierarchy), with settings propagating downward through the hierarchy.
Differing levels of log output, ranging from fatal error to debug. Low-level messages may be turned off in a production environment, while still allowing high-level messages to be written to the log.
Customizable output formatting, allowing boilerplate context information to be written to the log with each user-specified message.

Surprisingly, the built-in JDK logging framework did not supplant Log4J — in fact, I can't think of any project that I've worked on that has used it. Nor, in recent years, have I worked on many projects that use Log4J directly. Instead, most use the Apache Commons-Logging library, which is not itself a framework, but instead is a wrapper around both the JDK and Log4J, with the ability to integrate other frameworks. Keeping with this practice, all examples in this article use Commons Logging rather than an underlying framework.

Creating a Logger

A logger object (named Logger in Log4J and JDK Logging, Log in Commons-Logging) provides your program with a way to write to the log (seems obvious, right?). Each logger instance has a name, typically that of the class that uses it. Common practice is to create a static variable to hold the logger, and initialize it when the class loads:

private final static Log LOGGER = LogFactory.getLog(LogExample.class);

This approach provides a couple of benefits: First, a static logger minimizes per-instance overhead, because it's a shared reference. And second, it can be called by static methods as well as instance methods. However, I think it has several distinct disadvantages:

You have to explicitly specify the classname (I really wish that Java had a class-level equivalent to this). Although IDEs are very good about changing all references to a class when you change its name, I think this is a copy-paste error waiting to happen. Plus, it's not always easy to determine the classname, for example, when writing a JSP.
It doesn't easily support inheritance hierarchies, particularly when using anonymous child classes. Static members are always accessed based on the compiled type, not the actual instance class. While this may not seem to be a problem, consider what happens when you see log messages from class Foo, when you believe that your program should be using its subclass Bar.

As a result, I prefer to define the logger as an instance variable, as shown below. This approach isn't appropriate for value objects (although they shouldn't be logging anything anyway). Nor is it appropriate for classes that need logging from static methods (but I don't often mix static and instance methods in the same class).

protected final Log logger = LogFactory.getLog(this.getClass());

Note that I define the logger as protected rather than private. This is my nod to minimizing the footprint of an instance: the logger is initialized once and is available to all subclasses. You may consider it an unpardonable violation of encapsulation, and are welcome to make it private.

Non-standard Logger Names

Most of the time, you'll name your logger instance after the class that creates it: doing so improves the readability and usefulness of the log messages. In fact, Commons-Logging provides a factory method that takes the class object rather than its name. In some cases, however, you might want to create a logger with a unique name.

protected final Log logger = LogFactory.getLog("my_special_logger");

Perhaps the best reason is for debugging: you can create a second logger for a class, using a unique name, and then direct that logger's output to a different location. Once the debugging is done, you can simply set the log configuration to ignore messages from that name. This last point means that you should pick unique names for your non-standard loggers, lest you disable more logging that you planned.

Logging Guards, and an Alternative

Here's a piece of code that you'll often see: it checks to see if the desired logging level is in effect before it logs a message.

if (LOGGER.isDebugEnabled())
{
    LOGGER.debug("last node was: " + node);
}

The goal of such “logging guards” is not to prevent log messages from being written; the logging framework does that for you. Instead, the logging guard is designed to prevent needless calls to toString(), which can be very expensive (a Map, for example, iterates over its elements and calls toString() on each). Without the logging guard, this code would not only call toString() on node, it would also create a StringBuffer for the concatenation; only to throw it all away if the logging level was set above DEBUG.

While I recognize the desire to prevent wasted CPU cycles, it does smack of premature optimization. It also opens the possibility for errors: code added inside the include guard that has side-effects, or perhaps becomes a critical part of the execution — there's nothing more frustrating than a bug that disappears as soon as you switch to debug-level logging. If that weren't enough, I have actually seen code like the following in a production system:

if (LOGGER.isDebugEnabled())
{
    LOGGER.error("this code should not be executed; node = " + node);
}

I also find that the include guards are distracting, breaking up the flow of the code — particularly when writing compact methods. Replacing them, I typically create a a project-specific logging utility class (a wrapper on the wrapper) that uses the variable argument lists introduced with JDK 1.5 to defer “stringification”:

public class LogWrapper
{
    private final Log _logger;
    
    /**
     *  Create and wrap a <code>Log</code> with a specific name.
     */
    public LogWrapper(String logName)
    {
        _logger = LogFactory.getLog(logName);
    }
    
    /**
     *  Create and wrap a <code>Log</code> named after a class.
     */
    public LogWrapper(Class<?> logClass)
    {
        _logger = LogFactory.getLog(logClass);
    }

    // ...

    /**
     *  Log a message with DEBUG log level.
     */
    public void debug(Object... params)
    {
        if (_logger.isDebugEnabled())
        {
            String string = buildString(params);
            Throwable ex = getThrowable(params);
            if (ex != null)
                _logger.debug(string, ex);
            else
                _logger.debug(string);
        }
    }

    // ...

    private static void append(StringBuilder buf, Object obj)
    {
        if (obj instanceof Element)
            buf.append(((Element)obj).getNodeName());
        else
            buf.append(obj);
    }
}

You may feel that this is still a waste of CPU cycles, and creates an unnecessary parameter array that will have to be garbage-collected. With the generational garbage collector, however, this overhead is all but non-existent: the array is created in the Eden space, and in most cases never leaves.

Balanced against the cost of creating the argument array, you get much more control over what gets logged for any given class. For example, the toString() in the the JDK's org.w3c.dom.Element implementation throws a “null” into the string value for no apparent reason. I prefer to just see the nodename (or better, the XPath expression that selects the element), and am able to do this in my wrapper.

What to log, and when

Effective logging is a delicate balance between logging enough data to identify problems, while not being buried by details (or filling your disk drive). The reasons for error and fatal error logging are pretty straightforward: the former should be used when the program has hit an unexpected state, the latter when it's about to shut down. In either case, you should log as much information as you can, in the hope that a post-mortem analysis can find and fix the condition(s) that led to the error.

I rarely use trace-level logging: I'd rather use a debugger and really trace my code. I reserve info-level logging for special cases, such as reporting the contents of messages sent and received. These messages generally get their own named logger, to separate them from messages generated elsewhere in the application (especially since they can be huge).

That leaves debug-level logging. And since it's where I concentrate most of my logging effort, I've developed the following “do's and dont's” for this level of logging.

Do log decision points

Programs are made interesting by their “if” statements; everything else is just moving bits from one place to another. Not surprisingly, this is also where most bugs occur, so it's a great place to insert logging statements. You should log the variables used by the condition, not the condition's branches. If there's a problem you'll want to know why a particular branch was taken — the cause, not the effect.

The following is an example adapted from a J2EE filter class that I wrote. A request may be passed through the server multiple times, but I wanted to decorate the request only once. To make that happen, I used a request attribute to store a flag: if the filter code sees that the flag already exists, it doesn't apply the wrapper. The logging in this case provides several pieces of information: first, of course, is whether the program needs to decorate the current request. But it also gives a sense of how many times a single request is going through the app-server stack, and also whether the attribute is removed at some point. To make this one log message serve all these functions, I log the identity hashcode of the request object — a “good enough” indication of uniqueness.

private Log _logger = LogFactory.getLog(this.getClass());
private String _requestGuardKey = this.getClass().getName() + ".REQUEST_GUARD";

public void doFilter( ServletRequest request, ServletResponse response, FilterChain chain)
throws IOException, ServletException
{
    Boolean requestGuard = (Boolean)request.getAttribute(_requestGuardKey);
    _logger.debug("before applying decorator; request guard = " + requestGuard
                  + ", request = " + System.identityHashCode(request));
    if (requestGuard != null)
    {
        // apply ServletRequestWrapper
        request.setAttribute(_requestGuardKey, Boolean.TRUE);
    }
}

Don't log in short loops

Consider the following piece of code, which logs the query parameters for a request:

Enumeration paramItx = request.getParameterNames();
while (paramItx.hasMoreElements())
{
    String paramName = (String)paramItx.nextElement();
    _logger.debug("parameter \"" + paramName + "\" = " + request.getParameter(paramName));
}

The problem with this code — aside from the questionable value of seeing all request parameters — is that it writes a separate message for each parameter. In a busy app-server, those messages will be separated, dispersed throughout the log, with grep the only way to retrieve them. A better solution is to accumulate the parameters in a StringBuffer, and write them at the end of the loop. Still better, only write the parameters that you actually care about, at the point that you use them, with contextual information (in other words, log at the decision point).

Also, note that I said “short” loops. It's perfectly reasonable to insert logging statements in the middle of a longer loop, particularly a loop that calls some other method on each iteration, or has embedded “if” statements.

Only log exceptions if you're going to handle them

In general, you shouldn't catch an exception unless you're planning to handle it. Catching an exception just so that you can log it and throw it back up the chain is one of the worst ways to fill a log with meaningless trivia:

public void method1()
throws Exception
{
    try
    {
        method2();
    }
    catch (Exception e)
    {
        _logger.warn("an exception occurred!", e);
        throw(e);
    }
}

public void method2()
throws Exception
{
    try
    {
        // do something that causes exception
    }
    catch (Exception e)
    {
        _logger.warn("an exception occurred!", e);
        throw (e);
    }
}

Ultimately, either your application has to handle the exception, let it propagate to a container, or do nothing (and exit). In the last case, you can still log the exception, by installing an uncaught exception handler:

Thread.setDefaultUncaughtExceptionHandler(new UncaughtExceptionLogger());

The actual handler is very simple. Note that it logs the exception as a fatal error: assuming a single thread, the application will exit after the handler runs.

public class UncaughtExceptionLogger
implements UncaughtExceptionHandler
{
    private final Log _logger = LogFactory.getLog(this.getClass());

    public void uncaughtException(Thread t, Throwable e)
    {
        _logger.fatal("uncaught exception", e);
    }
}

Don't log exception messages, pass the exception object to the logger

The “log and throw” example above does show one good habit: it passes the exception object to the logger. All of the logging methods have two forms: one takes a simple message object (normally a String), and the other takes the message plus an exception object. When you use this second form, the log will contain the entire stack trace, allowing you to quickly find the source of an error.

This can also be used for debugging: there are times when it's very useful to see the complete call chain for your method (for example, to verify that your app-server is applying all expected servlet filters). You can create a dummy exception object to record that stack trace in your log:

_logger.debug("in method foo()", new Exception("stack trace"));

Output Formats

One of the great benefits of a logging framework is the amount of context that can be attached to a log message: timestamp, the current thread, the current class and method, and even (if the class was compiled with debug information) the source line number.

Some of this information is very expensive to collect: for example, the method and line number information is generated in older JVMs by creating an exception object, printing its stack trace to a buffer, and then parsing that buffer. Fortunately, you can decide whether that level of information is needed on a per-level or per-named-logger basis, and choose to enable it for specific runs without changing your code.

Two pieces context that I find very valuable are the current timestamp, with millisecond accuracy, and the current thread name. Neither of these is particularly expensive to generate, and both are invaluable when analyzing a large logfile. The thread name is particularly useful in an app-server, where multiple threads may be executing at the same time: you can run grep to extract only the messages that apply to your thread.

Specific output formats will depend on your underlying logging framework. Given the popularity of Log4J, however, my preferred format follows: the “ABSOLUTE” date format for time with millisecond precision (I don't often care about the actual date; if you do, use “DATE”), followed by the severity and thread. The “%c” specifier will output the logger name, which by default is the classname; with that, you don't normally need to use Log4J's location specifies (eg, “%C”). Finally, the log message and a newline.

%d{ABSOLUTE} %-5p [%t] %c - %m%n

And here's some sample output using that log format:

18:09:40,132 DEBUG [main] com.kdgregory.example.logging.LoggingExample - this is a debug-level message

For more information

The sample code for this article.

Log4J remains the most popular logging framework (at least in my experience). Like many open source projects, its documentation can be spotty, particularly with regards to configuration (which is presented by example). I find that I constantly refer to the API docs especially when setting up output layouts.

Apache Commons Logging is often used as the actual logging interface, because it determines at runtime what logging implementation is available. This feature is very useful if you're writing a library that may be used in differing end-user environments, less-so if you're writing an application (unless you think you might change implementations down the road). However, once you get into the Commons-Logging habit, it's easier to just use it everywhere.