Tornado with_timeout correct usage

I've got a web-server that runs some shell command. The command usually takes a couple of seconds, but in some occasions it takes more and in that case the client (it is not a web-browser or curl) disconnects.

I have no possibility to fix the client, so I thought about fixing the server. It is based on tornado framework. I rewrote it using tornado.gen.with_timeout function, but for some reason it doesn't work as I expect. I set timeout to 5 seconds, so when querying the server I expect to get either "finished in X seconds" (where X < 5) or "already took more than 5 seconds... still running". And in both cases I expect to get response in less than 5 seconds.

Here is the code:

import os
import json
import datetime
import random

from tornado.ioloop import IOLoop
from tornado.web import RequestHandler, Application
from tornado.gen import coroutine, with_timeout, TimeoutError, Return

@coroutine
def run_slow_command(command):
    res = os.system(command)
    raise Return(res)


class MainHandler(RequestHandler):
    @coroutine
    def get(self):
        TIMEOUT = 5
        duration = random.randint(1, 15)

        try:
            yield with_timeout(datetime.timedelta(seconds=TIMEOUT), run_slow_command('sleep %d' % duration))
            response = {'status' : 'finished in %d seconds' % duration}
        except TimeoutError:
            response = {'status' :  'already took more than %d seconds... still running' % TIMEOUT}

        self.set_header("Content-type", "application/json")
        self.write(json.dumps(response) + '\n')


def make_app():
    return Application([
        (r"/", MainHandler),
    ])

if __name__ == "__main__":
    app = make_app()
    app.listen(8080)
    IOLoop.current().start()

And here is the output from curl:

for i in `seq 1 5`; do curl http://127.0.0.1:8080/; done
{"status": "finished in 15 seconds"}
{"status": "finished in 12 seconds"}
{"status": "finished in 3 seconds"}
{"status": "finished in 11 seconds"}
{"status": "finished in 13 seconds"}

What am I doing wrong?

Solution

Although run_slow_command is decorated with coroutine it's still blocking, so Tornado is blocked and cannot run any code, including a timer, until the os.system call completes. You should defer the call to a thread:

from concurrent.futures import ThreadPoolExecutor

thread_pool = ThreadPoolExecutor(4)

@coroutine
def run_slow_command(command):
    res = yield thread_pool.submit(os.system, command)
    raise Return(res)

Or, since you just want the Future that's returned by submit, don't use coroutine at all:

def run_slow_command(command):
    return thread_pool.submit(os.system, command)

Instead of using os.system, however, you should use Tornado's own Subprocess support. Putting it all together, this example waits 5 seconds for a subprocess, then times out:

from datetime import timedelta
from functools import partial

from tornado import gen
from tornado.ioloop import IOLoop
from tornado.process import Subprocess

@gen.coroutine
def run_slow_command(command):
    yield gen.with_timeout(
        timedelta(seconds=5),
        Subprocess(args=command.split()).wait_for_exit())

IOLoop.current().run_sync(partial(run_slow_command, 'sleep 10'))