Monday, August 4, 2008

Tracking requests in multithreaded environment

One day night you'll have to troubleshoot your application and figure out what requests are causing error logs to fill up.   You can expedite investigation if you are able to trace every log statement done during processing of the request that resulted in error.  Usually, you can use thread local storage to stick a a random number at the beginning of processing of every request and print it in the logs.  However, since you're using log4j (aren't you? :-) ), you can take advantage of log4j.MDC object - "an instrument for distinguishing interleaved log output from different sources."

Follow these 3 steps:

  • create a log4j decorator object (MyLogDecorator)

import java.util.Random;
import org.apache.log4j.MDC;

public class MyLogDecorator { 
  private static Random myrandom = new Random(); 
  // use enum to ensure compile-time safety 
  public enum LoggerFields{
        RequestId,
        //plus other fields relevant to your app
    }

public static void put(LoggerFields key, Object value){
        MDC.put(key.toString(), value.toString());
}
public static void remove(LoggerFields key){
      MDC.remove(key.toString());
}
/* make sure that context is empty and add a

random request id */

public static void beginRequest(){
if (MDC.getContext()!=null &&

    MDC.getContext().size()>0){
endRequest();

}

put(LoggerFields.RequestId,

    myrandom.nextInt(10000000));
}

public static void endRequest()    {
for(LoggerFields key : LoggerFields.values())    {
            remove(key);
}}
}

  • call MyLogDecorator inside a Tomcat filter. Filter code is fairly standard.  Note that MyLogDecorator.beginRequest() call can be made by any application (e.g. multithreaded command-line up).

public void doFilter(...) {

    MyLogDecorator.beginRequest();
    chain.doFilter(request, response);
}

  • update pattern layout in log4j.xml to automatically add request id to every log statement:

    <param name="ConversionPattern" value="%d{yyyy-MM-dd HH:mm:ss.SSS} -%1X{RequestId} %c - %m%n"/>

No comments: