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
pablogsal commentedon Jun 3, 2021
How did you managed? I ran test_asyncio for almost 5 hours with -R in my linux machine and could not reproduce?
pablogsal commentedon Jun 3, 2021
Extending the bot time was done so we can use faulthandler to identify the test, because buildbot was cancelling the whole build before that :)
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) ...