https://github.com/python/cpython/commit/2561e148ec985755baa3984b91fd0bfc089b283c
commit: 2561e148ec985755baa3984b91fd0bfc089b283c
branch: main
author: Duane Griffin <[email protected]>
committer: vsajip <[email protected]>
date: 2025-05-08T13:33:06+01:00
summary:
gh-91555: disable logger while handling log record (GH-131812)
Prevent the possibility of re-entrancy leading to deadlock or infinite
recursion (caused by logging triggered by logging), by disabling logging while
the logger is handling log messages.
files:
A Misc/NEWS.d/next/Library/2025-03-30-16-42-38.gh-issue-91555.ShVtwW.rst
M Lib/logging/__init__.py
M Lib/test/test_logging.py
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 3f113ec1be47af..1e5adcc8db13f6 100644
--- a/Lib/test/test_logging.py
+++ b/Lib/test/test_logging.py
@@ -4214,6 +4214,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.
_______________________________________________
Python-checkins mailing list -- [email protected]
To unsubscribe send an email to [email protected]
https://mail.python.org/mailman3/lists/python-checkins.python.org/
Member address: [email protected]
