classification
Title: test_logging leaks dangling threads on FreeBSD
Type: resource usage Stage: resolved
Components: Tests Versions: Python 3.7
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: haypo, koobs
Priority: normal Keywords: buildbot, patch

Created on 2017-07-03 08:09 by haypo, last changed 2017-09-13 09:36 by haypo. This issue is now closed.

Pull Requests
URL Status Linked Edit
PR 3135 closed haypo, 2017-08-18 14:59
PR 3137 merged haypo, 2017-08-18 16:54
PR 3523 merged haypo, 2017-09-13 00:32
PR 3524 merged haypo, 2017-09-13 01:12
Messages (15)
msg297540 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-07-03 08:09
test_output (test.test_logging.HTTPHandlerTest) ... ok
Warning -- threading_cleanup() failed to cleanup -1 threads after 3 sec (count: 0, dangling: 1)

See also the previous test_logging threads issue, bpo-30131.
msg297541 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-07-03 08:10
http://buildbot.python.org/all/builders/AMD64%20FreeBSD%20CURRENT%20Non-Debug%203.x/builds/541
msg297574 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-07-03 13:05
I failed to reproduce the issue by running test_logging in a loop on Koobs's FreeBSD CURRENT.
msg298521 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-07-17 14:06
http://buildbot.python.org/all/builders/AMD64%20FreeBSD%2010.x%20Shared%203.x/builds/587/steps/test/logs/stdio

test_listen_config_10_ok (test.test_logging.ConfigDictTest) ... Warning -- threading_cleanup() failed to cleanup -1 threads after 3 sec (count: 0, dangling: 1)
ok

1 test altered the execution environment:
    test_logging

Tests result: ENV CHANGED
msg299838 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-08-07 09:56
Another test_listen_config_10_ok() example:

http://buildbot.python.org/all/builders/AMD64%20FreeBSD%2010.x%20Shared%203.x/builds/674/steps/test/logs/stdio

test_config_8a_ok (test.test_logging.ConfigDictTest) ... ok
test_config_9_ok (test.test_logging.ConfigDictTest) ... ok
test_listen_config_10_ok (test.test_logging.ConfigDictTest) ... Warning -- threading_cleanup() failed to cleanup -1 threads after 2 sec (count: 0, dangling: 1)
ok
test_listen_config_1_ok (test.test_logging.ConfigDictTest) ... ok
test_listen_verify (test.test_logging.ConfigDictTest) ... ok
test_out_of_order (test.test_logging.ConfigDictTest) ... ok
test_manager_loggerclass (test.test_logging.ManagerTest) ... ok
msg300108 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-08-10 15:44
bpo-31041 has been marked as a duplicate of this issue. Extracts:

test_handle_called_with_mp_queue (test.test_logging.QueueListenerTest) ...
Warning -- threading_cleanup() failed to cleanup -1 threads after 4 sec (count: 0, dangling: 1)

and

test_handle_called_with_mp_queue (test.test_logging.QueueListenerTest) ...
Warning -- threading_cleanup() failed to cleanup -1 threads after 3 sec (count: 0, dangling: 1)

--

"Maybe threading_cleanup() should call support.gc_collect()."
msg300336 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-08-16 08:47
http://buildbot.python.org/all/builders/AMD64%20FreeBSD%2010.x%20Shared%203.x/builds/698/steps/test/logs/stdio

test_output (test.test_logging.UnixDatagramHandlerTest) ... ok
test_output (test.test_logging.UnixSysLogHandlerTest) ... ok
test__all__ (test.test_logging.MiscTestCase) ... ok
test_handle_called_with_mp_queue (test.test_logging.QueueListenerTest) ... Warning -- threading_cleanup() failed to cleanup -1 threads after 3 sec (count: 0, dangling: 1)
ok
test_handle_called_with_queue_queue (test.test_logging.QueueListenerTest) ... ok
test_no_messages_in_queue_after_stop (test.test_logging.QueueListenerTest) ... ok
msg300513 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-08-18 16:22
The problem is that socketserver.ThreadingMixIn spawns threads without waiting for their completion in server_close(). For example, the following two tests use socketserver.ThreadingMixIn and so can leak a running thread:

* test.test_logging.SocketHandlerTest.test_output()
* test.test_logging.DatagramHandlerTest.test_output()

Example:

10-STABLE-amd64% ./python -m test -v test_logging --fail-env-changed -F -m test.test_logging.DatagramHandlerTest.test_output -m test.test_logging.ConfigDictTest.test_listen_config_10_ok  --match=test.test_logging.SocketHandlerTest.test_output

(...)

0:00:09 load avg: 2.54 [  7] test_logging
test_output (test.test_logging.SocketHandlerTest) ... ok
test_output (test.test_logging.DatagramHandlerTest) ... ok
test_listen_config_10_ok (test.test_logging.ConfigDictTest) ... threading_setup (1, <_weakrefset.WeakSet object at 0x806243398>)
msg300516 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-08-18 16:42
> Example:
>
> 10-STABLE-amd64% ./python -m test -v test_logging --fail-env-changed -F -m test.test_logging.DatagramHandlerTest.test_output -m test.test_logging.ConfigDictTest.test_listen_config_10_ok  --match=test.test_logging.SocketHandlerTest.test_output

