classification
Title: Windows: test_asyncio: test_huge_content_recvinto() fails randomly with ProactorEventLoop
Type: Stage: resolved
Components: asyncio, Tests Versions: Python 3.9, Python 3.8
process
Status: closed Resolution: out of date
Dependencies: Superseder:
Assigned To: asvetlov Nosy List: asvetlov, jkloth, vstinner, yselivanov
Priority: normal Keywords:

Created on 2019-04-26 07:44 by vstinner, last changed 2020-02-07 11:04 by vstinner. This issue is now closed.

Messages (12)
msg340892 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-04-26 07:44
Failure on AMD64 Windows7 SP1 3.x:
https://buildbot.python.org/all/#/builders/40/builds/2053

...
test_start_unix_server_1 (test.test_asyncio.test_server.SelectorStartServerTests) ... skipped 'no Unix sockets'
test_create_connection_sock (test.test_asyncio.test_sock_lowlevel.ProactorEventLoopTests) ... ok
test_huge_content (test.test_asyncio.test_sock_lowlevel.ProactorEventLoopTests) ... ok
test_huge_content_recvinto (test.test_asyncio.test_sock_lowlevel.ProactorEventLoopTests) ... ERROR
test_sock_accept (test.test_asyncio.test_sock_lowlevel.ProactorEventLoopTests) ... C:\buildbot.python.org\3.x.kloth-win64\build\lib\test\support\__init__.py:1627: ResourceWarning: unclosed <socket.socket fd=752, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('127.0.0.1', 42975), raddr=('127.0.0.1', 42974)>
  gc.collect()
ResourceWarning: Enable tracemalloc to get the object allocation traceback
ok
test_sock_client_fail (test.test_asyncio.test_sock_lowlevel.ProactorEventLoopTests) ... ok
test_sock_client_ops (test.test_asyncio.test_sock_lowlevel.ProactorEventLoopTests) ... ok
test_unix_sock_client_ops (test.test_asyncio.test_sock_lowlevel.ProactorEventLoopTests) ... skipped 'No UNIX Sockets'
test_create_connection_sock (test.test_asyncio.test_sock_lowlevel.SelectEventLoopTests) ... ok
test_huge_content (test.test_asyncio.test_sock_lowlevel.SelectEventLoopTests) ... ok
test_huge_content_recvinto (test.test_asyncio.test_sock_lowlevel.SelectEventLoopTests) ... ok
...

