查利博客

Java Logging - Log4j 2 Thread Context

In this article, we are going to learn what is the Log4j 2 Thread Context API. In web application, it is likely we will log the contextual information from HTTP requests such as IP addresses, users' information (if any) etc. So if we want to have these kind of information throughtout the HTTP request (could be request of login or transfer money). Shall we just pass the context variables to every subsequent calls? Of course not, luckily Log4j helped Java developers to solve the above problem by providing the supports for Nested Diagnostic Context (NDC) and Mapped Diagnostic Context (MDC) mechanisms. These two are pretty much the same except the usage. Therefore, Log4j 2 combined them and introduced the idea of Thread Context. They suggest using the Thread Context Map which is equivalent to MDC because it is more flexible. Let us look at some examples.

Add Log4j 2 dependency #

By default, Spring Boot uses Logback as the logging provider. We need to manually exclude it and add the Log4j dependency.

<dependency>
  <groupId>org.springframework.boot</groupId>
  <artifactId>spring-boot-starter</artifactId>
  <!-- To use Log4j2, we need to exclude Logback -->
  <exclusions>
    <exclusion>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-logging</artifactId>
    </exclusion>
  </exclusions>
</dependency>
<dependency>
  <groupId>org.springframework.boot</groupId>
  <artifactId>spring-boot-starter-log4j2</artifactId>
</dependency>

Add Log4j 2 Configuration #

Create a xml file named log4j2-spring.xml under the src/main/resources folder and customize it if needed. Also we need to include the ThreadContext when writing logs. Use %x, %X and %X{key} in PatternLayout to print logs for full contents of stack, full contents of Map and values of specified key respectively.

<?xml version="1.0" encoding="UTF-8"?>
<Configuration>
  <Appenders>
    <Console name="Console" target="SYSTEM_OUT">
      <PatternLayout>
        <pattern>%d %p %C{1.} %x %X{ipAddress} %m%n</pattern>
      </PatternLayout>
    </Console>

    <RollingFile name="RollingFile"
      fileName="./logs/spring-boot-logger-log4j2.log"
      filePattern="./logs/$${date:yyyy-MM}/spring-boot-logger-log4j2-%d{-dd-MMMM-yyyy}-%i.log.gz">
      <PatternLayout>
        <pattern>%d %p %C{1.} [%t] %m%n</pattern>
      </PatternLayout>
      <Policies>
        <!-- rollover on startup, daily and when the file reaches
          10 MegaBytes -->
        <OnStartupTriggeringPolicy />
        <SizeBasedTriggeringPolicy
          size="10 MB" />
        <TimeBasedTriggeringPolicy />
      </Policies>
    </RollingFile>
  </Appenders>

  <Loggers>
    <!-- LOG everything at INFO level -->
    <Root level="info">
      <AppenderRef ref="Console" />
      <AppenderRef ref="RollingFile" />
    </Root>

    <!-- LOG "com.caizhenhua*" at TRACE level -->
    <Logger name="com.caizhenhua" level="trace"></Logger>
  </Loggers>

</Configuration>

Create a simple REST API #

import org.apache.logging.log4j.ThreadContext;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;

@RestController
@RequestMapping("/open")
public class ThreadContextExample {
  Logger logger = LoggerFactory.getLogger(ThreadContextExample.class);

  @GetMapping("/testlog")
  public void testlog() {
    testNDC();
    testMDC();
  }
  // ... methods to be implemented
}

So we can test this endpoint by using the curl command:

curl -i http://localhost:8080/open/testlog

NDC Example #

private void testNDC() {
  ThreadContext.push("8.8.8.8");  // Keep track of client's IP address

  logger.info("request login ...");
  logger.info("do authentication ...");
  logger.info("login success ...");
  logger.info("retrieve user info ...");
  logger.info("set session ...");

  ThreadContext.pop();
  ThreadContext.clearStack(); // Release memory
}

Output:

2021-10-28 22:56:20,481 DEBUG c.c.s.h.ThreadContextExample [8.8.8.8]  request login ...
2021-10-28 22:56:20,481 INFO c.c.s.h.ThreadContextExample [8.8.8.8]  do authentication ...
2021-10-28 22:56:20,481 INFO c.c.s.h.ThreadContextExample [8.8.8.8]  login success ...
2021-10-28 22:56:20,481 INFO c.c.s.h.ThreadContextExample [8.8.8.8]  retrieve user info ...
2021-10-28 22:56:20,482 INFO c.c.s.h.ThreadContextExample [8.8.8.8]  set session ...

MDC Example #

private void testMDC() {
  ThreadContext.put("ipAddress", "8.8.4.4");  // Keep track of client's IP address

  logger.info("request login ...");
  logger.info("do authentication ...");
  logger.info("login success ...");
  logger.info("retrieve user info ...");
  logger.info("set session ...");

  ThreadContext.clearMap();   // Release memory
}

Output:

2021-10-28 22:56:20,482 DEBUG c.c.s.h.ThreadContextExample [] 8.8.4.4 request login ...
2021-10-28 22:56:20,483 INFO c.c.s.h.ThreadContextExample [] 8.8.4.4 do authentication ...
2021-10-28 22:56:20,483 INFO c.c.s.h.ThreadContextExample [] 8.8.4.4 login success ...
2021-10-28 22:56:20,483 INFO c.c.s.h.ThreadContextExample [] 8.8.4.4 retrieve user info ...
2021-10-28 22:56:20,483 INFO c.c.s.h.ThreadContextExample [] 8.8.4.4 set session ...

Conclusion #

To conclude, we learned how to use the Log4j 2 Thread Context API to log the contextual information. The code in this article is available on GitHub.