Block Image

In this tutorial we will see how to add MDC logs in Spring WebFlux using a library I created, called spring-webflux-mdc available in the Maven Central.

What are MDC logs

MDC stands for "Mapped Diagnostic Context". The MDC allows us to enrich our logs with fields that are not available in the scope where the logger is called.
For example:

public void entrypoint(String requestId, String aString) {
    log.info("Called entrypoint with requestId: {}", requestId);
    doSomehing(aString);
}

public void doSomehing(String aString) {
    log.info("Called doSomehing");
    ...
}

The first method has a parameter called requestId which represents the identifier of the HTTP request. This method calls the doSomehing method which contains a log and eventually calls other methods.
We would like to be able to add the requestId to the logs of doSomething and to the logs of all methods called in the chain, so that we can be able to easily correlate the logs of the same request.

We could easily do this by modifying the signature of each method so that it also accepts the requestId parameter, but this would go against the principles of Clean Code. Logs are cross cutting concerns, they should not "dirty" the application code. And that is where MDC comes in!

The MDC and the Reactive Context

In a non-Reactive context, we could solve the previous problem in this way:

public void entrypoint(String requestId, String aString) {
    log.info("Called entrypoint with requestId: {}", requestId);
    MDC.put("requestId", requestId);
    doSomehing(aString);
}

public void doSomehing(String aString) {
    log.info("Called doSomehing with requestId: {}", MDC.get("requestId"));
    ...
}

The MDC class is available in org.slf4j. It is nothing more than a context map bound to a ThreadLocal. In a non-reactive context, we know that each request HTTP corresponds to a Servlet Container Thread, so the MDC works fine.

In a Reactive context, however, the same thread can handle multiple requests effectively going to override the MDC's context map each time a request enters the same key.

MDC management in Spring WebFlux before Spring Boot 3 was not easy at all!
Fortunately, with Spring Boot 3, MDC management has become much easier. Full article from the official doc here:
Context Propagation with Project Reactor 3.

However, some code should always be written.
The most common case in using MDC is to insert values from headers into the logs for tracing microservices.
So I thought I would create a library that does this and deploy it to Maven Central!

Using the spring-webflux-mdc library.

The following example is given in the jUnit tests of the library.
To import the library we can add its dependency in our pom:

<dependency>
   <groupId>com.vincenzoracca</groupId>
   <artifactId>spring-webflux-mdc</artifactId>
   <version>1.0.2</version>
</dependency>

I still recommend that you always take a look at the latest version of the library here:
Spring WebFlux MDC - Releases.

Now, if we use AWS for example, the microservice tracing header that AWS automatically inserts with each request is X-Amzn-Trace-Id. We want to insert the value of this header in every log of the same request. In addition, the MDC key must be named trace_id. We can easily do this by writing in the application.properties this:

spring.mdc.headers.X-Amzn-Trace-Id=trace_id

In general, for each header we want to map to the MDC, we can add the property:

spring.mdc.headers.<header_key>=<mdc_key>
spring.mdc.headers.<another_header_key>=<another_mdc_key>

In addition, if we want to add the MDC key even when the header is not present, the library can add it by entering a UUID, like this:

spring.mdc.headers.X-Amzn-Trace-Id=trace_id
spring.mdc.defaults=X-Amzn-Trace-Id

So by also adding this property, if the X-Amzn-Trace-Id header is present, then the MDC key is inserted trace_id with the same value as the header. If the header is not present, the MDC key is equally added (again named trace_id) and as the value a UUID is inserted.
In general, the property spring.mdc.defaults can be valued with a list of strings representing header keys possibly not present that we want to include in the MDC anyway.

spring.mdc.defaults=<header_key1>,<header_key2>,...

All we have to do is activate the library by adding @Import(SpringMDC.class) to a class annotated with @Configuration or with @SpringBootApplication, for example:

@SpringBootApplication
@Import(SpringMDC.class)
public class SpringMDCApplication {

    public static void main(String[] args) {
        SpringApplication.run(SpringMDCApplication.class);
    }
}

Finished!

What if we want to add MDC entries programmatically?

If we need to add values to the MDC map that are not in the headers, we can do it programmatically in this way. First, we move to the first method where we can retrieve that parameter (thus on the "outermost" in the chain). We wrap the Reactive chain into a variable and use the static method MDCUtil.wrapMDC. For example, the following method:

public Mono<ResponseEntity<MessageResponse>> aMethod(String username) {
    String userId = retrieveUserId(username);
    return Mono.just("test-another-product")
            .delayElement(Duration.ofMillis(1))
            .flatMap(product ->
                    Flux.concat(
                                    addProduct(product, anHeader),
                                    notifyShop(product, anHeader))
                            .then(Mono.just(ResponseEntity.ok(new MessageResponse("Hello World!")))));
}

becomes like this:

public Mono<ResponseEntity<MessageResponse>> getMDCProgrammaticallyExampleTwo(String username) {
    String userId = retrieveUserId(username);
    Mono<ResponseEntity<MessageResponse>> responseEntityMono = Mono.just("test-another-product")
            .delayElement(Duration.ofMillis(1))
            .flatMap(product ->
                    Flux.concat(
                                    addProduct(product, anHeader),
                                    notifyShop(product, anHeader))
                            .then(Mono.just(ResponseEntity.ok(new MessageResponse("Hello World!")))));

    return MDCUtil.wrapMDC(responseEntityMono, "userId", userId);
}

