Losing MDC values in some scenarios

[davefarrelly]

Hi @vincenzo-racca

I have been struggling with adding MDC support to my Webflux project for a while now, so it is really great to see this library, thank you for your work!

I am still having issues where I lose the MDC values in certain scenarios and I was wondering if you can help me out. I have modified your example a bit to demonstrate my issue

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

    public Mono<String> getImage(String fileKey) {
        // Has MDC
        log.info("Inside getImage()");

        return getDocumentMetadata(fileKey)
                .flatMap(this::downloadImage);
    }

    private Mono<DocumentMetadata> getDocumentMetadata(String fileKey) {
        // Has MDC
        log.info("Inside getDocumentMetadata()");
        return documentMetadataRepository.findByFileKey(fileKey);
    }

    private Mono<String> downloadImage(DocumentMetadata documentMetadata) {
        // No MDC
        log.info("Inside downloadImage()");
        return Mono.just("example");
    }

Where documentMetadataRepository is a standard ReactiveCrudRepository

public interface DocumentMetadataRepository extends ReactiveCrudRepository<DocumentMetadata, String> {
    Mono<DocumentMetadata> findByFileKey(String fileKey);
}

This issue I am having is that my log inside downloadImage() does not have any MDC values, and I do not understand why.

Logs:

{"@timestamp":"2024-01-10T16:21:49.1136988Z","@version":"1","message":"Inside getImage()","logger_name":"com.vincenzoracca.webflux.mdc.api.MockApi","thread_name":"parallel-7","level":"INFO","level_value":20000,"trace_id":"test"}
{"@timestamp":"2024-01-10T16:21:49.1147004Z","@version":"1","message":"Inside getDocumentMetadata()","logger_name":"com.vincenzoracca.webflux.mdc.api.MockApi","thread_name":"parallel-7","level":"INFO","level_value":20000,"trace_id":"test"}
{"@timestamp":"2024-01-10T16:21:51.2039685Z","@version":"1","message":"Inside downloadImage()","logger_name":"com.vincenzoracca.webflux.mdc.api.MockApi","thread_name":"reactor-tcp-nio-2","level":"INFO","level_value":20000}

And it seems to be related to the repository, as if I replace this with just basic Mono.just(), my downloadImage() method then has MDC values..

    private Mono<DocumentMetadata> getDocumentMetadata(String fileKey) {
        // Has MDC
        log.info("Inside getDocumentMetadata()");
        return Mono.just(new DocumentMetadata());
    }

Have you any idea why this happens? Appreciate any info you can provide!

[vincenzo-racca]

Hi @davefarrelly thank you :)

I tried your example using Mongodb (and ReactiveMongoRepository, which extends ReactiveCrudRepository). The library seems to work correctly:

{"@timestamp":"2024-01-10T22:37:56.03029+01:00","@version":"1","message":"[trace_id_mock] Called getMDCExample with header:","logger_name":"com.vincenzoracca.webflux.mdc.api.MongoApi","thread_name":"reactor-http-kqueue-3","level":"INFO","level_value":20000,"trace_id":"trace_id_mock"}
{"@timestamp":"2024-01-10T22:37:56.036814+01:00","@version":"1","message":"Inside getImage()","logger_name":"com.vincenzoracca.webflux.mdc.api.MongoApi","thread_name":"parallel-1","level":"INFO","level_value":20000,"trace_id":"trace_id_mock"}
{"@timestamp":"2024-01-10T22:37:56.037204+01:00","@version":"1","message":"Inside getDocumentMetadata()","logger_name":"com.vincenzoracca.webflux.mdc.api.MongoApi","thread_name":"parallel-1","level":"INFO","level_value":20000,"trace_id":"trace_id_mock"}
{"@timestamp":"2024-01-10T22:37:56.069064+01:00","@version":"1","message":"Document found: DocumentMetadata(fileKey=fileKey1)","logger_name":"com.vincenzoracca.webflux.mdc.api.MongoApi","thread_name":"nioEventLoopGroup-3-3","level":"INFO","level_value":20000,"trace_id":"trace_id_mock"}
{"@timestamp":"2024-01-10T22:37:56.069448+01:00","@version":"1","message":"Inside downloadImage()","logger_name":"com.vincenzoracca.webflux.mdc.api.MongoApi","thread_name":"nioEventLoopGroup-3-3","level":"INFO","level_value":20000,"trace_id":"trace_id_mock"}

I pushed the example in this branch: https://github.com/vincenzo-racca/spring-webflux-mdc/blob/feature/test-reactive-mongo/src/test/java/com/vincenzoracca/webflux/mdc/api/MongoApi.java#L25

[davefarrelly]

@vincenzo-racca Interesting, I tested your example also and it works great.

Only difference is I am using spring-r2dbc with MS SQL instead of MongoDB. Is it possible that there is something missing on the spring-r2dbc or all reactive libraries should work out of the box?