fastapi: fix wrapping of middlewares #3012

adriangb · 2024-11-15T15:31:01Z

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 · 2024-11-19T08:34:26Z

@adriangb Please take a look at the failing tests

lzchen · 2024-11-19T20:51:10Z

.../opentelemetry-instrumentation-fastapi/src/opentelemetry/instrumentation/fastapi/__init__.py

+                # are handled.
+                # This should not happen unless there is a bug in OpenTelemetryMiddleware, but if there is we don't want that
+                # to impact the user's application just because we wrapped the middlewares in this order.
+                stack = ServerErrorMiddleware(stack)


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?

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.)

Since asgi middleware does not have exception handling of requests on it's own, wouldn't legitimate exceptions that are raised from the request itself (that we would want to collect telemetry from) be swallowed up by the new middleware? Or does ServerErrorMiddleware ONLY handle 500s? Apologies, I'm not very familiar with the inner workings of it.

Kludex · 2024-11-20T08:25:30Z

fixes #795

adriangb · 2024-11-27T00:35:15Z

instrumentation/opentelemetry-instrumentation-fastapi/tests/test_fastapi_instrumentation.py

@@ -170,7 +170,8 @@ def setUp(self):
        self._instrumentor = otel_fastapi.FastAPIInstrumentor()
        self._app = self._create_app()
        self._app.add_middleware(HTTPSRedirectMiddleware)
-        self._client = TestClient(self._app)
+        self._client = TestClient(self._app, base_url="https://testserver:443")


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 · 2024-11-27T00:35:41Z

@adriangb Please take a look at the failing tests

@xrmx see #3012 (comment)

adriangb · 2024-11-27T00:37:28Z

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

Kludex · 2024-11-27T10:12:51Z

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

xrmx · 2024-11-27T08:56:23Z

.../opentelemetry-instrumentation-fastapi/src/opentelemetry/instrumentation/fastapi/__init__.py

+                app = ServerErrorMiddleware(app)
+                return app
+
+            app._original_build_middleware_stack = app.build_middleware_stack


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

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

@xrmx genuine question: what would be the benefit of that in this case?

instrumentation/opentelemetry-instrumentation-fastapi/tests/test_fastapi_instrumentation.py

vanyae-cqc · 2024-11-27T15:12:06Z

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 · 2024-11-27T16:19:52Z

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

xrmx

I trust you on the fastapi knowledge but would be nice to add a test to check that the change does what it's supposed to fix

adriangb · 2024-12-03T16:01:29Z

Ups looks like that got lost, I had added it in 4220b09

Co-authored-by: Riccardo Magliocchetti <[email protected]>

adriangb · 2024-12-03T16:05:40Z

Added back and updated the branch

lzchen · 2024-12-03T17:22:08Z

.../opentelemetry-instrumentation-fastapi/src/opentelemetry/instrumentation/fastapi/__init__.py

-        tracer_provider=None,
-        meter_provider=None,
-        excluded_urls=None,
+        tracer_provider: TracerProvider | None = None,


Nit: Could you use typing.Optional to be consistent with most other places in the code?

Other places are out dated.

What should happen is to start switching the other places.

Hard agreement

For context the from __future__ import annotations let us use this syntax

xrmx · 2024-12-04T15:00:36Z

ICYMI the added test is red

adriangb · 2024-12-04T15:39:52Z

Thanks. I hadn't understood how the tests are parametrized and that _create_app is overridden in a subclass.

adriangb · 2024-12-13T15:18:57Z

@xrmx @lzchen can we get this merged please? I believe this is a major issue that deserves attention.

Kludex · 2024-12-18T09:42:52Z

.../opentelemetry-instrumentation-fastapi/src/opentelemetry/instrumentation/fastapi/__init__.py

+                app = ServerErrorMiddleware(app)
+                return app
+
+            app._original_build_middleware_stack = app.build_middleware_stack


@xrmx genuine question: what would be the benefit of that in this case?

Kludex · 2024-12-18T09:46:12Z

instrumentation/opentelemetry-instrumentation-fastapi/tests/test_fastapi_instrumentation.py

+        # run the lifespan, initialize the middleware stack
+        # this is more in-line with what happens in a real application when the server starts up
+        self._exit_stack = ExitStack()
+        self._exit_stack.enter_context(self._client)


The build_middleware_stack this PR patches is called on the startup event - which the TestClient only runs if called within a context manager, that's why @adriangb is using ExitStack here. FYI

