ContextVars pollution when uvicorn installed without [standard] extensions

[vladyslav-burylov]

Hi team, we have discovered a weird ContextVars behaviour when uvicorn being installed without [standard] extensions.

Can you please take a look - should this be considered as a bug or maybe you can help to explain why it happens?

Summary

• Since uvicorn creates async task for each specific request, it is expected that any context vars set while processing would be isolated within a request scope
• However, above works well with 'uvicorn[standard]' edition only

Workarounds

• Use uvicorn[standard] instead of plain uvicorn (seems to be a good option)
• Use ASGI scope to store request-bound data (not always possible: for example opentelemetry cloud tracing middleware stores current trace span inside context var and this logic cannot be changed)

Steps to reproduce

Hardware/OS/tools

• MacBook Pro M1
• macOS Ventura 13.3.1
• Python 3.10.9 installed via pyenv
• uvicorn 0.22.0

Prepare environment

mkdir test && cd test
pyenv install 3.10.9 # unless already installed
pyenv local 3.10.9
python --version # expected to print 3.10.9
python -m venv test
source ./test/bin/activate
pip install requests
pip install 'uvicorn==0.22.0'

Prepare test scripts - create following files:

client.py

import time
import uuid
import requests

print("")
print("Starting...")


def main():
    # Everything is good when payload is small
    huge_payload = ""
    for x in range(10000):
        huge_payload += f"{str(uuid.uuid4())}\n"

    # Send request each 1 second reusing single connection (without connection reuse it works well)
    with requests.Session() as session:
        while True:
            try:
                response = session.post('http://127.0.0.1:8002/test', huge_payload)
                print(response.text) # server will be responding with either 'OK' or 'FAIL'

                # In case if server reports 'FAIL' - we reproduced the issue and are OK to exit
                if response.text == "FAIL":
                    break

            except KeyboardInterrupt:
                break

            except BaseException as ex:
                print(str(ex))

            time.sleep(0.1)

main()

server.py

import uuid
import uvicorn
from contextvars import ContextVar

# This var expected to store some request-bound value. Here 'request_id' as example.
request_id: ContextVar[str] = ContextVar("request_id", default="")


# Minimalistic ASGI app which don't use any 3pt libraries
class MyApp:
    async def __call__(self, scope, receive, send) -> None:
        # https://asgi.readthedocs.io/en/latest/specs/lifespan.html
        if scope["type"] == "lifespan":
            while True:
                message = await receive()
                if message['type'] == 'lifespan.startup':
                    await send({'type': 'lifespan.startup.complete'})
                elif message['type'] == 'lifespan.shutdown':
                    await send({'type': 'lifespan.shutdown.complete'})
                    return

        print("")

        # request_id expected to be empty at this point: request has just started
        val = request_id.get()

        # Validate it and record unexpected behaviour if any
        failed = False
        if val:
            failed = True
            print("UNEXPECTED request_id value: ", val)

        # Generate new GUID and store it inside request_id for this request
        guid = str(uuid.uuid4())
        token = request_id.set(guid)

        # Primitive request processing: reply with OK/FAIL body
        # FAIL means that bug has been reproduced (request_id has been polluted by some of previous request)
        try:
            print("(1) ", guid) # Debug logging
            await send({"type": "http.response.start", "status": 200, "headers": []})
            print("(2) ", guid) # Debug logging
            await send({"type": "http.response.body", "body": b"FAIL" if failed else b"OK"})
            print("(3) ", guid) # Debug logging

        # Request completed. 
        # Reset request_id to an empty value
        finally:
            request_id.reset(token)
            print("(4) ", guid) # Debug logging


# Simplistic server without any magic
server = uvicorn.Server(config=uvicorn.Config(
    MyApp(),
    host="127.0.0.1",
    port=8002,
    workers=1,
    access_log=False,
    proxy_headers=False,
    server_header=False
))

server.run()

Executing test

1. Start server

# cd test
source ./test/bin/activate
python server.py

2. Start client

