classification
Title: test_asyncio: test_start_tls_server_1() fails on Python on x86 Windows7 3.7 and 3.x
Type: Stage: resolved
Components: asyncio, Tests Versions: Python 3.8, Python 3.7
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: asvetlov, miss-islington, ned.deily, pablogsal, vstinner, yselivanov
Priority: Keywords: patch

Created on 2018-05-30 11:19 by vstinner, last changed 2019-04-26 07:41 by vstinner. This issue is now closed.

Files
File name Uploaded Description Edit
Screen Shot 2018-05-30 at 11.38.38 AM.png yselivanov, 2018-05-30 15:43
race.py vstinner, 2018-06-07 10:21
Pull Requests
URL Status Linked Edit
PR 7479 closed vstinner, 2018-06-07 14:17
PR 7486 closed yselivanov, 2018-06-07 16:27
PR 7498 merged vstinner, 2018-06-07 21:51
PR 7499 merged miss-islington, 2018-06-07 22:27
PR 7522 merged vstinner, 2018-06-08 08:09
PR 7523 merged miss-islington, 2018-06-08 08:33
PR 10652 vstinner, 2018-12-07 17:23
PR 12951 vstinner, 2019-04-26 07:41
Messages (30)
msg318164 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-05-30 11:19
test_asyncio.test_start_tls_server_1() got many fixes recently: see bpo-32458 and bpo-33674... but it still fails on Python on x86 Windows7 3.x at revision bb9474f1fb2fc7c7ed9f826b78262d6a12b5f9e8 which contains all these fixes.

The test fails even when test_asyncio is re-run alone (not when other tests run in parallel).

http://buildbot.python.org/all/#/builders/58/builds/930

