[Python-checkins] bpo-36533: Reinit logging.Handler locks on fork(). (GH-12704)
Gregory P. Smith
webhook-mailer at python.org
Tue May 7 12:18:26 EDT 2019
https://github.com/python/cpython/commit/64aa6d2000665efb1a2eccae176df9520bf5f5e6
commit: 64aa6d2000665efb1a2eccae176df9520bf5f5e6
branch: master
author: Gregory P. Smith <greg at krypto.org>
committer: GitHub <noreply at github.com>
date: 2019-05-07T12:18:20-04:00
summary:
bpo-36533: Reinit logging.Handler locks on fork(). (GH-12704)
Instead of attempting to acquire and release them all across fork
which was leading to deadlocks in some applications that had chained
their own handlers while holding multiple locks.
files:
A Misc/NEWS.d/next/Library/2019-04-06-00-55-09.bpo-36533.kzMyRH.rst
M Lib/logging/__init__.py
M Lib/test/test_logging.py
diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py
index e093982a0cdf..07a0c0c4ae98 100644
--- a/Lib/logging/__init__.py
+++ b/Lib/logging/__init__.py
@@ -231,49 +231,38 @@ def _releaseLock():
# Prevent a held logging lock from blocking a child from logging.
if not hasattr(os, 'register_at_fork'): # Windows and friends.
- def _register_at_fork_acquire_release(instance):
+ def _register_at_fork_reinit_lock(instance):
pass # no-op when os.register_at_fork does not exist.
-else: # The os.register_at_fork API exists
- os.register_at_fork(before=_acquireLock,
- after_in_child=_releaseLock,
- after_in_parent=_releaseLock)
-
- # A collection of instances with acquire and release methods (logging.Handler)
- # to be called before and after fork. The weakref avoids us keeping discarded
- # Handler instances alive forever in case an odd program creates and destroys
- # many over its lifetime.
- _at_fork_acquire_release_weakset = weakref.WeakSet()
-
-
- def _register_at_fork_acquire_release(instance):
- # We put the instance itself in a single WeakSet as we MUST have only
- # one atomic weak ref. used by both before and after atfork calls to
- # guarantee matched pairs of acquire and release calls.
- _at_fork_acquire_release_weakset.add(instance)
-
+else:
+ # A collection of instances with a createLock method (logging.Handler)
+ # to be called in the child after forking. The weakref avoids us keeping
+ # discarded Handler instances alive. A set is used to avoid accumulating
+ # duplicate registrations as createLock() is responsible for registering
+ # a new Handler instance with this set in the first place.
+ _at_fork_reinit_lock_weakset = weakref.WeakSet()
+
+ def _register_at_fork_reinit_lock(instance):
+ _acquireLock()
+ try:
+ _at_fork_reinit_lock_weakset.add(instance)
+ finally:
+ _releaseLock()
- def _at_fork_weak_calls(method_name):
- for instance in _at_fork_acquire_release_weakset:
- method = getattr(instance, method_name)
+ def _after_at_fork_child_reinit_locks():
+ # _acquireLock() was called in the parent before forking.
+ for handler in _at_fork_reinit_lock_weakset:
try:
- method()
+ handler.createLock()
except Exception as err:
# Similar to what PyErr_WriteUnraisable does.
print("Ignoring exception from logging atfork", instance,
- method_name, "method:", err, file=sys.stderr)
-
-
- def _before_at_fork_weak_calls():
- _at_fork_weak_calls('acquire')
+ "._reinit_lock() method:", err, file=sys.stderr)
+ _releaseLock() # Acquired by os.register_at_fork(before=.
- def _after_at_fork_weak_calls():
- _at_fork_weak_calls('release')
-
-
- os.register_at_fork(before=_before_at_fork_weak_calls,
- after_in_child=_after_at_fork_weak_calls,
- after_in_parent=_after_at_fork_weak_calls)
+ os.register_at_fork(before=_acquireLock,
+ after_in_child=_after_at_fork_child_reinit_locks,
+ after_in_parent=_releaseLock)
#---------------------------------------------------------------------------
@@ -900,7 +889,7 @@ def createLock(self):
Acquire a thread lock for serializing access to the underlying I/O.
"""
self.lock = threading.RLock()
- _register_at_fork_acquire_release(self)
+ _register_at_fork_reinit_lock(self)
def acquire(self):
"""
diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py
index 82cbedada472..950217cec288 100644
--- a/Lib/test/test_logging.py
+++ b/Lib/test/test_logging.py
@@ -668,10 +668,28 @@ def remove_loop(fname, tries):
# register_at_fork mechanism is also present and used.
@unittest.skipIf(not hasattr(os, 'fork'), 'Test requires os.fork().')
def test_post_fork_child_no_deadlock(self):
- """Ensure forked child logging locks are not held; bpo-6721."""
- refed_h = logging.Handler()
+ """Ensure child logging locks are not held; bpo-6721 & bpo-36533."""
+ class _OurHandler(logging.Handler):
+ def __init__(self):
+ super().__init__()
+ self.sub_handler = logging.StreamHandler(
+ stream=open('/dev/null', 'wt'))
+
+ def emit(self, record):
+ self.sub_handler.acquire()
+ try:
+ self.sub_handler.emit(record)
+ finally:
+ self.sub_handler.release()
+
+ self.assertEqual(len(logging._handlers), 0)
+ refed_h = _OurHandler()
refed_h.name = 'because we need at least one for this test'
self.assertGreater(len(logging._handlers), 0)
+ self.assertGreater(len(logging._at_fork_reinit_lock_weakset), 1)
+ test_logger = logging.getLogger('test_post_fork_child_no_deadlock')
+ test_logger.addHandler(refed_h)
+ test_logger.setLevel(logging.DEBUG)
locks_held__ready_to_fork = threading.Event()
fork_happened__release_locks_and_end_thread = threading.Event()
@@ -709,19 +727,24 @@ def lock_holder_thread_fn():
locks_held__ready_to_fork.wait()
pid = os.fork()
if pid == 0: # Child.
- logging.error(r'Child process did not deadlock. \o/')
- os._exit(0)
+ try:
+ test_logger.info(r'Child process did not deadlock. \o/')
+ finally:
+ os._exit(0)
else: # Parent.
+ test_logger.info(r'Parent process returned from fork. \o/')
fork_happened__release_locks_and_end_thread.set()
lock_holder_thread.join()
start_time = time.monotonic()
while True:
+ test_logger.debug('Waiting for child process.')
waited_pid, status = os.waitpid(pid, os.WNOHANG)
if waited_pid == pid:
break # child process exited.
if time.monotonic() - start_time > 7:
break # so long? implies child deadlock.
time.sleep(0.05)
+ test_logger.debug('Done waiting.')
if waited_pid != pid:
os.kill(pid, signal.SIGKILL)
waited_pid, status = os.waitpid(pid, 0)
diff --git a/Misc/NEWS.d/next/Library/2019-04-06-00-55-09.bpo-36533.kzMyRH.rst b/Misc/NEWS.d/next/Library/2019-04-06-00-55-09.bpo-36533.kzMyRH.rst
new file mode 100644
index 000000000000..15c4222d4837
--- /dev/null
+++ b/Misc/NEWS.d/next/Library/2019-04-06-00-55-09.bpo-36533.kzMyRH.rst
@@ -0,0 +1,6 @@
+Reinitialize logging.Handler locks in forked child processes instead of
+attempting to acquire them all in the parent before forking only to be
+released in the child process. The acquire/release pattern was leading to
+deadlocks in code that has implemented any form of chained logging handlers
+that depend upon one another as the lock acquision order cannot be
+guaranteed.
More information about the Python-checkins
mailing list