Skip to content

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

Closed

Description

@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

Activity

  1. added 4 commits that reference this issue on Oct 13, 2023
  2. moved this from Todo to Done in asyncioon Oct 13, 2023
  3. gvanrossum commented on Oct 13, 2023

    @gvanrossum
    Member

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

  4. moved this from Done to In Progress in asyncioon Oct 13, 2023
  5. vstinner commented on Oct 14, 2023

    @vstinner
    MemberAuthor

    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.

  6. 1 remaining item

  7. gvanrossum commented on Oct 14, 2023

    @gvanrossum
    Member

    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.)

  8. moved this from Done to In Progress in asyncioon Oct 14, 2023
  9. self-assigned this
    on Oct 14, 2023
  10. gvanrossum commented on Oct 15, 2023

    @gvanrossum
    Member

    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.

  11. added a commit that references this issue on Oct 27, 2023
  12. added 2 commits that reference this issue on Oct 27, 2023
  13. added 2 commits that reference this issue on Oct 27, 2023
  14. moved this from In Progress to Done in asyncioon Oct 29, 2023
  15. added a commit that references this issue on Oct 29, 2023
  16. added a commit that references this issue on Feb 11, 2024
  17. added a commit that references this issue on Sep 2, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

Projects

  • Status
    Done

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions