Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Windows: test_asyncio: test_huge_content_recvinto() fails randomly with ProactorEventLoop #80913

Closed
vstinner opened this issue Apr 26, 2019 · 12 comments
Assignees
Labels
3.8 only security fixes 3.9 only security fixes tests Tests in the Lib/test dir topic-asyncio

Comments

@vstinner
Copy link
Member

BPO 36732
Nosy @vstinner, @jkloth, @asvetlov, @1st1

Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.

Show more details

GitHub fields:

assignee = 'https://github.com/asvetlov'
closed_at = <Date 2020-02-07.11:04:19.567>
created_at = <Date 2019-04-26.07:44:21.513>
labels = ['3.8', 'tests', '3.9', 'expert-asyncio']
title = 'Windows: test_asyncio: test_huge_content_recvinto() fails randomly with ProactorEventLoop'
updated_at = <Date 2020-02-07.11:04:19.565>
user = 'https://github.com/vstinner'

bugs.python.org fields:

activity = <Date 2020-02-07.11:04:19.565>
actor = 'vstinner'
assignee = 'asvetlov'
closed = True
closed_date = <Date 2020-02-07.11:04:19.567>
closer = 'vstinner'
components = ['Tests', 'asyncio']
creation = <Date 2019-04-26.07:44:21.513>
creator = 'vstinner'
dependencies = []
files = []
hgrepos = []
issue_num = 36732
keywords = []
message_count = 12.0
messages = ['340892', '344563', '345853', '346387', '346403', '346404', '349773', '349774', '349775', '357280', '357879', '361589']
nosy_count = 4.0
nosy_names = ['vstinner', 'jkloth', 'asvetlov', 'yselivanov']
pr_nums = []
priority = 'normal'
resolution = 'out of date'
stage = 'resolved'
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue36732'
versions = ['Python 3.8', 'Python 3.9']

@vstinner
Copy link
Member Author

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

@vstinner vstinner added 3.8 only security fixes tests Tests in the Lib/test dir topic-asyncio labels Apr 26, 2019
@vstinner
Copy link
Member Author

vstinner commented Jun 4, 2019

I didn't see this issue recently. I close it.

@vstinner vstinner closed this as completed Jun 4, 2019
@vstinner
Copy link
Member Author

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

@vstinner vstinner reopened this Jun 17, 2019
@asvetlov
Copy link
Contributor

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?

@vstinner
Copy link
Member Author

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?

@vstinner
Copy link
Member Author

The failing test was added by:

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

bpo-30064: Refactor sock_* asyncio API (bpo-10419)

@vstinner
Copy link
Member Author

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)

@asvetlov
Copy link
Contributor

ResourceWarning?
I'll take a look

@asvetlov asvetlov self-assigned this Aug 14, 2019
@vstinner
Copy link
Member Author

ResourceWarning?

That's a small bug in the test, but the main issue is that test_huge_content_recvinto() has a race condition.

@vstinner vstinner added the 3.9 only security fixes label Oct 21, 2019
@vstinner vstinner changed the title test_asyncio: test_huge_content_recvinto() fails randomly Windows: test_asyncio: test_huge_content_recvinto() fails randomly with ProactorEventLoop Oct 21, 2019
@vstinner
Copy link
Member Author

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)

@vstinner
Copy link
Member Author

vstinner commented Dec 5, 2019

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)

@vstinner
Copy link
Member Author

vstinner commented Feb 7, 2020

I didn't see the failure recently, I close the issue.

@vstinner vstinner closed this as completed Feb 7, 2020
@ezio-melotti ezio-melotti transferred this issue from another repository Apr 10, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
3.8 only security fixes 3.9 only security fixes tests Tests in the Lib/test dir topic-asyncio
Projects
None yet
Development

No branches or pull requests

2 participants