Spring Boot 3 Webflux project missing traceId and spanId in logs

[sanderino666]

When upgrading to Spring Boot 3 (and Micrometer) I noticed the traceId and spanId are not added to the logs when it's a Webflux project.

Webflux: https://github.com/sanderino666/webflux-micrometer-logs

2022-11-26T17:27:44.991+01:00 INFO [,,] 19376 --- [ctor-http-nio-3] com.example.demo.DemoApplication : home() has been called

MVC: https://github.com/sanderino666/mvc-micrometer-logs

2022-11-26T17:24:12.050+01:00 INFO [,63823dabe8475ad8d31ec1fc81853dcc,d31ec1fc81853dcc] 1848 --- [nio-8080-exec-1] com.example.demomvc.DemoMvcApplication : home() has been called

[bclozel]

This is the expected behavior. See spring-projects/spring-framework#29466

I'm keeping this opened for now as we need to find the best place to document this.

[sanderino666]

Interesting, we are switching from Spring Cloud Sleuth to Micrometer and with SCS this all worked just like it did in a MVC app. Was that sheer luck?

I am trying to understand the answers spring-projects/spring-framework#29466, does it mean we have to wrap each time we want pass the traceId and spanId to the logs?

[codependent]

I was also surprised when upgraded and didn't see the traceId/spanId in the logs anymore. It'd be really helpful to document the change of behaviour and how to make it work in webflux applications.

[codependent]

I guess we are expected to open the scope using the observation located in the context, aren't we?

This allowed the creation of the traceId/spanId. However the WebClient doesn't seem to be propagating the correlation headers. Could you point at how we can achieve that? I think Sleuth automatically instrumented the WebClient, is there an equivalent with Micrometer Tracing or we should implement it by ourselves?

    @GetMapping("/hello")
    fun hello(): Mono<String> {
        return webClient.get().uri("http://localhost:7654/helloWc")
            .retrieve()
            .bodyToMono(String::class.java)
            .doOnNext {
                logger.info("Retrieved hello")
            }
            .contextWrite{ context: Context ->
                val observation = context.get<Observation>(ObservationThreadLocalAccessor.KEY)
                observation.openScope()
                logger.info("Generated traceId/spanId")
                context
            }
    }

    @GetMapping("/helloWc")
    fun helloWc(): Mono<String> {
        return Mono.just("HelloWc")
            .map {
                logger.info("HelloWc map!")
                it
            }
            .contextWrite{ context: Context ->
                val observation = context.get<Observation>(ObservationThreadLocalAccessor.KEY)
                observation.openScope()
                logger.info("Propagated traceId - generated spanId")
                context
            }
    }

2022-11-28T23:34:15.761+01:00  INFO [server,638537626c6674288df2d3f47ac89a95,8df2d3f47ac89a95] 15811 --- [ctor-http-nio-2] d.DemotracingApplication$$SpringCGLIB$$0 : Generated traceId/spanId
2022-11-28T23:34:20.625+01:00  INFO [server,6385376b55b888c43c9ede86ca645b6f,3c9ede86ca645b6f] 15811 --- [ctor-http-nio-3] d.DemotracingApplication$$SpringCGLIB$$0 : Propagated traceId - generated spanId
2022-11-28T23:34:22.242+01:00  INFO [server,6385376b55b888c43c9ede86ca645b6f,3c9ede86ca645b6f] 15811 --- [ctor-http-nio-3] d.DemotracingApplication$$SpringCGLIB$$0 : HelloWc map!
2022-11-28T23:34:23.074+01:00  INFO [server,638537626c6674288df2d3f47ac89a95,8df2d3f47ac89a95] 15811 --- [ctor-http-nio-2] d.DemotracingApplication$$SpringCGLIB$$0 : Retrieved hello

Notice the Propagated traceId - generated spanId has a new traceId (6385376b55b888c43c9ede86ca645b6f) instead of the original one (638537626c6674288df2d3f47ac89a95)

[wilkinsona]

/cc @marcingrzejszczak

[marcingrzejszczak]

WebClient automatically injects trace context to the headers - https://github.com/spring-projects/spring-framework/blob/main/spring-webflux/src/test/java/org/springframework/web/reactive/function/client/WebClientObservationTests.java . We have also standalone samples for that here https://github.com/micrometer-metrics/micrometer-samples/tree/main/webclient

I guess we are expected to open the scope using the observation located in the context, aren't we?

You don't have to because you will pollute the threads. What we do is we require the ObservationThreadLocalAccessor.KEY to be there in Reactor Context and then we manually correlate observations - https://github.com/spring-projects/spring-framework/blob/main/spring-webflux/src/main/java/org/springframework/web/reactive/function/client/DefaultWebClient.java#L464

Have you created the WebFilter as a bean like this? https://github.com/micrometer-metrics/micrometer-samples/blob/main/webclient/src/main/java/com/example/micrometer/WebClientApplication.java#L48 Maybe your ObservationRegistry wasn't injected. For sure you shouldn't open scopes as you showed that in the sample.

[marcingrzejszczak]

