ContextVar modified in async deps are not available in middleware (with structlog) #4696
Description
First Check
- I added a very descriptive title to this issue.
- I used the GitHub search to find a similar issue and didn't find it.
- I searched the FastAPI documentation, with the integrated search.
- I already searched in Google "How to X in FastAPI" and didn't find any information.
- I already read and followed all the tutorial in the docs and didn't find an answer.
- I already checked if it is not related to FastAPI but to Pydantic.
- I already checked if it is not related to FastAPI but to Swagger UI.
- I already checked if it is not related to FastAPI but to ReDoc.
Commit to Help
- I commit to help with one of those options 👆
Example Code
import logging
import uuid
from typing import Callable, Awaitable
import structlog
from fastapi import Depends, FastAPI, Request, Response
app = FastAPI()
Middleware = Callable[[Request], Awaitable[Response]]
logger = structlog.get_logger(__name__)
@app.middleware("http")
async def request_middleware(request: Request, call_next: Middleware) -> Response:
structlog.contextvars.clear_contextvars()
request_id = str(uuid.uuid4())
structlog.contextvars.bind_contextvars(request_id=request_id)
logger.info(
"request received (in middlware)",
method=request.method,
path=request.url.path,
client=request.client and request.client.host,
ua=request.headers.get("User-Agent"),
)
response = await call_next(request)
# THIS LINE WON'T INCLUDE in_dep="true"
logger.info("request finished (in middleware)")
response.headers["Request-ID"] = request_id
return response
def setup_logging() -> None:
"""Configure logging."""
logging.basicConfig(format="%(message)s", level="INFO")
processors = [
structlog.contextvars.merge_contextvars,
structlog.stdlib.add_logger_name,
structlog.stdlib.add_log_level,
structlog.stdlib.PositionalArgumentsFormatter(),
structlog.processors.TimeStamper(fmt="%Y-%m-%d %H:%M.%S"),
structlog.processors.StackInfoRenderer(),
structlog.processors.format_exc_info,
structlog.dev.ConsoleRenderer(),
]
structlog.configure(
processors=processors, # type: ignore
wrapper_class=structlog.stdlib.BoundLogger,
logger_factory=structlog.stdlib.LoggerFactory(),
cache_logger_on_first_use=True,
)
async def dep():
logger.info("dep start")
structlog.contextvars.bind_contextvars(in_dep="true")
logger.info("dep end")
return "foo"
@app.get("/")
async def home(value: str = Depends(dep)):
logger.info("hello")
return value
setup_logging()Description
curl http://127.0.0.1:8001The included code lets you reproduce the issue. This is what's logged:
2022-03-17 15:22.38 [info ] request received (in middlware) [app] client=127.0.0.1 method=GET path=/ request_id=3cd6772f-4cb4-4cd4-9ace-44c2a3f19710 ua=curl/7.77.0
2022-03-17 15:22.38 [info ] dep start [app] request_id=3cd6772f-4cb4-4cd4-9ace-44c2a3f19710
2022-03-17 15:22.38 [info ] dep end [app] in_dep=true request_id=3cd6772f-4cb4-4cd4-9ace-44c2a3f19710
2022-03-17 15:22.38 [info ] hello [app] in_dep=true request_id=3cd6772f-4cb4-4cd4-9ace-44c2a3f19710
2022-03-17 15:22.38 [info ] request finished (in middleware) [app] request_id=3cd6772f-4cb4-4cd4-9ace-44c2a3f19710
In the last "request finished" line, I was expected in_dep=true to be kept, but it's not there.
It might be coming from structlog, but I doubt it since it's probably just using contextvars under the hood.
Operating System
macOS
Operating System Details
No response
FastAPI Version
0.75.0
Python Version
3.9.10
Additional Context
Tickets that seem relevant to this issue:
- Ability to change contextvars in sync dependencies #953 (but that's only about deps, not middleware)
- How can I implement a Correlation ID middleware? #397
- Can't get the correct contextvar set in the request handler in middleware's dispatch method Kludex/starlette#1081
I have read the following pages:
In the meantime I might be using https://github.com/snok/asgi-correlation-id