[Python] Lock-order deadlock introduced in 1.75.1; reachable without user-held cycles since 1.83.0

What version of gRPC and what language are you using?

Python grpcio.

The lock inversion was introduced in 1.75.1. Last clean release: 1.75.0. First affected release: 1.75.1.

A second regression in 1.83.0 makes the inversion reachable during ordinary completed unary calls without any user-created reference cycle. Both regressions are present in the latest tested release, 1.83.1.

The underlying lock inversion remains on master. Current master does, however, clear _done_callbacks after extracting them, which appears to remove the additional completed-call cycle introduced in 1.83.0.

What operating system (Linux, Windows,...) and version?

Linux.

What runtime / compiler are you using (e.g. python version or version of gcc)

CPython 3.12.6.

What did you do?

I ran a grpc.aio client loop making many small unary calls while approximately 200 other threads repeatedly called logging.config.dictConfig() with a normal handler/formatter configuration. (I am planning to fix this inefficient behaviour in my own code, but it has revealed a real bug.)

The reproduction below explicitly retains completed calls in cyclic garbage so that it demonstrates the underlying inversion on every affected release from 1.75.1 onward.

On grpcio 1.83.0 and 1.83.1, that explicit user-side cycle is unnecessary: gRPC itself retains every completed call in a reference cycle.

Lock inversion

There are two opposing lock-acquisition paths.

1. init_grpc_aio() in v1.83.1 acquires the process-global _global_aio_state.lock and calls _initialize_per_loop() while holding it. That calls get_working_loop(); the running-loop path in common.pyx.pxi executes:

   _LOGGER.debug(f"[_cygrpc] Loaded running loop: {id(loop)=}")
   

   If logging’s level cache was just cleared by dictConfig(), Logger.isEnabledFor() acquires logging._lock. The acquisition order is therefore:

   _global_aio_state.lock -> logging._lock
   

2. _AioCall.__dealloc__ in v1.83.1 synchronously calls shutdown_grpc_aio(), which acquires _global_aio_state.lock.

   A cyclic-GC finalizer can execute on a thread while that thread is inside dictConfig() and holds logging._lock. The reverse acquisition order is therefore:

   logging._lock -> _global_aio_state.lock
   

This initialization path is reached for every RPC, not only during channel or server construction: _AioCall.__cinit__ calls init_grpc_aio(). Consequently, the running-loop debug call executes under _global_aio_state.lock once per call.

The debug level does not need to be enabled. Logger.debug() first calls Logger.isEnabledFor(DEBUG). dictConfig() clears logger level caches, so the next isEnabledFor(DEBUG) is a cache miss and acquires logging._lock while recomputing and caching the effective-level result. A disabled debug statement can therefore participate in this deadlock.

First regression: log under the AIO lock from 1.75.1

Every available release between 1.74.0 and 1.83.1 was tested with the exact script below in a fresh virtual environment using CPython 3.12.6 on Linux and 200 dictConfig threads.

“Clean” means both counters increased on every two-second progress line for 90 seconds. “Deadlock” means the watchdog reported no progress. No run was ambiguous.

grpcio	result	detail	runs
1.74.0	clean	56,874 calls / 348,041 reconfigures at 90 s	1
1.75.0	clean	47k–56k calls / 300k+ reconfigures at 90 s	3
1.75.1	deadlock	12–13 s, frozen at calls=1..3	3
1.76.0, 1.78.0, 1.78.1, 1.80.0, 1.81.0, 1.81.1, 1.82.0, 1.82.1, 1.82.2, 1.83.0, 1.83.1	deadlock	12–13 s each, frozen at calls=1..2	1 each

Last clean: 1.75.0. First affected: 1.75.1.

The v1.75.0...v1.75.1 comparison shows the triggering change in aio/common.pyx.pxi at v1.75.1.

Version 1.75.0 has no _LOGGER calls in that file. Version 1.75.1 rewrites get_working_loop() and adds _get_running_loop() containing:

_LOGGER.debug(f"[_cygrpc] Loaded running loop: {id(loop)=}")

It also adds debug calls for the policy-loop fallback paths: “Loaded policy loop” and “Created policy loop”.

Version 1.75.1 also adds a sys is None or sys.is_finalizing() early return inside shutdown_grpc_aio(), still under _global_aio_state.lock; the locking itself is unchanged across this release boundary.

Version 1.75.0 and earlier already contain this debug call in _actual_aio_initialization() while the global lock is held:

_LOGGER.debug("Using %s as I/O engine", _global_aio_state.engine)

That call runs only when the process-level AIO refcount transitions from zero to one. It is therefore an older latent lock-order hazard, but it is not the per-RPC practical trigger introduced in 1.75.1.

Second regression: completed calls become cyclic garbage from 1.83.0

From grpcio 1.83.0, the inversion is reachable without a user-created cycle.

