Repository navigation
[buildbot] test_asyncio hangs (killed after 3 hours) on Refleak buildbots #88278
Description
| BPO | 44112 |
|---|---|
| Nosy | @vstinner, @asvetlov, @cjerdonek, @1st1, @pablogsal, @erlend-aasland, @shreyanavigyan |
| Superseder | |
| Files |
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 2021-06-04.22:52:58.389>
created_at = <Date 2021-05-12.09:40:34.127>
labels = ['3.11', 'tests', '3.10', 'expert-asyncio']
title = '[buildbot] test_asyncio hangs (killed after 3 hours) on Refleak buildbots'
updated_at = <Date 2021-06-09.21:25:27.860>
user = 'https://github.com/vstinner'bugs.python.org fields:
activity = <Date 2021-06-09.21:25:27.860>
actor = 'vstinner'
assignee = 'none'
closed = True
closed_date = <Date 2021-06-04.22:52:58.389>
closer = 'vstinner'
components = ['Tests', 'asyncio']
creation = <Date 2021-05-12.09:40:34.127>
creator = 'vstinner'
dependencies = []
files = ['50092']
hgrepos = []
issue_num = 44112
keywords = []
message_count = 19.0
messages = ['393491', '393492', '393493', '394923', '395035', '395036', '395037', '395041', '395042', '395048', '395068', '395070', '395091', '395093', '395094', '395095', '395101', '395135', '395480']
nosy_count = 7.0
nosy_names = ['vstinner', 'asvetlov', 'chris.jerdonek', 'yselivanov', 'pablogsal', 'erlendaasland', 'shreyanavigyan']
pr_nums = []
priority = 'normal'
resolution = 'duplicate'
stage = 'resolved'
status = 'closed'
superseder = '38323'
type = None
url = 'https://bugs.python.org/issue44112'
versions = ['Python 3.10', 'Python 3.11']
Activity
vstinner commentedon May 12, 2021
Buildbot kills the "test" step because it takes longer than 3 hours, whereas Python regrtest gets a timeout of 3 hour 15 min.
Refleak buildbots should get a longer timeout for the "test" step.
PPC64LE Fedora Rawhide Refleaks 3.10:
https://buildbot.python.org/all/#/builders/603/builds/7
./python ./Tools/scripts/run_tests.py -j 1 -u all -W --slowest --fail-env-changed --timeout=11700 -R 3:3 -u-cpu -j10
WARNING: Disable --verbose3 because it's incompatible with --huntrleaks: see http://bugs.python.org/issue27103
== CPython 3.10.0b1+ (heads/3.10:9a0e65c8e0, May 10 2021, 00:01:01) [GCC 11.1.1 20210428 (Red Hat 11.1.1-1)]
== Linux-5.7.0-0.rc0.git2.1.fc33.ppc64le-ppc64le-with-glibc2.33.9000 little-endian
== cwd: /home/buildbot/buildarea/3.10.cstratak-fedora-rawhide-ppc64le.refleak/build/build/test_python_1529753æ
== CPU count: 8
== encodings: locale=UTF-8, FS=utf-8
Using random seed 1661030
0:00:00 load avg: 3.25 Run tests in parallel using 10 child processes (timeout: 3 hour 15 min, worker timeout: 3 hour 20 min)
0:00:00 load avg: 3.25 [ 1/427] test_tix skipped (resource denied)
(...)
2:58:49 load avg: 0.00 running: test_asyncio (2 hour 58 min)
2:59:19 load avg: 0.00 running: test_asyncio (2 hour 58 min)
2:59:49 load avg: 0.00 running: test_asyncio (2 hour 59 min)
command timed out: 10800 seconds elapsed running [b'make', b'buildbottest', b'TESTOPTS=-R 3:3 -u-cpu -j10 ${BUILDBOT_TESTOPTS}', b'TESTPYTHONOPTS=', b'TESTTIMEOUT=11700'], attempting to kill
vstinner commentedon May 12, 2021
It seems to be a real bug in test_asyncio, since in other builds on the same buildbot worker, test_asyncio takes less than 30 minutes:
vstinner commentedon May 12, 2021
I bet that the hang is a duplicate of the old bpo-38323 "asyncio: MultiLoopWatcher has a race condition (test_asyncio: test_close_kill_running() hangs on AMD64 RHEL7 Refleaks 3.x)" that I reported 2 years ago and is not fixed yet.
[-][buildbot] test_asyncio hangs after 3 hours on Refleak buildbots[/-][+][buildbot] test_asyncio hangs (killed after 3 hours) on Refleak buildbots[/+][-][buildbot] test_asyncio hangs after 3 hours on Refleak buildbots[/-][+][buildbot] test_asyncio hangs (killed after 3 hours) on Refleak buildbots[/+]vstinner commentedon Jun 2, 2021
I changed buildbot Test step timeout from 3 hours to 4 hours:
shreyanavigyan commentedon Jun 3, 2021
Victor, this issue is reproducible on Linux. I reproduced it on my WSL. And I've identified the issue is in test_close_kill_running. The patch for resolving the crash in bpo-38323 can be the cause of the newly introduced hang. test_close_kill_running is running and passing and again it is running all over again infinitely. And extending the buildbot timer may not help since it seems it's running infinitely. Even if we look at the buildbot log there is no sign of crash but suddenly buildbot says "timeout!".
2 remaining items
shreyanavigyan commentedon Jun 3, 2021
Now it's not again not reproducing. Maybe I used some wrong flag. But I'll try to debug this issue.
shreyanavigyan commentedon Jun 3, 2021
I've also been trying to debug it for the whole day. Not sure what's causing this. (Why does all error occur in Fedora buildbots? If I remember correctly, another test also failed there.")
pablogsal commentedon Jun 3, 2021
Also, how did you reached this conclusion?
shreyanavigyan commentedon Jun 4, 2021
The test result I got kind of seemed that the problem was in test_close_kill_running but it maybe that I used wrong flag (maybe -F?). And it is also weird that the error is occurring only in Fedora buildbot and not on others. Also the logs are not showing which test it was executing when the timeout occured.
shreyanavigyan commentedon Jun 4, 2021
I ran the test_suite on commit f3fa63e in my WSL 1 Ubuntu and got some unexpected results. There are huge reference leaks in the tests and test_asyncio, test_subprocess, test_socket, etc., failed. I forked the branch a while ago so the HEAD is on f3fa63e. Don't know if these are fixed already but reported them here since there were no commits for any issue based on test_asyncio, test_subprocess recently. And most surprisingly I got a timeout error also but it was for "2:03:30 load avg: 0.52 running: test_ssl (1 hour 54 min), test_largefile (1 hour 18 min), test_io (1 hour 30 min)". I attached the log for full details. (I use WSL 1 so note it's written ./python.exe instead of ./python)
vstinner commentedon Jun 4, 2021
Pablo:
Right. I increased buildbot timeout to check if buildbots hang because of bpo-38323 or if it's a new regression.
bpo-38323 is not fixed yet, I can still easily reproduce the hang on Linux is less than 1 minute:
https://bugs.python.org/issue38323#msg395090
shreyanavigyan commentedon Jun 4, 2021
Yes, with the commands you provided in the https://bugs.python.org/issue38323#msg395090 I also reproduced the crash on my WSL. And any suggestions on the other test failures in the log I attached? I don't know if they are fixed already in the latest commits though.
pablogsal commentedon Jun 4, 2021
Your logs don't show this error. This error is test_asyncio hanging, but in your logs the test fails (multiple test do, actually).
shreyanavigyan commentedon Jun 4, 2021
I didn't include this error. I was just asking if we could do anything about the multiple test failures (especially test_asyncio failure).
pablogsal commentedon Jun 4, 2021
We don't see any failures as the ones in your logs in the buildbots or otherwise, so seems something wrong in your system or only affecting your system.
Sorry Shreyan, but unfortunately I find your messages very confusing. You seem to be mixing several different problems and your logs don't seem to be directly related to the issue at hand. Please, in the future, add some context to your messages if possible.
vstinner commentedon Jun 4, 2021
I bet that this issue is simply a duplicate of bpo-38323, since I can still (easily) reproduce it locally.
I fixed the buildbot configuration, so if the bug happens again on Refleak buildbots, at least we should know which test method hangs. If it's not bpo-38323, I suggest to open a new more specific issue about this test method.
vstinner commentedon Jun 9, 2021
aarch64 Fedora Rawhide Refleaks 3.8:
https://buildbot.python.org/all/#/builders/401/builds/47
This change worked as expected: buildbot now uses a timeout of 4 hours (14400 seconds).
At the first run, test_asyncio was blocked in test_close_kill_running() of test_asyncio/test_subprocess.py. From the traceback, it's not possible to be sure that the test uses MultiLoopChildWatcher. But it smells a lot like bpo-38323.
bpo-38323 was recently fixed in 3.9, 3.10 and main branches (by skipping MultiLoopChildWatcher tets, since this class has a known race condition). Sadly, the 3.8 branch no longer accepts bugfixes.
Logs:
0:00:00 load avg: 2.85 Run tests in parallel using 10 child processes (timeout: 3 hour 15 min, worker timeout: 3 hour 20 min)
(...)
3:21:15 load avg: 0.04 [423/423/1] test_asyncio crashed (Exit code 1)
beginning 6 repetitions
123456
.....Timeout (3:15:00)!
Thread 0x0000ffffaecbcd50 (most recent call first):
File "/home/buildbot/buildarea/3.8.cstratak-fedora-rawhide-aarch64.refleak/build/Lib/selectors.py", line 468 in select
File "/home/buildbot/buildarea/3.8.cstratak-fedora-rawhide-aarch64.refleak/build/Lib/asyncio/base_events.py", line 1823 in _run_once
File "/home/buildbot/buildarea/3.8.cstratak-fedora-rawhide-aarch64.refleak/build/Lib/asyncio/base_events.py", line 570 in run_forever
File "/home/buildbot/buildarea/3.8.cstratak-fedora-rawhide-aarch64.refleak/build/Lib/asyncio/base_events.py", line 603 in run_until_complete
File "/home/buildbot/buildarea/3.8.cstratak-fedora-rawhide-aarch64.refleak/build/Lib/test/test_asyncio/test_subprocess.py", line 484 in test_close_kill_running
(...)
test_ensure_future_task (test.test_asyncio.test_tasks.PyTask_CFuture_Tests) ... ok
test_error_in_call_soon (test.test_asyncio.test_tasks.PyTask_CFuture_Tests) ... ok
test_exception_traceback (test.test_asyncio.test_tasks.PyTask_CFuture_Tests) ... ok
test_gather_shield (test.test_asyncio.test_tasks.PyTask_CFuture_Tests) ... ok
test_get_coro (test.test_asyncio.test_tasks.PyTask_CFuture_Tests) ... ok
test_get_stack (test.test_asyncio.test_tasks.PyTask_CFuture_Tests) ... ok
test_iscoroutinefunction (test.test_asyncio.test_tasks.PyTask_CFuture_Tests) ... ok
command timed out: 14400 seconds elapsed running [b'make', b'buildbottest', b'TESTOPTS=-R 3:3 -u-cpu -j10 ${BUILDBOT_TESTOPTS}', b'TESTPYTHONOPTS=', b'TESTTIMEOUT=11700'], attempting to kill
.....make: *** [Makefile:1173: buildbottest] Terminated
process killed by signal 15
program finished with exit code -1
elapsedTime=14400.032773
test_log_destroyed_pending_task (test.test_asyncio.test_tasks.PyTask_CFuture_Tests) ...