Manual "spanning" of a Scala Future in conjunction with the java agent causes Spans to to suppressed.

[masonedmison]

I have a Pekko HTTP application that is using the opentelemtry-javaagent (version 2.15.0). More specifically, it's a Pekko HTTP application that uses manual instrumentation of Scala Futures as part of serving HTTP requests.

I noticed that when I add manual instrumentation of Scala Futures to this application, HTTP-related Spans and Traces are no longer exported; in the logs, I see the following:

{
  "@timestamp": "2025-05-21T14:28:39.903742376Z",
  "@version": "1",
  "message": " Trying to close scope which does not represent current context. Ignoring the call.",
  "logger": "io.opentelemetry.javaagent.shaded.io.opentelemetry.context.ThreadLocalContextStorage",
  "thread": "wh-trading-api-pekko.actor.default-dispatcher-12",
  "level": "DEBUG",
  "logLevel": 10000,
  "trace_id": "06698b524de29ff9297bc185431da679",
  "trace_flags": "01",
  "span_id": "fec9e387f0f1235d"
}

and soon following:

{
  "@timestamp": "2025-05-21T14:28:40.982519521Z",
  "@version": "1",
  "message": "Suppressed Spans by 'io.opentelemetry.pekko-http-1.0' (SERVER) : 3",
  "logger": "io.opentelemetry.javaagent.shaded.instrumentation.api.internal.SupportabilityMetrics",
  "thread": "supportability_metrics_reporter",
  "level": "DEBUG",
  "logLevel": 10000
}

I've tried to create a minimal reproducible example here, but I'm only able to reproduce the "Ignoring the call..." message, not the "Suppressed Spans" log message that I see in the actual application.

It's unclear to me if I'm doing something wrong or if this is a bug.

For reference (from the minimal repro), here is the traceFuture method that is manually spanning Futures:

  def traceFuture[A](name: String)(fut: => Future[A])(implicit
      ec: ExecutionContext
  ): Future[A] =
    for {
      (sp, scope) <- Future {
                       val sp =
                         GlobalOpenTelemetry
                           .get()
                           .getTracer("minimal-tapir-app")
                           .spanBuilder(name)
                           .startSpan()
                       sp -> sp.makeCurrent()
                     }
      result      <- fut.andThen { _ =>
                       sp.end
                       scope.close
                     }
    } yield result

Note I'm operating under the following assumption: my understanding is that, since I'm using the java agent, Scala Futures context should be correctly propagated across threads since the underlying Executor is instrumented; if I interpret this executor instrumentation correctly, I should be able to use Span.makeCurrent (and consequently scope.close), and everything should "work".

[masonedmison]

At this point, I'm assuming that the cause of Spans being suppressed (or at least a likely cause) is because Scopes aren't being closed properly.

With that assumption in mind, I've done some more digging, and it seems like Spans are failing to close within ScopeImpl because current() != toAttach. For reference, here is the implementation of ScopeImpl#close:

    @Override
    public void close() {
      if (!closed && current() == toAttach) {
        closed = true;
        THREAD_LOCAL_STORAGE.set(beforeAttach);
      } else {
        logger.log(
            Level.FINE,
            " Trying to close scope which does not represent current context. Ignoring the call.");
      }
    }

Running my minimal repro through my debugger within the andThen lambda, I see the following...

• closed = false
• Context.current =