Channel._register_call() in v1.83.1 registers every call this way:

self._active_calls.add(call)
call.add_done_callback(self._active_calls.discard)

Call.add_done_callback() creates a callback that strongly captures the call:

cb = partial(callback, self)
self._cython_call.add_done_callback(cb)

In released 1.83.x, _AioCall._set_status() invokes the callbacks but does not clear _done_callbacks. This leaves the completed call in a cycle containing, at minimum:

UnaryUnaryCall -> _AioCall -> functools.partial -> UnaryUnaryCall

As a result, completed calls are finalized by cyclic GC rather than ordinary reference counting on the asyncio thread. Cyclic GC may run in any thread that allocates Python objects, including a thread currently holding logging._lock inside dictConfig().

This was measured on a real 1,365-step workload containing 1,379 call objects per run:

grpcio/configuration	call objects reaching cyclic GC
1.80.0	0 / 1,379 per run
1.82.2	0 / 1,379 per run
1.83.0 with Channel._register_call() replaced by a no-op	0 / 1,379 per run
1.83.0	1,375–1,377 / 1,379 per run

Across 13 runs of the clean configurations, every call died by reference counting on the asyncio thread. With unmodified 1.83.0, approximately 96% of the cyclically collected calls were reclaimed on threads other than the asyncio thread.

A gc.DEBUG_SAVEALL census on 1.83.0 found exactly 1,376 instances of each of these types in the collected cycle groups:

_AioCall
UnaryUnaryCall
functools.partial
_asyncio.Task
coroutine

The same census found zero instances of those types in collected cycles on 1.82.2.

Therefore:

The lock inversion exists from 1.75.1. From 1.83.0 it is reachable with no user-side cycle at all: Channel._register_call() makes completed calls cyclic garbage, so a grpc.aio client running alongside a thread that calls logging.config.dictConfig() is exposed.

Current call.pyx.pxi on master now clears the callback list before invoking it:

callbacks = self._done_callbacks
self._done_callbacks = []
for callback in callbacks:
    callback()

That appears to break this particular completed-call cycle on master, but the released 1.83.x behavior and the underlying lock inversion remain relevant.

Reproduction

The following self-contained script starts an in-process AsyncIO server, continuously makes unary calls, retains completed calls in cyclic garbage, and repeatedly reconfigures logging from many threads.

It was validated on grpcio 1.83.0, which froze after the first one or two RPCs, and on 1.74.0 and 1.75.0, which ran clean.

The explicit cycle = [call] block is required to expose the inversion consistently on 1.75.1 through 1.82.2. It may be removed when testing 1.83.0 or 1.83.1 because those versions create the completed-call cycle internally.

Because deadlocked threads may prevent even os._exit() in the watchdog from ending the process, run the script under an external hard timeout:

timeout -s KILL 120s python repro.py

import asyncio
import gc
import logging
import logging.config
import os
import threading
import time

import grpc
import grpc.aio


CONFIG_THREADS = int(os.environ.get("CONFIG_THREADS", "200"))

LOGGING_CONFIG = {
    "version": 1,
    "disable_existing_loggers": False,
    "formatters": {
        "plain": {
            "format": "%(levelname)s %(name)s %(message)s",
        },
    },
    "handlers": {
        "sink": {
            "class": "logging.StreamHandler",
            "formatter": "plain",
            "stream": "ext://sys.stderr",
        },
    },
    "root": {
        "level": "WARNING",
        "handlers": ["sink"],
    },
}

calls_completed = 0
configs_completed = 0


def make_cyclic_garbage(count: int = 50) -> None:
    for _ in range(count):
        cycle = []
        cycle.append(cycle)


def reconfigure_logging() -> None:
    global configs_completed

    while True:
        make_cyclic_garbage()
        logging.config.dictConfig(LOGGING_CONFIG)
        configs_completed += 1


def watchdog() -> None:
    previous = None

    while True:
        time.sleep(2)
        current = (calls_completed, configs_completed)
        print(
            f"grpcio={grpc.__version__} calls={current[0]} "
            f"configs={current[1]}",
            flush=True,
        )
        if current == previous:
            print("No progress; inspect threads with py-spy or gdb.", flush=True)
        previous = current


async def echo(
    request: bytes,
    context: grpc.aio.ServicerContext,
) -> bytes:
    return request


