While debugging bpo-32458 (functional test on START TLS), I found a race condition in SSLProtocol of asyncio/sslproto.py.

Sometimes, _sslpipe.feed_ssldata() is called before _sslpipe.shutdown().

* SSLProtocol.connection_made() -> SSLProtocol._start_handshake(): self._loop.call_soon(self._process_write_backlog)
* SSLProtoco.data_received(): direct call to self._sslpipe.feed_ssldata(data)
* Later, self._process_write_backlog() calls self._sslpipe.do_handshake()

The first write is delayed by call_soon(), whereas the first read is a direct call to the SSL pipe.

Workaround:

diff --git a/Lib/asyncio/sslproto.py b/Lib/asyncio/sslproto.py
index 2bfa45dd15..4a5dbb38a1 100644
--- a/Lib/asyncio/sslproto.py
+++ b/Lib/asyncio/sslproto.py
@@ -592,7 +592,7 @@ class SSLProtocol(protocols.Protocol):
         # (b'', 1) is a special value in _process_write_backlog() to do
         # the SSL handshake
         self._write_backlog.append((b'', 1))
-        self._loop.call_soon(self._process_write_backlog)
+        self._process_write_backlog()
         self._handshake_timeout_handle = \
             self._loop.call_later(self._ssl_handshake_timeout,
                                   self._check_handshake_timeout)

loop.start_tls() method is new in Python 3.7. If possible, I would prefer to not see it with a builtin race condition, since such race condition is really hard to debug :-( So I raise the priority to release blocker. Sorry again Ned!

Yury Selivanov told me that usually it's safer to add call_soon(), than to remove call_soon(). But adding many call_soon() can make asyncio SSL slower.

SSLProtocol doesn't seem to like call_soon(), it's only used at:

* connection_lost(): call_soon(self._app_protocol.connection_lost, exc)
* connection_made() ~~> call_soon(self._process_write_backlog)
* _on_handshake_complete(): call_soon(self._process_write_backlog)

That's all. All other operations are done immediately.

_on_handshake_complete() contains a long comment:

        # In case transport.write() was already called. Don't call
        # immediately _process_write_backlog(), but schedule it:
        # _on_handshake_complete() can be called indirectly from
        # _process_write_backlog(), and _process_write_backlog() is not
        # reentrant.
        self._loop.call_soon(self._process_write_backlog)

The fix is correct and the bug is now obvious: data_received() occur pretty much any time after connection_made() call; if call_soon() is used in connection_made(), data_received() may find the protocol in an incorrect state.

Kudos Victor for debugging this.

And I agree, this should make it to 3.7.0

New changeset be00a5583a2cb696335c527b921d1868266a42c6 by Victor Stinner in branch 'master':
bpo-33674: asyncio: Fix SSLProtocol race (GH-7175)
https://github.com/python/cpython/commit/be00a5583a2cb696335c527b921d1868266a42c6

New changeset 0dd8fd03584b61cd769be88f5a2fb59b0d8f6d18 by Ned Deily (Miss Islington (bot)) in branch '3.7':
bpo-33674: asyncio: Fix SSLProtocol race (GH-7175) (#7187)
https://github.com/python/cpython/commit/0dd8fd03584b61cd769be88f5a2fb59b0d8f6d18

New changeset 7593b8a5075ff45d71be9f62980be6a9c005afa9 by Yury Selivanov (Victor Stinner) in branch '3.6':
bpo-33674: asyncio: Fix SSLProtocol race (GH-7175) (GH-7188)
https://github.com/python/cpython/commit/7593b8a5075ff45d71be9f62980be6a9c005afa9

New changeset f295587c45f96b62d24f9a12cef6931b0805f596 by Yury Selivanov in branch 'master':
bpo-33674: Pause the transport as early as possible (#7192)
https://github.com/python/cpython/commit/f295587c45f96b62d24f9a12cef6931b0805f596

New changeset eca085993cb8620ba9232560f46d91326a13cdd2 by Miss Islington (bot) in branch '3.7':
bpo-33674: Pause the transport as early as possible (GH-7192)
https://github.com/python/cpython/commit/eca085993cb8620ba9232560f46d91326a13cdd2

I fixed the main issue, so I remove the "release blocker" priority.

> bpo-33674: Pause the transport as early as possible (#7192)
> https://github.com/python/cpython/commit/f295587c45f96b62d24f9a12cef6931b0805f596

Is it ok to always resume reading? Previously reading was only resumed if the transport was reading.

yes, the method is idempotent.

Closing this one.  Please open new issues to track regressions.

stage: patch review -> resolved

messages: + msg318003