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

[vstinner]

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]

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]

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]

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]

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]

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

[vstinner]

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

[vstinner]

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]

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]

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