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?
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));
}