AgentContextWrapper@10957 "AgentContextWrapper{agentContext={opentelemetry-http-server-route-key=io.opentelemetry.javaagent.shaded.instrumentation.api.internal.HttpRouteState@32102fdc, opentelemetry-trace-span-key=SdkSpan{traceId=7fa2f2746cb3e9b989423b4e7cc62677, spanId=d66db33f93a4e3ff, parentSpanContext=ImmutableSpanContext{traceId=7fa2f2746cb3e9b989423b4e7cc62677, spanId=5013b8cd0f8896e8, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, name=INNERSPAN, kind=INTERNAL, attributes=AttributesMap{data={thread.id=30, thread.name=minimal-tapir-app-pekko.actor.default-dispatcher-8}, capacity=128, totalAddedValues=2}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1747859072705996709, endEpochNanos=0}, http-server-metrics-state=State{startAttributes={http.request.method=GET, url.path=/api/v1/items, server.address=localhost, user_agent.original=curl/8.12.1, url.scheme=http, server.port=8080}, startTimeNanos=276212177759208}, opentelemetry-traces-local-root-span=SdkSpan{traceId=7fa2f2746cb3e9b989423b4e7cc62677, spanId=5013b8cd0f8896e8, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=GET, kind=SERVER, attributes=AttributesMap{data={network.protocol.version=1.1, http.request.method=GET, url.path=/api/v1/items, error.type=503, server.address=localhost, user_agent.original=curl/8.12.1, thread.id=26, url.scheme=http, thread.name=minimal-tapir-app-pekko.actor.default-dispatcher-5, http.response.status_code=503, server.port=8080}, capacity=128, totalAddedValues=11}, status=ImmutableStatusData{statusCode=ERROR, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1747859072609979000, endEpochNanos=1747859092635227125}, opentelemetry-traces-span-key-http-server=SdkSpan{traceId=7fa2f2746cb3e9b989423b4e7cc62677, spanId=5013b8cd0f8896e8, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=GET, kind=SERVER, attributes=AttributesMap{data={network.protocol.version=1.1, http.request.method=GET, url.path=/api/v1/items, error.type=503, server.address=localhost, user_agent.original=curl/8.12.1, thread.id=26, url.scheme=http, thread.name=minimal-tapir-app-pekko.actor.default-dispatcher-5, http.response.status_code=503, server.port=8080}, capacity=128, totalAddedValues=11}, status=ImmutableStatusData{statusCode=ERROR, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1747859072609979000, endEpochNanos=1747859092635227125}, opentelemetry-pekko-route=io.opentelemetry.javaagent.instrumentation.pekkohttp.v1_0.server.route.PekkoRouteHolder@375acada, thread-propagation-locations=io.opentelemetry.javaagent.shaded.instrumentation.api.internal.ContextPropagationDebug@140fe257, otel-context={}}, applicationContext={}}"
  CONTEXT_KEY_BRIDGES: Collections$UnmodifiableRandomAccessList@10406 size=2
  agentContext: ArrayBasedContext@9693 "{opentelemetry-http-server-route-key=io.opentelemetry.javaagent.shaded.instrumentation.api.internal.HttpRouteState@32102fdc, opentelemetry-trace-span-key=SdkSpan{traceId=7fa2f2746cb3e9b989423b4e7cc62677, spanId=d66db33f93a4e3ff, parentSpanContext=ImmutableSpanContext{traceId=7fa2f2746cb3e9b989423b4e7cc62677, spanId=5013b8cd0f8896e8, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, name=INNERSPAN, kind=INTERNAL, attributes=AttributesMap{data={thread.id=30, thread.name=minimal-tapir-app-pekko.actor.default-dispatcher-8}, capacity=128, totalAddedValues=2}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1747859072705996709, endEpochNanos=0}, http-server-metrics-state=State{startAttributes={http.request.method=GET, url.path=/api/v1/items, server.address=localhost, user_agent.original=curl/8.12.1, url.scheme=http, server.port=8080}, startTimeNanos=276212177759208}, opentelemetry-traces-local-root-span=SdkSpan{traceId=7fa2f2746cb3e9b989423b4e7cc62677, spanId=5013b8cd0f8896e8, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=GET, kind=SERVER, attributes=AttributesMap{data={network.protocol.version=1.1, http.request.method=GET, url.path=/api/v1/items, error.type=503, server.address=localhost, user_agent.original=curl/8.12.1, thread.id=26, url.scheme=http, thread.name=minimal-tapir-app-pekko.actor.default-dispatcher-5, http.response.status_code=503, server.port=8080}, capacity=128, totalAddedValues=11}, status=ImmutableStatusData{statusCode=ERROR, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1747859072609979000, endEpochNanos=1747859092635227125}, opentelemetry-traces-span-key-http-server=SdkSpan{traceId=7fa2f2746cb3e9b989423b4e7cc62677, spanId=5013b8cd0f8896e8, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=GET, kind=SERVER, attributes=AttributesMap{data={network.protocol.version=1.1, http.request.method=GET, url.path=/api/v1/items, error.type=503, server.address=localhost, user_agent.original=curl/8.12.1, thread.id=26, url.scheme=http, thread.name=minimal-tapir-app-pekko.actor.default-dispatcher-5, http.response.status_code=503, server.port=8080}, capacity=128, totalAddedValues=11}, status=ImmutableStatusData{statusCode=ERROR, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1747859072609979000, endEpochNanos=1747859092635227125}, opentelemetry-pekko-route=io.opentelemetry.javaagent.instrumentation.pekkohttp.v1_0.server.route.PekkoRouteHolder@375acada, thread-propagation-locations=io.opentelemetry.javaagent.shaded.instrumentation.api.internal.ContextPropagationDebug@140fe257, otel-context={}}"
  applicationContext: ArrayBasedContext@9717 "{}"

