diff --git a/CHANGELOG.md b/CHANGELOG.md index 307880420..524f51aba 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -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)). diff --git a/headroom/subscription/tracker.py b/headroom/subscription/tracker.py index 319a44da1..4cccf79ea 100644 --- a/headroom/subscription/tracker.py +++ b/headroom/subscription/tracker.py @@ -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() diff --git a/tests/test_subscription_tracker.py b/tests/test_subscription_tracker.py index e315b503e..e7aff6824 100644 --- a/tests/test_subscription_tracker.py +++ b/tests/test_subscription_tracker.py @@ -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,