Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

test_logging: test_race_between_set_target_and_flush() leaks threads (threading_cleanup() failed to cleanup ...) #85905

Closed
vstinner opened this issue Sep 7, 2020 · 12 comments
Closed

test_logging: test_race_between_set_target_and_flush() leaks threads (threading_cleanup() failed to cleanup ...) #85905

vstinner opened this issue Sep 7, 2020 · 12 comments
Labels
3.10 only security fixes tests Tests in the Lib/test dir

Comments

@vstinner
Copy link
Member

vstinner commented Sep 7, 2020

BPO 41739
Nosy @vsajip, @vstinner, @corona10, @miss-islington, @shihai1991
PRs
  • bpo-41739: Fix test_logging.test_race_between_set_target_and_flush() #22655
  • [3.9] bpo-41739: Fix test_logging.test_race_between_set_target_and_flush() (GH-22655) #22656
  • [3.8] bpo-41739: Fix test_logging.test_race_between_set_target_and_flush() (GH-22655) (GH-22656) #22662
    		•

    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 2020-10-12.08:55:44.086>
created_at = <Date 2020-09-07.15:46:06.034>
labels = ['tests', '3.10']
title = 'test_logging: test_race_between_set_target_and_flush() leaks threads (threading_cleanup() failed to cleanup ...)'
updated_at = <Date 2020-10-12.08:55:44.084>
user = 'https://github.com/vstinner'

    bugs.python.org fields:

    activity = <Date 2020-10-12.08:55:44.084>
actor = 'vstinner'
assignee = 'none'
closed = True
closed_date = <Date 2020-10-12.08:55:44.086>
closer = 'vstinner'
components = ['Tests']
creation = <Date 2020-09-07.15:46:06.034>
creator = 'vstinner'
dependencies = []
files = []
hgrepos = []
issue_num = 41739
keywords = ['patch']
message_count = 12.0
messages = ['376509', '376510', '376961', '377311', '377312', '377315', '378458', '378459', '378465', '378469', '378477', '378478']
nosy_count = 5.0
nosy_names = ['vinay.sajip', 'vstinner', 'corona10', 'miss-islington', 'shihai1991']
pr_nums = ['22655', '22656', '22662']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue41739'
versions = ['Python 3.10']
    @vstinner
    Copy link
    Member Author

    vstinner commented Sep 7, 2020

    s390x RHEL8 LTO + PGO 3.x:
    https://buildbot.python.org/all/#/builders/442/builds/399

    0:01:43 load avg: 4.23 [229/423/1] test_logging failed (env changed) -- running: test_concurrent_futures (48.1 sec)
    Warning -- threading_cleanup() failed to cleanup 1 threads (count: 1, dangling: 2)
    Warning -- Dangling thread: <Thread(Thread-4, started daemon 4395811469584)>
    Warning -- Dangling thread: <_MainThread(MainThread, started 4395867015984)>

    @vstinner vstinner added 3.10 only security fixes tests Tests in the Lib/test dir labels Sep 7, 2020
    @vstinner
    Copy link
    Member Author

    vstinner commented Sep 7, 2020

    Same isuse on s390x RHEL7 LTO + PGO 3.x:
    https://buildbot.python.org/all/#/builders/244/builds/45

    Warning -- threading_cleanup() failed to cleanup 1 threads (count: 1, dangling: 2)
    Warning -- Dangling thread: <_MainThread(MainThread, started 4396860012288)>
    Warning -- Dangling thread: <Thread(Thread-4, started daemon 4396701710608)>

    @vstinner
    Copy link
    Member Author

    s390x Debian 3.x:
    https://buildbot.python.org/all/#/builders/49/builds/75

    Warning -- threading_cleanup() failed to cleanup 1 threads (count: 1, dangling: 2)
    Warning -- Dangling thread: <_MainThread(MainThread, started 4396138073968)>
    Warning -- Dangling thread: <Thread(Thread-3, started daemon 4396088817936)>

    @vstinner
    Copy link
    Member Author

    Previous issues:

    • bpo-30131: "test_logging now joins queue threads"
    • bpo-30830: test_logging uses threading_setup/cleanup, logging.config.listen() calls server_close(), socketserver.ThreadingMixIn.server_close()
    • bpo-31235: Fix ResourceWarning in test_logging

    @vstinner
    Copy link
    Member Author

    See also https://pythondev.readthedocs.io/unstable_tests.html

    @vstinner
    Copy link
    Member Author

    I created bpo-41833 "threading.Thread: use target name if the name parameter is omitted" to help me to debug this issue.

    @vstinner
    Copy link
    Member Author

    Cool, my threading change works as expected! The name of the target function was logged.

    https://buildbot.python.org/all/#/builders/509/builds/172

    0:00:28 load avg: 3.58 [ 36/424/1] test_logging failed (env changed)
    Warning -- threading_cleanup() failed to cleanup 2 threads (count: 2, dangling: 3)
    Warning -- Dangling thread: <Thread(Thread-4 (removeTarget), started daemon 4396862667024)>
    Warning -- Dangling thread: <Thread(Thread-11 (removeTarget), started daemon 4396595259664)>
    Warning -- Dangling thread: <_MainThread(MainThread, started 4396920310576)>

    So leaked threads are running removeTarget() which come from MemoryHandlerTest.test_race_between_set_target_and_flush().

    @vstinner vstinner changed the title test_logging: threading_cleanup() failed to cleanup 1 threads (count: 1, dangling: 2) test_logging: test_race_between_set_target_and_flush() leaks threads (threading_cleanup() failed to cleanup ...) Oct 11, 2020
    @vstinner vstinner changed the title test_logging: threading_cleanup() failed to cleanup 1 threads (count: 1, dangling: 2) test_logging: test_race_between_set_target_and_flush() leaks threads (threading_cleanup() failed to cleanup ...) Oct 11, 2020
    @vstinner
    Copy link
    Member Author

    I'm able to reproduce the issue if I reduce the sleep:

    diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py
