fastapi: fix wrapping of middlewares

[adriangb]

MRE:

import anyio
import fastapi
import httpx
import uvicorn
from opentelemetry import trace
from opentelemetry.instrumentation.fastapi import FastAPIInstrumentor
from opentelemetry.sdk.resources import SERVICE_NAME, Resource
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import BatchSpanProcessor, ConsoleSpanExporter

resource = Resource(attributes={SERVICE_NAME: '🐛'})

traceProvider = TracerProvider(resource=resource)
processor = BatchSpanProcessor(ConsoleSpanExporter())
traceProvider.add_span_processor(processor)
trace.set_tracer_provider(traceProvider)

app = fastapi.FastAPI()

@app.get('/ok')
async def ok() -> int:
    return 123

@app.get('/error')
async def error() -> int:
    raise Exception('An error occurred!')

FastAPIInstrumentor.instrument_app(app)


async def main() -> None:
    config = uvicorn.Config(app=app, port=9999, log_config=None)
    server = uvicorn.Server(config)

    async with anyio.create_task_group() as tg:
        tg.start_soon(server.serve)
        await anyio.sleep(1)  # Wait for the server to start
        async with httpx.AsyncClient(base_url='http://localhost:9999') as client:
            response = await client.get('/ok')
            assert response.status_code == 200, f'{response.status_code}: {response.text}'
            response = await client.get('/error')
            assert response.status_code == 500,  f'{response.status_code}: {response.text}'
            tg.cancel_scope.cancel()


if __name__ == '__main__':
    anyio.run(main)

With this change it shows up properly

Run this and you'll see that there is no "http.status_code": 500 in the logs.

[codefromthecrypt]

nice comment and test!

[xrmx]

@adriangb Please take a look at the failing tests

[lzchen]

Just to clarify, is the purpose of this pr to handle exceptions generated from the OpenTelemetryMiddleware itself (if there is a bug) or unhandled exceptions thrown from the request?

[adriangb]

Yep! If there is a bug in OpenTelemetryMiddleware without this double wrapping then the server might not send a 500 to the client and instead abruptly disconnect. In practice I believe every ASGI server I know of does also have it's own handling of unhandled exceptions such that this would not be the case, but I'm not sure we want to rely on that + there would still be a noticeable change (different response content at least, maybe different headers, etc.)

[Kludex]

fixes #795

[adriangb]

This was the root cause of tests failures. It turns out every request was being made twice because it was getting redirected to https. Before this PR that wasn't being instrumented correctly, so this was not being caught! I think that's another major bug this PR is fixing.

[adriangb]

@adriangb Please take a look at the failing tests

@xrmx see #3012 (comment)

[adriangb]

@Kludex could you update the Starlette instrumentations after we finish up this PR? I'm assuming they have the same bugs.

[Kludex]

The pipeline has been running for some hours... 👀

[xrmx]

Question: do you think it would be possible to use wrapt for monkeypatching instead?

[adriangb]

I'd rather not. This is simpler and works just fine.

[vanyae-cqc]

Hello! Just wondering if you'd expect this to enable getting the trace_id in a FastAPI exception_handler?

This has been discussed in more detail here: open-telemetry/opentelemetry-python#3477, but currently OpenTelemetryMiddleware's context seems to be removed by the time an exception gets to the ServerErrorMiddleware.

Would be great to enable users to report back a trace_id when they get an unexpected 500 status response. Have tried to verify this PR provides this by running it locally but haven't had any luck - could be something wrong in my setup though.

[Update]: Have now verified this achieves the above behaviour - this fix is greatly appreciated!

[adriangb]

Fixed issue with test shutdown hanging. All checks passing now.