# cd test
source ./test/bin/activate
python client.py

Expected behaviour

• No errors reported, both server and client running forever

Actual behaviour

• request_id context var value at the beginning of requests gets polluted with previous value eventually
• server.py log

INFO:     Started server process [32392]
INFO:     Waiting for application startup.
INFO:     Application startup complete.
INFO:     Uvicorn running on http://127.0.0.1:8002 (Press CTRL+C to quit)

(1)  57f92756-b50e-4627-824e-da5a93865316
(2)  57f92756-b50e-4627-824e-da5a93865316
(3)  57f92756-b50e-4627-824e-da5a93865316
(4)  57f92756-b50e-4627-824e-da5a93865316

UNEXPECTED request_id value:  57f92756-b50e-4627-824e-da5a93865316
(1)  dbd3ce8a-65ec-4796-b829-6f8da4287c3e
(2)  dbd3ce8a-65ec-4796-b829-6f8da4287c3e
(3)  dbd3ce8a-65ec-4796-b829-6f8da4287c3e
(4)  dbd3ce8a-65ec-4796-b829-6f8da4287c3e

• client.py log

Starting...
OK
FAIL

Notes

• It seems to be occurring periodically (unstable behaviour) - constants within test script adjusted to give high replication probability
• Test code uses requests library to make sample requests, however other client libraries give the same result (originally I have replicated it using much more sophisticated httpx.AsyncClient)
• Works well with uvicorn[standard] - maybe it's happening because standard edition utilises uvloop?

[Kludex]

Can you try only with unicorn and uvloop?

Can you try other python versions?

I don't know why this is happening, I'll check tomorrow.

[vladyslav-burylov]

Yeah, will try tomorrow a couple of combinations. Thanks for looking into this.

As for python - I have already tried 3.10.12 (latest 3.10) - same behaviour.
Not worth to try 3.11, though - it seems they made some changes within asyncio module.

I would like at least to confirm I am not doing something silly which might lead to other tricky unstable issues like this - if above expected to work in theory, I'm totally fine with standard uvicorn edition workaround. Example is oversimplified obviously - originally it was found during cloud traces analysis which were mixing a couple of requests within a single trace (as I mentioned opentelemetry libraary we use for tracing is build on top of middleware with context var like this).

[vladyslav-burylov]

FYI - I haven’t forgot my promise to try it in various envs, however since we’ve been able to resolve it with standard uvicorn edition, it’s not a high priority for us anymore.

Once I’ll have a couple of spare hours, I’ll try to prepare dockerised test and attach it here to simplify replication and testing under various conditions.

please bear with me

[Kludex]

Thanks

[tsx]

Hey! I've stumbled upon this issue as well. We're also using uvicorn with builtin asyncio (not uvloop) on python 3.10, and this have caused issues with opentelemetry tracing.
I was able to reproduce it with the example posted above. It does not happen if I install/use uvloop. Unfortunately changing to uvloop is not an option for us for legacy compatibility reasons, so this is the next best thing I've come up with:

def fix_contextvars_leak(app: ASGI3Application) -> ASGI3Application:
    async def wrapped_app(
        scope: Scope, receive: ASGIReceiveCallable, send: ASGISendCallable
    ) -> None:
        coro = app(scope, receive, send)
        return await Context().run(asyncio.create_task, coro)  # type: ignore

    return wrapped_app

Unfortunately contextvars API doesn't provide an async equivalent to Context().run(awaitable) so I had to resort to creating a new task.

I believe that it might be a good idea to start with a fresh context when uvicorn is creating tasks in

uvicorn/uvicorn/protocols/http/h11_impl.py

Line 255 in e2a3979

task = self.loop.create_task(self.cycle.run_asgi(app))

I'm not quite sure how the leakage happens but I suspect that sharing a single connection (and thus a single parent task handling the connection) is involved somehow and contextvar state from the child per-request task is propagated to the parent task when interacting (send/receive).

Is there any way I could assist in resolving this?

[Kludex]

Created #2167.