Spring Boot 3 + Micrometer Tracing: Context empty in Server request/response logs

[grassehh]

Description

Using Spring Boot 3.2.0, micrometer-tracing-bom 1.2.0 and logbook-bom 3.7.0, the request/response logs do not contain the traceId, spanId as well as custom baggages propagated in the MDC context.

Steps to Reproduce

• Clone this project
• Checkout issues/logbook-server-logs branch
• Start the app and call any routes as explained in the README

Actual Behavior

You will see that in the server request/response log, the MDC context is empty:

-MDC:[] -2023-12-08T13:17:27.161+01:00 -TRACE 67311 --- [ctor-http-nio-3] org.zalando.logbook.Logbook              : {"origin":"remote","type":"request","correlation":"cf2236f67267a49f","protocol":"HTTP/1.1","remote":"/127.0.0.1:63495","method":"GET","uri":"http://localhost:8080/coroutine","host":"localhost","path":"/coroutine","scheme":"http","port":"8080","headers":{"Accept":["*/*"],"Authorization":["XXX"],"Host":["localhost:8080"],"User-Agent":["curl/8.1.2"]}}
-MDC:[] -2023-12-08T13:17:27.163+01:00 -TRACE 67311 --- [ctor-http-nio-3] org.zalando.logbook.Logbook              : {"origin":"local","type":"response","correlation":"cf2236f67267a49f","duration":184,"protocol":"HTTP/1.1","status":200,"headers":{"Cache-Control":["no-cache, no-store, max-age=0, must-revalidate"],"content-length":["0"],"Expires":["0"],"Pragma":["no-cache"],"Referrer-Policy":["no-referrer"],"X-Content-Type-Options":["nosniff"],"X-Frame-Options":["DENY"],"X-XSS-Protection":["0"]}}

Expected Behavior

The request/response logs generated by logbook should contain a context like this:

-MDC:[traceId=657309566eee798c062831936ec58587, spanId=86d9f2bade640fd0, myBaggageController=aade4671-0161-455f-93c6-afd5069f4e78, myBaggageFilter=91137173-5881-4d13-a972-79306de60938]

Thank you

[kasmarian]

Looks like if you add

.metrics(true) { uriTagValue: String ->
                            uriTagValue
                        }

