Avoid deadlock caused by generational GC and object finalizers

loguru/_handler.py

@@ -5,7 +5,7 @@
 from threading import Thread
 
 from ._colorizer import Colorizer
-from ._locks_machinery import create_handler_lock
+from ._locks_machinery import HandlerLockNotReentrant, create_handler_lock
 
 
 def prepare_colored_format(format_, ansi_level):
@@ -175,7 +175,8 @@ def emit(self, record, level_id, from_decorator, is_raw, colored_message):
                     self._queue.put(str_record)
                 else:
                     self._sink.write(str_record)
-
+        except HandlerLockNotReentrant:
+            self._error_interceptor.print(record)
         except Exception:
             if not self._error_interceptor.should_catch():
                 raise

loguru/_locks_machinery.py

@@ -2,13 +2,46 @@
 import threading
 import weakref
 
+
+class HandlerLockNotReentrant(RuntimeError):
+    pass
+
+
+class _HandlerLockWrapper:
+    """Lock wrapper for the handler.
+
+    This avoids thread-local deadlock by propagating an exception rather than waiting forever.
+    See: https://github.com/Delgan/loguru/issues/712
+    """
+
+    def __init__(self, lock):
+        self._lock = lock
+        self._local = threading.local()
+        self._local.acquired = False
+
+    def __enter__(self):
+        if getattr(self._local, "acquired", False):
+            raise HandlerLockNotReentrant(
+                "Tried to emit a log in the process of handling a log. Log handler is not "
+                "re-entrant."
+            )
+        self._local.acquired = True
+        self._lock.acquire()
+        return
+
+    def __exit__(self, exc_type, exc_value, traceback):
+        self._lock.release()
+        self._local.acquired = False
+        return
+
+
 if not hasattr(os, "register_at_fork"):
 
     def create_logger_lock():
         return threading.Lock()
 
     def create_handler_lock():
-        return threading.Lock()
+        return _HandlerLockWrapper(threading.Lock())
 
 else:
     # While forking, we need to sanitize all locks to make sure the child process doesn't run into
@@ -47,4 +80,4 @@ def create_logger_lock():
     def create_handler_lock():
         lock = threading.Lock()
         handler_locks.add(lock)
-        return lock
+        return _HandlerLockWrapper(lock)

tests/test_locks.py

@@ -0,0 +1,65 @@
+import gc
+
+import pytest
+
+from loguru import logger
+
+
+class CyclicReference:
+    """A minimal cyclic reference.
+
+    Cyclical references are garbage collected using the generational collector rather than
+    via reference counting. This is important here, because the generational collector runs
+    periodically, meaning that it is hard to predict when the stack will be overtaken by a
+    garbage collection process - but it will almost always be when allocating memory of some
+    kind.
+
+    When this object is garbage-collected, a log will be emitted.
+    """
+
+    def __init__(self, _other: "CyclicReference" = None):
+        self.other = _other or CyclicReference(_other=self)
+
+    def __del__(self):
+        logger.info("tearing down")
+
+
+@pytest.fixture()
+def _remove_cyclic_references():
+    """Prevent cyclic isolate finalizers bleeding into other tests."""
+    try:
+        yield
+    finally:
+        for generation in range(3):
+            gc.collect(generation=generation)
+
+
+def test_no_deadlock_on_generational_garbage_collection(_remove_cyclic_references):
+    """Regression test for https://github.com/Delgan/loguru/issues/712
+
+    Assert that deadlocks do not occur when a cyclic isolate containing log output in
+    finalizers is collected by generational GC, during the output of another log message.
+    """
+
+    # GIVEN a sink which assigns some memory
+    output = []
+
+    def sink(message):
+        # This simulates assigning some memory as part of log handling. Eventually this will
+        # trigger the generational garbage collector to take over here.
+        # You could replace it with `json.dumps(message.record)` to get the same effect.
+        _ = [dict() for _ in range(20)]
+
+        # Actually write the message somewhere
+        output.append(message)
+
+    logger.add(sink, colorize=False)
+
+    # WHEN there are cyclic isolates in memory which log on GC
+    # AND logs are produced long enough to trigger generational GC
+    for _ in range(1000):
+        CyclicReference()
+        logger.info("test")
+
+    # THEN deadlock should not be reached
+    assert True