FastAPI instrumentation - Invalid TraceID/SpanID propagation, even with right traceparent information

[RomainCendre]

Describe your environment

OS: Ubuntu
Python version:3.11
SDK version: 1.29.0
API version: 1.29.0

What happened?

Hi everyone!
We are using a FastAPI server for some application using FastAPI instrumentation tool from OpenTelemetry, let's call it "computing_server".
This server is called behind another one also using OpenTelemetry in order to propagate some traceID, let's call it "calling_server".

Most of the time, when request are "slow" let's say arround every 10 seconds, everything is working finig fine and the right traceID is propagate from calling_server to computing_server, and logs are consistant.

Sometimes when we are doing calls every 0.5s or 1s, things starts to be disturbing: we have on computing_server some old remaining traceID from a previous call.

Instead of starting from NonRecordingSpan, application start from another retrieve Span, even if Detach token seems to be used ....
I don't really get it...

Thanks you for your help

Steps to Reproduce

import logging
import uvicorn

from opentelemetry import trace
from opentelemetry.sdk.resources import Resource
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import BatchSpanProcessor
from opentelemetry.exporter.otlp.proto.http.trace_exporter import OTLPSpanExporter
from opentelemetry.instrumentation.logging import LoggingInstrumentor    
from opentelemetry.instrumentation.fastapi import FastAPIInstrumentor

from contextlib import asynccontextmanager
from fastapi import FastAPI, APIRouter, Request, Response


class App:
    
    def __init__(self):
        self.app = None
        self.router = APIRouter(redirect_slashes=False)
        
    def __prepare_routes(self):
        self.router.add_api_route("/estimate/", self.__call_estimate, methods=["POST"], response_model=bytes)

    async def __call_estimate(self, request: Request):
        logging.info(request.headers["traceparent"])
        request = await request.body()
        result = Object()
        return Response(result, media_type='application/octet-stream')

    
    ## SERVER ACCESSORS
    def get_app(self):
        return self.app
    
    def init(self):
        @asynccontextmanager
        async def lifespan(app: FastAPI):
            logging.info("Starting...")

            # Prepare routes
            self.__prepare_routes()
            app.include_router(self.router)
            
            yield

            # Shutdown
            logging.info("Shutdown")

        # Init server
        self.app = FastAPI(lifespan=lifespan, redirect_slashes=False)
        
    def run(self):
        # Run server
        uvicorn.run(self.app, host="0.0.0.0", port=7771, log_config=None)

    
if __name__ == "__main__":
    span_processor = BatchSpanProcessor(OTLPSpanExporter(endpoint=f'http://0.0.0.0:4318/v1/traces'))
    provider = TracerProvider(resource=Resource.create({"service.name": "my_server"}))
    provider.add_span_processor(span_processor)
    trace.set_tracer_provider(provider)
    LoggingInstrumentor().instrument()
    root = logging.getLogger()
    root.disabled = False

    root.setLevel(logging.INFO)
    # create console handler and set level to debug
    console_handler = logging.StreamHandler()
    console_handler.setLevel(logging.INFO)
    # add formatter to console
    console_handler.setFormatter(logging.Formatter("---- 'service_name': '%(otelServiceName)s', 'trace_id': '%(otelTraceID)s', 'span_id': '%(otelSpanID)s', 'message': '%(message)s'"))
    root.addHandler(console_handler)

    # Run server
    server = App()
    server.init()
    FastAPIInstrumentor().instrument_app(server.get_app())
    server.run()

And some client like curl to send a lot of requests

Expected Result

In a perfect working case, we expect the tracedi from http request to be used like this :

---- HTTP call start
NonRecordingSpan(SpanContext(trace_id=0x00000000000000000000000000000000, span_id=0x0000000000000000, trace_flags=0x00, trace_state=[], is_remote=False))
-- Attach  <Token var=<ContextVar name='current_context' default={} at 0x7f04c507ea70> at 0x7f04c4365140>
-- Attach  <Token var=<ContextVar name='current_context' default={} at 0x7f04c507ea70> at 0x7f04c4307640>
---- From HTTP: 00-bbf1de194dd806bd18a68c7abde63c06-6051ddd8243e1671-01
-- Attach  <Token var=<ContextVar name='current_context' default={} at 0x7f04c507ea70> at 0x7f04c42ff000>
-- Detach  <Token var=<ContextVar name='current_context' default={} at 0x7f04c507ea70> at 0x7f04c42ff000>
{"trace_id": "bbf1de194dd806bd18a68c7abde63c06", "span_id": "bb142ed50f99272d"}
-- Attach  <Token var=<ContextVar name='current_context' default={} at 0x7f04c507ea70> at 0x7f04c438e840>
-- Detach  <Token var=<ContextVar name='current_context' default={} at 0x7f04c507ea70> at 0x7f04c438e840>
{"trace_id": "bbf1de194dd806bd18a68c7abde63c06", "span_id": "bb142ed50f99272d"}
-- Attach  <Token var=<ContextVar name='current_context' default={} at 0x7f04c507ea70> at 0x7f04c438e940>
-- Detach  <Token var=<ContextVar name='current_context' default={} at 0x7f04c507ea70> at 0x7f04c438e940>
-- Detach  <Token var=<ContextVar name='current_context' default={} at 0x7f04c507ea70> at 0x7f04c4307640>
-- Detach  <Token var=<ContextVar name='current_context' default={} at 0x7f04c507ea70> at 0x7f04c4365140>

