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:
- Cloud Native Spring in Action: https://amzn.to/3xZFg1S
- Pro Spring 5 (Spring da zero a hero): https://amzn.to/3KvfWWO
- Pivotal Certified Professional Core Spring 5 Developer Exam: A Study Guide Using Spring Framework 5 (per certificazione Spring): https://amzn.to/3KxbJSC
- Pro Spring Boot 2: An Authoritative Guide to Building Microservices, Web and Enterprise Applications, and Best Practices (Spring Boot del dettaglio): https://amzn.to/3TrIZic
- Docker: Sviluppare e rilasciare software tramite container: https://amzn.to/3AZEGDI
- Kubernetes. Guida per gestire e orchestrare i container : https://amzn.to/45RoqBJ