Structured logging in Spring Boot with Log4j2, Part 1: Context-enriched logs

8 min readNov 11, 2021

For logs to be useful when debugging thorny issues, context is crucial. Every log should consistently contain key details about the tenant, user, order, etc. associated with the request. Logs must also be structured in order to be parseable and searchable by log aggregators such as DataDog, StackDriver, Kibana, etc.

When I started working with Spring, there were two key goals I was looking to achieve related to logging:

Include key request context details automatically into all log messages associated with a given API request
Log a structured message for every API request providing basic details about the request (e.g. endpoint, query parameters) and the response (e.g. status code, duration)

I was surprised by how few resources I found describing how to achieve these goals in Spring Boot specifically, but also for other newer Java frameworks like Quarkus and Vert.x.

In this two-part series I’ll cover both of these topics, in the context of Spring Boot. In this article, we’ll cover (1) — how to include key request context details in all log messages associated with a given Spring web request.

Quick aside: why Log4j2, not Logback?

If you’re familiar with Spring Boot, you might be wondering, why use Log4j2 when Spring Boot to using Logback as its logging framework?

I won’t debate the pros/cons of the various Java logging libraries, as plenty of other articles have already been written to that effect, but the short answer is this: Log4j2’s async logging substantially outperforms Logback at high transaction volumes, while providing a developer-friendly API that’s fairly easy to use (we’ll compare/contrast a bit more in Part 2 of this series). As a result, my current company has standardized on Log4j2 for high throughput applications. For an intro to using Log4j2 with Spring Boot, please read this brief tutorial.

The need for context

When reviewing log messages, there are often some key pieces of “context” information associated with a given request which ideally would be present in every log message associated with a request, but which differ per-request.

For example, in authenticated applications, having the user id or tenant id (in multi-tenant applications) included in all log messages is very helpful when trying to quickly diagnose an issue, as you can find a given log message, grab the tenant id or user id, and then use those to go search for other errors associated with that user, or check if that tenant has some weird config settings, etc. Or, for internal services, you might have an order number in context, and to diagnose an issue with some step in the processing of that order, you want to filter your logs to just show logs associated with a given order number.

How can we achieve this with Java in Spring Boot?

Mapped Diagnostic Context (MDC)

Both Logback and Log4j2 support a feature called “Mapped Diagnostic Context”, or MDC, where a dictionary/map of context is attached to each thread, which you can then read from and write to as needed. Data stored in a thread’s MDC can be logged using the %X variable. You can either log all of the MDC, or just specific pieces of information, e.g. if your log pattern included %X{orderNumber}, just the value of the "orderNumber" key from a thread's MDC would be logged. Since every web request will be handled by a distinct thread, this gives us exactly what we want (there is a caveat to this, which we’ll cover later).

For example, let’s say we have a controller which allows us to retrieve items associated with an order from a database, which logs to to the console at several different locations:

// Import log4j classes.
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.core.config.plugins.validation.constraints.Required;
import org.springframework.web.bind.annotation.*;import java.util.List;@RestController
public class OrderController {    private static final Logger logger = LogManager.getLogger(OrderController.class);
    private static final Database d = new Database();    @RequestMapping(
            value = "/order/{orderNumber}/items",
            method = RequestMethod.GET,
            produces = "application/json"
    )
    @ResponseBody
    public List<OrderItem> getOrderItems(@PathVariable("orderNumber") @Required String orderNumber) {
        logger.info("Getting order items");        List<OrderItem> orderItems = null;
        try {
            orderItems = d.getItemsForOrder(orderNumber);
        } catch (Exception ex) {
            logger.error("Unable to fetch items from database", ex);
        }        logger.info("Got items, returning!");        return orderItems;
    }}

And here is our Log4j2 configuration file (located at src/main/resources/log4j2.xml):

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
    <Properties>
        <Property name="LOG_PATTERN">
            %d{yyyy-MM-dd HH:mm:ss.SSS} %5p [%15.15t] %-40.40c{1.} : %m%n%ex
        </Property>
    </Properties>
    <Appenders>
        <Console name="ConsoleAppender" target="SYSTEM_OUT" follow="true">
            <PatternLayout pattern="${LOG_PATTERN}"/>
        </Console>
    </Appenders>
    <Loggers>
        <Root level="info">
            <AppenderRef ref="ConsoleAppender" />
        </Root>
    </Loggers>
</Configuration>

If there are no errors fetching from the database, this would output log messages such as the following:

