FastAPI auto-instrumentation sends extra trace for a single API execution

[makeavish]

Describe Problem
I have a sample python project with FastAPI auto-instrumentation which export the traces to OTLP server, and I have a simple "GET" API which returns a "Hello": "World". But I notice it generates 2 traces instead of 1 for same API request. I was able to fix this issue after using TracerProvider from python otel sdk.

Describe your environment
fastapi==0.68.1
python-dotenv==0.19.0
uvicorn==0.15.0
requests
opentelemetry-distro==0.26b1
opentelemetry-exporter-otlp==1.7.1
opentelemetry-instrumentation-fastapi==0.26b1

Steps to reproduce
Here's the sample code that I am running:

import asyncio
from fastapi import FastAPI
from opentelemetry.instrumentation.fastapi import FastAPIInstrumentor
import requests
import random
random.seed(54321)


app = FastAPI()


@app.get("/")
async def read_root():
    return {"Hello": "World"}


@app.get("/ping")
async def health_check():
    return "pong"


@app.get("/items/{item_id}")
async def read_item(item_id: int, q: str = None):
    if item_id % 2 == 0:
        # mock io - wait for x seconds
        seconds = random.uniform(0, 3)
        await asyncio.sleep(seconds)
    return {"item_id": item_id, "q": q}


@app.get("/invalid")
async def invalid():
    raise ValueError("Invalid ")


@app.get("/external-api")
def external_api():
    seconds = random.uniform(0, 3)
    response = requests.get(f"https://httpbin.org/delay/{seconds}")
    response.close()
    return "ok"


FastAPIInstrumentor.instrument_app(app, excluded_urls="ping")

Run command: opentelemetry-instrument --traces_exporter console uvicorn main:app

When I make the below REST request:
curl --location --request GET 'http://localhost:8000/'
then I get 2 traces which are exactly same (except for span and trace Id).

What is the expected behavior?
Exactly one trace for one API execution

What is the actual behavior?
2 traces for one API execution

Additional context

I tried initializing tracer from python otel sdk and apparently it fixed the issue and now I am seeing exactly one trace for single API execution.
Here's that code which works:

import asyncio
from fastapi import FastAPI
from opentelemetry.instrumentation.fastapi import FastAPIInstrumentor
import requests
import random

from opentelemetry.sdk.trace import TracerProvider

tracer = TracerProvider()

random.seed(54321)


app = FastAPI()


@app.get("/")
async def read_root():
    return {"Hello": "World"}


@app.get("/ping")
async def health_check():
    return "pong"


@app.get("/items/{item_id}")
async def read_item(item_id: int, q: str = None):
    if item_id % 2 == 0:
        # mock io - wait for x seconds
        seconds = random.uniform(0, 3)
        await asyncio.sleep(seconds)
    return {"item_id": item_id, "q": q}


@app.get("/invalid")
async def invalid():
    raise ValueError("Invalid ")


@app.get("/external-api")
def external_api():
    seconds = random.uniform(0, 3)
    response = requests.get(f"https://httpbin.org/delay/{seconds}")
    response.close()
    return "ok"


FastAPIInstrumentor.instrument_app(app, tracer_provider=tracer, excluded_urls="ping")

To check difference between both the code you can check this PR: SigNoz/sample-fastAPI-app#2

[srikanthccv]

Are you sure it is two traces not two spans under same trace?

[makeavish]

@lonewolf3739 Yes I am sure that there are two traces.
Actually each request is generating 6 spans, 3 each for single trace.

[srikanthccv]

@makeavish I was unable to reproduce the issue here using your sample code. It doesn't generate two traces but only one trace with three spans. This is duplicate of #831. Please follow discussion there. Feel free to re-open if you can reproduce the issue of two traces for one request.

[makeavish]

@lonewolf3739 I see that you used TracerProvider() to get console spans, but as I said in description that when using TracerProvider() it is working fine (2nd Example).
Please run the first code snippet of my description as it is without using TracerProvider()
Also, to print spans on console, use this command to run the sample fastAPI app: opentelemetry-instrument --traces_exporter console uvicorn api:app

[srikanthccv]

@makeavish Setting sdk TracerProvider shouldn't change behaviour here. Based on your updated description -- you are instrumenting twice, once by opentelemetry-instrument and other by calling instrument_app(...) hence the two server traces. If you are going to use auto-instrumentation tool please avoid the semi-manual instrumentation calls such as FastAPIInstrumentor.instrument_app. Remove that line and follow the steps - you should only see one server trace.

[makeavish]

Thanks @lonewolf3739, I understood my mistake.
Also is it possible to set OTLP exporter endpoint without using TracerProvider when instrumenting via semi-manual way? For auto instrumentation, I was setting OTEL_EXPORTER_OTLP_ENDPOINT environment variable.

[srikanthccv]

I am not sure I understood your question. If you do not use the opentelemetry-instrument command then you have to set the SDK TracerProvider otherwise everything will be no-op.