OpenTelemetry: MDC context disappears on ManagedExecutor thread

[kerkhofsd]

Describe the bug

Given

• a Quarkus application with installed extensions: quarkus-rest, quarkus-opentelemetry
• the ManagedExecutor is used to execute work in the background
• the background work contains log statements

Simplified code sample:

        managedExecutor.execute(() -> {

            executeWorkOnWorkerThread();

            log.info("hello() from ManagedExecutor");
        });

As per my investigation, the "main" thread is calling OpenTelemetryUtil#clearMDCData(io.vertx.core.Context vertxContext), causing the MDC data to be cleared for the "worker" thread as well.

Expected behavior

The tracing specific MDC context is available for log statements of the background work/thread.

Actual behavior

The tracing specific MDC context is not available for log statements.

Sample logging (assuming quarkus.log.console.format is configured to include MDC.traceId)

2024-09-09 10:12:50,788 INFO  traceId= [org.acm.GreetingResource] (executor-thread-1) hello() from ManagedExecutor

How to Reproduce?

Reproducer: https://github.com/kerkhofsd/quarkus-issue-otel-clears-mdc

Output of uname -a or ver

WSL Ubuntu 24.04.1 LTS

Output of java -version

openjdk version "21.0.4" 2024-07-16

Quarkus version or git rev

3.14.2

Build tool (ie. output of mvnw --version or gradlew --version)

Apache Maven 3.9.8 (36645f6c9b5079805ea5009217e36f2cffd34256)

Additional information

No response

[quarkus-bot]

/cc @brunobat (opentelemetry), @radcortez (opentelemetry)

[brunobat]

What do you see in the tracing side? Have you tried to create a new span for the new thread?

[kerkhofsd]

From tracing side it looks okay.

Enabling the logging exporter for the reproducer project:

2024-09-09 16:22:14,497 INFO  traceId=022087416154836f2c9ac2f4b5763c74 [org.acm.GreetingResource] (executor-thread-1) hello() [traceId=022087416154836f2c9ac2f4b5763c74]
2024-09-09 16:22:14,504 INFO  traceId=022087416154836f2c9ac2f4b5763c74 [org.acm.GreetingResource] (executor-thread-2) hello() from ManagedExecutor before sleep [traceId=022087416154836f2c9ac2f4b5763c74]
2024-09-09 16:22:14,510 INFO  traceId= [io.ope.exp.log.LoggingSpanExporter] (vert.x-eventloop-thread-0) 'GET /hello' : 022087416154836f2c9ac2f4b5763c74 379b302dda5d0a21 SERVER [tracer: io.quarkus.opentelemetry:] AttributesMap{data={http.request.method=GET, code.function=hello, http.response.status_code=200, http.route=/hello, server.address=localhost, server.port=8080, client.address=0:0:0:0:0:0:0:1, user_agent.original=curl/8.5.0, url.path=/hello, code.namespace=org.acme.GreetingResource, url.scheme=http, http.response.body.size=23}, capacity=128, totalAddedValues=12}
2024-09-09 16:22:15,505 INFO  traceId= [org.acm.GreetingResource] (executor-thread-2) hello() from ManagedExecutor after sleep [traceId=022087416154836f2c9ac2f4b5763c74]

I didn't try to create a new span for the new thread. After adding a @WithSpan in the worker thread, the MDC.traceID does always get correctly logged it seems:

2024-09-09 16:24:39,029 INFO  traceId=1565754ca4f9d8e10fcd15bee083f107 [org.acm.GreetingResource] (executor-thread-1) hello() [traceId=1565754ca4f9d8e10fcd15bee083f107]
2024-09-09 16:24:39,035 INFO  traceId=1565754ca4f9d8e10fcd15bee083f107 [org.acm.GreetingResource] (executor-thread-2) hello() from ManagedExecutor before sleep [traceId=1565754ca4f9d8e10fcd15bee083f107]
2024-09-09 16:24:39,042 INFO  traceId= [io.ope.exp.log.LoggingSpanExporter] (vert.x-eventloop-thread-0) 'GET /hello' : 1565754ca4f9d8e10fcd15bee083f107 2e6332562b6ed7a6 SERVER [tracer: io.quarkus.opentelemetry:] AttributesMap{data={http.route=/hello, http.request.method=GET, code.function=hello, url.path=/hello, code.namespace=org.acme.GreetingResource, http.response.body.size=23, server.address=localhost, client.address=0:0:0:0:0:0:0:1, user_agent.original=curl/8.5.0, http.response.status_code=200, url.scheme=http, server.port=8080}, capacity=128, totalAddedValues=12}
2024-09-09 16:24:40,041 INFO  traceId= [io.ope.exp.log.LoggingSpanExporter] (executor-thread-2) 'GreetingResource.executeWorkOnWorkerThread' : 1565754ca4f9d8e10fcd15bee083f107 44c0ba8d4131d330 INTERNAL [tracer: io.quarkus.opentelemetry:] {}
2024-09-09 16:24:40,043 INFO  traceId=1565754ca4f9d8e10fcd15bee083f107 [org.acm.GreetingResource] (executor-thread-2) hello() from ManagedExecutor after sleep [traceId=1565754ca4f9d8e10fcd15bee083f107]

[geoand]

Also cc @manovotn

[brunobat]

This might be another consequence of the way we handle scopes...
Ideally, the same OTel context ("OTel" enhanced MDC or not) should be available until the scope is closed, even if that happens on another thread.
In here, what seems to be happening is that we have a split between the way we handle the OTel aware MDC context and the OTel context itself.
Only when we have an explicit span in the current thread, does the MDC context work.