Lots of CancelledError when requests are interupted

[samuelcolvin]

Long story short

aiohttp barfs out hundreds of concurrent.futures._base.CancelledError when requests are interrupted.

Expected behaviour

Not sure, I guess we can't just ignore CancelledError in requests but it would be good if there was some way to stop loads of errors being printed.

This is annoying in the terminal but could cause a major backlog if sentry etc. were connected and processing exceptions.

You can catch and ignore this error with middleware:

async def cancelled_error_middleware(app, handler):
    async def _handler(request):
        try:
            return await handler(request)
        except CancelledError:
            raise HTTPBadRequest()
    return _handler

But I'm not sure how safe this is?

Actual behaviour

[2017-01-30 12:22:19 +0000] [30723] [ERROR] Error handling request
Traceback (most recent call last):
  File "/home/vagrant/FrameworkBenchmarks/installs/py3/lib/python3.5/site-packages/aiohttp/web_server.py", line 61, in handle_request
    resp = yield from self._handler(request)
  File "/home/vagrant/FrameworkBenchmarks/installs/py3/lib/python3.5/site-packages/aiohttp/web.py", line 249, in _handle
    resp = yield from handler(request)
  File "/home/vagrant/FrameworkBenchmarks/frameworks/Python/aiohttp/app/views.py", line 142, in updates
    .values(randomnumber=randint(1, 10000))
  File "/home/vagrant/FrameworkBenchmarks/installs/py3/lib/python3.5/site-packages/aiopg/utils.py", line 72, in __await__
    resp = yield from self._coro
  File "/home/vagrant/FrameworkBenchmarks/installs/py3/lib/python3.5/site-packages/aiopg/sa/connection.py", line 110, in _execute
    yield from cursor.execute(str(compiled), post_processed_params[0])
  File "/home/vagrant/FrameworkBenchmarks/installs/py3/lib/python3.5/site-packages/aiopg/cursor.py", line 113, in execute
    yield from self._conn._poll(waiter, timeout)
  File "/home/vagrant/FrameworkBenchmarks/installs/py3/lib/python3.5/site-packages/aiopg/connection.py", line 240, in _poll
    raise exc
  File "/home/vagrant/FrameworkBenchmarks/installs/py3/lib/python3.5/site-packages/aiopg/connection.py", line 237, in _poll
    yield from asyncio.wait_for(self._waiter, timeout, loop=self._loop)
  File "/home/vagrant/FrameworkBenchmarks/installs/py3/lib/python3.5/asyncio/tasks.py", line 379, in wait_for
    yield from waiter
  File "/home/vagrant/FrameworkBenchmarks/installs/py3/lib/python3.5/asyncio/futures.py", line 358, in __iter__
    yield self  # This tells Task to wait for completion.
  File "uvloop/future.pyx", line 434, in uvloop.loop.BaseTask._fast_wakeup (uvloop/loop.c:114015)
  File "/home/vagrant/FrameworkBenchmarks/installs/py3/lib/python3.5/asyncio/futures.py", line 266, in result
    raise CancelledError
concurrent.futures._base.CancelledError

Coming through thousands of times as I run wrk load tests. I suspect the same would occur with ajax interrupted requests or even browsers stopping a request if a new one is requested.

Steps to reproduce

wrk -t12 -c100 -d10s http://localhost:8000/whatever

While running your aiohttp application with gunicorn.

Your environment

Ubuntu.

[fafhrd91]

here is code that handle cancelation https://github.com/KeepSafe/aiohttp/blob/master/aiohttp/server.py#L292

could you confirm same behavior with default event loop?

[samuelcolvin]

I can confirm it's happening with the standard event loop:

[2017-01-30 17:39:13 +0000] [28963] [INFO] Starting gunicorn 19.6.0
[2017-01-30 17:39:13 +0000] [28963] [INFO] Listening at: http://127.0.0.1:8000 (28963)
[2017-01-30 17:39:13 +0000] [28963] [INFO] Using worker: aiohttp.worker.GunicornWebWorker
[2017-01-30 17:39:13 +0000] [28972] [INFO] Booting worker with pid: 28972
[2017-01-30 17:39:21 +0000] [28972] [ERROR] Error handling request
Traceback (most recent call last):
  File "/path/to/code/env/lib/python3.6/site-packages/aiohttp/web_server.py", line 61, in handle_request
    resp = yield from self._handler(request)
  File "/path/to/code/env/lib/python3.6/site-packages/aiohttp/web.py", line 249, in _handle
    resp = yield from handler(request)
  File "/path/to/code/app/middleware.py", line 77, in _handler
    return await handler(request)
  File "/path/to/code/app/middleware.py", line 90, in _handler
    conn = await request['conn_manager'].get_connection()
  File "/path/to/code/app/middleware.py", line 69, in get_connection
    self._conn = await self._engine._acquire()
  File "/path/to/code/env/lib/python3.6/site-packages/aiopg/sa/engine.py", line 161, in _acquire
    raw = yield from self._pool.acquire()
  File "/path/to/code/env/lib/python3.6/site-packages/aiopg/utils.py", line 67, in __iter__
    resp = yield from self._coro
  File "/path/to/code/env/lib/python3.6/site-packages/aiopg/pool.py", line 168, in _acquire
    with (yield from self._cond):
  File "/usr/lib/python3.6/asyncio/locks.py", line 67, in __iter__
    yield from self.acquire()
  File "/usr/lib/python3.6/asyncio/locks.py", line 176, in acquire
    yield from fut
