From 64aa6d2000665efb1a2eccae176df9520bf5f5e6 Mon Sep 17 00:00:00 2001 From: "Gregory P. Smith" Date: Tue, 7 May 2019 12:18:20 -0400 Subject: 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. --- Lib/logging/__init__.py | 61 +++++++++------------- Lib/test/test_logging.py | 31 +++++++++-- .../2019-04-06-00-55-09.bpo-36533.kzMyRH.rst | 6 +++ 3 files changed, 58 insertions(+), 40 deletions(-) create mode 100644 Misc/NEWS.d/next/Library/2019-04-06-00-55-09.bpo-36533.kzMyRH.rst diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py index e093982..07a0c0c 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 @@ class Handler(Filterer): 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 82cbeda..950217c 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -668,10 +668,28 @@ class HandlerTest(BaseTest): # 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 @@ class HandlerTest(BaseTest): 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 0000000..15c4222 --- /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. -- cgit v0.12