index 4cd8c7e25d..fc395dc473 100644
--- a/Lib/test/test_logging.py
+++ b/Lib/test/test_logging.py
@@ -1177,7 +1177,7 @@ class MemoryHandlerTest(BaseTest):
         self.mem_hdlr.setTarget(target)
 
         for _ in range(10):
-            time.sleep(0.005)
+            time.sleep(1e-9)
             self.mem_logger.info("not flushed")
             self.mem_logger.warning("flushed")

    With the command:

    $ ./python -m test test_logging -m test_race_between_set_target_and_flush -F -j10 --fail-env-changed 
(...)
0:00:03 load avg: 3.74 [ 18/1] test_logging failed (env changed)
Warning -- threading_cleanup() failed to cleanup 1 threads (count: 1, dangling: 2)
Warning -- Dangling thread: <Thread(Thread-1 (removeTarget), started daemon 139860955428608)>
Warning -- Dangling thread: <_MainThread(MainThread, started 139861194377024)>

    @vstinner
    Copy link
    Member Author

    New changeset 13ff396 by Victor Stinner in branch 'master':
    bpo-41739: Fix test_logging.test_race_between_set_target_and_flush() (GH-22655)
    13ff396

    @vsajip
    Copy link
    Member

    vsajip commented Oct 12, 2020

    New changeset f5393dc by Victor Stinner in branch '3.9':
    bpo-41739: Fix test_logging.test_race_between_set_target_and_flush() (GH-22655) (GH-22656)
    f5393dc

    @vstinner
    Copy link
    Member Author

    New changeset 33057c7 by Miss Skeleton (bot) in branch '3.8':
    bpo-41739: Fix test_logging.test_race_between_set_target_and_flush() (GH-22655) (GH-22656) (GH-22662)
    33057c7

    @vstinner
    Copy link
    Member Author

    Ok, test_race_between_set_target_and_flush() should no longer leak dangling threads. I close the issue.

    @ezio-melotti ezio-melotti transferred this issue from another repository Apr 10, 2022
    Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
    Assignees
    No one assigned
    Labels
    3.10 only security fixes tests Tests in the Lib/test dir
    Projects
    None yet
    Milestone
    No milestone
    Development

    No branches or pull requests
    2 participants
    @vsajip @vstinner