Repository navigation
multiprocessing.get_logger() logger deadlock on first call by subprocess to logger.info("...") due to internal logger.debug(...) call by multiprocessing.Queue._start_thread #91555
Description
Python: v3.10.2
Platform: Windows 10
Description: A deadlock occurs when a subprocess uses a logging.Logger returned multiprocessing.get_logger() where the initial logging level at the time of the first call to logger.info is level DEBUG or lower, which causes, during that same initial call to logger.info, an internal call to logger.debug(...) (at top of multiprocessing.Queue._start_thread), all of which causes the same thread to attempt to re-acquire an already held lock.
Workaround: Set logging level to INFO or higher (something above DEBUG) to prevent the logging.debug() statement at the top of Queue._start_thread from attempting to init/lock while init is already in progress.
The following example exhibits the issue when SHOW_THE_DEADLOCK==True. Set SHOW_THE_DEADLOCK==False to observe the workaround.
from concurrent.futures import ProcessPoolExecutor
import logging
import logging.handlers
from multiprocessing import freeze_support
import multiprocessing
import sys
SHOW_THE_DEADLOCK = True # True to show the bug, False to show workaround.
g_queue: multiprocessing.Queue = None
def global_init(logging_queue):
global g_queue
g_queue = logging_queue
def subprocess_logging_test():
queue_handler = logging.handlers.QueueHandler(g_queue)
l2 = multiprocessing.get_logger()
l2.addHandler(queue_handler)
if not SHOW_THE_DEADLOCK:
l2.setLevel("INFO") # default level is UNSET, if level is <= DEBUG deadlock will occur, this prevents that.
l2.info("write to log once at info and higher to perform thread init etc.")
l2.setLevel("DEBUG")
l2.info("If initial level is DEBUG, deadlock here, else OK.")
l2.warning("If initial level is DEBUG, never reach this point, else OK.")
l2.debug("If initial level is DEBUG, never reach this point, else OK.")
l2.info("If initial level is DEBUG, never reach this point, else OK.")
def main():
global g_queue
g_queue = multiprocessing.Queue(maxsize=99)
handler = logging.StreamHandler(stream=sys.stdout)
listener = logging.handlers.QueueListener(g_queue, handler)
listener.start()
with ProcessPoolExecutor(
initializer=global_init,
initargs=(g_queue,)
) as pexec:
f = pexec.submit(subprocess_logging_test)
f.result()
listener.stop()
if __name__ == '__main__':
freeze_support()
main()
The following is an annotated stack from the above example when SHOW_THE_DEADLOCK==True.
put (c:\Users\HappyPythonDev\AppData\Local\Programs\Python\Python310\Lib\multiprocessing\queues.py:92)
with self._notempty: # <----- dead lock
if self._thread is None:
self._start_thread()
self._buffer.append(obj)
self._notempty.notify()
put_nowait (c:\Users\HappyPythonDev\AppData\Local\Programs\Python\Python310\Lib\multiprocessing\queues.py:138)
enqueue (c:\Users\HappyPythonDev\AppData\Local\Programs\Python\Python310\Lib\logging\handlers.py:1423)
emit (c:\Users\HappyPythonDev\AppData\Local\Programs\Python\Python310\Lib\logging\handlers.py:1461)
handle (c:\Users\HappyPythonDev\AppData\Local\Programs\Python\Python310\Lib\logging\__init__.py:968)
callHandlers (c:\Users\HappyPythonDev\AppData\Local\Programs\Python\Python310\Lib\logging\__init__.py:1696)
handle (c:\Users\HappyPythonDev\AppData\Local\Programs\Python\Python310\Lib\logging\__init__.py:1634)
_log (c:\Users\HappyPythonDev\AppData\Local\Programs\Python\Python310\Lib\logging\__init__.py:1624)
log (c:\Users\HappyPythonDev\AppData\Local\Programs\Python\Python310\Lib\logging\__init__.py:1547)
debug (c:\Users\HappyPythonDev\AppData\Local\Programs\Python\Python310\Lib\multiprocessing\util.py:50)
_start_thread (c:\Users\HappyPythonDev\AppData\Local\Programs\Python\Python310\Lib\multiprocessing\queues.py:165)
def _start_thread(self):
debug('Queue._start_thread()') # <----- at level DEBUG or lower, triggers logging call leading to deadlock.
put (c:\Users\HappyPythonDev\AppData\Local\Programs\Python\Python310\Lib\multiprocessing\queues.py:94)
put_nowait (c:\Users\HappyPythonDev\AppData\Local\Programs\Python\Python310\Lib\multiprocessing\queues.py:138)
enqueue (c:\Users\HappyPythonDev\AppData\Local\Programs\Python\Python310\Lib\logging\handlers.py:1423)
emit (c:\Users\HappyPythonDev\AppData\Local\Programs\Python\Python310\Lib\logging\handlers.py:1461)
handle (c:\Users\HappyPythonDev\AppData\Local\Programs\Python\Python310\Lib\logging\__init__.py:968)
callHandlers (c:\Users\HappyPythonDev\AppData\Local\Programs\Python\Python310\Lib\logging\__init__.py:1696)
handle (c:\Users\HappyPythonDev\AppData\Local\Programs\Python\Python310\Lib\logging\__init__.py:1634)
_log (c:\Users\HappyPythonDev\AppData\Local\Programs\Python\Python310\Lib\logging\__init__.py:1624)
info (c:\Users\HappyPythonDev\AppData\Local\Programs\Python\Python310\Lib\logging\__init__.py:1477)
subprocess_logging_test (c:\PythonTesting\logging_testing.py:25)
_process_worker (c:\Users\HappyPythonDev\AppData\Local\Programs\Python\Python310\Lib\concurrent\futures\process.py:243)
run (c:\Users\HappyPythonDev\AppData\Local\Programs\Python\Python310\Lib\multiprocessing\process.py:108)
_bootstrap (c:\Users\HappyPythonDev\AppData\Local\Programs\Python\Python310\Lib\multiprocessing\process.py:315)
_main (c:\Users\HappyPythonDev\AppData\Local\Programs\Python\Python310\Lib\multiprocessing\spawn.py:129)
spawn_main (c:\Users\HappyPythonDev\AppData\Local\Programs\Python\Python310\Lib\multiprocessing\spawn.py:116)
(:1)
Linked PRs
- gh-91555: disable logger while handling log record #131812
- [3.13] gh-91555: disable logger while handling log record (GH-131812) #133898
- [3.14] gh-91555: disable logger while handling log record (GH-131812) #133899
- gh-91555: Revert disabling of logger while handling log record. #135858
- [3.14] gh-91555: Revert disabling of logger while handling log record. (GH-135858) #135910
- [3.13] gh-91555: Revert disabling of logger while handling log record. (GH-135858) #135911
- gh-91555: add warning to docs about possibility of deadlock/infinite recursion #135954
- [3.14] gh-91555: add warning to docs about possibility of deadlock/infinite recursion (GH-135954) #135988
- [3.13] gh-91555: add warning to docs about possibility of deadlock/infinite recursion (GH-135954) #135989
Activity
akulakov commented on Apr 22, 2022
I reproduced in 3.11 latest version on MacOS, both the lockup and success when setting higher debug level.
iamdbychkov commented on May 22, 2022
see also:
#90321
duaneg commented on Mar 27, 2025
Queue's have a _notempty condition variable, created with a non-recursive lock. In this deadlock the queue handler tries to start a thread the first time a message is enqueued, however that logs a debug message to the same logger, which does the same thing again, trying to acquire the same lock and deadlocking:
Traceback (most recent call first): ... This line is deadlocked trying to acquire the _notempty lock: File "/home/duaneg/src/cpython/Lib/multiprocessing/queues.py", line 90, in put with self._notempty: ... File "/home/duaneg/src/cpython/Lib/multiprocessing/util.py", line 50, in debug _logger.log(DEBUG, msg, *args, stacklevel=2) File "/home/duaneg/src/cpython/Lib/multiprocessing/queues.py", line 174, in _start_thread debug('Queue._start_thread()') ... Note this line is called holding the _notempty lock: File "/home/duaneg/src/cpython/Lib/multiprocessing/queues.py", line 92, in put self._start_thread() ... File "/home/duaneg/src/cpython/Lib/logging/__init__.py", line 1736, in callHandlers hdlr.handle(record) ... File "/home/duaneg/src/cpython/Lib/logging/__init__.py", line 1507, in debug self._log(DEBUG, msg, args, **kwargs) ...We could make the lock recursive, however that will just turn the deadlock into a stack overflow. At present, while a handler is processing a log record for a logger, it must not log anything to that same logger.
Arguably this is fair enough: that seems like an inherently bad idea, and perhaps this issue (and #90321) should just be closed as a user error. In fact there is a warning about exactly these sort of possible deadlocks in the logging.Handler documentation. However, this is a nasty latent bug for anyone unlucky enough to hit it, and it might be difficult for e.g. custom handlers calling into third-party code to be sure it will never log.
As an alternative, we could relatively easily eliminate this whole class of bug by temporarily disabling logging for a given logger while its handlers are being called. I'll push a PR for consideration shortly.
Either way, I don't think this is a multiprocessing bug per se.
pythongh-91555: disable logger while handling log record
vsajip commented on Mar 27, 2025
What value does that internal DEBUG logging in multiprocessing really have? What happens if you remove it - do this issue and #90321 both go away?
duaneg commented on Mar 28, 2025
I can't comment on the value of that logging but removing it will indeed fix this issue and #90321. In this case, since multiprocessing and logging are all within the standard library and somewhat integrated already, perhaps that would be an appropriate and simpler/less risky fix.
I've done a quick code inspection of the other standard logging handlers and I don't think any of them have the same issue, although some do fairly involved things like making HTTP requests. More widely, custom handlers calling into third-party code may run into this issue and either having latent bugs or need tricky work-arounds. E.g. see the Sentry logging integration code:
https://github.com/getsentry/sentry-python/blob/2f4b0280048d103d95120ad5f802ec39157e3bc8/sentry_sdk/integrations/logging.py#L44
If folks think removing the logging from multiprocessing.Queue (or even multiprocessing entirely) is a better approach I'd be happy to whip up a PR to that effect.
vsajip commented on Mar 28, 2025
Well, multiprocessing introduces a custom logging level, which is allowed by logging for very specific scenarios but not recommended in general, so it's not as cohesive a design as one might think.
I only had a quick look, but it seems to just sidestep their own internal logging because it would cause recursion errors.
I would suggest opening a discuss.python.org topic to solicit feedback from other core developers. Personally, I would consider that removing the logging from multiprocessing.Queue is reasonable (but not, for now, changing anything that doesn't need to change to address the two issues). In general, an application or library should work exactly the same independently of logging verbosity settings, which in this case multiprocessing doesn't do, ISTM.
duaneg commented on Mar 29, 2025
OK, will do, thanks!
As it happens I was looking at a different bug in multiprocessing yesterday, and with this fresh in my mind used the built-in logging: it was very useful. It is also a publicly documented part of the module's API. Removing it doesn't feel appropriate to me, but let's see what other people think.
vsajip commented on Mar 29, 2025
If not completely removing it, then perhaps consider keeping the fix in multiprocessing where I think it belongs?
57 remaining items
pythongh-91555: disable logger while handling log record (pythonGH-13…
pythongh-91555: Revert disabling of logger while handling log record. (…
pythongh-91555: add warning to docs about possibility of deadlock/inf…
Use Fork-Server As Spawn Method (blakeblackshear#18682)
Use Fork-Server As Spawn Method (blakeblackshear#18682)
Add cpu compatibility check (#27)
Use Fork-Server As Spawn Method (#18682)
Use Fork-Server As Spawn Method (#18682)
Use Fork-Server As Spawn Method (#18682)
pythongh-91555: Revert disabling of logger while handling log record. (…
pythongh-91555: add warning to docs about possibility of deadlock/inf…
DeGirum Detector for Frigate (#19111)
Logging bugfix (blakeblackshear#18465)
Use Fork-Server As Spawn Method (blakeblackshear#18682)
DeGirum Detector for Frigate (blakeblackshear#19111)