How does Spring Cloud Sleuth propagate the MDC context in Webflux ouf of the box so that its content can be logged in different threads?

Question

I'd like to know how Spring Cloud Sleuth propagates the MDC context between threads making the MDC params available each of them.

I've read this article https://simonbasle.github.io/2018/02/contextual-logging-with-reactor-context-and-mdc/ that suggests using the subscriber context to propagate MDC state between threads.

I need to do something similar to with other parars from some request headers so I created that puts it into the MDC for the current thread and stores it in the subscriber context. However the next thread that resumes the execution doesn't have it available. Somehow I should call MDC again in the new thread using the value from the context, but how?

@Slf4j
@RequiredArgsConstructor
@Order(Ordered.HIGHEST_PRECEDENCE)
public class ReactiveRequestCorrelationFilter implements WebFilter {

    @Override
    public Mono<Void> filter(ServerWebExchange exchange, WebFilterChain chain) {
        String principal = exchange.getRequest().getHeaders().getFirst("principal-header");
        MDC.put("principal", principal);
        return chain.filter(exchange)
                .subscriberContext(Context.of("principal", principal))
                .doOnTerminate(MDC::clear);
    }

}

Have a look at this controller mapping:

    @GetMapping(value = "/v1/departments", produces = MediaType.APPLICATION_JSON_VALUE)
    public Flux<Department> getDepartments() {
        log.info("getDepartaments");
        return webClient.get().uri("http://someService:8080/api/v1/departamentosFoo").retrieve().bodyToFlux(Departments.class)
                .doOnNext(dep -> log.info("found department {}", dep));
    }

It generates this log:

logging.pattern.console="%magenta([%thread]) [%X{traceId}] [%X{spanId}] [%X{principal}]  - %m%n"

[boundedElastic-2] [d0a916db8be0cbf7] [d0a916db8be0cbf7] []  - getDepartments
[boundedElastic-2] [d0a916db8be0cbf7] [fb2367685db70201] []  - found department Department(id=1, nombre=dep, fechaAlta=Fri Apr 24 14:16:20 CEST 2020, staff=1, tag=, empresa=true)
[reactor-http-nio-3] [d0a916db8be0cbf7] [d0a916db8be0cbf7] []  - found department Department(id=1, nombre=dep, fechaAlta=Fri Apr 24 14:16:20 CEST 2020, staff=1, tag=, empresa=true)

The request started in a reactor-http-nio thread , and then swiched to boundedElastic-2. As you can see the traceId and spanId values are shown but not the one I put in my filter. How did Sleuth manage to propagate its context (traceId spanId) into the other threads?

Answer 1

You don't need any customization to get this to work. All that is required to propagate custom HTTP headers is to tell Sleuth about them:

#The one is on by default
spring.sleuth.log.slf4j.enabled=true

spring.sleuth.propagation-keys=principal-header
spring.sleuth.log.slf4j.whitelisted-mdc-keys=principal-header

(I'm using the properties version, but the same thing works with yaml)

Then in your logback configuration use

[%X{principal-header}]

That's it!

N.B. Personally I would prefer removing the -header bit from the header name.

Answer 2

They use Reactor Context along with Reactor Hooks. Relevant code from spring-cloud-sleuth: link Update: note there was quite a few changes to this, be sure to check out latest implementation as above link points to an old commit.

Couple of other links which might be useful:

• MDC with WebClient in WebMVC
• How can the MDC context be used in the reactive Spring applications
• MdcContextLifter

Answer 3

Doing some research, with the info provided by Martin in his answer, I worked it out as follows:

Updated filter:

@Slf4j
@RequiredArgsConstructor
@Order(Ordered.HIGHEST_PRECEDENCE + 6)
public class ReactiveRequestCorrelationFilter implements WebFilter {

    @Override
    public Mono<Void> filter(ServerWebExchange exchange, WebFilterChain chain) {
        return chain.filter(exchange)
                .doOnSubscribe(s -> {
                    String principal = exchange.getRequest().getHeaders().getFirst("principal-header");
                    ExtraFieldPropagation.set("principal", principal);
                });
    }

}

application.yml

spring:
  sleuth:
    log:
      slf4j:
        whitelisted-mdc-keys: principal
    baggage-keys: principal

With this my custom field started showing up in the logs, with Sleuth taking care of setting it and clearing it from MDC:

[boundedElastic-2] [fadba73bf6447d02] [fadba73bf6447d02] [myprincipal] getDepartaments