Spring-cloud-sleuth: Trace context is not propagated to Netty access logs

[qavid]

Describe the bug
When Reactor Netty access log is enabled and reactor signals are published on different scheduler, then there is no trace info in access logs. If same scheduler is used, trace context is propagated and correctly printed in access log.

Trace context should also be propagated to access log so we can correlate application logs with access logs.

Spring Cloud version: 2020.0.2
Spring Sleuth version: 3.0.2

Sample
Use Spring Initializer with Spring Reactive Web and Sleuth (in my case with Kotlin).
Add controller:

@RestController
class Controller {
    private val logger = LoggerFactory.getLogger(javaClass)

    @GetMapping("test1")
    fun test1() = Mono.just("response")
        .doOnNext {
            logger.info("Test1")
        }

    @GetMapping("test2")
    fun test2() = Mono.just("response")
        .doOnNext {
            logger.info("Test2 - before publishOn")
        }
        .publishOn(Schedulers.boundedElastic())
        .doOnNext {
            logger.info("Test2 - after publishOn")
        }
}

Start application with -Dreactor.netty.http.server.accessLogEnabled=true
GET http://localhost:8080/test1 correctly prints spanId & traceId

2021-05-25 09:45:53.357  INFO [,dc579da470f010ee,dc579da470f010ee] 31692 --- [ctor-http-nio-4] com.example.demo.Controller              : Test1
2021-05-25 09:45:53.357  INFO [,dc579da470f010ee,dc579da470f010ee] 31692 --- [ctor-http-nio-4] reactor.netty.http.server.AccessLog      : 127.0.0.1:52134 - - [25/May/2021:09:45:53 +0200] "GET /test1 HTTP/1.1" 200 8 0 ms

GET http://localhost:8080/test2 spanId & traceId is missing in access log

2021-05-25 09:45:55.990  INFO [,172cd6fa0e60cb81,172cd6fa0e60cb81] 31692 --- [ctor-http-nio-5] com.example.demo.Controller              : Test2 - before publishOn
2021-05-25 09:45:55.990  INFO [,172cd6fa0e60cb81,172cd6fa0e60cb81] 31692 --- [oundedElastic-2] com.example.demo.Controller              : Test2 - after publishOn
2021-05-25 09:45:55.990  INFO [,,] 31692 --- [ctor-http-nio-5] reactor.netty.http.server.AccessLog      : 127.0.0.1:52135 - - [25/May/2021:09:45:55 +0200] "GET /test2 HTTP/1.1" 200 8 0 ms

[marcingrzejszczak]

have you added

<!-- https://mvnrepository.com/artifact/io.projectreactor.netty/reactor-netty-http-brave -->
<dependency>
    <groupId>io.projectreactor.netty</groupId>
    <artifactId>reactor-netty-http-brave</artifactId>
    <scope>runtime</scope>
</dependency>

to the classpath?

[qavid]

yes, after your comment :sweat_smile: , but without change
version 1.0.7

[marcingrzejszczak]

Can you please prepare a project that replicates this? I think that some manual setup is required on the brave netty side? cc @violetagg

[qavid]

OK, I will prepare sample project in minutes.

I have also found that I need to decorate http server with tracing decorator (it is not auto-configured as I would expect), but no trace ids are in access log.

@Bean
fun tracingCustomizer(httpTracing: HttpTracing) =
    NettyServerCustomizer { server -> ReactorNettyHttpTracing.create(httpTracing).decorateHttpServer(server) }

I traced problem down to this code in reactor-netty:
https://github.com/reactor/reactor-netty/blob/9b1da8332fb8cae4cc4518beb5b794ab745146e9/reactor-netty-http/src/main/java/reactor/netty/http/server/logging/AccessLogHandlerH1.java#L89-L98

Before calling ctx.write(msg, promise.unvoid()), spandId and traceId are still present in thread local, but are not present in listener.

[qavid]

@marcingrzejszczak I have created PR to sleuth-issues repo: https://github.com/spring-cloud-samples/sleuth-issues/pull/67

[violetagg]

@qavid Thanks for the reproducible example, it helped a lot. I prepared a change in Reactor Netty https://github.com/reactor/reactor-netty/pull/1649

[marcingrzejszczak]

So let's close the issue here.

[violetagg]

@qavid You can try with Reactor Netty 1.0.8-SNAPSHOT

[qavid]

@violetagg many thanks. Trace context is now printed in access log with reactor-netty-http-brave 1.0.8-SNAPSHOT.