test_asyncio.test_subprocess leaked dangling threads on PPC64LE Fedora Stable 3.x:

[vstinner]

The machine was very slow (very busy) when the test failed: load avg: 21.37. Also, I noticed that this buildbot builder is now.

PPC64LE Fedora Stable 3.x:

0:11:53 load avg: 21.37 [383/467/1] test.test_asyncio.test_subprocess failed (env changed) (40.0 sec) -- running (8): test_subprocess (1 min 6 sec), test_capi (47.1 sec), test_math (57.5 sec), test_io (46.4 sec), test.test_gdb.test_cfunction (1 min 3 sec), test_weakref (1 min 17 sec), test_unparse (2 min 11 sec), test.test_asyncio.test_tasks (38.9 sec)

(...)

test_close_kill_running (test.test_asyncio.test_subprocess.SubprocessThreadedWatcherTests.test_close_kill_running) ... ok
test_communicate (test.test_asyncio.test_subprocess.SubprocessThreadedWatcherTests.test_communicate) ... ok
test_communicate_ignore_broken_pipe (test.test_asyncio.test_subprocess.SubprocessThreadedWatcherTests.test_communicate_ignore_broken_pipe) ... ok
test_communicate_none_input (test.test_asyncio.test_subprocess.SubprocessThreadedWatcherTests.test_communicate_none_input) ... ok
test_create_subprocess_env_exec (test.test_asyncio.test_subprocess.SubprocessThreadedWatcherTests.test_create_subprocess_env_exec) ... ok
test_create_subprocess_env_shell (test.test_asyncio.test_subprocess.SubprocessThreadedWatcherTests.test_create_subprocess_env_shell) ... ok
test_create_subprocess_exec_text_mode_fails (test.test_asyncio.test_subprocess.SubprocessThreadedWatcherTests.test_create_subprocess_exec_text_mode_fails) ... ok
test_create_subprocess_exec_with_path (test.test_asyncio.test_subprocess.SubprocessThreadedWatcherTests.test_create_subprocess_exec_with_path) ... ok
test_create_subprocess_shell_text_mode_fails (test.test_asyncio.test_subprocess.SubprocessThreadedWatcherTests.test_create_subprocess_shell_text_mode_fails) ... ok
test_devnull_error (test.test_asyncio.test_subprocess.SubprocessThreadedWatcherTests.test_devnull_error) ... ok
test_devnull_input (test.test_asyncio.test_subprocess.SubprocessThreadedWatcherTests.test_devnull_input) ... Warning -- threading_cleanup() failed to cleanup 1 threads (count: 1, dangling: 2)
Warning -- Dangling thread: <_MainThread(MainThread, started 140735686786240)>
Warning -- Dangling thread: <Thread(waitpid-0, started daemon 140735332413728)>
ok

test_asyncio.test_subprocess passed when re-run in verbose mode.

build: https://buildbot.python.org/all/#/builders/90/builds/3855

Linked PRs

• gh-110205: Fix asyncio ThreadedChildWatcher._join_threads() #110790
• gh-110205: Fix asyncio ThreadedChildWatcher._join_threads() #110884
• [3.12] gh-110205: Fix asyncio ThreadedChildWatcher._join_threads() (GH-110884) #111412
• [3.11] gh-110205: Fix asyncio ThreadedChildWatcher._join_threads() (GH-110884) #111413

[gvanrossum]

Sorry, this is not fixed. The PR attempting to fix it was not merged.

[vstinner]

Sorry, this is not fixed. The PR attempting to fix it was not merged.

I'm not interested to fix this issue anymore. If you consider that it's important issue, you can fix it. I close again the issue and unsubscribe from the issue.

[gvanrossum]

Sorry to the audience for the waffling. Victor doesn't want anything to do with this issue any more. But I will fix it (starting with his PR). So reopening one more time (it's not completed yet.)

[gvanrossum]

Interestingly, this test output quoted above:

Warning -- threading_cleanup() failed to cleanup 1 threads (count: 1, dangling: 2)
Warning -- Dangling thread: <_MainThread(MainThread, started 140735686786240)>
Warning -- Dangling thread: <Thread(waitpid-0, started daemon 140735332413728)>

(which sets the "environment changed" flag, causing CI to fail) still occurs when _join_threads() is fixed to close all threads. The messages are printed from threading_cleanup() in test/support/threading_helper.py. Looking at the code and the output it's clear that it's the waitpid-0 thread that wasn't there before. The PR renames it to asyncio-waitpid-0, and I still see that output here.

It looks like the work to delete references to the watcher's threads is gone to waste because the code in ThreadedChildWatcher._join_threads() only joins (waits for) non-daemon threads, but the child handler thread is a daemon thread. There was a discussion about this very cleanup when the join code was added -- it was proposed to use self._threads.pop(pid) but that was never implemented. The child watcher thread has been a daemon thread since it was introduced by gh-14344, so I'm not sure that the join code ever did what it was supposed to do.

In conclusion, I think there's an old bug (_join_threads() doesn't join daemon threads, but watcher threads are daemon threads), and and a new bug in this PR (close_loop() used to join all threads, but the refactored logic only waits for non-daemon threads).

We need to ask ourselves, why do we sometimes find a dangling waitpid thread? The only reason I can see would be that the process hasn't exited -- then the thread will be hanging in the os.waitpid() call in ThreadedChildWatcher_do_waitpid(). And how can we prevent this situation from happening, or recover from it? IIUC we have no way to kill a thread, so calling join() on the blocked thread won't help (unless the process is about to exit).

IMO _join_threads() is always a no-op, we might as well get rid of it. One could argue that waiting for the watcher's thread in TestCase.close_loop() is the right thing, possibly with a 30s timeout, as long as it includes daemon threads, which are the only threads created by the watcher. The remaining embellishments currently in the PR aren't needed.