SSL server sockets that haven't completed handshake lead to log spew on loop close

[kyuupichan]

This is very similar in root cause to issue #483 - SSL handshakes that have been initiated but not completed. This code in sslproto.py:

if compat.PY34:
    def __del__(self):
        if not self._closed:
            warnings.warn("unclosed transport %r" % self, ResourceWarning)
            self.close()

leads to annoying log spew that is out of the control of the server developer. The cause is wrapped SSL sockets that have not completed their handshake and that therefore the transport has not been provided to the protocol's connection_made() callback. As server developer I therefore have no way to cleanly close down these transports. So when the server admin shuts down the server, which does cleanly close all the transports it is aware of then does a loop.close() and exits, he is left with many messages like this sent to the logs. This is unsightly and frustrating as I am unable to prevent it.

Perhaps the above code in __del__() should not be executed if the loop has been closed?

017-01-20 19:32:16.331209500 Exception ignored in: <bound method _SSLProtocolTransport.del of <asyncio.sslproto._SSLProtocolTransport object at 0x80a8e5e10>>
2017-01-20 19:32:16.331215500 Traceback (most recent call last):
2017-01-20 19:32:16.331218500 File "/usr/local/lib/python3.5/asyncio/sslproto.py", line 328, in del
2017-01-20 19:32:16.331220500 self.close()
2017-01-20 19:32:16.331222500 File "/usr/local/lib/python3.5/asyncio/sslproto.py", line 319, in close
2017-01-20 19:32:16.331224500 self._ssl_protocol._start_shutdown()
2017-01-20 19:32:16.331340500 File "/usr/local/lib/python3.5/asyncio/sslproto.py", line 542, in _start_shutdown
2017-01-20 19:32:16.331343500 self._write_appdata(b'')
2017-01-20 19:32:16.331345500 File "/usr/local/lib/python3.5/asyncio/sslproto.py", line 547, in _write_appdata
2017-01-20 19:32:16.331347500 self._process_write_backlog()
2017-01-20 19:32:16.331349500 File "/usr/local/lib/python3.5/asyncio/sslproto.py", line 649, in _process_write_backlog
2017-01-20 19:32:16.331359500 self._on_handshake_complete(exc)
2017-01-20 19:32:16.331361500 File "/usr/local/lib/python3.5/asyncio/sslproto.py", line 587, in _on_handshake_complete
2017-01-20 19:32:16.331364500 self._wakeup_waiter(exc)
2017-01-20 19:32:16.331366500 File "/usr/local/lib/python3.5/asyncio/sslproto.py", line 445, in _wakeup_waiter
2017-01-20 19:32:16.331368500 self._waiter.set_exception(exc)
2017-01-20 19:32:16.331378500 File "/usr/local/lib/python3.5/asyncio/futures.py", line 349, in set_exception
2017-01-20 19:32:16.331393500 self._schedule_callbacks()
2017-01-20 19:32:16.331395500 File "/usr/local/lib/python3.5/asyncio/futures.py", line 242, in _schedule_callbacks
2017-01-20 19:32:16.331398500 self._loop.call_soon(callback, self)
2017-01-20 19:32:16.331400500 File "/usr/local/lib/python3.5/asyncio/base_events.py", line 497, in call_soon
2017-01-20 19:32:16.331403500 handle = self._call_soon(callback, args)
2017-01-20 19:32:16.331412500 File "/usr/local/lib/python3.5/asyncio/base_events.py", line 506, in _call_soon
2017-01-20 19:32:16.331414500 self._check_closed()
2017-01-20 19:32:16.331416500 File "/usr/local/lib/python3.5/asyncio/base_events.py", line 334, in _check_closed
2017-01-20 19:32:16.331419500 raise RuntimeError('Event loop is closed')
2017-01-20 19:32:16.331421500 RuntimeError: Event loop is closed
20

[1st1]

@fafhrd91 This one also seems to be important. There was an open bug for it somewhere on bpo, I can't find it now.

[fafhrd91]

this is actually another leak I want to work on. here is issue aio-libs/aiohttp#1679

[1st1]

Yep, it seems the bug in aiohttp is caused by this.

Speaking of sslproto.py I don't like its design. I think it's possible to simplify it a great deal, which should also improve performance. If, while working on sslproto, you have any ideas how we can rewrite it, let's discuss.

[fafhrd91]

sure