Logging parallel threads in logback

Logback Mapped Diagnostic Context (MDC) is your friend. It allows you to add thread local variables that can be managed, copied between threads, and logged using a logging format.

From the docs:

One of the design goals of logback is to audit and debug complex distributed applications. Most real-world distributed systems need to deal with multiple clients simultaneously. In a typical multithreaded implementation of such a system, different threads will handle different clients. A possible but slightly discouraged approach to differentiate the logging output of one client from another consists of instantiating a new and separate logger for each client. This technique promotes the proliferation of loggers and may increase their management overhead.

A lighter technique consists of uniquely stamping each log request servicing a given client. Neil Harrison described this method in the book Patterns for Logging Diagnostic Messages in Pattern Languages of Program Design 3, edited by R. Martin, D. Riehle, and F. Buschmann (Addison-Wesley, 1997). Logback leverages a variant of this technique included in the SLF4J API: Mapped Diagnostic Contexts (MDC).

To uniquely stamp each request, the user puts contextual information into the MDC, the abbreviation of Mapped Diagnostic Context. The salient parts of the MDC class are shown below. Please refer to the MDC javadocs for a complete list of methods.

If you would like an alternative to the unpredictable names you get with %thread as I usually do, you can use simple thread-local IDs. Its much easier on the eyes. This will work with logback...

public class ThreadIdConverter extends ClassicConverter {
  private static int nextId = 0;
  private static final ThreadLocal<String> threadId = new ThreadLocal<String>() {    
    @Override
    protected String initialValue() {
      int nextId = nextId();
      return String.format("%05d", nextId);
    }
  };

  private static synchronized int nextId() {
    return ++nextId;
  }

  @Override
  public String convert(ILoggingEvent event) {
    return threadId.get();
  }
}

Then put this simple line in your logback XML:

<conversionRule conversionWord="tid" 
    converterClass="com.yourstuff.logback.ThreadIdConverter" />

Set your pattern something like this (notice "tid"):

<pattern>%d{HH:mm:ss.SSS} [%tid] %-5level - %msg%n</pattern>

And your logs will look like this:

10:32:02.517 [00001] INFO something here
10:32:02.517 [00002] INFO something here
10:32:02.517 [00003] INFO something here
10:32:02.517 [00001] INFO something more here 
10:32:02.517 [00001] INFO something more here

You can do this with any logger that supports custom extensions. Hope it helps.