We're messing up STARTTLS somehow

[warsaw]

Previously in eof_received() I added a conditional around the return super().eof_received() call to avoid it if self.transport was None. I've since removed that, which has no effect on the test suite, but does cause traceback spew to the console whenever the SMTP client calls .starttls() and the connection is subsequently close. For example:

$ tox -e py35-nocov -- -P test_forget_ehlo -E
py35-nocov develop-inst-noop: /home/barry/projects/aiosmtpd
py35-nocov installed: -e git+git@github.com:aio-libs/aiosmtpd.git@5da59e96368bdb042f23d5cd8c2cadbcf8180fe4#egg=aiosmtpd,appdirs==1.4.3,atpublic==0.5,flufl.testing==0.7,nose2==0.6.5,packaging==16.8,pkg-resources==0.0.0,six==1.10.0
py35-nocov runtests: PYTHONHASHSEED='3663210934'
py35-nocov runtests: commands[0] | python -m nose2 -v -P test_forget_ehlo -E
test_forget_ehlo (aiosmtpd.tests.test_starttls.TestTLSForgetsSessionData) ... DEBUG:asyncio:Using selector: EpollSelector
INFO:mail.log:Peer: ('::1', 35050, 0, 0)
INFO:mail.log:('::1', 35050, 0, 0) handling connection
DEBUG:mail.log:b'220 presto Python SMTP 1.0a5+\r\n'
DEBUG:asyncio:poll took 13.645 ms: 1 events
DEBUG:mail.log:_handle_client readline: b'ehlo [172.16.114.137]\r\n'
INFO:mail.log:('::1', 35050, 0, 0) Data: b'ehlo [172.16.114.137]'
DEBUG:mail.log:b'250-presto\r\n'
DEBUG:mail.log:b'250-SIZE 33554432\r\n'
DEBUG:mail.log:b'250-STARTTLS\r\n'
DEBUG:mail.log:b'250 HELP\r\n'
DEBUG:asyncio:poll took 45.399 ms: 1 events
DEBUG:mail.log:_handle_client readline: b'STARTTLS\r\n'
INFO:mail.log:('::1', 35050, 0, 0) Data: b'STARTTLS'
INFO:mail.log:('::1', 35050, 0, 0) STARTTLS
DEBUG:mail.log:b'220 Ready to start TLS\r\n'
DEBUG:asyncio:<asyncio.sslproto.SSLProtocol object at 0x7f2e033d7198> starts SSL handshake
DEBUG:asyncio:poll took 0.565 ms: 1 events
DEBUG:asyncio:<asyncio.sslproto.SSLProtocol object at 0x7f2e033d7198>: SSL handshake took 5.9 ms
DEBUG:asyncio:poll took 0.368 ms: 1 events
DEBUG:mail.log:_handle_client readline: b'mail FROM:<sender@example.com>\r\n'
INFO:mail.log:('::1', 35050, 0, 0) Data: b'mail FROM:<sender@example.com>'
DEBUG:mail.log:b'503 Error: send HELO first\r\n'
DEBUG:asyncio:poll took 0.023 ms: 1 events
DEBUG:mail.log:_handle_client readline: b'QUIT\r\n'
INFO:mail.log:('::1', 35050, 0, 0) Data: b'QUIT'
DEBUG:mail.log:b'221 Bye\r\n'
INFO:mail.log:Connection lost during _handle_client()
INFO:mail.log:('::1', 35050, 0, 0) connection lost
DEBUG:asyncio:<_SelectorSocketTransport fd=10 read=polling write=<idle, bufsize=0>> received EOF
DEBUG:asyncio:<asyncio.sslproto.SSLProtocol object at 0x7f2e033d7198> received EOF
INFO:mail.log:('::1', 35050, 0, 0) EOF received
ERROR:asyncio:Exception in callback None()
handle: <Handle cancelled _SelectorSocketTransport._read_ready() created at /usr/lib/python3.5/asyncio/selector_events.py:262>
source_traceback: Object created at (most recent call last):
  File "/usr/lib/python3.5/threading.py", line 882, in _bootstrap
    self._bootstrap_inner()
  File "/usr/lib/python3.5/threading.py", line 914, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.5/threading.py", line 862, in run
    self._target(*self._args, **self._kwargs)
  File "/home/barry/projects/aiosmtpd/aiosmtpd/controller.py", line 55, in _run
    self.loop.run_forever()
  File "/usr/lib/python3.5/asyncio/base_events.py", line 421, in run_forever
    self._run_once()
  File "/usr/lib/python3.5/asyncio/base_events.py", line 1416, in _run_once
    handle._run()
  File "/usr/lib/python3.5/asyncio/events.py", line 126, in _run
    self._callback(*self._args)
  File "/usr/lib/python3.5/asyncio/selector_events.py", line 262, in _add_reader
    handle = events.Handle(callback, args, self)
Traceback (most recent call last):
  File "/usr/lib/python3.5/asyncio/events.py", line 126, in _run
    self._callback(*self._args)
  File "/usr/lib/python3.5/asyncio/selector_events.py", line 734, in _read_ready
    keep_open = self._protocol.eof_received()
  File "/usr/lib/python3.5/asyncio/sslproto.py", line 535, in eof_received
    keep_open = self._app_protocol.eof_received()
  File "/home/barry/projects/aiosmtpd/aiosmtpd/smtp.py", line 169, in eof_received
    return super().eof_received()
  File "/usr/lib/python3.5/asyncio/streams.py", line 256, in eof_received
    self._stream_reader.feed_eof()
AttributeError: 'NoneType' object has no attribute 'feed_eof'
INFO:mail.log:('::1', 35050, 0, 0) connection lost
DEBUG:asyncio:Close <_UnixSelectorEventLoop running=False closed=False debug=True>
ok

What seems to be happening is that, if we enter smtp_STARTTLS(), some state is messed up, and we eventually get eof_received() after connection_lost(). The latter is where self._stream_reader gets set to None.

Maybe we're doing something wrong when we flip on the SSL transport. Maybe there's a bug in asyncio, but if so, there have been no other reports on bugs.python.org that I can find. I don't believe it has anything to do with our overrides of eof_received() and connect_lost() since if I comment those two methods out, I still see the traceback. I think it's more likely we're messing with the asyncio state machine in problematic ways.

[warsaw]

FTR, the fact that we don't have an API for STARTTLS is known upstream.