Effective Logging

Originally published: 2008-11-25

Last updated: 2015-04-27

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 Java's dynamic loading and linking meant that adding a log statement was a matter of seconds. And more important, they were working with a multi-threaded application, and logging is often 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 it's usually relegated to working out bugs 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.

But 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 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 that useful in a real-world application. For one thing, the application may need to use the standard output stream to write its results, like Unix-style utilities. More important, println() 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 to 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 logThis() method that does it for you (and can be modified independently of its calls); 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 pantheon).

Both frameworks provide a similar set of features, including:

Interestingly, 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. What did supplant direct use of Log4J were logging facades: initially Jakarta Commons-Logging, and more recently, SLF4J (the Simple Logging Facade for Java).

Logging facades make a lot of sense if you're building a large framework like Spring or Hibernate: it will help your consumers if you provide logging, but you don't know what (if any) logging framework those consumers will actually use. So, rather than force them into using whatever you use (which might be different from what another frame developer used), the facade lets the library adapt to the consumer's environment. SLF4J does this extremely well, not only acting as a facade over the user's logging framework, but providing shims that let different frameworks and facades co-exist, routing all logging output through a single base framework.

For an application developer, the choice of facade versus base framework is less clear-cut: since you control the entire application, there's no need to use a facade to support multiple frameworks. Where facades make sense is to support developer productivity: rather than remember the quirks of different frameworks, you learn the facade and rely on it to do the right thing.

The examples in this article use the SLF4J facade. I originally wrote it for Jakarta Commons Logging, but the intervening years have seen SLF4J become the preferred facade. However, most of this article is about techniques for logging as a concept, not on the details of a specific framework.

Creating a Logger

You write messages to the log using a logger object (seems obvious, no?). All common frameworks associate a name with a logger instance, and apply a hierarchy where components of the name are separated by dots (as in a fully-qualified classname, like java.lang.String). And all frameworks provide multiple logging methods, such as debug() or warn(), to log output of different severity levels.

The biggest different between frameworks is the name of their logger class, and how you get an instance of that class. Log4J and java.util.logging use the Logger class, with a factory method Logger.getLogger(). Jakarta Commons Logging uses a Log object, which you get from a LogFactory. And SLF4J uses a Logger and LoggerFactory.

However you get your logger instance, you need a place to store it. One common practice — that I disagree with — is to make it a static variable: 

private final static Logger LOGGER = LoggerFactory.getLogger(BasicExamples.class);

Proponents of this approach point out that it saves memory, because a single variable can be shared between class instances, and that it can be called by static methods as well as instance methods. Against that, I have the following reasons not to do this:

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 Logger logger = LoggerFactory.getLogger(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 uses it; this is so common that all frameworks provide a factory that creates a logger from a Class instance. However, this is a convenience; loggers can have any name: 

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

Error logging is a common reason to create such a logger, because it can be directed to a different location than the normal application log, and will ensure that error messages aren't lost in the noise. Access logging is another use case, as is logging “special events” such as user creation or password change. And there's no reason that such logs have to go to a file: you could, for example, send an email to your ops group for every message logged to a “fatalError” logger.

Logging Guards, and an Alternative

Here's a piece of code that you'll see often: it checks 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. I have actually seen bugs like the following in a production system, the result of copy-and-paste coding: 

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

My biggest issue with logging guards is that I find them distracting, breaking up the flow of the code — especially in compact methods. So how to replace them?

If you use SLF4J it's easy: you invoke the logger with a format string and the individual values you want to log: 

logger.debug("loop iteration {}", ii);

This reduces the cost of logging to a function call, plus any auto-boxing required (as here) to turn the arguments into Objects. There are variants of each call optimized for one or two arguments, as well as a variant that takes a varargs list.

But what if you aren't using SLF4J? In this case, create your own LogWrapper class, wrapping the underlying logger instance: 

public class LogWrapper
{
    private Logger logger;


    public LogWrapper(Logger logger)
    {
        this.logger = logger;
    }


    public void debug(String format, Object... args)
    {
        if (logger.isDebugEnabled())
        {
            logger.debug(String.format(format, args));
        }
    }

    // and so on, for all the helper methods on Logger
}

Now, rather than defining a Logger member, your class uses a LogWrapper: 

protected LogWrapper logger = new LogWrapper(LoggerFactory.getLogger(getClass()));

// ...

public double doSomething(double v1, double v2)
{
    double result = v1 * v2;
    logger.debug("doSomething(%.2f, %.2f) = %.2f", v1, v2, result);
    return result;
}

A benefit of using your own wrapper, even if you do use SLF4J, is that you have fine control over formatting. This is particularly useful when the object's own toString() function isn't very useful. For example, the standard Element implementation has a very confusing string value, consisting of that element's name and its “value,” which happens to always be null (for example: “[foo: null]”). A better choice might be to combine namespace URI and local name, or simply use the element's tag name: 

public void debug(String format, Object... args)
{
    if (logger.isDebugEnabled())
    {
        preprocessArgs(args);
        logger.debug(String.format(format, args));
    }
}

// and so on, for all the helper methods

/**
 *  This function replaces logged arguments with our desired string values.
 *  At this time, we only care about XML Elements.
 */
private void preprocessArgs(Object[] args)
{
    for (int ii = 0 ; ii < args.length ; ii++)
    {
        if (args[ii] instanceof org.w3c.dom.Element)
            args[ii] = ((org.w3c.dom.Element)args[ii]).getTagName();
    }
}

A wrapper like this would be part of the application's core utility package, and may eventually include formatting code for many of the applications internal classes along with third-party classes. If you choose to create a wrapper, you should regularly check that other application components aren't bypassing it.

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 major program sequence points, such as completing initialization. For applications that process messages (including web requests), I create a dedicated logger; the level doesn't matter.

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 type 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, even if not guaranteed unique. 

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 logging methods have two forms: the first takes a simple message object (normally a String), and the second 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). To do this, 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 enable it using a configuration file without changing your code.

Two of 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 the same code at the same time; you can run grep on the logfule to see 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 “ISO8601” date format for date and time with millisecond precision, followed by the severity and thread name. 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

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.

SLF4J is a logging wrapper that adapts to whatever underlying framework you use. It also gives you the ability to apply simple formatting to your log messages.

Apache Commons Logging is an older logging wrapper, and was used in the previous iteration of this article; in my experience, it has been supplanted by SLF4J. Early versions of this framework had a reputation for leaking memory in app-servers, but that isn't a current problem (and hasn't been since the 1.1 version was released in 2006). However, it doesn't have the features of SLF4J, so I'd pick the latter unless you're on a legacy project that already uses Commons Logging.

Copyright © Keith D Gregory, all rights reserved

This site does not intentionally use tracking cookies. Any cookies have been added by my hosting provider (InMotion Hosting), and I have no ability to remove them. I do, however, have access to the site's access logs with source IP addresses.