Fastapi: multiple http receive and send spans for single request

[Nan2018]

I am using opentelemetry-instrumentation-fastapi. Everything works great except I get many small spans of http receive and http send for a single request. (see the screenshot below) Is there a way to combine these spans?

[owais]

Hi, are you using websockets by any chance? Could you please share a reproducible example we can try?

[Nan2018]

not using websocket. Here is an example app

from pydantic import BaseModel
from fastapi import FastAPI, File, UploadFile
from opentelemetry import trace
from opentelemetry.instrumentation.fastapi import FastAPIInstrumentor
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import BatchSpanProcessor, ConsoleSpanExporter
from opentelemetry.sdk.resources import Resource
import uvicorn

app = FastAPI()

trace.set_tracer_provider(TracerProvider(Resource.create({"service.name": "app"})))
trace.get_tracer_provider().add_span_processor(
    BatchSpanProcessor(ConsoleSpanExporter())
)
FastAPIInstrumentor.instrument_app(app)

class Item(BaseModel):
    data: bytes


@app.post("/upload")
async def post(upload: UploadFile = File(...)):
    data = await upload.read()
    return Item(data=data)


if __name__ == "__main__":
    import uvicorn

    uvicorn.run(app, log_config="log-config.yaml")

uploading a file of 400KB gives me the following spans:

