homepage

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.

http://buildbot.python.org/all/builders/AMD64%20FreeBSD%20CURRENT%20Non-Debug%203.x/builds/541 

I failed to reproduce the issue by running test_logging in a loop on Koobs's FreeBSD CURRENT.

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

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

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

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

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

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

I opened bpo-31233: socketserver.ThreadingMixIn leaks running threads after server_close().

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

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

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.

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

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.