OTel baggage dropped in Play Framework endpoint Action

[lewistg]

Tracer Version(s)

1.58.2

Java Version(s)

21.0.10

JVM Vendor

Amazon Corretto

Bug Report

We are using the Play Framework. I'm trying to propagate W3C baggage, but the it appears to be stripped from the OtelContext once the thread of execution invokes the endpoint's Action.

Expected Behavior

The OTel baggage gets propagated into the Action.

Reproduction Code

Environment

• Play Framework version: 3.0.10
  • Using the Netty server backend (not Pekko HTTP); Netty version 4.2.6
  • Scala version
• Using OTel API
• dd-trace-java config:

# Relevant settings
-Ddd.integrations.enabled=true
-Ddd.integration.opentracing.enabled=true
-Ddd.trace.otel.enabled=true
-Ddd.trace.propagation.style.inject=b3multi,baggage
-Ddd.trace.propagation.style.extract=b3multi,baggage

# I believe the above settings are most relevant. 
# Here (more or less) are the rest of our settings, just including for completeness
-Ddd.trace.propagation.style.b3.padding.enabled=false
-Ddd.integration.jdbc-datasource.enabled=true
-Ddd.integration.jdbc.enabled=true
-Ddd.dbm.propagation.mode=full
-Ddd.trace.db.client.split-by-host=false
-Ddd.trace.PeerServiceTagInterceptor.enabled=true
-Ddd.trace.128.bit.traceid.generation.enabled=false
-Ddd.writer.type=LoggingWriter
-Ddatadog.slf4j.simpleLogger.defaultLogLevel=warn
-Ddd.profiling.enabled=false
-Ddd.http.client.error.statuses=400-403,405-499
-Ddd.trace.128.bit.traceid.generation.enabled=false
-Ddd.instrumentation.telemetry.enabled=false
-Ddd.jmxfetch.enabled=false

Setup

To poke at the behavior I set up a simple request filter that prints the current baggage and context:

package com.example.play.filters.otel

import com.example.logging.logsafe.*
import io.opentelemetry.api.baggage.Baggage
import io.opentelemetry.context.Context
import org.apache.pekko.stream.Materializer
import play.api.mvc.{Filter, RequestHeader, Result}
import scala.concurrent.Future

class OtelBaggageLogger(implicit override val mat: Materializer) extends Filter {
  private implicit lazy val logger: SafeLogger = SafeLogger.getLogger(this)

  override def apply(block: RequestHeader => Future[Result])(request: RequestHeader): Future[Result] = {
    val context = Context.current()
    logger.debug(log"context: $context")

    val baggage = Baggage.current()
    logger.debug(log"baggage: ${baggage.asMap}")

    block(request)
  }
}

I also set up a simple endpoint that also prints the current baggage and context:

package com.example.play.controllers.echo

import com.example.logging.logsafe.*
import io.opentelemetry.context.Context
import io.opentelemetry.api.baggage.Baggage
import play.api.mvc.{Action, AnyContent, BaseController, ControllerComponents}

class EchoController(override protected val controllerComponents: ControllerComponents) extends BaseController {
  private implicit lazy val logger: SafeLogger = SafeLogger.getLogger(this)

  def main(message: String): Action[Unit] = Action(controllerComponents.parsers.empty) { request =>
    val context = Context.current()
    logger.debug(log"context: $context")

    val baggage = Baggage.current()
    logger.debug(log"baggage: ${baggage.asMap}")

    Ok(message)
  }
}

I make a request with curl:

curl "https://$HOST/echo?message=foo" \
    -H "baggage: user.id=1234,foo=bar"

And I get the following logs. (Newlines added for readability):

# OtelBaggageLogger logs

00:13:22 user DEBUG c.l.s.c.c.u.b.OtelBaggageLogger 2191379227095458586 context: OtelContext {
  delegate=IndexedContext{
      store=[DDSpan [ 
          t_id=2191379227095458586, 
          s_id=2716988011523247765, 
          p_id=2191379227095458586 ] 
          trace=user/netty.request/GET /echo *measured* 
          tags={
            _dd.profiling.enabled=0, 
            _dd.trace_span_attribute_schema=0, 
            b3.spanid=1e6957cbef31e31a, 
            b3.traceid=1e6957cbef31e31a, 
            component=netty, 
            http.hostname=localhost, 
            http.method=GET, 
            http.query.string=message=foo, 
            http.url=http://localhost/echo, 
            http.useragent=curl/8.5.0, 
            language=jvm, 
            peer.ipv4=127.0.0.1, 
            peer.port=50606, 
            process_id=2992113, 
            runtime-id=ae7f11c5-75d5-4d27-a8ad-b92dfbf1aa06, 
            span.kind=server, 
            thread.id=133, 
            thread.name=netty-event-loop-4
          }, 
          duration_ns=0, 
          forceKeep=false, 
          links=[], 
          null, 
          null, 
          datadog.trace.bootstrap.instrumentation.api.Baggage@6842a052
      ]
  }
} -

00:13:22 user DEBUG c.l.s.c.c.u.b.OtelBaggageLogger 2191379227095458586 baggage: {
  user.id=datadog.opentelemetry.shim.baggage.OtelBaggage$ValueOnly@170842, 
  foo=datadog.opentelemetry.shim.baggage.OtelBaggage$ValueOnly@17c13
} -

# EchoController logs

00:13:22 user DEBUG c.l.u.s.c.e.EchoController 2191379227095458586 context: OtelContext{
  delegate=DDSpan [ 
        t_id=2191379227095458586, 
        s_id=6444585375118020543, 
        p_id=2716988011523247765 
    ] trace=user/play.request/GET /echo *measured* 
    tags={
        component=play-action, 
        http.hostname=localhost, 
        http.method=GET, 
        http.query.string=message=foo, 
        http.route=/echo, 
        http.url=http://localhost/echo, 
        language=jvm, peer.ipv4=127.0.0.1, 
        span.kind=server, 
        thread.id=129, 
        thread.name=application-pekko.actor.default-dispatcher-9
    }, 
    duration_ns=0, 
    forceKeep=false, 
    links=[]
} -

00:13:22 user DEBUG c.l.u.s.c.e.EchoController 2191379227095458586 baggage: {} -

Findings from local debugging

• Stepping through the Play Framework code, the context logged by the OtelBaggageLogger seems to to be preserved up to about this point in play.api.mvc.ActionBuilder#async.
• Shortly thereafter the controller's Action is invoked
• Just prior to entering the Action, I've noticed datadog.context.Context#attach is called, which results in a call to datadog.trace.core.scopemanager.ScopeStack#push

Hypothesis

I believe actions in that last bullet point effectively swaps the OtelContext's delegate from the IndexedContext that has the baggage to just a bare DDSpan. From what I can tell this Context#attach call is a result of the Play instrumentation.

[mcculls]

Hi @lewistg - thanks for reporting this. We will fix this for the next release, v1.60.0 which is expected at the start of March.

[github-actions]

🤖 This issue has been addressed in the latest release. Check full details in the Release Notes.