to the logbookNettyServerCustomizer, as was suggested in the initial issue you created for reactor-netty (reactor/reactor-netty#2850), you'll start getting the trace id and span id in the log.

I wouldn't be able to tell why it's required, though.

Maybe we could create a separate NettyServerCustomizer and ReactorNettyHttpClientMapper for cases when clients have io.micrometer.context.ContextSnapshotFactory class in the classpath. But not sure if we want to get involved into context propagations of other libraries.

[grassehh]

@kasmarian indeed, the traceId and spanId appears, but not the custom baggages. Also, the traceId is not the same. Here's an example:

-MDC:[traceId=657345d5ade6a80c2d65bba5e4f03aaa, spanId=9f7e35b0d94b7997, myBaggageController=5aefb488-62a3-48ea-961b-ec07a6a7e2f2, myBaggageFilter=658a418b-1222-40d0-8bc4-75e4a7cff490] -2023-12-08T17:35:33.867+01:00 -DEBUG 85932 --- [         task-1] c.g.app.controller.SampleController      : CONTROLLER LOG BEFORE COROUTINE
-MDC:[traceId=657345d5ade6a80c2d65bba5e4f03aaa, spanId=9f7e35b0d94b7997, myBaggageController=5aefb488-62a3-48ea-961b-ec07a6a7e2f2, myBaggageFilter=658a418b-1222-40d0-8bc4-75e4a7cff490] -2023-12-08T17:35:33.870+01:00 -DEBUG 85932 --- [atcher-worker-1] c.g.app.controller.SampleController      : CONTROLLER LOG INSIDE COROUTINE
-MDC:[traceId=657345d5fa2bf0b57a22fc3ee65c058d, spanId=7a22fc3ee65c058d] -2023-12-08T17:35:33.891+01:00 -TRACE 85932 --- [ctor-http-nio-3] org.zalando.logbook.Logbook              : {"origin":"remote","type":"request","correlation":"91c7dd9903717db9","protocol":"HTTP/1.1","remote":"/127.0.0.1:54367","method":"GET","uri":"http://localhost:8080/coroutine","host":"localhost","path":"/coroutine","scheme":"http","port":"8080","headers":{"Accept":["*/*"],"Authorization":["XXX"],"Host":["localhost:8080"],"User-Agent":["curl/8.1.2"]}}
-MDC:[traceId=657345d5fa2bf0b57a22fc3ee65c058d, spanId=7a22fc3ee65c058d] -2023-12-08T17:35:33.892+01:00 -TRACE 85932 --- [ctor-http-nio-3] org.zalando.logbook.Logbook              : {"origin":"local","type":"response","correlation":"91c7dd9903717db9","duration":158,"protocol":"HTTP/1.1","status":200,"headers":{"Cache-Control":["no-cache, no-store, max-age=0, must-revalidate"],"content-length":["0"],"Expires":["0"],"Pragma":["no-cache"],"Referrer-Policy":["no-referrer"],"X-Content-Type-Options":["nosniff"],"X-Frame-Options":["DENY"],"X-XSS-Protection":["0"]}}
-MDC:[traceId=657345d5ade6a80c2d65bba5e4f03aaa, spanId=fc9a87d3c911ec0b, myBaggageController=5aefb488-62a3-48ea-961b-ec07a6a7e2f2, myBaggageFilter=658a418b-1222-40d0-8bc4-75e4a7cff490] -2023-12-08T17:35:34.230+01:00 -TRACE 85932 --- [ctor-http-nio-4] org.zalando.logbook.Logbook              : {"origin":"local","type":"request","correlation":"ca5eeac3ed50a2fd","protocol":"HTTP/1.1","remote":"www.google.fr/142.250.179.67:443","method":"GET","uri":"https://www.google.fr/","host":"www.google.fr","path":"/","scheme":"https","port":"443","headers":{"accept":["*/*"],"accept-encoding":["gzip"],"host":["www.google.fr"],"mybaggagecontroller":["5aefb488-62a3-48ea-961b-ec07a6a7e2f2"],"mybaggagefilter":["658a418b-1222-40d0-8bc4-75e4a7cff490"],"user-agent":["ReactorNetty/1.1.13"],"X-B3-ParentSpanId":["9f7e35b0d94b7997"],"X-B3-Sampled":["1"],"X-B3-SpanId":["fc9a87d3c911ec0b"],"X-B3-TraceId":["657345d5ade6a80c2d65bba5e4f03aaa"]}}

[kasmarian]

@grassehh did I get it right, that the issue with the baggage item is resolved with Spring Framework 6.1.2-SNAPSHOT? Did it also resolve the problem with the traceId being different for server logs? I didn't test it yet myself

[grassehh]

@kasmarian It's quite confusing because I think there were multiple problems in the same issue..
But to sum it up, with 6.1.2-SNAPSHOT, the "traceId" and "spanId" reappear in the context.
However the initially issue, which is that custom baggages do not appear in server request/response logs remains.
I've updated the issues/logbook-server-logs branch of my sample with spring-boot 3.2.1-SNAPSHOT.

[grassehh]

Hello @kasmarian, any update about the initial issue ?

[kasmarian]

I don't have any good progress on this issue, unfortunately. The thread that is used during write of LastHttpContent doesn't have the baggage items in its context. I assume this is happening because this thread has a version of the context prior to the creation of the baggage items in the filter.

To be able to have all the micrometer tracing context be reflected in logbook's logs, especially with reactive applications, it would probably be more sensible to have logbook integrated more deeply with micrometer's infrastructure. So far we didn't plan to have this integration, as we didn't have the need simply.