• scope.toAttach =

toAttach ArrayBasedContext = ArrayBasedContext@9693 "{opentelemetry-http-server-route-key=io.opentelemetry.javaagent.shaded.instrumentation.api.internal.HttpRouteState@32102fdc, opentelemetry-trace-span-key=SdkSpan{traceId=7fa2f2746cb3e9b989423b4e7cc62677, spanId=d66db33f93a4e3ff, parentSpanContext=ImmutableSpanContext{traceId=7fa2f2746cb3e9b989423b4e7cc62677, spanId=5013b8cd0f8896e8, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, name=INNERSPAN, kind=INTERNAL, attributes=AttributesMap{data={thread.id=30, thread.name=minimal-tapir-app-pekko.actor.default-dispatcher-8}, capacity=128, totalAddedValues=2}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1747859072705996709, endEpochNanos=0}, http-server-metrics-state=State{startAttributes={http.request.method=GET, url.path=/api/v1/items, server.address=localhost, user_agent.original=curl/8.12.1, url.scheme=http, server.port=8080}, startTimeNanos=276212177759208}, opentelemetry-traces-local-root-span=SdkSpan{traceId=7fa2f2746cb3e9b989423b4e7cc62677, spanId=5013b8cd0f8896e8, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=GET, kind=SERVER, attributes=AttributesMap{data={network.protocol.version=1.1, http.request.method=GET, url.path=/api/v1/items, error.type=503, server.address=localhost, user_agent.original=curl/8.12.1, thread.id=26, url.scheme=http, thread.name=minimal-tapir-app-pekko.actor.default-dispatcher-5, http.response.status_code=503, server.port=8080}, capacity=128, totalAddedValues=11}, status=ImmutableStatusData{statusCode=ERROR, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1747859072609979000, endEpochNanos=1747859092635227125}, opentelemetry-traces-span-key-http-server=SdkSpan{traceId=7fa2f2746cb3e9b989423b4e7cc62677, spanId=5013b8cd0f8896e8, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=GET, kind=SERVER, attributes=AttributesMap{data={network.protocol.version=1.1, http.request.method=GET, url.path=/api/v1/items, error.type=503, server.address=localhost, user_agent.original=curl/8.12.1, thread.id=26, url.scheme=http, thread.name=minimal-tapir-app-pekko.actor.default-dispatcher-5, http.response.status_code=503, server.port=8080}, capacity=128, totalAddedValues=11}, status=ImmutableStatusData{statusCode=ERROR, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1747859072609979000, endEpochNanos=1747859092635227125}, opentelemetry-pekko-route=io.opentelemetry.javaagent.instrumentation.pekkohttp.v1_0.server.route.PekkoRouteHolder@375acada, thread-propagation-locations=io.opentelemetry.javaagent.shaded.instrumentation.api.internal.ContextPropagationDebug@140fe257, otel-context={}}"

So it looks like the current Context is wrapped within an AgentContextWrapper, but it does contain a agentContext that equals toAttach, an ArrayBasedContext with the same elements.

[laurit]

It's unclear to me if I'm doing something wrong or if this is a bug.

Scope must be opened and closed on the same thread. I'd start from removing sp.makeCurrent() and scope.close.

[masonedmison]

Though this does fix the issue, it precludes the ability to create nested spans, which I'd like to support if possible, e.g.,

traceFuture("parent")(
  traceFuture("child")(Future(println("I'm a child!")
)

Is there any good way to support this other than manually propagating Context, e.g.,

def traceFuture[A](name: String)(fut: Context => Future[A]): Context => Future[A] = ???

??

[laurit]

I don't know enough scala to comment on how this should be done there. In java if you wish to return a CompletableFuture whose callbacks run with a given context you could use https://github.com/open-telemetry/opentelemetry-java-instrumentation/blob/main/instrumentation/aws-sdk/aws-sdk-2.2/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/awssdk/v2_2/CompletableFutureWrapper.java#L20