headroom/tests/test_prometheus_obs_counters.py
Sebastian Schkudlara 517bf992cf
fix(proxy): quarantine compression while timed-out workers run (#2292)
## Description

A request-side `asyncio.wait_for()` timeout stops waiting, but it cannot
preempt an executor thread that already started. The proxy counted those
late workers and still admitted more compression, so repeated slow calls
could consume the whole compression pool and charge every request
another full timeout.

This change tracks running post-timeout workers as timeout debt and
quarantines request-path compression while that debt is non-zero. New
attempts raise `CompressionQuarantinedError` before executor admission,
using an `asyncio.TimeoutError` subclass so Python 3.10 handlers apply
the existing compression-failure policy. Quarantine clears automatically
after all known timed-out workers genuinely exit.

Mitigates #946 and #810. It does not attempt to kill the first running
thread; Python cannot safely preempt it.

## Type of Change

- [x] Bug fix (non-breaking change that fixes an issue)
- [ ] New feature (non-breaking change that adds functionality)
- [ ] Breaking change (fix or feature that would cause existing
functionality to change)
- [x] Documentation update
- [ ] Performance improvement
- [ ] Code refactoring (no functional changes)

## Changes Made

- Track started, finished, timed-out, and debt-recorded state under the
existing compression metrics lock.
- Reject new compression before enqueue while timed-out workers remain;
clear quarantine on the final worker exit.
- Preserve queued-timeout behavior: work cancelled before worker start
does not activate quarantine; a cancellation/start race is
conservatively tracked as running debt.
- Add `/health` and `/stats` runtime fields for quarantine state, worker
debt, activations, and skips.
- Add `headroom_compression_quarantine_total{event="activated|skipped"}`
Prometheus counters.
- Add regression, recovery, queue-race, runtime-payload, export, reset,
and Python 3.10 exception-class coverage.
- Update `CHANGELOG.md`; no dependency or lockfile changes.

## Reproduction

On base commit `718c8dc5`, I applied only the new regression test and
ran:

```bash
.venv/bin/pytest -q \
  tests/test_proxy_compression_executor.py::test_timeout_quarantines_new_work_until_timed_out_worker_finishes
```

The first worker timed out but remained blocked. The second callable
entered the executor instead of being rejected:

```text
FAILED: DID NOT RAISE TimeoutError
```

## Testing

- [x] Affected unit tests pass
- [x] Linting passes (`ruff check .`)
- [x] Changed-file type checking passes
- [x] New tests added for the fix
- [x] Manual testing performed

### Test Output

```text
Python 3.10.20

$ .venv/bin/pytest -q -m 'not slow' \
    tests/test_proxy_compression_executor.py \
    tests/test_prometheus_obs_counters.py \
    tests/test_proxy/test_compression_failure_action.py \
    tests/test_proxy/test_compression_timeout_config.py \
    tests/test_anthropic_pre_upstream_backpressure.py \
    tests/test_openai_codex_ws_lifecycle.py \
    tests/test_codex_ws_compression_scheduler.py \
    tests/test_gemini_compression_offload.py \
    tests/test_proxy_handlers_batch.py \
    tests/test_tokenizer_count_offload.py \
    tests/test_cold_start_fast_pass.py
125 passed, 1 skipped, 1 deselected, 1 warning in 11.06s

$ .venv/bin/ruff check .
All checks passed!

$ .venv/bin/ruff format --check .
1310 files already formatted

$ .venv/bin/mypy headroom/proxy/server.py headroom/proxy/prometheus_metrics.py
Success: no issues found in 2 source files

$ git diff --check
# no output
```

The warning is the existing Starlette `TestClient`/`httpx` deprecation
warning.

## Real Behavior Proof

- Environment: macOS 15.7.4 x86_64, Python 3.10.20,
`compression_max_workers=2`, direct proxy executor path, no external
provider/model.
- Exact command / steps: instantiate the proxy; run a blocking
compression callable with a 50 ms timeout; immediately attempt a second
callable and time the rejection; release the first worker; wait for debt
to reach zero; run the second callable again; export Prometheus metrics.
- Observed result: the first request timed out at 51.182 ms; the second
attempt was rejected in 0.014 ms and its callable never started; debt
was 1 while quarantined, returned to 0 after release, and compression
then resumed normally.

```json
{
  "after_release": {
    "activations_total": 1,
    "leaked_threads_total": 1,
    "quarantine_active": false,
    "skips_total": 1,
    "timed_out_workers": 0
  },
  "bypass_elapsed_ms": 0.014,
  "bypass_error": "compression quarantined: 1 timed-out worker(s) still running",
  "during_quarantine": {
    "quarantine_active": true,
    "timed_out_workers": 1
  },
  "first_timeout_elapsed_ms": 51.182,
  "prometheus": [
    "headroom_compression_quarantine_total{event=\"activated\"} 1",
    "headroom_compression_quarantine_total{event=\"skipped\"} 1"
  ],
  "resumed_result": "resumed",
  "second_callable_started_during_quarantine": false
}
```

- Not tested: a live external model/provider; forced termination of a
permanently wedged native worker; the marked slow native scheduler
benchmark. A broad non-slow run collected 9,859 selected tests but was
stopped at
`tests/test_adversarial_grid.py::TestRunGrid::test_grid_shape_and_schema`
after a macOS process sample showed the pre-existing native
`_core.abi3.so` semaphore stall (`_dispatch_semaphore_wait_slow` →
`semaphore_wait_trap`). The affected executor/handler slice above
completed cleanly.

## Review Readiness

- [x] I have performed a self-review
- [x] This PR is ready for human review

## Checklist

- [x] My code follows the project's style guidelines
- [x] I have performed a self-review of my code
- [x] I have commented hard-to-understand concurrency paths
- [x] I have made corresponding changes to the documentation
- [x] My changes generate no new warnings
- [x] I have added tests that prove the fix is effective
- [x] New and affected existing unit tests pass locally
- [x] I have updated the CHANGELOG.md

---------

Co-authored-by: Tejas Chopra <chopratejas@gmail.com>
2026-07-16 14:30:06 -07:00

147 lines
5.3 KiB
Python

"""Unit tests for fail-open compression observability counters.
Covers the related counters added to ``PrometheusMetrics``:
* ``headroom_compression_failed_total{reason}`` — recorded at the proxy's
optimization fail-open site, split into "timeout" vs "error".
* ``headroom_kompress_size_gate_total{outcome}`` — recorded by ContentRouter
via the observer hook, split into "exceeded" vs "within".
* ``headroom_compression_quarantine_total{event}`` — records quarantine
activation and immediate executor skips while a timed-out worker remains.
Imports only the metrics module so the test stays free of heavy ML deps.
"""
from __future__ import annotations
import asyncio
import threading
import pytest
from headroom.proxy.prometheus_metrics import PrometheusMetrics
def test_record_compression_failed_buckets_by_reason() -> None:
metrics = PrometheusMetrics()
metrics.record_compression_failed("timeout")
metrics.record_compression_failed("error")
metrics.record_compression_failed("error")
assert metrics.compression_failed_by_reason["timeout"] == 1
assert metrics.compression_failed_by_reason["error"] == 2
def test_record_compression_failed_empty_reason_defaults_to_error() -> None:
metrics = PrometheusMetrics()
metrics.record_compression_failed("")
assert metrics.compression_failed_by_reason["error"] == 1
def test_record_kompress_size_gate_buckets_by_outcome() -> None:
metrics = PrometheusMetrics()
metrics.record_kompress_size_gate("exceeded")
metrics.record_kompress_size_gate("within")
metrics.record_kompress_size_gate("within")
assert metrics.kompress_size_gate_by_outcome["exceeded"] == 1
assert metrics.kompress_size_gate_by_outcome["within"] == 2
def test_record_compression_quarantine_buckets_by_event() -> None:
metrics = PrometheusMetrics()
metrics.record_compression_quarantine("activated")
metrics.record_compression_quarantine("skipped")
metrics.record_compression_quarantine("skipped")
assert metrics.compression_quarantine_by_event["activated"] == 1
assert metrics.compression_quarantine_by_event["skipped"] == 2
@pytest.mark.asyncio
async def test_counters_exported_in_prometheus_text() -> None:
metrics = PrometheusMetrics()
metrics.record_compression_failed("timeout")
metrics.record_compression_failed("error")
metrics.record_kompress_size_gate("exceeded")
metrics.record_kompress_size_gate("within")
metrics.record_compression_quarantine("activated")
metrics.record_compression_quarantine("skipped")
text = await metrics.export()
assert "# TYPE headroom_compression_failed_total counter" in text
assert 'headroom_compression_failed_total{reason="timeout"} 1' in text
assert 'headroom_compression_failed_total{reason="error"} 1' in text
assert "# TYPE headroom_kompress_size_gate_total counter" in text
assert 'headroom_kompress_size_gate_total{outcome="exceeded"} 1' in text
assert 'headroom_kompress_size_gate_total{outcome="within"} 1' in text
assert "# TYPE headroom_compression_quarantine_total counter" in text
assert 'headroom_compression_quarantine_total{event="activated"} 1' in text
assert 'headroom_compression_quarantine_total{event="skipped"} 1' in text
@pytest.mark.asyncio
async def test_counters_absent_from_export_until_recorded() -> None:
metrics = PrometheusMetrics()
text = await metrics.export()
# Conditional emission: the families only appear once a sample exists,
# matching the other labelled-counter blocks in export().
assert "headroom_compression_failed_total" not in text
assert "headroom_kompress_size_gate_total" not in text
assert "headroom_compression_quarantine_total" not in text
@pytest.mark.asyncio
async def test_reset_runtime_clears_observability_counters() -> None:
metrics = PrometheusMetrics()
metrics.record_compression_failed("timeout")
metrics.record_kompress_size_gate("exceeded")
metrics.record_compression_quarantine("activated")
await metrics.reset_runtime()
assert dict(metrics.compression_failed_by_reason) == {}
assert dict(metrics.kompress_size_gate_by_outcome) == {}
assert dict(metrics.compression_quarantine_by_event) == {}
@pytest.mark.asyncio
async def test_gate_counter_is_thread_safe_under_concurrent_export() -> None:
# record_kompress_size_gate runs on the compression executor thread while
# export() reads from the event loop. Concurrent unguarded access would
# lose increments or raise "dictionary changed size during iteration".
metrics = PrometheusMetrics()
n_threads, per_thread = 8, 4000
errors: list[str] = []
def hammer() -> None:
for i in range(per_thread):
metrics.record_kompress_size_gate("within" if i % 2 else "exceeded")
threads = [threading.Thread(target=hammer) for _ in range(n_threads)]
for t in threads:
t.start()
while any(t.is_alive() for t in threads):
try:
await metrics.export()
except Exception as exc: # pragma: no cover - failure path
errors.append(repr(exc))
await asyncio.sleep(0)
for t in threads:
t.join()
assert not errors, f"export() raced the writer: {errors[:3]}"
totals = dict(metrics.kompress_size_gate_by_outcome)
assert sum(totals.values()) == n_threads * per_thread