javaagent Kotlin coroutines usage (with ktor client), potential bug with delay and contexts.

[amccague]

Whilst trying to get to grips on the expected usage of OTEL using the agent and coroutines I felt it was ambiguous the intended usage. And I'm not clear how and when the out-of-the-box javaagent behaviour kicks in. It appears like it's hard to escape peppering in the OTEL additions which looks easy for people to accidentally miss (which is not ideal!).

Let's assume this is always how the parent and root span is defined:

val span = tracer.spanBuilder("demo-client")
    .setNoParent()
    .startSpan()

And the Ktor HttpClient is defined like this, I'll omit the request prepare statement as it's not relevant (as far as I know):

HttpClient(Java) {
    install(ContentNegotiation) {
        jackson()
    }
}

Both of the following leads to new trace IDs, not using my defined span as the parent:

try {
    span.makeCurrent().use { // Presuming the scope should be closed before the span is ended?
        withContext(Dispatchers.IO) { // Expecting the agent to add the OTEL context agent here?
            post.execute { response ->
                response.body<DummyDto>()
            }
            post.execute { response ->
                response.body<DummyDto>()
            }
        }
    }
} finally {
    span.end()
}

try {
    span.makeCurrent().use { // The `withContext` isn't strictly required anyway - the ThreadLocal appears to not be propagated into the ktor-client scopes out of the box.
        post.execute { response ->
            response.body<DummyDto>()
        }
        post.execute { response ->
            response.body<DummyDto>()
        }
    }
} finally {
    span.end()
}

If I'm not mistaken this looks like the intended use, which implies there's nothing out of the box with coroutines:
Works as expected, traceIds are correct with this example

try {
    span.makeCurrent().use { // You would still want to load the ThreadLocal context, e.g. for loggers reading ThreadLocal MDC?
        withContext(span.asContextElement()) { // Could have used the OTEL context because the span was made current.
            post.execute { response ->
                response.body<DummyDto>()
            }
            post.execute { response ->
                response.body<DummyDto>()
            }
        }
    }
} finally {
    span.end()
}

In the prior example where the withContext(Dispatchers.IO) { .. } was used, whenever withContext is used we must + the coroutine context e.g.:
Works as expected

try {
    span.makeCurrent().use {
        withContext(Dispatchers.IO + Context.current().asContextElement()) {
            post.execute { response ->
                response.body<DummyDto>()
            }
            post.execute { response ->
                response.body<DummyDto>()
            }
        }
    }
} finally {
    span.end()
}

And to throw a spanner in the works if I add a delay in here it goes wrong again:
Does not work as expected

try {
    span.makeCurrent().use {
        withContext(Context.current().asContextElement()) {
            delay(1000)
            post.execute { response ->
                response.body<DummyDto>()
            }
            post.execute { response ->
                response.body<DummyDto>()
            }
        }
    }
} finally {
    span.end()
}

However if I add the Dispatchers.IO it repairs it:
Works as expected

try {
    span.makeCurrent().use {
        withContext(Dispatchers.IO + Context.current().asContextElement()) {
            delay(1000)
            post.execute { response ->
                response.body<DummyDto>()
            }
            post.execute { response ->
                response.body<DummyDto>()
            }
        }
    }
} finally {
    span.end()
}

I can also isolate the delay but it's getting very noisy at this point:
Works as expected

try {
    span.makeCurrent().use {
        withContext(Context.current().asContextElement()) {
            withContext(Context.current().asContextElement()) {
                delay(1000)
            }
            post.execute { response ->
                response.body<DummyDto>()
            }
            post.execute { response ->
                response.body<DummyDto>()
            }
        }
    }
} finally {
    span.end()
}

I'm hoping some of this usability is the result of some subtle bug or something I've missed.

Using 2.9.0 agent with

implementation(platform("io.opentelemetry.instrumentation:opentelemetry-instrumentation-bom:2.9.0"))
implementation("io.opentelemetry:opentelemetry-api")
implementation("io.opentelemetry:opentelemetry-extension-kotlin")

[laurit]

I didn't try to run and debug the snippets you provided and I don't know much about kotlin so the following is just a guess. Firstly when you open a scope with makeCurrent (this is what updates the thread local context) you must ensure that the scope is closed and that the scope is closed on the same thread it was opened and that the scopes are closed in the correct order. Failure to do so will break things. This means that you should not use span.makeCurrent().use {...} inside an suspending method around another call to a suspending method.
Have a look at https://github.com/open-telemetry/opentelemetry-java/blob/main/extensions/kotlin/src/main/java/io/opentelemetry/extension/kotlin/KotlinContextElement.java this is what the agent uses to synchronize the otel context from kotlin coroutine context to thread local. My understanding is that as the synchronization happens from coroutine context to thread local you should update the otel context in coroutine context and not update the thread local directly.
If you believe you have found a bug then please provide a minimal application that reproduces the issue, this will increase the chances that someone will take a look at your issue.

[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.

[amccague]

you should not use span.makeCurrent().use {...} inside an suspending method around another call to a suspending method. Have a look at https://github.com/open-telemetry/opentelemetry-java/blob/main/extensions/kotlin/src/main/java/io/opentelemetry/extension/kotlin/KotlinContextElement.java this is what the agent uses to synchronize the otel context from kotlin coroutine context to thread local.

I see so the following is a better baseline, avoiding using span.makeCurrent()

val span = tracer.spanBuilder("demo-client")
    .setNoParent()
    .startSpan()
try {
    withContext(span.asContextElement()) { // Will make the span current, and close the scope when context ends
        post.execute { response ->
            response.body<DummyDto>()
        }
        post.execute { response ->
            response.body<DummyDto>()
        }
    }
} finally {
    span.end()
}

This does work as expected, however adding a delay to the body of the try:

withContext(span.asContextElement()) {
    delay(1000)
    post.execute { response ->
        response.body<DummyDto>()
    }
    post.execute { response ->
        response.body<DummyDto>()
    }
}

Results in typically one orphaned span being created for one of the posts. The other is fine.

It looks like delay is a special case in how its invoked on the context so might require some additional instrumentation.
I will see if I can package a MVE.

[amccague]

I've done some further debugging, this behaviour appears to be specific to if there is no ContinuationInterceptor in the CoroutineContext.

In my example I was launching the application as:

suspend fun main(): Unit = coroutineScope { .. application .. }

Which has no coroutineContext[ContinuationInterceptor]
As such the code following the delay() is typically continuing on another (its own?) thread, not carrying the OTEL context.

Starting the application as:

suspend fun main(): Unit = withContext(Dispatchers.Default) { .. application .. }

Generally solves it.

This is something I can correct for, but perhaps there's something that could be done in the agent instrumentation to ensure that the OTEL context Element asserts that there's a ContinuationInterceptor to ensure expected behaviour.

Using my above examples the following works as expected in both conditions, and if the calling code is using a different dispatcher it will continue to use that:

withContext(when {
    coroutineContext[ContinuationInterceptor] != null -> span.asContextElement()
    else -> span.asContextElement() + Dispatchers.Default
}) {
    delay(1000)
    post.execute { response ->
        response.body<DummyDto>()
    }
    post.execute { response ->
        response.body<DummyDto>()
    }
}