concurrent.futures._base.CancelledError

I got this on a different project as running the benchmark tests is a bit involved but it's the same problem.

Seems to always relate to aiopg, but I don't know if that's significant.

[fafhrd91]

i see the problem

[samuelcolvin]

Looking at it, the second case is slightly different as the connection is being acquired in middleware. Is that significant?

[fafhrd91]

it is related to web_server.Server implementation, it was introduced in 1.2.0 version. it just swallows exceptions

[fafhrd91]

should be fixed in master

[samuelcolvin]

This is indeed fixed in master. Thanks a lot, it would be great if there was a new release so I could use it on FrameworkBenchmarks currently every time a test is run aiohttp is printing about 10k lines of errors.

[fafhrd91]

I will make new release early next week. I need to add timeouts to client close

[AraHaan]

@fafhrd91 Will it not conflict with #1586? because that would also be something to merge before the release as well as it fixes an issue with the warnings about initializing client session outside of an coroutine with an event loop. Because the original one was bugged because some things was flipped around.

[niteeshm]

Even with aiohttp 1.3.2 I am facing the same issue , if a request gets cancelled I get tonnes of errors in my error log saying TypeError: CancelledError() is not JSON serializable

[samuelcolvin]

This sounds like a different issue. aiohttp is correctly dealing with CancelledError, this is an error with your application code.

You'll need to do something like (in your view handler)

try:
    obj = await get_the_data()
except CancelledError:
    raise  # aiohttp will cope with error
else:
    return json_response(obj)

[niteeshm]

@samuelcolvin Even after adding the above handler it still gives me a bunch of CancelledError

Added this to my handler :

        except CancelledError:
            raise
        except Exception as e:
            return self._send_response({'status': {'type': 'ERROR', 'message': e}, 'data': {}, 'code': 500})

ERROR 2017-03-07 11:36:18,325 Module:web_server --- Error handling request
Traceback (most recent call last):
  File "/usr/local/lib/python3.5/site-packages/aiohttp/web_server.py", line 61, in handle_request
    resp = yield from self._handler(request)
  File "/usr/local/lib/python3.5/site-packages/aiohttp/web.py", line 249, in _handle
    resp = yield from handler(request)
  File "/usr/local/lib/python3.5/site-packages/aiohttp/web_urldispatcher.py", line 113, in handler_wrapper
    result = yield from result
  File "/Users/6332/git/sizing_service/service/app/handler/size_handler.py", line 84, in get_recommended_size
    return_percentage = await self.redis_get('return_percentage:' + brand)
  File "/Users/6332/git/myservice/service/app/handler.py", line 20, in redis_get
    return await self.redis_conn.get(key)
  File "/usr/local/Cellar/python3/3.5.1/Frameworks/Python.framework/Versions/3.5/lib/python3.5/asyncio/futures.py", line 358, in __iter__
    yield self  # This tells Task to wait for completion.
  File "/usr/local/Cellar/python3/3.5.1/Frameworks/Python.framework/Versions/3.5/lib/python3.5/asyncio/tasks.py", line 290, in _wakeup
    future.result()
  File "/usr/local/Cellar/python3/3.5.1/Frameworks/Python.framework/Versions/3.5/lib/python3.5/asyncio/futures.py", line 266, in result
    raise CancelledError
concurrent.futures._base.CancelledError

[niteeshm]

Yeah can confirm this has still not been fixed.

[samuelcolvin]

I'm pretty sure the issue I originally submitted the issue about has been fixed.

But that doesn't mean you can't still have issues in your application code with CancelledError.

However, I could be wrong. Please provide a simple example I can run which demonstrates the issue, eg. via a gist.

[fafhrd91]

@niteeshm what version do you use? Did you try master?

[niteeshm]

@fafhrd91 @samuelcolvin I tried this on 1.3.3. I am using wrk to send requests to my server and it gives this CancelledError for a bunch of the requests when wrk benchmark completes.

[samuelcolvin]

As i said before you can still get cancellederror from upstream connections, eg. Database. This is not aiohttp at fault.

Please provide an example yo demonstrate the problem.

[fafhrd91]

@niteeshm please provide an example, will reopen then

[lock]

This thread has been automatically locked since there has not been
any recent activity after it was closed. Please open a new issue for
related bugs.

If you feel like there's important points made in this discussion,
please include those exceprts into that new issue.