uvloop: after CancelledError web response still tries to write EOF to closed socket

[balloob]

Long story short

If a CancelledError is raised while a web response handler is waiting for it's data, aiohttp fails when trying to write EOF to the closed socket.

This issue only happens when using UVLoop. If I use UnixSelectorEventLoop (default on OS X) I do not experience this issue. That's why I am not 100% sure if this issue is related to aiohttp or UVLoop. I will work on getting an isolated test case together tomorrow.

Expected behaviour

Premature client cancelling should be handled correctly.

Actual behaviour

17-04-05 23:54:51 ERROR (MainThread) [aiohttp.server] Unhandled exception
Traceback (most recent call last):
  File "/Users/paulus/dev/python/home-assistant/homeassistant/components/camera/__init__.py", line 269, in handle
    image = yield from camera.async_camera_image()
  File "/Users/paulus/dev/python/home-assistant/homeassistant/components/camera/mjpeg.py", line 92, in async_camera_image
    None, self.camera_image)
  File "uvloop/future.pyx", line 230, in __iter__ (uvloop/loop.c:110600)
  File "uvloop/future.pyx", line 432, in uvloop.loop.BaseTask._fast_wakeup (uvloop/loop.c:113980)
  File "uvloop/future.pyx", line 96, in uvloop.loop.BaseFuture._result_impl (uvloop/loop.c:108829)
concurrent.futures._base.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Users/paulus/dev/python/home-assistant/config/deps/aiohttp/web_protocol.py", line 430, in start
    yield from resp.write_eof()
  File "/Users/paulus/dev/python/home-assistant/config/deps/aiohttp/web_response.py", line 576, in write_eof
    yield from super().write_eof()
  File "/Users/paulus/dev/python/home-assistant/config/deps/aiohttp/web_response.py", line 413, in write_eof
    yield from self._payload_writer.write_eof(data)
  File "/Users/paulus/dev/python/home-assistant/config/deps/aiohttp/http_writer.py", line 281, in write_eof
    yield from self.drain(True)
  File "/Users/paulus/dev/python/home-assistant/config/deps/aiohttp/http_writer.py", line 291, in drain
    self._transport.write(b''.join(self._buffer))
  File "uvloop/handles/stream.pyx", line 632, in uvloop.loop.UVStream.write (uvloop/loop.c:74612)
  File "uvloop/handles/handle.pyx", line 150, in uvloop.loop.UVHandle._ensure_alive (uvloop/loop.c:54917)
RuntimeError: unable to perform operation on <TCPTransport closed=True reading=False 0x7fa24400b858>; the handler is closed

Right after this exception, aiohttp writes to the debug log (in both loops): Ignored premature client disconnection.

Steps to reproduce

Going to sleep first, will get to this tomorrow 👍

Your environment

OS X, aiohttp 2.0.5

[fafhrd91]

@1st1 could you check? should aiohttp handle this case differently?

[1st1]

I'll take a look at the code later, but maybe you can check transport.is_closed() before writing EOF?

[fafhrd91]

I'd rather not, but I can just add try/except for RuntimeError

[balloob]

The weird thing is that it's handled correctly in the normal event loop.

Suppressing RuntimeError seems dangerous, there are many things that can raise that and we might not be notified of different bugs.

[1st1]

I'd rather not, but I can just add try/except for RuntimeError

Why not? It's not safe to suppress RuntimeErrors

[1st1]

The weird thing is that it's handled correctly in the normal event loop.

I think I'll allow write_eof call on closed transports in uvloop, but we need to make aiohttp compatible with older versions.

[1st1]

I'm looking at the traceback and I'm not sure why http_writer.py tries to write something to a closed transport. @fafhrd91 can transports, somehow, get closed earlier with uvloop than with asyncio in aiohttp?

[balloob]

The weird thing is that besides the exception we also get the log Ignored premature client disconnection. printed. Judging from web_protocol.py, when that is printed we break out of the while loop and thus should never even reach line 430.

[balloob]

Never mind, there is another identical log message in the finally block.

[fafhrd91]

this is classic async problem.

1. loops wakes tcptransport because of socket close, transport closes socket.
   then during same loop iteration, loop wakes up handler task because it has something to write.
2. transport get closed, web_protocol got connection_lost and cancel handler tasks,
   but handler task will get cancel exception during next loop iteration
3. handler get called and started to write to closed transport.

that is the reason why RuntimeError is not good idea in async transport.

similar to python/cpython#528

[fafhrd91]

added special case for RuntimeError logging

[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.