[Windows] : Proactor test_sendfile_close_peer_in_the_middle_of_receiving failure

[aeros]

BPO	41682
Nosy	@gvanrossum, @terryjreedy, @ncoghlan, @vstinner, @asvetlov, @1st1, @miss-islington, @sweeneyde, @aeros, @erlend-aasland, @sobolevn, @Fidget-Spinner, @kumaraditya303, @arhadthedev
PRs	bpo-41682: skip test_sendfile_close_peer_in_the_middle_of_receiving in test_asyncio #30801 [3.9] bpo-41682: Skip unstable test_asyncio sendfile test on Windows (GH-30801) #30811 [3.10] bpo-41682: Skip unstable test_asyncio sendfile test on Windows (GH-30801) #30812 bpo-45382: test.pythoninfo logs more Windows versions #30817 bpo-41682: fixed flaky test test_sendfile_close_peer_in_the_middle_of_receiving #30845 [3.10] bpo-41682: fixed flaky test test_sendfile_close_peer_in_the_middle_of_receiving (GH-30845) #30860 [3.9] bpo-41682: fixed flaky test test_sendfile_close_peer_in_the_middle_of_receiving (GH-30845) #30861

^{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 = None
closed_at = <Date 2022-01-25.17:41:06.264>
created_at = <Date 2020-09-01.01:20:55.485>
labels = ['type-bug', '3.10', '3.11', 'tests', 'OS-windows', 'expert-asyncio']
title = '[Windows] : Proactor test_sendfile_close_peer_in_the_middle_of_receiving failure'
updated_at = <Date 2022-01-25.18:03:17.384>
user = 'https://github.com/aeros'

bugs.python.org fields:

activity = <Date 2022-01-25.18:03:17.384>
actor = 'vstinner'
assignee = 'none'
closed = True
closed_date = <Date 2022-01-25.17:41:06.264>
closer = 'vstinner'
components = ['Tests', 'Windows', 'asyncio']
creation = <Date 2020-09-01.01:20:55.485>
creator = 'aeros'
dependencies = []
files = []
hgrepos = []
issue_num = 41682
keywords = ['patch']
message_count = 23.0
messages = ['376175', '376176', '391134', '392061', '396238', '396503', '399770', '402294', '404820', '408612', '411293', '411299', '411313', '411322', '411386', '411508', '411638', '411639', '411640', '411641', '411643', '411646', '411651']
nosy_count = 14.0
nosy_names = ['gvanrossum', 'terry.reedy', 'ncoghlan', 'vstinner', 'asvetlov', 'yselivanov', 'miss-islington', 'Dennis Sweeney', 'aeros', 'erlendaasland', 'sobolevn', 'kj', 'kumaraditya', 'arhadthedev']
pr_nums = ['30801', '30811', '30812', '30817', '30845', '30860', '30861']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue41682'
versions = ['Python 3.10', 'Python 3.11']

[aeros]

In an unrelated PR to add a new argument to the base Executor class for concurrent.futures, there was a test_asyncio failure in test_sendfile for the ProactorEventLoop tests:

======================================================================
FAIL: test_sendfile_close_peer_in_the_middle_of_receiving (test.test_asyncio.test_sendfile.ProactorEventLoopTests)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "D:\a\cpython\cpython\lib\test\test_asyncio\test_sendfile.py", line 452, in test_sendfile_close_peer_in_the_middle_of_receiving
    self.run_loop(
AssertionError: ConnectionError not raised

---

https://github.com/python/cpython/pull/22023/checks?check_run_id=1049760805#step:5:2373

[aeros]

In case the link to the logs are lost from closing and reopening the PR, it was a Windows CI test (GitHub actions) ran with the following configuration:

D:\a\cpython\cpython>"D:\a\cpython\cpython\PCbuild\amd64\python.exe" -u -Wd -E -bb -m test -uall -u-cpu -rwW --slowest --timeout 1200 -j0
== CPython 3.10.0a0 (remotes/pull/22023/merge:992cc27, Aug 31 2020, 06:11:21) [MSC v.1927 64 bit (AMD64)]
== Windows-10-10.0.17763-SP0 little-endian
== cwd: D:\a\cpython\cpython\build\test_python_6372�
== CPU count: 2
== encodings: locale=cp1252, FS=utf-8
Using random seed 491155
0:00:00 Run tests in parallel using 4 child processes (timeout: 20 min, worker timeout: 25 min)

[vstinner]

I marked bpo-42124 and bpo-43539 as a duplicate of this issue.

[ncoghlan]

Another instance at https://github.com/python/cpython/pull/25585/checks?check_run_id=2447701034

I unlinked the previously linked PR, as that looked to be for bpo-43539 rather than this issue.

[vstinner]

This bug still occurs time to time on GitHub Actions.

https://github.com/python/cpython/pull/26826/checks?check_run_id=2874631119

======================================================================
FAIL: test_sendfile_close_peer_in_the_middle_of_receiving (test.test_asyncio.test_sendfile.ProactorEventLoopTests)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "D:\a\cpython\cpython\lib\test\test_asyncio\test_sendfile.py", line 457, in test_sendfile_close_peer_in_the_middle_of_receiving
    with self.assertRaises(ConnectionError):
AssertionError: ConnectionError not raised

[erlend-aasland]

Two new failures today:

https://github.com/python/cpython/runs/2905621215:
2021-06-24T14:18:23.3772681Z ======================================================================
2021-06-24T14:18:23.3773622Z FAIL: test_sendfile_close_peer_in_the_middle_of_receiving (test.test_asyncio.test_sendfile.ProactorEventLoopTests)
2021-06-24T14:18:23.3774665Z ----------------------------------------------------------------------

2021-06-24T14:18:23.3775258Z Traceback (most recent call last):
2021-06-24T14:18:23.3776123Z   File "D:\a\cpython\cpython\lib\test\test_asyncio\test_sendfile.py", line 457, in test_sendfile_close_peer_in_the_middle_of_receiving
2021-06-24T14:18:23.3777065Z     with self.assertRaises(ConnectionError):
2021-06-24T14:18:23.3777775Z AssertionError: ConnectionError not raised
2021-06-24T14:18:23.3778226Z 
2021-06-24T14:18:23.3778744Z 

---

2021-06-24T14:18:23.3779161Z
2021-06-24T14:18:23.3779555Z Ran 2022 tests in 54.341s
2021-06-24T14:18:23.3779870Z
2021-06-24T14:18:23.3780352Z FAILED (failures=1, skipped=63)
2021-06-24T14:18:23.3780890Z test test_asyncio failed

https://github.com/python/cpython/runs/2906141524:
2021-06-24T15:23:11.7177493Z ======================================================================
2021-06-24T15:23:11.7178338Z FAIL: test_sendfile_close_peer_in_the_middle_of_receiving (test.test_asyncio.test_sendfile.ProactorEventLoopTests)
2021-06-24T15:23:11.7179234Z ----------------------------------------------------------------------

2021-06-24T15:23:11.7179754Z Traceback (most recent call last):
2021-06-24T15:23:11.7180469Z   File "D:\a\cpython\cpython\lib\test\test_asyncio\test_sendfile.py", line 457, in test_sendfile_close_peer_in_the_middle_of_receiving
2021-06-24T15:23:11.7181284Z     with self.assertRaises(ConnectionError):
2021-06-24T15:23:11.7182125Z AssertionError: ConnectionError not raised
2021-06-24T15:23:11.7182560Z 
2021-06-24T15:23:11.7183334Z 

---

2021-06-24T15:23:11.7183839Z

[vstinner]

Recent failure on GHA Windows x64:

https://github.com/python/cpython/runs/3342514542

2021-08-16T17:19:58.4338049Z ======================================================================
2021-08-16T17:19:58.4339129Z FAIL: test_sendfile_close_peer_in_the_middle_of_receiving (test.test_asyncio.test_sendfile.ProactorEventLoopTests)
2021-08-16T17:19:58.4340315Z ----------------------------------------------------------------------

2021-08-16T17:19:58.4340937Z Traceback (most recent call last):
2021-08-16T17:19:58.4341846Z   File "D:\a\cpython\cpython\lib\test\test_asyncio\test_sendfile.py", line 457, in test_sendfile_close_peer_in_the_middle_of_receiving
2021-08-16T17:19:58.4342849Z     with self.assertRaises(ConnectionError):
2021-08-16T17:19:58.4343398Z     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2021-08-16T17:19:58.4343982Z AssertionError: ConnectionError not raised

[sobolevn]

Happened to me today: https://dev.azure.com/Python/cpython/_build/results?buildId=88208&view=logs&j=c83831cd-3752-5cc7-2f01-8276919eb334&t=5a421c4a-0933-53d5-26b9-04b36ad165eb

test_sendfile_close_peer_in_the_middle_of_receiving (test.test_asyncio.test_sendfile.ProactorEventLoopTests) ... FAIL
test test_asyncio failed
test_sendfile_close_peer_in_the_middle_of_receiving (test.test_asyncio.test_sendfile.SelectEventLoopTests) ... ok

======================================================================
FAIL: test_sendfile_close_peer_in_the_middle_of_receiving (test.test_asyncio.test_sendfile.ProactorEventLoopTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "D:\a\1\s\lib\test\test_asyncio\test_sendfile.py", line 457, in test_sendfile_close_peer_in_the_middle_of_receiving
    with self.assertRaises(ConnectionError):
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
AssertionError: ConnectionError not raised

----------------------------------------------------------------------
Ran 2 tests in 0.087s

FAILED (failures=1)
0:08:56 load avg: 3.51 Re-running test_concurrent_futures in verbose mode (matching: test_cancel_futures_wait_false)
test_cancel_futures_wait_false (test.test_concurrent_futures.ThreadPoolShutdownTest) ... ok

----------------------------------------------------------------------
Ran 1 test in 0.303s

OK
1 test failed again:
    test_asyncio

[erlend-aasland]

New failure today: https://github.com/python/cpython/runs/3979900415?check_suite_focus=true

test_sendfile_close_peer_in_the_middle_of_receiving (test.test_asyncio.test_sendfile.SelectEventLoopTests) ... ok

======================================================================
FAIL: test_sendfile_close_peer_in_the_middle_of_receiving (test.test_asyncio.test_sendfile.ProactorEventLoopTests)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "D:\a\cpython\cpython\lib\test\test_asyncio\test_sendfile.py", line 457, in test_sendfile_close_peer_in_the_middle_of_receiving
    with self.assertRaises(ConnectionError):
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
AssertionError: ConnectionError not raised

[Fidget-Spinner]

Happened to a PR I was reviewing today:
https://github.com/python/cpython/runs/4535247255?check_suite_focus=true

[erlend-aasland]

Previously, this failure was more sporadic; now it happens almost every single run on the Azure CI. Has there been updates on the Azure CI lately?

[vstinner]

New changeset 1ded8ed by Nikita Sobolev in branch 'main':
bpo-41682: Skip unstable test_asyncio sendfile test on Windows (GH-30801)
1ded8ed

[miss-islington]

New changeset ba932d9 by Miss Islington (bot) in branch '3.9':
bpo-41682: Skip unstable test_asyncio sendfile test on Windows (GH-30801)
ba932d9

[vstinner]

New changeset 486b4d3 by Miss Islington (bot) in branch '3.10':
bpo-41682: Skip unstable test_asyncio sendfile test on Windows (GH-30801) (GH-30812)
486b4d3

[gvanrossum]

I'm wondering if the test is faulty. It seems to call EventLoop.sendfile() with a file that is 8K + 1 byte long,
and the protocol is instructed to close after 1K bytes have been written, but it seems to try to send as much of the file as it can.
Could it be that on Win22 the primitive used (TransmitFile) has an internal minimum buffer size that exceeds this file size, so the first call sends the whole file and there's no error?

@andrew Svetlov, do you know enough of the internals of this code to validate my theory?

[asvetlov]

Guido, I can not confirm your suggestion but it seems correct to me.

[vstinner]

Test fixed on Windows 2022 by:

commit 1c705fd
Author: Kumar Aditya <59607654+kumaraditya303@users.noreply.github.com>
Date: Tue Jan 25 02:34:47 2022 +0530

fixed flaky test (GH-30845)

[vstinner]

New changeset 75d88b9 by Miss Islington (bot) in branch '3.10':
bpo-41682: fixed flaky test test_sendfile_close_peer_in_the_middle_of_receiving (GH-30845) (bpo-30860)
75d88b9

[vstinner]

New changeset f9ff0bf by Miss Islington (bot) in branch '3.9':
bpo-41682: fixed flaky test test_sendfile_close_peer_in_the_middle_of_receiving (GH-30845) (bpo-30861)
f9ff0bf

[vstinner]

Thanks Kumar for the fix!

[vstinner]

This failing test was one of my most hated test because it failed randomly for almost 2 years. I'm happy that it has been fixed :-)

Regularly, I'm asking for help to fix test_asyncio:

• October 2020: https://mail.python.org/archives/list/python-dev@python.org/message/Y7I5ADXAQEGK6DOFAPVDTKMBT6NUFNQ4/
• October 2019: https://mail.python.org/archives/list/python-dev@python.org/message/R7X6NKGEOKWD3PBWIL2LPZWZ6MMRANN5/

Last years I gave up, since almost no one replied to my requests.

[asvetlov]

I'm sorry, Victor.

[vstinner]

I'm sorry, Victor.

As a maintainer of the Python CIs, The Night's Watch (*), it's my fault that I didn't skip these tests earlier. Honestly, it's ok to skip a bunch of tests or even remove them if there is no active maintainer.

It's also ok that there is no active maintainer if existing tests continue to pass. asyncio is far from being an exception. Just look at test_nntplib: not maintained for 9 years, https://bugs.python.org/issue40735

This test failure got more attention since it started to fail even more frequently (always?) on Windows 2022.

(*) https://pythondev.readthedocs.io/ci.html#the-night-s-watch-is-fixing-the-cis-in-the-darkness-for-you

[tasty0tomato]

I built 3.11.5 on my own Windows computer, and found it passed this test on one computer, but didn't pass on another computer. I think that this issue may not be fixed completely, or I can provide needed information of the computer which this test didn't pass to find out the reason why it didn't pass.

[vstinner]

This issue is closed, please open a new issue.