diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py index aa9b79d8cab4bb..283a1055182b63 100644 --- a/Lib/logging/__init__.py +++ b/Lib/logging/__init__.py @@ -1474,6 +1474,8 @@ class Logger(Filterer): level, and "input.csv", "input.xls" and "input.gnu" for the sub-levels. There is no arbitrary limit to the depth of nesting. """ + _tls = threading.local() + def __init__(self, name, level=NOTSET): """ Initialize the logger with a name and an optional level. @@ -1670,14 +1672,19 @@ def handle(self, record): This method is used for unpickled records received from a socket, as well as those created locally. Logger-level filtering is applied. """ - if self.disabled: - return - maybe_record = self.filter(record) - if not maybe_record: + if self._is_disabled(): return - if isinstance(maybe_record, LogRecord): - record = maybe_record - self.callHandlers(record) + + self._tls.in_progress = True + try: + maybe_record = self.filter(record) + if not maybe_record: + return + if isinstance(maybe_record, LogRecord): + record = maybe_record + self.callHandlers(record) + finally: + self._tls.in_progress = False def addHandler(self, hdlr): """ @@ -1765,7 +1772,7 @@ def isEnabledFor(self, level): """ Is this logger enabled for level 'level'? """ - if self.disabled: + if self._is_disabled(): return False try: @@ -1815,6 +1822,11 @@ def _hierlevel(logger): if isinstance(item, Logger) and item.parent is self and _hierlevel(item) == 1 + _hierlevel(item.parent)) + def _is_disabled(self): + # We need to use getattr as it will only be set the first time a log + # message is recorded on any given thread + return self.disabled or getattr(self._tls, 'in_progress', False) + def __repr__(self): level = getLevelName(self.getEffectiveLevel()) return '<%s %s (%s)>' % (self.__class__.__name__, self.name, level) diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index 58e0381c4aa934..84ca91ad4f7331 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -4163,6 +4163,89 @@ def __init__(self, *args, **kwargs): handler = logging.getHandlerByName('custom') self.assertEqual(handler.custom_kwargs, custom_kwargs) + # See gh-91555 and gh-90321 + @support.requires_subprocess() + def test_deadlock_in_queue(self): + queue = multiprocessing.Queue() + handler = logging.handlers.QueueHandler(queue) + logger = multiprocessing.get_logger() + level = logger.level + try: + logger.setLevel(logging.DEBUG) + logger.addHandler(handler) + logger.debug("deadlock") + finally: + logger.setLevel(level) + logger.removeHandler(handler) + + def test_recursion_in_custom_handler(self): + class BadHandler(logging.Handler): + def __init__(self): + super().__init__() + def emit(self, record): + logger.debug("recurse") + logger = logging.getLogger("test_recursion_in_custom_handler") + logger.addHandler(BadHandler()) + logger.setLevel(logging.DEBUG) + logger.debug("boom") + + @threading_helper.requires_working_threading() + def test_thread_supression_noninterference(self): + lock = threading.Lock() + logger = logging.getLogger("test_thread_supression_noninterference") + + # Block on the first call, allow others through + # + # NOTE: We need to bypass the base class's lock, otherwise that will + # block multiple calls to the same handler itself. + class BlockOnceHandler(TestHandler): + def __init__(self, barrier): + super().__init__(support.Matcher()) + self.barrier = barrier + + def createLock(self): + self.lock = None + + def handle(self, record): + self.emit(record) + + def emit(self, record): + if self.barrier: + barrier = self.barrier + self.barrier = None + barrier.wait() + with lock: + pass + super().emit(record) + logger.info("blow up if not supressed") + + barrier = threading.Barrier(2) + handler = BlockOnceHandler(barrier) + logger.addHandler(handler) + logger.setLevel(logging.DEBUG) + + t1 = threading.Thread(target=logger.debug, args=("1",)) + with lock: + + # Ensure first thread is blocked in the handler, hence supressing logging... + t1.start() + barrier.wait() + + # ...but the second thread should still be able to log... + t2 = threading.Thread(target=logger.debug, args=("2",)) + t2.start() + t2.join(timeout=3) + + self.assertEqual(len(handler.buffer), 1) + self.assertTrue(handler.matches(levelno=logging.DEBUG, message='2')) + + # The first thread should still be blocked here + self.assertTrue(t1.is_alive()) + + # Now the lock has been released the first thread should complete + t1.join() + self.assertEqual(len(handler.buffer), 2) + self.assertTrue(handler.matches(levelno=logging.DEBUG, message='1')) class ManagerTest(BaseTest): def test_manager_loggerclass(self): diff --git a/Misc/NEWS.d/next/Library/2025-03-30-16-42-38.gh-issue-91555.ShVtwW.rst b/Misc/NEWS.d/next/Library/2025-03-30-16-42-38.gh-issue-91555.ShVtwW.rst new file mode 100644 index 00000000000000..e8f5ba56fcc23d --- /dev/null +++ b/Misc/NEWS.d/next/Library/2025-03-30-16-42-38.gh-issue-91555.ShVtwW.rst @@ -0,0 +1,2 @@ +Ignore log messages generated during handling of log messages, to avoid +deadlock or infinite recursion.