Log4j2 ThreadContext – Fish Tagging

Log4j2 ThreadContext allows us to tag the log statements with multiple unique tags to analyze logs while diagnose a problem in runtime – mostly in multithreaded applications where applications generate plenty of logging in short duration.

For example, we may want to scan all logs for a particular user transaction or complete session. This process is also called fish tagging (i.e. add some extra context information in every log statement). The fish tagging can help using the automated tools for logs such as Splunk.

Let’s see how we can use ThreadContext class for fish tagging in log4j2.

1. Add and Remove Context Information

1.1. ThreadContext.put()

To uniquely stamp each request, ThreadContext provide put(String key, String value) method which accept a key and it’s value. We can add as many tags as we need to capture the whole context information. Note that all methods of the ThreadContext class are static.

package com.howtodoinjava.log4j2.examples;

import java.util.UUID;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.ThreadContext;

public class Log4j2HelloWorldExample 
{
	private static final Logger LOGGER = LogManager.getLogger(Log4j2HelloWorldExample.class.getName());
	
	public static void main(String[] args) 
	{
		//Add context information
		ThreadContext.put("id", UUID.randomUUID().toString());
		ThreadContext.put("ipAddress", "192.168.21.9");
		
		LOGGER.debug("Debug Message Logged !!");
		LOGGER.info("Info Message Logged !!");
		LOGGER.debug("Another Debug Message !!");
		
		//Clear the map
		ThreadContext.clearMap();
		
		LOGGER.debug("Thread Context Cleaned up !!");
		LOGGER.debug("Log message with no context information !!");
	}
}

1.2. ThreadContext.push()

Or We can use ThreadContext’s Stack implemeration with ThreadContext.push(String value) as below:

//Add context information
ThreadContext.push(UUID.randomUUID().toString());
ThreadContext.push("192.168.21.9");

LOGGER.debug("Debug Message Logged !!");
LOGGER.info("Info Message Logged !!");
LOGGER.debug("Another Debug Message !!");

//Clear the map
ThreadContext.clearStack();

LOGGER.debug("Thread Context Cleaned up !!");
LOGGER.debug("Log message with no context information !!");

1.3. ThreadContext.clearMap()

After the transaction is over or context information is no more required, you can empty the information using ThreadContext.clearMap() method.

2. Modify Conversion Pattern

Now to print the above tags in log statements, we need to modify the conversion pattern in the log4j2 configuration file.

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="INFO">
	<Appenders>
		<Console name="console" target="SYSTEM_OUT">
			<PatternLayout
				pattern="[%-5level] %d{yyyy-MM-dd HH:mm:ss.SSS} [%t] [%X{id}] [%X{ipAddress}] %c{1} - %msg%n" />
		</Console>
	</Appenders>
	<Loggers>
		<Root level="debug" additivity="false">
			<AppenderRef ref="console" />
		</Root>
	</Loggers>
</Configuration>

• Use %X by itself to include the full contents of the Map.
• Use %X{key} to include the specified key.
• Use %x to include the full contents of the Stack.

Now when you run the above code – we will get the below output:

 
[DEBUG] 2016-06-21 13:09:56.485 [main] [7cdd4cf0-2c26-4b81-b374-1adce3781499] [192.168.21.9] Log4j2HelloWorldExample - Debug Message Logged !!
[INFO ] 2016-06-21 13:09:56.487 [main] [7cdd4cf0-2c26-4b81-b374-1adce3781499] [192.168.21.9] Log4j2HelloWorldExample - Info Message Logged !!
[DEBUG] 2016-06-21 13:09:56.487 [main] [7cdd4cf0-2c26-4b81-b374-1adce3781499] [192.168.21.9] Log4j2HelloWorldExample - Another Debug Message !!
[DEBUG] 2016-06-21 13:09:56.487 [main] [] [] Log4j2HelloWorldExample - Thread Context Cleaned up !!
[DEBUG] 2016-06-21 13:09:56.487 [main] [] [] Log4j2HelloWorldExample - Log message with no context information !!

As you can see the first three log statements have context information added to them – and the other two statements do not have such information.

Happy Learning !!