Search code examples
spring-bootspring-cloudspring-webfluxproject-reactorspring-cloud-sleuth

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?

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?

Solution

  • UPDATE 2023: a new article series was published about the current state of context propagation in reactive systems: https://spring.io/blog/2023/03/28/context-propagation-with-project-reactor-1-the-basics

    UPDATE 2021: note there was quite a few changes to this, be sure to check out latest implementation as below link points to an old commit.

    They use Reactor Context along with Reactor Hooks. Relevant code from spring-cloud-sleuth: link

    Couple of other links which might be useful: