- Tornado Version 6.1
- Python Versions tested Python 3.9.1 (tags/v3.9.1:1e5d33e9), Python 3.7.9 (tags/v3.7.9:13c94747)
If a request handler is waiting on a task that is cancelled, then the asyncio.CancelledError escapes and the request handler is never "finished". Previous to Python 3.8, this would have been caught in web.RequestHandler._execute. I suspect that it should be caught today as well so that the request handler but I am not completely sure what the correct action to take is.
Currently, the control flow seems to go back to the ioloop where it is discarded which leaves the connection hanging and the request handler never "finishes".
The following very contrived example shows the problem:
#!/usr/bin/env python
import asyncio
import json
import logging
from tornado import ioloop, web
class Handler(web.RequestHandler):
async def prepare(self):
super().prepare()
self.logger = logging.getLogger('Handler')
async def get(self):
self.logger.info('processing request')
self.work = asyncio.create_task(asyncio.sleep(10))
work_result, killed = await asyncio.gather(
self.do_work(), self.killer())
self.set_status(200)
self.write(json.dumps({'work_result': work_result, 'killed': killed}))
async def do_work(self):
self.logger.info('doing work')
try:
await self.work
except asyncio.CancelledError:
self.logger.warning('work cancelled!')
raise
return 10
async def killer(self):
await asyncio.sleep(4)
self.logger.info('cancelling work')
self.work.cancel()
return True
def on_finish(self):
super().on_finish()
self.logger.info('request handler has finished')
if __name__ == '__main__':
logging.basicConfig(level=logging.DEBUG,
format='%(levelname)-15s %(name)s: %(message)s')
iol = ioloop.IOLoop.current()
app = web.Application([(r'/', Handler)])
app.listen(8000)
try:
iol.start()
except KeyboardInterrupt:
iol.stop()When run under Python 3.7, curl'ing "127.0.0.1:8000/" results in the following log output and the client receives a 500 Internal Server Error.
DEBUG asyncio: Using selector: KqueueSelector
INFO asyncio: poll took 2537.233 ms: 1 events
INFO Handler: processing request
INFO Handler: doing work
INFO asyncio: poll 3999.843 ms took 4002.786 ms: timeout
INFO Handler: cancelling work
WARNING Handler: work cancelled!
ERROR tornado.application: Uncaught exception GET / (127.0.0.1)
HTTPServerRequest(protocol='http', host='127.0.0.1:8000', method='GET', uri='/', version='HTTP/1.1', remote_ip='127.0.0.1')
Traceback (most recent call last):
File "/Users/daves/Temporary/coros/env37/lib/python3.7/site-packages/tornado/web.py", line 1704, in _execute
result = await result
File "tornado-testie", line 19, in get
self.do_work(), self.killer())
concurrent.futures._base.CancelledError
ERROR tornado.access: 500 GET / (127.0.0.1) 4011.11ms
INFO Handler: request handler has finished
When run under Python 3.9, the same request results in the following log output and the client never receives a response.
DEBUG asyncio: Using selector: KqueueSelector
INFO Handler: processing request
INFO Handler: doing work
INFO Handler: cancelling work
WARNING Handler: work cancelled!
ERROR asyncio: Exception in callback _HandlerDelegate.execute.<locals>.<lambda>(<Task cancell...do/gen.py:867>) at /Users/daves/Temporary/coros/env39/lib/python3.9/site-packages/tornado/web.py:2326
handle: <Handle _HandlerDelegate.execute.<locals>.<lambda>(<Task cancell...do/gen.py:867>) at /Users/daves/Temporary/coros/env39/lib/python3.9/site-packages/tornado/web.py:2326 created at /Users/daves/opt/lib/python3.9/asyncio/events.py:80>
source_traceback: Object created at (most recent call last):
File "/Users/daves/Temporary/coros/tornado-testie", line 51, in <module>
iol.start()
File "/Users/daves/Temporary/coros/env39/lib/python3.9/site-packages/tornado/platform/asyncio.py", line 199, in start
self.asyncio_loop.run_forever()
File "/Users/daves/opt/lib/python3.9/asyncio/base_events.py", line 596, in run_forever
self._run_once()
File "/Users/daves/opt/lib/python3.9/asyncio/base_events.py", line 1882, in _run_once
handle._run()
File "/Users/daves/opt/lib/python3.9/asyncio/events.py", line 80, in _run
self._context.run(self._callback, *self._args)
Traceback (most recent call last):
File "/Users/daves/opt/lib/python3.9/asyncio/tasks.py", line 651, in sleep
return await future
asyncio.exceptions.CancelledError
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/Users/daves/Temporary/coros/tornado-testie", line 27, in do_work
await self.work
asyncio.exceptions.CancelledError
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/Users/daves/Temporary/coros/env39/lib/python3.9/site-packages/tornado/web.py", line 1704, in _execute
result = await result
File "/Users/daves/Temporary/coros/tornado-testie", line 18, in get
work_result, killed = await asyncio.gather(
asyncio.exceptions.CancelledError
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/Users/daves/opt/lib/python3.9/asyncio/events.py", line 80, in _run
self._context.run(self._callback, *self._args)
File "/Users/daves/Temporary/coros/env39/lib/python3.9/site-packages/tornado/web.py", line 2326, in <lambda>
fut.add_done_callback(lambda f: f.result())
asyncio.exceptions.CancelledError
When I add asyncio.CancelledError to the except clause on tornado/web.py:1707 , I get the same outward behavior in both Python versions though the stack traces are different.
If a request handler is waiting on a task that is cancelled, then the
asyncio.CancelledErrorescapes and the request handler is never "finished". Previous to Python 3.8, this would have been caught in web.RequestHandler._execute. I suspect that it should be caught today as well so that the request handler but I am not completely sure what the correct action to take is.Currently, the control flow seems to go back to the ioloop where it is discarded which leaves the connection hanging and the request handler never "finishes".
The following very contrived example shows the problem:
When run under Python 3.7, curl'ing "127.0.0.1:8000/" results in the following log output and the client receives a 500 Internal Server Error.
When run under Python 3.9, the same request results in the following log output and the client never receives a response.
When I add
asyncio.CancelledErrorto theexceptclause on tornado/web.py:1707 , I get the same outward behavior in both Python versions though the stack traces are different.