Logging Thread Names with Log4j

In some applications that start multiple threads to handle some concurrent processing, tracking the activity for a particular thread can be tricky. Take the following log file snippet where a group of JMS messages are sent off all around the same time:

2011-11-15 10:08:25,460 INFO  [JmsMessageSender:?] Sending message to queue: UPDATE.REQ.QUEUE
2011-11-15 10:08:25,460 INFO  [JMSMessageReceiver:47] Using JMS Selector JMSCorrelationID='d6d3278b-7f7d-47f5-9d1f-a67e4100d800'
2011-11-15 10:08:25,461 INFO  [JmsMessageSender:?] Sending message to queue: UPDATE.REQ.QUEUE
2011-11-15 10:08:25,489 INFO  [JMSMessageSender:60] Using replyToQueue UPDATE.RESP.QUEUE
2011-11-15 10:08:25,486 INFO  [JMSMessageReceiver:47] Using JMS Selector JMSCorrelationID='10287b5f-c061-4bba-8d9d-f92dbf6fb239'
2011-11-15 10:08:25,489 INFO  [JMSMessageSender:60] Using replyToQueue UPDATE.RESP.QUEUE
2011-11-15 10:08:25,505 INFO  [JMSMessageReceiver:47] Using JMS Selector JMSCorrelationID='b7892699-8f26-4260-ae36-62fa8b09c9c3'
2011-11-15 10:08:25,517 INFO  [JmsMessageSender:?] Received message from queue UPDATE.RESP.QUEUE
2011-11-15 10:08:25,564 INFO  [JmsMessageSender:?] Received message from queue UPDATE.RESP.QUEUE

With the case above, where many messages are sent and the responses will be eventually dealt with for further processing (which will also be logged), we could filter the log
Message on the thread to help track where something may have gone wrong.

The logging patterns for log4j allow for logging the name of the thread with %t. Here is the pattern used to output the messages above:

log4j.appender.outFile.layout.ConversionPattern=%d{ISO8601} %-5p [%c{1}:%L] %m%n

We can add the %t next to the class (%c):

log4j.appender.outFile.layout.ConversionPattern=%d{ISO8601} %-5p [%t:%c{1}:%L] %m%n

The next run produces similar logging statements with the thread name. As this is a Spring Batch application, the threads are named after the class handling their creation, SimpleAsyncTaskExecutor, with a number appened on as in: SimpleAsyncTaskExecutor-5

2011-11-15 10:57:51,643 INFO  [SimpleAsyncTaskExecutor-5:JMSMessageSender:47] Sending to destination queue UPDATE.REQ.QUEUE
2011-11-15 10:57:51,659 INFO  [SimpleAsyncTaskExecutor-5:JMSMessageSender:60] Using replyToQueue UPDATE.RESP.QUEUE
2011-11-15 10:57:51,665 INFO  [SimpleAsyncTaskExecutor-4:JmsMessageSender:?] Sending message to queue: UPDATE.REQ.QUEUE
2011-11-15 10:57:51,665 INFO  [SimpleAsyncTaskExecutor-4:JMSMessageSender:47] Sending to destination queue UPDATE.REQ.QUEUE
2011-11-15 10:57:51,666 INFO  [SimpleAsyncTaskExecutor-5:JMSMessageReceiver:47] Using JMS Selector JMSCorrelationID='846cc984-84fd-47a5-bfd3-c293da829927'
2011-11-15 10:57:51,687 INFO  [SimpleAsyncTaskExecutor-4:JMSMessageSender:60] Using replyToQueue UPDATE.RESP.QUEUE
2011-11-15 10:57:51,695 INFO  [SimpleAsyncTaskExecutor-4:JMSMessageReceiver:47] Using JMS Selector JMSCorrelationID='d44087e2-bd19-474a-a8d1-71ac0fc618a7'
2011-11-15 10:57:51,827 INFO  [SimpleAsyncTaskExecutor-5:JmsMessageSender:?] Received message from queue UPDATE.RESP.QUEUE
2011-11-15 10:57:51,831 INFO  [SimpleAsyncTaskExecutor-4:JmsMessageSender:?] Received message from queue UPDATE.RESP.QUEUE

Here we can now map request and responses to particular threads if we were to encounter a error (that's logged of course) later in processing.

I'm sure something similar can be done with the newer logging frameworks as well.