Kotlin coroutines: tracing baggage remains on MDC but should be removed [otel]

[akrikheli]

Hello!

Using Spring Boot 3.1.4, webflux, micrometer:

         <dependency>
            <groupId>io.micrometer</groupId>
            <artifactId>micrometer-tracing</artifactId>
        </dependency>
        <dependency>
            <groupId>io.micrometer</groupId>
            <artifactId>micrometer-registry-prometheus</artifactId>
            <scope>runtime</scope>
        </dependency>
        <dependency>
            <groupId>io.micrometer</groupId>
            <artifactId>context-propagation</artifactId>
            <version>1.0.6</version>
        </dependency>
        <dependency>
            <groupId>io.micrometer</groupId>
            <artifactId>micrometer-tracing-bridge-otel</artifactId>
        </dependency>

Encountered interesting behavior that looks like bug:

Got simple endpoint:

private val ctx = newSingleThreadContext("thread")

  @GetMapping(value = ["/"])
  suspend fun handler(): ResponseEntity<*> {
    log.info("Incoming response: allBaggage={}", tracer.allBaggage)
    withContext(ctx + observationRegistry.asContextElement()) {
      delay(100)
      log.info("This block is always executed on thread {}", Thread.currentThread().name)
    }
    return ResponseEntity.ok().build<Void>()
  }

and custom tracing baggage settings:

management.tracing.baggage.correlation.fields=customId
management.tracing.baggage.remoteFields=customId

Call endpoint at the first time with headers:

curl -H 'baggage: customId=custom-value;propagation%3Dunlimited' -H 'customId: custom-value' http://localhost:8080/coroutines/

See in logs:

2023-10-14T15:23:30.943+03:00 [spring-tracing-otel, traceId=f190f0ad4faddd0570cc40ff0471906d, spanId=bfe432c3ecb947a9, customId=custom-value]  INFO 23822 --- [ctor-http-nio-3] r.c.springtracing.CoroutineController    : Incoming response: allBaggage={customId=custom-value}
2023-10-14T15:23:31.059+03:00 [spring-tracing-otel, traceId=f190f0ad4faddd0570cc40ff0471906d, spanId=bfe432c3ecb947a9, customId=custom-value]  INFO 23822 --- [         thread] r.c.springtracing.CoroutineController    : This block is always executed on thread thread

all right!

After that call endpoint again but WITHOUT headers:

curl  http://localhost:8080/coroutines/

And see in logs:

2023-10-14T15:25:41.001+03:00 [spring-tracing-otel, traceId=26fa3b91b2dc3fb06a0768812836883a, spanId=b531b0ad38badf4e]  INFO 23822 --- [ctor-http-nio-6] r.c.springtracing.CoroutineController    : Incoming response: allBaggage={}
2023-10-14T15:25:41.105+03:00 [spring-tracing-otel, traceId=26fa3b91b2dc3fb06a0768812836883a, spanId=b531b0ad38badf4e, customId=custom-value]  INFO 23822 --- [         thread] r.c.springtracing.CoroutineController    : This block is always executed on thread thread

customId=custom-value remains on MDC context for thread but it's wrong!

The quick analysis shows the problem is in publishing event ScopeRestoredEvent.

When I set logging level to TRACE for logging.level.io.micrometer.tracing.otel.bridge I found:

2023-10-14T15:32:12.618+03:00 [spring-tracing-otel, traceId=b96a28e693c9ab7e5f4cb047d0973e55, spanId=a2ce9fec70a3ebdf, customId=custom-value]  INFO 30022 --- [         thread] r.c.springtracing.CoroutineController    : This block is always executed on thread thread
2023-10-14T15:32:12.619+03:00 [spring-tracing-otel, traceId=b96a28e693c9ab7e5f4cb047d0973e55, spanId=a2ce9fec70a3ebdf, customId=custom-value] TRACE 30022 --- [         thread] i.m.t.o.b.Slf4JBaggageEventListener      : Got scope attached event [ScopeAttached{context: [span: null] [baggage: null]}]
2023-10-14T15:32:12.619+03:00 [spring-tracing-otel, traceId=b96a28e693c9ab7e5f4cb047d0973e55, spanId=a2ce9fec70a3ebdf, customId=custom-value] TRACE 30022 --- [         thread] i.m.t.otel.bridge.Slf4JEventListener     : Got scope changed event [ScopeAttached{context: [span: null] [baggage: null]}]
2023-10-14T15:32:12.619+03:00 [spring-tracing-otel, traceId=b96a28e693c9ab7e5f4cb047d0973e55, spanId=a2ce9fec70a3ebdf, customId=custom-value] TRACE 30022 --- [         thread] i.m.t.o.b.Slf4JBaggageEventListener      : Got scope closed event [io.micrometer.tracing.otel.bridge.EventPublishingContextWrapper$ScopeClosedEvent@3c511539]
2023-10-14T15:32:12.619+03:00 [spring-tracing-otel, traceId=b96a28e693c9ab7e5f4cb047d0973e55, spanId=a2ce9fec70a3ebdf] TRACE 30022 --- [         thread] i.m.t.otel.bridge.Slf4JEventListener     : Got scope closed event [io.micrometer.tracing.otel.bridge.EventPublishingContextWrapper$ScopeClosedEvent@3c511539]
2023-10-14T15:32:12.619+03:00 [spring-tracing-otel, ] TRACE 30022 --- [         thread] i.m.t.o.b.Slf4JBaggageEventListener      : Got scope restored event [ScopeRestored{context: [span: SdkSpan{traceId=b96a28e693c9ab7e5f4cb047d0973e55, spanId=a2ce9fec70a3ebdf, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=http get /coroutines/, kind=SERVER, attributes=AttributesMap{data={outcome=SUCCESS, status=200, uri=/coroutines/, http.url=/coroutines/, method=GET, exception=none}, capacity=128, totalAddedValues=6}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1697286732512952000, endEpochNanos=1697286732619215647}] [baggage: {customId=ImmutableEntry{value=custom-value, metadata=ImmutableEntryMetadata{value=propagation=unlimited}}}]}]
2023-10-14T15:32:12.619+03:00 [spring-tracing-otel, customId=custom-value] TRACE 30022 --- [         thread] i.m.t.otel.bridge.Slf4JEventListener     : Got scope restored event [ScopeRestored{context: [span: SdkSpan{traceId=b96a28e693c9ab7e5f4cb047d0973e55, spanId=a2ce9fec70a3ebdf, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=http get /coroutines/, kind=SERVER, attributes=AttributesMap{data={outcome=SUCCESS, status=200, uri=/coroutines/, http.url=/coroutines/, method=GET, exception=none}, capacity=128, totalAddedValues=6}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1697286732512952000, endEpochNanos=1697286732619215647}] [baggage: {customId=ImmutableEntry{value=custom-value, metadata=ImmutableEntryMetadata{value=propagation=unlimited}}}]}]

I confused what for the scope is restored and the baggage is put back to MDC Context. Looks like a bug.
May be anybody can help to solve this problem?

[akrikheli]

Found that the old value of remote baggage is restored by OtelBaggageManager from io.opentelemetry.context.Context. I think the Context should be cleaned after request completed

[akrikheli]

Issue has been already resolved, duplicate: #363
Fixed in io.micrometer:micrometer-tracing:1.1.6