Oh, I forgot to mention that I also run "./python -m test -j4" in a different terminal in parallel to make the bug more likely.
msg300522 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-08-18 17:29
I opened bpo-31233: socketserver.ThreadingMixIn leaks running threads after server_close().
msg300537 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-08-18 21:47
New changeset 6966960468327c958b03391f71f24986bd697307 by Victor Stinner in branch 'master':
bpo-30830: test_logging uses threading_setup/cleanup (#3137)
https://github.com/python/cpython/commit/6966960468327c958b03391f71f24986bd697307
msg300538 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-08-18 21:49
> New changeset 6966960468327c958b03391f71f24986bd697307 by Victor Stinner in branch 'master':
> bpo-30830: test_logging uses threading_setup/cleanup (#3137)

With this commit, test_logging should detect better bugs in the code.

The commit also skips all tests using socketserver, until bpo-31233 is fixed, just to reduce the failure rate on the FreeBSD buildbots.

This issue (bpo-30830) made FreeBSD 10 buildbot very unstable.
msg302023 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-09-13 01:13
While testing PR 3138 (stricter threading_cleanup) with PR 3523 (socketserver joins threads), I got the following warning:

test_listen_config_1_ok (test.test_logging.ConfigDictTest) ... Warning -- threading_cleanup() detected 1 leaked threads (count: 1, dangling: 2)
ok

Attached PR 3524 should fix this warning, once combined with PR 3523.
msg302035 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-09-13 08:44
New changeset 97d7e65dfed1d42d40d9bc2f630af56240555f02 by Victor Stinner in branch 'master':
bpo-30830: logging.config.listen() calls server_close() (#3524)
https://github.com/python/cpython/commit/97d7e65dfed1d42d40d9bc2f630af56240555f02
msg302041 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-09-13 09:36
Ok, the main bugs have been fixed by the following socketserver fix.

commit b8f4163da30e16c7cd58fe04f4b17e38d53cd57e
Author: Victor Stinner <victor.stinner@gmail.com>
Date:   Wed Sep 13 01:47:22 2017 -0700

    bpo-31233: socketserver.ThreadingMixIn.server_close() (#3523)
    
    socketserver.ThreadingMixIn now keeps a list of non-daemonic threads
    to wait until all these threads complete in server_close().
    
    Reenable test_logging skipped tests.
    
    Fix SocketHandlerTest.tearDown(): close the socket handler before
    stopping the server, so the server can join threads.

I'm not sure that it's possible to fix the bug in Python 3.6 without breaking the backward compatibility.

test_logging shouldn't fail with the threading_cleanup() warning anymore.
History
Date User Action Args
2017-09-13 09:36:22hayposetstatus: open -> closed
messages: + msg302041

dependencies: - socketserver.ThreadingMixIn leaks running threads after server_close()
resolution: fixed
stage: patch review -> resolved
2017-09-13 08:44:14hayposetmessages: + msg302035
2017-09-13 01:13:36hayposetmessages: + msg302023
2017-09-13 01:12:27hayposetpull_requests: + pull_request3523
2017-09-13 00:32:23hayposetkeywords: + patch
stage: patch review
pull_requests: + pull_request3522
2017-08-18 21:49:32hayposetmessages: + msg300538
2017-08-18 21:47:56hayposetmessages: + msg300537
2017-08-18 17:29:29hayposetdependencies: + socketserver.ThreadingMixIn leaks running threads after server_close()
messages: + msg300522
2017-08-18 16:54:54hayposetpull_requests: + pull_request3171
2017-08-18 16:42:03hayposetmessages: + msg300516
2017-08-18 16:22:34hayposetmessages: + msg300513
2017-08-18 14:59:53hayposetpull_requests: + pull_request3170
2017-08-16 08:47:35hayposetmessages: + msg300336
2017-08-11 00:01:38hayposettitle: test_logging leaks a "dangling" threads on FreeBSD -> test_logging leaks dangling threads on FreeBSD
2017-08-10 15:44:34hayposetmessages: + msg300108
2017-08-10 15:43:31haypolinkissue31041 superseder
2017-08-10 15:43:02hayposettitle: HTTPHandlerTest of test_logging leaks a "dangling" thread on AMD64 FreeBSD CURRENT Non-Debug 3.x -> test_logging leaks a "dangling" threads on FreeBSD
2017-08-07 09:56:58hayposetmessages: + msg299838
2017-07-17 14:06:53hayposetmessages: + msg298521
2017-07-03 13:05:12hayposetmessages: + msg297574
2017-07-03 08:10:55hayposettitle: HTTPHandlerTest of test_logging leaks a "dangling" thread on FreeBSD CURRENT -> HTTPHandlerTest of test_logging leaks a "dangling" thread on AMD64 FreeBSD CURRENT Non-Debug 3.x
2017-07-03 08:10:46hayposettitle: HTTPHandlerTest of test_logging leaks a "dangling" thread -> HTTPHandlerTest of test_logging leaks a "dangling" thread on FreeBSD CURRENT
2017-07-03 08:10:40hayposetmessages: + msg297541
2017-07-03 08:09:05haypocreate