From 3b4b28efbde63502709bede7c5f9403ec6f37428 Mon Sep 17 00:00:00 2001 From: "Gregory P. Smith" Date: Tue, 7 May 2019 16:29:41 -0400 Subject: [PATCH] [3.7] bpo-36533: Reinit logging.Handler locks on fork(). (GH-12704) (GH-13170) 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. (cherry picked from commit 64aa6d2000665efb1a2eccae176df9520bf5f5e6) Co-authored-by: Gregory P. Smith [Google LLC] --- 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 66fd5ac9fe06..cd80d5cccc6e 100644 --- a/Lib/logging/__init__.py +++ b/Lib/logging/__init__.py @@ -229,49 +229,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) #--------------------------------------------------------------------------- @@ -844,7 +833,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 6c5cb81377b3..42746d40d2cd 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -673,10 +673,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() @@ -714,19 +732,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 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. -- 2.47.3