Warning triggered by asgi.OpenTelemetryMiddleware

[sk-]

Describe your environment
Python: 3.10.7
opentelemetry-instrumentation-asgi: 0.33b0
opentelemetry-api 1.12.0
Fastapi: 0.79.0

Steps to reproduce
Setup the asgi middleware with fastapi as following:

app = fastapi.FastAPI()
app.add_middleware(OpenTelemetryMiddleware)
# Configure OTEL exporter

What is the expected behavior?
We should not see any warnings.

What is the actual behavior?
The following warning is raised multiple times.

An instrument with name http.server.duration, type Histogram, unit ms and description measures the duration of the inbound HTTP request has been created already.

Additional context
Seems to be related to open-telemetry/opentelemetry-python#2558. This is the code triggering the issue

https://github.com/open-telemetry/opentelemetry-python/blob/75313b6c6d58945c1401622b6683ccdd28657984/opentelemetry-sdk/src/opentelemetry/sdk/metrics/_internal/__init__.py#L195-L202

I imagine that somehow FastAPI is creating multiple instances of the middleware, and hence the instruments are created multiple times.

Labels: asgi, warning, fastapi

[sanketmehta28]

What command do you run to execute the code?

[sk-]

@sanketmehta28 we use the command gunicorn -k uvicorn.workers.UvicornWorker --bind 0.0.0.0:5000 app.main:app --workers "$WORKERS", and the warning also occurs when using uvicorn app.main:app --workers "$WORKERS".

Both commands produce one warning at startup for each of the WORKERS, even in the case we use a single worker.

[TheAnshul756]

@sk-
I suspect your fastapi is already instrumented by auto-instrumentation even before you created your app. To check, you can print the type of app you created using print(type(app)). What do you get with this print statement?

[sk-]

Thanks @TheAnshul756 that pointed me to the right direction. I managed to create a small reproduction case

import fastapi
from fastapi.exception_handlers import http_exception_handler
from opentelemetry.instrumentation.asgi import OpenTelemetryMiddleware
from opentelemetry.metrics import set_meter_provider
from opentelemetry.sdk.metrics import MeterProvider
from opentelemetry.sdk.metrics.export import ConsoleMetricExporter, PeriodicExportingMetricReader

app = fastapi.FastAPI()

# OTEL Middleware
app.add_middleware(OpenTelemetryMiddleware)

# OTEL Setup
reader = PeriodicExportingMetricReader(ConsoleMetricExporter(), 3000)
provider = MeterProvider(
    metric_readers=[reader],
)
set_meter_provider(provider)

# Exception handler
@app.exception_handler(fastapi.HTTPException)
async def custom_http_exception_handler(
    request: fastapi.Request, e: fastapi.HTTPException
) -> fastapi.responses.JSONResponse:
    return await http_exception_handler(request, e)

The culprit seems to be the order in which things are being done. If I move the exception_handler before the OTEL middleware, then it works.

Below are all the combinations and whether it works:

• OTEL Middleware, OTEL Setup, Exception Handler: does not work
• OTEL Setup, OTEL Middleware, Exception Handler: does not work
• OTEL Middleware, Exception Handler, OTEL Setup: does not work
• OTEL Setup, Exception Handler, OTEL Middleware: does work
• Exception Handler, OTEL Middleware, OTEL Setup: does work
• Exception Handler, OTEL Setup, OTEL Middleware: does work

The problem is that calling app.exception_handler or even calling app.add_middleware reconstructs all middleware instances (build_middleware_stack), meaning the warning is going to be raised.

I think it's not ideal that the OpenTelemetryMiddleware can only be built once, because that means it must be the last middleware that's inserted using add_middleware. It's be great if that info was somewhere in the documentation.

[TheAnshul756]

I think it's not ideal that the OpenTelemetryMiddleware can only be built once, because that means it must be the last middleware that's inserted using add_middleware. It's be great if that info was somewhere in the documentation.

Yes, the warning is from the creation of metric data models, and there is nothing wrong with initialising the middleware again and again. The model creation method throws a warning if there is already an existing data model with the same name, unit and detail and does not create another, which is the expected behaviour.
And I agree it is weird from a user's point of view to get a warning if nothing is wrong from their side. To avoid this, we can add a check for the existing data model if it exists before creating or else we can also have an API like 'get_histogram', which will create one if it doesn't exist or it'll return the existing one.

@srikanthccv what do you think?

[srikanthccv]

Documenting this behavior would be ideal for this issue. We don't want to introduce additional things to API interface unless necessary.

[brent-moffit]

After seeing this warning myself I did my own investigation and the only thing I will add is that this is happening because of how Starlette (the core of FastAPI) manages middleware. It looks like it'll probably be fixed in a future release.

If you're curious, the old add_middleware implementation did this:

    def add_middleware(
        self, middleware_class: type, **options: typing.Any
    ) -> None:  # pragma: no cover
        self.user_middleware.insert(0, Middleware(middleware_class, **options))
        self.middleware_stack = self.build_middleware_stack()

As a result, each time middleware is added build_middleware_stack() is called, which initializes new instances of each middleware class in user_middleware and causes this warning. The new code lazily loads middleware only once when the first request is handled:

    def add_middleware(self, middleware_class: type, **options: typing.Any) -> None:
        if self.middleware_stack is not None:  # pragma: no cover
            raise RuntimeError("Cannot add middleware after an application has started")
        self.user_middleware.insert(0, Middleware(middleware_class, **options))