bpo-36533: Reinit logging.Handler locks on fork(). (GH-12704) · python/cpython@64aa6d2 · GitHub
Skip to content

Commit 64aa6d2

Browse files
authored
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.
1 parent e85ef7a commit 64aa6d2

3 files changed

Lines changed: 58 additions & 40 deletions

File tree

Lib/logging/__init__.py

Lines changed: 25 additions & 36 deletions

Lib/test/test_logging.py

Lines changed: 27 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -668,10 +668,28 @@ def remove_loop(fname, tries):
668668
# register_at_fork mechanism is also present and used.
669669
@unittest.skipIf(not hasattr(os, 'fork'), 'Test requires os.fork().')
670670
def test_post_fork_child_no_deadlock(self):
671-
"""Ensure forked child logging locks are not held; bpo-6721."""
672-
refed_h = logging.Handler()
671+
"""Ensure child logging locks are not held; bpo-6721 & bpo-36533."""
672+
class _OurHandler(logging.Handler):
673+
def __init__(self):
674+
super().__init__()
675+
self.sub_handler = logging.StreamHandler(
676+
stream=open('/dev/null', 'wt'))
677+
678+
def emit(self, record):
679+
self.sub_handler.acquire()
680+
try:
681+
self.sub_handler.emit(record)
682+
finally:
683+
self.sub_handler.release()
684+
685+
self.assertEqual(len(logging._handlers), 0)
686+
refed_h = _OurHandler()
673687
refed_h.name = 'because we need at least one for this test'
674688
self.assertGreater(len(logging._handlers), 0)
689+
self.assertGreater(len(logging._at_fork_reinit_lock_weakset), 1)
690+
test_logger = logging.getLogger('test_post_fork_child_no_deadlock')
691+
test_logger.addHandler(refed_h)
692+
test_logger.setLevel(logging.DEBUG)
675693

676694
locks_held__ready_to_fork = threading.Event()
677695
fork_happened__release_locks_and_end_thread = threading.Event()
@@ -709,19 +727,24 @@ def lock_holder_thread_fn():
709727
locks_held__ready_to_fork.wait()
710728
pid = os.fork()
711729
if pid == 0: # Child.
712-
logging.error(r'Child process did not deadlock. \o/')
713-
os._exit(0)
730+
try:
731+
test_logger.info(r'Child process did not deadlock. \o/')
732+
finally:
733+
os._exit(0)
714734
else: # Parent.
735+
test_logger.info(r'Parent process returned from fork. \o/')
715736
fork_happened__release_locks_and_end_thread.set()
716737
lock_holder_thread.join()
717738
start_time = time.monotonic()
718739
while True:
740+
test_logger.debug('Waiting for child process.')
719741
waited_pid, status = os.waitpid(pid, os.WNOHANG)
720742
if waited_pid == pid:
721743
break # child process exited.
722744
if time.monotonic() - start_time > 7:
723745
break # so long? implies child deadlock.
724746
time.sleep(0.05)
747+
test_logger.debug('Done waiting.')
725748
if waited_pid != pid:
726749
os.kill(pid, signal.SIGKILL)
727750
waited_pid, status = os.waitpid(pid, 0)
Lines changed: 6 additions & 0 deletions

0 commit comments

Comments
 (0)