How can I raise a Tornado timeout exception within a ContextDecorator?

Question

I am looking to:

• Make a custom timer wrapper, for logging/other timing purposes
• Include preemptive exiting if the wrapped operation(s) exceed a predefined length of time

This is what I have so far:

from contextlib import ContextDecorator
import datetime

from tornado import gen, ioloop
from tornado.concurrent import Future


class timing_logger(ContextDecorator):
    def __init__(self, allowed_ms):
        self.allowed_ms = allowed_ms
        self.f = Future()
        # this exception is not bubbled up by Tornado but fires
        gen.with_timeout(datetime.timedelta(seconds=1+allowed_ms/1000), self.f)

    def __enter__(self):
        self.start_time = datetime.datetime.now()
        return self

    def __exit__(self, exc_type, exc_val, traceback):
        self.f.set_result(True)
        elapsed_time_ms = (datetime.datetime.now() - self.start_time).total_seconds() * 1000

        if exc_type == gen.TimeoutError:
            raise TimeoutError('ruh oh, this is reeeally bad')

        if elapsed_time_ms > self.allowed_ms:
            raise TimeoutError('took {actual} ms, but was only allowed {allowed}.'.format(
                 actual=elapsed_time_ms, allowed=self.allowed_ms))

        else:
            print('worked. nothing to see here...')
        return False


@gen.coroutine
def main():

    with timing_logger(1000):
        # real application may be a variety of coroutines
        # and regular function calls, some of which may hang
        # for a long time
        for i in range(25):
            yield gen.sleep(0.1)


if __name__ == "__main__":
    ioloop.IOLoop.current().run_sync(
        lambda: main())

The problem I have here is that because I am not yielding the gen.with_timeout future, in the stack I see:

$python test.py 
ERROR:tornado.application:Future <tornado.concurrent.Future object at 0x10c7cb668> exception was never retrieved: tornado.gen.TimeoutError: Timeout
Traceback (most recent call last):
  File "test.py", line 48, in <module>
    lambda: main())
<snip>
    yielded = self.gen.send(value)
  File "test.py", line 43, in main
    yield gen.sleep(0.1)
  File "test.py", line 28, in __exit__
    actual=elapsed_time_ms, allowed=self.allowed_ms))
TimeoutError: took 2606.2940000000003 ms, but was only allowed 1000.

The tornado timeout is not being "bubbled" (for lack of better word).

I would like to have the __exit__ capture the exception, so that I can handle it in and log appropriately, while re-raising as a different exception type.

I am not sure if I need to:

• Not use a ContextDecorator at all
• Do something different with how/where I have the tornado call
• ????

I know that in this example, I can wrap all the calling code into a coroutine and add a timeout to the main function around the timing logger wrap, like this:

@gen.coroutine
def main():


    @gen.coroutine
    def f():
        with timing_logger(1000):
            # real application may be a variety of coroutines
            # and regular function calls, some of which may hang
            # for a long time
            for i in range(25):
                yield gen.sleep(0.1)

    future = f()
    yield gen.with_timeout(datetime.timedelta(seconds=1), future)

But I am looking to include the above into my ContextDecorator because having to copy that around everything I want to use timing_logger with becomes tedious as well as error prone.

How can I achieve desired functionality to allow my ContextDecorator to include timeouts as part of how it functions?

Using Python 3.6.1 and the latest Tornado (4.5.1).

Answer 1

Rather than using a tornado timeout, you can use a signal to interrupt and trigger this exception (though alarm only allows integer, second inputs):

    def timeout_handler(signum, frame):
        raise gen.TimeoutError()

    self.signal = signal.signal(signal.SIGALRM, timeout_handler)
    signal.alarm(1 + self.allowed_ms // 1000)

This will raise the exception appropriately, resulting in a full ContextDecorator that looks like:

from contextlib import ContextDecorator
import datetime

from tornado import gen, ioloop
from tornado.concurrent import Future


class timing_logger(ContextDecorator):
    def __init__(self, allowed_ms):
        self.allowed_ms = allowed_ms
        self.f = Future()
        # this exception is not bubbled up by Tornado but fires
        gen.with_timeout(datetime.timedelta(seconds=1+allowed_ms/1000), self.f)

    def __enter__(self):
        self.start_time = datetime.datetime.now()
        def timeout_handler(signum, frame):
            raise gen.TimeoutError()  # could be any type of exception

        self.signal = signal.signal(signal.SIGALRM, timeout_handler)
        signal.alarm(1 + self.allowed_ms // 1000)

        return self

    def __exit__(self, exc_type, exc_val, traceback):
        signal.alarm(0)
        self.f.set_result(True)
        elapsed_time_ms = (datetime.datetime.now() - self.start_time).total_seconds() * 1000

        if exc_type == gen.TimeoutError:
            raise TimeoutError('ruh oh, this is reeeally bad')

        if elapsed_time_ms > self.allowed_ms:
            raise TimeoutError('took {actual} ms, but was only allowed {allowed}.'.format(
                 actual=elapsed_time_ms, allowed=self.allowed_ms))

        else:
            print('worked. nothing to see here...')
        return False

Note that you need to reset the alarm in the __exit__ or it will fire later in your code.