---- HTTP call start
NonRecordingSpan(SpanContext(trace_id=0x00000000000000000000000000000000, span_id=0x0000000000000000, trace_flags=0x00, trace_state=[], is_remote=False))
-- Attach  <Token var=<ContextVar name='current_context' default={} at 0x7f04c507ea70> at 0x7f04c438eac0>
-- Attach  <Token var=<ContextVar name='current_context' default={} at 0x7f04c507ea70> at 0x7f04c438ed40>
---- From HTTP: 00-1ede97640306257aad3de05d4d0a2079-d80ade9ffb28f0cd-01
-- Attach  <Token var=<ContextVar name='current_context' default={} at 0x7f04c507ea70> at 0x7f04c438f080>
-- Detach  <Token var=<ContextVar name='current_context' default={} at 0x7f04c507ea70> at 0x7f04c438f080>
{"trace_id": "1ede97640306257aad3de05d4d0a2079", "span_id": "3093d4f2979b6ea9"}
-- Attach  <Token var=<ContextVar name='current_context' default={} at 0x7f04c507ea70> at 0x7f04c438f540>
-- Detach  <Token var=<ContextVar name='current_context' default={} at 0x7f04c507ea70> at 0x7f04c438f540>
{"trace_id": "1ede97640306257aad3de05d4d0a2079", "span_id": "3093d4f2979b6ea9"}
-- Attach  <Token var=<ContextVar name='current_context' default={} at 0x7f04c507ea70> at 0x7f04c438f740>
-- Detach  <Token var=<ContextVar name='current_context' default={} at 0x7f04c507ea70> at 0x7f04c438f740>
-- Detach  <Token var=<ContextVar name='current_context' default={} at 0x7f04c507ea70> at 0x7f04c438ed40>
-- Detach  <Token var=<ContextVar name='current_context' default={} at 0x7f04c507ea70> at 0x7f04c438eac0>

---- HTTP call start
NonRecordingSpan(SpanContext(trace_id=0x00000000000000000000000000000000, span_id=0x0000000000000000, trace_flags=0x00, trace_state=[], is_remote=False))
-- Attach  <Token var=<ContextVar name='current_context' default={} at 0x7f04c507ea70> at 0x7f04c438fac0>
-- Attach  <Token var=<ContextVar name='current_context' default={} at 0x7f04c507ea70> at 0x7f04c438fd40>
---- From HTTP: 00-41946a2aef9860e175524c6e7517d041-1de81ff4bc522e5f-01
-- Attach  <Token var=<ContextVar name='current_context' default={} at 0x7f04c507ea70> at 0x7f04bc490100>
-- Detach  <Token var=<ContextVar name='current_context' default={} at 0x7f04c507ea70> at 0x7f04bc490100>
{"trace_id": "41946a2aef9860e175524c6e7517d041", "span_id": "9bb5ad1366bdc997"}
-- Attach  <Token var=<ContextVar name='current_context' default={} at 0x7f04c507ea70> at 0x7f04bc4905c0>
-- Detach  <Token var=<ContextVar name='current_context' default={} at 0x7f04c507ea70> at 0x7f04bc4905c0>
{"trace_id": "41946a2aef9860e175524c6e7517d041", "span_id": "9bb5ad1366bdc997"}
-- Attach  <Token var=<ContextVar name='current_context' default={} at 0x7f04c507ea70> at 0x7f04bc4907c0>
-- Detach  <Token var=<ContextVar name='current_context' default={} at 0x7f04c507ea70> at 0x7f04bc4907c0>
-- Detach  <Token var=<ContextVar name='current_context' default={} at 0x7f04c507ea70> at 0x7f04c438fd40>
-- Detach  <Token var=<ContextVar name='current_context' default={} at 0x7f04c507ea70> at 0x7f04c438fac0>

Actual Result

The non expected behaviour:

