Updating context vars within FastAPI deps or response handlers

[lukehsiao]

FastAPI seems to have this issue: fastapi/fastapi#8632

In short, by following the example in this asgi-correlation-id repo, I can easily get the request-id in my requests, but if I try and add additional context in my FastAPI deps or endpoint handlers themselves, those are not displayed.

Is there a snok-recommended way to handle this?

[sondrelg]

This is new to me, so not sure. Are you saying that you'd be able to run this code normally:

foo = ContextVar("foo")

async def bar():
    foo.set("test")

def baz():
    print(foo.get())

asyncio.run(bar())
baz()

but if you put the set into a FastAPI endpoint it stops working?

[lukehsiao]

Apologies for not giving a full reproducer. Here's is an example of the issue. The code is run in a fresh venv with

pip install fastapi[all] asgi-correlation-id

The code:

import logging
import sys
import time
from typing import Annotated

import structlog
from asgi_correlation_id import CorrelationIdMiddleware, correlation_id
from fastapi import Depends, FastAPI, Request, Response
from uvicorn.protocols.utils import get_path_with_query_string

logging.basicConfig(
    format="%(message)s",
    stream=sys.stdout,
    level=logging.INFO,
)

logger = structlog.get_logger()
app = FastAPI()


@app.middleware("http")
async def logging_middleware(  # type: ignore[no-untyped-def]
    request: Request,
    call_next,
) -> Response:
    """Add logging middleware."""
    structlog.contextvars.clear_contextvars()
    # These context vars will be added to all log entries emitted during the request
    request_id = correlation_id.get()
    structlog.contextvars.bind_contextvars(request_id=request_id)

    start_time = time.perf_counter_ns()
    # If the call_next raises an error, we still want to return our own 500 response,
    # so we can add headers to it (process time, request ID...)
    response = Response(status_code=500)
    try:
        response = await call_next(request)
    except Exception:
        structlog.get_logger("api.error").exception()
        raise
    finally:
        process_time = time.perf_counter_ns() - start_time
        status_code = response.status_code
        url = get_path_with_query_string(request.scope)
        http_method = request.method
        http_version = request.scope["http_version"]
        user_agent = request.headers.get("user-agent", "")
        # Recreate the Uvicorn access log format, but add all parameters as structured
        # information
        logger.info(
            f""""{http_method} {url} HTTP/{http_version}" {status_code}""",  # noqa: E501
            http={
                "url": str(request.url),
                "status_code": status_code,
                "method": http_method,
                "request_id": request_id,
                "version": http_version,
                "user_agent": user_agent,
            },
            duration=process_time,
        )
        response.headers["X-Process-Time"] = str(process_time / 10**9)
        return response


app.add_middleware(CorrelationIdMiddleware, validator=None)


def common_parameters() -> dict:
    # This works if this dependency is async
    structlog.contextvars.bind_contextvars(test2="bound in deps")
    return {"key": "value"}


@app.get("/hello")
async def hello_world(commons: Annotated[dict, Depends(common_parameters)]) -> dict:
    commons["msg"] = "Hello, world!"

    logger.info("Log before setting var")
    structlog.contextvars.bind_contextvars(test="bound in endpoint")
    logger.info("Log after var")

    return commons

Running this with

uvicorn example:app --reload

And hitting it:

curl http://localhost:8000/hello

Results in the following logs

2023-05-12 12:09:05 [info     ] Log before setting var         request_id=0810d793c8254b2594360d0575497d04
2023-05-12 12:09:05 [info     ] Log after var                  request_id=0810d793c8254b2594360d0575497d04 test=bound in endpoint
2023-05-12 12:09:05 [info     ] "GET /hello HTTP/1.1" 200      duration=19465221 http={'url': 'http://localhost:8000/hello', 'status_code': 200, 'method': 'GET', 'request_id': '0810d793c8254b2594360d0575497d04', 'version': '1.1', 'user_agent': 'curl/7.68.0'} request_id=0810d793c8254b2594360d0575497d04
INFO:     127.0.0.1:47144 - "GET /hello HTTP/1.1" 200 OK

If I change common_parameters to async def, then the log looks like

2023-05-12 12:10:31 [info     ] Log before setting var         request_id=ef204b7f4ad34daf9549ddfe1cfffed5 test2=bound in deps
2023-05-12 12:10:31 [info     ] Log after var                  request_id=ef204b7f4ad34daf9549ddfe1cfffed5 test=bound in endpoint test2=bound in deps
2023-05-12 12:10:31 [info     ] "GET /hello HTTP/1.1" 200      duration=731584 http={'url': 'http://localhost:8000/hello', 'status_code': 200, 'method': 'GET', 'request_id': 'ef204b7f4ad34daf9549ddfe1cfffed5', 'version': '1.1', 'user_agent': 'curl/7.68.0'} request_id=ef204b7f4ad34daf9549ddfe1cfffed5
INFO:     127.0.0.1:57416 - "GET /hello HTTP/1.1" 200 OK

In our codebase, we use these dependencies heavily, but typically without async definitions. So, it would be awesome to be able to bind extra context vars in those deps and have things work.

I realize based on the linked FastAPI issue that this is perhaps expected behavior, but mostly curious if you have recommendations.