From 64a53beaff30bc4367bda39ba39a3c52d7458ce1 Mon Sep 17 00:00:00 2001 From: "Gregory P. Smith" Date: Sat, 21 Oct 2017 13:09:13 -0700 Subject: [PATCH 1/7] [bpo-6721] Sanitize logging locks while forking. --- Lib/logging/__init__.py | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py index a4a950dc4e2c8d..75a7e1a89e7531 100644 --- a/Lib/logging/__init__.py +++ b/Lib/logging/__init__.py @@ -225,6 +225,11 @@ def _releaseLock(): if _lock: _lock.release() +# Prevent a held logging lock from blocking a child from logging. +os.register_at_fork(before=_acquireLock, + after_in_child=_releaseLock, + after_in_parent=_releaseLock) + #--------------------------------------------------------------------------- # The logging record #--------------------------------------------------------------------------- @@ -795,6 +800,9 @@ def createLock(self): Acquire a thread lock for serializing access to the underlying I/O. """ self.lock = threading.RLock() + os.register_at_fork(before=self.acquire, + after_in_child=self.release, + after_in_parent=self.release) def acquire(self): """ From a0c2cfb8bfc7ba9bcc80b375121d782d739da9b1 Mon Sep 17 00:00:00 2001 From: "Gregory P. Smith" Date: Wed, 12 Sep 2018 00:59:09 -0700 Subject: [PATCH 2/7] Use the WeakSet approach per code review. --- Lib/logging/__init__.py | 40 +++++++++++++++++++++++++++++++++++++--- 1 file changed, 37 insertions(+), 3 deletions(-) diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py index 75a7e1a89e7531..ee51aec9f80e20 100644 --- a/Lib/logging/__init__.py +++ b/Lib/logging/__init__.py @@ -225,11 +225,44 @@ def _releaseLock(): if _lock: _lock.release() + # Prevent a held logging lock from blocking a child from logging. 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 _at_fork_weak_calls(method_name): + for instance in _at_fork_acquire_release_weakset: + method = getattr(instance, method_name) + try: + method() + 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') + + +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) + + #--------------------------------------------------------------------------- # The logging record #--------------------------------------------------------------------------- @@ -800,9 +833,10 @@ def createLock(self): Acquire a thread lock for serializing access to the underlying I/O. """ self.lock = threading.RLock() - os.register_at_fork(before=self.acquire, - after_in_child=self.release, - after_in_parent=self.release) + # 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(self) def acquire(self): """ From 1d5bbcb08247b66b42e0fc3dffb36302229e42c4 Mon Sep 17 00:00:00 2001 From: "Gregory P. Smith" Date: Thu, 13 Sep 2018 10:09:23 -0700 Subject: [PATCH 3/7] blurb --- .../NEWS.d/next/Library/2018-09-13-10-09-19.bpo-6721.ZUL_F3.rst | 2 ++ 1 file changed, 2 insertions(+) create mode 100644 Misc/NEWS.d/next/Library/2018-09-13-10-09-19.bpo-6721.ZUL_F3.rst diff --git a/Misc/NEWS.d/next/Library/2018-09-13-10-09-19.bpo-6721.ZUL_F3.rst b/Misc/NEWS.d/next/Library/2018-09-13-10-09-19.bpo-6721.ZUL_F3.rst new file mode 100644 index 00000000000000..073a441db679f9 --- /dev/null +++ b/Misc/NEWS.d/next/Library/2018-09-13-10-09-19.bpo-6721.ZUL_F3.rst @@ -0,0 +1,2 @@ +Acquire the logging module's commonly used internal locks while fork()ing to +avoid deadlocks in the child process. From 6be017a56aef3cd82464e5660e33e01db28bed1e Mon Sep 17 00:00:00 2001 From: "Gregory P. Smith" Date: Thu, 13 Sep 2018 13:37:07 -0700 Subject: [PATCH 4/7] Make the logic conditional on register_at_fork. --- Lib/logging/__init__.py | 59 ++++++++++++++++++++++++----------------- 1 file changed, 35 insertions(+), 24 deletions(-) diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py index ee51aec9f80e20..f327ae53f5e4a6 100644 --- a/Lib/logging/__init__.py +++ b/Lib/logging/__init__.py @@ -227,40 +227,51 @@ def _releaseLock(): # Prevent a held logging lock from blocking a child from logging. -os.register_at_fork(before=_acquireLock, - after_in_child=_releaseLock, - after_in_parent=_releaseLock) +if not hasattr(os, 'register_at_fork'): # Windows and friends. + def _register_at_fork_acquire_release(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() + # 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 _at_fork_weak_calls(method_name): - for instance in _at_fork_acquire_release_weakset: - method = getattr(instance, method_name) - try: - method() - 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 _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) + + + def _at_fork_weak_calls(method_name): + for instance in _at_fork_acquire_release_weakset: + method = getattr(instance, method_name) + try: + method() + 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') + def _before_at_fork_weak_calls(): + _at_fork_weak_calls('acquire') -def _after_at_fork_weak_calls(): - _at_fork_weak_calls('release') + 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=_before_at_fork_weak_calls, + after_in_child=_after_at_fork_weak_calls, + after_in_parent=_after_at_fork_weak_calls) #--------------------------------------------------------------------------- From ebb4b743826263f3400c66fa2c55fdef5968264d Mon Sep 17 00:00:00 2001 From: "Gregory P. Smith" Date: Thu, 13 Sep 2018 15:17:23 -0700 Subject: [PATCH 5/7] Add a unittest! --- Lib/test/test_logging.py | 39 +++++++++++++++++++++++++++++++++++++++ 1 file changed, 39 insertions(+) diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index f7232f67eee730..26b2f3a52a1042 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -35,6 +35,7 @@ import queue import random import re +import signal import socket import struct import sys @@ -666,6 +667,44 @@ def remove_loop(fname, tries): if os.path.exists(fn): os.unlink(fn) + # The implementation relies on os.register_at_fork existing, but we test + # based on os.fork existing because that is what users and this test use. + # This helps ensure that when fork exists (the important concept) that the + # 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() + refed_h.name = 'because we need at least one for this test' + logging._acquireLock() + try: + self.assertGreater(len(logging._handlers), 0) + the_handler = next(iter(logging._handlers.values())) + the_handler.acquire() + try: + pid = os.fork() + if pid == 0: # Child. + logging.error(r'Child process did not deadlock. \o/') + os._exit(0) + else: # Parent. + start_time = time.monotonic() + while True: + waited_pid, status = os.waitpid(pid, os.WNOHANG) + if waited_pid == pid: + break # child process exited. + if time.monotonic() - start_time > 20: + break # so long? implies child deadlock. + time.sleep(0.05) + if waited_pid != pid: + os.kill(pid, signal.SIGKILL) + waited_pid, status = os.waitpid(pid, 0) + self.fail("child process deadlocked.") + self.assertEqual(status, 0, msg="child process error") + finally: + the_handler.release() + finally: + logging._releaseLock() + class BadStream(object): def write(self, data): From 5d5426f560f87763f65d2ae829aebb508c3d83f0 Mon Sep 17 00:00:00 2001 From: "Gregory P. Smith" Date: Thu, 13 Sep 2018 15:21:28 -0700 Subject: [PATCH 6/7] Actually use the registration fn... --- Lib/logging/__init__.py | 5 +---- 1 file changed, 1 insertion(+), 4 deletions(-) diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py index f327ae53f5e4a6..7aeff45f26668a 100644 --- a/Lib/logging/__init__.py +++ b/Lib/logging/__init__.py @@ -844,10 +844,7 @@ def createLock(self): Acquire a thread lock for serializing access to the underlying I/O. """ self.lock = threading.RLock() - # 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(self) + _register_at_fork_acquire_release(self) def acquire(self): """ From 1066bb169d213ebc1729c1630e6bdfeb3112e29b Mon Sep 17 00:00:00 2001 From: "Gregory P. Smith" Date: Thu, 13 Sep 2018 15:55:44 -0700 Subject: [PATCH 7/7] Fix the test to actually work. Now it fails on the previous code and is fixed by the logging changes. The test now uses a thread to hold the locks during the fork in a synchronized manner. Due to mixing of fork and a thread there is potential for deadlock in the child process. buildbots and time will tell if this actually manifests itself in this test or not. :/ --- Lib/test/test_logging.py | 80 +++++++++++++++++++++++++++------------- 1 file changed, 54 insertions(+), 26 deletions(-) diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index 26b2f3a52a1042..b9dad64a5949c7 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -676,34 +676,62 @@ def test_post_fork_child_no_deadlock(self): """Ensure forked child logging locks are not held; bpo-6721.""" refed_h = logging.Handler() refed_h.name = 'because we need at least one for this test' - logging._acquireLock() - try: - self.assertGreater(len(logging._handlers), 0) - the_handler = next(iter(logging._handlers.values())) - the_handler.acquire() + self.assertGreater(len(logging._handlers), 0) + + locks_held__ready_to_fork = threading.Event() + fork_happened__release_locks_and_end_thread = threading.Event() + + def lock_holder_thread_fn(): + logging._acquireLock() try: - pid = os.fork() - if pid == 0: # Child. - logging.error(r'Child process did not deadlock. \o/') - os._exit(0) - else: # Parent. - start_time = time.monotonic() - while True: - waited_pid, status = os.waitpid(pid, os.WNOHANG) - if waited_pid == pid: - break # child process exited. - if time.monotonic() - start_time > 20: - break # so long? implies child deadlock. - time.sleep(0.05) - if waited_pid != pid: - os.kill(pid, signal.SIGKILL) - waited_pid, status = os.waitpid(pid, 0) - self.fail("child process deadlocked.") - self.assertEqual(status, 0, msg="child process error") + refed_h.acquire() + try: + # Tell the main thread to do the fork. + locks_held__ready_to_fork.set() + + # If the deadlock bug exists, the fork will happen + # without dealing with the locks we hold, deadlocking + # the child. + + # Wait for a successful fork or an unreasonable amount of + # time before releasing our locks. To avoid a timing based + # test we'd need communication from os.fork() as to when it + # has actually happened. Given this is a regression test + # for a fixed issue, potentially less reliably detecting + # regression via timing is acceptable for simplicity. + # The test will always take at least this long. :( + fork_happened__release_locks_and_end_thread.wait(0.5) + finally: + refed_h.release() finally: - the_handler.release() - finally: - logging._releaseLock() + logging._releaseLock() + + lock_holder_thread = threading.Thread( + target=lock_holder_thread_fn, + name='test_post_fork_child_no_deadlock lock holder') + lock_holder_thread.start() + + 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) + else: # Parent. + fork_happened__release_locks_and_end_thread.set() + lock_holder_thread.join() + start_time = time.monotonic() + while True: + 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) + if waited_pid != pid: + os.kill(pid, signal.SIGKILL) + waited_pid, status = os.waitpid(pid, 0) + self.fail("child process deadlocked.") + self.assertEqual(status, 0, msg="child process error") class BadStream(object):