From 8a9ddfc3caedb7a782a2aefb990df5a0f461cdd2 Mon Sep 17 00:00:00 2001 From: Etan Joseph Heyman Date: Sat, 18 Jul 2026 15:08:05 +0300 Subject: [PATCH 1/4] =?UTF-8?q?fix(watchdog):=20alert-framing=20=E2=80=94?= =?UTF-8?q?=20page=20once=20per=20wedge=20episode,=20not=20per=20kickstart?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The throughput-watchdog alerted (:3847/notify + osascript) on EVERY kickstart. During a chronic wedge sawtooth (watcher re-wedging on the live 1.4.3 apsw bug, watchdog recovering each cycle) this paged the operator every ~10min. orc alert-framing law (stalker postmortem): operator pings = state-CHANGES only, never heartbeats. Fix: episode-based alerting. Page on the FIRST wedge of an episode only; the latch clears after a SUSTAINED healthy run (_EPISODE_RESET_TICKS consecutive progressing ticks), so the NEXT genuine wedge pages again but a sawtooth does not. Recovery (kickstart) still runs every tick — only the paging is throttled. Test: test_alert_framing_pages_once_per_episode_not_per_kickstart drives a full sawtooth — first wedge pages, mid-sawtooth kickstart suppressed, sustained recovery resets, new-episode wedge pages again. Suite 21/21. Note: the cask bump to 1.4.4 (apsw fix) stops the wedging at the root, which kills most pings; this is the durable throttle for any residual episode. Follow-ups (documented, not in this PR): recovery-FAILED escalation ping + a once-daily digest line. Co-Authored-By: Claude Fable 5 --- scripts/launchd/throughput-watchdog.py | 34 +++++++++++++++--- tests/test_throughput_watchdog.py | 50 ++++++++++++++++++++++++++ 2 files changed, 79 insertions(+), 5 deletions(-) diff --git a/scripts/launchd/throughput-watchdog.py b/scripts/launchd/throughput-watchdog.py index a8acb97a..8fcb26d7 100755 --- a/scripts/launchd/throughput-watchdog.py +++ b/scripts/launchd/throughput-watchdog.py @@ -21,6 +21,11 @@ DEFAULT_WATCH_LABEL = "com.brainlayer.watch" DEFAULT_NOTIFY_ENDPOINT = "http://localhost:3847/notify" +# Alert-framing (orc law, stalker postmortem): after a wedge episode is paged once, +# the operator is re-notified for the NEXT episode only — i.e. after this many +# consecutive healthy (progressing) ticks clear the latch. Prevents a chronic +# wedge sawtooth from paging on every kickstart. +_EPISODE_RESET_TICKS = 3 DEFAULT_COMMAND_TIMEOUT_SECONDS = 15 KICKSTART_TIMEOUT_SECONDS = 45 @@ -491,11 +496,15 @@ def run_once( elif config.dry_run: result.action = "would_kickstart" else: - try: - alert_fn(config, result) - except Exception as exc: - result.alert_error = str(exc) - print(f"throughput-watchdog alert failed: {exc}", file=sys.stderr) + # Alert-framing: page on the FIRST wedge of an episode only — never + # per-kick of a chronic sawtooth. The latch clears after a sustained + # healthy run (episode reset below). Recovery still runs every tick. + if not state.get("episode_alerted"): + try: + alert_fn(config, result) + except Exception as exc: + result.alert_error = str(exc) + print(f"throughput-watchdog alert failed: {exc}", file=sys.stderr) attempt_state = dict(state) attempt_state.update( { @@ -512,6 +521,7 @@ def run_once( "last_action": "recovery_attempt", "last_restart_epoch": checked_at, "restart_attempt_count": int(state.get("restart_attempt_count", 0)) + 1, + "episode_alerted": True, } ) _atomic_write_json(config.state_path, attempt_state) @@ -549,6 +559,20 @@ def run_once( next_state["last_alert_error"] = result.alert_error else: next_state.pop("last_alert_error", None) + + # Episode reset (alert-framing): clear the first-wedge page latch after a + # SUSTAINED healthy run, so the next genuine wedge pages again without + # re-paging every cycle of a chronic sawtooth. A kickstart tick is never + # "healthy" (its state already advanced the liveness rowid), so the counter + # only climbs on real, unassisted watcher progress. + prev_liveness = int(state.get("watcher_liveness_highwater_rowid", 0) or 0) + if result.stalled_ticks == 0 and current_liveness_highwater > prev_liveness: + healthy_ticks = int(state.get("healthy_ticks", 0)) + 1 + next_state["healthy_ticks"] = healthy_ticks + if healthy_ticks >= _EPISODE_RESET_TICKS: + next_state["episode_alerted"] = False + else: + next_state["healthy_ticks"] = 0 _atomic_write_json(config.state_path, next_state) return result diff --git a/tests/test_throughput_watchdog.py b/tests/test_throughput_watchdog.py index 401f76b0..7973d2b3 100644 --- a/tests/test_throughput_watchdog.py +++ b/tests/test_throughput_watchdog.py @@ -606,3 +606,53 @@ def test_launchagent_runs_every_minute_and_invokes_installed_script() -> None: assert plist["EnvironmentVariables"]["BRAINLAYER_ENV_FILE"] == "__BRAINLAYER_ENV_FILE__" assert plist["EnvironmentVariables"]["BRAINLAYER_LAUNCHD_SERVICE"] == "watch" assert plist["SoftResourceLimits"]["NumberOfFiles"] >= 4096 + + +def test_alert_framing_pages_once_per_episode_not_per_kickstart(tmp_path: Path) -> None: + """Alert-framing: a chronic wedge sawtooth pages on the FIRST wedge of an + episode only, re-paging for a NEW episode after a sustained healthy run.""" + module = _load_module() + config = _config(module, tmp_path, stall_threshold=3, cooldown_seconds=0) + alerts: list[int] = [] + + def command_runner(args: list[str]): + stdout = "state = running\npid = 4321\n" if args[:2] == ["launchctl", "print"] else "" + return SimpleNamespace(returncode=0, stdout=stdout, stderr="") + + clock = {"t": 1_000} + + def tick(rowid: int, *, pending: bool) -> object: + clock["t"] += 60 + evidence = module.SourceEvidence(2, 120, 3, 999.0) if pending else module.SourceEvidence(0, 0, 0, 999.0) + res = module.run_once( + config, + now_epoch=clock["t"], + progress_reader=lambda _p, r=rowid: _progress(module, r, r), + source_probe=lambda _c, _n, e=evidence: e, + command_runner=command_runner, + alert_fn=lambda _c, _r: alerts.append(clock["t"]), + ) + return res + + tick(40, pending=True) # baseline + tick(40, pending=True) # stall 1 + tick(40, pending=True) # stall 2 + k1 = tick(40, pending=True) # stall 3 -> kickstart + FIRST alert + assert k1.action.startswith("kickstart:") + assert len(alerts) == 1 # episode 1 paged once + + tick(50, pending=True) # brief recovery (1 healthy tick, < reset) + tick(50, pending=True) # stall 1 + tick(50, pending=True) # stall 2 + k2 = tick(50, pending=True) # stall 3 -> kickstart, SUPPRESSED (same episode) + assert k2.action.startswith("kickstart:") + assert len(alerts) == 1 # sawtooth did NOT re-page + + tick(60, pending=True) # sustained recovery: healthy 1 + tick(70, pending=True) # healthy 2 + tick(80, pending=True) # healthy 3 -> episode latch clears + tick(80, pending=True) # stall 1 + tick(80, pending=True) # stall 2 + k3 = tick(80, pending=True) # stall 3 -> kickstart + NEW-episode alert + assert k3.action.startswith("kickstart:") + assert len(alerts) == 2 # new episode paged again From 8771ec2bd5691d9ece83ba369edcb3edb8744bac Mon Sep 17 00:00:00 2001 From: Etan Joseph Heyman Date: Sat, 18 Jul 2026 16:01:06 +0300 Subject: [PATCH 2/4] fix(watchdog): count chunk progress toward episode reset (Codex P2) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The episode-reset latch keyed only on liveness_rowid advancement, but a DB without watcher_liveness_events reports liveness_rowid==0 forever while chunk highwater still advances — so after the first alerted wedge the latch never cleared and no NEW episode ever re-paged. Now "healthy" progress counts EITHER chunk highwater OR liveness. Kickstart ticks still don't count (state pre-advances both rowids). Suite 21/21, ruff clean. Co-Authored-By: Claude Fable 5 --- scripts/launchd/throughput-watchdog.py | 13 +++++++++---- 1 file changed, 9 insertions(+), 4 deletions(-) diff --git a/scripts/launchd/throughput-watchdog.py b/scripts/launchd/throughput-watchdog.py index 8fcb26d7..0f025bc1 100755 --- a/scripts/launchd/throughput-watchdog.py +++ b/scripts/launchd/throughput-watchdog.py @@ -562,11 +562,16 @@ def run_once( # Episode reset (alert-framing): clear the first-wedge page latch after a # SUSTAINED healthy run, so the next genuine wedge pages again without - # re-paging every cycle of a chronic sawtooth. A kickstart tick is never - # "healthy" (its state already advanced the liveness rowid), so the counter - # only climbs on real, unassisted watcher progress. + # re-paging every cycle of a chronic sawtooth. "Healthy" = real watcher + # progress by EITHER measure — chunk highwater OR liveness rowid — because + # a DB without watcher_liveness_events reports liveness_rowid==0 forever + # while chunks still advance (else the latch would never reset there). A + # kickstart tick is never healthy: its own state pre-advances both rowids to + # the current values, so neither comparison is strictly-greater on that tick. + prev_chunk = int(state.get("watcher_highwater_rowid", 0) or 0) prev_liveness = int(state.get("watcher_liveness_highwater_rowid", 0) or 0) - if result.stalled_ticks == 0 and current_liveness_highwater > prev_liveness: + progressed = current_highwater > prev_chunk or current_liveness_highwater > prev_liveness + if result.stalled_ticks == 0 and progressed: healthy_ticks = int(state.get("healthy_ticks", 0)) + 1 next_state["healthy_ticks"] = healthy_ticks if healthy_ticks >= _EPISODE_RESET_TICKS: From d3350ea25fac2299b6117159729accaf934a9862 Mon Sep 17 00:00:00 2001 From: Etan Joseph Heyman Date: Sat, 18 Jul 2026 16:03:47 +0300 Subject: [PATCH 3/4] style(test): ruff-format the alert-framing test (CI lint) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The appended episode-gating test wasn't ruff-formatted; `ruff format --check tests/` failed in CI. Formatting only — no logic change. Suite 21/21. Co-Authored-By: Claude Fable 5 --- tests/test_throughput_watchdog.py | 36 +++++++++++++++---------------- 1 file changed, 18 insertions(+), 18 deletions(-) diff --git a/tests/test_throughput_watchdog.py b/tests/test_throughput_watchdog.py index 7973d2b3..a5ff04df 100644 --- a/tests/test_throughput_watchdog.py +++ b/tests/test_throughput_watchdog.py @@ -634,25 +634,25 @@ def tick(rowid: int, *, pending: bool) -> object: ) return res - tick(40, pending=True) # baseline - tick(40, pending=True) # stall 1 - tick(40, pending=True) # stall 2 - k1 = tick(40, pending=True) # stall 3 -> kickstart + FIRST alert + tick(40, pending=True) # baseline + tick(40, pending=True) # stall 1 + tick(40, pending=True) # stall 2 + k1 = tick(40, pending=True) # stall 3 -> kickstart + FIRST alert assert k1.action.startswith("kickstart:") - assert len(alerts) == 1 # episode 1 paged once + assert len(alerts) == 1 # episode 1 paged once - tick(50, pending=True) # brief recovery (1 healthy tick, < reset) - tick(50, pending=True) # stall 1 - tick(50, pending=True) # stall 2 - k2 = tick(50, pending=True) # stall 3 -> kickstart, SUPPRESSED (same episode) + tick(50, pending=True) # brief recovery (1 healthy tick, < reset) + tick(50, pending=True) # stall 1 + tick(50, pending=True) # stall 2 + k2 = tick(50, pending=True) # stall 3 -> kickstart, SUPPRESSED (same episode) assert k2.action.startswith("kickstart:") - assert len(alerts) == 1 # sawtooth did NOT re-page - - tick(60, pending=True) # sustained recovery: healthy 1 - tick(70, pending=True) # healthy 2 - tick(80, pending=True) # healthy 3 -> episode latch clears - tick(80, pending=True) # stall 1 - tick(80, pending=True) # stall 2 - k3 = tick(80, pending=True) # stall 3 -> kickstart + NEW-episode alert + assert len(alerts) == 1 # sawtooth did NOT re-page + + tick(60, pending=True) # sustained recovery: healthy 1 + tick(70, pending=True) # healthy 2 + tick(80, pending=True) # healthy 3 -> episode latch clears + tick(80, pending=True) # stall 1 + tick(80, pending=True) # stall 2 + k3 = tick(80, pending=True) # stall 3 -> kickstart + NEW-episode alert assert k3.action.startswith("kickstart:") - assert len(alerts) == 2 # new episode paged again + assert len(alerts) == 2 # new episode paged again From 96ef4b8497fe8b57116f419b1c33bd4f15d0ae3e Mon Sep 17 00:00:00 2001 From: Etan Joseph Heyman Date: Sat, 18 Jul 2026 21:02:18 +0300 Subject: [PATCH 4/4] fix(watchdog): latch the episode only when the page actually sent MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit reviewer-1 caught a page-once→page-zero inversion: episode_alerted was written True unconditionally even when alert_fn RAISED, so a transient notify failure on the first wedge silenced the ENTIRE episode — and the page is the operator's only outage signal. Now the latch is set only on a successful send; a failed alert leaves it clear so the next wedge retries. Test: test_failed_alert_does_not_latch_episode_and_retries — first-wedge alert raises, second wedge in the same episode retries (not silenced). Suite 22/22, ruff clean. Co-Authored-By: Claude Fable 5 --- scripts/launchd/throughput-watchdog.py | 10 +++++-- tests/test_throughput_watchdog.py | 40 ++++++++++++++++++++++++++ 2 files changed, 48 insertions(+), 2 deletions(-) diff --git a/scripts/launchd/throughput-watchdog.py b/scripts/launchd/throughput-watchdog.py index 0f025bc1..8e4445d4 100755 --- a/scripts/launchd/throughput-watchdog.py +++ b/scripts/launchd/throughput-watchdog.py @@ -499,9 +499,15 @@ def run_once( # Alert-framing: page on the FIRST wedge of an episode only — never # per-kick of a chronic sawtooth. The latch clears after a sustained # healthy run (episode reset below). Recovery still runs every tick. - if not state.get("episode_alerted"): + # The latch is set ONLY when the page actually sent — a transient + # notify failure on the first wedge must NOT silence the whole + # episode (page-once must never become page-zero); the next tick + # retries the alert instead. + episode_alerted = bool(state.get("episode_alerted")) + if not episode_alerted: try: alert_fn(config, result) + episode_alerted = True except Exception as exc: result.alert_error = str(exc) print(f"throughput-watchdog alert failed: {exc}", file=sys.stderr) @@ -521,7 +527,7 @@ def run_once( "last_action": "recovery_attempt", "last_restart_epoch": checked_at, "restart_attempt_count": int(state.get("restart_attempt_count", 0)) + 1, - "episode_alerted": True, + "episode_alerted": episode_alerted, } ) _atomic_write_json(config.state_path, attempt_state) diff --git a/tests/test_throughput_watchdog.py b/tests/test_throughput_watchdog.py index a5ff04df..d3c9905c 100644 --- a/tests/test_throughput_watchdog.py +++ b/tests/test_throughput_watchdog.py @@ -656,3 +656,43 @@ def tick(rowid: int, *, pending: bool) -> object: k3 = tick(80, pending=True) # stall 3 -> kickstart + NEW-episode alert assert k3.action.startswith("kickstart:") assert len(alerts) == 2 # new episode paged again + + +def test_failed_alert_does_not_latch_episode_and_retries(tmp_path: Path) -> None: + """A transient notify failure on the first wedge must NOT silence the + episode — page-once must never become page-zero; the next wedge retries.""" + module = _load_module() + config = _config(module, tmp_path, stall_threshold=3, cooldown_seconds=0) + calls = {"n": 0} + + def command_runner(args): + stdout = "state = running\npid = 4321\n" if args[:2] == ["launchctl", "print"] else "" + return SimpleNamespace(returncode=0, stdout=stdout, stderr="") + + def flaky_alert(_config, _result): + calls["n"] += 1 + if calls["n"] == 1: + raise RuntimeError("notify endpoint down") + + clock = {"t": 1_000} + + def tick(): + clock["t"] += 60 + return module.run_once( + config, + now_epoch=clock["t"], + progress_reader=lambda _p: _progress(module, 40, 40), + source_probe=lambda _c, _n: module.SourceEvidence(2, 120, 3, 999.0), + command_runner=command_runner, + alert_fn=flaky_alert, + ) + + tick() # baseline (establishes highwater; not a stall) + tick() # stall 1 + tick() # stall 2 + tick() # stall 3 -> kickstart, alert RAISES (call 1), NOT latched + assert calls["n"] == 1 + tick() # stall 1 + tick() # stall 2 + tick() # stall 3 -> kickstart, alert RETRIES in same episode (call 2) + assert calls["n"] == 2 # retried, not silenced by the earlier failure