How to troubleshoot cause of "Waiting for background tasks to complete. (CTRL+C to force quit)" ?

[ZipBrandon]

I'm facing intermittent issues on my dev server running --reload. I'm receiving "Waiting for background tasks to complete. (CTRL+C to force quit)". I enabled --log-level trace --timeout-graceful-shutdown 10 and can see that after the 10 seconds that a ASGI task will complete: | TRACE: 172.27.0.6:55020 - ASGI [62] Completed. I go back in the logging to see what ASGI [62] was

devapp  | TRACE:    172.27.0.6:55020 - ASGI [62] Receive {'type': 'http.request', 'body': '<8305 bytes>', 'more_body': False}
devapp  | INFO 2023-08-20 17:05:41,934 asgi_middleware 1396 281473889983792 GraphQL request:  MyGqlOperation

I made a middleware for Django to parse the operation name out for the log. I believe this correlated with the graphql request that would be immediately before that so it would be what is running for ASGI [62]. My problem is that when I do get into this condition it is not always the same GraphQL operation that is running. Is there a better way to diagnose this than the path I am going?

[jakobjw]

Having the same problem... Thanks for the --timeout-graceful-shutdown 10 anyway! xD

[r-owen]

I am having what I think is the same problem. My fastapi/uvicorn application uses a websocket. The main code is written as a class that is an async context manager and that is constructed in a lifespan event handler. Here are the basics:

@asynccontextmanager
async def lifespan(app: FastAPI) -> AsyncGenerator[None, FastAPI]:
    global loom_server
    async with LoomServer() as loom_server:
        yield

app = FastAPI(lifespan=lifespan)

@app.websocket("/ws")
async def websocket_endpoint(websocket: WebSocket) -> None:
    global loom_server
    await loom_server.run_client(websocket=websocket)

This works fine (including for unit tests) except that once a client has connected, the web server can no longer gracefully shut down or restart.

The hang is happening before my application's __aexit__ method is called (as I verified by starting that method with a print statement). This seems likely to be a bug.

The full code is available here: https://github.com/r-owen/seguin_loom_server.git. It is not yet fully functional, so I have not added it to PyPI, but if you download it and do an editable install with "pip install -e ." that should pull over the few required dependencies and the unit tests should work. To see the problem, run the server and connect a web client, then try to stop the server with ctrl-C (or tweak a source file to trigger reload).

[piotrekkr]

@r-owen On prod I don't use --reload because there is no file changes, but I had similar issue on local dev. Setting --timeout-graceful-shutdown 0 insta-kill those background tasks and reloads all code correctly. Take a look at logs, especially Cancel 1 running task(s), timeout graceful shutdown exceeded:

{"message": "Shutting down", "asctime": "2025-04-14 14:39:39,567", "levelname": "INFO", "name": "uvicorn.error", "module": "server", "filename": "server.py", "funcName": "shutdown", "lineno": 263, "timestamp": "2025-04-14T14:39:39.567004+00:00", "level": "INFO"}
{"message": "Waiting for background tasks to complete. (CTRL+C to force quit)", "asctime": "2025-04-14 14:39:39,667", "levelname": "INFO", "name": "uvicorn.error", "module": "server", "filename": "server.py", "funcName": "_wait_tasks_to_complete", "lineno": 305, "timestamp": "2025-04-14T14:39:39.667615+00:00", "level": "INFO"}
{"message": "Cancel 1 running task(s), timeout graceful shutdown exceeded", "asctime": "2025-04-14 14:39:40,667", "levelname": "ERROR", "name": "uvicorn.error", "module": "server", "filename": "server.py", "funcName": "shutdown", "lineno": 283, "timestamp": "2025-04-14T14:39:40.667429+00:00", "level": "ERROR"}
{"message": "Waiting for application shutdown.", "asctime": "2025-04-14 14:39:40,667", "levelname": "INFO", "name": "uvicorn.error", "module": "on", "filename": "on.py", "funcName": "shutdown", "lineno": 67, "timestamp": "2025-04-14T14:39:40.667710+00:00", "level": "INFO"}
{"message": "Application shutdown complete.", "asctime": "2025-04-14 14:39:40,668", "levelname": "INFO", "name": "uvicorn.error", "module": "on", "filename": "on.py", "funcName": "shutdown", "lineno": 76, "timestamp": "2025-04-14T14:39:40.668193+00:00", "level": "INFO"}
{"message": "Finished server process [784]", "asctime": "2025-04-14 14:39:40,668", "levelname": "INFO", "name": "uvicorn.error", "module": "server", "filename": "server.py", "funcName": "_serve", "lineno": 93, "color_message": "Finished server process [\u001b[36m%d\u001b[0m]", "timestamp": "2025-04-14T14:39:40.668367+00:00", "level": "INFO"}
{"message": "Started server process [815]", "asctime": "2025-04-14 14:39:42,308", "levelname": "INFO", "name": "uvicorn.error", "module": "server", "filename": "server.py", "funcName": "_serve", "lineno": 83, "color_message": "Started server process [\u001b[36m%d\u001b[0m]", "timestamp": "2025-04-14T14:39:42.308438+00:00", "level": "INFO"}
{"message": "Waiting for application startup.", "asctime": "2025-04-14 14:39:42,308", "levelname": "INFO", "name": "uvicorn.error", "module": "on", "filename": "on.py", "funcName": "startup", "lineno": 48, "timestamp": "2025-04-14T14:39:42.308603+00:00", "level": "INFO"}
{"message": "Application startup complete.", "asctime": "2025-04-14 14:39:42,308", "levelname": "INFO", "name": "uvicorn.error", "module": "on", "filename": "on.py", "funcName": "startup", "lineno": 62, "timestamp": "2025-04-14T14:39:42.308795+00:00", "level": "INFO"}

Before using this parameter uvicorn was waiting for those background tasks for a minute or more blocking all incoming requests. Now it is killing it instantly and reloads code.

@ZipBrandon Thanks for mentioning this parameter!