zalando/logbook

Tracing not working for LogbookClientHandler

rajapanda15 opened this issue · 3 comments

rajapanda15 commented

Description

The LogbookClientHandler in Spring Boot 3 is not printing trace IDs when logging requests and responses using the LogbookClientHandler.

Expected Behavior

The logbook instance passed to LogbookClientHandler should log the trace and span ids.

Actual Behavior

The logs are printing empty/blank values.
image

The below project can be referred
https://github.com/rajapanda15/Springboot3-Logbook.git

kasmarian commented

Related to #1513 ?

grassehh commented

I have the same issue.
I don't know if you are using Micrometer and Webflux, but you can check my issue on Reactor Netty.
I managed to make webClient calls working by overriding Logbook's logbookNettyClientCustomizers and wrapping the LogbookClientHandlerwith a custom Netty's ChannelDuplexHandler as suggested by Violeta.
However, using the same mecanism for customizing the Netty HttpServerdoes not work, even though the LogbookServerHandler is called.

Checkout my sample here on the issues/reactor-netty branch.

msdousti commented

You set log pattern to get the traceId and spanId from the MDC:

logging.pattern.console=%d{yyyy-MM-dd HH:mm:ss.SSS} %5p [${spring.application.name:},%X{traceId:-},%X{spanId:-}] ...

And then expect them to be added to the log lines of Logbook (red boxes below, where they are empty):

image

However, notice that green boxes in the above figure: They show that Logbook is being executed from a separate thread called reactor-http-nio-2, while the original thread was called http-nio-8080-exec-* (not shown in the figure). It appears that WebClient runs in a thread separate from the controller.

The important point to note, from Logback documentation (Logback is an implementation of SLF4J API, and is used behind the scenes by Logbook):

The MDC manages contextual information on a per thread basis.

image

So, here is what happens:

  1. Your controller receives a call, and the MDC is populated by traceId/spanId
  2. The controller calls WebClient without propagating the MDC. It creates a new thread with an empty MDC map.
  3. Any logs printed (regardless whether they are by Logbook or not) will not have traceId/spanId.

This article might be helpful: https://ttddyy.github.io/mdc-with-webclient-in-webmvc/

Pay special attention to Spring Boot 3 section. Hope this helps!