Python Multiprocessing + Logging hangs

I am trying to configure the Python logging framework to handle messages from multiple processes from a multiprocessing.Pool. In most cases, the script will hang indefinitely, although some other behaviours have been observed such as exiting without printing all log messages.

My actual code is more complex, but I have reduced it down to the following script which breaks fairly reliably on the computers I have tested it on.

#!/usr/bin/env python3

import logging
import logging.handlers
import multiprocessing
import multiprocessing.util

L = logging.getLogger(__name__)

_globalQueue = None
_globalListener = None

def basicsetup():
    global _globalQueue
    global _globalListener

    cf = logging.Formatter("[{levelname}] {created:.7f} {name} ({process}~{processName}): {message}", style="{")

    handler = logging.StreamHandler()
    handler.setLevel(logging.DEBUG)
    handler.setFormatter(cf)

    # Subprocesses should use the queue to send log messages back to a thread in the main process
    _globalQueue = multiprocessing.Queue()

    _globalListener = logging.handlers.QueueListener(_globalQueue, handler, respect_handler_level=True)
    _globalListener.start()

    # Configure logging for main thread
    process_setup(get_queue())

def get_queue():
    return _globalQueue

def process_setup(queue):
    handler = logging.handlers.QueueHandler(queue)
    logger = logging.getLogger()
    logger.setLevel(logging.DEBUG)
    logger.addHandler(handler)



def do_work(i):
    # Do something that involves logging
    # If nothing is logged, it works fine
    L.info("Hello {} from MP".format(i))

if __name__ == "__main__":
    # Also fails with other startup methods, but this is what I'm using in the actual application
    multiprocessing.set_start_method("spawn")
    # Optional, but more debugging info
    multiprocessing.util.log_to_stderr()
    # Configure logging
    basicsetup()

    # Set up multiprocessing pool, initialising logging in each subprocess
    with multiprocessing.Pool(initializer=process_setup, initargs=(get_queue(),)) as pl:
        # 100 seems to work fine, 500 fails most of the time.
        # If you're having trouble reproducing the error, try bumping this number up to 1000
        pl.map(do_work, range(500))

    if _globalListener is not None:
        # Stop the listener and join the thread it runs on.
        # If we don't do this, we may lose log messages when we exit.
        _globalListener.stop()

The idea of the script is to handle logging in subprocesses using a multiprocessing queue and the standard logging QueueListener and QueueHandler classes.

Expected behaviour - the script should log "Hello X from MP" 1000 times.

Actual behaviour - at some point (varies between runs, occasionally doesn't happen at all) the program will hang indefinitely. Pressing Ctrl+C will produce a traceback and some log messages then pressing Ctrl+C again will terminate the script with another traceback.

Example output in the case of a failed run (very much nondeterministic, but generally looks similar to this):

# First several hundred lines of logs removed - as far as I can tell, there's not much of interest missing.

[INFO] 1590652696.6525624 __mp_main__ (72404~SpawnPoolWorker-4): Hello 456 from MP
[INFO] 1590652696.6525996 __mp_main__ (72404~SpawnPoolWorker-4): Hello 457 from MP
[INFO] 1590652696.6526365 __mp_main__ (72404~SpawnPoolWorker-4): Hello 458 from MP
[INFO] 1590652696.6526761 __mp_main__ (72404~SpawnPoolWorker-4): Hello 459 from MP
[INFO] 1590652696.6527176 __mp_main__ (72404~SpawnPoolWorker-4): Hello 460 from MP
[INFO] 1590652696.6527598 __mp_main__ (72404~SpawnPoolWorker-4): Hello 461 from MP
^CTraceback (most recent call last):
  File "./test_logging.py", line 62, in <module>
    _globalListener.stop()
  File "/usr/lib/python3.8/logging/handlers.py", line 1508, in stop
    self._thread.join()
  File "/usr/lib/python3.8/threading.py", line 1011, in join
    self._wait_for_tstate_lock()
  File "/usr/lib/python3.8/threading.py", line 1027, in _wait_for_tstate_lock
    elif lock.acquire(block, timeout):
KeyboardInterrupt
[INFO/MainProcess] process shutting down
[DEBUG/MainProcess] running all "atexit" finalizers with priority >= 0
[DEBUG/MainProcess] telling queue thread to quit
[DEBUG/MainProcess] running the remaining "atexit" finalizers
[DEBUG/MainProcess] joining queue thread
^CError in atexit._run_exitfuncs:
Traceback (most recent call last):
  File "/usr/lib/python3.8/multiprocessing/util.py", line 300, in _run_finalizers
    finalizer()
  File "/usr/lib/python3.8/multiprocessing/util.py", line 224, in __call__
    res = self._callback(*self._args, **self._kwargs)
  File "/usr/lib/python3.8/multiprocessing/queues.py", line 195, in _finalize_join
    thread.join()
  File "/usr/lib/python3.8/threading.py", line 1011, in join
    self._wait_for_tstate_lock()
  File "/usr/lib/python3.8/threading.py", line 1027, in _wait_for_tstate_lock
    elif lock.acquire(block, timeout):
KeyboardInterrupt

System configuration: I have reproduced this on Python 3.8.3 on Arch Linux (up to date as of today) on 3 different machines and on Python 3.7.7 on Fedora 30.

Any insight into the problem would be much appreciated - I've been scratching my head on this one for a while.

Recommended topics

Hot tags