ContextVar modified in async deps are not available in middleware (with structlog)

[charlax]

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:8001

The 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 encode/starlette#1081

I have read the following pages:

• https://fastapi.tiangolo.com/async/

In the meantime I might be using https://github.com/snok/asgi-correlation-id

[ramilmsh]

same here, cannot seem to come up with a fix that would allow me to use structlog with fastapi. Because of concurrency, cannot use threadlocal, but contextvars don't seem to work either

[ramilmsh]

FYI, for anyone searching for an answer, I was eventually able to solve the issue with starlette-context

[timofurrer]

I have a similar case and for me it's not even related to Depends, but also happens if you simply use bind_contextvars() in the route handler.

[jarviliam]

Experiencing the same thing here on 0.78.0. Just to add it seems like the context returned from contextvars.copy_context in structlog does not contain the updated/added vars. The global variable _CONTEXT_VARS in structlog does contain the added variables so it seems to not be a structlog issue.