From 9dc2ecd6044d47fa4437e3305b09796099d0345f Mon Sep 17 00:00:00 2001 From: AIOSAI Date: Wed, 15 Jul 2026 10:45:38 -0700 Subject: [PATCH] =?UTF-8?q?feat:=20rate=5Ftracker=20v1.2.0=20burst-evasion?= =?UTF-8?q?=20fix=20=E2=80=94=20severity=20evaluates=20max(instant=5Frate,?= =?UTF-8?q?=2060s=20window=20avg):=20bursty=20runaways=20(20=20lines/6s=20?= =?UTF-8?q?retry-loop=20shape,=20200/min=20avg,=20previously=204min=20unde?= =?UTF-8?q?tected=20live)=20now=20sustain=20through=20gap=20windows;=20con?= =?UTF-8?q?tinuous=20unchanged,=20subsidence=20clears.=204=20new=20burst?= =?UTF-8?q?=20tests,=201032=20green=20+=20seedgo=20100%=20devpulse-verifie?= =?UTF-8?q?d,=20live-proven=20from=20running=20service:=20RUNAWAY=20WARNIN?= =?UTF-8?q?G=20prax=5Fburst=5Fstorm=5Ftest.log=20191=20lines/min=20sustain?= =?UTF-8?q?ed=20120s.?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- CHANGELOG.md | 15 ++ .../apps/handlers/monitoring/rate_tracker.py | 26 ++- src/aipass/prax/tests/test_rate_tracker.py | 154 ++++++++++++++++-- 3 files changed, 174 insertions(+), 21 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 09c35342..54f58a6b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -51,6 +51,21 @@ PyPI version — not the changelog header. per the ca096295 convention, leaving `execvp` (already mocked) as the only terminal call. Ruling recorded in compass; the "forget CI" era is over. +- **Burst-evasion closed: bursty runaways can no longer slip past the rate + tracker.** Found live during the morning's chain verification: any single + below-threshold 10-second scan window zero-reset the sustain counter, so a + bursty writer (20 short lines every 6 seconds — 200 lines/min average, the + exact retry-loop-with-sleep shape of the TG relay incident) ran 4 minutes + undetected. @prax's fix (rate_tracker v1.2.0): severity now evaluates + `max(instant_rate, 60s window average)` — continuous writers behave exactly + as before (instant rate dominates), bursts sustain through their gap + windows, and subsidence still clears as zeros fill the window. Four new + burst tests; live-proven with the previously-evading storm pattern: + `RUNAWAY WARNING: prax_burst_storm_test.log — 191 lines/min sustained 120s` + in the tracker log, fired from the restarted running service. Detection + evidence now spans all three storm shapes: continuous fast (332/min), + continuous moderate (257/min), bursty (191/min). + ## [2026-07-14] ### Fixed diff --git a/src/aipass/prax/apps/handlers/monitoring/rate_tracker.py b/src/aipass/prax/apps/handlers/monitoring/rate_tracker.py index 21768917..21be2c01 100644 --- a/src/aipass/prax/apps/handlers/monitoring/rate_tracker.py +++ b/src/aipass/prax/apps/handlers/monitoring/rate_tracker.py @@ -1,9 +1,9 @@ # =================== AIPass ==================== # Name: rate_tracker.py # Description: Log file rate tracking for runaway detection -# Version: 1.1.0 +# Version: 1.2.0 # Created: 2026-07-14 -# Modified: 2026-07-14 +# Modified: 2026-07-15 # ============================================= """ @@ -41,6 +41,7 @@ CRITICAL_LINES_PER_MIN = 600 # 10/sec * 60 CRITICAL_SUSTAINED_INTERVALS = 6 # 6 * 10s = 1 min _RATE_HISTORY_SIZE = 30 +_WINDOW_INTERVALS = 6 _DATA_FILE = "rate_tracker" @@ -236,6 +237,14 @@ def scan_rates() -> list: return results +def _window_average(state: FileRateState) -> float: + """Average lines/min over the last _WINDOW_INTERVALS entries.""" + if not state.rates: + return 0.0 + window = list(state.rates)[-_WINDOW_INTERVALS:] + return sum(r for _, r in window) / len(window) + + def _evaluate_thresholds( state: FileRateState, lines_per_min: float, @@ -244,19 +253,20 @@ def _evaluate_thresholds( ) -> Optional[str]: """Update sustained counters and fire events when thresholds are crossed.""" severity = None + effective_rate = max(lines_per_min, _window_average(state)) - if lines_per_min >= CRITICAL_LINES_PER_MIN: + if effective_rate >= CRITICAL_LINES_PER_MIN: state.critical_sustained += 1 state.warning_sustained += 1 - elif lines_per_min >= WARNING_LINES_PER_MIN: + elif effective_rate >= WARNING_LINES_PER_MIN: state.critical_sustained = 0 state.warning_sustained += 1 else: if state.fired_warning or state.fired_critical: logger.info( - "[rate_tracker] %s rate subsided (%.0f lines/min)", + "[rate_tracker] %s rate subsided (%.0f lines/min avg)", log_file.name, - lines_per_min, + effective_rate, ) state.warning_sustained = 0 state.critical_sustained = 0 @@ -268,12 +278,12 @@ def _evaluate_thresholds( severity = "critical" state.fired_critical = True duration = state.critical_sustained * SCAN_INTERVAL - _fire_event(file_key, lines_per_min, duration, "critical") + _fire_event(file_key, effective_rate, duration, "critical") elif state.warning_sustained >= WARNING_SUSTAINED_INTERVALS and not state.fired_warning: severity = "warning" state.fired_warning = True duration = state.warning_sustained * SCAN_INTERVAL - _fire_event(file_key, lines_per_min, duration, "warning") + _fire_event(file_key, effective_rate, duration, "warning") else: if state.critical_sustained > 0: severity = "rising_critical" diff --git a/src/aipass/prax/tests/test_rate_tracker.py b/src/aipass/prax/tests/test_rate_tracker.py index edcdd6bd..b41d6c59 100644 --- a/src/aipass/prax/tests/test_rate_tracker.py +++ b/src/aipass/prax/tests/test_rate_tracker.py @@ -1,7 +1,7 @@ # =================== AIPass ==================== # Name: test_rate_tracker.py # Description: Tests for the rate tracker runaway-log detector -# Version: 1.1.0 +# Version: 1.2.0 # Created: 2026-07-14 # Modified: 2026-07-15 # ============================================= @@ -11,6 +11,7 @@ Covers: - Rate calculation from byte offset changes - Sustained threshold detection (WARNING and CRITICAL) +- Burst detection via rolling-window average - Subsidence reset when rate drops - Per-file suppression - Event firing via callback @@ -233,27 +234,154 @@ class TestSubsidence: assert event_mock.call_count == 1 - idle_offset = mod.WARNING_SUSTAINED_INTERVALS + 1 - with patch.object( - mod.time, - "time", - return_value=base_time + idle_offset * mod.SCAN_INTERVAL, - ): - mod.scan_rates() - - for i in range(mod.WARNING_SUSTAINED_INTERVALS): - log_file.write_bytes(b"x" * bytes_per_interval + log_file.read_bytes()) - offset = idle_offset + i + 1 + for j in range(mod._WINDOW_INTERVALS): + idle_offset = mod.WARNING_SUSTAINED_INTERVALS + j + 1 with patch.object( mod.time, "time", - return_value=base_time + offset * mod.SCAN_INTERVAL, + return_value=base_time + idle_offset * mod.SCAN_INTERVAL, + ): + mod.scan_rates() + + gap = mod.WARNING_SUSTAINED_INTERVALS + mod._WINDOW_INTERVALS + for i in range(mod.WARNING_SUSTAINED_INTERVALS): + log_file.write_bytes(b"x" * bytes_per_interval + log_file.read_bytes()) + with patch.object( + mod.time, + "time", + return_value=base_time + (gap + i + 1) * mod.SCAN_INTERVAL, ): mod.scan_rates() assert event_mock.call_count == 2 +class TestBurstDetection: + """Window average catches bursty writers that evade per-interval checks.""" + + def test_bursty_writer_fires_warning(self, tmp_path, monkeypatch): + """Alternating high/zero intervals averaging above threshold fires WARNING.""" + logs_dir = tmp_path / "system" + logs_dir.mkdir(parents=True) + log_file = logs_dir / "test_module.log" + log_file.write_text("x" * 100) + + mod, event_mock = _import_tracker(monkeypatch, logs_dir=logs_dir) + base_time = time.time() + mod.scan_rates() + + bytes_burst = int(mod.WARNING_LINES_PER_MIN * 3 * mod.AVG_LINE_BYTES * mod.SCAN_INTERVAL / 60) + + for i in range(mod.WARNING_SUSTAINED_INTERVALS): + if i % 2 == 0: + log_file.write_bytes(b"x" * bytes_burst + log_file.read_bytes()) + with patch.object( + mod.time, + "time", + return_value=base_time + (i + 1) * mod.SCAN_INTERVAL, + ): + mod.scan_rates() + + event_mock.assert_called_once() + assert event_mock.call_args[1]["severity"] == "warning" + + def test_single_burst_does_not_fire(self, tmp_path, monkeypatch): + """One burst followed by silence clears before reaching sustained threshold.""" + logs_dir = tmp_path / "system" + logs_dir.mkdir(parents=True) + log_file = logs_dir / "test_module.log" + log_file.write_text("x" * 100) + + mod, event_mock = _import_tracker(monkeypatch, logs_dir=logs_dir) + base_time = time.time() + mod.scan_rates() + + bytes_burst = int(mod.WARNING_LINES_PER_MIN * 3 * mod.AVG_LINE_BYTES * mod.SCAN_INTERVAL / 60) + + log_file.write_bytes(b"x" * bytes_burst + log_file.read_bytes()) + with patch.object( + mod.time, + "time", + return_value=base_time + mod.SCAN_INTERVAL, + ): + mod.scan_rates() + + for i in range(mod.WARNING_SUSTAINED_INTERVALS): + with patch.object( + mod.time, + "time", + return_value=base_time + (i + 2) * mod.SCAN_INTERVAL, + ): + mod.scan_rates() + + event_mock.assert_not_called() + + def test_bursty_critical_fires(self, tmp_path, monkeypatch): + """Alternating very-high/zero intervals averaging above critical threshold fires CRITICAL.""" + logs_dir = tmp_path / "system" + logs_dir.mkdir(parents=True) + log_file = logs_dir / "test_module.log" + log_file.write_text("x" * 100) + + mod, event_mock = _import_tracker(monkeypatch, logs_dir=logs_dir) + base_time = time.time() + mod.scan_rates() + + bytes_burst = int(mod.CRITICAL_LINES_PER_MIN * 3 * mod.AVG_LINE_BYTES * mod.SCAN_INTERVAL / 60) + + for i in range(mod.CRITICAL_SUSTAINED_INTERVALS): + if i % 2 == 0: + log_file.write_bytes(b"x" * bytes_burst + log_file.read_bytes()) + with patch.object( + mod.time, + "time", + return_value=base_time + (i + 1) * mod.SCAN_INTERVAL, + ): + mod.scan_rates() + + assert event_mock.call_count == 1 + assert event_mock.call_args[1]["severity"] == "critical" + + def test_window_average_subsides_after_storm(self, tmp_path, monkeypatch): + """Window average drops below threshold after burst stops — no false latch.""" + logs_dir = tmp_path / "system" + logs_dir.mkdir(parents=True) + log_file = logs_dir / "test_module.log" + log_file.write_text("x" * 100) + + mod, event_mock = _import_tracker(monkeypatch, logs_dir=logs_dir) + base_time = time.time() + mod.scan_rates() + + bytes_burst = int(mod.WARNING_LINES_PER_MIN * 3 * mod.AVG_LINE_BYTES * mod.SCAN_INTERVAL / 60) + + for i in range(mod.WARNING_SUSTAINED_INTERVALS): + if i % 2 == 0: + log_file.write_bytes(b"x" * bytes_burst + log_file.read_bytes()) + with patch.object( + mod.time, + "time", + return_value=base_time + (i + 1) * mod.SCAN_INTERVAL, + ): + mod.scan_rates() + + assert event_mock.call_count == 1 + + offset = mod.WARNING_SUSTAINED_INTERVALS + for j in range(mod._WINDOW_INTERVALS): + with patch.object( + mod.time, + "time", + return_value=base_time + (offset + j + 1) * mod.SCAN_INTERVAL, + ): + mod.scan_rates() + + file_key = str(log_file) + state = mod._tracked[file_key] + assert state.warning_sustained == 0 + assert state.fired_warning is False + + class TestSuppression: """Per-file suppression skips configured files."""