Log4j Nested Diagnostic Contexts (NDC)

Wednesday, June 2nd, 2010

Introduction and Problem

Log4j is a brilliant set of libraries which provides good “out of the box” logging capabilities.

Sometimes however, in multi-threaded environments (for example web apps), it can be hard to decipher the interleaved messages from the various clients

e.g.

Client A logs something
Client B logs something
Client A logs something
Client C logs something
Client A logs something
Client A logs something
Client B logs something
Client A logs something

Getting hard to read already!

Solution

Luckily for us Log4j has a built in solution to this common problem: Nested Diagnostic Contexts.

To quote the API doc “A Nested Diagnostic Context, or NDC in short, is an instrument to distinguish interleaved log output from different sources. Log output is typically interleaved when a server handles multiple clients near-simultaneously.

Interleaved log output can still be meaningful if each log entry from different contexts had a distinctive stamp. This is where NDCs come into play….”

http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/NDC.html

The simple example below applies NDC to a Message Driven Bean (MDB):

Sample Java Code

package test.controller;

import javax.jms.Message;
import javax.jms.MessageListener;

import org.apache.log4j.Logger;
import org.apache.log4j.NDC;

public class Log4jDiagnosticContextSetter implements MessageListener {

    private static final Logger LOG = Logger.getLogger(Log4jDiagnosticContextSetter.class);

    private MessageListener messageListener;

    public void onMessage(Message message) {
        boolean loggingContextIsSet = addLoggingContextData(message);

        try {
            messageListener.onMessage(message); // the bean does its stuff
        }
        finally {
            if (loggingContextIsSet){
                removeLoggingContextData();
            }
        }
    }

    private boolean addLoggingContextData(Message message) {
        if (!LOG.isInfoEnabled())
            return false;
        
        try {
            NDC.push(getUniqueRef());
        }
        catch (Exception e) {
            LOG.error("Error pushing identifier onto Log4J NDC stack.", e);

            return false;
        }

        return true;
    }

    private void removeLoggingContextData() {
        try {
            while (NDC.getDepth() != 0) {
                NDC.pop();
            }
        }
        catch (Exception e) {
            LOG.error("Error popping message ID off of Log4J NDC stack.", e);
    }

    private String getUniqueRef() {
        // some way to get a unique reference
    }
}

Sample Log Output

You can see here in the example log output the result of the NDC push code above (in this case “98765432” is the unique identifier)

[02/06/2010 12:49:34:883 BST] [MessageListenerThreadPool : 0] DEBUG AuditServiceListener [98765432] - Processing message
[02/06/2010 12:49:34:883 BST] [MessageListenerThreadPool : 0] DEBUG ServiceMsgProcessor  [98765432] - Starting processing of XML request. Request=()
[02/06/2010 12:49:34:883 BST] [MessageListenerThreadPool : 0] DEBUG RequestUnmarshaller  [98765432] - Unmarshalling XML request payload to object.

You can leave a response, or trackback from your own site.

Tags: java, log4j, logging
Posted in: Development, How to's