Uvloop: TimeoutError not thrown

[Snawoot]

• uvloop version: 0.12.2
• Python version: 3.5.3
• Platform: Debian 9
• Can you reproduce the bug with PYTHONASYNCIODEBUG in env?: not sure, it happens naturally

I have following exceptions in log when client connection gets timed out:

Мар 26 20:07:32 mx ssh-tarpit[23515]: Exception in callback loop._on_idle
Мар 26 20:07:32 mx ssh-tarpit[23515]: handle: <Handle loop._on_idle>
Мар 26 20:07:32 mx ssh-tarpit[23515]: Traceback (most recent call last):
Мар 26 20:07:32 mx ssh-tarpit[23515]:   File "uvloop/cbhandles.pyx", line 71, in uvloop.loop.Handle._run
Мар 26 20:07:32 mx ssh-tarpit[23515]:   File "uvloop/loop.pyx", line 410, in uvloop.loop.Loop._on_idle
Мар 26 20:07:32 mx ssh-tarpit[23515]:   File "uvloop/loop.pyx", line 588, in uvloop.loop.Loop._exec_queued_writes
Мар 26 20:07:32 mx ssh-tarpit[23515]:   File "uvloop/handles/stream.pyx", line 470, in uvloop.loop.UVStream._exec_write
Мар 26 20:07:32 mx ssh-tarpit[23515]:   File "uvloop/handles/stream.pyx", line 397, in uvloop.loop.UVStream._try_write
Мар 26 20:07:32 mx ssh-tarpit[23515]:   File "uvloop/handles/basetransport.pyx", line 46, in uvloop.loop.UVBaseTransport._fatal_error
Мар 26 20:07:32 mx ssh-tarpit[23515]: TimeoutError: [Errno 110] Connection timed out

Only place where my TCP stream handler writes something looks like this:

        try:
            while True:
                await asyncio.sleep(self._interval)
                writer.write(b'%.8x\r\n' % random.randrange(2**32))
                await writer.drain()
        except (ConnectionResetError, RuntimeError, TimeoutError):
            pass
        except OSError as e:
            if e.errno == 107:
                pass
            else:
                raise
        finally:
            self._logger.info("Client %s disconnected", str(peer_addr))

It seems to me TimeoutError not propagated to caller. With default Python eventloop TimeoutError is properly raised and catchable by my code.

[1st1]

I'm not sure I follow... I see a TimeoutError in the attached log, and I also see that you're ignoring TimeoutErrors in your code. Where's the bug?

[Snawoot]

Bug is: this exception doesn't not gets raised for user code and printed into stderr instead. It doesn't even reach my (empty) exception handler.

[1st1]

I see the problem now -- a pending write crashed, but the transport didn't propagate the exception on the subsequent operation. Would you be able to write a unittest that demonstrates this (would be a huge help)?

[Snawoot]

I'm not sure how can I reproduce TimeoutError because it happens on real connections when peer disappears, but I'll try.

[Snawoot]

Alright, I've built test bed like this:

1. On my server I've enabled discard TCP service in xinetd. It's a TCP service on port 9 which receives and discards all input data.
2. I've simulated connection choke on server with iptables rule: iptables -A OUTPUT -m tcp -p tcp --sport 9 -m connbytes --connbytes-dir original --connbytes 5000 --connbytes-mode bytes -j DROP
3. I've prepared following test script:

#!/usr/bin/env python3

import asyncio
import uvloop
import unittest
import socket

buf = bytearray(4096)

async def amain(loop):
    sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
    sock.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 0)  # this is intentional restriction

    # Make timeout happen faster
    sock.setsockopt(socket.IPPROTO_TCP, socket.TCP_USER_TIMEOUT, 1000)
    sock.connect(('vm-0.com', 9))
    reader, writer = await asyncio.open_connection(sock=sock,
                                                   loop=loop)
    writer.transport.pause_reading()
    try:
        while True:
            writer.write(buf)
            await writer.drain()
    except TimeoutError:
        return True
    except:
        return False

class TimeoutErrorTest(unittest.TestCase):
    def test_uvloop(self):
        loop = uvloop.new_event_loop()
        self.assertTrue(loop.run_until_complete(amain(loop)))

    def test_no_uvloop(self):
        loop = asyncio.new_event_loop()
        self.assertTrue(loop.run_until_complete(amain(loop)))

if __name__ == '__main__':
    unittest.main()

I've got following output:

user@dt1:~/63e0060ae9caa29784b681488be8cd02$ ./timeout_error_test.py 
Fatal write error on socket transport
protocol: <asyncio.streams.StreamReaderProtocol object at 0x7fd3d1efcb38>
transport: <_SelectorSocketTransport fd=6 read=idle write=<idle, bufsize=0>>
Traceback (most recent call last):
  File "/opt/python3/lib/python3.7/asyncio/selector_events.py", line 880, in _write_ready
    n = self._sock.send(self._buffer)
TimeoutError: [Errno 110] Connection timed out
.Fatal error on transport TCPTransport (error status in uv_stream_t.write callback)
protocol: <asyncio.streams.StreamReaderProtocol object at 0x7fd3d1efc358>
transport: <TCPTransport closed=False reading=False 0x555935b38ff8>
TimeoutError: [Errno 110] Connection timed out
.
----------------------------------------------------------------------
Ran 2 tests in 3.036s

OK

What I found:

1. It seems exception is raised both with asyncio and uvloop event loop. That's OK and probably resolves actual issue (assuming correctness of my test).
2. Both print into console "fatal" error. That is bad and I doomed to see "fatal error" garbage for trivial situations which I already handled by the way. But it's unrelated to uvloop specifically.

[deed02392]

@Snawoot great work on this, why is it not possible to suppress this garbage though?

[1st1]

Both print into console "fatal" error. That is bad and I doomed to see "fatal error" garbage for trivial situations which I already handled by the way. But it's unrelated to uvloop specifically.

Yeah, let's keep this issue open. I'll see if I can silence this in both asyncio and uvloop.

[deed02392]

I managed to catch this exception when using uvloop with aiohttp:

        except aiohttp.ClientConnectorError as exc:
            logging.info(f"Connection failed: {exc}")

[1st1]

@fantix will need to look at this in detail. If this is a garbage exception we need to silence it in both uvloop/asyncio.

[fantix]

Reproducibility:

| Test | uvloop | Python 3.6 | Python 3.7 | Python 3.8 |
|---|---|---|---|---|
| test_no_uvloop | | ✅ | ❌ | ❌ |
| test_uvloop | 0.12.2 | ✅ | ✅ | unsupported |
| test_uvloop | 0.14.0 | ❌ | ❌ | ❌ |

So I think this is already fixed in newer asyncio / uvloop. Please feel free to reopen if there're more questions or issues.