4

I'm debugging a FastAPI application, and I have a problem similar to what's been mentioned in this post: a call to asyncio.wait_for that should time out doesn't:

try:
    await wait_for(completion_event.wait(), 1.0)
except TimeoutError:
    logging.info("timeout")
    return SubmissionResult(post_id=post_id, language_check_pending=True)

This snippet is a part of a FastAPI's POST request handler. Here, completion_event is an asyncio.Event object. I can put a breakpoint on the line with wait_for, watch it get stuck for much more than 1s, and then move right past the except block. There's no doubt that wait_for doesn't do what it's expected to do.

I have no idea why it behaves like that. At this point, I'm starting to suspect the FastAPI's internals, since it uses uvloop as a "faster drop-in replacement for asyncio". But I don't know how to test this assumption, much less to fix this problem if it's indeed the case.

Any suggestions?

Semisonic
  • 1,152
  • 8
  • 21
  • 1
    If `completion_event.wait()` performs some IO/CPU blocking operation and never `await`s for a coroutine to give up control for other tasks in the event loop to run (including `asyncio.wait_for()`), it will block the event loop (the entire server essentially) until is completed. See [this answer](https://stackoverflow.com/a/73743908/17865804). – Chris Oct 20 '22 at 11:15
  • @Chris why would `asyncio.Event.wait()` do that? It's a standard library class and you can see how it's implemented – Semisonic Oct 20 '22 at 18:48
  • Chris is making a good point. The thread that's running the event loop could be getting blocked somehow. For example in my program, if you replace the line `await asyncio.sleep(0.7)` with `time.sleep(0.7)`, that will block the loop until more than 1 second has passed. So you might expect the TimeoutError to be raised. But it's not, because the event loop is blocked and is unable to process the timeout. The blocking call doesn't need to be in completion_event.wait but in some other task. Any call that blocks the loop will cause this problem. – Paul Cornelius Oct 22 '22 at 22:41

2 Answers2

2

A possible explanation is that completion_event.wait() is raising an exception before the time delay has elapsed. A cancellation of the enclosing Task would count as an Exception. The following program illustrates this:

import asyncio

async def fail():
    await asyncio.sleep(0.5)
    # raise ValueError("Half a second")
    await asyncio.sleep(0.7)
    
async def cancel_point_three(task):
    await asyncio.sleep(0.3)
    task.cancel()
    
async def main():
    task = asyncio.create_task(fail())
    # asyncio.create_task(cancel_point_three(task))
        
    try:
        await asyncio.wait_for(task, 1.0)
    except asyncio.TimeoutError:
        print("Timed out")
    else:
        print("Did not time out")
        
asyncio.run(main())

Run this program as is and it will print "Timed out" as expected. Remove the comment in front of raise ValueError and the code drops all the way through to the end, without printing "Timed out". The Exception occurs before the timeout.

A similar thing happens if you instead remove the comment in front of asyncio.create_task(cancel_point_three(task)). There is no timeout, even though the method fail() did not raise any Exception.

Also note that there are two TimeoutError classes in the standard library. One of them is asyncio.TimeoutError, which is the one raised by asyncio.wait_for. There is also a TimeoutError in the basic exception heirarchy - it's a subclass of OSError and is not the one you want here.

Paul Cornelius
  • 9,245
  • 1
  • 15
  • 24
  • Thanks for your suggestions Paul! However, I don't think those are relevant in my case. And here's why: 1) I enabled debugging of the 3rd party package code and placed a breakpoint inside `Event.wait()`. It's never called until I actually call `Event.set()` for this event. So there's no way it could throw. 2) I have `from asyncio import TimeoutError` in my module. Plus, if I hadn't caught the right exception it would've propagated outwards, and the code continued to execute past the `except` block. So there's something more fishy going on here I'm afraid – Semisonic Oct 20 '22 at 18:40
0

I think this can be fixed using asyncio.timeout_at (present in Python 3.11) instead asyncio.wait_for.

I'm using python 3.9, so, as a workaround, I've created a decorator to use in the endpoints you want to raise a response 504: (place it in a file named abort_after.py)

import functools
import signal
import sys

from fastapi.responses import JSONResponse
from starlette import status


class TimeOutException(Exception):
    """It took longer than expected"""


def abort_after(max_execution_time):
    def decorator(func):
        @functools.wraps(func)
        def wrapper(*args, **kwargs):
            def handle_timeout(signum, frame):
                raise TimeOutException(f"Function execution took longer than {max_execution_time}s and was terminated")
            if sys.platform == 'win32':
                print("Won't be stopped in windows!")
            else:
                signal.signal(signal.SIGALRM, handle_timeout)
                signal.alarm(max_execution_time)
            result = func(*args, **kwargs)
            if sys.platform != 'win32':
                signal.alarm(0)
            return result
        return wrapper
    return decorator


def timeout_response() -> JSONResponse:
    return JSONResponse(
        {
            'detail': 'Request processing time excedeed limit',
        },
        status_code=status.HTTP_504_GATEWAY_TIMEOUT,
    )

Then you can use it in your endpoint:

import time
from fastapi import APIRouter
from abort_after import abort_after, TimeOutException, timeout_response

router = APIRouter()


@router.post(f"{URL_prefix}/test",
             tags=['Test'],
             )
async def test():
    try:
        long_func(60)
    except TimeOutException:
        return timeout_response()
    return {'Test': 'ok'}


@abort_after(5)
def long_func(seconds: int) -> None:
    time.sleep(seconds)
Adrian Mole
  • 49,934
  • 160
  • 51
  • 83
Patrullero Matt
  • 1