{
    "name": "/upload http receive",
    "context": {
        "trace_id": "0xcd95090bd8c96769a30a985e4341ccf7",
        "span_id": "0x9fcd3e85560a6ed7",
        "trace_state": "[]"
    },
    "kind": "SpanKind.INTERNAL",
    "parent_id": "0xeda32507fe593eb6",
    "start_time": "2021-08-27T20:52:43.723703Z",
    "end_time": "2021-08-27T20:52:43.723703Z",
    "status": {
        "status_code": "UNSET"
    },
    "attributes": {
        "type": "http.request"
    },
    "events": [],
    "links": [],
    "resource": {
        "telemetry.sdk.language": "python",
        "telemetry.sdk.name": "opentelemetry",
        "telemetry.sdk.version": "1.5.0",
        "service.name": "app"
    }
}
{
    "name": "/upload http receive",
    "context": {
        "trace_id": "0xcd95090bd8c96769a30a985e4341ccf7",
        "span_id": "0x68f63c70e2ad40b3",
        "trace_state": "[]"
    },
    "kind": "SpanKind.INTERNAL",
    "parent_id": "0xeda32507fe593eb6",
    "start_time": "2021-08-27T20:52:43.752706Z",
    "end_time": "2021-08-27T20:52:43.753703Z",
    "status": {
        "status_code": "UNSET"
    },
    "attributes": {
        "type": "http.request"
    },
    "events": [],
    "links": [],
    "resource": {
        "telemetry.sdk.language": "python",
        "telemetry.sdk.name": "opentelemetry",
        "telemetry.sdk.version": "1.5.0",
        "service.name": "app"
    }
}
{
    "name": "/upload http receive",
    "context": {
        "trace_id": "0xcd95090bd8c96769a30a985e4341ccf7",
        "span_id": "0x9ce406c65120d0bd",
        "trace_state": "[]"
    },
    "kind": "SpanKind.INTERNAL",
    "parent_id": "0xeda32507fe593eb6",
    "start_time": "2021-08-27T20:52:43.807709Z",
    "end_time": "2021-08-27T20:52:43.808707Z",
    "status": {
        "status_code": "UNSET"
    },
    "attributes": {
        "type": "http.request"
    },
    "events": [],
    "links": [],
    "resource": {
        "telemetry.sdk.language": "python",
        "telemetry.sdk.name": "opentelemetry",
        "telemetry.sdk.version": "1.5.0",
        "service.name": "app"
    }
}
{
    "name": "/upload http send",
    "context": {
        "trace_id": "0xcd95090bd8c96769a30a985e4341ccf7",
        "span_id": "0x90f1aa7da6a7f897",
        "trace_state": "[]"
    },
    "kind": "SpanKind.INTERNAL",
    "parent_id": "0xeda32507fe593eb6",
    "start_time": "2021-08-27T20:52:43.819706Z",
    "end_time": "2021-08-27T20:52:43.820673Z",
    "status": {
        "status_code": "UNSET"
    },
    "attributes": {
        "http.status_code": 200,
        "type": "http.response.start"
    },
    "events": [],
    "links": [],
    "resource": {
        "telemetry.sdk.language": "python",
        "telemetry.sdk.name": "opentelemetry",
        "telemetry.sdk.version": "1.5.0",
        "service.name": "app"
    }
}
{
    "name": "/upload http send",
    "context": {
        "trace_id": "0xcd95090bd8c96769a30a985e4341ccf7",
        "span_id": "0x3aba6b15b0f9895e",
        "trace_state": "[]"
    },
    "kind": "SpanKind.INTERNAL",
    "parent_id": "0xeda32507fe593eb6",
    "start_time": "2021-08-27T20:52:43.820673Z",
    "end_time": "2021-08-27T20:52:43.821711Z",
    "status": {
        "status_code": "UNSET"
    },
    "attributes": {
        "type": "http.response.body"
    },
    "events": [],
    "links": [],
    "resource": {
        "telemetry.sdk.language": "python",
        "telemetry.sdk.name": "opentelemetry",
        "telemetry.sdk.version": "1.5.0",
        "service.name": "app"
    }
}
{
    "name": "/upload",
    "context": {
        "trace_id": "0xcd95090bd8c96769a30a985e4341ccf7",
        "span_id": "0xeda32507fe593eb6",
        "trace_state": "[]"
    },
    "kind": "SpanKind.SERVER",
    "parent_id": null,
    "start_time": "2021-08-27T20:52:43.722703Z",
    "end_time": "2021-08-27T20:52:43.822669Z",
    "status": {
        "status_code": "UNSET"
    },
    "attributes": {
        "http.scheme": "http",
        "http.host": "127.0.0.1:8000",
        "net.host.port": 8000,
        "http.flavor": "1.1",
        "http.target": "/upload",
        "http.url": "http://127.0.0.1:8000/upload",
        "http.method": "POST",
        "http.server_name": "localhost:8000",
        "http.user_agent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.159 Safari/537.36",
        "net.peer.ip": "127.0.0.1",
        "net.peer.port": 56124,
        "http.route": "/upload",
        "http.status_code": 200
    },
    "events": [],
    "links": [],
    "resource": {
        "telemetry.sdk.language": "python",
        "telemetry.sdk.name": "opentelemetry",
        "telemetry.sdk.version": "1.5.0",
        "service.name": "app"
    }
}

[adriangb]

This is per design I think: there are spans for each time data is received and sent (i.e. things are going over the wire). I think this is important because it would let you detect if for example the issue is a slow client.

[niehongxu116]

I also have a similar issue with a POST endpoint that uses JSON transmission. In the trace, there are multiple HTTP receive events. I suspect this might be because the request body is too large and exceeds the buffer size, or is it caused by something else?

uvicorn == 0.31.1
fastApi == 0.115.6
opentelemetry-instrumentation-fastapi == 0.49b2

[alexwilson1]

Exact same as above on POST of a large body. 10,000 spans generated.

Seems like a duplicate of this which contains a workaround and a link to the fix here.

TLDR - Add exclude_spans e.g.,
FastAPIInstrumentor.instrument_app(app, exclude_spans=["send", "receive"])

[SuperSecureHuman]

So in this case, is the workaround able to preserve the inputs and the outputs of this route.. I have a similar issue working with FastAPI streaming responses..

At the moment, I would not want to trace the chunks (events) rather the input and output and overall latency of the route (from request to stream end)