Saturday, April 9, 2016

The log4j2 ThreadContext with configurable tags

Marking messages with application context tags has a great value for logs analyzing.
A context tag is some application-meaningful data, for example user id, specific application flow etc.

The log4j2 provides mechanism for aggregating tags in context of a thread with the ThreadContext.

Context tags may be put to the ThreadContext like a key/value pairs (map) or pushed by value (stack).
Printing of the accumulated context tags should be done with the dedicated PatternLayout format specifiers.
The map is more flexible since a particular tag may be accessed by the key and so one may control in what order the tags are printed into the log.
The tags in stack are printed all together according to the order they were pushed.

These are the PatternLayout format specifiers for printing context tags:
  • %X - to include the full contents of the map (X is in UPPERCASE)
  • %X{key} - to include the specified key of the map
  • %x - to include the full contents of the stack (x is in lowercase)

Simple Example

The simple example demonstrates usage of Thread Context map and stack.

Entries are added into the ThreadContext map with:
ThreadContext.put("USER", "user-ala");  
ThreadContext.put("EXAMPLE", "example1");  

The same values are added into the ThreadContext stack with:

In order to cause the thread context contents to be printed into the log, the appropriate appender format should be defined in the log4j2 configuration file.

The example defines three console appenders and demonstrates:
  • Logging of the whole ThreadContext map - C1 appender
  • Logging of the particular values of the ThreadContext map - C2 appender; it defines the exact order of tags in the log.
  • Logging of the ThreadContext stack - C3 appender.
Note: The map entry key in the code and in the log4j2 configuration should be exactly the same (it is marked in green).

The source:
 package com.alasch1.logging.examples;  
 import org.apache.logging.log4j.LogManager;  
 import org.apache.logging.log4j.Logger;  
 import org.apache.logging.log4j.ThreadContext;  
 public class SimpleThreadContextExample {  
      private static Logger LOG;  
      public static void main(String[] args) {  
           System.setProperty("log4j.configurationFile", "example1-log4j2.xml");  
           // Logger initialization should be done after setting the log4j2 configuration  
           LOG = LogManager.getLogger();  
      private static void threadContextMapExample() {  
           ThreadContext.put("USER", "user-ala");  
           ThreadContext.put("EXAMPLE", "example1");  
 "This is an example of thread context map");  
      private static void threadContextStackExample() {  
 "This is an example of thread context stack");  

The log4j2 configuration:
 <?xml version="1.0" encoding="UTF-8"?>  
 <Configuration >  
           <Console name="C1">  
                <!-- ThreadContextMap -->  
                          C1: %d %level{length=2} [%X] (%c{1.}.%M:%L) - %m%n  
           <Console name="C2">  
                <!-- ThreadContextMap -->  
                          C2: %d %level{length=2} [%X{USER}|%X{EXAMPLE}] (%c{1.}.%M:%L) - %m%n  
           <Console name="C3">  
                <!-- ThreadContextStack -->  
                          C3: %d %level{length=2} %x (%c{1.}.%M:%L) - %m%n  
           <root level="trace">  
                <appenderRef ref="C1" />  
                <appenderRef ref="C2" />  
                <appenderRef ref="C3" />  
           <logger name="com.alasch1.logging.examples" level="trace" additivity="false">  
                <appenderRef ref="C1" />  
                <appenderRef ref="C2" />  
                <appenderRef ref="C3" />  

A log message is printed several times - for each one of the appenders. The log output:
 C3: 2016-04-07 12:56:22,807 IN [] (c.a.l.e.SimpleThreadContextExample.threadContextMapExample:21) - This is an example of thread context map  
 C1: 2016-04-07 12:56:22,807 IN [{EXAMPLE=example1, USER=user-ala}] (c.a.l.e.SimpleThreadContextExample.threadContextMapExample:21) - This is an example of thread context map  
 C2: 2016-04-07 12:56:22,807 IN [user-ala|example1] (c.a.l.e.SimpleThreadContextExample.threadContextMapExample:21) - This is an example of thread context map  
 C3: 2016-04-07 12:56:22,809 IN [user-ala, example2] (c.a.l.e.SimpleThreadContextExample.threadContextStackExample:30) - This is an example of thread context stack  
 C1: 2016-04-07 12:56:22,809 IN [{}] (c.a.l.e.SimpleThreadContextExample.threadContextStackExample:30) - This is an example of thread context stack  
 C2: 2016-04-07 12:56:22,809 IN [|] (c.a.l.e.SimpleThreadContextExample.threadContextStackExample:30) - This is an example of thread context stack  

The method used for C2 appender has major disadvantages:
- There is coupling between the source and log4j2 configuration: map keys should exactly match in both of them.
- Thread context tags are fixed. Adding of a new tag demands changes in the code and in the log4j2 configuration.
- Touching of the pattern format string for key modification in the log4j2 configuration is error prone.

The configurable tags example solves all the above problems.

Configurable context tags example

The example defines up-6 tags in the log message. The first three tags are initialized by default upon creation of the log context and are: process id, thread id and user id. The rest of tags are the placeholders.

The implementation includes:
  1. The dedicated properties file contains the tag names:
     # log context tags   
     # max 6 tags are supported  
     # tags names are used for log4j ThreadContext map  

  2. Tag values are referred in the log4j2 configuration with the properties lookup:
     <Configuration monitorInterval="300" status="warn" packages="com.alasch1.logging.plugins">  
               <property name="tag1">${bundle:contextTags:tag1}</property>  
               <property name="tag2">${bundle:contextTags:tag2}</property>  
               <property name="tag3">${bundle:contextTags:tag3}</property>  
               <property name="tag4">${bundle:contextTags:tag4}</property>  
               <property name="tag5">${bundle:contextTags:tag5}</property>  
               <property name="tag6">${bundle:contextTags:tag6}</property>  
               <Console name="SysOut">  
                              %d %p [%X{${tag1}}|%X{${tag2}}|%X{${tag3}}|%X{${tag4}}|%X{${tag5}}|%X{${tag6}}] (%c{1.}.%M:%L)- %m%n  

  3. Context tags initialization is encapsulated by the class LogContextHandler:
    protected LogContextHandler(String nullableUserId) {  
           this.userId = nullableUserId != null ? nullableUserId : ANONYMOUS_USER;  
           this.processId = JvmProcessID.get();  
           this.threadId = Long.toString(Thread.currentThread().getId());  

  4. Tag lookups are interpolated into the properties values upon output into the log:
  5.  2016-04-09 01:11:04,664 INFO [5192|1|user-1|||] (c.a.a.LogApplicationTest.printBulkMessages:37)- ApplicationTest Start  

All the sources on Git.

1 comment :

CarlosM said...
This comment has been removed by the author.

About the author

My Photo
I trust only simple code and believe that code should be handsome. This is not a matter of technology, but professional approach, consolidated after years of software development. I enjoy to cause things working and feel very happy, when I manage to solve a problem.
Back to Top