adriangb requested a review from a team as a code owner November 15, 2024 15:35

Kludex approved these changes Nov 15, 2024

View reviewed changes

codefromthecrypt approved these changes Nov 19, 2024

View reviewed changes

lzchen reviewed Nov 19, 2024

View reviewed changes

adriangb force-pushed the fix-asgi-middleware branch from e406be8 to 3d8dd4f Compare November 27, 2024 00:29

adriangb commented Nov 27, 2024

View reviewed changes

adriangb requested a review from lzchen November 27, 2024 00:35

adriangb requested a review from codefromthecrypt November 27, 2024 00:36

xrmx reviewed Nov 27, 2024

View reviewed changes

adriangb requested a review from xrmx November 27, 2024 16:20

xrmx reviewed Dec 3, 2024

View reviewed changes

adriangb added 11 commits December 3, 2024 08:03

fastapi: fix wrapping of middlewares

707b192

fix import, super

dcfab56

add test

a78b1c6

changelog

e25e143

lint

54d4482

lint

81f1e83

fix

96e66b9

ci

46e1809

fix wip

daa5a1b

fix

de9e795

fix

f9d348b

adriangb and others added 8 commits December 3, 2024 08:04

lint

7bc89b3

lint

f629932

Exit?

437891b

Update test_fastapi_instrumentation.py

1340ac7

Co-authored-by: Riccardo Magliocchetti <[email protected]>

remove break

003d7af

fix

be26393

remove dunders

ec545b7

add test

f825c76

adriangb force-pushed the fix-asgi-middleware branch from 7497d32 to f825c76 Compare December 3, 2024 16:04

lint

d909633

lzchen reviewed Dec 3, 2024

View reviewed changes

adriangb added 2 commits December 4, 2024 09:34

add endpoint to class

0de3e37

fmt

d57b673

adriangb requested review from lzchen and xrmx December 13, 2024 15:24

Kludex approved these changes Dec 18, 2024

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

fastapi: fix wrapping of middlewares #3012

fastapi: fix wrapping of middlewares #3012

adriangb commented Nov 15, 2024 •

edited

Loading

codefromthecrypt left a comment

xrmx commented Nov 19, 2024

lzchen Nov 19, 2024 •

edited

Loading

adriangb Nov 20, 2024

lzchen Dec 3, 2024

Kludex commented Nov 20, 2024

adriangb Nov 27, 2024

adriangb commented Nov 27, 2024 •

edited

Loading

adriangb commented Nov 27, 2024

Kludex commented Nov 27, 2024

xrmx Nov 27, 2024

adriangb Nov 27, 2024

Kludex Dec 18, 2024

vanyae-cqc commented Nov 27, 2024 •

edited

Loading

adriangb commented Nov 27, 2024

xrmx left a comment

adriangb commented Dec 3, 2024

adriangb commented Dec 3, 2024

lzchen Dec 3, 2024

Kludex Dec 3, 2024

adriangb Dec 3, 2024

xrmx Dec 3, 2024

xrmx commented Dec 4, 2024

adriangb commented Dec 4, 2024

adriangb commented Dec 13, 2024 •

edited

Loading

Kludex Dec 18, 2024

Kludex Dec 18, 2024

fastapi: fix wrapping of middlewares #3012

Are you sure you want to change the base?

fastapi: fix wrapping of middlewares #3012

Conversation

adriangb commented Nov 15, 2024 • edited Loading

codefromthecrypt left a comment

Choose a reason for hiding this comment

xrmx commented Nov 19, 2024

lzchen Nov 19, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Kludex commented Nov 20, 2024

Choose a reason for hiding this comment

adriangb commented Nov 27, 2024 • edited Loading

adriangb commented Nov 27, 2024

Kludex commented Nov 27, 2024

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

vanyae-cqc commented Nov 27, 2024 • edited Loading

adriangb commented Nov 27, 2024

xrmx left a comment

Choose a reason for hiding this comment

adriangb commented Dec 3, 2024

adriangb commented Dec 3, 2024

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

xrmx commented Dec 4, 2024

adriangb commented Dec 4, 2024

adriangb commented Dec 13, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

adriangb commented Nov 15, 2024 •

edited

Loading

lzchen Nov 19, 2024 •

edited

Loading

adriangb commented Nov 27, 2024 •

edited

Loading

vanyae-cqc commented Nov 27, 2024 •

edited

Loading

adriangb commented Dec 13, 2024 •

edited

Loading