KtorServerTracing with Netty engine broken when used together with Ktor's HttpClient

[LangdalP]

Describe the bug

When using KtorServerTracing on a server with Netty engine, in combination with a route that uses Ktor's HttpClient, tracing of incoming requests will start to fail. The result is that if the host computer or JVM has N processors available, your trace collector will receive up to N SERVER traces, regardless of how many requests you make to the server.

There seems to be context leak which causes a given thread to be associated with an OpenTelemetry context, and therefore also a span. If a given thread has already processed an incoming request, it will from that point on be associated with the span that was created the first time. On subsequent requests processed by the same thread, it will not create new SERVER spans.

The bug causes the shouldSuppress function to return true.

That function is called from here.

Note that changing the engine to CIO seems to result in correct tracing.
Also note that removing the use of a HttpClient inside the route will also stop the bug from happening.

As such, it seems the bug is only triggered when using the combination of Netty server engine and Ktor's HttpClient inside a route.

Note: Please let me know if you think this is the wrong place for this bug report. I am not sure if the error is with Netty or with opentelemetry-java-instrumentation.

Steps to reproduce

I have made a minimal reproducible case in a separate repo. It has instructions on how to run it:
https://github.com/LangdalP/ktor-otel-debug

Expected behavior

Each request should result in a new trace, given that the incoming traceparent-header is different each time (or non-existing).

Actual behavior

If the server has one processor, it will correctly trace up to one request, and subsequent requests will not be traced correctly since there are no new SERVER spans created.

I made these 5 requests:

Here is the only trace created and collected:

Note that changing the engine to CIO will correctly result in 5 requests being traced.
Also note that removing the use of a HttpClient inside the route will also result in 5 requests being traced.

Javaagent or library instrumentation version

2.2.0-alpha, sdk-version 1.36.0

Environment

JDK: Eclipse Temurin JDK 17
OS: MacOS and docker-image eclipse-temurin:17-alpine

Additional context

Note that the README for the Ktor server instrumentation suggests using Netty, which is a bad idea due to this bug:
https://github.com/open-telemetry/opentelemetry-java-instrumentation/tree/main/instrumentation/ktor/ktor-2.0/library

Please let me know if you think I should instead create a bug report with Ktor/Netty.

[laurit]

I find it unlikely that the bug is in this project. Our ktor instrumentation doesn't do much with the context, it relies on https://github.com/open-telemetry/opentelemetry-java/tree/main/extensions/kotlin for propagating the context. After debugging it a bit to me it seems more likely that the bug is in the kotlin coroutines implementation. Call to https://github.com/open-telemetry/opentelemetry-java/blob/8937a1009a59059fdbafcc58e4bcdd642b172200/extensions/kotlin/src/main/java/io/opentelemetry/extension/kotlin/KotlinContextElement.java#L42 should be paired with a call to https://github.com/open-telemetry/opentelemetry-java/blob/8937a1009a59059fdbafcc58e4bcdd642b172200/extensions/kotlin/src/main/java/io/opentelemetry/extension/kotlin/KotlinContextElement.java#L47 to avoid context leaks but here it seems to miss a call to restoreThreadContext. As far as I can tell the call should happen from https://github.com/Kotlin/kotlinx.coroutines/blob/515308dc3d5fe0624f235cb9fd84358e7e59b7a1/kotlinx-coroutines-core/jvm/src/CoroutineContext.kt#L115 but is skipped because undispatchedCompletion.clearThreadContext() on the previous line evaluates to false.

[cbruegg]

This seems to be the same bug: https://youtrack.jetbrains.com/issue/KTOR-6118/CallMonitoring-SuspendFunctionGun-sometimes-leaks-coroutine-context

[cbruegg]

Looks like Ktor 3.0.0 resolves this issue - at least my test doesn't fail anymore.

[trask]

@LangdalP does this resolve your issue also? thanks

[github-actions]

This has been automatically marked as stale because it has been marked as needing author feedback and has not had any activity for 7 days. It will be closed automatically if there is no response from the author within 7 additional days from this comment.