Debugging a Ghost Re-Entrancy Bug in Python Async Logging Under Load

I ran into a bug that felt impossible: my async application was “sometimes” hanging, and the stack traces looked totally normal—until I added one line of debug logging and the hang became a little more frequent. That’s the moment I knew I was dealing with a re-entrancy issue: code that accidentally re-enters itself while it’s already in the middle of doing the same work.

In this post I’ll document the exact failure mode I found: a Python logging setup where a custom handler tried to log while logging was already in progress, causing recursive calls and deadlocks (or a “freeze” that looked like network slowness). I’ll build a minimal reproduction, show how to diagnose it, and then fix it with a concrete pattern.

---

The minimal reproduction: custom async logging handler that re-enters itself

I wanted a handler that sends logs over the network. To keep the app fast, I used an async queue and a background task. The twist: the “sending” path also logged errors, which turned out to re-enter the logger while the logger was still holding internal locks.

Here’s a small, runnable reproduction. It uses:

• logging’s global machinery (including internal locks),
• a custom handler that formats records,
• and a background worker that logs failures from inside the handler’s critical path.

Repro code

import asyncio
import logging
import sys
from typing import Optional


class ReentrantNetworkHandler(logging.Handler):
    """
    A handler that simulates sending logs over a network using an asyncio Task.
    The bug: when sending fails, it logs again via the same logger, re-entering
    the logging system while the handler is still processing the original record.
    """

    def __init__(self) -> None:
        super().__init__()
        self.queue: asyncio.Queue[Optional[logging.LogRecord]] = asyncio.Queue()
        self.worker_started = False

    def emit(self, record: logging.LogRecord) -> None:
        """
        Called by logging synchronously.
        We enqueue the record for async sending.
        """
        try:
            self.queue.put_nowait(record)
        except asyncio.QueueFull:
            # In real life you'd drop logs or block; here we just log.
            # This already uses logging, which can cause re-entrancy.
            logger = logging.getLogger("app")
            logger.error("Queue full while emitting: %s", record.getMessage())

        # Start the worker lazily once an event loop exists.
        # In a real app you’d wire this at startup.
        if not self.worker_started:
            self.worker_started = True
            loop = asyncio.get_event_loop()
            loop.create_task(self._worker())

    async def _worker(self) -> None:
        while True:
            record = await self.queue.get()
            if record is None:
                return

            # Simulate a failure on a specific message.
            msg = record.getMessage()
            try:
                await self._send_over_network(msg)
            except Exception:
                # BUG: logging here re-enters logging while the original emit
                # path may still be inside logging internals.
                logger = logging.getLogger("app")
                logger.exception("Network send failed for: %s", msg)

    async def _send_over_network(self, msg: str) -> None:
        await asyncio.sleep(0.01)
        if msg.endswith("boom"):
            raise RuntimeError("simulated network error")


async def main() -> None:
    global logger
    logger = logging.getLogger("app")
    logger.setLevel(logging.DEBUG)

    # Make logging print to stderr so we can see it.
    stream_handler = logging.StreamHandler(sys.stderr)
    stream_handler.setLevel(logging.DEBUG)

    # The buggy handler
    net_handler = ReentrantNetworkHandler()
    net_handler.setLevel(logging.DEBUG)

    logger.addHandler(stream_handler)
    logger.addHandler(net_handler)

    # Trigger the failure
    logger.info("hello world")
    logger.info("this will boom")

    # Give the worker time; in the broken version, you often see recursion
    # and the program may appear to hang under load.
    await asyncio.sleep(0.2)


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

What I observed when I ran it

On my machine, once "this will boom" happened, the handler tried to log "Network send failed...", which created a new LogRecord. That new record flowed back through emit(), which could start the worker and (critically) run while the logger was still in the middle of handling the previous record.

Sometimes this ends in:

• runaway recursive logging (tons of stack frames),
• apparent “deadlock-like” hangs,
• or extreme CPU use due to repeated exceptions.

Even when it “eventually finishes,” it’s clearly wrong.

---

Why this happens: logging holds internal locks

logging is thread-safe. To do that, it uses internal synchronization. When you call logger.error(...) inside code that itself is being called by the logging system, you can get re-entrancy into the same locked path.

In synchronous code, this might manifest as repeated recursion without obvious lock contention. In async code under load, it’s more chaotic because:

• records can be emitted quickly,
• the background task logs while the event loop continues,
• and the logger’s lock timing depends on scheduling.

The key debugging clue for me was: adding or changing logging changed timing and frequency. That’s classic “Heisenbug” behavior.

---

Diagnosis: make the recursion visible

To confirm I wasn’t chasing the wrong thing, I added a re-entrancy guard: a thread-local (or context-local) flag set when emit() runs, so I could detect nested logging.

Here’s a version with instrumentation that prints a warning when emit() is invoked while we’re already emitting:

import asyncio
import logging
import sys
import threading
from typing import Optional


