logging deadlock when dictConfig or fileConfig used concurrently with custom handlers

[shalabhc]

Bug report

The attached code below fairly reliably reproduces the deadlock.

There is a module level lock in logging/__init__.py. Each handler has its own lock also, implemented as an instance attribute.

Calling dictConfig (or fileConfig) locks them in this order:

1. acquire module lock
2. acquire handler locks in _clearExistingHandlers, which calls shutdown

Calling some logging functions from within a custom emit() can lock in this order:

1. acquire handler lock (acquired before emit is called)
2. acquire module lock (if emit calls into a library that uses logging.getLogger(), it will acquire the module lock)

The same issue exists with fileConfig. Note calling fileConfig during program execution is ok as per the docs: This function can be called several times from an application, allowing an end user to select from various pre-canned configurations (if the developer provides a mechanism to present the choices and load the chosen configuration).

While emit may not directly include code to logging.getLogger() it may call into another library that happens to do that. Even logger.isEnabledFor and logger.setLevel etc acquire the module lock and have the same issue.

Your environment

• CPython versions tested on: 3.8.13, 3.10.5
• Operating system and architecture: mac-os

Code to reproduce deadlock

import logging
import logging.config
import threading
import time
import os


def tick(msg):
    print(time.strftime("%H:%M:%S"), msg)


class CustomHandler(logging.Handler):
    def emit(self, record):
        logging.getLogger("other-logger")  # comment out this line to avoid deadlock
        pass


def log_loop(i):
    while True:
        logger = logging.getLogger()
        logger.setLevel(logging.INFO)
        logger.info("some log")

        tick(f"tick from log_loop-{i}")


def config_loop():
    while True:
        config_once()


def config_once():
    logging.config.dictConfig(
        {
            "version": 1,
            "handlers": {"custom": {"class": "logging_deadlock.CustomHandler"}},
            "root": {"handlers": ["custom"]},
        }
    )
    tick(f"tick from config_once. pid: {os.getpid()}")


if __name__ == "__main__":
    for i in range(10):
        t = threading.Thread(target=log_loop, args=[i], name=f"log_loop-{i}")
        t.start()

    t2 = threading.Thread(target=config_loop, name="config_loop")
    t2.start()

Call stacks that deadlocked

Thread 0x305833000 (idle): "log_loop-3"
    _acquireLock (logging/__init__.py:226)  # asking for the module lock
    getLogger (logging/__init__.py:1329)
    getLogger (logging/__init__.py:2079)
    emit (logging_deadlock.py:16)
    handle (logging/__init__.py:968)   # this acquired the handler lock
    callHandlers (logging/__init__.py:1696)
    handle (logging/__init__.py:1634)
    _log (logging/__init__.py:1624)
    info (logging/__init__.py:1477)
    log_loop (logging_deadlock.py:24)
    run (threading.py:953)
    _bootstrap_inner (threading.py:1016)
    _bootstrap (threading.py:973)

Thread 0x30C848000 (idle): "config_loop"
    acquire (logging/__init__.py:917)  # asking for the handler lock
    shutdown (logging/__init__.py:2181)
    _clearExistingHandlers (logging/config.py:275)
    configure (logging/config.py:544)  # acquired the module lock
    dictConfig (logging/config.py:810)
    config_once (logging_deadlock.py:35)
    config_loop (logging_deadlock.py:31)
    run (threading.py:953)
    _bootstrap_inner (threading.py:1016)
    _bootstrap (threading.py:973)

[vsajip]

I don't think this is a bug in logging, but a rather contrived example. It would be a bug in the custom handler that called e.g. getLogger() during an emit(). As emit() calls are done within a handler lock/release, they don't have complete freedom as to what they can do.

[shalabhc]

I agree this example looks contrived. However we did see it in production.

Both of the following possibilities seem reasonable:

1. a custom log handler writes to a database or another storage system (eg code from a cookbook showing an SQLAlchemyHandler)
2. the write path for the storage system has its own logging calls (eg SQLAlchemy CursorResult.__init__ calls _should_log_debug which calls isEnabledFor)

These are sufficient to lock the logging module within an emit() call.

That said, I'm not sure what the right solution here is. Some alternatives:

1. The docs recommend that users lock any active handlers before calling dictConfig or fileConfig to avoid deadlocks.
2. dictConfig and fileConfig themselves lock all active handlers before locking the module.
3. _clearExistingHandlers is reimplemented without locking the handlers.

[vsajip]

I prefer to just add documentation - you need an unusual set of circumstances to hit this (very specialised handler and repeated configuration during program execution), and in this case the very few people who need to do this and hit a deadlock will need to find a workaround.