2021-06-07 09:12:02.493 INFO [nio-8080-exec-1] c.z.s.s.OrderController : Getting order items
2021-06-07 09:12:02.498 INFO [nio-8080-exec-1] c.z.s.s.OrderController : Got items, returning2021-06-07 09:12:14.829 INFO [nio-8080-exec-4] c.z.s.s.OrderController : Getting order items
2021-06-07 09:12:14.834 INFO [nio-8080-exec-4] c.z.s.s.OrderController : Got items, returning

These logs aren’t terribly helpful because we don’t know which request or order number each message is associated with, so if there was an error with one order lookup, we wouldn’t be able to effectively debug the sequence of code that ran leading up to the error or have any context about which order was requested when an error occurred.

How can we enrich our log messages with this helpful context?

It’s tempting to just append the order number into each log message string:

logger.info("Getting order items for order {}", orderNumber);
logger.info("Got items for order {}, returning", orderNumber);

Which does get the job done…

2021-06-08 12:14:06.560 INFO [nio-8080-exec-1] c.z.s.s.OrderController : Getting items for order 1111
2021-06-08 12:14:06.560 INFO [nio-8080-exec-1] c.z.s.s.OrderController : Got items for order 1111, returning!2021-06-08 12:15:35.723 INFO [nio-8080-exec-2] c.z.s.s.OrderController : Getting items for order 2313
2021-06-08 12:15:35.723 INFO [nio-8080-exec-2] c.z.s.s.OrderController : Got items for order 2313, returning!

However, this approach is:

Tedious: we have to remember to add the order number to each and every log message.
Inconsistent: it’s tempting to append the order number at different places within the log message, e.g. log.info("Getting items for order: {}", orderNumber) or log.error("Exception when fetching items for order: {}, {}", orderNumber, ex);
Not searchable or parseable by log aggregators: many log aggregators are able to bucket messages by patterns, but as each log message is slightly different, due to the order numbers being distinct, it’s not easy to search all log messages associated with a given order number. To do this, we’d have to use a wildcard free text search across all log messages, which will often be slower and more inefficient depending on the aggregator.

With MDC, there’s a much more elegant way to solve this:

Inject the order number into the associated thread’s MDC at the start of each request
Update our log pattern to output the thread context

Here’s what this looks like for Log4j2:

import org.apache.logging.log4j.ThreadContext;
...
public List<OrderItem> getOrderItems(@PathVariable("orderNumber") @Required String orderNumber) {
    ThreadContext.put("orderNumber", orderNumber);
    logger.info("Getting items");    List<OrderItem> orderItems = null;
    try {
        orderItems = d.getItemsForOrder(orderNumber);
    } catch (Exception ex) {
        logger.error("Unable to fetch items from database for order", ex);
    }    logger.info("Got items, returning");
    ThreadContext.clearAll();
    return orderItems;
}

(For Logback, the corresponding methods are MDC.put(), MDC.clear())

To output this in our logs, we just need to include %Xin our log pattern:

<Property name="LOG_PATTERN">
    %d{yyyy-MM-dd HH:mm:ss.SSS} %5p [%15.15t] %-40.40c{1.} : %X : %m%n%ex
</Property>

Which yields:

2021-06-08 12:25:10.774 INFO [nio-8080-exec-1] c.z.s.s.OrderController : {orderNumber=2313} : Getting items
2021-06-08 12:25:10.774 INFO [nio-8080-exec-1] c.z.s.s.OrderController : {orderNumber=2313} : Got items, returning
2021-06-08 12:25:26.732 INFO [nio-8080-exec-2] c.z.s.s.OrderController : {orderNumber=8291} : Getting items
2021-06-08 12:25:26.732 INFO [nio-8080-exec-2] c.z.s.s.OrderController : {orderNumber=8291} : Got items, returning

Now, if we add additional logs, they will all automatically include the order number included. Moreover, if we need to add additional context data, we don’t have to change individual logging statements at all — — we just need to add the additional context properties to the MDC map.

For example, if our API is responsible for managing orders for multiple retailers, another required parameter might be retailer, and so having a retailer key included in the MDC would be very helpful as well:

