mirror of
https://github.com/headroomlabs-ai/headroom.git
synced 2026-08-27 14:17:10 -04:00
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>
This commit is contained in:
Nick Vigilante
GitHub
parent
b618d2d11a
commit
8d6c175d60
3 changed files with 60 additions and 4 deletions
|
|
@ -28,6 +28,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
|
|||
|
||||
### Bug Fixes
|
||||
|
||||
* **subscription:** stop zeroing the 5-hour headroom contribution counters on every poll. The rollover check compared `five_hour.resets_at` with a bare `!=`, but the usage API reports that timestamp with second-level jitter (observed flapping between `01:59:59Z` and `02:00:00Z` on consecutive polls within the same window), so a spurious "5h window rolled over" reset fired every poll interval (~5 min) and the dashboard's per-window savings stuck near 0%. Only a forward jump larger than `_ROLLOVER_MIN_ADVANCE` (1 minute) now counts as a real rollover.
|
||||
* **transforms/content_router:** stop replacing `role="tool"` output with a lossy-unrecoverable summary on the live compression path (refs [#1307](https://github.com/chopratejas/headroom/issues/1307)). `ContentRouter.apply()` routed OpenAI-style `role="tool"` string messages — `Bash`/`grep`/`ls`/`cat` output — through the ML/word-drop summarizers; when the result carried no CCR retrieve marker (CCR off, ratio >= 0.8, or the size-gate fallback) the original was unrecoverable and the agent acted on a fabricated summary. Tool-role string content is now kept verbatim unless the compressed form is CCR-recoverable. Assistant/user text is unaffected, and structurally-lossless passes (SmartCrusher/Log/Search) still apply. The Anthropic `tool_result` block path is tracked separately.
|
||||
* **rtk:** stop `rtk` hook registration from spuriously timing out during `headroom wrap`. Output is captured to a temp file instead of pipes, and `stdin` is closed, so a background process forked by `rtk init` can no longer hold the pipe open and block `subprocess.run` past its 10s timeout after the hooks were already registered.
|
||||
* **ccr:** stop re-compressing `headroom_retrieve` output, which created an infinite retrieval loop, and stop emitting retrieval markers when the `headroom_retrieve` tool is not injected, which silently dropped data ([#1077](https://github.com/chopratejas/headroom/issues/1077), [#1006](https://github.com/chopratejas/headroom/issues/1006)).
|
||||
|
|
|
|||
|
|
@ -124,6 +124,15 @@ _ON_DEMAND_POLL_TIMEOUT_S = 2.0
|
|||
_FIVE_HOUR_WINDOW = timedelta(hours=5)
|
||||
_SEVEN_DAY_WINDOW = timedelta(days=7)
|
||||
|
||||
# A genuine 5-hour-window rollover advances ``five_hour.resets_at`` by ~5 hours.
|
||||
# The usage API, however, reports ``resets_at`` with second-level jitter — it has
|
||||
# been observed flapping between e.g. ``01:59:59Z`` and ``02:00:00Z`` on
|
||||
# consecutive polls within the *same* window. A bare ``!=`` comparison therefore
|
||||
# misfires on essentially every poll, zeroing the contribution counters every
|
||||
# poll interval instead of once per window. Only treat a *forward* jump larger
|
||||
# than this threshold as a real rollover (jitter is sub-second; a rollover is hours).
|
||||
_ROLLOVER_MIN_ADVANCE = timedelta(minutes=1)
|
||||
|
||||
# Surge pricing threshold: if actual utilization is >N% higher than expected,
|
||||
# flag it as a potential surge pricing event.
|
||||
_SURGE_THRESHOLD_PCT = 15.0
|
||||
|
|
@ -770,7 +779,7 @@ class SubscriptionTracker(QuotaTracker):
|
|||
if (
|
||||
prev_resets_at is not None
|
||||
and curr_resets_at is not None
|
||||
and curr_resets_at != prev_resets_at
|
||||
and curr_resets_at - prev_resets_at > _ROLLOVER_MIN_ADVANCE
|
||||
):
|
||||
logger.info("5h window rolled over; resetting headroom contribution counters")
|
||||
self._state.contribution = HeadroomContribution()
|
||||
|
|
|
|||
|
|
@ -2,7 +2,7 @@ from __future__ import annotations
|
|||
|
||||
import sys
|
||||
import threading
|
||||
from datetime import timedelta
|
||||
from datetime import datetime, timedelta
|
||||
from pathlib import Path
|
||||
from types import SimpleNamespace
|
||||
|
||||
|
|
@ -21,14 +21,21 @@ from headroom.subscription.tracker import SubscriptionTracker
|
|||
|
||||
|
||||
def _make_snapshot(
|
||||
*, token_prefix: str = "token123", reset_offset_hours: int = 5
|
||||
*,
|
||||
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=_utc_now() + timedelta(hours=reset_offset_hours),
|
||||
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,
|
||||
|
|
@ -111,6 +118,45 @@ async def test_tracker_start_stop_and_rollover_reset(
|
|||
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,
|
||||
|
|
|
|||
Loading…
Add table
Add a link
Reference in a new issue