zalando/logbook

Spring boot 3 reactive with micrometer - no traceId in logs for service calls and webclient

lzhaza77 opened this issue · 2 comments

lzhaza77 commented

With spring boot 3 reactive services the logs from logbook are not using traceId and spanId.

Description

Logs from reactive services are not showing the traceId (and in some cases the spanId).
I have two services, the first one invokes the second one using a webclient.
Logs for the first service:

2023-05-28T20:38:08.083+02:00  INFO [service1,64739f90c9e13ec3a7048d5dfba4c499,a7048d5dfba4c499] 4322 --- [ctor-http-nio-3] o.l.l.s.controller.Service1Controller    : Service calling to service2...
2023-05-28T20:38:08.139+02:00 TRACE [service1,,a7048d5dfba4c499] 4322 --- [ctor-http-nio-3] org.zalando.logbook.Logbook              : {"origin":"remote","type":"request","correlation":"cb3e0b95acf8eee5","protocol":"HTTP/1.1","remote":"/127.0.0.1:50990","method":"GET","uri":"http://localhost:8080/service1","host":"localhost","path":"/service1","scheme":"http","port":"8080","headers":{"Accept":["*/*"],"Host":["localhost:8080"],"User-Agent":["curl/7.88.1"]}}
2023-05-28T20:38:08.147+02:00 TRACE [service1,,a7048d5dfba4c499] 4322 --- [ctor-http-nio-3] org.zalando.logbook.Logbook              : {"origin":"local","type":"request","correlation":"c3bfc83aec2fc445","protocol":"HTTP/1.1","remote":"localhost/127.0.0.1:8081","method":"GET","uri":"http://localhost:8081/service2","host":"localhost","path":"/service2","scheme":"http","port":"8081","headers":{"accept":["*/*"],"host":["localhost:8081"],"traceparent":["00-64739f90c9e13ec3a7048d5dfba4c499-2f50f2a1fa218f10-00"],"user-agent":["ReactorNetty/1.1.7"]}}
2023-05-28T20:38:08.240+02:00 TRACE [service1,,a7048d5dfba4c499] 4322 --- [ctor-http-nio-3] org.zalando.logbook.Logbook              : {"origin":"remote","type":"response","correlation":"c3bfc83aec2fc445","duration":93,"protocol":"HTTP/1.1","status":200,"headers":{"Content-Length":["5"],"Content-Type":["text/plain;charset=UTF-8"]},"body":"done!"}
2023-05-28T20:38:08.246+02:00 TRACE [service1,64739f90c9e13ec3a7048d5dfba4c499,a7048d5dfba4c499] 4322 --- [ctor-http-nio-3] org.zalando.logbook.Logbook              : {"origin":"local","type":"response","correlation":"cb3e0b95acf8eee5","duration":189,"protocol":"HTTP/1.1","status":200,"headers":{"Content-Length":["5"],"Content-Type":["text/plain;charset=UTF-8"]},"body":"done!"}

and the logs for the second service:

2023-05-28T20:38:08.217+02:00  INFO [service2,64739f90c9e13ec3a7048d5dfba4c499,61c824a2d63bbe97] 4353 --- [ctor-http-nio-2] o.l.l.s.controller.Service2Controller    : Received
2023-05-28T20:38:08.251+02:00 TRACE [service2,,] 4353 --- [ctor-http-nio-2] org.zalando.logbook.Logbook              : {"origin":"remote","type":"request","correlation":"face2ef92c7f5d52","protocol":"HTTP/1.1","remote":"/127.0.0.1:50991","method":"GET","uri":"http://localhost:8081/service2","host":"localhost","path":"/service2","scheme":"http","port":"8081","headers":{"accept":["*/*"],"host":["localhost:8081"],"traceparent":["00-64739f90c9e13ec3a7048d5dfba4c499-2f50f2a1fa218f10-00"],"user-agent":["ReactorNetty/1.1.7"]}}
2023-05-28T20:38:08.254+02:00 TRACE [service2,,] 4353 --- [ctor-http-nio-2] org.zalando.logbook.Logbook              : {"origin":"local","type":"response","correlation":"face2ef92c7f5d52","duration":63,"protocol":"HTTP/1.1","status":200,"headers":{"Content-Length":["5"],"Content-Type":["text/plain;charset=UTF-8"]},"body":"done!"}

Expected Behavior

TraceId and spanId should be present in logbook logs.

Steps to Reproduce

In this project you can find all you need to reproduce the error and more information:
https://github.com/lzhaza77/spring-boot-3-logbook-reactive

Your Environment

  • Java 17.0.6
  • Spring boot 3.1.0
  • Logbook 3.0.0
grassehh commented

Hello,

I'm using Spring Boot 3 + Spring Webflux + Logbook Spring Webflux + Kotlinx Coroutine Reactor + Netty Http Brave

Migrating from Spring Boot 2 (w/ Spring Sleuth) to Spring Boot 3 (w/ Micrometer) is being a real pain.

For instance, I have the opposite of your issue: My MDC is correctly traced (kind of) for my internal WebClient calls (i use tracer.createBaggageInScope function to add them into the context), but not my Netty HTTP Server request/response (which is logged after the web client calls too !)

Using Hooks.enableAutomaticContextPropagation() or not does not matter.

Any help is appreciated !

EDIT: I have also created an issue on Reactor Netty here for those who are struggling to log the context in a Spring Boot 3 Webflux + Coroutine environment.

EDIT 2 After a few tests, it seems that calling Hooks.enableAutomaticContextPropagation() make the MDC no longer logged. It seems like there is an issue with Logbook and Reactor integration. I will probably create an issue soon with an example.

msdousti commented

Please take a look at the discussion here:
#1512 (comment)

In short, Logbook prints the "message" part of the log; the rest (like timestaps, thread names, MDC) is handled by SLF4J/Logback. The above discussion shows one possible resolution, though it's unrelated to Logbook.