Spring-Webflux: Add jaeger traceId to log via MDC

Question

I use Sping-Webflux and want to automatically add jaeger traceId into my @Slf4j log.

I have an appender in my logback.xml with %X{traceId} pattern like this

<Pattern>
     %d{yyyy-MM-dd HH:mm:ss} %X{traceId} -2048msg%n
</Pattern>

Following to this answer on a similiar topic I have created a custom web filter where I added traceId into MDC:

@Component
@RequiredArgsConstructor
public class CustomWebFilter implements WebFilter {

    private final Tracer tracer;

    @Override
    public Mono<Void> filter(ServerWebExchange exchange, WebFilterChain chain) {
        SpanContext spanContext = tracer.activeSpan().context();
        MDC.put("traceId", spanContext.toTraceId());
        return chain
            .filter(exchange);
    }
}

I have tested it and it seems it works. But I have doubts that this solution is correct. I do not understand how a static MDC.put can handle simultaneously multiple different log events if they happen at the same time? When I put traceId into MDC will it affect all logs or only the required log which is linked to the web request?

Answer 1

I found the answer in this very helpful article on habr. I followed the solution described in the article and realized the following:

@Component
@RequiredArgsConstructor
public class CustomWebFilter implements WebFilter {

    private final Tracer tracer;

    @Override
    public Mono<Void> filter(ServerWebExchange exchange, WebFilterChain chain) {
        return chain.filter(exchange)
                .doOnSubscribe(subscription -> {
                    SpanContext spanContext = tracer.activeSpan().context();
                    MDC.put("traceId", spanContext.toTraceId());
                })
                .doFinally(signalType -> {
                    MDC.remove("traceId");
                });
    }
}

As described in the article that solution has a limitation: it will not work if you will operate manually with a new thread creation - for example when using subscribeOn(Schedulers.boundedElastic()). This case is covered in the chapter "Дополнение" via Schedulers.onScheduleHook.

There is also an official solution from projectreactor faq on how to handle mdc for logging. You will find it here. This solution is different from the habr article as it requires extra code and explicit set of contextWrite everytime you want to log the event.

Firstly, you introduce this helper function

public static <T> Consumer<Signal<T>> logOnNext(Consumer<T> logStatement) {
    return signal -> {
        if (!signal.isOnNext()) return;
        Optional<String> toPutInMdc = signal.getContext().getOrEmpty("traceId");

        toPutInMdc.ifPresentOrElse(tpim -> {
        try (MDC.MDCCloseable cMdc = MDC.putCloseable("traceId", tpim)) {
            logStatement.accept(signal.get());
        }
    },
    () -> logStatement.accept(signal.get()));
    };
}

Secondly, everytime you log something you need to call explicitly logOnNext and put traceId into reactive context:

@GetMapping("/byPrice")
public Flux<Restaurant> byPrice(@RequestParam Double maxPrice) {    
    return restaurantService.byPrice(maxPrice))
        .doOnEach(logOnNext(r -> LOG.debug("found restaurant {}", r.getName())))
        .contextWrite(Context.of("traceId", traceId));
}