feat: rate_tracker v1.2.0 burst-evasion fix — severity evaluates max(instant_rate, 60s window avg): bursty runaways (20 lines/6s retry-loop shape, 200/min avg, previously 4min undetected live) now sustain through gap windows; continuous unchanged, subsidence clears. 4 new burst tests, 1032 green + seedgo 100% devpulse-verified, live-proven from running service: RUNAWAY WARNING prax_burst_storm_test.log 191 lines/min sustained 120s.

This commit is contained in:
AIOSAI
2026-07-15 10:45:38 -07:00
parent 13ae64cbae
commit 9dc2ecd604
3 changed files with 174 additions and 21 deletions
+15
View File
@@ -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
@@ -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"
+141 -13
View File
@@ -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."""