Trace/Span IDs not available in Netty access log

[adammichalik]

Lately Netty (v0.7.9.RELEASE / v0.8.0.RELEASE) introduced access logging https://github.com/reactor/reactor-netty/issues/301. However, Sleuth trace/span IDs are not available in the access log. Tested with Spring Boot 2.1.0 + Spring Cloud Greenwich.BUILD-SNAPSHOT / Sleuth 2.1.0.BUILD-SNAPSHOT.

Sample application:

@SpringBootApplication
public class DemoApplication {

    public static void main(String[] args) {
        SpringApplication.run(DemoApplication.class, args);
    }
}

@RestController
@RequestMapping("/test")
class PublicationFamilyEndpoint {

    @GetMapping("/")
    public Mono<String> testWithBody() {
        LoggerFactory.getLogger(getClass()).info("Log HELLO");
        return Mono.just("HELLO");
    }
}

prints

2018-11-12 11:36:51.228  INFO [-,61ffb45cccef95c3,61ffb45cccef95c3,false] 2576 --- [ctor-http-nio-2] c.e.demo.PublicationFamilyEndpoint       : Log HELLO
2018-11-12 11:36:51.275  INFO [-,,,] 2576 --- [ctor-http-nio-2] reactor.netty.http.server.AccessLog      : 0:0:0:0:0:0:0:1 - - [12/Nov/2018:11:36:51 +0100] "GET /test/ HTTP/1.1" 200 5 8080 141 ms

[marcingrzejszczak]

Sleuth's netty client support was not designed to work with that approach. I guess we'll need to look into this @smaldini

[smaldini]

I'll have a look thanks for the feedback.

[marcingrzejszczak]

ping @smaldini

[bjartek]

I get this working with the following code: https://github.com/bjartek/webflux-playground/tree/accesslog-tracing

In order to get this to work i add a %X as part of the logback pattern for the access log

Example output: 127.0.0.1 - - [29/Feb/2020:20:42:36 +0100] "GET /auth/foo HTTP/1.1" 200 17 8080 37 ms traceId=a6fda6abf7421af5, spanId=86f5da276bf91999, spanExportable=false, X-Span-Export=false, X-B3-SpanId=86f5da276bf91999, X-B3-ParentSpanId=a6fda6abf7421af5, X-B3-TraceId=a6fda6abf7421af5, parentId=a6fda6abf7421af5 However as soon as I add spring-security to the classpath the MDC dissappear.

[marcingrzejszczak]

In order for this to work fine please use the latest Sleuth snapshots (or upcoming 2020.0.0 aka Ilford release) and change your code like this

@SpringBootApplication
public class DemoApplication {

    public static void main(String[] args) {
        SpringApplication.run(DemoApplication.class, args);
    }
}

@RestController
@RequestMapping("/test")
class PublicationFamilyEndpoint {

     private final Tracing tracing;

     // constructor injection

    @GetMapping("/")
    public Mono<String> testWithBody(ServerWebExchange exchange) {
        WebFluxSleuthOperators.withSpanInScope(tracing, exchange, () -> LoggerFactory.getLogger(getClass()).info("Log HELLO"));
        return Mono.just("HELLO");
    }
}

and to speed things up set spring.sleuth.reactor.instrumentation-type=MANUAL

[ShahzebAnsari]

I am trying this new version to print trace Id in access log but unable to do it. Could you please provide a sample for it. It would be very helpful for me to understand where I am making mistake.

[marcingrzejszczak]

I've presented the sample in the comment above

[ShahzebAnsari]

Can you provide pom.xml for it.

[marcingrzejszczak]

It's using Spring cloud starter sleuth and the cloud bom is in version 2020.0.0-SNAPSHOT, boot is 2.4.0-SNAPSHOT

[dameng58]

@marcingrzejszczak i'm use reactor-netty-http-brave 1.0.24 and spring cloud 2021.0.2. and start application with -Dreactor.netty.http.server.accessLogEnabled=true.But, trace id is null in my access log. are there other configurations to be configured？