@RequestMapping(
        value = "/order/{retailer}/{orderNumber}/items",
        method = RequestMethod.GET,
        produces = "application/json"
)
@ResponseBody
public List<OrderItem> getOrderItems(
        @PathVariable("orderNumber") @Required String orderNumber,
        @PathVariable("retailer") @Required String retailer) {
    ThreadContext.put("orderNumber", orderNumber);
    ThreadContext.put("retailer", retailer);

And that’s it, now we see retailer show up in our logs as well:

12:47:21.766 INFO {orderNumber=8291, retailer=acme} : Getting items
12:47:21.767 INFO {orderNumber=8291, retailer=acme} : Got items
12:47:24.839 INFO {orderNumber=1111, retailer=bees} : Getting items
12:47:24.840 INFO {orderNumber=1111, retailer=bees} : Got items

How to avoid leaky context

Because Spring reuses threads across requests, it is possible for context from one request to leak into a the context map for a different request — a danger that we can avoid by following these rules:

Clear the thread context at the end of a request’s lifecycle — — either manually using ThreadContext.clearAll() , or automatically using CloseableThreadContext (see example below).
Transfer thread context to any other asynchronous threads required to process an inbound request — — for example, if you are making multiple database requests in parallel using a separate thread pool with a bunch ofCompleteableFuture calls, make sure to extract the relevant thread context from the main thread, store it, and then apply this context within the new threads using ThreadContext.putAll(priorContext) .

To eliminate the need to manually clear the thread context at the end of a request/thread lifecycle, you can use a try-with-resources block and CloseableThreadContext, which automatically clears thread context at the end of the try block:

public List<OrderItem> getOrderItems(
        @PathVariable("orderNumber") @Required String orderNumber,
        @PathVariable("retailer") @Required String retailer) {
    try (final CloseableThreadContext.Instance ignored = CloseableThreadContext
        .put("orderNumber", orderNumber)
        .put("retailer", retailer)) {

        logger.info("Getting items");

        List<OrderItem> orderItems = null;
        try {
            orderItems = d.getItemsForOrder(orderNumber);
        } catch (Exception ex) {
            logger.error("Unable to fetch items from database for order", ex);
            throw ex;
        }

        logger.info("Got items, returning");
        return orderItems;
    }
}

Outputting logs as JSON

For logs to be parsed by DataDog, Kibana, StackDriver, etc., they need to be output in a structured format such as JSON. With Log4j2, this is pretty easy to achieve, we just need to switch from a PatternLayoutto a JsonLayout, making sure to include properties="true" , which outputs MDC properties within a contextMapkey in the output JSON. (Note: there are other layouts that enable outputting logs as JSON with Log4j2, but JsonLayout is a simple one that gets the job done)

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
    <Appenders>
        <Console name="ConsoleAppender" target="SYSTEM_OUT" follow="true">
            <JsonLayout complete="false" compact="true" eventEol="true" properties="true"  />
        </Console>
    </Appenders>
    <Loggers>
        <Root level="info">
            <AppenderRef ref="ConsoleAppender" />
        </Root>
    </Loggers>
</Configuration>

This will yield logs like the following (note: with compact="true" there will be no indentation, but I’ve retained indentation for readability)

{
  "instant" : {
    "epochSecond" : 1623175219,
    "nanoOfSecond" : 57747000
  },
  "thread" : "http-nio-8080-exec-2",
  "level" : "INFO",
  "loggerName" : "com.zachelrath.springboot.structuredloggingdemo.OrderController",
  "message" : "Getting items",
  "endOfBatch" : false,
  "loggerFqcn" : "org.apache.logging.log4j.spi.AbstractLogger",
  "contextMap" : {
    "orderNumber" : "12323",
    "retailer" : "acme"
  },
  "threadId" : 25,
  "threadPriority" : 5
}
{
  "instant" : {
    "epochSecond" : 1623175219,
    "nanoOfSecond" : 58120000
  },
  "thread" : "http-nio-8080-exec-2",
  "level" : "INFO",
  "loggerName" : "com.zachelrath.springboot.structuredloggingdemo.OrderController",
  "message" : "Got items, returning",
  "endOfBatch" : false,
  "loggerFqcn" : "org.apache.logging.log4j.spi.AbstractLogger",
  "contextMap" : {
    "orderNumber" : "12323",
    "retailer" : "acme"
  },
  "threadId" : 25,
  "threadPriority" : 5
}

That’s it! Now, in a log aggregator, you should be able to filter for all log messages with a given retailer / order number simply by doing a query such as, for StackDriver:jsonPayload.contextMap.orderNumber="12323" .

Source code

An example Spring Boot application using Log4j2 which demonstrates the approaches shown in this post is available in this Github repo:

https://github.com/zachelrath/structured-logging-spring-boot

What’s next

So far, all of our logs have just output a simple string message, e.g. log.info("Some message") . In my next post, I’ll cover how to log structured object messages with Log4j2, as well as how to log such a structured message on every Spring web request/response containing essential details about the request and response.