Saturday, March 10, 2012

Thread Name Based Logging for Log4J

In a multi-threaded environment , it sometimes becomes hard to debug parts of the application because you constantly have logs from multiple threads. Simplest method to debug such cases is to do a grep on the thread name .  I have been asked a few times if it was possible to log messages happening in one thread to a separate file.  I couldn't find such a implementation. Log4J , which is what i have mostly been using , didnt have anything of that kind out there .

The drawback with Log4j configuration is that , you have to assign appenders to packages . So if you wanted to log a particular functionality in a separate file, you have to design your code packages in such a way that all classes related to that functionality  share the same package ( or package hierarchy ) . This is fine and that is how you would usually structure your code. But the problem arises when you use third party libraries . These end up not being captured along with your file , so it becomes useless once you separate a package to use a different log file . 


The only way we could capture the entire flow is  by using the Thread names. ( like we would do with a grep ). So log messages from each thread can be routed to seperate files. Not many would prefer this , i doubt anybody would want to do this . But if you are using a naming convention for threads then it would be easier to do the routing.In my case , we are doing that in my current project. So here is my attempt to do just that with a custom appender for Log4j. 

 ThreadNamePatternAppender is an appender for routing your Logging messages to multiple files by using the thread name patterns as a key . 
E.g You have 2 threads that have the names(Thread.getName())
       Consumer and Producer. 
 You can route the logging from the Consumer Thread to Cosumer.log and logging from Producer Thread to Producer.log with a log4j.properties that  looks as follows


log4j.rootLogger=DEBUG, MY_THREAD_APPENDER

log4j.appender.MY_THREAD_APPENDER=com.rex.logging.appender.ThreadNamePatternAppender
log4j.appender.MY_THREAD_APPENDER.defaultFile=EveryThingElse.log
log4j.appender.MY_THREAD_APPENDER.layout=org.apache.log4j.PatternLayout
log4j.appender.MY_THREAD_APPENDER.layout.ConversionPattern= %-4r [%t] %-5p %c %x - %m%n
log4j.appender.MY_THREAD_APPENDER.threadNameMapping=Consumer>Consumer.log|Producer>Producer.log

  
 This uses a DailyRollingFileAppender internally. So you should be able to use all the parameters   you would use with a DailyRollingFileAppender like DatePattern , Encoding etc. So you can control how frequently the files needs to be rolled over. However you cant control it at each thread level , but you can control it at an appender level.

 If you have multiple threads sharing the Same name or Have similar names , They can be routed to the same file by using * along with the names. 
  
   e.g If there are Threads by the name Consumer-1 , Consumer-2 , Consumer-3 ,     you can route messages from all three threads to the same file as follows .

 log4j.appender.MY_THREAD_APPENDER.threadNameMapping=Consumer*>Consumer.log|Producer>Producer.log


You can add multiple Thread name mappings by separating them with a pipe '|'.


You can download the jar for this from here .  You can view the code here