I am trying to understand the answers spring-projects/spring-framework#29466, does it mean we have to wrap each time we want pass the traceId and spanId to the logs?

For now yes, you can read more about it here https://micrometer.io/docs/observation#instrumentation_of_reactive_libraries

[codependent]

@marcingrzejszczak thanks for the clarification, I'll go over the references you provided.

[codependent]

@marcingrzejszczak

I've updated the sample, now it looks like this:

@RestController
@SpringBootApplication
class DemotracingApplication(
    private val webClient: WebClient,
    private val observationRegistry: ObservationRegistry,
    private val tracer: Tracer
) {

    private val logger = LoggerFactory.getLogger(javaClass)

    @GetMapping("/hello")
    fun hello(): Mono<String> {
        val observation: Observation = Observation.start("webclient-sample", observationRegistry)
        return Mono.just(observation).flatMap { span ->
            observation.scoped {
                logger.info("Hello!")
            }
            webClient.get().uri("http://localhost:7654/helloWc")
                .retrieve()
                .bodyToMono(String::class.java)
                .doOnNext {
                    observation.scoped {
                        logger.info("Retrieved hello")
                    }
                }
        }.doFinally { signalType ->
            observation.stop()
        }.contextWrite { it.put(ObservationThreadLocalAccessor.KEY, observation) }
    }

    @GetMapping("/helloWc")
    fun helloWc(): Mono<String> {
        val observation: Observation = Observation.start("webclient-samplewc", observationRegistry)
        observation.scoped {
            logger.info("HelloWc!")
        }
        return Mono.just("HelloWc")
            .map {
                observation.scoped {
                    logger.info("HelloWc map!")
                }
                it
            }
    }
}

The WebClient is defined as a bean:

@Configuration
internal class WebClientConfiguration {

    @Bean
    fun webClient (): WebClient {
        return WebClient.builder().build()
    }
}

I can see the generated traceId/spanId in the observation.scoped block logs. However, the service that is invoked by the WebClient still shows a different traceId:

2022-11-29T17:05:58.008+01:00  INFO [server,63862de503de9741d4bf5e608895f0b6,d4bf5e608895f0b6] 19035 --- [ctor-http-nio-2] d.DemotracingApplication$$SpringCGLIB$$0 : Hello!
2022-11-29T17:05:58.243+01:00  INFO [server,63862de60d0ff4fcb42ff242ce42f22c,b42ff242ce42f22c] 19035 --- [ctor-http-nio-3] d.DemotracingApplication$$SpringCGLIB$$0 : HelloWc!
2022-11-29T17:05:58.244+01:00  INFO [server,63862de60d0ff4fcb42ff242ce42f22c,b42ff242ce42f22c] 19035 --- [ctor-http-nio-3] d.DemotracingApplication$$SpringCGLIB$$0 : HelloWc map!
2022-11-29T17:05:58.265+01:00  INFO [server,63862de503de9741d4bf5e608895f0b6,d4bf5e608895f0b6] 19035 --- [ctor-http-nio-2] d.DemotracingApplication$$SpringCGLIB$$0 : Retrieved hello

What am I missing?

[wilkinsona]

@codependent You should inject the auto-configured WebClient.Builder rather than creating a new one and then call build() on it to create your WebClient bean. Using the auto-configured builder ensures that the client's instrumented for observation.

[codependent]

@wilkinsona How strange, I updated it to use the WebClient.Builder but still see that requests aren't being correlated.

The sample project I'm using is available here in case you can have a look a it: https://github.com/codependent/demotracing

@Configuration
internal class WebClientConfiguration {

    @Bean
    fun webClient (webClientBuilder: WebClient.Builder): WebClient {
        return webClientBuilder.build()
    }
}

2022-11-29T17:51:10.870+01:00  INFO [server,6386387e6592debc20bd5a56f3a991a9,20bd5a56f3a991a9] 19544 --- [ctor-http-nio-3] d.DemotracingApplication$$SpringCGLIB$$0 : Hello!
2022-11-29T17:51:10.969+01:00  INFO [server,6386387ed0cd998c9e9e1aa80a2fd1ea,9e9e1aa80a2fd1ea] 19544 --- [ctor-http-nio-4] d.DemotracingApplication$$SpringCGLIB$$0 : HelloWc!
2022-11-29T17:51:10.970+01:00  INFO [server,6386387ed0cd998c9e9e1aa80a2fd1ea,9e9e1aa80a2fd1ea] 19544 --- [ctor-http-nio-4] d.DemotracingApplication$$SpringCGLIB$$0 : HelloWc map!
2022-11-29T17:51:10.994+01:00  INFO [server,6386387e6592debc20bd5a56f3a991a9,20bd5a56f3a991a9] 19544 --- [ctor-http-nio-3] d.DemotracingApplication$$SpringCGLIB$$0 : Retrieved hello

[codependent]

