Logging parallel threads in logback

Question

I'll try to make a brief description of my Selenium framework so that I can explain my problem.

I use Selenium 2 (current version 2.3.1) + testNG 5.14

I set testng.xml file to run the tests in the test suite in parallel, just 2 instances

For logging purposes, I use logback (I've read is the next best thing in the log world)

My problem is that when checking what the application logs I get something like this:

18:48:58.551 [TestNG] INFO d.a.a.s.t.setup.TestConfiguration - Retrieving random User from User Pool

18:48:58.551 [TestNG] INFO d.a.a.s.t.setup.TestConfiguration - Retrieving random User from User Pool

18:48:58.551 [TestNG] DEBUG d.a.a.s.t.setup.TestConfiguration - Creating DataSource for acccessing DataBase

18:48:58.551 [TestNG] DEBUG d.a.a.s.t.setup.TestConfiguration - Creating DataSource for acccessing DataBase

18:48:58.552 [TestNG] DEBUG d.a.a.s.t.setup.TestConfiguration - Launching SQL Query

18:48:58.552 [TestNG] DEBUG d.a.a.s.t.setup.TestConfiguration - Launching SQL Query

18:48:59.613 [TestNG] TRACE d.a.a.s.t.setup.TestConfiguration - Query succesful

18:48:59.613 [TestNG] TRACE d.a.a.s.t.setup.TestConfiguration - Query succesful

As you may see, it is impossible to see the difference between the two threads that are running at the same time. My question is, is there a way I can configure the logback settings so that they also add a number or Id to identify each thread that is running?

PD Just in case it may help, my logback.xml file looks like this:

<?xml version="1.0" encoding="UTF-8"?>
<configuration>

  <appender name="FILE" class="ch.qos.logback.core.FileAppender">
    <file>logs/selenium.log</file>

    <encoder>
      <pattern>%date %level [%thread] %logger{10} [%file:%line] %msg%n</pattern>
    </encoder>
  </appender>

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <!-- encoders are assigned the type
         ch.qos.logback.classic.encoder.PatternLayoutEncoder by default -->
    <encoder>
      <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
  </appender>

  <root level="trace">
    <appender-ref ref="FILE" />
    <appender-ref ref="STDOUT" />
  </root>
</configuration>

Answer 1

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.

Answer 2

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.