🐛 Awkward errors after fastapi_events setup

[ediskandarov]

Traces gathered by sentry.io:

ValueError: <Token var=<ContextVar name='fastapi_context' at 0x7f256cfd1bd0> at 0x7f255dd9e800> was created in a different Context
  File "fastapi_events/middleware.py", line 29, in __call__
    self._teardown_event_store()
  File "fastapi_events/middleware.py", line 40, in _teardown_event_store
    event_store.reset(self._token)

RuntimeError: <Token used var=<ContextVar name='fastapi_context' at 0x7f256cfd1bd0> at 0x7f255c3a6dc0> has already been used once
  File "fastapi_events/middleware.py", line 29, in __call__
    self._teardown_event_store()
  File "fastapi_events/middleware.py", line 40, in _teardown_event_store
    event_store.reset(self._token)

Trace I'm seeing in logs

Oct 19 01:16:53 PM  Traceback (most recent call last):
  File "/app/.venv/lib/python3.8/site-packages/uvicorn/protocols/http/httptools_impl.py", line 375, in run_asgi
    result = await app(self.scope, self.receive, self.send)
  File "/app/.venv/lib/python3.8/site-packages/uvicorn/middleware/proxy_headers.py", line 75, in __call__
    return await self.app(scope, receive, send)
  File "/app/.venv/lib/python3.8/site-packages/fastapi/applications.py", line 208, in __call__
    await super().__call__(scope, receive, send)
  File "/app/.venv/lib/python3.8/site-packages/starlette/applications.py", line 112, in __call__
    await self.middleware_stack(scope, receive, send)
  File "/app/.venv/lib/python3.8/site-packages/starlette/middleware/errors.py", line 181, in __call__
    raise exc
  File "/app/.venv/lib/python3.8/site-packages/starlette/middleware/errors.py", line 159, in __call__
    await self.app(scope, receive, _send)
  File "/app/.venv/lib/python3.8/site-packages/starlette/middleware/cors.py", line 84, in __call__
    await self.app(scope, receive, send)
  File "/app/.venv/lib/python3.8/site-packages/sentry_sdk/integrations/asgi.py", line 106, in _run_asgi3
    return await self._run_app(scope, lambda: self.app(scope, receive, send))
  File "/app/.venv/lib/python3.8/site-packages/sentry_sdk/integrations/asgi.py", line 152, in _run_app
    raise exc from None
  File "/app/.venv/lib/python3.8/site-packages/sentry_sdk/integrations/asgi.py", line 149, in _run_app
    return await callback()
  File "/app/.venv/lib/python3.8/site-packages/fastapi_events/middleware.py", line 29, in __call__
    self._teardown_event_store()
  File "/app/.venv/lib/python3.8/site-packages/fastapi_events/middleware.py", line 40, in _teardown_event_store
    event_store.reset(self._token)
RuntimeError: <Token used var=<ContextVar name='fastapi_context' at 0x7f256cfd1bd0> at 0x7f255d943340> has already been used once

[ediskandarov]

It is easy to reproduce with this minimal app

import asyncio
import random

from fastapi import FastAPI
from fastapi_events.dispatcher import dispatch
from fastapi_events.handlers.local import local_handler
from fastapi_events.middleware import EventHandlerASGIMiddleware

app = FastAPI()
app.add_middleware(EventHandlerASGIMiddleware, handlers=[local_handler])


@app.get("/healthz")
async def healthz():
    dispatch("xyz", payload=None)
    await asyncio.sleep(random.randint(1, 5))

Running

poetry run uvicorn --loop asyncio --http h11 example.minimal_fastapi_app:app
...

INFO:     127.0.0.1:63106 - "GET /healthz HTTP/1.1" 200 OK
ERROR:    Exception in ASGI application
Traceback (most recent call last):
  File "/Users/e.iskandarov/example/.venv/lib/python3.8/site-packages/uvicorn/protocols/http/h11_impl.py", line 373, in run_asgi
    result = await app(self.scope, self.receive, self.send)
  File "/Users/e.iskandarov/example/.venv/lib/python3.8/site-packages/uvicorn/middleware/proxy_headers.py", line 75, in __call__
    return await self.app(scope, receive, send)
  File "/Users/e.iskandarov/example/.venv/lib/python3.8/site-packages/fastapi/applications.py", line 208, in __call__
    await super().__call__(scope, receive, send)
  File "/Users/e.iskandarov/example/.venv/lib/python3.8/site-packages/starlette/applications.py", line 112, in __call__
    await self.middleware_stack(scope, receive, send)
  File "/Users/e.iskandarov/example/.venv/lib/python3.8/site-packages/starlette/middleware/errors.py", line 181, in __call__
    raise exc
  File "/Users/e.iskandarov/example/.venv/lib/python3.8/site-packages/starlette/middleware/errors.py", line 159, in __call__
    await self.app(scope, receive, _send)
  File "/Users/e.iskandarov/example/.venv/lib/python3.8/site-packages/fastapi_events/middleware.py", line 29, in __call__
    self._teardown_event_store()
  File "/Users/e.iskandarov/example/.venv/lib/python3.8/site-packages/fastapi_events/middleware.py", line 40, in _teardown_event_store
    event_store.reset(self._token)
ValueError: <Token var=<ContextVar name='fastapi_context' at 0x106b196d0> at 0x106b89200> was created in a different Context

and executing wrk to sent requests asynchronously

wrk -c2 -d30s http://127.0.0.1:8000/healthz

Libraries

MacOS 10.14.6

Python 3.8.6
fastapi-events==0.1.1; python_version >= "3.7"
fastapi==0.70.0; python_full_version >= "3.6.1"
uvicorn==0.15.0
uvloop==0.16.0; sys_platform != "win32" and sys_platform != "cygwin" and platform_python_implementation != "PyPy" and python_version >= "3.7"
anyio==3.3.2; python_version >= "3.6" and python_full_version >= "3.6.2"
h11==0.12.0; python_version >= "3.6"

[ediskandarov]

the issue persists with EchoHandler too

[melvinkcx]

Hi, @emcpow2, thanks for reporting the issue.
I am able to reproduce it, and thanks for making a fix so quickly! I'll be merging it and releasing a new version too