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

logging._removeHandlerRef is not threadsafe during interpreter shutdown #65348

Closed
ssbr mannequin opened this issue Apr 3, 2014 · 10 comments
Closed

logging._removeHandlerRef is not threadsafe during interpreter shutdown #65348

ssbr mannequin opened this issue Apr 3, 2014 · 10 comments
Assignees
Labels
stdlib Python modules in the Lib dir type-bug An unexpected behavior, bug, or error

Comments

@ssbr
Copy link
Mannequin

ssbr mannequin commented Apr 3, 2014

BPO 21149
Nosy @gpshead, @vsajip, @ssbr, @bitdancer, @yilei
PRs
  • [2.7] bpo-21149: Workaround a GC finalization bug in logging. #4368
  • Files
  • patch.diff
  • 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 = 'https://github.com/gpshead'
    closed_at = <Date 2017-11-11.22:50:48.920>
    created_at = <Date 2014-04-03.20:20:57.840>
    labels = ['type-bug', 'library']
    title = 'logging._removeHandlerRef is not threadsafe during interpreter shutdown'
    updated_at = <Date 2017-11-11.22:50:48.920>
    user = 'https://github.com/ssbr'

    bugs.python.org fields:

    activity = <Date 2017-11-11.22:50:48.920>
    actor = 'gregory.p.smith'
    assignee = 'gregory.p.smith'
    closed = True
    closed_date = <Date 2017-11-11.22:50:48.920>
    closer = 'gregory.p.smith'
    components = ['Library (Lib)']
    creation = <Date 2014-04-03.20:20:57.840>
    creator = 'Devin Jeanpierre'
    dependencies = []
    files = ['34718']
    hgrepos = []
    issue_num = 21149
    keywords = ['patch']
    message_count = 10.0
    messages = ['215466', '215479', '215483', '215484', '215507', '215531', '215581', '306056', '306070', '306095']
    nosy_count = 6.0
    nosy_names = ['gregory.p.smith', 'vinay.sajip', 'Devin Jeanpierre', 'r.david.murray', 'python-dev', 'yilei']
    pr_nums = ['4368']
    priority = 'normal'
    resolution = 'fixed'
    stage = 'commit review'
    status = 'closed'
    superseder = None
    type = 'behavior'
    url = 'https://bugs.python.org/issue21149'
    versions = ['Python 2.7']

    @ssbr
    Copy link
    Mannequin Author

    ssbr mannequin commented Apr 3, 2014

    If another thread is active during interpreter shutdown, it can hold the last reference to a handler; when it drops that reference, the weakref callback -- _removeHandlerRef -- will be executed in this other thread. So while this callback is running, the main thread is replacing module globals with None. This creates a data race for the globals in logging -- for example, _releaseLock can be replaced with None after the "_releaseLock is not None" check, but before it is used.

    In principle I suspect this could cause a deadlock, in practice all I've seen are exception messages mentioning how None is not callable.

    I have attached a patch that I think resolves this issue. The patch is written against 2.7, although I expect this issue affects all versions of Python prior to 3.4

    BTW, the copyright for this patch belongs to my employer, Google; please let me know if there are any contributor agreements or such that my employer needs to look at.

    @ssbr ssbr mannequin added the stdlib Python modules in the Lib dir label Apr 3, 2014
    @vsajip
    Copy link
    Member

    vsajip commented Apr 3, 2014

    please let me know if there are any contributor agreements

    Yes, there is a contributor agreement form which needs to be completed and signed:

    https://www.python.org/psf/contrib/contrib-form-python/

    @ssbr
    Copy link
    Mannequin Author

    ssbr mannequin commented Apr 4, 2014

    Are you sure? There should have been many previous contributions by Google, so the relevant copyright agreements _should_ have already been signed.

    I asked internally and was told that a corporate version of this agreement had been signed a long time ago.

    @bitdancer
    Copy link
    Member

    Yes, I remember previous discussions of the corporate agreement from Google, so I'm sure it exists.

    @python-dev
    Copy link
    Mannequin

    python-dev mannequin commented Apr 4, 2014

    New changeset b6deab7204e6 by Vinay Sajip in branch '2.7':
    Issue bpo-21149: Improved thread-safety in logging cleanup during interpreter shutdown.
    http://hg.python.org/cpython/rev/b6deab7204e6

    New changeset b5c91b61991a by Vinay Sajip in branch '3.4':
    Issue bpo-21149: Improved thread-safety in logging cleanup during interpreter shutdown.
    http://hg.python.org/cpython/rev/b5c91b61991a

    New changeset 76689a706900 by Vinay Sajip in branch 'default':
    Closes bpo-21149: Improved thread-safety in logging cleanup during interpreter shutdown.
    http://hg.python.org/cpython/rev/76689a706900

    @python-dev python-dev mannequin closed this as completed Apr 4, 2014
    @ssbr
    Copy link
    Mannequin Author

    ssbr mannequin commented Apr 4, 2014

    Please don't take my word for it, but my understanding is that this issue doesn't apply to 3.4+ since module globals are no longer set to None during interpreter shutdown. (So all the checks against None could even be deleted.)

    @vsajip
    Copy link
    Member

    vsajip commented Apr 5, 2014

    The release notes say about PEP-442 that "As part of this change, module globals are no longer forcibly set to None during interpreter shutdown in most cases". I haven't looked at the PEP in detail, so I'm not sure specifically what "most cases" means - so I played it safe.

    @gpshead
    Copy link
    Member

    gpshead commented Nov 10, 2017

    We're still seeing this (in 2.7.12, but the code at 2.7 head hasn't changed). In this case the RLock being used within _acquireLock() still exists but is an incomplete object by the time we use it.

    @gpshead gpshead reopened this Nov 10, 2017
    @yilei
    Copy link
    Mannequin

    yilei mannequin commented Nov 11, 2017

    Here is a minimal example:

    main.py:
    from pkg_a import lib_a
    pkg_a/init.py
    pkg_a/lib_a.py
    import logging
    import sys
    import pkg_a # This is important
    handler = logging.StreamHandler(sys.stderr)

    It does not happen in Python 3 though (3.5.3 at least).

    @gpshead gpshead self-assigned this Nov 11, 2017
    @gpshead
    Copy link
    Member

    gpshead commented Nov 11, 2017

    New changeset e84f6d3 by Gregory P. Smith in branch '2.7':
    [2.7] bpo-21149: Workaround a GC finalization bug in logging. (bpo-4368)
    e84f6d3

    @gpshead gpshead closed this as completed Nov 11, 2017
    @gpshead gpshead added the type-bug An unexpected behavior, bug, or error label Nov 11, 2017
    @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
    Labels
    stdlib Python modules in the Lib dir type-bug An unexpected behavior, bug, or error
    Projects
    None yet
    Development

    No branches or pull requests

    3 participants