4

I am developing a FastAPI app, and my goal is to record some information in a Request scope and then reuse this information later in log records.

My idea was to use context vars to store the "request context", use a middleware to manipulate the request and set the context var, and finally use a LogFilter to attach the context vars values to the LogRecord.

This is my app skeleton

logger = logging.getLogger(__name__) app = FastAPI() app.add_middleware(SetterMiddlware) app.add_middleware(FooMiddleware) @app.get("/") def read_root(setter = Depends(set_request_id)): print("Adding req_id to body", req_id.get()) # This is 1234567890 logging.info("hello") return {"Req_id": str(req_id.get())}

and those are my middlewares

class SetterMiddlware(BaseHTTPMiddleware): async def dispatch(self, request: Request, call_next): calculated_id = "1234567890" req_id.set(calculated_id) request.state.req_id = calculated_id response = await call_next(request) return response class FooMiddleware(BaseHTTPMiddleware): async def dispatch(self, request: Request, call_next): response = await call_next(request) return response

and the Logging Filter

from vars import req_id class CustomFilter(Filter): """Logging filter to attach the user's authorization to log records""" def filter(self, record: LogRecord) -> bool: record.req_id = req_id.get() return True

And finally following a part of my log configuration

... "formatters": { "default": { "format": "%(levelname)-9s %(asctime)s [%(req_id)s]| %(message)s", "datefmt": "%Y-%m-%d,%H:%M:%S", }, }, "handlers": { ... "handlers": { "console": { "class": "logging.StreamHandler", "formatter": "default", "stream": "ext://sys.stderr", "filters": [ "custom_filter", ], "level": logging.NOTSET, }, ... "loggers": { "": { "handlers": ["console"], "level": logging.DEBUG, }, "uvicorn": {"handlers": ["console"], "propagate": False}, },

When SetterMiddlware is the latest added in the app (FooMiddleware commented in the example), my app logs as expected

Adding req_id to body 1234567890 INFO 2025-04-14,15:02:28 [1234567890]| hello INFO 2025-04-14,15:02:28 [1234567890]| 127.0.0.1:52912 - "GET / HTTP/1.1" 200

But if I add some other middleware after SetterMiddlware, uvicorn logger does not find anymore the context_var req_id set.

Adding req_id to body 1234567890 INFO 2025-04-14,15:03:56 [1234567890]| hello INFO 2025-04-14,15:03:56 [None]| 127.0.0.1:52919 - "GET / HTTP/1.1" 200

I tried using the package https://starlette-context.readthedocs.io/en/latest/ but I wasn't luckier; it looks like it suffers the same problems.

I would like to know why this behavior happens and how I can fix it, without the constraint of having the SetterMiddleware in the last middleware position.

Improve this question
2
  • Did you try reversing the order of the middlewares? The middlewares are executed in the reverse order of their addition. Commented Apr 21 at 8:35
  • @npk I know about the order, and they were in that order for a dependency reason unfortuntaly Commented Apr 23 at 12:53

2 Answers 2

Reset to default
2

Currently dealing with a similar setup and I spent some time digging..

I'm not sure if this truly answers the why in your question but what I found is that if I use a custom middleware class without inheriting from BaseHTTPMiddleware (à la Pure ASGI Middleware) the context variables get propagated correctly to the uvicorn access logger.

This might have something to do with the known starlette BaseHTTPMiddleware limitation of not propagating contextvars "upwards". IIRC there are also some raised anyio issues related to contextvars...

So the solution would be along the lines of:

from starlette.types import ASGIApp, Receive, Scope, Send class SetterMiddlware: def __init__(self, app: ASGIApp) -> None: self.app = app async def __call__(self, scope: Scope, receive: Receive, send: Send) -> None: calculated_id = "1234567890" req_id.set(calculated_id) request = Request(scope, receive) request.state.req_id = calculated_id response = await self.app(scope, receive, send) return response class FooMiddleware: def __init__(self, app: ASGIApp) -> None: self.app = app async def __call__(self, scope: Scope, receive: Receive, send: Send) -> None: response = await self.app(scope, receive, send) return response
Improve this answer
Sign up to request clarification or add additional context in comments.

1 Comment

I came up with the same conclusion a few days ago with the same chain of thought. I also dug into the Starlette code and it was clear that BaseHTTPmiddleware were run a in task group, therefore the context was copied, but when the child middleware/app exited the root middleware lost the changes in the context... as general approach asgi middleware should be the last added (therefore the first run) in an app
0

The problem most likely lies in that if you are using FastAPI/Starlette with synchronous code (in opposition to assynchronous code, with async def'ed calls everywhere), the framework code has to call your functions in other threads -

And upon making a call in other thread to call your view (likely with asyncio's loop.run_in_executor ) - your view will get an unitialized context in the other thread - the contextvar values set on the main loop thread won't be available there.

(For what is now a side note, Commit a214db0c to main CPython code made on 2025-04-10 (aka last Thursday) creates a new feature in the language itself that will make this possible - as an opt-in for the frameworks - but that is for Python 3.14 onwards (post Oct. 2025) )

In my package "extracontext" I also offer an alternative executor class which can preserve the contextvar values across threads - but that can only be used when YOUR code is the one making the loop.run_in_executor call - in this example, the code making this is the framework code, and it calls your view.

REPL snippet demonstrating the issue:

In [1]: import contextvars, threading In [2]: var = contextvars.ContextVar("var", default="root value") In [3]: def onthread(): ...: print(var.get()) ...: In [4]: async def middleware(): ...: var.set("child value") ...: loop = asyncio.get_running_loop() ...: await loop.run_in_executor(None, onthread) ...: print(var.get()) ...: In [5]: import asyncio In [6]: asyncio.run(middleware()); print(var.get()) root value child value root value

Too complex! What to do?

The simple fix is move all your code do async code: in the case of views, just declare them with async def - if you are performing no I/O (external network requests, database queries, etc) in your view, that is as simple as that. If you are, you have to turn that calls into asynchronous (and then, the way to do that requiring fewer modifications is to place all synchronous calls in loop.run_in_executor calls yourself) - but that should make the contextvars values available in your view.

 @app.get("/") async def read_root(setter = Depends(set_request_id)): print("Adding req_id to body", req_id.get()) # This is 1234567890 logging.info("hello") # need to make long network request with "requests": loop = asyncio.get_running_loop() result = await loop.run_in_executor(None, requests.get, <*args_to_requests.get>) ... return {"Req_id": str(req_id.get())}
Improve this answer

2 Comments

thank you for the answer. The problem persists even with async routes. And the weird stuff is that the route can access the context vars and find it set properly; it's just the uvicorn logger that can't. I was thinking about something like you said about the context copy, but in that case I would expect that alsot he router could not access the context
Logging threading.get_ident() in different middlewares and request handler might help, but this didn't solve it for me as I suspect there is some anyio thread switching going on which messes up the contextvars context. See my answer.

Start asking to get answers

Find the answer to your question by asking.

Ask question

Explore related questions

See similar questions with these tags.