Contexts#wrap(ExecutorService) doesn't propagate OTEL span

[boris-senapt]

In using Helidon SE without the Java agent I tried to propagate context information to an async task using io.helidon.common.context.Contexts#wrap(java.util.concurrent.ExecutorService) - but the OTEL span information was dropped.

This resulted in the async task traces being uncorrelated with the original request. Double wrapping resolves the immediate issue, but is counter-intuitive and breaks the abstraction Helidon Tracing provides

Contexts.wrap(Context.taskWrapping(executor))

Environment Details

• Helidon Version: 4.0.7
• Helidon SE
• JDK version: GraalVM CE 22+36.1 (build 22+36-jvmci-b02)
• OS: macOS Sonoma 14.4.1
• Docker version (if applicable): N/A

---

Problem Description

I have a request that spawns a long-running async task on an ExecutorService. When the request comes in, I call executor.submit(Runnable).

I expect this async task to have the same traceId as the original request, so I wrap the ExecutorService in Contexts.wrap. This claims to propagate context across threads - which I take to mean Tracing context as well as other contexts.

However, in the traces and in the logs the trace id is not the same - and a new trace is generated. On investigation there is only one implementation of io.helidon.common.context.spi.DataPropagationProvider and that propagates the Log4j2 MDC.

Adding a second wrapping with the OTEL API - io.opentelemetry.context.Context#taskWrapping(java.util.concurrent.ExecutorService) resolves the issue, but requires direct usage of the OTEL API, breaking the Helidon Tracing abstraction layer.

[tjquinno]

@boris-senapt Thanks for the report.

Can you provide a simple reproducer project that shows this? If not I'll start creating one but we'd prefer one from you so we are sure we are looking at the specific problem you are.

[boris-senapt]

@boris-senapt Thanks for the report.

Can you provide a simple reproducer project that shows this? If not I'll start creating one but we'd prefer one from you so we are sure we are looking at the specific problem you are.

Sure thing - should be able to get you a reproducer tomorrow.

[boris-senapt]

@tjquinno I have pushed a recreate up, apologies for the delay

https://github.com/boris-senapt/helidon-trace-propagation-recreate

[tjquinno]

Thanks very much for the reproducer.

I am seeing what you are in the logging output but it looks to me as if the span context is being propagated properly.

I made the following small change to the pingAsync method in PingService to explicitly display the span and trace ID from the current context's span context, if present. (There are two added imports not shown here):

@@ -24,7 +26,11 @@ public class PingService implements HttpService {
     private void pingAsync(final ServerRequest serverRequest, final ServerResponse serverResponse) {
         LOGGER.info("Async ping request received");
         executor.submit(() -> {
-            LOGGER.info("Running async ping request");
+            Optional<SpanContext> spanContext = Contexts.context().flatMap(c -> c.get(SpanContext.class));
+            String msg = String.format("In async ping request: span_id=%s, trace_id=%s",
+                                       spanContext.map(SpanContext::spanId).orElse("n/a"),
+                                       spanContext.map(SpanContext::traceId).orElse("n/a"));
+            LOGGER.info("Running async ping request - " +  msg);
         });
         serverResponse.send("pong");
     }

and here is the output I see:

12:52:33.165 [[0x6b79605e 0x1163ba20] WebServer socket] INFO  uk.co.borismorris.PingService {span_id=3baae8fd9de6851b, trace_flags=01, trace_id=8d901da0b6aaa22dbc47a5b01c30a126} - Async ping request received
12:52:33.167 [] INFO  uk.co.borismorris.PingService {} - Running async ping request - In async ping request: span_id=3baae8fd9de6851b, trace_id=8d901da0b6aaa22dbc47a5b01c30a126
12:52:33.170 [[0x6b79605e 0x1163ba20] WebServer socket] INFO  io.opentelemetry.exporter.logging.LoggingSpanExporter {span_id=3baae8fd9de6851b, trace_flags=01, trace_id=8d901da0b6aaa22dbc47a5b01c30a126} - 'content-write' : 8d901da0b6aaa22dbc47a5b01c30a126 5b2216a5b39de3c1 INTERNAL [tracer: helidon-service:] {}
12:52:33.174 [[0x6b79605e 0x1163ba20] WebServer socket] INFO  io.opentelemetry.exporter.logging.LoggingSpanExporter {span_id=3baae8fd9de6851b, trace_flags=01, trace_id=8d901da0b6aaa22dbc47a5b01c30a126} - 'HTTP Request' : 8d901da0b6aaa22dbc47a5b01c30a126 3baae8fd9de6851b SERVER [tracer: helidon-service:] AttributesMap{data={http.url=http://localhost:8080/ping-async, http.status_code=200, http.method=GET, http.version=1.1, component=helidon-webserver}, capacity=128, totalAddedValues=5}

Although the log message prefix from the async code does not contain the span and trace IDs the message built using the retrieved span context does show those IDs and they match the IDs logged by the code that receives the request.

Maybe the logging/MDC is not working quite correctly with the span context in this scenario.

Based on what I've seen I'm going to recategorize this as a logging issue rather than a tracing one. Someone else might carry on from here as that's not an area I'm as familiar with.

[boris-senapt]

Interesting - so it might be that the Helidon Tracing context has kept the span in "scope" but the underlying OTEL framework hasn't; I suppose some battle of thread locals is happening.

The logging uses opentelemetry-log4j-context-data-2.17-autoconfigure which is https://github.com/open-telemetry/opentelemetry-java-instrumentation/blob/main/instrumentation/log4j/log4j-context-data/log4j-context-data-2.17/library-autoconfigure/src/main/java/io/opentelemetry/instrumentation/log4j/contextdata/v2_17/OpenTelemetryContextDataProvider.java

This uses io.opentelemetry.context.Context.current() to get the context - which is presumably returning empty.

---

The implications are a bit deeper than just logging however - the reason I came across the issue is that we use OKhttp to make calls to other services, and those calls were also losing their traces.

i.e. whilst Helidon seems to keep its SpanContext OTEL has lost its one, and so all of the OTEL instrumentation stops working.

[tjquinno]

Your note sent me back to the revised test project and, while Contexts.context().get().get(SpanContext.class) in the async code does find the correct span context there, there is no current span in scope which is undoubtedly where logging looks and probably why the propagation chain is not maintained from there forward.

More digging to do on my end.

[tjquinno]

Definitely a bug in tracing. PR forthcoming.