Tracing information is removed from MDC before logging

[akefirad]

Describe the bug I'm not sure if it's misconfiguration in my code or a bug in spring-cloud-gateway or any other dependent ones (e.g. sleuth, brave, reactor, etc); the tracing information is not included in logs when there's a route. For example let's say you have a very simple gateway application (nothing crazy, just a simple app downloaded from start.spring.io with only gateway and sleuth as dependencies) in which you have:

@SpringBootApplication
class Application

fun main(args: Array<String>) {
    runApplication<Application>(*args) {
        addInitializers(
            beans {
                bean {
                    ref<RouteLocatorBuilder>().routes {
                        route {
                            path("/get")
                            uri("https://httpbin.org")
                        }
                    }
                }
            }
        )
    }
}

Now if you run the app and call localhost:8080, you'd see logs with tracing information:

2021-12-28 09:26:08.728 DEBUG [gateway,,] 64402 --- [ctor-http-nio-2] o.s.c.s.instrument.web.TraceWebFilter    : Received a request to uri [/]
2021-12-28 09:26:08.732 DEBUG [gateway,,] 64402 --- [ctor-http-nio-2] o.s.c.s.instrument.web.TraceWebFilter    : Handled receive of span NoopSpan(63ee40cad6472dd8/63ee40cad6472dd8)
2021-12-28 09:26:08.756 DEBUG [gateway,63ee40cad6472dd8,63ee40cad6472dd8] 64402 --- [ctor-http-nio-2] o.s.c.s.instrument.web.TraceWebFilter    : Adding a class tag with value [ResourceWebHandler] to a span NoopSpan(63ee40cad6472dd8/63ee40cad6472dd8)
2021-12-28 09:26:08.758 DEBUG [gateway,63ee40cad6472dd8,63ee40cad6472dd8] 64402 --- [ctor-http-nio-2] o.s.c.s.instrument.web.TraceWebFilter    : Handled send of NoopSpan(63ee40cad6472dd8/63ee40cad6472dd8)

but if you call localhost:8080/get (for which there's a route), you'd get:

2021-12-28 09:26:53.601 DEBUG [gateway,,] 64402 --- [ctor-http-nio-3] o.s.c.s.instrument.web.TraceWebFilter    : Received a request to uri [/get]
2021-12-28 09:26:53.602 DEBUG [gateway,,] 64402 --- [ctor-http-nio-3] o.s.c.s.instrument.web.TraceWebFilter    : Handled receive of span NoopSpan(2832d97ea4fe4d9a/2832d97ea4fe4d9a)
2021-12-28 09:26:54.342 DEBUG [gateway,,] 64402 --- [ctor-http-nio-3] ientBeanPostProcessor$TracingDoOnRequest : Handled send of the netty client span [NoopSpan(2832d97ea4fe4d9a/aecdeae706b7b839)] with parent [2832d97ea4fe4d9a/2832d97ea4fe4d9a]
2021-12-28 09:26:54.471 DEBUG [gateway,,] 64402 --- [ctor-http-nio-3] PostProcessor$AbstractTracingDoOnHandler : Handle receive of the netty client span [NoopSpan(2832d97ea4fe4d9a/aecdeae706b7b839)]
2021-12-28 09:26:54.474 DEBUG [gateway,,] 64402 --- [ctor-http-nio-3] o.s.c.s.instrument.web.TraceWebFilter    : Handled send of NoopSpan(2832d97ea4fe4d9a/2832d97ea4fe4d9a)

I have a general understanding about the internal of how tracing works. But what I found is that in the latter case, the code removes the tracing data from MDC (via brave.context.slf4j.MDCScopeDecorator.MDCContext#update) before the actual logging happens. To be precise, it's not just the MDC, but the whole span is closed and there's no tracing context available anymore thanks to the try-with-resource block in TraceWebFilter.MonoWebFilterTrace#subscribe.

Sample gateway-app.zip

[marcingrzejszczak]

Yeah that's a problem that is hard to fix at this point - we will try to make it work natively with Spring Framework 6 and Spring Boot 3. We're suggesting to the users that they leverage the WebFluxSleuthOperators static methods to manually mark where the tracing information should be put in scope thus in MDC too.

[akefirad]

I see, is there any code snippet of how to do it anywhere? Thanks.

[marcingrzejszczak]

Can you please rewrite this sample to use Java and preferably Maven? I'd prefer to isolate solving a problem to one thing at a time (Kotlin and Gradle introduces unnecessary noise).

[spring-cloud-issues]

If you would like us to look at this issue, please provide the requested information. If the information is not provided within the next 7 days this issue will be closed.

[TheBestPessimist]

do not close

[spring-cloud-issues]

If you would like us to look at this issue, please provide the requested information. If the information is not provided within the next 7 days this issue will be closed.

[akefirad]

There you go gateway-app.zip.

[spring-cloud-issues]

Closing due to age of the question. If you would like us to look at this issue, please comment and we will look at re-opening the issue.

[TheBestPessimist]

@marcingrzejszczak please whitelist this to not auto close