Custom Baggage not traced in server request/response logs

[grassehh]

Some background first

I had created an issue to Reactor Netty in order to find out how to replace the deprecated ReactorNettyHttpTracing class when migrating from Spring Boot 2 w/ Spring Cloud Sleuth to Spring Boot 3 w/ Micrometer.
After some suggestions from Violetta, we came to a solution that uses Netty's channel handlers mecanism.

Describe the bug

The custom baggages added through the Tracer.createBaggageInScope() method are not traced in the server request/response logs. They are however correctly traced in the controller and webClient calls logs.

Steps to Reproduce

• Clone this project
• Checkout issues/micrometer-tracing branch
• Start the app and call the server as explained in the README

You will see that in the server request/response log, there is no custom baggage logged in the MDC:

-MDC Context: [] - -2023-07-12T19:52:24.119+02:00 -TRACE 42957 --- [ctor-http-nio-4] org.zalando.logbook.Logbook              : {"origin":"local","type":"request","correlation":"896af375872f07c2","protocol":"HTTP/1.1","remote":"google.com/216.58.214.174:443","method":"GET","uri":"https://google.com/","host":"google.com","path":"/","scheme":"https","port":"443","headers":{"accept":["*/*"],"accept-encoding":["gzip"],"b3":["64aee8571dbceb4af15d6f787e96756f-4bba3d9ce759afef-1"],"host":["google.com"],"mybaggagecontroller":["myBaggageControllerValue"],"mybaggagefilter":["myBaggageFilterValue"],"user-agent":["ReactorNetty/1.1.8"]}}

Expected result

The custom baggages in scope (myBaggageFilter and myBaggageControlelr) should be traced in the server request/responses logs.
This used to work with Spring Cloud Sleuth, using ReactorNettyHttpTracing.
This issue is quite blocking for our project because we need to migrate to Spring Boot 3 and we need to have custom baggages to correlate and filter our logs on Datadog.

Thanks for the help

[stefan-g]

I might faceing a similar issue. i'm using spring boot 3.1.4 and micrometer-tracing 1.1.5. The "BaggageField" context propagation for org.springframework.web.reactive.function.client.WebClient header values seems to work but not for mdc values. Hooks.enableAutomaticContextPropagation() is activated.

It might be related to #363 or #359. Sometimes baggage fields are there but not up to date.

I initialized the WebClient like this (using zalando logbook to log request/responses)

@Bean
  public WebClient webClient(@NonNull final ReactorLoadBalancerExchangeFilterFunction lbFunction,
                             @NonNull final WebClient.Builder builder,
                             @NonNull final Logbook logbook) {
    return builder.filter(lbFunction)
                  .clientConnector(new ReactorClientHttpConnector(HttpClient.create()
                                                                            .doOnConnected(connection -> connection.addHandlerLast(new LogbookClientHandler(
                                                                                logbook)))
                                                                            .responseTimeout(Duration.ofSeconds(20))))
                  .build();
  }

and BaggaeField like this:

 @Bean
  public BaggageField getBaggageFieldSessionId() {
    return BaggageField.create("x-session-id");
  }

  @Bean
  public CurrentTraceContext.ScopeDecorator mdcScopeDecorator(@NonNull final BaggageField field) {
    return MDCScopeDecorator.newBuilder()
                            .add(newBuilder(field).name("sessionId")
                                                           .flushOnUpdate()
                                                           .build())
                            .build();
  }

[grassehh]

@stefan-g

As for the WebClient side, it works for me, you can take a look at my WebClient configuration in my sample. The trick is to wrap Logbook's server handler with some custom Netty handler that restores a the context during the pipeline.
My issue is rather related to the server logs specifically.

[stefan-g]

@grassehh are you sure the whole configuration is necessary? i miss the simplicity from sleuth....

[grassehh]

@grassehh are you sure the whole configuration is necessary? i miss the simplicity from sleuth....

Pretty sure, somehow the Logbook server handler does not seem to be compatible out of the box with Netty. Check this issue reactor/reactor-netty#2850, this is where the suggestions have been made.
Feel free to try my sample if you want to test it out :)

On Spring Boot 2 with Spring Sleuth, you had to configure it using ReactorNettyHttpTracing:

@Bean
fun reactorNettyHttpTracing(httpTracing: HttpTracing) = ReactorNettyHttpTracing.create(httpTracing)

@Bean
fun httpClientCustomizer(reactorNettyHttpTracing: ReactorNettyHttpTracing) = ReactorNettyHttpClientMapper {
    reactorNettyHttpTracing.decorateHttpClient(it)
}

@Bean
fun webClientCustomizer(clientHttpConnector: ClientHttpConnector) = WebClientCustomizer {
    it.clientConnector(clientHttpConnector)
}

Maybe Micrometer could add some specific instrumentation for Spring or Netty I don't know, but for now, they are totally separated projects.

[marcingrzejszczak]

@violetagg what is the current micrometer observation way of instrumenting this? ☝️

[violetagg]

https://github.com/grassehh/spring-boot-3-tracing-coroutine/blob/issues/reactor-netty-java/app/src/main/java/com/grassehh/app/configuration/ServerConfiguration.java

https://github.com/grassehh/spring-boot-3-tracing-coroutine/blob/issues/reactor-netty-java/app/src/main/java/com/grassehh/app/configuration/ClientConfiguration.java

[violetagg]

From what I understood the trace id is there, only the custom baggage is not. @grassehh Is that correct?

[stefan-g]

it worked when i add a TracingChannelDuplexHandler to the WebClient. In my case custom baggage fields seems to work as well.

@grassehh thanks for your help and sorry for capture your issue

[violetagg]

yes for the client there is no issue, the issue is for the server

[grassehh]

@violetagg @marcingrzejszczak @stefan-g
Somehow, on my main branch, the webClient works without declaring the logbookNettyClientCustomizer

[marcingrzejszczak]

There are too many things going on in your reproducer @grassehh. You're using Kotlin Coroutines that itself have some issues #174 . Can we simplify the sample to use only the basic building blocks (e.g. no Kotlin) ?

[grassehh]

@marcingrzejszczak make sure you checkout the issues/micrometer-tracing branch. It is in Java.

[grassehh]

@violetagg @marcingrzejszczak since spring-boot 3.2.0 and/or micrometer-tracing-bom 3.7.0, the traceId in the server logs is now different than in the other logs.
For example:

@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"]}}

As of the missing custom baggages, the issue is still present. I also created an issue on logbook as I'm not sure about who's responsible of fixing this (Logbook, Micrometer or Spring).

[violetagg]

@grassehh Can you please test with Spring Framework 6.1.2-SNAPSHOT?

[grassehh]

@grassehh Can you please test with Spring Framework 6.1.2-SNAPSHOT?

Confirm this works with 6.1.2-SNAPSHOT !
Thanks :)

[marcingrzejszczak]

Thanks for checking @grassehh !