From e9f6079c23b23760b8b84497de9f35212bd60c82 Mon Sep 17 00:00:00 2001 From: Duane Griffin Date: Fri, 28 Mar 2025 11:04:42 +1300 Subject: [PATCH 1/4] gh-91555: disable logger while handling log record Prevent the possibility of re-entrancy and deadlock or infinite recursion caused by logging triggered by logging by disabling logging while the logger is handling log messages. --- Lib/logging/__init__.py | 27 +++++++++++++++++++-------- 1 file changed, 19 insertions(+), 8 deletions(-) diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py index aa9b79d8cab4bb..5c818155e00d12 100644 --- a/Lib/logging/__init__.py +++ b/Lib/logging/__init__.py @@ -1459,6 +1459,9 @@ def _clear_cache(self): # Logger classes and functions #--------------------------------------------------------------------------- +_tls = threading.local() +_tls.in_progress = False + class Logger(Filterer): """ Instances of the Logger class represent a single logging channel. A @@ -1670,14 +1673,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) + + _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: + _tls.in_progress = False def addHandler(self, hdlr): """ @@ -1765,7 +1773,7 @@ def isEnabledFor(self, level): """ Is this logger enabled for level 'level'? """ - if self.disabled: + if self._is_disabled(): return False try: @@ -1815,6 +1823,9 @@ def _hierlevel(logger): if isinstance(item, Logger) and item.parent is self and _hierlevel(item) == 1 + _hierlevel(item.parent)) + def _is_disabled(self): + return self.disabled or getattr(_tls, 'in_progress', False) + def __repr__(self): level = getLevelName(self.getEffectiveLevel()) return '<%s %s (%s)>' % (self.__class__.__name__, self.name, level) From 5a89172f61daef41d0ce731d01152720ad620ebd Mon Sep 17 00:00:00 2001 From: Duane Griffin Date: Sun, 30 Mar 2025 13:25:55 +1300 Subject: [PATCH 2/4] Move TLS into class variable and add tests --- Lib/logging/__init__.py | 13 +++++++------ Lib/test/test_logging.py | 25 +++++++++++++++++++++++++ 2 files changed, 32 insertions(+), 6 deletions(-) diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py index 5c818155e00d12..283a1055182b63 100644 --- a/Lib/logging/__init__.py +++ b/Lib/logging/__init__.py @@ -1459,9 +1459,6 @@ def _clear_cache(self): # Logger classes and functions #--------------------------------------------------------------------------- -_tls = threading.local() -_tls.in_progress = False - class Logger(Filterer): """ Instances of the Logger class represent a single logging channel. A @@ -1477,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. @@ -1676,7 +1675,7 @@ def handle(self, record): if self._is_disabled(): return - _tls.in_progress = True + self._tls.in_progress = True try: maybe_record = self.filter(record) if not maybe_record: @@ -1685,7 +1684,7 @@ def handle(self, record): record = maybe_record self.callHandlers(record) finally: - _tls.in_progress = False + self._tls.in_progress = False def addHandler(self, hdlr): """ @@ -1824,7 +1823,9 @@ def _hierlevel(logger): _hierlevel(item) == 1 + _hierlevel(item.parent)) def _is_disabled(self): - return self.disabled or getattr(_tls, 'in_progress', False) + # 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()) diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index e34fe45fd68e52..05470342871645 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -4174,6 +4174,31 @@ 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") class ManagerTest(BaseTest): def test_manager_loggerclass(self): From 7b68d12955176885d6941046b20a7569c643c7e6 Mon Sep 17 00:00:00 2001 From: Duane Griffin Date: Sun, 30 Mar 2025 16:42:43 +1300 Subject: [PATCH 3/4] Add news entry --- .../next/Library/2025-03-30-16-42-38.gh-issue-91555.ShVtwW.rst | 2 ++ 1 file changed, 2 insertions(+) create mode 100644 Misc/NEWS.d/next/Library/2025-03-30-16-42-38.gh-issue-91555.ShVtwW.rst 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. From bc4bd11705c65324dda7ea25cab5b1321c14d176 Mon Sep 17 00:00:00 2001 From: Duane Griffin Date: Thu, 17 Apr 2025 22:31:18 +1200 Subject: [PATCH 4/4] Add test that verifies one thread having logging supressed while it handles a message does not block a different thread from handling a message on the same logger. --- Lib/test/test_logging.py | 58 ++++++++++++++++++++++++++++++++++++++++ 1 file changed, 58 insertions(+) diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index 05470342871645..4db6124c275c0c 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -4200,6 +4200,64 @@ def emit(self, record): 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): logged = []