Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

test_logging leaks dangling threads on FreeBSD #75013

Closed
vstinner opened this issue Jul 3, 2017 · 15 comments
Closed

test_logging leaks dangling threads on FreeBSD #75013

vstinner opened this issue Jul 3, 2017 · 15 comments
Labels
3.7 (EOL) end of life performance Performance or resource usage tests Tests in the Lib/test dir

Comments

@vstinner
Copy link
Member

vstinner commented Jul 3, 2017

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
    Copy link
    Member Author

    vstinner commented Jul 3, 2017

    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 vstinner added 3.7 (EOL) end of life tests Tests in the Lib/test dir performance Performance or resource usage labels Jul 3, 2017
    @vstinner
    Copy link
    Member Author

    vstinner commented Jul 3, 2017

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

    @vstinner vstinner changed the title HTTPHandlerTest of test_logging leaks a "dangling" thread HTTPHandlerTest of test_logging leaks a "dangling" thread on FreeBSD CURRENT Jul 3, 2017
    @vstinner vstinner changed the title 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 Jul 3, 2017
    @vstinner
    Copy link
    Member Author

    vstinner commented Jul 3, 2017

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

    @vstinner
    Copy link
    Member Author

    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
    Copy link
    Member Author

    vstinner commented Aug 7, 2017

    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 vstinner changed the title HTTPHandlerTest of test_logging leaks a "dangling" thread on AMD64 FreeBSD CURRENT Non-Debug 3.x test_logging leaks a "dangling" threads on FreeBSD Aug 10, 2017
    @vstinner
    Copy link
    Member Author

    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 vstinner changed the title test_logging leaks a "dangling" threads on FreeBSD test_logging leaks dangling threads on FreeBSD Aug 11, 2017
    @vstinner
    Copy link
    Member Author

    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
    Copy link
    Member Author

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

    @vstinner
    Copy link
    Member Author

    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.

    @vstinner
    Copy link
    Member Author

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

    @vstinner
    Copy link
    Member Author

    New changeset 6966960 by Victor Stinner in branch 'master':
    bpo-30830: test_logging uses threading_setup/cleanup (bpo-3137)
    6966960

    @vstinner
    Copy link
    Member Author

    New changeset 6966960 by Victor Stinner in branch 'master':
    bpo-30830: test_logging uses threading_setup/cleanup (bpo-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.

    @vstinner
    Copy link
    Member Author

    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.

    @vstinner
    Copy link
    Member Author

    New changeset 97d7e65 by Victor Stinner in branch 'master':
    bpo-30830: logging.config.listen() calls server_close() (bpo-3524)
    97d7e65

    @vstinner
    Copy link
    Member Author

    Ok, the main bugs have been fixed by the following socketserver fix.

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

    bpo-31233: socketserver.ThreadingMixIn.server_close() (bpo-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.

    @ezio-melotti ezio-melotti transferred this issue from another repository Apr 10, 2022
    Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
    Assignees
    No one assigned
    Labels
    3.7 (EOL) end of life performance Performance or resource usage tests Tests in the Lib/test dir
    Projects
    None yet
    Milestone
    No milestone
    Development

    No branches or pull requests
    1 participant
    @vstinner