Hey everyone, I'm currently trying to implement an API endpoint using FastAPI which starts a long running background task using asyncio.create_task(startlongrunningtask()) and then without waiting for that task to finish, return a response to the client. The long running task starts up fine, but times out after e few seconds with the error message [CRITICAL] WORKER TIMEOUT and Booting worker with pid: 25
How can I prevent the worker from getting timed out?
Is it possible to create such long running tasks which continue even after sending a response to the client?
Thanks a lot and best regards
happy to help but you'd need to give more info on what the tasks does, how you're running the app, what worker stops (uvicorn one or gunicorn)
the below snippet shows a long running background task in action, it just sleeps and doesn't use asyncio.create_task like you describe though
Connected to pydev debugger (build 192.6817.19)
email-validator not installed, email fields will be treated as str.
To install, run: pip install email-validator
2019-10-10 13:18:21,122 uvicorn INFO Started server process [29570]
2019-10-10 13:18:21,122 uvicorn INFO Waiting for application startup.
2019-10-10 13:18:21,124 uvicorn INFO Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
2019-10-10 13:18:29,706 uvicorn INFO ('127.0.0.1', 46716) - "POST /backgroundasync HTTP/1.1" 200
2019-10-10 13:18:29,706 __main__ DEBUG sleeping 30s
2019-10-10 13:18:59,707 __main__ DEBUG slept 30s
import asyncio
import logging
from typing import Dict
import uvicorn
from fastapi import FastAPI
from pydantic import BaseModel
from starlette.background import BackgroundTasks
logging.basicConfig(format="%(asctime)s %(name)-12s %(levelname)-8s %(message)s")
logger: logging.Logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)
app = FastAPI()
class Item(BaseModel):
amount: int
async def background_async(amount: int) -> None:
logger.debug(f"sleeping {amount}s")
await asyncio.sleep(amount)
logger.debug(f"slept {amount}s")
@app.post("/backgroundasync")
async def sleepingtheback(
item: Item, background_tasks: BackgroundTasks
) -> Dict[str, str]:
background_tasks.add_task(background_async, item.amount)
return {"message": f"sleeping {item.amount} in the back"}
if __name__ == "__main__":
uvicorn.run(app=app)
gunicorn working fine too
unicorn -w 4 -k uvicorn.workers.UvicornWorker 611_very_long_background:app
[2019-10-10 13:43:00 +0200] [30577] [INFO] Starting gunicorn 19.9.0
[2019-10-10 13:43:00 +0200] [30577] [INFO] Listening at: http://127.0.0.1:8000 (30577)
[2019-10-10 13:43:00 +0200] [30577] [INFO] Using worker: uvicorn.workers.UvicornWorker
[2019-10-10 13:43:00 +0200] [30580] [INFO] Booting worker with pid: 30580
email-validator not installed, email fields will be treated as str.
To install, run: pip install email-validator
[2019-10-10 13:43:00 +0200] [30581] [INFO] Booting worker with pid: 30581
[2019-10-10 13:43:00 +0200] [30580] [INFO] Started server process [30580]
[2019-10-10 13:43:00 +0200] [30580] [INFO] Waiting for application startup.
email-validator not installed, email fields will be treated as str.
To install, run: pip install email-validator
[2019-10-10 13:43:00 +0200] [30582] [INFO] Booting worker with pid: 30582
[2019-10-10 13:43:00 +0200] [30583] [INFO] Booting worker with pid: 30583
email-validator not installed, email fields will be treated as str.
To install, run: pip install email-validator
[2019-10-10 13:43:00 +0200] [30581] [INFO] Started server process [30581]
[2019-10-10 13:43:00 +0200] [30581] [INFO] Waiting for application startup.
email-validator not installed, email fields will be treated as str.
To install, run: pip install email-validator
[2019-10-10 13:43:00 +0200] [30582] [INFO] Started server process [30582]
[2019-10-10 13:43:00 +0200] [30582] [INFO] Waiting for application startup.
[2019-10-10 13:43:00 +0200] [30583] [INFO] Started server process [30583]
[2019-10-10 13:43:00 +0200] [30583] [INFO] Waiting for application startup.
[2019-10-10 13:43:07 +0200] [30583] [INFO] ('127.0.0.1', 58450) - "GET / HTTP/1.1" 404
[2019-10-10 13:43:16 +0200] [30583] [INFO] ('127.0.0.1', 58534) - "POST /backgroundasync HTTP/1.1" 200
2019-10-10 13:43:16,785 611_very_long_background DEBUG sleeping 60s
[2019-10-10 13:43:17 +0200] [30583] [INFO] ('127.0.0.1', 58534) - "POST /backgroundasync HTTP/1.1" 200
2019-10-10 13:43:17,724 611_very_long_background DEBUG sleeping 60s
[2019-10-10 13:43:18 +0200] [30583] [INFO] ('127.0.0.1', 58534) - "POST /backgroundasync HTTP/1.1" 200
2019-10-10 13:43:18,171 611_very_long_background DEBUG sleeping 60s
[2019-10-10 13:43:18 +0200] [30583] [INFO] ('127.0.0.1', 58534) - "POST /backgroundasync HTTP/1.1" 200
2019-10-10 13:43:18,560 611_very_long_background DEBUG sleeping 60s
2019-10-10 13:44:16,786 611_very_long_background DEBUG slept 60s
2019-10-10 13:44:17,725 611_very_long_background DEBUG slept 60s
2019-10-10 13:44:18,172 611_very_long_background DEBUG slept 60s
2019-10-10 13:44:18,561 611_very_long_background DEBUG slept 60s
You'll need to configure this: http://docs.gunicorn.org/en/latest/settings.html#timeout
Otherwise if the background task runs for too long, gunicorn considers the worker running it to be unresponsive - so it's restarted
@ellmh I don't think that's the case, as you can see above I tested with a default gunicorn, timeout is 30,with tasks lasting 60s and that works fine.
gunicorn timeout checks the response arrives before 30s which is immediate in case of a background task. Well that's how I understand it.
gunicorn timeout checks the response arrives before 30s which is immediate in case of a background task. Well that's how I understand it.
@euri10 you're right there, sorry!
I've tried a few things and the only way I could reproduce this was by starting a background task that blocked the worker - try replacing asyncio.sleep with time.sleep. Otherewise uvicorn does what it's supposed to do
If you're OK with blocking a worker, then the you'll need to configure the timeout as above. I imagine there's probably a library/function somewhere that's blocking and not properly async.
@xiaodiannao @ellmh You should never use time.sleep (or any function with blocking io) inside an async def function (background task or otherwise) -- in general, that would block your server.
I know you said "If you're OK with blocking a worker" -- but there is no reason that should be necessary; just use a def function rather than an async def, and it will be run inside a threadpool if called as a background task. This would prevent the timeout issues.
Hey everyone thanks a lot for all your replies. Yes I'm indeed starting a background task which takes a few minutes (starts another application using subprocess) and when it returns the worker should continue with some cleanup tasks. @euri10 I also switched from asyncio.create_task to BackgroundTask by Starlette but the worker still shuts down.
EDIT: @ellmh oh yea the subprocess is blocking the worker for multiple minutes
@dmontagu the BackgroundTask I'm starting currently is a async def, I'm switching it to a def function and try again
@xiaodiannao I'm curious to hear if switching to def fixes it.
This isn't really the intended use case for BackgroundTasks -- I think BackgroundTasks is intended more for shorter, low-compute tasks like triggering an email send or similar.
For tasks involving multi-minute calls to subprocesses, I think long term you would benefit from putting in the effort to set up a celery worker and a task queue, and have the celery worker do the subprocess stuff. (I have a similar setup on one of my own projects, which runs multi-minute compute-intensive jobs.) That will decouple your server from the worker, and may help you avoid/preempt a lot of issues arising from long-running and/or compute-intensive jobs running alongside your server.
If you wanted to do this, the full stack fastapi postgres template has a celery worker; you should be able to adapt it to your use case.
@dmontagu it indeed fixed the problem, great stuff! Yea this is an intermediate solution the next step would be to hand the long running tasks to something like celery workers etc. I'll have to look into that next.
Thank everyone for the help!
Hey everyone thanks a lot for all your replies. Yes I'm indeed starting a background task which takes a few minutes (starts another application using subprocess) and when it returns the worker should continue with some cleanup tasks. @euri10 I also switched from asyncio.create_task to BackgroundTask by Starlette but the worker still shuts down.
EDIT: @ellmh oh yea the subprocess is blocking the worker for multiple minutes
it would be helpful to post a snippet of what you're doing or we talk about hypothetical stuff.
are you sure you're using https://docs.python.org/3/library/asyncio-subprocess.html ?
@euri10 I wasn't even aware an asyncio had built-in subprocess capabilities -- thanks for sharing!
with an async def spawning 4 processes that lasts 2min, I got no issue
gunicorn log
(rapidfastapitest) ➜ rapidfastapitest git:(master) ✗ gunicorn -w 4 -k uvicorn.workers.UvicornWorker 611_very_long_background:app
[2019-10-11 11:59:28 +0200] [457] [INFO] Starting gunicorn 19.9.0
[2019-10-11 11:59:28 +0200] [457] [INFO] Listening at: http://127.0.0.1:8000 (457)
[2019-10-11 11:59:28 +0200] [457] [INFO] Using worker: uvicorn.workers.UvicornWorker
[2019-10-11 11:59:28 +0200] [460] [INFO] Booting worker with pid: 460
email-validator not installed, email fields will be treated as str.
To install, run: pip install email-validator
[2019-10-11 11:59:28 +0200] [461] [INFO] Booting worker with pid: 461
[2019-10-11 11:59:28 +0200] [462] [INFO] Booting worker with pid: 462
email-validator not installed, email fields will be treated as str.
To install, run: pip install email-validator
[2019-10-11 11:59:28 +0200] [460] [INFO] Started server process [460]
[2019-10-11 11:59:28 +0200] [460] [INFO] Waiting for application startup.
[2019-10-11 11:59:28 +0200] [463] [INFO] Booting worker with pid: 463
email-validator not installed, email fields will be treated as str.
To install, run: pip install email-validator
email-validator not installed, email fields will be treated as str.
To install, run: pip install email-validator
[2019-10-11 11:59:28 +0200] [461] [INFO] Started server process [461]
[2019-10-11 11:59:28 +0200] [461] [INFO] Waiting for application startup.
[2019-10-11 11:59:28 +0200] [462] [INFO] Started server process [462]
[2019-10-11 11:59:28 +0200] [462] [INFO] Waiting for application startup.
[2019-10-11 11:59:28 +0200] [463] [INFO] Started server process [463]
[2019-10-11 11:59:28 +0200] [463] [INFO] Waiting for application startup.
[2019-10-11 11:59:32 +0200] [461] [INFO] ('127.0.0.1', 39476) - "GET /backgroundsubprocess HTTP/1.1" 200
2019-10-11 11:59:32,528 611_very_long_background DEBUG subprocesss in
[2019-10-11 11:59:33 +0200] [460] [INFO] ('127.0.0.1', 39488) - "GET /backgroundsubprocess HTTP/1.1" 200
2019-10-11 11:59:33,355 611_very_long_background DEBUG subprocesss in
[2019-10-11 11:59:33 +0200] [463] [INFO] ('127.0.0.1', 39500) - "GET /backgroundsubprocess HTTP/1.1" 200
2019-10-11 11:59:33,939 611_very_long_background DEBUG subprocesss in
[2019-10-11 11:59:34 +0200] [463] [INFO] ('127.0.0.1', 39504) - "GET /backgroundsubprocess HTTP/1.1" 200
2019-10-11 11:59:34,479 611_very_long_background DEBUG subprocesss in
2019-10-11 12:01:32,533 611_very_long_background DEBUG 5924
2019-10-11 12:01:32,534 611_very_long_background DEBUG subprocess out with 5924 bytes
2019-10-11 12:01:33,363 611_very_long_background DEBUG 5413
2019-10-11 12:01:33,364 611_very_long_background DEBUG subprocess out with 5413 bytes
2019-10-11 12:01:33,944 611_very_long_background DEBUG 4826
2019-10-11 12:01:33,944 611_very_long_background DEBUG subprocess out with 4826 bytes
2019-10-11 12:01:34,490 611_very_long_background DEBUG 4824
2019-10-11 12:01:34,490 611_very_long_background DEBUG subprocess out with 4824 bytes
edit: tried 20 minutes tasks, using the server in between
gunicorn log 20min
(rapidfastapitest) ➜ rapidfastapitest git:(master) ✗ gunicorn -w 4 -k uvicorn.workers.UvicornWorker 611_very_long_background:app
[2019-10-11 12:05:57 +0200] [1057] [INFO] Starting gunicorn 19.9.0
[2019-10-11 12:05:57 +0200] [1057] [INFO] Listening at: http://127.0.0.1:8000 (1057)
[2019-10-11 12:05:57 +0200] [1057] [INFO] Using worker: uvicorn.workers.UvicornWorker
[2019-10-11 12:05:57 +0200] [1062] [INFO] Booting worker with pid: 1062
[2019-10-11 12:05:57 +0200] [1063] [INFO] Booting worker with pid: 1063
[2019-10-11 12:05:57 +0200] [1065] [INFO] Booting worker with pid: 1065
[2019-10-11 12:05:57 +0200] [1066] [INFO] Booting worker with pid: 1066
email-validator not installed, email fields will be treated as str.
To install, run: pip install email-validator
email-validator not installed, email fields will be treated as str.
To install, run: pip install email-validator
email-validator not installed, email fields will be treated as str.
To install, run: pip install email-validator
email-validator not installed, email fields will be treated as str.
To install, run: pip install email-validator
[2019-10-11 12:05:57 +0200] [1065] [INFO] Started server process [1065]
[2019-10-11 12:05:57 +0200] [1063] [INFO] Started server process [1063]
[2019-10-11 12:05:57 +0200] [1063] [INFO] Waiting for application startup.
[2019-10-11 12:05:57 +0200] [1062] [INFO] Started server process [1062]
[2019-10-11 12:05:57 +0200] [1062] [INFO] Waiting for application startup.
[2019-10-11 12:05:57 +0200] [1065] [INFO] Waiting for application startup.
[2019-10-11 12:05:57 +0200] [1066] [INFO] Started server process [1066]
[2019-10-11 12:05:57 +0200] [1066] [INFO] Waiting for application startup.
[2019-10-11 12:06:05 +0200] [1065] [INFO] ('127.0.0.1', 42744) - "GET /backgroundsubprocess HTTP/1.1" 200
2019-10-11 12:06:05,309 611_very_long_background DEBUG subprocesss in
[2019-10-11 12:06:05 +0200] [1065] [INFO] ('127.0.0.1', 42748) - "GET /backgroundsubprocess HTTP/1.1" 200
2019-10-11 12:06:05,868 611_very_long_background DEBUG subprocesss in
[2019-10-11 12:06:06 +0200] [1066] [INFO] ('127.0.0.1', 42760) - "GET /backgroundsubprocess HTTP/1.1" 200
2019-10-11 12:06:06,362 611_very_long_background DEBUG subprocesss in
[2019-10-11 12:06:06 +0200] [1063] [INFO] ('127.0.0.1', 42764) - "GET /backgroundsubprocess HTTP/1.1" 200
2019-10-11 12:06:06,848 611_very_long_background DEBUG subprocesss in
[2019-10-11 12:06:07 +0200] [1066] [INFO] ('127.0.0.1', 42776) - "GET /backgroundsubprocess HTTP/1.1" 200
2019-10-11 12:06:07,325 611_very_long_background DEBUG subprocesss in
[2019-10-11 12:06:07 +0200] [1062] [INFO] ('127.0.0.1', 42780) - "GET /backgroundsubprocess HTTP/1.1" 200
2019-10-11 12:06:07,768 611_very_long_background DEBUG subprocesss in
[2019-10-11 12:06:09 +0200] [1066] [INFO] ('127.0.0.1', 42800) - "GET /backgroundsubprocess HTTP/1.1" 200
2019-10-11 12:06:09,036 611_very_long_background DEBUG subprocesss in
[2019-10-11 12:06:09 +0200] [1063] [INFO] ('127.0.0.1', 42804) - "GET /backgroundsubprocess HTTP/1.1" 200
2019-10-11 12:06:09,673 611_very_long_background DEBUG subprocesss in
[2019-10-11 12:06:10 +0200] [1066] [INFO] ('127.0.0.1', 42816) - "GET /backgroundsubprocess HTTP/1.1" 200
2019-10-11 12:06:10,217 611_very_long_background DEBUG subprocesss in
[2019-10-11 12:06:10 +0200] [1063] [INFO] ('127.0.0.1', 42820) - "GET /backgroundsubprocess HTTP/1.1" 200
2019-10-11 12:06:10,732 611_very_long_background DEBUG subprocesss in
[2019-10-11 12:13:48 +0200] [1065] [INFO] ('127.0.0.1', 46630) - "GET /backgroundasync HTTP/1.1" 405
[2019-10-11 12:13:49 +0200] [1066] [INFO] ('127.0.0.1', 46642) - "GET /backgroundasync HTTP/1.1" 405
[2019-10-11 12:14:03 +0200] [1066] [INFO] ('127.0.0.1', 46768) - "POST /backgroundasync HTTP/1.1" 422
[2019-10-11 12:14:34 +0200] [1065] [INFO] ('127.0.0.1', 47014) - "POST /backgroundasync HTTP/1.1" 422
[2019-10-11 12:14:49 +0200] [1065] [INFO] ('127.0.0.1', 47138) - "POST /backgroundasync HTTP/1.1" 200
2019-10-11 12:14:49,565 611_very_long_background DEBUG sleeping 10s
[2019-10-11 12:14:50 +0200] [1066] [INFO] ('127.0.0.1', 47150) - "POST /backgroundasync HTTP/1.1" 200
2019-10-11 12:14:50,868 611_very_long_background DEBUG sleeping 10s
[2019-10-11 12:14:51 +0200] [1066] [INFO] ('127.0.0.1', 47162) - "POST /backgroundasync HTTP/1.1" 200
2019-10-11 12:14:51,475 611_very_long_background DEBUG sleeping 10s
[2019-10-11 12:14:51 +0200] [1066] [INFO] ('127.0.0.1', 47176) - "POST /backgroundasync HTTP/1.1" 200
2019-10-11 12:14:51,958 611_very_long_background DEBUG sleeping 10s
2019-10-11 12:14:59,564 611_very_long_background DEBUG slept 10s
2019-10-11 12:15:00,867 611_very_long_background DEBUG slept 10s
2019-10-11 12:15:01,477 611_very_long_background DEBUG slept 10s
2019-10-11 12:15:01,961 611_very_long_background DEBUG slept 10s
[2019-10-11 12:15:13 +0200] [1066] [INFO] ('127.0.0.1', 47348) - "POST /backgroundasync HTTP/1.1" 200
2019-10-11 12:15:13,754 611_very_long_background DEBUG sleeping 300s
[2019-10-11 12:15:18 +0200] [1065] [INFO] ('127.0.0.1', 47392) - "POST /backgroundasync HTTP/1.1" 200
2019-10-11 12:15:18,629 611_very_long_background DEBUG sleeping 30s
2019-10-11 12:15:48,629 611_very_long_background DEBUG slept 30s
2019-10-11 12:20:13,754 611_very_long_background DEBUG slept 300s
2019-10-11 12:26:05,395 611_very_long_background DEBUG 12274
2019-10-11 12:26:05,395 611_very_long_background DEBUG subprocess out with 12274 bytes
2019-10-11 12:26:05,873 611_very_long_background DEBUG 11758
2019-10-11 12:26:05,873 611_very_long_background DEBUG subprocess out with 11758 bytes
2019-10-11 12:26:06,368 611_very_long_background DEBUG 11134
2019-10-11 12:26:06,368 611_very_long_background DEBUG subprocess out with 11134 bytes
2019-10-11 12:26:06,853 611_very_long_background DEBUG 10547
2019-10-11 12:26:06,853 611_very_long_background DEBUG subprocess out with 10547 bytes
2019-10-11 12:26:07,330 611_very_long_background DEBUG 9997
2019-10-11 12:26:07,331 611_very_long_background DEBUG subprocess out with 9997 bytes
2019-10-11 12:26:07,773 611_very_long_background DEBUG 9373
2019-10-11 12:26:07,773 611_very_long_background DEBUG subprocess out with 9373 bytes
2019-10-11 12:26:09,042 611_very_long_background DEBUG 8786
2019-10-11 12:26:09,042 611_very_long_background DEBUG subprocess out with 8786 bytes
2019-10-11 12:26:09,678 611_very_long_background DEBUG 8199
2019-10-11 12:26:09,678 611_very_long_background DEBUG subprocess out with 8199 bytes
2019-10-11 12:26:10,223 611_very_long_background DEBUG 7612
2019-10-11 12:26:10,223 611_very_long_background DEBUG subprocess out with 7612 bytes
2019-10-11 12:26:10,746 611_very_long_background DEBUG 7025
2019-10-11 12:26:10,746 611_very_long_background DEBUG subprocess out with 7025 bytes
[2019-10-11 12:31:49 +0200] [1065] [INFO] ('127.0.0.1', 55526) - "POST /backgroundasync HTTP/1.1" 200
2019-10-11 12:31:49,001 611_very_long_background DEBUG sleeping 3s
2019-10-11 12:31:52,001 611_very_long_background DEBUG slept 3s
import asyncio
import logging
from typing import Dict
import uvicorn
from fastapi import FastAPI
from pydantic import BaseModel
from starlette.background import BackgroundTasks
# logging.basicConfig(format="%(asctime)s %(name)-12s %(levelname)-8s %(message)s")
logger: logging.Logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)
if not logger.hasHandlers():
sh = logging.StreamHandler()
fmt = logging.Formatter(fmt="%(asctime)s %(name)-12s %(levelname)-8s %(message)s")
sh.setFormatter(fmt)
logger.addHandler(sh)
logger.propagate = False
app = FastAPI()
class Item(BaseModel):
amount: int
async def background_async(amount: int) -> None:
logger.debug(f"sleeping {amount}s")
await asyncio.sleep(amount)
logger.debug(f"slept {amount}s")
async def background_async_subprocess(amount: int) -> None:
logger.debug(f"subprocesss in")
cmd = f"timeout {amount}s tail -f ~/.xsession-errors"
proc = await asyncio.create_subprocess_shell(
cmd, stdout=asyncio.subprocess.PIPE, stderr=asyncio.subprocess.PIPE
)
stdout, stderr = await proc.communicate()
logger.debug(len(stdout))
logger.debug(f"subprocess out with {len(stdout)} bytes")
@app.post("/backgroundasync")
async def sleepingtheback(
item: Item, background_tasks: BackgroundTasks
) -> Dict[str, str]:
background_tasks.add_task(background_async, item.amount)
return {"message": f"sleeping {item.amount} in the back"}
@app.get("/backgroundsubprocess")
async def backgroundsubprocess_list(
background_tasks: BackgroundTasks
) -> Dict[str, str]:
background_tasks.add_task(background_async_subprocess, 120)
return {"message": f"subprocess in the back"}
if __name__ == "__main__":
uvicorn.run("611_very_long_background:app", reload=True)
Thanks for the help here everyone! :clap: :bow:
Thanks for reporting back and closing the issue @xiaodiannao :+1:
Hii, can any one help me with this Stackoverflow question based on background task
Most helpful comment
@xiaodiannao I'm curious to hear if switching to def fixes it.
This isn't really the intended use case for BackgroundTasks -- I think BackgroundTasks is intended more for shorter, low-compute tasks like triggering an email send or similar.
For tasks involving multi-minute calls to subprocesses, I think long term you would benefit from putting in the effort to set up a celery worker and a task queue, and have the celery worker do the subprocess stuff. (I have a similar setup on one of my own projects, which runs multi-minute compute-intensive jobs.) That will decouple your server from the worker, and may help you avoid/preempt a lot of issues arising from long-running and/or compute-intensive jobs running alongside your server.
If you wanted to do this, the full stack fastapi postgres template has a celery worker; you should be able to adapt it to your use case.