Overview

An asyncio server runs every request on one event loop. A handler that makes a blocking call, a synchronous subprocess.run, a future.result(), a big os.walk, a signing round trip, does not only make its own request slow. It stops the loop, so nothing else on that loop runs until the call returns. That includes the trivial /healthz route a platform polls to decide whether your instance is alive.

We met this in a sandbox service that kept dying in the middle of a scan. The scan itself was correct. A synchronous subprocess call on the loop held it for about a minute, the health check went unanswered three times, and the platform killed the instance. The work directory died with the instance, and the failure that surfaced was a missing file, which looked like a storage bug. This lab reproduces the mechanism on a laptop, adds a monitor that names the block, and fixes it.

What you’ll do

• Run a small asyncio server whose /scan handler blocks the loop.
• See a one-request test pass while the loop is stopped.
• Run a liveness probe next to a scan, and watch the instance get “killed”.
• Add a loop-lag monitor so the block names itself, then fix the handler.

What you’ll need: Python 3.12 or later (tested on 3.13), and one terminal. No Docker and no network.

Get the code

git clone https://github.com/mvpzone/mvplabs.git
cd mvplabs/codelab/blocked-event-loop
python3 -m venv .venv && . .venv/bin/activate
pip install -r requirements.txt

The only dependency is pytest. The server is plain asyncio: GET /healthz answers ok, and GET /scan calls handlers.scan() and returns what it gives back. handlers.py exists twice, in broken/ and fixed/, and the environment variable CODELAB picks which one the tests import.

The handler that blocks

scan() stands in for a slow external scanner: a child Python process that sleeps for 1.5 seconds. The handler is an async def, which is the trap. It looks asynchronous and never awaits anything:

# broken/handlers.py
import subprocess
import sys

SCAN = "import time; time.sleep(1.5); print('scan done')"  # stands in for a slow external scanner


async def scan() -> str:
    # `async def`, but the body never awaits: subprocess.run holds the whole event loop for 1.5 s.
    out = subprocess.run([sys.executable, "-c", SCAN], capture_output=True, text=True)
    return out.stdout.strip()

The test that passes

Most suites check this the obvious way: one request, one answer.

# test_single_request.py
import asyncio

import probe
from server import ServerThread


def test_scan_returns_its_result():
    """The check most suites have: one request, one answer. It cannot see a starved loop."""
    with ServerThread() as srv:
        body = asyncio.run(probe.get(srv.port, "/scan", timeout=10))
    assert body == "scan done"

CODELAB=broken python -m pytest -q test_single_request.py

.                                                                        [100%]
1 passed in 1.54s

The test is green because the scan finishes and returns the right answer. It sends nothing else while the scan runs, so nothing can tell it the loop was stopped.

The probe that fails

probe.py does what a platform’s liveness check does: GET /healthz every 0.1 seconds with a 0.3-second timeout, and three misses in a row mean the instance is killed. (The incident ran 3 misses over 90 seconds; the shape is the same, scaled down so the lab takes seconds.) The next test starts a scan and the probe together:

# test_liveness.py
import asyncio

import probe
from server import ServerThread


def test_healthz_stays_up_during_a_scan():
    """Run a scan and the liveness probe at the same time. A platform kills after 3 misses in a row."""

    async def scenario(port: int):
        done = asyncio.Event()
        watcher = asyncio.ensure_future(probe.liveness(port, until=done))
        await asyncio.sleep(0.2)                       # let the probe establish a baseline
        body = await probe.get(port, "/scan", timeout=10)
        done.set()
        return body, *(await watcher)

    with ServerThread() as srv:
        body, verdict, seconds = asyncio.run(scenario(srv.port))
    print(f"scan={body!r} liveness={verdict} after {seconds:.1f}s")
    assert verdict == "alive", f"instance killed {seconds:.1f}s in: /healthz missed 3 probes in a row"

The server runs on its own event loop in a thread (ServerThread), so the probe in the test is a separate observer and is not stopped along with it.

CODELAB=broken python -m pytest -q -s test_liveness.py

[loop-lag] event loop blocked for 1.53s
scan='scan done' liveness=killed after 1.3s
F
...
E       AssertionError: instance killed 1.3s in: /healthz missed 3 probes in a row
E       assert 'killed' == 'alive'
...
1 failed in 1.75s