async def main() -> None:
    global calls_completed

    gc.set_threshold(50, 5, 5)

    server = grpc.aio.server()
    server.add_generic_rpc_handlers(
        (
            grpc.method_handlers_generic_handler(
                "deadlock.Repro",
                {
                    "Echo": grpc.unary_unary_rpc_method_handler(
                        echo,
                        request_deserializer=lambda value: value,
                        response_serializer=lambda value: value,
                    ),
                },
            ),
        )
    )

    port = server.add_insecure_port("127.0.0.1:0")
    await server.start()

    channel = grpc.aio.insecure_channel(f"127.0.0.1:{port}")
    rpc = channel.unary_unary(
        "/deadlock.Repro/Echo",
        request_serializer=lambda value: value,
        response_deserializer=lambda value: value,
    )

    for index in range(CONFIG_THREADS):
        threading.Thread(
            target=reconfigure_logging,
            name=f"dictConfig-{index}",
            daemon=True,
        ).start()

    threading.Thread(
        target=watchdog,
        name="watchdog",
        daemon=True,
    ).start()

    try:
        while True:
            call = rpc(b"x")
            await call
            calls_completed += 1

            # This explicit call cycle is needed to exercise versions
            # 1.75.1 through 1.82.2. It may be removed on >=1.83.0,
            # where Channel._register_call() creates an internal cycle.
            cycle = [call]
            cycle.append(cycle)
            del call, cycle
    finally:
        await channel.close()
        await server.stop(None)


if __name__ == "__main__":
    asyncio.run(main())

What did you expect to see?

The client and logging-reconfiguration loops should continue making progress.

Neither gRPC initialization nor destruction of an AsyncIO call should create a cross-library lock-order dependency with Python logging. Completed calls should also release their done callbacks after those callbacks have fired.

What did you see instead?

The process reproducibly freezes at 0% CPU with no Python exception or error message.

With the reproduction above, affected releases froze after 12–13 seconds, with the calls counter stopping on the first one to three RPCs. grpcio 1.83.0 and 1.83.1 froze after the first one or two RPCs; 1.74.0 and 1.75.0 ran clean for 90 seconds.

py-spy and gdb show two blocked threads:

• One holds _global_aio_state.lock in init_grpc_aio() and waits for logging._lock through _LOGGER.debug() / Logger.isEnabledFor().
• One holds logging._lock in logging.config.dictConfig() and waits for _global_aio_state.lock through cyclic GC, _AioCall.__dealloc__, and shutdown_grpc_aio().

Anything else we should know about your project / environment?

The underlying locking paths remain on master:

with _global_aio_state.lock:
    _global_aio_state.refcount += 1
    ...
    _initialize_per_loop()

def __dealloc__(self):
    if self.call:
        grpc_call_unref(self.call)
    shutdown_grpc_aio()

Suggested directions for a fix:

1. Do not perform logging while holding _global_aio_state.lock.

   Resolve the working loop and perform its diagnostic logging before taking the global lock, or otherwise move the logging out of the critical section. _actual_aio_initialization() also emits an I/O-engine debug message while called from the locked initialization section; that log should be moved outside the lock as well.

2. Do not synchronously acquire _global_aio_state.lock from _AioCall.__dealloc__.

   If the lock is contended, defer the AIO-state reference decrement and possible shutdown to a safe execution context.

3. Ensure completed callbacks do not retain calls.

   Backport or retain the current master behavior that clears _done_callbacks before invoking the callbacks. Alternatively, make the _register_call() bookkeeping callback avoid capturing a strong reference to the call, for example through weak-reference-based removal.

   Besides removing the ordinary path to this deadlock, breaking the cycle avoids approximately 1,400 cyclic-garbage groups per process in the measured workload.

For example, the initialization path could have this shape:

cdef object loop = get_working_loop()

with _global_aio_state.lock:
    _global_aio_state.refcount += 1
    if _global_aio_state.refcount == 1:
        _actual_aio_initialization()
    _initialize_per_loop(loop)

# Any diagnostic logging belongs outside the global AIO lock.

The finalizer path should have this property, with the exact deferral mechanism chosen by the implementation:

def __dealloc__(self):
    if self.call:
        grpc_call_unref(self.call)

    # Must not wait synchronously for _global_aio_state.lock here.
    defer_grpc_aio_refcount_decrement(self._loop)

User-side mitigations

Pinning grpcio<=1.75.0 avoids the lock-inversion regression. The bisection above verified 1.74.0 and 1.75.0 as clean.

For workloads that do not themselves retain call objects in cycles, grpcio<=1.82.2 also avoids the ordinary completed-call trigger introduced in 1.83.0. In the measured 1.80.0 workload, including the production image, 0 of 4,137 call objects reached cyclic GC.

This second mitigation is narrower: abandoned or cancelled calls, application-created cycles, or tracebacks that retain frames may still make calls cyclic on older versions. Those paths were not measured.

Relevant CPython discussions

• python/cpython#96727 directly documents dictConfig()/fileConfig() taking the logging module lock and then entering handler shutdown, and separately notes that Logger.isEnabledFor() can acquire the module lock. It is closed without a linked PR.
• python/cpython#84551 / BPO-40371 is an older, still-open report titled “Deadlock in logging.config.dictConfig”. Its migrated record contains only an attached thread dump and no linked PR, so it does not establish this exact GC/finalizer mechanism.