Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
lzhaza77 opened this issue May 29, 2023 · 2 comments

Comments

@lzhaza77
Copy link

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
Copy link

grassehh commented Jul 8, 2023

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
Copy link
Collaborator

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

4 participants