Reactor-core: Guidance on logging with MDC

[rstoyanchev]

The Reactor documentation has Adding Context To a Reactive Sequence that covers the topic of ThreadLocal alternatives but there is no mention of how to log with MDC context.

@simonbasle has a blog post but I think it must not be easy to find because various suggestions keep showing up that typically tend to not work in all cases or have significant trade-offs.

There should be some guidance that is easier to find. Possibly even a short section in the Reactor docs with a link to the blog post. Whatever it ends up being, we can further link to it from the Spring Framework docs.

A more ambitious option would be to provide logging framework integrations but that could end up as a separate issue. In the mean time some minimal documentation would really help.

[ttddyy]

Hi,

I had usecase using MDC with WebClient and summarized how to do it in my blog post, MDC with WebClient in WebMVC.

I put implementations with Schedulers.onScheduleHook and Schedulers.addExecutorServiceDecorator, as well as Hooks.onEachOperator.

The implementation is I only considerd for WebMVC environment(I haven't thought about pure reactive env), but it is helpful to have such info as well since usage of WebClient brings people to use reactor in servlet environment.

[membersound]

What about the solution presented with reactor.core.publisher.Hooks?
https://github.com/archie-swif/webflux-mdc/tree/master/src/main/java/com/example/webfluxmdc

@ttddyy could you give a working example with Schedulers.onScheduleHook() for spring-boot-2.2.x? I tried both approaches. While the one with Hooks.onEachOperator() worked, the Schedulers solution did not. But as the later looks really nice, I'd prefer it. Still I don't know why it's not working and the MDC is not copied correctly.

[membersound]

Here a proof that the mdc is not retained using the Schedulers approach:

    public static ExchangeFilterFunction logRequest =
        ExchangeFilterFunction.ofRequestProcessor(clientRequest -> {
            System.out.println("MDC=" + MDC.getCopyOfContextMap());
            return Mono.just(clientRequest);
        });

    public static ExchangeFilterFunction logResponse =
        ExchangeFilterFunction.ofResponseProcessor(clientResponse -> {
            System.out.println("MDC=" + MDC.getCopyOfContextMap());
            return Mono.just(clientResponse);
        });

    public static ExchangeFilterFunction mdcFilter = (request, next) -> {
        // here runs on main(request's) thread
        Map<String, String> map = MDC.getCopyOfContextMap();
        return next.exchange(request)
                .doOnRequest(value -> {
                    // here runs on reactor's thread
                    if (map != null) {
                        MDC.setContextMap(map);
                    }
                });
    };

@Configuration
@ConditionalOnClass(WebClient.class)
public class WebClientLoggingAutoConfiguration implements WebClientCustomizer {
    static {
        Schedulers.onScheduleHook("mdc", runnable -> {
            Map<String, String> map = MDC.getCopyOfContextMap();
            return () -> {
                if (map != null) {
                    MDC.setContextMap(map);
                }
                try {
                    runnable.run();
                } finally {
                }
            };
        });
    }

    @Override
    public void customize(WebClient.Builder builder) {
        builder.filter(mdcFilter)
                .filter(logRequest)
                .filter(logResponse);
    }
}

If you execute this, the MDC is correctly filled during the Request logging. But on Response logging the MDC is empty!

[ttddyy]

Hi @membersound

Thanks for checking the post.

There are couple of things:
First, I had typo on my blog post. For mdcFilter, it should be doOnNext instead of doOnRequest. The intention here is to perform MDC-set-operation(mdcFilter) immediately after WebClient exchange has happened in reactor thread. (Sorry for the confusion, I fixed this on my blog post)

    public static ExchangeFilterFunction mdcFilter = (request, next) -> {
        // here runs on main(request's) thread
        Map<String, String> map = MDC.getCopyOfContextMap();
        return next.exchange(request)
                .doOnNext(value -> {       //   <======= HERE
                    // here runs on reactor's thread
                    if (map != null) {
                        MDC.setContextMap(map);
                    }
                });
    };

Another thing is the order of applying filters to WebClient. Since the MDC-set-operation(mdcFilter) needs to happen BEFORE logResponse filter, mdcFilter needs to be added AFTER logResponse filter.

WebClient webClient = WebClient.builder()
        .filter(logResponse)
        .filter(logRequest)
        .filter(mdcFilter)
        .build();

Please try with these two changes.

[membersound]

@ttddyy thanks for the guidance, I could get it working when using your filter order.
Could you go a bit more into detail why only the reverse order works? Are those filters evaluated buttomup? (I'd expect topdown evaluation instead).

Plus I had to change the doOnNext() to doOnEach(), as otherwise the MDC does not get propagated in case of errors!

       return next.exchange(request)
                .doOnEach(value -> {
                    // here runs on reactor's thread
                    if (map != null) MDC.setContextMap(map);
                });

Now the question is: is the Schedulers.onScheduleHook approach better than the Hooks.onEachOperator?

@simonbasle Thanks for adding a faq to MDC logging directly on a Mono/Flux. But this issue is about finding a global MDC configuration so that not each mono/flux has to be boilerplated with logging code. Maybe you could extend the docs regarding this?