I had a look at the Webflux sample and adapted the code:

    @GetMapping("/hello")
    fun hello(): Mono<String> {
        return Mono.deferContextual { contextView: ContextView ->
            ContextSnapshot.setThreadLocalsFrom(contextView, ObservationThreadLocalAccessor.KEY)
                .use { scope: ContextSnapshot.Scope ->
                    val traceId = tracer.currentSpan()!!.context().traceId()
                    logger.info("<ACCEPTANCE_TEST> <TRACE:{}> Hello!", traceId)
                    webClient.get().uri("http://localhost:7654/helloWc")
                        .retrieve()
                        .bodyToMono(String::class.java)
                        .doOnNext {
                            logger.info("Retrieved helloWc {}", it)
                        }
                }
        }
    }

    @GetMapping("/helloWc")
    fun helloWc(): Mono<String> {
        return Mono.deferContextual { contextView: ContextView ->
            ContextSnapshot.setThreadLocalsFrom(contextView, ObservationThreadLocalAccessor.KEY)
                .use { scope: ContextSnapshot.Scope ->
                    val traceId = tracer.currentSpan()!!.context().traceId()
                    logger.info("<ACCEPTANCE_TEST> <TRACE:{}> HelloWc", traceId)
                    Mono.just(traceId)
            }
        }
    }

Now I can see that the log correlation almost works as expected:

2022-11-29T22:08:33.824+01:00  INFO [server,638674d1a9fb39a38867f5b4c3bbe2ec,8867f5b4c3bbe2ec] 20745 --- [ctor-http-nio-3] d.DemotracingApplication$$SpringCGLIB$$0 : <ACCEPTANCE_TEST> <TRACE:638674d1a9fb39a38867f5b4c3bbe2ec> Hello!
2022-11-29T22:08:33.938+01:00  INFO [server,638674d1a9fb39a38867f5b4c3bbe2ec,49ff37d958d5d315] 20745 --- [ctor-http-nio-4] d.DemotracingApplication$$SpringCGLIB$$0 : <ACCEPTANCE_TEST> <TRACE:638674d1a9fb39a38867f5b4c3bbe2ec> HelloWc
2022-11-29T22:08:33.960+01:00  INFO [server,,] 20745 --- [ctor-http-nio-3] d.DemotracingApplication$$SpringCGLIB$$0 : Retrieved helloWc io.micrometer.context.DefaultContextSnapshot$DefaultScope@7739ec0c

If you look at the last line of the log, that correspondes to the doOnNext block, it doesn't show the traceId/spanId.

Modifying the code to include another nested ContextSnapshot.setThreadLocalsFrom(contextView, ObservationThreadLocalAccessor.KEY) call inside the ´doOnNext{}´, the traceId/spanId are shown:

    @GetMapping("/hello")
    fun hello(): Mono<String> {
        return Mono.deferContextual { contextView: ContextView ->
            ContextSnapshot.setThreadLocalsFrom(contextView, ObservationThreadLocalAccessor.KEY)
                .use { scope: ContextSnapshot.Scope ->
                    val traceId = tracer.currentSpan()!!.context().traceId()
                    logger.info("<ACCEPTANCE_TEST> <TRACE:{}> Hello!", traceId)
                    webClient.get().uri("http://localhost:7654/helloWc")
                        .retrieve()
                        .bodyToMono(String::class.java)
                        .doOnNext {
                            ContextSnapshot.setThreadLocalsFrom(contextView, ObservationThreadLocalAccessor.KEY)
                                .use { scope: ContextSnapshot.Scope ->
                                    logger.info("Retrieved helloWc {}", it)
                                }
                        }
                }
        }
    }

2022-11-29T22:12:58.103+01:00  INFO [server,638675da838c746176c5388aedc7127f,76c5388aedc7127f] 20849 --- [ctor-http-nio-3] d.DemotracingApplication$$SpringCGLIB$$0 : <ACCEPTANCE_TEST> <TRACE:638675da838c746176c5388aedc7127f> Hello!
2022-11-29T22:12:58.215+01:00  INFO [server,638675da838c746176c5388aedc7127f,3fd552c513cb339b] 20849 --- [ctor-http-nio-4] d.DemotracingApplication$$SpringCGLIB$$0 : <ACCEPTANCE_TEST> <TRACE:638675da838c746176c5388aedc7127f> HelloWc
2022-11-29T22:12:58.237+01:00  INFO [server,638675da838c746176c5388aedc7127f,76c5388aedc7127f] 20849 --- [ctor-http-nio-3] d.DemotracingApplication$$SpringCGLIB$$0 : Retrieved helloWc 638675da838c746176c5388aedc7127f

It seems the change from Sleuth to Micrometer Tracing is going to need quite a lot of work on our codebases. Can you confirm this is the proper usage?

BTW, thanks for your answers.

[marcingrzejszczak]

It seems the change from Sleuth to Micrometer Tracing is going to need quite a lot of work on our codebases. Can you confirm this is the proper usage?

For now, if you want to have the loggers have correlated MDC context, then yes, it will require some work. Because you could instead of doing doOnNext just call tap() or handle() and then you'll get the MDC correlated for you.

I'm in touch with @OlegDokuka and the reactor team to work on something more automated that would resemble how Sleuth worked but would be more performant and less buggy. But that will take some time.