Context propagation is not working correctly when using Netflix DGS on a reactive stack

[denniseffing]

Hi all!

I am currently in the process of migrating our Spring Boot services using Netflix DGS to Spring Boot 3. I encountered a lot of small issues I could work around but the one thing I could not get to work correctly is tracing.

I actually managed generating correct traces and spans for GraphQL request by following the instrumentation docs and by following the take aways of the Spring blog posts mentioned above.

My application:

• Uses Spring WebFlux for all Netflix DGS components
• Calls Hooks.enableAutomaticContextPropagation() to enable automatic context propagation
• Utilizes the GraphQlObservationInstrumentation of the Spring GraphQL project to instrument tracing for GraphQL requests & DataFetchers

Things that work

• Observations are correctly created when a GraphQL request is made and properly translated to traces and spans due to Spring Boot's Micrometer Tracing integration
• Trace IDs are correctly included in logs when the logs are written inside of the data fetcher code

Things that don't work

• Span IDs are included in the logs, but show the wrong span ID
• Trace IDs and span IDs are not included in the logs when the logs are written inside of a custom Netflix DGS exception handler

Screenshot of generated trace visualized in Zipkin:

Logs of the request:

2023-04-04T15:26:19.780+02:00 trace_id=32acfbe401efdccc92f7dd7b9ecec495 span_id=4d639f2e844b578e trace_flags= INFO 26891 --- [ctor-http-nio-2] c.n.a.demo.test.TestDgs        : The first log entry that should contain a trace ID (assembly time).
2023-04-04T15:26:19.788+02:00 trace_id=32acfbe401efdccc92f7dd7b9ecec495 span_id=4d639f2e844b578e trace_flags= INFO 26891 --- [     parallel-3] c.n.a.demo.test.TestService    : The second log entry that should contain a trace ID (execution time).
2023-04-04T15:26:19.790+02:00 trace_id=32acfbe401efdccc92f7dd7b9ecec495 span_id=4d639f2e844b578e trace_flags= INFO 26891 --- [     parallel-3] c.n.a.l.p.p.TestRepository     : The third log entry that should contain a trace ID (execution time).
2023-04-04T15:26:19.959+02:00 trace_id= span_id= trace_flags= ERROR 26891 --- [nc-response-0-0] g.d.e.DefaultDataFetcherExceptionHandler : Exception while executing data fetcher for /testObject: <exception message>

As you can see when comparing the screenshot and the logs, the logs contain the span ID of the parent span (demo-app: graphql field test-object), but not the span ID of the data fetcher span (demo-app: graphql field test-object).

Also, the Netflix DGS exception handler doesn't have access to the tracing context. Not sure what is going on here, even after reading the newest blog articles regarding the context propagation functionality in Spring Boot and Project Reactor:

• The basics - A blog post outlining the issue with context propagation regarding asynchronous processing and reactiveness
• The bumpy road of Spring Cloud Sleuth - Several approaches Sleuth utilized to work around these issues
• Unified Bridging between Reactive and Imperative - How the Spring Team unified Sleuth's approaches regarding context propagation, not just in the context of tracing but in general

Does anyone have an idea what is going on here?

Looking forward to your feedback!

Best regards,
Dennis