logging._removeHandlerRef is not threadsafe during interpreter shutdown

[ssbr]

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]

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.

[vsajip]

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]

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]

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

[python-dev]

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

[ssbr]

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]

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]

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.

[yilei]

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]

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