======================================================================
ERROR: test_start_tls_server_1 (test.test_asyncio.test_sslproto.ProactorStartTLSTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows7\build\lib\test\test_asyncio\test_sslproto.py", line 467, in test_start_tls_server_1
    self.loop.run_until_complete(run_main())
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows7\build\lib\asyncio\base_events.py", line 566, in run_until_complete
    raise RuntimeError('Event loop stopped before Future completed.')
RuntimeError: Event loop stopped before Future completed.

======================================================================
FAIL: test_start_tls_server_1 (test.test_asyncio.test_sslproto.ProactorStartTLSTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows7\build\lib\test\test_asyncio\functional.py", line 42, in tearDown
    self.fail('unexpected calls to loop.call_exception_handler()')
AssertionError: unexpected calls to loop.call_exception_handler()


The test fails also on x86 Windows7 3.7:


======================================================================
ERROR: test_start_tls_server_1 (test.test_asyncio.test_sslproto.ProactorStartTLSTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "D:\cygwin\home\db3l\buildarea\3.7.bolen-windows7\build\lib\test\test_asyncio\test_sslproto.py", line 467, in test_start_tls_server_1
    self.loop.run_until_complete(run_main())
  File "D:\cygwin\home\db3l\buildarea\3.7.bolen-windows7\build\lib\asyncio\base_events.py", line 566, in run_until_complete
    raise RuntimeError('Event loop stopped before Future completed.')
RuntimeError: Event loop stopped before Future completed.

======================================================================
FAIL: test_start_tls_server_1 (test.test_asyncio.test_sslproto.ProactorStartTLSTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "D:\cygwin\home\db3l\buildarea\3.7.bolen-windows7\build\lib\test\test_asyncio\functional.py", line 42, in tearDown
    self.fail('unexpected calls to loop.call_exception_handler()')
AssertionError: unexpected calls to loop.call_exception_handler()


Moreover, 3.7 got an additional failure:

======================================================================
ERROR: test_pipe_handle (test.test_asyncio.test_windows_utils.PipeTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "D:\cygwin\home\db3l\buildarea\3.7.bolen-windows7\build\lib\test\test_asyncio\test_windows_utils.py", line 73, in test_pipe_handle
    raise RuntimeError('expected ERROR_INVALID_HANDLE')
RuntimeError: expected ERROR_INVALID_HANDLE


The Windows7 buildbot is known to be slow. For example, test_value() of test_multiprocessing_spawn failed with a timeout (15 min) on x86 Windows7 3.x:

0:48:12 [276/416/1] test_multiprocessing_spawn crashed (Exit code 1)
Timeout (0:15:00)!
Thread 0x000008e4 (most recent call first):
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows7\build\lib\multiprocessing\popen_spawn_win32.py", line 80 in wait
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows7\build\lib\multiprocessing\process.py", line 140 in join
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows7\build\lib\test\_test_multiprocessing.py", line 1925 in test_value



Maybe something is wrong with my karma, I don't know. Or test_asyncio just hate me.
msg318165 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-05-30 11:20
The test fails also on x86 Windows7 3.7:
http://buildbot.python.org/all/#/builders/111/builds/297
msg318193 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2018-05-30 15:43
I can't reproduce test_start_tls_server_1 fails when I do (screenshot attached)

1. run test_asyncio
2. run test_asyncio.test_sslproto
3. run test_asyncio.test_sslproto -m test_start_tls_server_1

I run them in Windows 7 VM on Mac OS.

All other tests pass fine for me except test_sendfile_close_peer_in_the_middle_of_receiving.  Andrew, please look at this, this is your test, and I'm not sure I follow why we use SNDBUF at all. IMO it should be possible to write a test without using that (or if not, maybe time to use mocks).

With regards to start_tls tests -- I give up, I don't have time to look into this before 3.7.0.  I suggest to mask the test on the specific win buildbot it crashes on and fix it before 3.7.1 (or maybe when Windows users come up with a reliable way to reproduce the bug).
msg318194 - (view) Author: Andrew Svetlov (asvetlov) * (Python committer) Date: 2018-05-30 15:49
I used SNDBUF to enforce send buffer overloading.
It is not required by sendfile tests but I thought that better to have non-mocked way to test such situations.
We can remove the socket buffers size manipulation at all without any problem.
msg318195 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2018-05-30 15:50
> We can remove the socket buffers size manipulation at all without any problem.


When I tried to do that I think I was having more failures with that test. But really up to you.
msg318209 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-05-30 21:38
> I used SNDBUF to enforce send buffer overloading.

What is that? Would you mind to elaborate? I'm curious :-)
msg318424 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-06-01 14:55
The test also failed on AMD64 Windows8.1 Refleaks 3.7. This buildbot is also very slow because it runs reference leak hunting. It confirms that the remaining issue is a race condition which is only seen when the system becomes slow.

http://buildbot.python.org/all/#/builders/132/builds/154

======================================================================
ERROR: test_start_tls_server_1 (test.test_asyncio.test_sslproto.ProactorStartTLSTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "D:\buildarea\3.7.ware-win81-release.refleak\build\lib\test\test_asyncio\test_sslproto.py", line 467, in test_start_tls_server_1
    self.loop.run_until_complete(run_main())
  File "D:\buildarea\3.7.ware-win81-release.refleak\build\lib\asyncio\base_events.py", line 566, in run_until_complete
    raise RuntimeError('Event loop stopped before Future completed.')
RuntimeError: Event loop stopped before Future completed.

======================================================================
FAIL: test_start_tls_server_1 (test.test_asyncio.test_sslproto.ProactorStartTLSTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "D:\buildarea\3.7.ware-win81-release.refleak\build\lib\test\test_asyncio\functional.py", line 42, in tearDown
    self.fail('unexpected calls to loop.call_exception_handler()')
AssertionError: unexpected calls to loop.call_exception_handler()
msg318569 - (view) Author: Pablo Galindo Salgado (pablogsal) * (Python committer) Date: 2018-06-03 16:18
The test fails also on x86 Windows7 3.x:
http://buildbot.python.org/all/#/builders/58/builds/947
msg318705 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-06-04 21:07
A variant of the bug?

AMD64 Windows8.1 Non-Debug 3.x:
http://buildbot.python.org/all/#/builders/12/builds/948

======================================================================
ERROR: test_create_connection_ssl_failed_certificate (test.test_asyncio.test_sslproto.ProactorStartTLSTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "D:\buildarea\3.x.ware-win81-release\build\lib\test\test_asyncio\test_sslproto.py", line 623, in test_create_connection_ssl_failed_certificate
    self.loop.run_until_complete(client(srv.addr))
  File "D:\buildarea\3.x.ware-win81-release\build\lib\asyncio\base_events.py", line 566, in run_until_complete
    raise RuntimeError('Event loop stopped before Future completed.')
RuntimeError: Event loop stopped before Future completed.
msg318707 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-06-04 21:36
> AMD64 Windows8.1 Non-Debug 3.x
> ERROR: test_create_connection_ssl_failed_certificate (test.test_asyncio.test_sslproto.ProactorStartTLSTests)

Not surprising: same error on AMD64 Windows8.1 Non-Debug 3.7:
http://buildbot.python.org/all/#builders/133/builds/304
msg318809 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-06-06 10:30
Another variant seen on AppVeyor (PR 7439, master branch):

https://ci.appveyor.com/project/python/cpython/build/3.8build16980

======================================================================
ERROR: test_create_connection_ssl_failed_certificate (test.test_asyncio.test_sslproto.ProactorStartTLSTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\projects\cpython\lib\test\test_asyncio\test_sslproto.py", line 623, in test_create_connection_ssl_failed_certificate
    self.loop.run_until_complete(client(srv.addr))
  File "C:\projects\cpython\lib\asyncio\base_events.py", line 566, in run_until_complete
    raise RuntimeError('Event loop stopped before Future completed.')
RuntimeError: Event loop stopped before Future completed.
----------------------------------------------------------------------
msg318869 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-06-07 00:58
The bug can be reproduced on Linux using this patch:

diff --git a/Lib/test/test_asyncio/test_sslproto.py b/Lib/test/test_asyncio/test_sslproto.py
index 78ab1eb822..735313152c 100644
--- a/Lib/test/test_asyncio/test_sslproto.py
+++ b/Lib/test/test_asyncio/test_sslproto.py
@@ -471,6 +471,8 @@ class BaseStartTLS(func_tests.FunctionalTestCaseMixin):
 
             self.assertEqual(proto.data, b'')
 
+            await asyncio.sleep(1)
+
             new_tr = await self.loop.start_tls(
                 tr, proto, server_context,
                 server_side=True,
msg318872 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-06-07 01:08
Call stack when the asyncio client connects to the server when the bug occurs:

SSLProtocol.connection_made()
-> SSLProtocol._start_handshake()
-> SSLProtocol._process_write_backlog()
-> SSLPipe.do_handshake()
-> SSLPipe.feed_ssldata(b'', only_handshake=True)
-> SSLObject.do_handshake()
-> C SSL_do_handshake() returns immediately because the socket is non-blocking

It seems like SSLObject.do_handshake() is only attempted once and... then nothing. The client is supposed to send data, retry the handshake, or something, but it does *nothing*. So the handshake never completes and the test hangs to later fail with a timeout.
msg318873 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-06-07 01:26
The issue occurs when the server calls start_tls() because the client calls start_tls(). In that case, ServerProto.data_received() is called with the server TLS handshake and so the client SSLProtocol never this this handshake from server...
msg318874 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-06-07 01:44
Sorry, the patch to reproduce the issue on Linux is wrong: it introduces a bug in the test. Ignore this comment.

--

It seems like I found the root cause: pause_reading() / resume_reading() on the transport is not safe. Sometimes, we loose data. See the "TODO" below...

class _ProactorReadPipeTransport(_ProactorBasePipeTransport,
                                 transports.ReadTransport):
    """Transport for read pipes."""
    (...)
    def pause_reading(self):
        if self._closing or self._paused:
            return
        self._paused = True

        if self._read_fut is not None and not self._read_fut.done():
            # TODO: This is an ugly hack to cancel the current read future
            # *and* avoid potential race conditions, as read cancellation
            # goes through `future.cancel()` and `loop.call_soon()`.
            # We then use this special attribute in the reader callback to
            # exit *immediately* without doing any cleanup/rescheduling.
            self._read_fut.__asyncio_cancelled_on_pause__ = True

            self._read_fut.cancel()
            self._read_fut = None
            self._reschedule_on_resume = True

        if self._loop.get_debug():
            logger.debug("%r pauses reading", self)


If you remove the "ugly hack", the test no longer hangs...
msg318875 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-06-07 02:26
_ProactorReadPipeTransport.set_transport():

        if self.is_reading():
            # reset reading callback / buffers / self._read_fut
            self.pause_reading()
            self.resume_reading()

This method cancelled the pending overlapped WSARecv(), and then create a new overlapped WSARecv().

Even after CancelIoEx(old overlapped), the IOCP loop still gets an event for the completion of the recv. Problem: since the Python future is cancelled, the even is ignored and so 176 bytes are lost.

I'm surprised that an overlapped WSARecv() cancelled by CancelIoEx() still returns data when IOCP polls for events.
msg318876 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-06-07 02:52
Something else. The bug occurs when CancelIoEx() (on the current overlapped WSARecv()) fails internally with ERROR_NOT_FOUND. According to overlapped.c, it means:

/* CancelIoEx returns ERROR_NOT_FOUND if the I/O completed in-between */

HasOverlappedIoCompleted() returns 0 in that case.

The problem is that currently, Overlapped.cancel() also returns None in that case, and later the asyncio IOCP loop ignores the completion event and so drops incoming received data.
msg318915 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-06-07 08:37
Yury, Andrew, Ned: I set the priority to release blocker because I'm scared by what I saw. The START TLS has a race condition in its ProactorEventLoop implementation. But the bug doesn't see to be specific to START TLS, but rather to transport.set_transport(), and even more generally to transport.pause_reading() / transport.resume_reading(). The bug is quite severe: we loose data and it's really hard to know why (I spent a few hours to add many many print and try to reproduce on a very tiny reliable unit test). As an asyncio user, I expect that transports are 100% reliable, and I would first look into my look (like looking into start_tls() implementation in my case).

If the bug was very specific to start_tls(), I would suggest to "just" "disable" start_tls() on ProactorEventLoop (sorry, Windows!). But since the data loss seems to concern basically any application using ProactorEventLoop, I don't see any simple workaround.

My hope is that a fix can be written shortly to not block the 3.7.0 final release for too long :-(

Yury, Andrew: Can you please just confirm that it's a regression and that a release blocker is justified?
msg318921 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-06-07 10:21
race.py: simple echo client and server sending packets in both directions. Pause/resume reading the client transport every 100 ms to trigger the bug.

Using ProactorEventLoop and 2000 packets of 16 KiB, I easily reproduce the bug.

So again, it's nothing related to start_tls(), start_tls() was just one way to spot the bug.

The bug is in Proactor transport: the cancellation of overlapped WSARecv() sometime drops packets. The bug occurs when CancelIoEx() fails with ERROR_NOT_FOUND which means that the I/O (WSARecv()) completed.

One solution would be to not cancel WSARecv() on pause_reading(): wait until the current WSARecv() completes, store data something but don't pass it to protocol.data_received()!, and no schedule a new WSARecv(). Once reading is resumed: call protocol.data_received() and schedule a new WSARecv().

That would be a workaround. I don't know how to really fix WSARecv() cancellation without loosing data. A good start would be to modify Overlapped.cancel() to return a boolean to notice if the overlapped I/O completed even if we just cancelled it. Currently, the corner case (CancelIoEx() fails with ERROR_NOT_FOUND) is silently ignored, and then the IOCP loop silently ignores the event of completed I/O...
msg318977 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-06-07 22:25
New changeset 79790bc35fe722a49977b52647f9b5fe1deda2b7 by Victor Stinner in branch 'master':
bpo-33694: Fix race condition in asyncio proactor (GH-7498)
https://github.com/python/cpython/commit/79790bc35fe722a49977b52647f9b5fe1deda2b7
msg318979 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-06-07 22:49
New changeset 8fa398d5cecec80990c5642b081f52cbbc6a05eb by Victor Stinner (Miss Islington (bot)) in branch '3.7':
bpo-33694: Fix race condition in asyncio proactor (GH-7498) (GH-7499)
https://github.com/python/cpython/commit/8fa398d5cecec80990c5642b081f52cbbc6a05eb
msg318993 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-06-08 00:13
I fixed the root issue, a race condition in ProactorEventLoop. But I prefer to keep the issue open a few days to see if the bug is really gone from all CIs.
msg319034 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-06-08 08:32
New changeset ff6c07729211fb98431a2793e074d07a21e0650a by Victor Stinner in branch 'master':
bpo-33694: Fix typo in helper function name (GH-7522)
https://github.com/python/cpython/commit/ff6c07729211fb98431a2793e074d07a21e0650a
msg319035 - (view) Author: miss-islington (miss-islington) Date: 2018-06-08 08:48
New changeset 17beebcc8b22a66b7973cbe5b1577567ab391c0a by Miss Islington (bot) in branch '3.7':
bpo-33694: Fix typo in helper function name (GH-7522)
https://github.com/python/cpython/commit/17beebcc8b22a66b7973cbe5b1577567ab391c0a
msg319155 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-06-09 16:44
I ran attached race.py on the 3.6 branch:

* 2000 packets of 16 KiB: ok
* 50 packets of 16 MiB: ok

It seems like Python 3.6 (at least the 3.6 development branch) doesn't have this bug.

It didn't see the bug recently, so I close the issue.

Python 3.6 has a different issue: pause_reading() cannot be called twice, same issue with resume_reading(). But I'm not sure that it can be called a bug. Python 3.7 allows to call these methods twice and to call these methods while closing: they just do nothing in that case.

I close the issue.
msg319175 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2018-06-09 19:51
pause_reading and resume_reading became idempotent only in 3.7
msg319209 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-06-10 11:51
>  pause_reading and resume_reading became idempotent only in 3.7

Do you consider that it's a new feature or a bugfix? Should we backport this change to 3.6? Currently, race.py fails with an error because of the 3.6 behaviour. (I modified asyncio to be able to run race.py on 3.6.)
msg319220 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2018-06-10 13:18
Since it a minor change we can reconsider it as s bug fix. Feel free to make a pr.
msg319299 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-06-11 11:55
"Since it a minor change we can reconsider it as s bug fix. Feel free
to make a pr."

Ok, I created https://github.com/python/cpython/pull/7629/ for bpo-32356
msg319450 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-06-13 10:25
New changeset 142e3c08a40c75b5788474b0defe7d5c0671f675 by Victor Stinner in branch '3.6':
[3.6] bpo-32356: idempotent pause_/resume_reading (GH-4914) (GH-7629)
https://github.com/python/cpython/commit/142e3c08a40c75b5788474b0defe7d5c0671f675
History
Date User Action Args
2019-04-26 07:41:32vstinnersetpull_requests: + pull_request12891
2018-12-07 17:23:14vstinnersetpull_requests: + pull_request10267
2018-11-07 21:56:13vstinnersetpull_requests: - pull_request9681
2018-11-07 17:15:59Martin Bijl-Schwabsetpull_requests: + pull_request9681
2018-06-13 10:25:50vstinnersetmessages: + msg319450
2018-06-11 11:55:56vstinnersetmessages: + msg319299
2018-06-10 13:18:49yselivanovsetmessages: + msg319220
2018-06-10 11:51:01vstinnersetmessages: + msg319209
2018-06-09 19:51:35yselivanovsetmessages: + msg319175
2018-06-09 16:44:39vstinnersetstatus: open -> closed
priority: release blocker ->
messages: + msg319155

resolution: fixed
stage: patch review -> resolved
2018-06-08 08:48:55miss-islingtonsetnosy: + miss-islington
messages: + msg319035
2018-06-08 08:33:18miss-islingtonsetpull_requests: + pull_request7151
2018-06-08 08:32:13vstinnersetmessages: + msg319034
2018-06-08 08:09:05vstinnersetpull_requests: + pull_request7150
2018-06-08 00:13:26vstinnersetmessages: + msg318993
2018-06-07 22:49:36vstinnersetmessages: + msg318979
2018-06-07 22:27:23miss-islingtonsetpull_requests: + pull_request7124
2018-06-07 22:25:54vstinnersetmessages: + msg318977
2018-06-07 21:51:29vstinnersetpull_requests: + pull_request7123
2018-06-07 16:27:28yselivanovsetpull_requests: + pull_request7111
2018-06-07 14:17:23vstinnersetkeywords: + patch
stage: patch review
pull_requests: + pull_request7106
2018-06-07 10:21:06vstinnersetfiles: + race.py

messages: + msg318921
2018-06-07 08:37:15vstinnersetpriority: normal -> release blocker
nosy: + ned.deily
messages: + msg318915

2018-06-07 02:52:02vstinnersetmessages: + msg318876
2018-06-07 02:26:38vstinnersetmessages: + msg318875
2018-06-07 01:44:49vstinnersetmessages: + msg318874
2018-06-07 01:26:08vstinnersetmessages: + msg318873
2018-06-07 01:08:32vstinnersetmessages: + msg318872
2018-06-07 00:58:25vstinnersetmessages: + msg318869
2018-06-06 10:30:08vstinnersetmessages: + msg318809
2018-06-04 21:36:24vstinnersetmessages: + msg318707
2018-06-04 21:07:32vstinnersetmessages: + msg318705
2018-06-03 16:18:02pablogsalsetnosy: + pablogsal
messages: + msg318569
2018-06-01 14:55:30vstinnersetmessages: + msg318424
2018-05-30 21:38:11vstinnersetmessages: + msg318209
2018-05-30 15:50:28yselivanovsetmessages: + msg318195
2018-05-30 15:49:36asvetlovsetmessages: + msg318194
2018-05-30 15:43:26yselivanovsetfiles: + Screen Shot 2018-05-30 at 11.38.38 AM.png

messages: + msg318193
2018-05-30 11:20:51vstinnersetmessages: + msg318165
2018-05-30 11:19:38vstinnercreate