classification
Title: test_logging: test_race_between_set_target_and_flush() leaks threads (threading_cleanup() failed to cleanup ...)
Type: Stage: resolved
Components: Tests Versions: Python 3.10
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: corona10, miss-islington, shihai1991, vinay.sajip, vstinner
Priority: normal Keywords: patch

Created on 2020-09-07 15:46 by vstinner, last changed 2020-10-12 08:55 by vstinner. This issue is now closed.

Pull Requests
URL Status Linked Edit
PR 22655 merged vstinner, 2020-10-11 22:14
PR 22656 merged vstinner, 2020-10-11 22:38
PR 22662 merged miss-islington, 2020-10-12 04:31
Messages (12)
msg376509 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2020-09-07 15:46
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)>
msg376510 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2020-09-07 15:47
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)>
msg376961 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2020-09-15 22:45
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)>
msg377311 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2020-09-22 11:32
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
msg377312 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2020-09-22 11:32
See also https://pythondev.readthedocs.io/unstable_tests.html
msg377315 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2020-09-22 11:56
I created bpo-41833 "threading.Thread: use target name if the name parameter is omitted" to help me to debug this issue.
msg378458 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2020-10-11 22:01
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().
msg378459 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2020-10-11 22:05
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)>
msg378465 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2020-10-11 22:37
New changeset 13ff396c019d548ba181cf22c6f39309a300723c by Victor Stinner in branch 'master':
bpo-41739: Fix test_logging.test_race_between_set_target_and_flush() (GH-22655)
https://github.com/python/cpython/commit/13ff396c019d548ba181cf22c6f39309a300723c
msg378469 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2020-10-12 04:31
New changeset f5393dc2a0ced7bf670ebc56b5fd10a3eb328d1a by Victor Stinner in branch '3.9':
bpo-41739: Fix test_logging.test_race_between_set_target_and_flush() (GH-22655) (GH-22656)
https://github.com/python/cpython/commit/f5393dc2a0ced7bf670ebc56b5fd10a3eb328d1a
msg378477 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2020-10-12 08:51
New changeset 33057c70920787627f2c94d08eb5d33c31f8bdd9 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)
https://github.com/python/cpython/commit/33057c70920787627f2c94d08eb5d33c31f8bdd9
msg378478 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2020-10-12 08:55
Ok, test_race_between_set_target_and_flush() should no longer leak dangling threads. I close the issue.
History
Date User Action Args
2020-10-12 08:55:44vstinnersetstatus: open -> closed
resolution: fixed
messages: + msg378478

stage: patch review -> resolved
2020-10-12 08:51:40vstinnersetmessages: + msg378477
2020-10-12 04:31:05miss-islingtonsetnosy: + miss-islington
pull_requests: + pull_request21638
2020-10-12 04:31:00vinay.sajipsetnosy: + vinay.sajip
messages: + msg378469
2020-10-11 22:38:51vstinnersetpull_requests: + pull_request21632
2020-10-11 22:37:27vstinnersetmessages: + msg378465
2020-10-11 22:14:17vstinnersetkeywords: + patch
stage: patch review
pull_requests: + pull_request21631
2020-10-11 22:05:58vstinnersetmessages: + msg378459
2020-10-11 22:01:17vstinnersetmessages: + msg378458
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 ...)
2020-09-24 14:36:47corona10setnosy: + corona10
2020-09-22 11:56:27vstinnersetmessages: + msg377315
2020-09-22 11:32:43vstinnersetmessages: + msg377312
2020-09-22 11:32:29vstinnersetmessages: + msg377311
2020-09-15 22:45:41vstinnersetmessages: + msg376961
2020-09-07 15:50:03shihai1991setnosy: + shihai1991
2020-09-07 15:47:51vstinnersetmessages: + msg376510
2020-09-07 15:46:06vstinnercreate