headroom/tests/test_proxy_compression_executor.py
chopratejas ea78cf6252 fix(proxy): cache concurrency lock, multi-worker docs, bounded compression executor
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`.
2026-05-01 15:25:18 -07:00

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"