test_logging leaks dangling threads on FreeBSD

[vstinner]

BPO	30830
Nosy	@vstinner, @koobs
PRs	bpo-30830: test_logging: don't use daemon threads #3135 bpo-30830: test_logging uses threading_setup/cleanup #3137 bpo-31233: socketserver.ThreadingMixIn.server_close() #3523 bpo-30830: logging.config.listen() calls server_close() #3524

^{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 2017-09-13.09:36:22.242>
created_at = <Date 2017-07-03.08:09:05.694>
labels = ['3.7', 'tests', 'performance']
title = 'test_logging leaks dangling threads on FreeBSD'
updated_at = <Date 2017-09-13.09:36:22.240>
user = 'https://github.com/vstinner'

bugs.python.org fields:

activity = <Date 2017-09-13.09:36:22.240>
actor = 'vstinner'
assignee = 'none'
closed = True
closed_date = <Date 2017-09-13.09:36:22.242>
closer = 'vstinner'
components = ['Tests']
creation = <Date 2017-07-03.08:09:05.694>
creator = 'vstinner'
dependencies = []
files = []
hgrepos = []
issue_num = 30830
keywords = ['patch', 'buildbot']
message_count = 15.0
messages = ['297540', '297541', '297574', '298521', '299838', '300108', '300336', '300513', '300516', '300522', '300537', '300538', '302023', '302035', '302041']
nosy_count = 2.0
nosy_names = ['vstinner', 'koobs']
pr_nums = ['3135', '3137', '3523', '3524']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'resource usage'
url = 'https://bugs.python.org/issue30830'
versions = ['Python 3.7']

[vstinner]

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.

[vstinner]

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

[vstinner]

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

[vstinner]

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

[vstinner]

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

[vstinner]

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

[vstinner]

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

[vstinner]

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