mirror of
https://github.com/headroomlabs-ai/headroom.git
synced 2026-08-27 14:17:10 -04:00
## Description The 5-hour-window rollover detector in `SubscriptionTracker._maybe_reset_contribution` zeroes the `HeadroomContribution` counters on **every poll** instead of once per window, so the dashboard's per-window savings figure stays pinned near 0%. Root cause: the rollover check compared `five_hour.resets_at` between consecutive polls with a bare `!=`. Anthropic's usage API reports that timestamp with **second-level jitter** — on my account it flaps between `01:59:59Z` and `02:00:00Z` on consecutive polls *within the same window* — so the `!=` is true on essentially every poll and fires a spurious `5h window rolled over; resetting headroom contribution counters`. The fix treats only a **forward jump larger than `_ROLLOVER_MIN_ADVANCE` (1 minute)** as a genuine rollover. Jitter is sub-second; a real rollover advances `resets_at` by ~5 hours, so the threshold cleanly separates the two. ## 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) - [ ] Documentation update - [ ] Performance improvement - [ ] Code refactoring (no functional changes) ## Changes Made - `headroom/subscription/tracker.py`: replaced the `curr_resets_at != prev_resets_at` rollover test with `curr_resets_at - prev_resets_at > _ROLLOVER_MIN_ADVANCE`, and added the `_ROLLOVER_MIN_ADVANCE = timedelta(minutes=1)` constant with a comment explaining the API jitter. - `tests/test_subscription_tracker.py`: extended `_make_snapshot` to accept an explicit `resets_at`; added `test_second_level_reset_jitter_does_not_reset_contribution` (1-second flap must NOT reset) and `test_genuine_five_hour_rollover_resets_contribution` (5-hour jump still resets). - `CHANGELOG.md`: added a Bug Fixes entry under Unreleased. ## Testing - [x] Unit tests pass (`pytest`) - [x] Linting passes (`ruff check .`) - [x] Type checking passes (`mypy headroom`) - [x] New tests added for new functionality - [x] Manual testing performed ### Test Output ```text $ uv run pytest tests/test_subscription_tracker.py -v test_tracker_notify_active_update_and_basic_state PASSED [ 14%] test_tracker_start_stop_and_rollover_reset PASSED [ 28%] test_second_level_reset_jitter_does_not_reset_contribution PASSED [ 42%] test_genuine_five_hour_rollover_resets_contribution PASSED [ 57%] test_maybe_poll_handles_inactive_and_none_snapshot PASSED [ 71%] test_maybe_poll_success_updates_state_and_metrics PASSED [ 85%] test_persist_and_load_state_round_trip PASSED [100%] ======================= 7 passed in 0.10s ======================= # Fails-before proof: stash the source fix, keep the new tests, re-run the jitter test $ git stash push -- headroom/subscription/tracker.py $ uv run pytest tests/test_subscription_tracker.py::test_second_level_reset_jitter_does_not_reset_contribution -q E AssertionError: assert 0 == 99 E + where 0 = HeadroomContribution(tokens_submitted=0, ...).tokens_submitted FAILED tests/test_subscription_tracker.py::test_second_level_reset_jitter_does_not_reset_contribution 1 failed in 0.09s $ uv run ruff check headroom/subscription/tracker.py tests/test_subscription_tracker.py All checks passed! $ uv run mypy headroom/subscription/tracker.py Success: no issues found in 1 source file ``` ## Real Behavior Proof - Environment: Linux (kernel 7.0), Python 3.14, `uv` 0.11.23, headroom proxy on `127.0.0.1:8787`, Anthropic OAuth subscription account (Claude Max), model `claude-opus-4-8`, Claude Code `claude-cli/2.1.185`. - Exact command / steps: Inspected the live proxy on `main` before patching. `~/.headroom/logs/proxy.log` contained 65 `5h window rolled over; resetting headroom contribution counters` lines over a ~6h session; I computed the gaps between consecutive events, and dumped `five_hour.resets_at` from `~/.headroom/subscription_state.json` history. - Observed result: Median gap between resets was **exactly 300.0s** (= the default `poll_interval_s`), not ~5h — i.e. it reset every poll. The persisted history showed `five_hour.resets_at` flapping across only 4 distinct values, all within ~2s of `02:00:00Z` (e.g. `2026-06-22T01:59:59Z` ↔ `2026-06-22T02:00:00Z`), and `contribution` was all-zeros. After the patch, the unit tests reproduce this exact flap (`base` vs `base + 1s`) and the counters are preserved; a genuine +5h jump still resets. - Not tested: I did not run the patched proxy live for a full 5-hour window to observe a real rollover end-to-end (would need a multi-hour session); the genuine-rollover path is covered by unit test only. No change to the dashboard rendering code. Verified on Linux/Python 3.14 only. ## 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 my code, particularly in hard-to-understand areas - [ ] I have made corresponding changes to the documentation - [x] My changes generate no new warnings - [x] I have added tests that prove my fix is effective or that my feature works - [x] New and existing unit tests pass locally with my changes - [x] I have updated the CHANGELOG.md if applicable ## Additional Notes Docs checklist item is N/A — this is an internal accounting fix with no user-facing API/config change. The threshold constant (`_ROLLOVER_MIN_ADVANCE = 1 min`) is deliberately generous over the observed sub-second jitter while remaining far below a real ~5h advance; happy to tune or switch to an "old deadline has elapsed" guard (`prev_resets_at <= now`) if maintainers prefer that framing. Co-authored-by: JD Davis <mxjerrett@gmail.com>
319 lines
12 KiB
Python
319 lines
12 KiB
Python
from __future__ import annotations
|
|
|
|
import sys
|
|
import threading
|
|
from datetime import datetime, timedelta
|
|
from pathlib import Path
|
|
from types import SimpleNamespace
|
|
|
|
import pytest
|
|
|
|
import headroom.subscription.tracker as tracker_module
|
|
from headroom.subscription.models import (
|
|
HeadroomContribution,
|
|
RateLimitWindow,
|
|
SubscriptionSnapshot,
|
|
WindowDiscrepancy,
|
|
WindowTokens,
|
|
_utc_now,
|
|
)
|
|
from headroom.subscription.tracker import SubscriptionTracker
|
|
|
|
|
|
def _make_snapshot(
|
|
*,
|
|
token_prefix: str = "token123",
|
|
reset_offset_hours: int = 5,
|
|
resets_at: datetime | None = None,
|
|
) -> SubscriptionSnapshot:
|
|
return SubscriptionSnapshot(
|
|
five_hour=RateLimitWindow(
|
|
used=10,
|
|
limit=100,
|
|
utilization_pct=10.0,
|
|
resets_at=(
|
|
resets_at
|
|
if resets_at is not None
|
|
else _utc_now() + timedelta(hours=reset_offset_hours)
|
|
),
|
|
),
|
|
seven_day=RateLimitWindow(used=20, limit=200, utilization_pct=10.0),
|
|
token_prefix=token_prefix,
|
|
)
|
|
|
|
|
|
def test_tracker_notify_active_update_and_basic_state(monkeypatch: pytest.MonkeyPatch) -> None:
|
|
monkeypatch.setattr(SubscriptionTracker, "_load_persisted_state", lambda self: None)
|
|
# PR-G2: keep the unit test deterministic — do not let
|
|
# ``update_contribution`` call out to ``rtk gain`` via the proxy helper.
|
|
monkeypatch.setattr(SubscriptionTracker, "_poll_rtk_delta", lambda self: 0)
|
|
tracker = SubscriptionTracker(enabled=False)
|
|
|
|
assert tracker.is_available() is False
|
|
assert tracker.latest_snapshot is None
|
|
assert tracker.is_active() is False
|
|
assert isinstance(tracker.get_stats(), dict)
|
|
|
|
tracker.notify_active("")
|
|
tracker.notify_active("Basic token")
|
|
tracker.notify_active("Bearer sk-ant-api-key")
|
|
assert tracker._current_token is None
|
|
|
|
tracker.notify_active("Bearer oauth-token-123")
|
|
assert tracker._current_token == "oauth-token-123"
|
|
assert tracker._full_tokens["oauth-to"] == 1
|
|
assert tracker.is_active() is True
|
|
|
|
tracker.update_contribution(
|
|
tokens_submitted=10,
|
|
tokens_saved_compression=5,
|
|
tokens_saved_cli_filtering=-1,
|
|
tokens_saved_cache_reads=3,
|
|
compression_savings_usd=1.25,
|
|
cache_savings_usd=-2.0,
|
|
)
|
|
contribution = tracker._state.contribution
|
|
assert contribution.tokens_submitted == 10
|
|
assert contribution.tokens_saved_compression == 5
|
|
assert contribution.tokens_saved_cli_filtering == 0
|
|
assert contribution.tokens_saved_rtk == 0
|
|
assert contribution.tokens_saved_cache_reads == 3
|
|
assert contribution.to_dict()["tokens_saved"]["compression"] == 5
|
|
assert contribution.to_dict()["tokens_saved"]["proxy_compression"] == 5
|
|
assert contribution.to_dict()["tokens_saved"]["cli_filtering"] == 0
|
|
assert contribution.to_dict()["tokens_saved"]["rtk"] == 0
|
|
assert contribution.compression_savings_usd == 1.25
|
|
assert contribution.cache_savings_usd == 0.0
|
|
|
|
|
|
@pytest.mark.asyncio
|
|
async def test_tracker_start_stop_and_rollover_reset(
|
|
monkeypatch: pytest.MonkeyPatch, tmp_path: Path
|
|
) -> None:
|
|
monkeypatch.setattr(SubscriptionTracker, "_load_persisted_state", lambda self: None)
|
|
tracker = SubscriptionTracker(persist_path=tmp_path / "state.json")
|
|
|
|
async def fake_poll_loop() -> None:
|
|
assert tracker._stop_event is not None
|
|
await tracker._stop_event.wait()
|
|
|
|
tracker._poll_loop = fake_poll_loop # type: ignore[method-assign]
|
|
await tracker.start()
|
|
first_task = tracker._poll_task
|
|
assert first_task is not None
|
|
|
|
await tracker.start()
|
|
assert tracker._poll_task is first_task
|
|
|
|
await tracker.stop()
|
|
assert tracker._stop_event is not None and tracker._stop_event.is_set()
|
|
assert tracker._persist_path.exists()
|
|
|
|
tracker._state.history = [
|
|
_make_snapshot(reset_offset_hours=5),
|
|
_make_snapshot(reset_offset_hours=6),
|
|
]
|
|
tracker._state.contribution = HeadroomContribution(tokens_submitted=99)
|
|
tracker._maybe_reset_contribution(tracker._state.history[-1])
|
|
assert tracker._state.contribution.tokens_submitted == 0
|
|
|
|
|
|
def test_second_level_reset_jitter_does_not_reset_contribution(
|
|
monkeypatch: pytest.MonkeyPatch, tmp_path: Path
|
|
) -> None:
|
|
"""Regression: the usage API reports ``resets_at`` with second-level jitter
|
|
within a single window (observed flapping between ``01:59:59Z`` and
|
|
``02:00:00Z`` on consecutive polls). That must NOT be treated as a rollover,
|
|
or the contribution counters get zeroed every poll and the dashboard sticks
|
|
at ~0% savings.
|
|
"""
|
|
monkeypatch.setattr(SubscriptionTracker, "_load_persisted_state", lambda self: None)
|
|
tracker = SubscriptionTracker(persist_path=tmp_path / "state.json")
|
|
|
|
base = _utc_now() + timedelta(hours=3)
|
|
tracker._state.history = [
|
|
_make_snapshot(resets_at=base),
|
|
_make_snapshot(resets_at=base + timedelta(seconds=1)),
|
|
]
|
|
tracker._state.contribution = HeadroomContribution(tokens_submitted=99)
|
|
tracker._maybe_reset_contribution(tracker._state.history[-1])
|
|
assert tracker._state.contribution.tokens_submitted == 99
|
|
|
|
|
|
def test_genuine_five_hour_rollover_resets_contribution(
|
|
monkeypatch: pytest.MonkeyPatch, tmp_path: Path
|
|
) -> None:
|
|
"""A real rollover advances ``resets_at`` by ~5 hours and still resets."""
|
|
monkeypatch.setattr(SubscriptionTracker, "_load_persisted_state", lambda self: None)
|
|
tracker = SubscriptionTracker(persist_path=tmp_path / "state.json")
|
|
|
|
base = _utc_now()
|
|
tracker._state.history = [
|
|
_make_snapshot(resets_at=base),
|
|
_make_snapshot(resets_at=base + timedelta(hours=5)),
|
|
]
|
|
tracker._state.contribution = HeadroomContribution(tokens_submitted=99)
|
|
tracker._maybe_reset_contribution(tracker._state.history[-1])
|
|
assert tracker._state.contribution.tokens_submitted == 0
|
|
|
|
|
|
@pytest.mark.asyncio
|
|
async def test_maybe_poll_handles_inactive_and_none_snapshot(
|
|
monkeypatch: pytest.MonkeyPatch,
|
|
) -> None:
|
|
monkeypatch.setattr(SubscriptionTracker, "_load_persisted_state", lambda self: None)
|
|
tracker = SubscriptionTracker()
|
|
|
|
monkeypatch.setattr("headroom.subscription.client.read_cached_oauth_token", lambda: None)
|
|
await tracker._maybe_poll()
|
|
assert tracker._state.poll_count == 0
|
|
|
|
monkeypatch.setattr(
|
|
"headroom.subscription.client.read_cached_oauth_token", lambda: "cached-token"
|
|
)
|
|
|
|
async def fetch_none(token: str | None):
|
|
return None
|
|
|
|
tracker._client = SimpleNamespace(fetch=fetch_none)
|
|
await tracker._maybe_poll()
|
|
assert tracker._state.last_error == "fetch returned None"
|
|
assert tracker._state.poll_errors == 1
|
|
|
|
|
|
@pytest.mark.asyncio
|
|
async def test_maybe_poll_success_updates_state_and_metrics(
|
|
monkeypatch: pytest.MonkeyPatch,
|
|
) -> None:
|
|
monkeypatch.setattr(SubscriptionTracker, "_load_persisted_state", lambda self: None)
|
|
tracker = SubscriptionTracker()
|
|
tracker.notify_active("Bearer live-oauth-token")
|
|
|
|
snapshot = _make_snapshot()
|
|
discrepancies = [WindowDiscrepancy(kind="cache_miss", description="miss", severity="warning")]
|
|
metrics_calls: list[dict] = []
|
|
|
|
async def fetch_snapshot(token: str | None):
|
|
assert token == "live-oauth-token"
|
|
return snapshot
|
|
|
|
tracker._client = SimpleNamespace(fetch=fetch_snapshot)
|
|
monkeypatch.setattr(
|
|
tracker_module, "_compute_window_tokens_for_snapshot", lambda snap: WindowTokens(input=7)
|
|
)
|
|
monkeypatch.setattr(tracker_module, "_detect_discrepancies", lambda snap, tokens: discrepancies)
|
|
monkeypatch.setattr(
|
|
tracker, "_persist_state", lambda: metrics_calls.append({"persisted": True})
|
|
)
|
|
monkeypatch.setitem(
|
|
sys.modules,
|
|
"headroom.observability.metrics",
|
|
SimpleNamespace(
|
|
get_otel_metrics=lambda: SimpleNamespace(
|
|
record_subscription_window=lambda state: metrics_calls.append(state)
|
|
)
|
|
),
|
|
)
|
|
|
|
await tracker._maybe_poll()
|
|
assert tracker.latest_snapshot is snapshot
|
|
assert tracker._state.window_tokens.input == 7
|
|
assert tracker._state.discrepancies[-1].kind == "cache_miss"
|
|
assert tracker._state.last_error is None
|
|
assert tracker._state.poll_count == 1
|
|
assert metrics_calls[0] == {"persisted": True}
|
|
assert isinstance(metrics_calls[1], dict)
|
|
|
|
|
|
@pytest.mark.asyncio
|
|
async def test_maybe_poll_runs_transcript_scan_off_event_loop(
|
|
monkeypatch: pytest.MonkeyPatch,
|
|
) -> None:
|
|
"""Regression: the transcript scan must run off the event-loop thread, or a
|
|
multi-second ~/.claude/projects scan wedges the proxy every poll interval."""
|
|
monkeypatch.setattr(SubscriptionTracker, "_load_persisted_state", lambda self: None)
|
|
tracker = SubscriptionTracker()
|
|
tracker.notify_active("Bearer live-oauth-token")
|
|
|
|
snapshot = _make_snapshot()
|
|
|
|
async def fetch_snapshot(token: str | None) -> SubscriptionSnapshot:
|
|
return snapshot
|
|
|
|
tracker._client = SimpleNamespace(fetch=fetch_snapshot)
|
|
|
|
loop_thread_id = threading.get_ident()
|
|
seen: dict[str, int] = {}
|
|
|
|
def recording_compute(snap: SubscriptionSnapshot) -> WindowTokens:
|
|
seen["thread_id"] = threading.get_ident()
|
|
return WindowTokens(input=7)
|
|
|
|
monkeypatch.setattr(tracker_module, "_compute_window_tokens_for_snapshot", recording_compute)
|
|
monkeypatch.setattr(tracker_module, "_detect_discrepancies", lambda snap, tokens: [])
|
|
monkeypatch.setattr(tracker, "_persist_state", lambda: None)
|
|
monkeypatch.setitem(
|
|
sys.modules,
|
|
"headroom.observability.metrics",
|
|
SimpleNamespace(
|
|
get_otel_metrics=lambda: SimpleNamespace(record_subscription_window=lambda state: None)
|
|
),
|
|
)
|
|
|
|
await tracker._maybe_poll()
|
|
|
|
# The blocking scan ran on a worker thread, not the event-loop thread.
|
|
assert seen["thread_id"] != loop_thread_id
|
|
|
|
|
|
def test_persist_and_load_state_round_trip(tmp_path: Path, monkeypatch: pytest.MonkeyPatch) -> None:
|
|
# PR-G2: ``update_contribution`` polls RTK by default; pin the helper to
|
|
# 0 so the round-trip is deterministic.
|
|
monkeypatch.setattr(SubscriptionTracker, "_poll_rtk_delta", lambda self: 0)
|
|
|
|
persist_path = tmp_path / "tracker-state.json"
|
|
tracker = SubscriptionTracker(persist_path=persist_path)
|
|
tracker.update_contribution(
|
|
tokens_submitted=11,
|
|
tokens_saved_compression=2,
|
|
tokens_saved_cli_filtering=3,
|
|
tokens_saved_cache_reads=4,
|
|
compression_savings_usd=1.5,
|
|
cache_savings_usd=2.5,
|
|
)
|
|
# PR-G2: also write a raw RTK delta directly to assert the persisted
|
|
# ``rtk_raw`` field round-trips independently of cli_filtering.
|
|
tracker.update_contribution(tokens_saved_rtk=9)
|
|
tracker._state.poll_count = 7
|
|
tracker._persist_state()
|
|
|
|
loader = SubscriptionTracker(persist_path=persist_path)
|
|
assert loader._state.contribution.tokens_submitted == 11
|
|
assert loader._state.contribution.tokens_saved_compression == 2
|
|
# PR-G2: the raw counters now round-trip independently of the legacy
|
|
# dashboard alias.
|
|
assert loader._state.contribution.tokens_saved_cli_filtering == 3
|
|
assert loader._state.contribution.tokens_saved_rtk == 9
|
|
assert loader._state.contribution.tokens_saved_cache_reads == 4
|
|
# ``compression`` is ``proxy_compression + cli_filtering_saved()`` =
|
|
# ``2 + max(3, 9)`` = 11 after PR-G2 (was 5 when rtk mirrored
|
|
# cli_filtering).
|
|
assert loader._state.contribution.to_dict()["tokens_saved"]["compression"] == 11
|
|
assert loader._state.contribution.to_dict()["tokens_saved"]["proxy_compression"] == 2
|
|
# Dashboard ``cli_filtering`` / ``rtk`` keys remain ``max(cli, rtk)``
|
|
# for legacy display — 9 wins. Raw counters expose the un-aliased
|
|
# values for the tracker's own round-trip.
|
|
assert loader._state.contribution.to_dict()["tokens_saved"]["cli_filtering"] == 9
|
|
assert loader._state.contribution.to_dict()["tokens_saved"]["rtk"] == 9
|
|
assert loader._state.contribution.to_dict()["tokens_saved"]["cli_filtering_raw"] == 3
|
|
assert loader._state.contribution.to_dict()["tokens_saved"]["rtk_raw"] == 9
|
|
assert loader._state.contribution.compression_savings_usd == 1.5
|
|
assert loader._state.contribution.cache_savings_usd == 2.5
|
|
assert loader._state.poll_count == 7
|
|
|
|
persist_path.write_text("{invalid", encoding="utf-8")
|
|
broken = SubscriptionTracker(persist_path=persist_path)
|
|
assert broken._state.poll_count == 0
|
|
|
|
missing = SubscriptionTracker(persist_path=tmp_path / "missing.json")
|
|
assert missing._state.poll_count == 0
|