---- HTTP call start
NonRecordingSpan(SpanContext(trace_id=0x00000000000000000000000000000000, span_id=0x0000000000000000, trace_flags=0x00, trace_state=[], is_remote=False))
-- Attach  <Token var=<ContextVar name='current_context' default={} at 0x7f9558c6f290> at 0x7f9553fff580>
{'current-span-1cfff2ec-c830-49ea-8c63-7905b29e6847': NonRecordingSpan(SpanContext(trace_id=0x733247fb3efe5fe2b7fa8a5db0cabd6b, span_id=0xd1fa76b36391d33d, trace_flags=0x01, trace_state=[], is_remote=True))}
-- Attach  <Token var=<ContextVar name='current_context' default={} at 0x7f9558c6f290> at 0x7f95536e6740>
---- From HTTP: 00-733247fb3efe5fe2b7fa8a5db0cabd6b-d1fa76b36391d33d-01
{'current-span-1cfff2ec-c830-49ea-8c63-7905b29e6847': _Span(name="POST /estimate/", context=SpanContext(trace_id=0x733247fb3efe5fe2b7fa8a5db0cabd6b, span_id=0xb5d3e2c16655d2b6, trace_flags=0x01, trace_state=[], is_remote=False))}
-- Attach  <Token var=<ContextVar name='current_context' default={} at 0x7f9558c6f290> at 0x7f9551c0ef00>
-- Detach  <Token var=<ContextVar name='current_context' default={} at 0x7f9558c6f290> at 0x7f9551c0ef00>
-- Attach  <Token var=<ContextVar name='current_context' default={} at 0x7f9558c6f290> at 0x7f9551c0f040>
-- Detach  <Token var=<ContextVar name='current_context' default={} at 0x7f9558c6f290> at 0x7f9551c0f040>
-- Attach  <Token var=<ContextVar name='current_context' default={} at 0x7f9558c6f290> at 0x7f9551c0f200>
-- Detach  <Token var=<ContextVar name='current_context' default={} at 0x7f9558c6f290> at 0x7f9551c0f200>
-- Attach  <Token var=<ContextVar name='current_context' default={} at 0x7f9558c6f290> at 0x7f9551c0f480>
-- Detach  <Token var=<ContextVar name='current_context' default={} at 0x7f9558c6f290> at 0x7f9551c0f480>
{"trace_id": "733247fb3efe5fe2b7fa8a5db0cabd6b", "span_id": "b5d3e2c16655d2b6"}
-- Attach  <Token var=<ContextVar name='current_context' default={} at 0x7f9558c6f290> at 0x7f95536ce700>
-- Detach  <Token var=<ContextVar name='current_context' default={} at 0x7f9558c6f290> at 0x7f95536ce700>
{"trace_id": "733247fb3efe5fe2b7fa8a5db0cabd6b", "span_id": "b5d3e2c16655d2b6"}
-- Attach  <Token var=<ContextVar name='current_context' default={} at 0x7f9558c6f290> at 0x7f951f330900>
-- Detach  <Token var=<ContextVar name='current_context' default={} at 0x7f9558c6f290> at 0x7f951f330900>
-- Detach  <Token var=<ContextVar name='current_context' default={} at 0x7f9558c6f290> at 0x7f95536e6740>
-- Detach  <Token var=<ContextVar name='current_context' default={} at 0x7f9558c6f290> at 0x7f9553fff580>

---- HTTP call start
_Span(name="POST /estimate/", context=SpanContext(trace_id=0x733247fb3efe5fe2b7fa8a5db0cabd6b, span_id=0xb5d3e2c16655d2b6, trace_flags=0x01, trace_state=[], is_remote=False))
-- Attach  <Token var=<ContextVar name='current_context' default={} at 0x7f9558c6f290> at 0x7f95435df780>
---- From HTTP: 00-6eb43e73f936aee8b83328f1d9c901b7-b3ed9b4f5e27fb35-01
{'current-span-1cfff2ec-c830-49ea-8c63-7905b29e6847': _Span(name="POST /estimate/", context=SpanContext(trace_id=0x733247fb3efe5fe2b7fa8a5db0cabd6b, span_id=0xe35d2e0ce570cc68, trace_flags=0x01, trace_state=[], is_remote=False))}
-- Attach  <Token var=<ContextVar name='current_context' default={} at 0x7f9558c6f290> at 0x7f9541916b40>
-- Detach  <Token var=<ContextVar name='current_context' default={} at 0x7f9558c6f290> at 0x7f9541916b40>
-- Attach  <Token var=<ContextVar name='current_context' default={} at 0x7f9558c6f290> at 0x7f9581233000>
-- Detach  <Token var=<ContextVar name='current_context' default={} at 0x7f9558c6f290> at 0x7f9581233000>
-- Attach  <Token var=<ContextVar name='current_context' default={} at 0x7f9558c6f290> at 0x7f94f7d80400>
-- Detach  <Token var=<ContextVar name='current_context' default={} at 0x7f9558c6f290> at 0x7f94f7d80400>
-- Attach  <Token var=<ContextVar name='current_context' default={} at 0x7f9558c6f290> at 0x7f9558935940>
-- Detach  <Token var=<ContextVar name='current_context' default={} at 0x7f9558c6f290> at 0x7f9558935940>
{"trace_id": "733247fb3efe5fe2b7fa8a5db0cabd6b", "span_id": "e35d2e0ce570cc68"}
-- Attach  <Token var=<ContextVar name='current_context' default={} at 0x7f9558c6f290> at 0x7f95435f3240>
-- Detach  <Token var=<ContextVar name='current_context' default={} at 0x7f9558c6f290> at 0x7f95435f3240>
-- Attach  <Token var=<ContextVar name='current_context' default={} at 0x7f9558c6f290> at 0x7f954360cb40>
-- Detach  <Token var=<ContextVar name='current_context' default={} at 0x7f9558c6f290> at 0x7f954360cb40>
-- Detach  <Token var=<ContextVar name='current_context' default={} at 0x7f9558c6f290> at 0x7f95435df780>

Additional context

No response

Would you like to implement a fix?

None