Opentelemetry-java: How to troubleshoot "ThreadLocalContextStorage - Context was not attached when detaching" from the agent?

[holyjak]

Hello! I am using the java agent (0.9.0) with a Kotlin + Ktor application. The agent regularly logs this error:

[opentelemetry.auto.trace 2020-11-10 10:02:21:955 +0100] [nioEventLoopGroup-3-1] ERROR io.opentelemetry.javaagent.shaded.io.grpc.ThreadLocalContextStorage - Context was not attached when detaching
java.lang.Throwable
        at io.opentelemetry.javaagent.shaded.io.grpc.ThreadLocalContextStorage.detach(ThreadLocalContextStorage.java:48)
        at io.opentelemetry.javaagent.shaded.io.grpc.Context.detach(Context.java:463)
        at io.opentelemetry.javaagent.shaded.io.opentelemetry.context.ContextUtils$ContextInScope.close(ContextUtils.java:45)
        at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:66)
        at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:500)
        at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
        at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.base/java.lang.Thread.run(Thread.java:834)

I don't create any spans myself so I do not think it is a defect I have introduced. However I suspect there could be a mismatch between the use of ThreadLocal storage and Kotlin and Ktor's heavy use of coroutines.

I would like to troubleshoot and help fix this issue so that I could use OpenTelemetry safely with my application. Any tips?

Thank you!

Update I guess https://github.com/grpc/grpc-kotlin/blob/master/stub/src/main/java/io/grpc/kotlin/GrpcContextElement.kt points in the right direction to solving the problem.

Artifacts

I have this in my gradle.build:

implementation(platform("io.opentelemetry:opentelemetry-bom:0.9.1"))
implementation "io.opentelemetry:opentelemetry-api"
implementation "io.opentelemetry:opentelemetry-sdk"
 implementation "io.opentelemetry:opentelemetry-exporters-otlp"

and I start the app with "-javaagent:aws-opentelemetry-agent-0.9.0.jar"

Environment

Compiler: openjdk 11.0.1 2018-10-16
OS: OSX

[jkwatson]

@holyjak it sounds like this might be an issue more appropriate to the instrumentation project? Also, in 0.10.0, we no longer use grpc-context for our Context, so if you could see if this is still an issue in 0.10.0, that would be helpful.

[Oberon00]

you could see if this is still an issue in 0.10.0, that would be helpful

Note that we set the logging level for this issue to FINE, so you probably won't see this issue by default even if it's there (#1821).

[holyjak]

Thank you! OK, I will try to switch to 0.10.

I thought this was the instrumentation project 😅 I have not noticed there was also https://github.com/open-telemetry/opentelemetry-java-instrumentation before.

If you prefer, then just close it. I will check with 0.10 and, if still a problem, re-open it under the right project.

[jkwatson]

closing as it belongs in the instrumentation project.

[holyjak]

FYI 0.10.1 does not exhibit the issue

[Oberon00]

Note that this error is not logged since 0.10 unless you set the log level to FINE or more, so it might still be there even if you don't immediately see the log message.

[holyjak]

I run with -Dio.opentelemetry.javaagent.slf4j.simpleLogger.defaultLogLevel=debug. You are suggesting I actually need "fine" there, right?

[Oberon00]

I don't know how slf4j works, but if the debug applies to that logger, then FINE messages should also be displayed, so probably the error is really gone 👍

[holyjak]

According to https://stackoverflow.com/a/20807571/204205 is JUL FINE covered by Sl4j's DEBUG.