class DetectingReentrantNetworkHandler(logging.Handler):
    def __init__(self) -> None:
        super().__init__()
        self.queue: asyncio.Queue[Optional[logging.LogRecord]] = asyncio.Queue()
        self.worker_started = False
        self._emitting = threading.local()
        self._emitting.flag = False

    def emit(self, record: logging.LogRecord) -> None:
        # Detect re-entrancy into the handler while already emitting.
        if getattr(self._emitting, "flag", False):
            print(f"[DETECT] re-entrant emit for message: {record.getMessage()}", file=sys.stderr)

        self._emitting.flag = True
        try:
            self.queue.put_nowait(record)
        finally:
            self._emitting.flag = False

        if not self.worker_started:
            self.worker_started = True
            loop = asyncio.get_event_loop()
            loop.create_task(self._worker())

    async def _worker(self) -> None:
        while True:
            record = await self.queue.get()
            if record is None:
                return

            msg = record.getMessage()
            try:
                await self._send_over_network(msg)
            except Exception:
                # Still the problematic behavior: logging from inside the handler's async worker.
                logger = logging.getLogger("app")
                logger.exception("Network send failed for: %s", msg)

    async def _send_over_network(self, msg: str) -> None:
        await asyncio.sleep(0.01)
        if msg.endswith("boom"):
            raise RuntimeError("simulated network error")


async def main() -> None:
    logger = logging.getLogger("app")
    logger.setLevel(logging.DEBUG)
    logger.handlers.clear()

    logger.addHandler(logging.StreamHandler(sys.stderr))

    net_handler = DetectingReentrantNetworkHandler()
    net_handler.setLevel(logging.DEBUG)
    logger.addHandler(net_handler)

    logger.info("hello world")
    logger.info("this will boom")

    await asyncio.sleep(0.2)


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

What the detector told me

As soon as the simulated network failure happened, the detector printed re-entrant emit... for the new log record created by logger.exception(...). That proved the handler caused nested logging.

---

The fix: never log from inside the logging-driven failure path

The robust pattern I used is:

1. The handler’s worker catches exceptions.
2. It does not use the same logger to report failures.
3. Instead it uses a safe fallback:
   • either print(...),
   • or writes directly to sys.stderr,
   • or uses a separate “internal logger” that doesn’t route back through the same handler.

Below is a fixed version that avoids re-entering logging by writing directly to sys.stderr.

Fixed code

import asyncio
import logging
import sys
from typing import Optional


class SafeNetworkHandler(logging.Handler):
    """
    Fixed version:
    - Worker errors do NOT call logger.exception(...)
    - Worker writes to stderr directly to avoid re-entering logging.
    """

    def __init__(self) -> None:
        super().__init__()
        self.queue: asyncio.Queue[Optional[logging.LogRecord]] = asyncio.Queue()
        self.worker_started = False

    def emit(self, record: logging.LogRecord) -> None:
        try:
            self.queue.put_nowait(record)
        except asyncio.QueueFull:
            # Still avoid calling logger here; write to stderr directly.
            print("[SafeNetworkHandler] queue full; dropping log", file=sys.stderr)

        if not self.worker_started:
            self.worker_started = True
            loop = asyncio.get_event_loop()
            loop.create_task(self._worker())

    async def _worker(self) -> None:
        while True:
            record = await self.queue.get()
            if record is None:
                return

            msg = record.getMessage()
            try:
                await self._send_over_network(msg)
            except Exception as e:
                # Critical fix: don't call logger.* from here.
                print(f"[SafeNetworkHandler] send failed: {e!r} for msg={msg!r}", file=sys.stderr)

    async def _send_over_network(self, msg: str) -> None:
        await asyncio.sleep(0.01)
        if msg.endswith("boom"):
            raise RuntimeError("simulated network error")


async def main() -> None:
    logger = logging.getLogger("app")
    logger.setLevel(logging.DEBUG)
    logger.handlers.clear()

    logger.addHandler(logging.StreamHandler(sys.stderr))

    net_handler = SafeNetworkHandler()
    net_handler.setLevel(logging.DEBUG)
    logger.addHandler(net_handler)

    logger.info("hello world")
    logger.info("this will boom")

    await asyncio.sleep(0.2)


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

What changed

• The program still reports the “send failed” error, but it does so without generating new LogRecords.
• That breaks the recursive chain.
• Under load, the behavior stays stable because the handler no longer re-enters the logging system as part of error handling.

---

Practical debugging checklist I used for this class of bug

1. Search for logger.* calls inside anything that runs under logging.
   That includes custom handlers, filters, formatters, and error paths.

2. Add a re-entrancy detector.
   A simple flag around emit() (or around your handler logic) can confirm nested logging instantly.

3. Replace error-reporting inside the handler with a “side channel.”
   For example, sys.stderr.write(...) or a separate logger that doesn’t use the problematic handler.

4. Assume timing will change the bug.
   If adding logging changes the hang, instrument the control flow with minimal-impact prints or counters.

---

Wrap-up

I tracked this down by building a tiny async logging handler that intentionally logs from inside its own failure path, then proving the re-entrancy with a detector around emit(). The core lesson is that logging is not just “output”—it’s code with locks and control flow, so emitting logs from within logging internals can create recursive behavior and deadlock-like hangs. The fix was straightforward and effective: stop using the main logger for handler-internal error reporting, and route those internal errors to a safe fallback like sys.stderr.