======================================================================
ERROR: test_huge_content_recvinto (test.test_asyncio.test_sock_lowlevel.ProactorEventLoopTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\asyncio\windows_events.py", line 474, in finish_recv
    return ov.getresult()
OSError: [WinError 64] The specified network name is no longer available

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\test\test_asyncio\test_sock_lowlevel.py", line 225, in test_huge_content_recvinto
    self.loop.run_until_complete(
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\asyncio\base_events.py", line 590, in run_until_complete
    return future.result()
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\test\test_asyncio\test_sock_lowlevel.py", line 211, in _basetest_huge_content_recvinto
    nbytes = await self.loop.sock_recv_into(sock, buf)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\asyncio\proactor_events.py", line 551, in sock_recv_into
    return await self._proactor.recv_into(sock, buf)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\asyncio\windows_events.py", line 760, in _poll
    value = callback(transferred, key, ov)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\asyncio\windows_events.py", line 478, in finish_recv
    raise ConnectionResetError(*exc.args)
ConnectionResetError: [WinError 64] The specified network name is no longer available
msg344563 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-06-04 13:00
I didn't see this issue recently. I close it.
msg345853 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-06-17 12:52
New failure on AMD64 Windows7 SP1 3.8:
https://buildbot.python.org/all/#/builders/208/builds/75

======================================================================
ERROR: test_huge_content_recvinto (test.test_asyncio.test_sock_lowlevel.SelectEventLoopTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\buildbot.python.org\3.8.kloth-win64\build\lib\test\test_asyncio\test_sock_lowlevel.py", line 225, in test_huge_content_recvinto
    self.loop.run_until_complete(
  File "C:\buildbot.python.org\3.8.kloth-win64\build\lib\asyncio\base_events.py", line 608, in run_until_complete
    return future.result()
  File "C:\buildbot.python.org\3.8.kloth-win64\build\lib\test\test_asyncio\test_sock_lowlevel.py", line 211, in _basetest_huge_content_recvinto
    nbytes = await self.loop.sock_recv_into(sock, buf)
  File "C:\buildbot.python.org\3.8.kloth-win64\build\lib\asyncio\selector_events.py", line 400, in sock_recv_into
    return await fut
  File "C:\buildbot.python.org\3.8.kloth-win64\build\lib\asyncio\selector_events.py", line 409, in _sock_recv_into
    nbytes = sock.recv_into(buf)
ConnectionResetError: [WinError 10054] An existing connection was forcibly closed by the remote host

(... test_asyncio re-run in verbose mode ...)

======================================================================
ERROR: test_huge_content (test.test_asyncio.test_sock_lowlevel.ProactorEventLoopTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\buildbot.python.org\3.8.kloth-win64\build\lib\asyncio\windows_events.py", line 453, in finish_recv
    return ov.getresult()
OSError: [WinError 64] The specified network name is no longer available

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\buildbot.python.org\3.8.kloth-win64\build\lib\test\test_asyncio\test_sock_lowlevel.py", line 170, in test_huge_content
    self.loop.run_until_complete(
  File "C:\buildbot.python.org\3.8.kloth-win64\build\lib\asyncio\base_events.py", line 608, in run_until_complete
    return future.result()
  File "C:\buildbot.python.org\3.8.kloth-win64\build\lib\test\test_asyncio\test_sock_lowlevel.py", line 157, in _basetest_huge_content
    data = await self.loop.sock_recv(sock, DATA_SIZE)
  File "C:\buildbot.python.org\3.8.kloth-win64\build\lib\asyncio\proactor_events.py", line 690, in sock_recv
    return await self._proactor.recv(sock, n)
  File "C:\buildbot.python.org\3.8.kloth-win64\build\lib\asyncio\windows_events.py", line 808, in _poll
    value = callback(transferred, key, ov)
  File "C:\buildbot.python.org\3.8.kloth-win64\build\lib\asyncio\windows_events.py", line 457, in finish_recv
    raise ConnectionResetError(*exc.args)
ConnectionResetError: [WinError 64] The specified network name is no longer available
msg346387 - (view) Author: Andrew Svetlov (asvetlov) * (Python committer) Date: 2019-06-24 12:28
There is an interesting discussion: https://stackoverflow.com/questions/14499593/can-the-infamous-error-netname-deleted-error-be-considered-an-error-at-all

"[WinError 64] The specified network name is no longer available" is raised on pending reads from closed socket.

Looks like we can just drop these reads without error reporting, it is safe and easy.

Victor, what do you think?
msg346403 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-06-24 13:48
We get a ConnectionResetError exception thanks to IocpProactor.recv() callback:

        def finish_recv(trans, key, ov):
            try:
                return ov.getresult()
            except OSError as exc:
                if exc.winerror in (_overlapped.ERROR_NETNAME_DELETED,
                                    _overlapped.ERROR_OPERATION_ABORTED):
                    raise ConnectionResetError(*exc.args)
                else:
                    raise

Would it be legit to convert ConnectionResetError to returning b'' in sock_recv()? Example with the test:

        while True:
            data = await self.loop.sock_recv(sock, DATA_SIZE)
            if not data:
                break
            expected = bytes(islice(checker, len(data)))
            self.assertEqual(data, expected)
            size -= len(data)
        self.assertEqual(size, 0)

"if not data:" is a common test to check if we reached the end of file or if a socket has been closed by the peer, no?

Proposed patch:

diff --git a/Lib/asyncio/proactor_events.py b/Lib/asyncio/proactor_events.py
index 9b8ae064a8..14b7f10729 100644
--- a/Lib/asyncio/proactor_events.py
+++ b/Lib/asyncio/proactor_events.py
@@ -687,10 +687,16 @@ class BaseProactorEventLoop(base_events.BaseEventLoop):
         super().close()
 
     async def sock_recv(self, sock, n):
-        return await self._proactor.recv(sock, n)
+        try:
+            return await self._proactor.recv(sock, n)
+        except (ConnectionResetError, ConnectionAbortedError):
+            return b''
 
     async def sock_recv_into(self, sock, buf):
-        return await self._proactor.recv_into(sock, buf)
+        try:
+            return await self._proactor.recv_into(sock, buf)
+        except (ConnectionResetError, ConnectionAbortedError):
+            return 0
 
     async def sock_sendall(self, sock, data):
         return await self._proactor.send(sock, data)


I'm not sure about this change.

I'm not sure about sock_recv_info(): are you suppose to truncate buf to 0 bytes in this case?
msg346404 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-06-24 13:49
The failing test was added by:

commit 74387926072abf338a4c1cec1bf0501fc65bbee5
Author: Andrew Svetlov <andrew.svetlov@gmail.com>
Date:   Mon Nov 12 19:00:22 2018 +0200

    bpo-30064: Refactor sock_* asyncio API (#10419)
msg349773 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-08-14 22:46
Recent failure on AMD64 Windows7 SP1 3.8:
https://buildbot.python.org/all/#/builders/208/builds/268

test_huge_content_recvinto (test.test_asyncio.test_sock_lowlevel.ProactorEventLoopTests) ... C:\buildbot.python.org\3.8.kloth-win64\build\lib\test\support\__init__.py:1637: ResourceWarning: unclosed <socket.socket fd=564, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('127.0.0.1', 59291), raddr=('127.0.0.1', 59290)>
ResourceWarning: Enable tracemalloc to get the object allocation traceback

ERROR: test_huge_content (test.test_asyncio.test_sock_lowlevel.ProactorEventLoopTests)

Re-running failed tests in verbose mode
C:\buildbot.python.org\3.8.kloth-win64\build\lib\test\support\__init__.py:1637: ResourceWarning: unclosed <socket.socket fd=456, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('127.0.0.1', 3999), raddr=('127.0.0.1', 3998)>
ResourceWarning: Enable tracemalloc to get the object allocation traceback
FAIL: test_huge_content_recvinto (test.test_asyncio.test_sock_lowlevel.SelectEventLoopTests)
msg349774 - (view) Author: Andrew Svetlov (asvetlov) * (Python committer) Date: 2019-08-14 22:53
ResourceWarning?
I'll take a look
msg349775 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-08-14 22:59
> ResourceWarning?

That's a small bug in the test, but the main issue is that test_huge_content_recvinto() has a race condition.
msg357280 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-11-22 13:33
AMD64 Windows7 SP1 3.x:
https://buildbot.python.org/all/#/builders/40/builds/3470

ERROR: test_huge_content_recvinto (test.test_asyncio.test_sock_lowlevel.SelectEventLoopTests)
...
ERROR: test_huge_content (test.test_asyncio.test_sock_lowlevel.SelectEventLoopTests)
msg357879 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-12-05 18:26
New failure on AMD64 Windows7 SP1 3.x:
https://buildbot.python.org/all/#/builders/81/builds/16

ERROR: test_huge_content_recvinto (test.test_asyncio.test_sock_lowlevel.SelectEventLoopTests)

also:

ERROR: test_pipe_handle (test.test_asyncio.test_windows_utils.PipeTests)
msg361589 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2020-02-07 11:04
I didn't see the failure recently, I close the issue.
History
Date User Action Args
2020-02-07 11:04:19vstinnersetstatus: open -> closed
resolution: out of date
messages: + msg361589
2019-12-05 18:26:35vstinnersetmessages: + msg357879
2019-11-22 13:33:24vstinnersetmessages: + msg357280
2019-10-21 12:01:17jklothsetnosy: + jkloth
2019-10-21 10:21:04vstinnersettitle: test_asyncio: test_huge_content_recvinto() fails randomly -> Windows: test_asyncio: test_huge_content_recvinto() fails randomly with ProactorEventLoop
versions: + Python 3.9
2019-08-14 22:59:50vstinnersetmessages: + msg349775
2019-08-14 22:54:01asvetlovsetassignee: asvetlov
2019-08-14 22:53:52asvetlovsetmessages: + msg349774
2019-08-14 22:46:51vstinnersetmessages: + msg349773
2019-06-24 13:49:54vstinnersetmessages: + msg346404
2019-06-24 13:48:19vstinnersetmessages: + msg346403
2019-06-24 12:28:27asvetlovsetmessages: + msg346387
2019-06-17 12:52:40vstinnersetstatus: closed -> open
resolution: out of date -> (no value)
messages: + msg345853
2019-06-04 13:00:16vstinnersetstatus: open -> closed
resolution: out of date
messages: + msg344563

stage: resolved
2019-04-26 07:44:21vstinnercreate