mirror of
https://github.com/headroomlabs-ai/headroom.git
synced 2026-08-27 14:17:10 -04:00
Three audit follow-ups from issue #327's deep-dive review. C1 — CompressionCache concurrency lock ====================================== `CompressionCache` instances are shared per `session_id` and accessed from async-dispatched threadpool workers. Pre-fix, concurrent requests for the same session raced on `_cache`, `_stable_hashes`, `_first_seen`, and `_total_tokens_saved` with no synchronization. Observable failures: * Lost-update on `_total_tokens_saved` (read-modify-write). * `RuntimeError: OrderedDict mutated during iteration` from `apply_cached` when a concurrent `store_compressed` evicts during the walk. * Lost stable-hash records — next-turn compute_frozen_count reads inconsistent state. May also explain part of SvenMeyer's `_cache: 0 entries / 1003 misses` observation: the cache was being clobbered concurrently. Added `threading.RLock` guarding all mutating methods. `RLock` (not `Lock`) so future code can call locked methods from inside another locked method without self-deadlock. Also locked `HeadroomProxy._compression_caches` dict-of-caches access via a separate `_compression_caches_lock` so two concurrent calls for the same session_id can't each create distinct CompressionCache objects (which would split the cache state between them). The `/stats` endpoint snapshots the cache list under the dict lock before iterating to avoid eviction-during-iteration. C2 — Multi-worker CCR fragmentation: documented + startup warning ================================================================= The in-memory `InMemoryCcrStore` (Rust), `_compression_caches` (Python), `session_tracker_store` (Python), and TOIN learner state are ALL per-process. Multi-worker uvicorn round-robins requests across workers, so a session whose turn-1 lands on worker A may have turn-2 land on worker B. Worker B has zero knowledge of A's CCR markers, replay cache, or prefix-cache state. Result: `Retrieve original: hash=X` markers stay in-context as opaque directives, every fresh tool_result is recompressed from scratch, and `frozen_message_count=0` causes Anthropic prefix-cache busts on every cross-worker turn. Added a "Multi-worker deployment — CCR fragmentation" section in `RUST_DEV.md` documenting the failure modes, the supported configuration (`--workers 1`), and the sticky-session workaround for horizontal scale. The proxy emits a `WARNING`-level log line on startup if `workers > 1` is detected, pointing at the doc section. C3 — Bounded compression executor with cancel-aware metrics =========================================================== `asyncio.wait_for(asyncio.to_thread(pipeline.apply), timeout=...)` cancellation does NOT propagate into the threadpool worker that's running Rust code. Once the worker has picked up the task, `concurrent.futures.Future.cancel()` returns False and the thread runs to completion. Stuck threads accumulated invisibly on asyncio's default executor, contending with unrelated `to_thread` callers (file IO, etc.). Replaced all 7 `asyncio.to_thread` call sites for `pipeline.apply()` across `proxy/handlers/anthropic.py` (3) and `proxy/handlers/openai.py` (4) with a new `HeadroomProxy._run_compression_in_executor(fn, *, timeout)` helper that: 1. Submits to a dedicated bounded `ThreadPoolExecutor` named `headroom-compress` (configurable via `ProxyConfig.compression_max_workers`; defaults to `min(32, (cpu_count or 1) * 4)`). 2. Increments `_compression_in_flight` (gauge) when work starts and decrements when work completes; tracks `_compression_in_flight_max` as a high-water mark. 3. Detects "leaked threads" by comparing wall-clock elapsed against the timeout in the worker's `finally` block. Increments `_compression_leaked_threads` when a worker finishes after its asyncio future was cancelled. Operators can see the leaked-thread rate climbing in `/stats runtime.compression_executor` BEFORE the pool fills up. Tests ===== * `TestCompressionCacheConcurrency` (3 tests) — many threads store_compressed / apply_cached / update_from_result on a single CompressionCache; assert no exceptions, no lost updates, no partial state. * `test_get_compression_cache_returns_same_instance_under_contention` — 32 concurrent `_get_compression_cache(same_id)` calls return the identical instance (would split pre-lock). * `test_proxy_compression_executor.py` (8 tests) — pool size respects config, in-flight gauge tracks running compressions, high-water mark is monotonic, timeout propagates to awaiter, leaked-thread counter increments on post-deadline completion, `/stats` surfaces all three gauges. Verification ============ * All 123 targeted regression tests pass. * `make ci-precheck` clean. * No `Co-Authored-By` trailer; conventional `fix:` prefix; no `--no-verify`.
259 lines
9.2 KiB
Python
259 lines
9.2 KiB
Python
"""Audit follow-up C3: bounded compression executor + cancel-aware metrics.
|
|
|
|
Replaces ``asyncio.to_thread`` for ``pipeline.apply()`` calls with a dedicated
|
|
``ThreadPoolExecutor`` that's bounded by ``ProxyConfig.compression_max_workers``.
|
|
|
|
Locks the following invariants:
|
|
|
|
1. The pool exists and respects ``compression_max_workers`` (auto and explicit).
|
|
2. ``compression_in_flight`` increments while a compression is running and
|
|
decrements after it completes — under load, the high-water mark moves up
|
|
as expected.
|
|
3. When a compression call exceeds its timeout, the awaiter unblocks with
|
|
``TimeoutError`` — but the worker thread keeps running (Python cannot
|
|
preempt running CPython bytecode or in-flight Rust calls), and when the
|
|
work eventually completes, ``compression_leaked_threads`` increments.
|
|
4. ``/stats runtime.compression_executor`` surfaces the gauge + counter so
|
|
operators can see leaked-thread rate.
|
|
|
|
These tests also serve as documentation: anyone reading them sees that
|
|
"timeout fired" does not mean "compression was cancelled" — it means "we
|
|
stopped waiting; the worker is still going". A bounded pool plus the
|
|
leaked-thread counter is how we make that visible.
|
|
"""
|
|
|
|
from __future__ import annotations
|
|
|
|
import asyncio
|
|
import threading
|
|
import time
|
|
|
|
import pytest
|
|
|
|
pytest.importorskip("fastapi")
|
|
|
|
from headroom.proxy.helpers import COMPRESSION_TIMEOUT_SECONDS # noqa: F401
|
|
from headroom.proxy.server import ProxyConfig, create_app
|
|
|
|
|
|
def _make_proxy(compression_max_workers: int | None = None):
|
|
"""Construct a HeadroomProxy with a no-op pipeline. Returns the proxy."""
|
|
config = ProxyConfig(
|
|
optimize=False,
|
|
cache_enabled=False,
|
|
rate_limit_enabled=False,
|
|
cost_tracking_enabled=False,
|
|
log_requests=False,
|
|
ccr_inject_tool=False,
|
|
ccr_handle_responses=False,
|
|
ccr_context_tracking=False,
|
|
image_optimize=False,
|
|
compression_max_workers=compression_max_workers,
|
|
)
|
|
app = create_app(config)
|
|
return app.state.proxy
|
|
|
|
|
|
def test_compression_executor_default_size_matches_asyncio_default() -> None:
|
|
"""When ``compression_max_workers`` is None, the resolved size should
|
|
match asyncio's default executor sizing (``min(32, (cpu+1)*4)`` style).
|
|
"""
|
|
import os
|
|
|
|
proxy = _make_proxy(compression_max_workers=None)
|
|
expected = min(32, (os.cpu_count() or 1) * 4)
|
|
assert proxy.compression_max_workers == expected
|
|
assert proxy._compression_executor._max_workers == expected
|
|
|
|
|
|
def test_compression_executor_explicit_override() -> None:
|
|
"""``ProxyConfig.compression_max_workers=N`` is honored verbatim."""
|
|
proxy = _make_proxy(compression_max_workers=3)
|
|
assert proxy.compression_max_workers == 3
|
|
assert proxy._compression_executor._max_workers == 3
|
|
|
|
|
|
def test_compression_executor_minimum_one_worker() -> None:
|
|
"""A non-positive override clamps to 1 (zero workers would deadlock)."""
|
|
proxy = _make_proxy(compression_max_workers=0)
|
|
assert proxy.compression_max_workers == 1
|
|
|
|
|
|
def test_in_flight_gauge_tracks_running_compressions() -> None:
|
|
"""While a compression is running, ``_compression_in_flight`` reads ≥ 1.
|
|
After it completes, it returns to 0. The high-water mark records the
|
|
peak observed.
|
|
"""
|
|
proxy = _make_proxy(compression_max_workers=4)
|
|
|
|
enter_event = threading.Event()
|
|
release_event = threading.Event()
|
|
observed: dict[str, int] = {}
|
|
|
|
def _slow_compression():
|
|
enter_event.set()
|
|
# Block until the test thread reads in_flight from the gauge.
|
|
release_event.wait(timeout=5.0)
|
|
return "done"
|
|
|
|
async def _drive():
|
|
task = asyncio.create_task(
|
|
proxy._run_compression_in_executor(_slow_compression, timeout=10.0)
|
|
)
|
|
# Wait for the worker to actually start.
|
|
for _ in range(50):
|
|
if enter_event.is_set():
|
|
break
|
|
await asyncio.sleep(0.01)
|
|
with proxy._compression_metrics_lock:
|
|
observed["mid_flight"] = proxy._compression_in_flight
|
|
observed["mid_flight_max"] = proxy._compression_in_flight_max
|
|
release_event.set()
|
|
result = await task
|
|
return result
|
|
|
|
result = asyncio.run(_drive())
|
|
assert result == "done"
|
|
assert observed["mid_flight"] == 1, (
|
|
f"in_flight should be 1 mid-call, got {observed['mid_flight']}"
|
|
)
|
|
assert observed["mid_flight_max"] >= 1
|
|
# Decremented after task completes.
|
|
with proxy._compression_metrics_lock:
|
|
assert proxy._compression_in_flight == 0
|
|
|
|
|
|
def test_high_water_mark_persists_after_completion() -> None:
|
|
"""``_compression_in_flight_max`` is monotonic — never decreases."""
|
|
proxy = _make_proxy(compression_max_workers=8)
|
|
|
|
enter_events = [threading.Event() for _ in range(3)]
|
|
release_events = [threading.Event() for _ in range(3)]
|
|
|
|
def _make_slow(idx: int):
|
|
def _slow():
|
|
enter_events[idx].set()
|
|
release_events[idx].wait(timeout=5.0)
|
|
return idx
|
|
|
|
return _slow
|
|
|
|
async def _drive():
|
|
tasks = [
|
|
asyncio.create_task(proxy._run_compression_in_executor(_make_slow(i), timeout=10.0))
|
|
for i in range(3)
|
|
]
|
|
# Wait for all 3 to enter.
|
|
for ev in enter_events:
|
|
for _ in range(50):
|
|
if ev.is_set():
|
|
break
|
|
await asyncio.sleep(0.01)
|
|
peak = proxy._compression_in_flight
|
|
for ev in release_events:
|
|
ev.set()
|
|
for t in tasks:
|
|
await t
|
|
return peak
|
|
|
|
peak = asyncio.run(_drive())
|
|
assert peak == 3, f"Should have observed 3 concurrent compressions, got {peak}"
|
|
# After all complete, in_flight is back to 0 but max remains 3.
|
|
with proxy._compression_metrics_lock:
|
|
assert proxy._compression_in_flight == 0
|
|
assert proxy._compression_in_flight_max >= 3
|
|
|
|
|
|
def test_timeout_fires_and_leaked_thread_is_counted() -> None:
|
|
"""When the compression exceeds ``timeout``, the awaiter sees
|
|
``TimeoutError`` immediately. The worker keeps running; when it finishes,
|
|
``_compression_leaked_threads`` increments by 1.
|
|
"""
|
|
proxy = _make_proxy(compression_max_workers=2)
|
|
finished_event = threading.Event()
|
|
timeout_seconds = 0.10
|
|
|
|
def _slow_compression():
|
|
# Sleep well past the timeout so the asyncio side cancels first.
|
|
time.sleep(timeout_seconds * 5)
|
|
finished_event.set()
|
|
return "completed-after-deadline"
|
|
|
|
async def _drive():
|
|
with pytest.raises(asyncio.TimeoutError):
|
|
await proxy._run_compression_in_executor(_slow_compression, timeout=timeout_seconds)
|
|
|
|
asyncio.run(_drive())
|
|
|
|
# Wait for the worker to actually finish (it ran past the deadline).
|
|
finished_event.wait(timeout=2.0)
|
|
# Give the worker thread a moment to update the counter under the lock.
|
|
deadline = time.monotonic() + 1.0
|
|
while time.monotonic() < deadline:
|
|
with proxy._compression_metrics_lock:
|
|
if proxy._compression_leaked_threads >= 1:
|
|
break
|
|
time.sleep(0.01)
|
|
|
|
with proxy._compression_metrics_lock:
|
|
assert proxy._compression_leaked_threads >= 1, (
|
|
f"leaked_threads should be ≥ 1; got {proxy._compression_leaked_threads}. "
|
|
f"The worker either didn't finish past the deadline, or the wrapper "
|
|
f"didn't increment the counter."
|
|
)
|
|
# In-flight gauge restored.
|
|
assert proxy._compression_in_flight == 0
|
|
|
|
|
|
def test_compression_executor_metrics_appear_in_runtime_payload() -> None:
|
|
"""``/stats runtime.compression_executor`` surfaces the new gauges."""
|
|
from fastapi.testclient import TestClient
|
|
|
|
config = ProxyConfig(
|
|
optimize=False,
|
|
cache_enabled=False,
|
|
rate_limit_enabled=False,
|
|
cost_tracking_enabled=False,
|
|
log_requests=False,
|
|
ccr_inject_tool=False,
|
|
ccr_handle_responses=False,
|
|
ccr_context_tracking=False,
|
|
image_optimize=False,
|
|
compression_max_workers=5,
|
|
)
|
|
app = create_app(config)
|
|
|
|
with TestClient(app) as client:
|
|
# The compression_executor metrics are published from the runtime
|
|
# payload (also surfaced in /health). Hit /health and look there.
|
|
r = client.get("/health")
|
|
assert r.status_code == 200
|
|
runtime = r.json()["runtime"]
|
|
assert "compression_executor" in runtime
|
|
ce = runtime["compression_executor"]
|
|
assert ce["max_workers"] == 5
|
|
assert ce["in_flight"] == 0
|
|
assert ce["leaked_threads_total"] == 0
|
|
assert ce["source"] == "explicit"
|
|
|
|
|
|
def test_explicit_None_resolves_to_auto_source() -> None:
|
|
"""When max_workers is None (default), the runtime payload reports
|
|
``source: auto``."""
|
|
from fastapi.testclient import TestClient
|
|
|
|
config = ProxyConfig(
|
|
optimize=False,
|
|
cache_enabled=False,
|
|
rate_limit_enabled=False,
|
|
cost_tracking_enabled=False,
|
|
log_requests=False,
|
|
ccr_inject_tool=False,
|
|
ccr_handle_responses=False,
|
|
ccr_context_tracking=False,
|
|
image_optimize=False,
|
|
)
|
|
app = create_app(config)
|
|
with TestClient(app) as client:
|
|
r = client.get("/health")
|
|
assert r.json()["runtime"]["compression_executor"]["source"] == "auto"
|