The wrapMDC method has various overloading, it can accept a Mono or a Flux, it can accept a single key-value pair or a Map, if we need to place multiple values in the MDC at the same point:

public static <T> Mono<T> wrapMDC(Mono<T> mono, Map<String, Object> mdcMap) {
        mdcMap.forEach((key, value) -> registerMDC(key));
        return Mono.defer(() -> mono.contextWrite(Context.of(mdcMap)));
}

public static <T> Mono<T> wrapMDC(Mono<T> mono, String mdcKey, String mdcValue) {
    registerMDC(mdcKey);
    return Mono.defer(() -> mono.contextWrite(Context.of(mdcKey, mdcValue)));
}

public static <T> Flux<T> wrapMDC(Flux<T> flux, Map<String, Object> mdcMap) {
    mdcMap.forEach((key, value) -> registerMDC(key));
    return Flux.defer(() -> flux.contextWrite(Context.of(mdcMap)));
}

public static <T> Flux<T> wrapMDC(Flux<T> flux, String mdcKey, String mdcValue) {
    registerMDC(mdcKey);
    return Flux.defer(() -> flux.contextWrite(Context.of(mdcKey, mdcValue)));
}

Let's try the library

In the library test folder (github.com/vincenzo-racca/spring-webflux-mdc/tree/main/src/test/java/com/vincenzoracca/webflux/mdc) we have this class RestController:

@RestController
@Slf4j
public class MockApi {

    @GetMapping("test-client")
    public Mono<ResponseEntity<MessageResponse>> getMDCExample(@RequestHeader("X-Amzn-Trace-Id") String awsTraceId) {
        log.info("[{}] Called getMDCExample with header:", awsTraceId);
        return Mono.just("test-product")
                .delayElement(Duration.ofMillis(1))
                .flatMap(product ->
                        Flux.concat(
                                        addProduct(product, awsTraceId),
                                        notifyShop(product, awsTraceId))
                                .then(Mono.just(ResponseEntity.ok(new MessageResponse("Hello World!")))));
    }

    Mono<Void> addProduct(String productName, String awsTraceId) {
        log.info("Adding product: {}, with header: {}", productName, awsTraceId);
        return Mono.empty(); // Assume we’re actually storing the product
    }

    Mono<Boolean> notifyShop(String productName, String awsTraceId) {
        log.info("Notifying shop about: {} with header: {}", productName, awsTraceId);
        return Mono.just(true);
    }

Let's analyze the code:

  • we have several logs, from the main method getMDCExample to the private methods addProduct and notifyShop
  • the private methods have the awsTraceId parameter in the signature so we can compare the latter with the MDC key in the log and verify that the library is working properly
  • the private methods run on a different thread than WebFlux, so this is a good way to test the library.

The application.properties is as follows:

logging.config=classpath:logback-logstash.xml

spring.mdc.headers.X-Amzn-Trace-Id=trace_id
spring.mdc.defaults=X-Amzn-Trace-Id

We use the Logstash appender so that we have the logs in JSON format and already have MDC keys included in the logs.

The Main class is as follows:


@SpringBootApplication
@Import(SpringMDC.class)
public class SpringMDCApplication {

    public static void main(String[] args) {
        SpringApplication.run(SpringMDCApplication.class);
    }
}

We run the application and then the script src/test/resources/test-client.sh. This script makes 100 HTTP calls with some degree of of concurrency (it uses the HTTPie tool instead of cURL).

Let's analyze the logs (let's extrapolate just one request):

{
   "@timestamp":"2023-09-17T12:43:58.032351+02:00",
   "@version":"1",
   "message":"[7C98F3AB-4CF3-4A0D-B662-69FE3B6F6295] Called getMDCExample with header:",
   "logger_name":"com.vincenzoracca.webflux.mdc.api.MockApi",
   "thread_name":"reactor-http-kqueue-10",
   "level":"INFO",
   "level_value":20000,
   "trace_id":"7C98F3AB-4CF3-4A0D-B662-69FE3B6F6295"
},
{
    "@timestamp":"2023-09-17T12:43:58.383917+02:00",
    "@version":"1",
    "message":"Adding product: test-product, with header: 7C98F3AB-4CF3-4A0D-B662-69FE3B6F6295",
    "logger_name":"com.vincenzoracca.webflux.mdc.api.MockApi",
    "thread_name":"parallel-1",
    "level":"INFO",
    "level_value":20000,
    "trace_id":"7C98F3AB-4CF3-4A0D-B662-69FE3B6F6295"
},
{
    "@timestamp":"2023-09-17T12:43:58.384182+02:00",
    "@version":"1",
    "message":"Notifying shop about: test-product with header: 7C98F3AB-4CF3-4A0D-B662-69FE3B6F6295",
    "logger_name":"com.vincenzoracca.webflux.mdc.api.MockApi",
    "thread_name":"parallel-1",
    "level":"INFO",
    "level_value":20000,
    "trace_id":"7C98F3AB-4CF3-4A0D-B662-69FE3B6F6295"
}

We can see that the trace_id of the message field always corresponds to the MDC key traceId. Also, the last 2 logs are part of a different thread than the WebFlux thread, but nevertheless we did not miss the value of the trace_id!

Conclusions

In this article we saw how to use the spring-webflux-mdc library.
This library quickly allows you to add MDC logs in a Reactive context without writing any code logic.

Find the full library code on GitHub: spring-web-mdc.

More articles on Spring: Spring.
Articles about Docker: Docker.

Recommended books on Spring, Docker, and Kubernetes: