8000 bpo-36533: Reinit logging.Handler locks on fork(). (GH-12704) · lisroach/cpython@64aa6d2 · GitHub
[go: up one dir, main page]

Skip to content

Commit 64aa6d2

Browse files
authored
bpo-36533: Reinit logging.Handler locks on fork(). (pythonGH-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

File tree

3 files changed

+58
-40
lines changed
  • Misc/NEWS.d/next/Library
  • 3 files changed

    +58
    -40
    lines changed

    Lib/logging/__init__.py

    Lines changed: 25 additions & 36 deletions
    8000
    Original file line numberDiff line numberDiff line change
    @@ -231,49 +231,38 @@ def _releaseLock():
    231231
    # Prevent a held logging lock from blocking a child from logging.
    232232

    233233
    if not hasattr(os, 'register_at_fork'): # Windows and friends.
    234-
    def _register_at_fork_acquire_release(instance):
    234+
    def _register_at_fork_reinit_lock(instance):
    235235
    pass # no-op when os.register_at_fork does not exist.
    236-
    else: # The os.register_at_fork API exists
    237-
    os.register_at_fork(before=_acquireLock,
    238-
    after_in_child=_releaseLock,
    239-
    after_in_parent=_releaseLock)
    240-
    241-
    # A collection of instances with acquire and release methods (logging.Handler)
    242-
    # to be called before and after fork. The weakref avoids us keeping discarded
    243-
    # Handler instances alive forever in case an odd program creates and destroys
    244-
    # many over its lifetime.
    245-
    _at_fork_acquire_release_weakset = weakref.WeakSet()
    246-
    247-
    248-
    def _register_at_fork_acquire_release(instance):
    249-
    # We put the instance itself in a single WeakSet as we MUST have only
    250-
    # one atomic weak ref. used by both before and after atfork calls to
    251-
    # guarantee matched pairs of acquire and release calls.
    252-
    _at_fork_acquire_release_weakset.add(instance)
    253-
    236+
    else:
    237+
    # A collection of instances with a createLock method (logging.Handler)
    238+
    # to be called in the child after forking. The weakref avoids us keeping
    239+
    # discarded Handler instances alive. A set is used to avoid accumulating
    240+
    # duplicate registrations as createLock() is responsible for registering
    241+
    # a new Handler instance with this set in the first place.
    242+
    _at_fork_reinit_lock_weakset = weakref.WeakSet()
    243+
    244+
    def _register_at_fork_reinit_lock(instance):
    245+
    _acquireLock()
    246+
    try:
    247+
    _at_fork_reinit_lock_weakset.add(instance)
    248+
    finally:
    249+
    _releaseLock()
    254250

    255-
    def _at_fork_weak_calls(method_name):
    256-
    for instance in _at_fork_acquire_release_weakset:
    257-
    method = getattr(instance, method_name)
    251+
    def _after_at_fork_child_reinit_locks():
    252+
    # _acquireLock() was called in the parent before forking.
    253+
    for handler in _at_fork_reinit_lock_weakset:
    258254
    try:
    259-
    method()
    255+
    handler.createLock()
    260256
    except Exception as err:
    261257
    # Similar to what PyErr_WriteUnraisable does.
    262258
    print("Ignoring exception from logging atfork", instance,
    263-
    method_name, "method:", err, file=sys.stderr)
    264-
    265-
    266-
    def _before_at_fork_weak_calls():
    267-
    _at_fork_weak_calls('acquire')
    259+
    "._reinit_lock() method:", err, file=sys.stderr)
    260+
    _releaseLock() # Acquired by os.register_at_fork(before=.
    268261

    269262

    270-
    def _after_at_fork_weak_calls():
    271-
    _at_fork_weak_calls('release')
    272-
    273-
    274-
    os.register_at_fork(before=_before_at_fork_weak_calls,
    275-
    after_in_child=_after_at_fork_weak_calls,
    276-
    after_in_parent=_after_at_fork_weak_calls)
    263+
    os.register_at_fork(before=_acquireLock,
    264+
    after_in_child=_after_at_fork_child_reinit_locks,
    265+
    after_in_parent=_releaseLock)
    277266

    278267

    279268
    #---------------------------------------------------------------------------
    @@ -900,7 +889,7 @@ def createLock(self):
    900889
    Acquire a thread lock for serializing access to the underlying I/O.
    901890
    """
    902891
    self.lock = threading.RLock()
    903-
    _register_at_fork_acquire_release(self)
    892+
    _register_at_fork_reinit_lock(self)
    904893

    905894
    def acquire(self):
    906895
    """

    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
    Original file line numberDiff line numberDiff line change
    @@ -0,0 +1,6 @@
    1+
    Reinitialize logging.Handler locks in forked child processes instead of
    2+
    attempting to acquire them all in the parent before forking only to be
    3+
    released in the child process. The acquire/release pattern was leading to
    4+
    deadlocks in code that has implemented any form of chained logging handlers
    5+
    that depend upon one another as the lock acquision order cannot be
    6+
    guaranteed.

    0 commit comments

    Comments
     (0)
    0