[Starlette] ordering of adding the ElasticAPM is no relevant and must be last middleware to be added

[bjoernmeier]

Describe the bug:

Since elastic-apm>=6.13.0 we did not get transaction information anymore from our FastAPI application. It turned out that since then the order of adding multiple layers of middleware is relevant. If a middleware is added after elasticapm.contrib.starlette.ElasticAPM the transaction information is missing when the transaction is closed here https://github.com/elastic/apm-agent-python/blob/main/elasticapm/instrumentation/packages/asyncio/starlette.py#L52. Meaning the call here https://github.com/elastic/apm-agent-python/blob/main/elasticapm/base.py#L324 returns None in such a case.

Reordering of adding the middleware layers does resolve the issue.

To Reproduce

1. create a FastAPI app:

import time

from fastapi import FastAPI
from elasticapm.contrib.starlette import make_apm_client, ElasticAPM
from starlette.middleware import Middleware
from starlette.middleware.base import BaseHTTPMiddleware


class CustomHeaderMiddleware(BaseHTTPMiddleware):
   async def dispatch(self, request, call_next):
       start_time = time.time()
       response = await call_next(request)
       process_time = time.time() - start_time
       response.headers["X-Process-Time"] = str(process_time)
       return response

apm = make_apm_client()
app = FastAPI()

# this ordering works
# app.add_middleware(CustomHeaderMiddleware)
app.add_middleware(ElasticAPM, client=apm)

# this order does not work
app.add_middleware(CustomHeaderMiddleware)

@app.get("/ok")
async def ok():
   return {"details": "ok"}


@app.get("/raise")
async def raise_route():
   raise ValueError("oho")

2. install requirements: elastic-apm, fastapi, uvicorn
3. run the app with an APM server running and define how to reach it:

ELASTIC_APM_SERVER_URL=http://localhost:8200
ELASTIC_APM_SECRET_TOKEN=
ELASTIC_APM_SERVICE_NAME=my-service
ELASTIC_APM_ENVIRONMENT=test

run it with: uvicorn app:app
4. check if transactions are send and complete in APM, which is not the case

Environment (please complete the following information)

• OS: Debian bullseye and OS X
• Python version: 3.10
• Framework and version: elastic-apm-6.13.2 fastapi-0.88.0 starlette-0.22.0 uvicorn-0.20.0
• APM Server version: 7.15.2 (local) and 8.4.2 on elastic-cloud.com
• Agent version: 6.13.0, 6.13.1, 6.13.2

Additional context

It seems that this happens since the change to the StarletteServerErrorMiddlewareInstrumentation done here https://github.com/elastic/apm-agent-python/pull/1674/files

• requirements.txt:

  Click to expand

  elastic-apm==6.13.2
  fastapi==0.88.0
  uvicorn==0.20.0
  

[basepi]

Hmmm, this is very odd that it's not working. My understanding was that the ServerErrorMiddleware will always be the outermost middleware due to these lines in FastAPI and Starlette. So the user middleware shouldn't matter? 🤔

We'll definitely take a look, thanks for providing a reproduction case.

[basepi]

I can reproduce this issue. Just trying to figure out the best solution, because relying on users to get the middleware order correct isn't a viable solution IMO.

[basepi]

I figured out the cause: docs and permalink

Because you're using a middleware which inherits from BaseHTTPMiddleware, our running transaction isn't propagated from our ElasticAPM middleware to the outer ServerErrorMiddleware because BaseHTTPMiddleware breaks contextvar propagation.

I am going to rely on a docs note for now, because I'm not sure how else to maintain our ability to collect all server errors while also allowing any order for BaseHTTPMiddleware.