headroom/tests/test_subscription_tracker.py
Nick Vigilante 8d6c175d60
fix(subscription): only reset 5h contribution on real rollover, not API jitter (#1255)
## 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>
2026-06-26 14:13:44 -05:00

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