How to correctly use slf4j MDC in spring-webflux WebFilter

Question

I referenced with the blog post Contextual Logging with Reactor Context and MDC but I don't know how to access reactor context in WebFilter.

@Component
public class RequestIdFilter implements WebFilter {

    @Override
    public Mono<Void> filter(ServerWebExchange exchange, WebFilterChain chain) {
        List<String> myHeader =  exchange.getRequest().getHeaders().get("X-My-Header");

        if (myHeader != null && !myHeader.isEmpty()) {
            MDC.put("myHeader", myHeader.get(0));
        }

        return chain.filter(exchange);
    }
}

Answer 1

As of Spring Boot 2.2 there is Schedulers.onScheduleHook that enables you to handle MDC:

Schedulers.onScheduleHook("mdc", runnable -> {
    Map<String, String> map = MDC.getCopyOfContextMap();
    return () -> {
        if (map != null) {
            MDC.setContextMap(map);
        }
        try {
            runnable.run();
        } finally {
            MDC.clear();
        }
    };
});

Alternatively, Hooks.onEachOperator can be used to pass around the MDC values via subscriber context.

http://ttddyy.github.io/mdc-with-webclient-in-webmvc/

This is not full MDC solution, e.g. in my case I cannot cleanup MDC values in R2DBC threads.

UPDATE: this article really solves my MDC problem: https://www.novatec-gmbh.de/en/blog/how-can-the-mdc-context-be-used-in-the-reactive-spring-applications/

It provides correct way of updating MDC based on subscriber context.

Combine it with SecurityContext::class.java key populated by AuthenticationWebFilter and you will be able to put user login to your logs.

Answer 2

Here's one solution based on the latest approach, as of May 2021, taken from the official documentation:

import java.util.List;
import java.util.Optional;
import java.util.UUID;
import java.util.function.Consumer;
import lombok.extern.slf4j.Slf4j;
import org.slf4j.MDC;
import org.springframework.context.annotation.Configuration;
import org.springframework.http.HttpHeaders;
import org.springframework.http.server.reactive.ServerHttpRequest;
import org.springframework.web.server.ServerWebExchange;
import org.springframework.web.server.WebFilter;
import org.springframework.web.server.WebFilterChain;
import reactor.core.publisher.Mono;
import reactor.core.publisher.Signal;
import reactor.util.context.Context;

@Slf4j
@Configuration
public class RequestIdFilter implements WebFilter {

  @Override
  public Mono<Void> filter(ServerWebExchange exchange, WebFilterChain chain) {
    ServerHttpRequest request = exchange.getRequest();
    String requestId = getRequestId(request.getHeaders());
    return chain
        .filter(exchange)
        .doOnEach(logOnEach(r -> log.info("{} {}", request.getMethod(), request.getURI())))
        .contextWrite(Context.of("CONTEXT_KEY", requestId));
  }

  private String getRequestId(HttpHeaders headers) {
    List<String> requestIdHeaders = headers.get("X-Request-ID");
    return requestIdHeaders == null || requestIdHeaders.isEmpty()
        ? UUID.randomUUID().toString()
        : requestIdHeaders.get(0);
  }

  public static <T> Consumer<Signal<T>> logOnEach(Consumer<T> logStatement) {
    return signal -> {
      String contextValue = signal.getContextView().get("CONTEXT_KEY");
      try (MDC.MDCCloseable cMdc = MDC.putCloseable("MDC_KEY", contextValue)) {
        logStatement.accept(signal.get());
      }
    };
  }

  public static <T> Consumer<Signal<T>> logOnNext(Consumer<T> logStatement) {
    return signal -> {
      if (!signal.isOnNext()) return;
      String contextValue = signal.getContextView().get("CONTEXT_KEY");
      try (MDC.MDCCloseable cMdc = MDC.putCloseable("MDC_KEY", contextValue)) {
        logStatement.accept(signal.get());
      }
    };
  }
}

Given you have the following line in your application.properties:

logging.pattern.level=[%X{MDC_KEY}] %5p

then every time an endpoint is called your server logs will contain a log like this:

2021-05-06 17:07:41.852 [60b38305-7005-4a05-bac7-ab2636e74d94]  INFO 20158 --- [or-http-epoll-6] my.package.RequestIdFilter    : GET http://localhost:12345/my-endpoint/444444/

Every time you want to log manually something within a reactive context you will have add the following to your reactive chain:

.doOnEach(logOnNext(r -> log.info("Something")))

If you want the X-Request-ID to be propagated to other services for distributed tracing, you need to read it from the reactive context (not from MDC) and wrap your WebClient code with the following:

Mono.deferContextual(
    ctx -> {
      RequestHeadersSpec<?> request = webClient.get().uri(uri);
      request = request.header("X-Request-ID", ctx.get("CONTEXT_KEY"));
      // The rest of your request logic...
    });