The scan returned 'scan done', the same correct answer as the previous step. The probe was killed 1.3 seconds in, well before the scan ended. On a real platform that is the instance dying mid-work, and whatever lived only in that instance, a scratch directory, an in-memory job, goes with it. The error you then see is about that missing state, not about the loop.

Make the block name itself

The first line of that output, [loop-lag], came from loopmon.py, which is how the real incident stopped being a mystery. The monitor sleeps for a short interval and measures how late it wakes. If the loop was free, the lateness is close to zero. Whatever is left was spent blocked:

# loopmon.py
"""Loop-lag monitor: sleep a short interval; whatever the loop took beyond it was spent blocked."""
import asyncio
import time

LAGS: list[float] = []


async def monitor(interval: float = 0.05, threshold: float = 0.25) -> None:
    while True:
        start = time.perf_counter()
        await asyncio.sleep(interval)
        lag = time.perf_counter() - start - interval
        if lag > threshold:
            LAGS.append(lag)
            print(f"[loop-lag] event loop blocked for {lag:.2f}s", flush=True)

It costs one task. It does not tell you which call blocked, but it turns “the instance restarts sometimes” into a line you can grep for and a duration you can compare to the probe period. In the incident it also found the next offenders on its first deploy: a capability probe that ran several synchronous --version calls one after another on the loop.

Make it a test, so a block fails the build before it fails a probe:

# test_loopmon.py
import asyncio

import probe
from server import ServerThread


def test_a_block_names_itself():
    """The monitor turns a mystery liveness failure into a line that says the loop was blocked, and for how long."""
    with ServerThread() as srv:
        asyncio.run(probe.get(srv.port, "/scan", timeout=10))
        lags = list(srv.lags)
    assert lags == [], f"[loop-lag] the loop was blocked: {[round(x, 2) for x in lags]}"

CODELAB=broken python -m pytest -q test_loopmon.py

E       AssertionError: [loop-lag] the loop was blocked: [1.47]
E       assert [1.4695617919962387] == []
...
----------------------------- Captured stdout call -----------------------------
[loop-lag] event loop blocked for 1.47s
1 failed in 1.54s

This test needs no probe and no timing race: any block over 0.25 seconds fails it. It is the cheaper of the two checks to keep in a suite.

Await the child instead

The child process is the same. The change is that the loop awaits it, so while the child runs, the loop serves other requests:

# fixed/handlers.py
import asyncio
import sys

SCAN = "import time; time.sleep(1.5); print('scan done')"  # stands in for a slow external scanner


async def scan() -> str:
    # Same child process, but the loop awaits it instead of waiting on it.
    proc = await asyncio.create_subprocess_exec(sys.executable, "-c", SCAN, stdout=asyncio.subprocess.PIPE)
    out, _ = await proc.communicate()
    return out.decode().strip()

CODELAB=fixed python -m pytest -q -s -v

============================= test session starts ==============================
platform darwin -- Python 3.13.14, pytest-9.1.1, pluggy-1.7.0
rootdir: /Users/vinesh/var/tmp/l4-dry
collected 3 items

test_liveness.py scan='scan done' liveness=alive after 1.7s
.
test_loopmon.py .
test_single_request.py .

============================== 3 passed in 4.83s ===============================

The probe ran for the whole 1.7 seconds the scan took and never missed. The monitor stayed silent. The single-request test is unchanged, which is the point: it passed before and it passes now, and it never told the two apart.

Not every blocking call has an async version. For a synchronous library call or CPU-bound work, move it off the loop with await asyncio.to_thread(fn, *args) at the nearest async seam. In the incident we chose the async subprocess API over wrapping subprocess.run in a thread because it is the right model for executing a child; the thread is the tool for everything that has no async form. A publish that nobody awaits can be fired and forgotten.

What to keep

• A synchronous call inside async def is a liveness bug before it is a latency bug. It stops every other task on the loop, including the health check, and a platform that probes liveness will kill the instance mid-work.
• The failure shows up somewhere else. State that died with the instance surfaces as a missing file or a timeout, so the block gets misattributed to storage or to the work itself.
• A single-request test cannot see it. Check with a second observer that runs at the same time, or with a loop-lag monitor in the suite.
• Put a loop-lag monitor in the service. It costs one task, and the next block names itself instead of arriving as a mystery restart.
• Fix at the async seam: await the async API where one exists, asyncio.to_thread where it does not.

The handler was async in name. The loop could tell the difference.