Block Image

In questo tutorial vedremo come aggiungere log MDC in Spring WebFlux utilizzando una libreria creata da me, chiamata spring-webflux-mdc disponibile nel Maven Central.

Cosa sono i log MDC

MDC sta per "Mapped Diagnostic Context". L'MDC permette di arricchire i nostri log con dei campi che non sono disponibili nello scope dove viene richiamato il logger.
Ad esempio:

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");
    ...
}

Il primo metodo ha un parametro chiamato requestId che rappresenta l'identificativo della richiesta HTTP. Questo metodo chiama il metodo doSomehing che contiene un log e richiama eventualmente altri metodi.
Vorremmo poter aggiungere ai log di doSomething e a quelli di tutti i metodi richiamati nella catena, la requestId, in modo tale da poter correlare facilmente i log di una stessa richiesta.

Potremmo facilmente farlo modificando la firma di ogni metodo, in modo tale da accettare anche il parametro requestId, ma questo andrebbe contro i principi del Clean Code. I log sono dei "cross cutting concerns", non dovrebbero "sporcare" il codice applicativo. Ed è qui che entra in gioco l'MDC!

L'MDC e il contesto Reactive

In un contesto non Reactive, potremmo risolvere la problematica precedente in questo modo:

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"));
    ...
}

La classe MDC è disponibile in org.slf4j. Non è altro che una mappa di contesto legata a un ThreadLocal. In un contesto non Reactive, sappiamo che a ogni richiesta HTTP corrisponde un Thread del Servlet Container, quindi l'MDC funziona bene.

In un contesto Reactive però, uno stesso thread può gestire più richieste andando di fatto a sovrascrivere la mappa dell'MDC ogni volta che una richiesta inserisce la stessa chiave.

La gestione dell'MDC in Spring WebFlux prima di Spring Boot 3 non era per niente facile!
Fortunatamente con Spring Boot 3, la gestione dell'MDC si è semplificata parecchio. Qui l'articolo completo della doc ufficiale:
Context Propagation with Project Reactor 3.

Tuttavia, un po' di codice bisogna sempre scriverlo.
Il caso più comune nell'utilizzo dell'MDC è inserire nei log dei valori provenienti dagli headers per il tracing dei microservizi.
Ho pensato quindi di creare una libreria che faccia questo e deployarla in Maven Central!

Utilizzo della libreria spring-webflux-mdc

L'esempio che segue è riportato nei test jUnit della libreria.
Per importare la libreria possiamo aggiungere la sua dipendenza nel nostro pom:

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

Ti consiglio comunque di dare sempre un'occhiata all'ultima versione della libreria qui:
Spring WebFlux MDC - Releases.

Ora, se ad esempio utilizziamo AWS, l'header di tracing dei microservizi che AWS inserisce automaticamente ad ogni richiesta è X-Amzn-Trace-Id. Vogliamo inserire il valore di questo header in ogni log della stessa richiesta. Inoltre la chiave MDC deve chiamarsi trace_id. Possiamo farlo facilmente scrivendo nell'application.properties questo:

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

In generale, per ogni header che vogliamo mappare nell'MDC, possiamo aggiungere la property:

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

Inoltre se vogliamo aggiungere la chiave MDC anche quando l'header non è presente, la libreria può aggiungerla inserendo come valore un UUID, in questo modo:

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

Quindi aggiungendo anche questa property, se l'header X-Amzn-Trace-Id è presente, allora viene inserita la chiave MDC trace_id con lo stesso valore dell'header. Se l'header non è presente, la chiave MDC viene ugualmente aggiunta (sempre con nome trace_id) e come valore viene inserito un UUID.
In generale, la property spring.mdc.defaults può essere valorizzata con una lista di stringhe che rappresenta le chiavi degli header eventualmente non presenti che vogliamo inserire comunque nell'MDC.

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

Non ci resta che attivare la libreria aggiungendo @Import(SpringMDC.class) a una classe annotata con @Configuration o con @SpringBootApplication, ad esempio:

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

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

Finito!

E se volessimo aggiungere programmaticamente delle entries MDC?

Se abbiamo la necessità di aggiungere alla mappa dell'MDC dei valori non presenti negli headers, possiamo farlo programmaticamente in questo modo. Innanzitutto ci spostiamo nel primo metodo in cui riusciamo a recuperare quel parametro (quindi sul metodo più "esterno" della catena). Wrappiamo la catena Reactive in una variabile ed utilizziamo il metodo statico MDCUtil.wrapMDC. Ad esempio, il seguente metodo:

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!")))));
}

diventa così:

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);
}

Il metodo wrapMDC ha vari overloading, può accettare un Mono o un Flux, può accettare una sola coppia chiave-valore oppure una Map, se abbiamo necessità di inserire più valori nell'MDC nello stesso punto:

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)));
}

Proviamo la libreria

Nella cartella di test della libreria (github.com/vincenzo-racca/spring-webflux-mdc/tree/main/src/test/java/com/vincenzoracca/webflux/mdc) abbiamo questa classe 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);
    }

Analizziamo il codice:

  • abbiamo divers log, dal metodo principale getMDCExample fino ai metodi privati addProduct e notifyShop
  • i metodo privati hanno il parametro awsTraceId nella firma così da confrontare quest'ultimo con la chiave MDC del log e verificare che la libreria funzioni correttamente
  • i metodi privati vengono eseguiti su un thread diverso rispetto a quello di WebFlux, quindi questo è un buon modo per testare la libreria.

L'application.properties è il seguente:

logging.config=classpath:logback-logstash.xml

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

Utilizziamo l'appender di Logstash in modo tale da avere i log in formato JSON e avere già inclusi le chiavi MDC nei log.

La classe Main è la seguente:


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

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

Eseguiamo l'applicazione e poi lo script src/test/resources/test-client.sh. Questo script effettua 100 chiamate HTTP con un certo grado di concorrenza (utilizza il tool HTTPie invece che cURL).

Analizziamo i log (estrapoliamo giusto una richiesta):

{
   "@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"
}

Possiamo notare che i trace_id del campo message corrispondono sempre alla chiave MDC traceId. Inoltre, gli ultimi 2 log fanno parte di un thread diverso rispetto a quello di WebFlux, ma nonostante tutto non ci siamo persi il valore del trace_id!

Conclusioni

In questo articolo abbiamo visto come utilizzare la libreria spring-webflux-mdc.
Questa libreria permette in modo veloce di aggiungere log MDC in un contesto Reactive senza scrivere alcuna logica di codice.

Trovate il codice completo della libreria su GitHub: spring-web-mdc.

Altri articoli su Spring: Spring.
Articoli su Docker: Docker.

Libri consigliati su Spring, Docker e Kubernetes: