Skip to content

[3.13] gh-91555: disable logger while handling log record (GH-131812) #133898

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 1 commit into from
May 12, 2025
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
28 changes: 20 additions & 8 deletions Lib/logging/__init__.py
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down Expand Up @@ -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):
"""
Expand Down Expand Up @@ -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:
Expand Down Expand Up @@ -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)
Expand Down
83 changes: 83 additions & 0 deletions Lib/test/test_logging.py
Original file line number Diff line number Diff line change
Expand Up @@ -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):
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,2 @@
Ignore log messages generated during handling of log messages, to avoid
deadlock or infinite recursion.
Loading