This issue tracker has been migrated to GitHub, and is currently read-only.
For more information, see the GitHub FAQs in the Python's Developer Guide.

classification
Title: logging._removeHandlerRef is not threadsafe during interpreter shutdown
Type: behavior Stage: commit review
Components: Library (Lib) Versions: Python 2.7
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: gregory.p.smith Nosy List: Devin Jeanpierre, gregory.p.smith, python-dev, r.david.murray, vinay.sajip, yilei
Priority: normal Keywords: patch

Created on 2014-04-03 20:20 by Devin Jeanpierre, last changed 2022-04-11 14:58 by admin. This issue is now closed.

Files
File name Uploaded Description Edit
patch.diff Devin Jeanpierre, 2014-04-03 20:20 review
Pull Requests
URL Status Linked Edit
PR 4368 merged gregory.p.smith, 2017-11-11 01:06
Messages (10)
msg215466 - (view) Author: Devin Jeanpierre (Devin Jeanpierre) * Date: 2014-04-03 20:20
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.
msg215479 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2014-04-03 23:06
> 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/
msg215483 - (view) Author: Devin Jeanpierre (Devin Jeanpierre) * Date: 2014-04-04 00:18
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.
msg215484 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2014-04-04 01:12
Yes, I remember previous discussions of the corporate agreement from Google, so I'm sure it exists.
msg215507 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2014-04-04 09:57
New changeset b6deab7204e6 by Vinay Sajip in branch '2.7':
Issue #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 #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 #21149: Improved thread-safety in logging cleanup during interpreter shutdown.
http://hg.python.org/cpython/rev/76689a706900
msg215531 - (view) Author: Devin Jeanpierre (Devin Jeanpierre) * Date: 2014-04-04 15:40
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.)
msg215581 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2014-04-05 00:45
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.
msg306056 - (view) Author: Gregory P. Smith (gregory.p.smith) * (Python committer) Date: 2017-11-10 23:10
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.
msg306070 - (view) Author: Yilei Yang (yilei) * Date: 2017-11-11 00:17
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).
msg306095 - (view) Author: Gregory P. Smith (gregory.p.smith) * (Python committer) Date: 2017-11-11 22:48
New changeset e84f6d3817ad3d18fdfbb5223b8078606166cea0 by Gregory P. Smith in branch '2.7':
[2.7] bpo-21149: Workaround a GC finalization bug in logging. (#4368)
https://github.com/python/cpython/commit/e84f6d3817ad3d18fdfbb5223b8078606166cea0
History
Date User Action Args
2022-04-11 14:58:01adminsetgithub: 65348
2017-11-11 22:50:48gregory.p.smithsetstatus: open -> closed
type: behavior
resolution: fixed
stage: patch review -> commit review
2017-11-11 22:48:52gregory.p.smithsetmessages: + msg306095
2017-11-11 01:06:00gregory.p.smithsetstage: resolved -> patch review
pull_requests: + pull_request4321
2017-11-11 00:21:58gregory.p.smithsetassignee: gregory.p.smith
2017-11-11 00:17:25yileisetnosy: + yilei
messages: + msg306070
2017-11-10 23:10:08gregory.p.smithsetstatus: closed -> open
resolution: fixed -> (no value)
messages: + msg306056
2014-04-05 00:45:25vinay.sajipsetmessages: + msg215581
2014-04-04 15:40:31Devin Jeanpierresetmessages: + msg215531
2014-04-04 09:57:44python-devsetstatus: open -> closed

nosy: + python-dev
messages: + msg215507

resolution: fixed
stage: resolved
2014-04-04 01:12:09r.david.murraysetnosy: + r.david.murray
messages: + msg215484
2014-04-04 00:18:06Devin Jeanpierresetmessages: + msg215483
2014-04-03 23:06:07vinay.sajipsetmessages: + msg215479
2014-04-03 21:04:35ned.deilysetnosy: + vinay.sajip
2014-04-03 20:20:57Devin Jeanpierrecreate