From df435998f9372e79eccb69bedab9bead4f51304a Mon Sep 17 00:00:00 2001 From: Alexander Nikolas Date: Thu, 24 Sep 2026 10:28:21 +0000 Subject: [PATCH 1/7] fix: retain session prompt across route metadata writes (#958) Verified targeted session-state, restore, accounting, and model-resume tests: 236 passed, 1 pre-existing dashboard-auth fixture warning deselected. Reproduced NULL from billing route before fix. Co-authored-by: Kyzcreig <9063726+Kyzcreig@users.noreply.github.com> --- hermes_state.py | 34 +++++++++---------- tests/agent/test_system_prompt_restore.py | 32 ++++++++++++++++++ tests/test_hermes_state_core.py | 7 ++-- tests/test_session_system_prompt_dedup.py | 41 ++++++++++++++++++++--- 4 files changed, 87 insertions(+), 27 deletions(-) diff --git a/hermes_state.py b/hermes_state.py index 742df80a7e24d..f08f5f4689198 100644 --- a/hermes_state.py +++ b/hermes_state.py @@ -9148,6 +9148,11 @@ def _do(conn): "SET system_prompt_hash = ?, system_prompt = NULL WHERE id = ?", (system_prompt_hash, session_id), ) + if system_prompt is None: + logger.warning( + "Explicit system_prompt=NULL write for session %s via " + "update_system_prompt", session_id, stack_info=True, + ) self._delete_unreferenced_system_prompts(conn) self._execute_write(_do) @@ -9232,9 +9237,9 @@ def update_session_model( Unlike ``update_token_counts`` which uses ``COALESCE(model, ?)`` (only filling in NULL), this unconditionally sets the model column so that the dashboard reflects the user's latest /model choice. - Also nulls ``system_prompt`` so stale ``Model:`` / ``Provider:`` - footer metadata is rebuilt on the next turn. A successful /model - switch explicitly replaces any confirmed Browser runtime lock while + Retains the prior prompt until the next turn replaces it: the restore + path checks its runtime identity and rebuilds on a real change. A + successful /model switch replaces any confirmed Browser runtime lock while preserving unrelated lineage markers in ``model_config``. When *provider* is given, it is merged into ``model_config`` @@ -9267,12 +9272,10 @@ def _do(conn): return conn.execute( "UPDATE sessions SET " - "model = ?, model_config = ?, " - "system_prompt = NULL, system_prompt_hash = NULL " + "model = ?, model_config = ? " "WHERE id = ?", (model, merged, session_id), ) - self._delete_unreferenced_system_prompts(conn) self._execute_write(_do) def _merge_model_config_json( @@ -9379,8 +9382,8 @@ def update_session_runtime_lock( """Persist a Browser / API client runtime lock without clobbering lineage markers. Merges ``browser_model_lock`` into the existing ``model_config`` JSON so - ``_branched_from`` / ``_delegate_from`` survive. Nulls ``system_prompt`` - so cached ``Model:`` / ``Provider:`` footers cannot lie after a switch. + ``_branched_from`` / ``_delegate_from`` survive. The prior prompt is + retained until restore checks the runtime identity and replaces it. """ lock = { "provider": provider or "", @@ -9400,13 +9403,10 @@ def _do(conn): conn.execute( """UPDATE sessions SET model_config = ?, - model = COALESCE(?, model), - system_prompt = NULL, - system_prompt_hash = NULL + model = COALESCE(?, model) WHERE id = ?""", (merged, model, session_id), ) - self._delete_unreferenced_system_prompts(conn) self._execute_write(_do) def set_session_yolo(self, session_id: str, enabled: bool) -> None: @@ -9521,9 +9521,8 @@ def update_session_billing_route( (only filling in NULL), this unconditionally sets the billing fields so that the dashboard reflects the user's latest /model switch. - Also nulls ``system_prompt`` so the cached snapshot (which embeds a - stale ``Model:`` / ``Provider:`` header) is rebuilt — matching the - behavior of ``update_session_model`` (see #48173, #48248). + Retains the cached snapshot until restore compares its runtime identity; + a billing-only route update does not change the prompt bytes. """ # Barrier against queued token deltas — see update_session_model. self.flush_token_counts() @@ -9533,13 +9532,10 @@ def _do(conn): """UPDATE sessions SET billing_provider = ?, billing_base_url = ?, - billing_mode = COALESCE(?, billing_mode), - system_prompt = NULL, - system_prompt_hash = NULL + billing_mode = COALESCE(?, billing_mode) WHERE id = ?""", (provider, base_url, billing_mode, session_id), ) - self._delete_unreferenced_system_prompts(conn) self._execute_write(_do) # ── Async token accounting ── diff --git a/tests/agent/test_system_prompt_restore.py b/tests/agent/test_system_prompt_restore.py index aee08f1061ec1..9d64cbb59fa5e 100644 --- a/tests/agent/test_system_prompt_restore.py +++ b/tests/agent/test_system_prompt_restore.py @@ -46,6 +46,38 @@ def _make_agent(session_db=None, prebuilt_prompt: str = "BUILT_PROMPT"): class TestStoredPromptReuse: + def test_route_write_preserves_prompt_until_next_turn_rebuilds(self, tmp_path, caplog): + from hermes_state import SessionDB + + old = "Model: old-model\nProvider: openrouter" + new = "Model: new-model\nProvider: openrouter" + history = [{"role": "user", "content": "continue"}] + with SessionDB(db_path=tmp_path / "state.db") as db: + db.create_session("test-session-id", "telegram", system_prompt=old) + db.update_session_billing_route( + "test-session-id", provider="openrouter", base_url="https://other.example/v1" + ) + same = _make_agent(session_db=db) + same.model = "old-model" + with caplog.at_level(logging.INFO, logger="agent.conversation_loop"): + _restore_or_build_system_prompt(same, None, history) + assert same._cached_system_prompt == old + same._build_system_prompt.assert_not_called() + assert "is null" not in caplog.text + + db.update_session_model("test-session-id", "new-model", provider="openrouter") + changed = _make_agent(session_db=db, prebuilt_prompt=new) + changed.model = "new-model" + caplog.clear() + with caplog.at_level(logging.INFO, logger="agent.conversation_loop"): + _restore_or_build_system_prompt(changed, None, history) + changed._build_system_prompt.assert_called_once_with(None) + restored = db.get_session("test-session-id") + assert restored is not None + assert restored["system_prompt"] == new + assert "stale runtime identity" in caplog.text + assert "is null" not in caplog.text + def test_present_row_is_reused_verbatim(self, caplog): """Continuing session with a stored prompt → reuse byte-for-byte.""" stored = "Stored prompt from turn 1 — byte-identical reuse" diff --git a/tests/test_hermes_state_core.py b/tests/test_hermes_state_core.py index 21d40ce802eea..76cacab7066a0 100644 --- a/tests/test_hermes_state_core.py +++ b/tests/test_hermes_state_core.py @@ -1052,8 +1052,8 @@ def test_update_session_billing_route_overwrites_after_switch(self, db): COALESCE(billing_provider, ?) (first-writer-wins), so after a provider switch the dashboard kept attributing cost to the original provider (#48248). update_session_billing_route sets them - unconditionally and nulls system_prompt so the next turn rebuilds - the Model:/Provider: header (#48173). + unconditionally. The prompt remains until the next turn checks its + runtime identity and rebuilds only if Model:/Provider: changed (#48173). """ db.create_session(session_id="s1", source="telegram") # First token update seeds the billing route. @@ -1081,8 +1081,7 @@ def test_update_session_billing_route_overwrites_after_switch(self, db): assert sess["billing_provider"] == "ollama" assert sess["billing_base_url"] == "http://localhost:11434/v1" assert sess["billing_mode"] == "local" - assert sess["system_prompt"] is None, \ - "system_prompt must be nulled so the next turn rebuilds Model:/Provider:" + assert sess["system_prompt"] == "Model: x/old\nProvider: openrouter" # billing_mode defaults to COALESCE — omitting it preserves the value. db.update_session_billing_route( diff --git a/tests/test_session_system_prompt_dedup.py b/tests/test_session_system_prompt_dedup.py index 966920a76caf3..0546a479ffe62 100644 --- a/tests/test_session_system_prompt_dedup.py +++ b/tests/test_session_system_prompt_dedup.py @@ -3,6 +3,7 @@ from __future__ import annotations import json +import logging import sqlite3 import time @@ -76,7 +77,7 @@ def test_prompt_replacement_and_route_changes_collect_only_orphans(db): confirmed=True, ) s1 = db.get_session("s1") - assert s1["system_prompt"] is None + assert s1["system_prompt"] == shared_prompt assert json.loads(s1["model_config"])["_branched_from"] == "parent" assert db.get_session("s2")["system_prompt"] == shared_prompt assert _prompt_count(db) == 1 @@ -86,13 +87,45 @@ def test_prompt_replacement_and_route_changes_collect_only_orphans(db): provider="openrouter", base_url="https://example.test/v1", ) - assert db.get_session("s2")["system_prompt"] is None - assert _prompt_count(db) == 0 + assert db.get_session("s2")["system_prompt"] == shared_prompt + assert _prompt_count(db) == 1 db.update_system_prompt("s2", "replacement") assert db.get_session("s2")["system_prompt"] == "replacement" db.update_system_prompt("s2", None) - assert _prompt_count(db) == 0 + assert _prompt_count(db) == 1 # s1 still references the original snapshot + + +def test_route_updates_keep_prompt_until_replacement_is_ready(db): + """Changing routes must not leave a continuing session with a NULL prompt.""" + prompt = "Model: original\nProvider: old" + db.create_session("s1", "telegram", model="original", system_prompt=prompt) + + db.update_session_billing_route("s1", provider="old", base_url="https://new.example/v1") + assert db.get_session("s1")["system_prompt"] == prompt + + db.update_session_model("s1", "replacement", provider="new") + assert db.get_session("s1")["system_prompt"] == prompt + + db.update_session_runtime_lock("s1", model="replacement", provider="new", confirmed=True) + assert db.get_session("s1")["system_prompt"] == prompt + + db.update_system_prompt("s1", "Model: replacement\nProvider: new") + assert db.get_session("s1")["system_prompt"] == "Model: replacement\nProvider: new" + assert _prompt_count(db) == 1 + + +def test_explicit_prompt_clear_records_writer_stack(db, caplog): + db.create_session("s1", "cli", system_prompt="stored prompt") + with caplog.at_level(logging.WARNING, logger="hermes_state"): + db.update_system_prompt("s1", None) + assert db.get_session("s1")["system_prompt"] is None + assert any( + "s1" in record.getMessage() + and "update_system_prompt" in (record.stack_info or "") + and "test_explicit_prompt_clear_records_writer_stack" in (record.stack_info or "") + for record in caplog.records + ) def test_existing_session_enrichment_does_not_leak_unused_prompt(db): From 2ddcd585e9ff41fde2c7dbf7f25c92302f0a17ae Mon Sep 17 00:00:00 2001 From: Kyzcreig <9063726+Kyzcreig@users.noreply.github.com> Date: Thu, 24 Sep 2026 03:29:44 -0700 Subject: [PATCH 2/7] fix(gateway): restart follow-ups keep adapter-granted admission; refused replays reported lost (t_43e058b7) Argus r8 N1 (t_e253d9d5): SessionSource.to_dict drops is_bot / role_authorized / delivered_via_upstream_relay / profile_route_rejected, so a spooled follow-up admitted only by ALLOW_BOTS, ALLOWED_ROLES or the relay was refused as "Unauthorized user" on boot replay, its spool file acked, and restart_followup_lost logged 0 lines. Trust model: to_dict stays wire-safe (unchanged). The spool record carries the flags in a separate `admission` block and the whole record is HMAC-SHA256'd with a per-home 0600 key (/gateway/restart_followups.key). On load the flags are restored only if the MAC verifies; otherwise no trust flag is restored (only fail-closed profile_route_rejected is honoured) and PHASE=restart_followup_untrusted is logged. Live policy is still re-evaluated by the normal intake. A replay the intake refuses (unauthorized / profile_route_rejected) now logs PHASE=restart_followup_lost with reason. MF (same review): AST contract that the post-turn draining site spools pending_event itself, not None. Verified: new real stop->boot e2e (human/bot/role/relay, forged, tampered, gate-closed-during-restart, to_dict class guard) 8/8; on base 3 admission arms fail, human control passes. Focused restart suites 49/49. Mutants: MAC unchecked, refusal unreported, admission unrestored, MF pending_event=None all KILLED. Argus probe_r8_source_authz_real_intake: B/R PRESERVED, CONTROL ok. Session/authz/startup-restore suites 445 passed. --- gateway/fork_ext/restart_followups.py | 100 +++++++ gateway/run.py | 46 +++- gateway/session.py | 3 + .../test_restart_followups_admission_e2e.py | 259 ++++++++++++++++++ ...test_restart_interrupt_intent_followups.py | 26 ++ 5 files changed, 431 insertions(+), 3 deletions(-) create mode 100644 tests/gateway/test_restart_followups_admission_e2e.py diff --git a/gateway/fork_ext/restart_followups.py b/gateway/fork_ext/restart_followups.py index b94a969b27432..3a1b68d27aef3 100644 --- a/gateway/fork_ext/restart_followups.py +++ b/gateway/fork_ext/restart_followups.py @@ -20,9 +20,12 @@ from __future__ import annotations +import hashlib +import hmac import json import logging import os +import secrets import time import uuid from pathlib import Path @@ -60,6 +63,88 @@ def spool_dir(home: Optional[Path] = None) -> Path: } +# SessionSource admission signals that ``SessionSource.to_dict`` deliberately +# does NOT serialise (t_43e058b7). Without them a follow-up admitted only by an +# adapter-granted flag (``{PLATFORM}_ALLOW_BOTS`` -> ``is_bot``, +# ``DISCORD_ALLOWED_ROLES`` -> ``role_authorized``, the authenticated relay -> +# ``delivered_via_upstream_relay``) is refused as "Unauthorized user" on replay. +# +# Trust model. ``to_dict`` stays wire-safe (a peer or a persisted session row +# must never be able to assert these). The restart spool instead records the +# transport's verdict in a separate ``admission`` block and binds the WHOLE +# record with an HMAC keyed by a per-home secret (``SPOOL_KEY_NAME``, 0600, +# created by the gateway itself). On load: +# * MAC verifies -> the admission flags are restored exactly as parked; +# the live policy (ALLOW_BOTS / ALLOWED_ROLES / relay adapter) is still +# re-evaluated by the normal intake, so a gate closed during the restart +# still refuses. +# * MAC missing / wrong (hand-written, edited, copied from another home, or +# written by a pre-fix build) -> NO trust flag is restored; only the +# fail-closed ``profile_route_rejected`` is honoured, since it can only +# tighten. A forged record therefore gains nothing it could not get by +# omitting the block. +# Anyone able to read the key can already edit this home's .env/config and +# grant themselves access directly, so the key adds no new trust root. +# A replay the intake still refuses is reported as ``restart_followup_lost`` +# by the runner, never silently acknowledged. +TRUST_GRANTING_ADMISSION_FIELDS = ("is_bot", "role_authorized", "delivered_via_upstream_relay") +FAIL_CLOSED_ADMISSION_FIELDS = ("profile_route_rejected",) +ADMISSION_FIELDS = TRUST_GRANTING_ADMISSION_FIELDS + FAIL_CLOSED_ADMISSION_FIELDS +SPOOL_KEY_NAME = "restart_followups.key" + + +def admission_fields(source: Any) -> Dict[str, bool]: + """The SessionSource admission flags, as strict bools (``is True``).""" + return {name: getattr(source, name, False) is True for name in ADMISSION_FIELDS} + + +def _spool_key(home: Optional[Path] = None, *, create: bool) -> Optional[bytes]: + path = spool_dir(home).parent / SPOOL_KEY_NAME + try: + return bytes.fromhex(path.read_text(encoding="ascii").strip()) + except FileNotFoundError: + if not create: + return None + except Exception: + logger.warning("restart follow-up spool key unreadable: %s", path, exc_info=True) + return None + try: + path.parent.mkdir(parents=True, exist_ok=True) + fd = os.open(str(path), os.O_WRONLY | os.O_CREAT | os.O_EXCL, 0o600) + with os.fdopen(fd, "w", encoding="ascii") as fh: + fh.write(secrets.token_hex(32)) + fh.flush() + os.fsync(fh.fileno()) + except FileExistsError: + pass # a concurrent writer created it first; read theirs + except Exception: + logger.warning("restart follow-up spool key could not be created: %s", path, exc_info=True) + return None + return _spool_key(home, create=False) + + +def _record_mac(key: bytes, record: Dict[str, Any]) -> str: + body = {k: v for k, v in record.items() if k != "mac" and not k.startswith("_")} + payload = json.dumps(body, sort_keys=True, separators=(",", ":")).encode("utf-8") + return hmac.new(key, payload, hashlib.sha256).hexdigest() + + +def restored_admission(record: Dict[str, Any]) -> Dict[str, bool]: + """Admission flags a loaded record may apply to its rebuilt SessionSource.""" + claimed = record.get("admission") + if not isinstance(claimed, dict): + return {} + if record.get("_admission_verified") is True: + return {name: claimed.get(name) is True for name in ADMISSION_FIELDS} + if any(claimed.get(name) is True for name in TRUST_GRANTING_ADMISSION_FIELDS): + logger.warning( + "PHASE=restart_followup_untrusted session=%s: admission flags are not " + "vouched for by this home's spool key; replaying WITHOUT them", + record.get("session_key"), + ) + return {name: True for name in FAIL_CLOSED_ADMISSION_FIELDS if claimed.get(name) is True} + + def event_fields(event: Any) -> Tuple[Optional[Dict[str, Any]], Optional[str]]: """Serialise every carried MessageEvent field. @@ -117,11 +202,14 @@ def spool_followup( home: Optional[Path] = None, now: Optional[float] = None, event: Optional[Dict[str, Any]] = None, + admission: Optional[Dict[str, bool]] = None, ) -> Optional[Path]: """Durably record ONE follow-up. Returns the file path, or None on failure. ``event`` is the ``event_fields`` dict of the parked MessageEvent; without it the record replays as a plain user text message (version 1 shape). + ``admission`` is ``admission_fields(source)``; it is stored MAC-bound (see + the trust model above) and only restored when the MAC verifies. """ if not session_key or not isinstance(text, str): return None @@ -142,6 +230,11 @@ def spool_followup( } if event is not None: record["event"] = event + if admission: + record["admission"] = {k: admission.get(k) is True for k in ADMISSION_FIELDS} + key = _spool_key(home, create=True) + if key is not None: + record["mac"] = _record_mac(key, record) try: directory = spool_dir(home) directory.mkdir(parents=True, exist_ok=True) @@ -177,6 +270,7 @@ def take_followups( except Exception: return records, stale current = time.time() if now is None else float(now) + key = _spool_key(home, create=False) for path in files: try: record = json.loads(path.read_text(encoding="utf-8")) @@ -193,6 +287,12 @@ def take_followups( stale += 1 path.rename(path.with_suffix(".stale")) continue + mac = record.get("mac") + record["_admission_verified"] = bool( + key is not None + and isinstance(mac, str) + and hmac.compare_digest(mac, _record_mac(key, record)) + ) record["_spool_path"] = str(path) records.append(record) except Exception: diff --git a/gateway/run.py b/gateway/run.py index 4fa5ca5582e33..8aea888f8e3ad 100644 --- a/gateway/run.py +++ b/gateway/run.py @@ -15777,7 +15777,11 @@ async def _preserve_followup_across_restart( event that was parked. An event with a field that cannot be stored durably is refused and logged as lost by field name. """ - from gateway.fork_ext.restart_followups import event_fields, spool_followup + from gateway.fork_ext.restart_followups import ( + admission_fields, + event_fields, + spool_followup, + ) fields = None if pending_event is not None: @@ -15835,6 +15839,10 @@ async def _preserve_followup_across_restart( src_dict, reason=self._status_action_label(), event=fields, + # Adapter-granted admission (is_bot / role_authorized / + # relay) that SessionSource.to_dict never serialises; + # MAC-bound so a forged record cannot assert it (t_43e058b7). + admission=admission_fields(src), ) except Exception: logger.debug("restart follow-up spool failed", exc_info=True) @@ -15924,7 +15932,11 @@ async def _spool_one_adapter_pending(self, adapter: Any, seen: Optional[set] = N async def _load_restart_followups(self) -> int: """Queue follow-ups spooled by the previous life into startup restore.""" try: - from gateway.fork_ext.restart_followups import event_kwargs, take_followups + from gateway.fork_ext.restart_followups import ( + event_kwargs, + restored_admission, + take_followups, + ) records, stale = await asyncio.to_thread(take_followups) except Exception: @@ -15936,9 +15948,15 @@ async def _load_restart_followups(self) -> int: carried = record.get("event") kwargs = event_kwargs(carried) if isinstance(carried, dict) else {} kwargs.setdefault("message_type", MessageType.TEXT) + source = SessionSource.from_dict(record["source"]) + for flag, value in restored_admission(record).items(): + setattr(source, flag, value) + # In-process only: lets the intake report a replay it refuses + # as restart_followup_lost (the spool file is already acked). + source._restart_followup_session = record.get("session_key") event = MessageEvent( text=record["text"], - source=SessionSource.from_dict(record["source"]), + source=source, **kwargs, ) event._hermes_restart_followup_path = record["_spool_path"] @@ -15958,6 +15976,25 @@ async def _load_restart_followups(self) -> int: ) return queued + def _report_refused_restart_followup(self, source: Any, reason: str) -> None: + """A replayed restart follow-up refused at intake is LOST, never silent. + + Its spool file was acknowledged when the adapter accepted the replay, + so this log line is the only remaining trace (t_43e058b7). + """ + session = getattr(source, "_restart_followup_session", None) + if not session: + return + logger.error( + "PHASE=restart_followup_lost session=%s reason=%s platform=%s chat=%s " + "user=%s: replayed follow-up refused at intake; it is DROPPED", + session, + reason, + getattr(getattr(source, "platform", None), "value", "unknown"), + getattr(source, "chat_id", None), + getattr(source, "user_id", None), + ) + def _queue_startup_restore_event(self, event: MessageEvent) -> None: queue = getattr(self, "_startup_restore_queue", None) if queue is None: @@ -22839,6 +22876,7 @@ async def _handle_message(self, event: MessageEvent) -> Optional[str]: "Dropping inbound message because its explicit profile route " "targets an unserved profile" ) + self._report_refused_restart_followup(source, "profile_route_rejected") return None # Internal events (e.g. background-process completion notifications) @@ -22935,9 +22973,11 @@ async def _handle_message(self, event: MessageEvent) -> Optional[str]: # sender). Defer to _is_user_authorized so that path runs. if not self._is_user_authorized_for_source(source): logger.debug("Ignoring message with no user_id from %s", source.platform.value) + self._report_refused_restart_followup(source, "unauthorized") return None elif not self._is_user_authorized_for_source(source): logger.warning("Unauthorized user: %s (%s) on %s", source.user_id, source.user_name, source.platform.value) + self._report_refused_restart_followup(source, "unauthorized") # In DMs: offer pairing code. In groups: silently ignore. if ( source.chat_type == "dm" diff --git a/gateway/session.py b/gateway/session.py index 937591d555e2b..f16e0863749dc 100644 --- a/gateway/session.py +++ b/gateway/session.py @@ -244,6 +244,9 @@ class SessionSource: # Set locally by the relay transport (``ws_transport._event_from_wire``); # deliberately excluded from ``to_dict``/``from_dict`` so a peer can never # forge it across the wire or have it restored from persistence. + # Sole exception: the gateway's own restart spool carries it (with is_bot / + # role_authorized) in a separate MAC-bound ``admission`` block and restores + # it only when that MAC verifies — see gateway/fork_ext/restart_followups.py. delivered_via_upstream_relay: bool = False def __post_init__(self) -> None: diff --git a/tests/gateway/test_restart_followups_admission_e2e.py b/tests/gateway/test_restart_followups_admission_e2e.py new file mode 100644 index 0000000000000..3ca2bd2b7de24 --- /dev/null +++ b/tests/gateway/test_restart_followups_admission_e2e.py @@ -0,0 +1,259 @@ +"""Restart follow-ups keep adapter-granted admission across the spool (t_43e058b7). + +Argus r8 N1 (t_e253d9d5): a follow-up admitted only by an adapter-granted +SessionSource flag (``is_bot`` under DISCORD_ALLOW_BOTS, ``role_authorized`` +under DISCORD_ALLOWED_ROLES, ``delivered_via_upstream_relay`` from the relay) +lost that flag in ``SessionSource.to_dict`` -> spool -> ``from_dict``, was +refused as "Unauthorized user" on boot replay, its spool file was acked anyway +and ``restart_followup_lost`` logged 0 lines. + +Everything is the production path on a throwaway home: park on the real +adapter slot, real ``GatewayRunner.stop(restart=True)``, real ``start()`` -> +loader -> drain -> REAL ``BasePlatformAdapter.handle_message`` -> runner +intake/authz. The only stub is ``_handle_message_with_agent`` (the LLM turn), +replaced by a recorder: "reached the agent" is the oracle. +""" + +import asyncio +import json +import logging + +import pytest + +from gateway.config import GatewayConfig, Platform, PlatformConfig +from gateway.fork_ext import restart_followups as rf +from gateway.platforms.base import BasePlatformAdapter, MessageEvent, MessageType, SendResult +from gateway.run import GatewayRunner +from gateway.session import SessionSource + +LOST = "PHASE=restart_followup_lost" +UNTRUSTED = "PHASE=restart_followup_untrusted" + + +class _Capture(logging.Handler): + def __init__(self): + super().__init__(logging.DEBUG) + self.lines = [] + + def emit(self, record): + try: + self.lines.append(record.getMessage()) + except Exception: + pass + + +class _FakeAdapter(BasePlatformAdapter): + """Fake transport; ``handle_message`` is NOT overridden (real intake).""" + + def __init__(self, platform): + super().__init__(PlatformConfig(enabled=True, token="synthetic"), platform) + + async def connect(self, *, is_reconnect=False): + self._mark_connected() + return True + + async def disconnect(self): + self._mark_disconnected() + + async def send(self, chat_id, content, reply_to=None, metadata=None): + return SendResult(success=True, message_id="1") + + async def send_typing(self, chat_id, metadata=None): + return None + + async def get_chat_info(self, chat_id): + return {"id": chat_id} + + +_CAP = _Capture() + + +def _runner(home, reached, platforms): + runner = GatewayRunner(GatewayConfig( + platforms={p: PlatformConfig(enabled=True, token="synthetic") for p in platforms}, + sessions_dir=home / "sessions", + )) + + async def _no_secondary(): + return 0 + + async def _recorder(event, source, quick_key, run_generation): + reached.append(event.text) + return None + + runner._start_secondary_profile_adapters = _no_secondary + runner._create_adapter = lambda platform, config: _FakeAdapter(platform) + runner._handle_message_with_agent = _recorder + return runner + + +def _event(user_id, chat_id, **flags): + src = SessionSource( + platform=Platform.DISCORD, chat_id=chat_id, chat_type="group", + guild_id="g1", user_id=user_id, **flags, + ) + return MessageEvent(text=f"follow-up from {user_id}", message_type=MessageType.TEXT, source=src) + + +@pytest.fixture +def home(tmp_path, monkeypatch): + monkeypatch.setenv("HERMES_HOME", str(tmp_path)) + monkeypatch.delenv("HERMES_PROFILE", raising=False) + for name in ("GATEWAY_ALLOW_ALL_USERS", "DISCORD_ALLOW_ALL_USERS", "DISCORD_ALLOWED_ROLES", + "GATEWAY_ALLOWED_USERS", "DISCORD_ALLOW_BOTS"): + monkeypatch.delenv(name, raising=False) + monkeypatch.setenv("DISCORD_ALLOWED_USERS", "human-1") + monkeypatch.setenv("DISCORD_ALLOW_BOTS", "mentions") + (tmp_path / "logs").mkdir() + cap = _CAP + cap.lines.clear() + root = logging.getLogger() + old_level = root.level + root.addHandler(cap) + root.setLevel(logging.DEBUG) + yield tmp_path + root.removeHandler(cap) + root.setLevel(old_level) + + +async def _park_and_stop(home, event, platforms): + first = _runner(home, [], platforms) + await asyncio.wait_for(first.start(), timeout=90) + key = f"agent:main:discord:group:{event.source.chat_id}:{event.source.user_id}" + first.adapters[Platform.DISCORD]._pending_messages[key] = event + await asyncio.wait_for(first.stop(restart=True, service_restart=False), timeout=90) + return sorted(rf.spool_dir().glob("*.json")) + + +async def _boot(home, platforms, before_boot=None): + if before_boot is not None: + before_boot() + reached = [] + mark = len(_CAP.lines) + boot = _runner(home, reached, platforms) + try: + await asyncio.wait_for(boot.start(), timeout=90) + for _ in range(150): + if reached: + break + await asyncio.sleep(0.1) + await asyncio.sleep(0.5) # a late refusal / duplicate would land here + finally: + await asyncio.wait_for(boot.stop(), timeout=60) + lines = _CAP.lines[mark:] + return reached, lines, sorted(rf.spool_dir().glob("*.json")) + + +ARMS = { + "human-control": (_event("human-1", "700"), (Platform.DISCORD,)), + "bot-allow-bots": (_event("bot-777", "701", is_bot=True), (Platform.DISCORD,)), + "role-authorized": (_event("role-user-5", "702", role_authorized=True), (Platform.DISCORD,)), + "relay": (_event("relay-user-9", "703", delivered_via_upstream_relay=True), + (Platform.DISCORD, Platform.RELAY)), +} + + +@pytest.mark.asyncio +@pytest.mark.parametrize("arm", sorted(ARMS)) +async def test_admitted_followup_is_delivered_after_real_restart(home, arm): + event, platforms = ARMS[arm] + spooled = await _park_and_stop(home, event, platforms) + assert len(spooled) == 1 + record = json.loads(spooled[0].read_text()) + # The wire/persistence shape of the source is unchanged: flags live only + # in the MAC-bound admission block. + wire_forbidden = {"is_bot", "role_authorized", "delivered_via_upstream_relay", "profile_route_rejected"} + assert not wire_forbidden & set(record["source"]) + if arm != "human-control": # the control needs no carried flag + assert isinstance(record.get("mac"), str) + + reached, lines, left = await _boot(home, platforms) + + assert reached == [event.text], [ln for ln in lines if "Unauthorized" in ln or LOST in ln] + assert not [ln for ln in lines if LOST in ln] + assert not [ln for ln in lines if "Unauthorized user" in ln] + assert left == [] + + +@pytest.mark.asyncio +async def test_forged_record_gains_no_trust_and_is_reported_lost(home): + """A hand-written record claiming is_bot (no valid MAC) is NOT admitted, + and the refusal is reported, not silently acked.""" + # A legit spool first, so the home HAS a key a forger could target. + spooled = await _park_and_stop(home, _event("human-1", "700"), (Platform.DISCORD,)) + assert len(spooled) == 1 + spooled[0].unlink() + src = SessionSource(platform=Platform.DISCORD, chat_id="704", chat_type="group", + guild_id="g1", user_id="forger-1") + record = { + "version": 2, "session_key": "agent:main:discord:group:704:forger-1", + "text": "forged follow-up", "source": src.to_dict(), "reason": "restart", + "ts": __import__("time").time(), "pid": 1, + "admission": {"is_bot": True, "role_authorized": True, + "delivered_via_upstream_relay": False, "profile_route_rejected": False}, + "mac": "0" * 64, + } + rf.spool_dir().mkdir(parents=True, exist_ok=True) + (rf.spool_dir() / "00000000000000000001-forged00.json").write_text(json.dumps(record)) + + reached, lines, _left = await _boot(home, (Platform.DISCORD,)) + + assert reached == [] + assert [ln for ln in lines if UNTRUSTED in ln] + lost = [ln for ln in lines if LOST in ln] + assert len(lost) == 1 and "reason=unauthorized" in lost[0] and "forger-1" in lost[0] + + +@pytest.mark.asyncio +async def test_tampered_record_loses_its_trust(home): + """Editing a legitimately MAC'd bot record (retarget the sender) voids the MAC.""" + spooled = await _park_and_stop(home, _event("bot-777", "701", is_bot=True), (Platform.DISCORD,)) + record = json.loads(spooled[0].read_text()) + record["source"]["user_id"] = "someone-else" + spooled[0].write_text(json.dumps(record)) + + reached, lines, _left = await _boot(home, (Platform.DISCORD,)) + + assert reached == [] + assert [ln for ln in lines if UNTRUSTED in ln] + assert len([ln for ln in lines if LOST in ln]) == 1 + + +@pytest.mark.asyncio +async def test_gate_closed_during_restart_refusal_is_reported_lost(home, monkeypatch): + """Admissible at park; the operator closed DISCORD_ALLOW_BOTS before boot. + Live policy still wins (refused) and the loss is reported, never silent.""" + spooled = await _park_and_stop(home, _event("bot-777", "701", is_bot=True), (Platform.DISCORD,)) + assert len(spooled) == 1 + + reached, lines, left = await _boot( + home, (Platform.DISCORD,), before_boot=lambda: monkeypatch.delenv("DISCORD_ALLOW_BOTS"), + ) + + assert reached == [] + assert not [ln for ln in lines if UNTRUSTED in ln] # MAC was valid + lost = [ln for ln in lines if LOST in ln] + assert len(lost) == 1, lines + assert "reason=unauthorized" in lost[0] and "bot-777" in lost[0] + assert left == [] + + +def test_admission_roundtrip_covers_every_field_to_dict_drops(home): + """Class guard: every SessionSource field that to_dict/from_dict loses and + that gates admission is carried by the spool's admission block.""" + import dataclasses + + all_on = {} + for f in dataclasses.fields(SessionSource): + if f.type in (bool, "bool"): + all_on[f.name] = True + src = SessionSource(platform=Platform.DISCORD, chat_id="1", user_id="u", **all_on) + back = SessionSource.from_dict(src.to_dict()) + lost = {name for name in all_on if getattr(back, name) is not True} + assert lost <= set(rf.ADMISSION_FIELDS), lost - set(rf.ADMISSION_FIELDS) + + path = rf.spool_followup("k", "t", src.to_dict(), admission=rf.admission_fields(src)) + (record,), _ = rf.take_followups() + assert record["_admission_verified"] is True + assert rf.restored_admission(record) == {name: True for name in rf.ADMISSION_FIELDS} + assert path is not None diff --git a/tests/gateway/test_restart_interrupt_intent_followups.py b/tests/gateway/test_restart_interrupt_intent_followups.py index b71e454155f9a..c19a9b6188a25 100644 --- a/tests/gateway/test_restart_interrupt_intent_followups.py +++ b/tests/gateway/test_restart_interrupt_intent_followups.py @@ -255,6 +255,32 @@ def test_draining_site_preserves_instead_of_discarding(): assert "await self._preserve_followup_across_restart(" in src[start:end] +def test_draining_site_spools_the_parked_event_itself(): + """Event identity at the post-turn draining site (Argus r8 MF, t_43e058b7): + the spool must receive ``pending_event`` (the parked MessageEvent: type, + media, internal, metadata, source admission), not ``None`` + the derived + ``pending`` string. Mutating the argument to ``None`` survived 40/40.""" + import ast + + src = RUN_PY.read_text(encoding="utf-8") + head = "if self._draining and (pending_event or pending):" + start = src.find(head) + assert start != -1, "draining follow-up branch not found" + end = src.find("if pending_event or pending:", start + len(head)) + line_start = src.rfind("\n", 0, start) + 1 + branch = ast.parse(__import__("textwrap").dedent(src[line_start:end]).rstrip() + "\n") + calls = [ + n for n in ast.walk(branch) + if isinstance(n, ast.Call) + and isinstance(n.func, ast.Attribute) + and n.func.attr == "_preserve_followup_across_restart" + ] + assert len(calls) == 1 + args = calls[0].args + assert [type(a).__name__ for a in args[:3]] == ["Name", "Name", "Name"], ast.dump(calls[0]) + assert [a.id for a in args[:3]] == ["session_key", "pending_event", "pending"] + + # -- ASK 4 / requester logging: in-band restart is attributable ------------- From 5d879a7e05de803bf444415dfdbe71090aa550a7 Mon Sep 17 00:00:00 2001 From: Alexander Nikolas Date: Thu, 24 Sep 2026 11:46:11 +0000 Subject: [PATCH 3/7] fix(kanban): judge goal deliverables before completion; fail open for operator errors (#960) * fix(kanban): grade goal deliverables before completion and isolate judge errors Verified 81 targeted tests pass (one ACP-dependent test excluded). Mutating the completion rubric makes the first-completion regression fail as expected. * refactor(kanban): one shared goal-mode handoff gate for CLI and tool surfaces Argus r1 (t_c4e23682): _goal_mode_handoff_rejection was byte-identical in tools/kanban_tools.py and hermes_cli/kanban.py; only the tool copy was test-gated, so 4 CLI mutants survived (Issue #38367 two-copies class). - goals.kanban_handoff_rejection is now the single predicate (judge with completion_handoff=True; owned worker retries then blocks transient on judge error; operator fails open with a judge_error event; caller's conn). - Both surfaces' complete + request-review delegate to it, injecting only their run-id resolver and judge-availability probe. - CLI tests drive the real `kanban complete` / `request-review` argv path (build_parser -> kanban_command): completion_handoff reaches the judge and the card closes; real judge prompt accepts first completion; owned-worker 500 -> 2 calls, blocked transient, error on stderr, rc!=0; review gated. - AST contract: exactly one function in the tree calls the judge with completion_handoff, and both surface wrappers delegate to it. Verified: 86 passed, 1 deselected (inherited ModuleNotFoundError: acp, also red on ce0c9d3). Mutation matrix: baseline green precondition, 16/16 KILLED by named failing tests (M01-M13 re-targeted at the shared helper + W1-W9 wiring/duplicate-predicate mutants). --------- Co-authored-by: Kyzcreig <9063726+Kyzcreig@users.noreply.github.com> --- hermes_cli/goals.py | 91 +++++++++- hermes_cli/kanban.py | 41 ++--- tests/hermes_cli/test_kanban_goal_mode.py | 199 ++++++++++++++++++++++ tests/tools/test_kanban_tools.py | 65 ++++++- tools/kanban_tools.py | 57 ++----- 5 files changed, 378 insertions(+), 75 deletions(-) diff --git a/hermes_cli/goals.py b/hermes_cli/goals.py index c678c7c28cf4e..15667613c9720 100644 --- a/hermes_cli/goals.py +++ b/hermes_cli/goals.py @@ -40,7 +40,7 @@ import time from dataclasses import dataclass, field, asdict from datetime import datetime, timezone -from typing import Any, Dict, List, Optional, Tuple +from typing import Any, Callable, Dict, List, Optional, Tuple logger = logging.getLogger(__name__) @@ -1174,6 +1174,7 @@ def judge_goal( subgoals: Optional[List[str]] = None, background_processes: Optional[List[Dict[str, Any]]] = None, contract: Optional[GoalContract] = None, + completion_handoff: bool = False, ) -> Tuple[str, str, bool, Optional[Dict[str, Any]], bool]: """Ask the auxiliary model whether the goal is satisfied. @@ -1274,10 +1275,21 @@ def judge_goal( # Route through call_llm so auxiliary.goal_judge.* config # (provider/model/base_url, extra_body, reasoning_effort, retries) # all apply — the direct-create path dropped extra_body (#35566). + system_prompt = JUDGE_SYSTEM_PROMPT + if completion_handoff: + system_prompt += ( + "\nKANBAN COMPLETION HANDOFF: This is the first attempt to complete " + "the task. Judge only the deliverables and verification evidence " + "in the proposed summary against the task criteria. Do not require " + "a prior kanban_complete call, a completed board state, or a " + "completion receipt; those cannot exist until after your verdict. " + "Ignore lifecycle-call requirements in the goal text when deciding " + "whether the substantive work is done.\n" + ) resp = call_llm( task="goal_judge", messages=[ - {"role": "system", "content": JUDGE_SYSTEM_PROMPT}, + {"role": "system", "content": system_prompt}, {"role": "user", "content": prompt}, ], temperature=0, @@ -1302,6 +1314,81 @@ def judge_goal( return verdict, reason, parse_failed, wait_directive, False +def goal_judge_available() -> bool: + """True when an auxiliary client is configured for the goal judge. + + ``judge_goal`` is fail-open at the source: with no reachable auxiliary + model it returns a ``"continue"`` verdict indistinguishable from a real + "not done yet". Kanban handoff gates probe this first so an unconfigured + judge never wedges a ``goal_mode`` worker out of closing its own task. + """ + try: + from agent.auxiliary_client import get_text_auxiliary_client + client, model = get_text_auxiliary_client("goal_judge") + except Exception: + return False + return client is not None and bool(model) + + +def kanban_handoff_rejection( + task: Any, + evidence: str, + *, + conn: Any = None, + task_id: Optional[str] = None, + worker_run_id_for: Callable[[str], Optional[int]], + judge_available: Callable[[], bool], + judge: Optional[Callable[..., Tuple[Any, ...]]] = None, +) -> Optional[str]: + """The ONE goal-mode gate for kanban complete / request-review handoffs. + + Shared by ``tools.kanban_tools`` and ``hermes_cli.kanban`` (the CLI) so the two + surfaces cannot drift (Issue #38367 was two copies of one gate). Each + surface injects only its own seams: its run-ownership resolver, its judge + availability probe, and optionally the judge callable it exposes for tests. + + Contract: + * The judge grades the proposed deliverables with + ``completion_handoff=True`` — it must never demand a prior + kanban_complete receipt (that receipt cannot exist before this call). + * A real verdict gates: ``done`` -> None, anything else -> the reason. + * A judge ERROR (transport failure / exception / unparseable reply): + - the owning worker (resolver returns a run id) retries once, then + the card is blocked ``transient`` with the error named; + - an operator (no owned run) fails open, with a ``judge_error`` + event recorded on the caller's ``conn`` for audit. + Uses the caller's ``conn``; never opens its own. + """ + if not task or not getattr(task, "goal_mode", False) or not judge_available(): + return None + from hermes_cli import kanban_db as kb + + if judge is None: + judge = judge_goal + worker_run_id = worker_run_id_for(task_id) if task_id else None + reason = "judge unavailable" + for _ in range(2 if worker_run_id is not None else 1): + try: + verdict, reason, parse_failed, _, transport_failed = judge( + goal=f"{task.title}\n\n{task.body or ''}".strip(), + last_response=(evidence or "").strip(), + completion_handoff=True, + ) + except Exception as exc: + verdict, reason, parse_failed, transport_failed = ( + "continue", f"judge error: {type(exc).__name__}", False, True, + ) + if not (parse_failed or transport_failed): + return reason if verdict != "done" else None + if conn is not None and task_id: + kb._append_event(conn, task_id, "judge_error", {"reason": reason}, run_id=worker_run_id) + conn.commit() + if worker_run_id is not None: + blocked = kb.block_task(conn, task_id, reason=reason, kind="transient", expected_run_id=worker_run_id) + return f"{reason}; task {'blocked transient after judge retry' if blocked else 'not blocked (run ownership changed)'}" + return None + + def gather_background_processes(task_id: Optional[str] = None) -> List[Dict[str, Any]]: """Return the live background-process snapshot for the goal judge. diff --git a/hermes_cli/kanban.py b/hermes_cli/kanban.py index fc1361eeb5e83..0df7ed18aef38 100644 --- a/hermes_cli/kanban.py +++ b/hermes_cli/kanban.py @@ -3685,37 +3685,16 @@ def _worker_run_id_for(task_id: str) -> Optional[int]: return None -def _goal_mode_handoff_rejection(task: Optional[kb.Task], evidence: str) -> Optional[str]: - """Apply the goal judge to every terminal worker handoff, including review.""" - if task is None or not task.goal_mode: - return None - try: - from agent.auxiliary_client import get_text_auxiliary_client - - client, model = get_text_auxiliary_client("goal_judge") - except Exception: - return None - if client is None or not model: - return None +def _goal_mode_handoff_rejection(task: Optional[kb.Task], evidence: str, *, conn=None, task_id=None) -> Optional[str]: + """CLI-surface wiring of the shared goal-mode handoff gate (complete + review).""" + from hermes_cli import goals - from hermes_cli.goals import judge_goal - - verdict = "done" - reason = "" - try: - verdict, reason, _, _, _ = judge_goal( - goal=f"{task.title}\n\n{task.body or ''}".strip(), - last_response=evidence.strip(), - ) - except Exception as judge_exc: - import logging as _logging - - _logging.getLogger(__name__).warning( - "goal judge check failed, allowing lifecycle handoff: %s", - judge_exc, - exc_info=True, - ) - return reason if verdict != "done" else None + return goals.kanban_handoff_rejection( + task, evidence, conn=conn, task_id=task_id, + worker_run_id_for=_worker_run_id_for, + judge_available=goals.goal_judge_available, + judge=goals.judge_goal, + ) def _cmd_complete(args: argparse.Namespace) -> int: @@ -3772,6 +3751,7 @@ def _cmd_complete(args: argparse.Namespace) -> int: rejection = None if superseded_by is not None else _goal_mode_handoff_rejection( task, (summary or args.result or "").strip(), + conn=conn, task_id=tid, ) if rejection is not None: print( @@ -4022,6 +4002,7 @@ def _cmd_request_review(args: argparse.Namespace) -> int: rejection = _goal_mode_handoff_rejection( kb.get_task(conn, tid), summary or "", + conn=conn, task_id=tid, ) if rejection is not None: print( diff --git a/tests/hermes_cli/test_kanban_goal_mode.py b/tests/hermes_cli/test_kanban_goal_mode.py index 6fc6c40f4267b..1cd516b880df8 100644 --- a/tests/hermes_cli/test_kanban_goal_mode.py +++ b/tests/hermes_cli/test_kanban_goal_mode.py @@ -288,6 +288,205 @@ def _continue_judge(goal, response, **_kw): # CLI judge gate tests (hermes kanban complete bypass fix) # --------------------------------------------------------------------------- +def test_completion_handoff_judge_does_not_require_prior_completion(monkeypatch): + from types import SimpleNamespace + from agent import auxiliary_client + + prompts = [] + + def fake_call_llm(**kwargs): + system = kwargs["messages"][0]["content"] + prompts.append(system) + # A rubric that omits the lifecycle exception reproduces the circular + # rejection: evidence exists, but no completion receipt can exist yet. + done = "Do not require a prior kanban_complete call" in system + content = '{"verdict":"done","reason":"deliverables verified"}' if done else '{"verdict":"continue","reason":"kanban_complete not called"}' + return SimpleNamespace(choices=[SimpleNamespace(message=SimpleNamespace(content=content))]) + + monkeypatch.setattr(auxiliary_client, "call_llm", fake_call_llm) + verdict, reason, *_ = goals.judge_goal( + goal="Print two canary phases and then call kanban_complete", + last_response="CANARY_PHASE1_NEW exit 0; CANARY_PHASE2_NEW exit 0", + completion_handoff=True, + ) + assert verdict == "done", reason + assert len(prompts) == 1 + + +def test_cli_operator_completion_survives_judge_500(kanban_home, monkeypatch): + import argparse + from hermes_cli import kanban as cli + from agent import auxiliary_client + + with kb.connect() as conn: + tid = kb.create_task(conn, title="Verified artifact", assignee="builder", goal_mode=True) + assert kb.claim_task(conn, tid) + monkeypatch.delenv("HERMES_KANBAN_TASK", raising=False) + monkeypatch.setattr(auxiliary_client, "get_text_auxiliary_client", lambda name: (object(), "judge")) + monkeypatch.setattr(goals, "judge_goal", lambda **kw: ("continue", "judge error: InternalServerError", False, None, True)) + args = argparse.Namespace(task_ids=[tid], summary="artifact and test passed", result=None, metadata=None) + assert cli._cmd_complete(args) == 0 + with kb.connect() as conn: + assert kb.get_task(conn, tid).status == "done" + events = conn.execute("SELECT kind FROM task_events WHERE task_id = ?", (tid,)).fetchall() + assert any(e["kind"] == "judge_error" for e in events) + + +def _cli_goal_card(conn, title="Print two canary phases and then call kanban_complete"): + tid = kb.create_task(conn, title=title, assignee="builder", goal_mode=True) + claimed = kb.claim_task(conn, tid) + assert claimed + return tid, claimed.current_run_id + + +def _kanban_argv(argv): + """Drive the real ``hermes kanban ...`` argv path: build_parser -> parse_args + -> kanban_command, exactly as the top-level CLI dispatches it.""" + import argparse + from hermes_cli import kanban as cli + + wrap = argparse.ArgumentParser(prog="wrap", add_help=False) + parser = cli.build_parser(wrap.add_subparsers(dest="_top")) + return cli.kanban_command(parser.parse_args(argv)) + + +def test_cli_complete_first_call_passes_completion_handoff_and_closes(kanban_home, monkeypatch): + """(a') ``kanban complete`` argv path: the judge must be asked to grade the + deliverables (completion_handoff=True) and the card closes on the first call.""" + from agent import auxiliary_client + + with kb.connect() as conn: + tid, _ = _cli_goal_card(conn) + monkeypatch.delenv("HERMES_KANBAN_TASK", raising=False) + monkeypatch.setattr(auxiliary_client, "get_text_auxiliary_client", lambda name: (object(), "judge")) + calls = [] + + def judge(**kwargs): + calls.append(kwargs) + ok = kwargs.get("completion_handoff") is True + return ("done" if ok else "continue", "deliverables verified" if ok else "kanban_complete not called", False, None, False) + + monkeypatch.setattr(goals, "judge_goal", judge) + rc = _kanban_argv(["complete", tid, "--summary", "CANARY_PHASE1_NEW exit 0; CANARY_PHASE2_NEW exit 0"]) + assert rc == 0 + assert len(calls) == 1 and calls[0]["completion_handoff"] is True + with kb.connect() as conn: + assert kb.get_task(conn, tid).status == "done" + + +def test_cli_complete_real_judge_rubric_accepts_first_completion(kanban_home, monkeypatch): + """(a')+(c) end to end on the argv path with the REAL judge_goal prompt. + A rubric that demands a prior kanban_complete receipt makes this RED.""" + from types import SimpleNamespace + from agent import auxiliary_client + + with kb.connect() as conn: + tid, _ = _cli_goal_card(conn) + monkeypatch.delenv("HERMES_KANBAN_TASK", raising=False) + monkeypatch.setattr(auxiliary_client, "get_text_auxiliary_client", lambda name: (object(), "judge")) + + def fake_call_llm(**kwargs): + system = kwargs["messages"][0]["content"] + done = "Do not require a prior kanban_complete call" in system + content = '{"verdict":"done","reason":"deliverables verified"}' if done else '{"verdict":"continue","reason":"kanban_complete not called"}' + return SimpleNamespace(choices=[SimpleNamespace(message=SimpleNamespace(content=content))]) + + monkeypatch.setattr(auxiliary_client, "call_llm", fake_call_llm) + assert _kanban_argv(["complete", tid, "--summary", "CANARY_PHASE1_NEW exit 0; CANARY_PHASE2_NEW exit 0"]) == 0 + with kb.connect() as conn: + assert kb.get_task(conn, tid).status == "done" + + +def test_cli_owned_worker_judge_500_retries_then_blocks_transient(kanban_home, monkeypatch, capsys): + """(b') ``kanban complete`` argv path, owning worker: a judge error is retried + once, then the card blocks transient with the error named; never completes.""" + from hermes_cli import kanban as cli + from agent import auxiliary_client + + with kb.connect() as conn: + tid, run_id = _cli_goal_card(conn, title="Verified artifact") + monkeypatch.delenv("HERMES_KANBAN_OWNER_PID", raising=False) + monkeypatch.setenv("HERMES_KANBAN_TASK", tid) + monkeypatch.setenv("HERMES_KANBAN_RUN_ID", str(run_id)) + assert cli._worker_run_id_for(tid) == run_id + monkeypatch.setattr(auxiliary_client, "get_text_auxiliary_client", lambda name: (object(), "judge")) + calls = [] + + def failing_judge(**kwargs): + calls.append(kwargs) + return ("continue", "judge error: InternalServerError", False, None, True) + + monkeypatch.setattr(goals, "judge_goal", failing_judge) + rc = _kanban_argv(["complete", tid, "--summary", "artifact and test passed"]) + err = capsys.readouterr().err + assert rc != 0 + assert len(calls) == 2 + assert "InternalServerError" in err + with kb.connect() as conn: + task = kb.get_task(conn, tid) + assert task.status == "blocked" + assert task.block_kind == "transient" + events = conn.execute("SELECT kind FROM task_events WHERE task_id = ?", (tid,)).fetchall() + assert any(e["kind"] == "judge_error" for e in events) + + +def test_cli_request_review_uses_shared_gate(kanban_home, monkeypatch): + """``kanban request-review`` argv path reaches the same gate: a real + ``continue`` verdict blocks the handoff and the judge saw completion_handoff.""" + from agent import auxiliary_client + + with kb.connect() as conn: + tid, _ = _cli_goal_card(conn) + monkeypatch.delenv("HERMES_KANBAN_TASK", raising=False) + monkeypatch.setattr(auxiliary_client, "get_text_auxiliary_client", lambda name: (object(), "judge")) + calls = [] + + def judge(**kwargs): + calls.append(kwargs) + return ("continue", "phase 2 output missing", False, None, False) + + monkeypatch.setattr(goals, "judge_goal", judge) + assert _kanban_argv(["request-review", tid, "--summary", "phase 1 only"]) != 0 + assert len(calls) == 1 and calls[0]["completion_handoff"] is True + with kb.connect() as conn: + assert kb.get_task(conn, tid).status == "running" + + +def test_goal_handoff_predicate_is_defined_exactly_once(): + """AST contract (Issue #38367 class): the goal-mode handoff rejection + predicate — the one function that asks the judge with + ``completion_handoff`` — exists exactly once in the tree, and every + surface wrapper delegates to it instead of re-implementing it.""" + import ast + + root = Path(goals.__file__).resolve().parents[1] + definers = [] + delegating = {} + for pkg in ("hermes_cli", "tools", "gateway", "agent", "plugins"): + base = root / pkg + if not base.is_dir(): + continue + for path in base.rglob("*.py"): + try: + tree = ast.parse(path.read_text(encoding="utf-8")) + except (SyntaxError, UnicodeDecodeError): + continue + for fn in ast.walk(tree): + if not isinstance(fn, (ast.FunctionDef, ast.AsyncFunctionDef)): + continue + calls = [n for n in ast.walk(fn) if isinstance(n, ast.Call)] + if any(k.arg == "completion_handoff" for c in calls for k in c.keywords): + definers.append((path.relative_to(root).as_posix(), fn.name)) + if fn.name == "_goal_mode_handoff_rejection": + names = { + getattr(c.func, "attr", None) or getattr(c.func, "id", None) + for c in calls + } + delegating[path.relative_to(root).as_posix()] = "kanban_handoff_rejection" in names + assert definers == [("hermes_cli/goals.py", "kanban_handoff_rejection")], definers + assert delegating == {"tools/kanban_tools.py": True, "hermes_cli/kanban.py": True}, delegating + + class TestCLIJudgeGate: """hermes kanban complete must apply the same goal_mode judge gate as the kanban_complete tool (Issue #38367 sibling gap). diff --git a/tests/tools/test_kanban_tools.py b/tests/tools/test_kanban_tools.py index e6ebc7b2843ff..c35c4cb9f0da5 100644 --- a/tests/tools/test_kanban_tools.py +++ b/tests/tools/test_kanban_tools.py @@ -207,7 +207,7 @@ def test_complete_goal_mode_rejected_by_judge(monkeypatch, tmp_path): # Mock the judge to reject the completion. The gate only runs when a # judge is reachable, so force the availability probe True as well. - def mock_judge_goal(goal, last_response, *, timeout=30.0, subgoals=None): + def mock_judge_goal(goal, last_response, **kwargs): # Match the real judge_goal contract: # (verdict, reason, parse_failed, wait_directive, transport_failed) return "continue", "missing verification evidence", False, None, False @@ -232,6 +232,65 @@ def mock_judge_goal(goal, last_response, *, timeout=30.0, subgoals=None): conn2.close() +def test_goal_complete_first_call_uses_deliverables_not_completion_receipt(monkeypatch, tmp_path): + from hermes_cli import kanban_db as kb + from tools import kanban_tools as kt + + tid = _make_goal_mode_worker_env(monkeypatch, tmp_path) + monkeypatch.setattr(kt, "_is_dispatcher_owned_worker", lambda: True) + monkeypatch.setattr(kt, "_goal_judge_available", lambda: True) + + def judge(**kwargs): + assert kwargs["completion_handoff"] is True + assert "kanban_complete" not in kwargs["last_response"] + return ("done", "deliverable verified", False, None, False) + + monkeypatch.setattr(kt, "judge_goal", judge) + result = json.loads(kt._handle_complete({"summary": "CANARY_PHASE1_NEW and CANARY_PHASE2_NEW; both exit 0"})) + assert result.get("ok") is True, result + with kb.connect() as conn: + assert kb.get_task(conn, tid).status == "done" + + +def test_goal_complete_judge_500_blocks_worker_transient(monkeypatch, tmp_path): + from hermes_cli import kanban_db as kb + from tools import kanban_tools as kt + + tid = _make_goal_mode_worker_env(monkeypatch, tmp_path) + monkeypatch.setattr(kt, "_is_dispatcher_owned_worker", lambda: True) + monkeypatch.setattr(kt, "_goal_judge_available", lambda: True) + calls = [] + + def failing_judge(**kwargs): + calls.append(kwargs) + return ("continue", "judge error: InternalServerError", False, None, True) + + monkeypatch.setattr(kt, "judge_goal", failing_judge) + out = json.loads(kt._handle_complete({"summary": "Verified output"})) + assert len(calls) == 2 + assert "InternalServerError" in out["error"] + with kb.connect() as conn: + task = kb.get_task(conn, tid) + assert task.status == "blocked" + assert task.block_kind == "transient" + + +def test_goal_complete_operator_judge_500_fails_open_with_event(monkeypatch, tmp_path): + from hermes_cli import kanban_db as kb + from tools import kanban_tools as kt + + tid = _make_goal_mode_worker_env(monkeypatch, tmp_path) + monkeypatch.delenv("HERMES_KANBAN_TASK") + monkeypatch.setattr(kt, "_goal_judge_available", lambda: True) + monkeypatch.setattr(kt, "judge_goal", lambda **kw: ("continue", "judge error: InternalServerError", False, None, True)) + out = json.loads(kt._handle_complete({"task_id": tid, "summary": "Verified output"})) + assert out["ok"] is True + with kb.connect() as conn: + assert kb.get_task(conn, tid).status == "done" + events = conn.execute("SELECT kind, payload FROM task_events WHERE task_id = ?", (tid,)).fetchall() + assert any(e["kind"] == "judge_error" and "InternalServerError" in e["payload"] for e in events) + + def test_block_happy_path(worker_env): from tools import kanban_tools as kt out = kt._handle_block({"reason": "need clarification"}) @@ -266,10 +325,12 @@ def _make_goal_mode_worker_env(monkeypatch, tmp_path): conn, title="goal-mode-block-test", assignee="test-worker", body="Must achieve X.", goal_mode=True, ) - kb.claim_task(conn, goal_task_id) + claimed = kb.claim_task(conn, goal_task_id) + run_id = claimed.current_run_id finally: conn.close() monkeypatch.setenv("HERMES_KANBAN_TASK", goal_task_id) + monkeypatch.setenv("HERMES_KANBAN_RUN_ID", str(run_id)) return goal_task_id diff --git a/tools/kanban_tools.py b/tools/kanban_tools.py index 402138bf07cdd..e72499def688a 100644 --- a/tools/kanban_tools.py +++ b/tools/kanban_tools.py @@ -288,46 +288,20 @@ def _connect(board: Optional[str] = None): def _goal_judge_available() -> bool: - """True when an auxiliary client is configured for the goal judge. - - ``judge_goal`` is fail-open at the source: when no auxiliary model can - be reached it returns a ``"continue"`` verdict that is indistinguishable - from a real "not done yet" judgment. The completion gate must not treat - that as a rejection, or an unconfigured/degraded auxiliary model would - wedge every ``goal_mode`` worker (it could never close its own task). - - So we probe availability first and only enforce the gate when a judge is - actually reachable. This mirrors the same client lookup ``judge_goal`` - performs internally. - """ - try: - from agent.auxiliary_client import get_text_auxiliary_client - client, model = get_text_auxiliary_client("goal_judge") - except Exception: - return False - return client is not None and bool(model) - - -def _goal_mode_handoff_rejection(task, evidence: str) -> Optional[str]: - """Return a rejection reason when a goal-mode terminal handoff is premature.""" - if not task or not task.goal_mode or not _goal_judge_available(): - return None - verdict = "done" - reason = "" - try: - verdict, reason, _, _, _ = judge_goal( - goal=f"{task.title}\n\n{task.body or ''}".strip(), - last_response=evidence.strip(), - ) - except Exception as judge_exc: - # Keep the existing fail-open semantics: an unavailable/broken - # auxiliary judge must not permanently wedge goal-mode work. - logger.warning( - "goal judge check failed, allowing lifecycle handoff: %s", - judge_exc, - exc_info=True, - ) - return reason if verdict != "done" else None + """Tool-surface judge availability probe; see ``goals.goal_judge_available``.""" + from hermes_cli.goals import goal_judge_available + return goal_judge_available() + + +def _goal_mode_handoff_rejection(task, evidence: str, *, conn=None, task_id=None) -> Optional[str]: + """Tool-surface wiring of the shared goal-mode handoff gate.""" + from hermes_cli.goals import kanban_handoff_rejection + return kanban_handoff_rejection( + task, evidence, conn=conn, task_id=task_id, + worker_run_id_for=_worker_run_id, + judge_available=_goal_judge_available, + judge=judge_goal, + ) # --------------------------------------------------------------------------- @@ -885,6 +859,7 @@ def _handle_complete(args: dict, **kw) -> str: rejection = None if superseded_by is not None else _goal_mode_handoff_rejection( task, (summary or result or "").strip(), + conn=conn, task_id=tid, ) if rejection is not None: return tool_error( @@ -1077,7 +1052,7 @@ def _handle_request_review(args: dict, **kw) -> str: kb, conn = _connect(board=board) try: task = kb.get_task(conn, tid) - rejection = _goal_mode_handoff_rejection(task, summary) + rejection = _goal_mode_handoff_rejection(task, summary, conn=conn, task_id=tid) if rejection is not None: return tool_error( f"Goal review handoff rejected by judge: {rejection}. " From d8e7e8af82082e635325dc48d29dd5dc28ee6e75 Mon Sep 17 00:00:00 2001 From: Alexander Nikolas Date: Thu, 24 Sep 2026 12:35:01 +0000 Subject: [PATCH 4/7] fix(kanban): resume dependency-wait PR and page stranded ready cards (#952) * fix(kanban): respawn guard honors worker dependency_wait->promoted resume; add requeue_task + stuck-guard probe t_7d7ff489. Rule 4 active_pr no longer strands a card whose own dependency block (kind=dependency) postdates the newest PR comment and whose promotion has not yet spawned. requeue_task emits operator-intent 'requeued' for READY cards. respawn_guard_stuck_tasks lists cards held by active_pr >= 30 min. * fix(kanban): surface guarded ready cards and provide requeue verb Verify dependency_wait promotion dispatches once and subsequent crash is guarded; CLI requeue and one-shot alert tests pass (168 passed, 1 skipped in focused suites). t_7d7ff489. * test(kanban): keep corruption probe independent of watcher call count Verified: corrupt-board regression 2 passed, 22 deselected; ruff and diff check pass. Original two failures reproduced on clean fork base. * fix(kanban): keep PR continuation through status comments and unobserved ticks Verified 213 passed, 2 skipped across focused DB/CLI/watcher suites; subprocess stdin guard passed. * fix(kanban): consume event-ordered PR requeue intent Verified 183 passed, 1 skipped across DB/CLI/watcher; ruff and subprocess stdin guard pass. Same-second event-order mutant fails the regression test. * docs(kanban): state one-shot PR intent ordering * fix(kanban): bind PR comments to events and consume dependency intent Verified real dispatcher regressions RED before fix, then 210 passed, 2 skipped in focused DB/CLI/watcher suite; ruff and subprocess guard passed. * fix(kanban): pin READY requeue to PR comment identity Legacy same-second inline audit comments can share author and length; requeue snapshots the PR row id and remains one-shot. Verified 211 passed, 2 skipped; ruff clean. * fix(kanban): snapshot comment identity for every resume intent Verified focused DB/CLI/watcher/core suite: 217 passed, 2 skipped. Legacy equal-second strict mutant fails the intended arm. * fix(kanban): guard-stuck age ignores data events; board-scoped recovery command - respawn_guard_stuck_tasks: only kinds that can change the active_pr answer (_RESPAWN_GUARD_FAILURE_RESET_KINDS + dependency_wait + spawned, or a guard decline for another reason) restart the continuous-guard age; comments, heartbeats, attachments are data. - render_operator_command(board, verb, *args): single renderer, always emits --board ; clear_verb uses it; watcher passes the probed board. - test_triage_resolve_records_who_and_why: expect after_comment_id == max(task_comments.id) at emit time (CI slice 15/16 red). Verified: new tests RED on 581299d9a1 (4 failed), GREEN here; recovery command executed via real CLI on default and secondary boards (rc0); no-board renderer mutant fails; 244 passed/1 skipped on db/triage/ watchers/cli/boards; ruff clean. --------- Co-authored-by: Kyzcreig <9063726+Kyzcreig@users.noreply.github.com> --- gateway/kanban_watchers.py | 108 ++++- hermes_cli/kanban.py | 17 + hermes_cli/kanban_db.py | 227 ++++++++-- tests/gateway/test_kanban_watchers_mixin.py | 73 ++++ tests/hermes_cli/test_kanban_cli.py | 14 + .../test_kanban_core_functionality.py | 12 +- tests/hermes_cli/test_kanban_db.py | 403 ++++++++++++++++++ tests/hermes_cli/test_kanban_triage_exit.py | 6 +- 8 files changed, 814 insertions(+), 46 deletions(-) diff --git a/gateway/kanban_watchers.py b/gateway/kanban_watchers.py index 10e9e8e8aed91..e394616991ab5 100644 --- a/gateway/kanban_watchers.py +++ b/gateway/kanban_watchers.py @@ -475,7 +475,75 @@ def _observe_workspace_refusal_outages(notifier, results) -> int: return delivered -def _stall_streak_is_bad(ready_pending, any_spawned, results) -> bool: +def _guard_stuck_cards(results) -> tuple[list[tuple[str, dict]], set[str]]: + """Probe guarded cards; only successful board probes can prove recovery.""" + from hermes_cli import kanban_db as kb + + cards = [] + observed_boards = set() + for board, result in results or []: + if result is None or getattr(result, "skipped_locked", False): + continue + try: + with kb.connect_closing(board=board) as conn: + cards.extend( + (board, item) + for item in kb.respawn_guard_stuck_tasks(conn, board=board) + ) + observed_boards.add(board) + except Exception: + logger.exception("kanban dispatcher: guard-stuck probe failed on %s", board) + return cards, observed_boards + + +class _GuardStuckNotifier: + """Page once per (board, card) until it recovers; retry failed sends.""" + + def __init__(self) -> None: + self._delivered: set[tuple[str, str]] = set() + + def observe(self, cards, send, observed_boards=None) -> int: + current = {(board, item["task_id"]) for board, item in cards} + if observed_boards is None: + observed_boards = {board for board, _ in cards} + self._delivered = { + key for key in self._delivered + if key[0] not in observed_boards or key in current + } + delivered = 0 + for board, item in cards: + key = board, item["task_id"] + if key not in self._delivered and send(board, item): + self._delivered.add(key) + delivered += 1 + return delivered + + +def _send_guard_stuck_alert(board: str, item: dict) -> bool: + """Best-effort #alerts page with the exact recovery verb.""" + script = Path.home() / ".hermes" / "scripts" / "notify.py" + if not script.is_file(): + logger.error("kanban dispatcher: notify.py unavailable; guard-stuck page not delivered") + return False + message = ( + "🛑 **Kanban dispatcher** · READY card stuck behind active_pr (>30 min)\n" + f"Board: `{board}` · Card: `{item['task_id']}`\n" + f"Operator recovery: `{item['clear_verb']}`" + ) + try: + proc = subprocess.run( + [sys.executable, str(script), "--send", message, "--channel", "discord", + "--profile", "default", "--sev", "error"], + check=False, stdin=subprocess.DEVNULL, stdout=subprocess.DEVNULL, + stderr=subprocess.DEVNULL, timeout=30, + ) + except Exception: + logger.exception("kanban dispatcher: guard-stuck page failed") + return False + return proc.returncode == 0 + + +def _stall_streak_is_bad(ready_pending, any_spawned, results, *, guard_stuck=False) -> bool: """Decide whether a dispatcher tick counts toward the "stuck" streak. A tick is "bad" (stall-suspect) only when there is spawnable work, @@ -489,6 +557,8 @@ def _stall_streak_is_bad(ready_pending, any_spawned, results) -> bool: credentials)" warning that fired for ~2h during a provider 429 window / large fan-out, when the dispatcher was healthy but throttled. """ + if guard_stuck: + return True if not ready_pending or any_spawned: return False declined_benign = False @@ -2145,6 +2215,7 @@ async def _run_kanban_dispatcher(self, service) -> None: last_stranded_warn_at: dict[str, int] = {} last_workspace_refusal_warn: dict[str, tuple[str, int]] = {} workspace_refusal_notifier = _WorkspaceRefusalOutageNotifier() + guard_stuck_notifier = _GuardStuckNotifier() # Avoid hot-looping corrupt-looking board DBs, but do not suppress # same-fingerprint retries forever: transient WAL/open races can # surface as "database disk image is malformed" for one tick. @@ -2462,6 +2533,7 @@ def _auto_decompose_tick(auto_decompose_per_tick: int) -> int: # workers finish naturally; zombie reaping above still runs. if not _kanban_dispatch_allowed(): ready_pending = False + guard_stuck = [] bad_ticks = 0 else: # Re-read the auto-decompose toggle live each tick so a user @@ -2542,22 +2614,38 @@ def _auto_decompose_tick(auto_decompose_per_tick: int) -> int: # throttled, not broken). ``_stall_streak_is_bad`` consults the # DispatchResult buckets so telemetry can tell "busy/throttled" # from "genuinely stuck" instead of guessing. + guard_stuck, observed_boards = await service(_guard_stuck_cards, results) + guard_pages = await service( + guard_stuck_notifier.observe, guard_stuck, _send_guard_stuck_alert, + observed_boards, + ) + if guard_pages: + logger.error("kanban dispatcher: %d active_pr card(s) STUCK >30 min; " + "#alerts paged with recovery verbs", guard_pages) ready_pending = await service(_ready_nonempty) - if _stall_streak_is_bad(ready_pending, any_spawned, results): + if _stall_streak_is_bad(ready_pending, any_spawned, results, + guard_stuck=bool(guard_stuck)): bad_ticks += 1 else: bad_ticks = 0 if bad_ticks >= HEALTH_WINDOW: now = int(time.time()) if now - last_warn_at >= 300: - logger.warning( - "kanban dispatcher stuck: ready queue non-empty for " - "%d consecutive ticks but 0 workers spawned, with no " - "benign decline (cap/rate-limit/lock) to explain it. " - "Check profile health (venv, PATH, credentials) and " - "`hermes kanban list --status ready`.", - bad_ticks, - ) + if guard_stuck: + logger.warning( + "kanban dispatcher STUCK: active_pr held %d READY card(s) " + ">30 min. Use the per-card requeue verb in #alerts.", + len(guard_stuck), + ) + else: + logger.warning( + "kanban dispatcher stuck: ready queue non-empty for " + "%d consecutive ticks but 0 workers spawned, with no " + "benign decline (cap/rate-limit/lock) to explain it. " + "Check profile health (venv, PATH, credentials) and " + "`hermes kanban list --status ready`.", + bad_ticks, + ) last_warn_at = now except asyncio.CancelledError: logger.debug("kanban dispatcher: cancelled") diff --git a/hermes_cli/kanban.py b/hermes_cli/kanban.py index 0df7ed18aef38..1f3f22757b218 100644 --- a/hermes_cli/kanban.py +++ b/hermes_cli/kanban.py @@ -945,6 +945,10 @@ def build_parser(parent_subparsers: argparse._SubParsersAction) -> argparse.Argu ) p_unblock.add_argument("task_ids", nargs="+") + p_requeue = sub.add_parser("requeue", help="Explicitly retry a READY card held by the respawn guard") + p_requeue.add_argument("task_id") + p_requeue.add_argument("reason", nargs="+", help="Required operator reason") + p_reopen = sub.add_parser( "reopen", help=( @@ -1554,6 +1558,7 @@ def kanban_command(args: argparse.Namespace) -> int: "block": _cmd_block, "schedule": _cmd_schedule, "unblock": _cmd_unblock, + "requeue": _cmd_requeue, "reopen": _cmd_reopen, "request-review": _cmd_request_review, "request-changes": _cmd_request_changes, @@ -1631,6 +1636,7 @@ def _profile_author() -> str: "block", "schedule", "unblock", + "requeue", "reopen", "promote", "triage-resolve", @@ -3946,6 +3952,17 @@ def _cmd_unblock(args: argparse.Namespace) -> int: return 0 if not failed else 1 +def _cmd_requeue(args: argparse.Namespace) -> int: + reason = " ".join(args.reason).strip() + with kb.connect_closing() as conn: + ok, err = kb.requeue_task(conn, args.task_id, actor=_profile_author(), reason=reason) + if not ok: + print(f"cannot requeue {args.task_id}: {err}", file=sys.stderr) + return 1 + print(f"Requeued {args.task_id}: {reason}") + return 0 + + def _cmd_reopen(args: argparse.Namespace) -> int: """Reverse a false completion so the real work can be re-dispatched.""" reason = " ".join(args.reason).strip() if args.reason else "" diff --git a/hermes_cli/kanban_db.py b/hermes_cli/kanban_db.py index 2771de83a96bc..a375ce91e84f4 100644 --- a/hermes_cli/kanban_db.py +++ b/hermes_cli/kanban_db.py @@ -84,6 +84,7 @@ import re import random import secrets +import shlex import shutil import sqlite3 import subprocess @@ -6521,6 +6522,15 @@ def _append_event( and the row carries NULL. """ now = int(time.time()) + if kind in _RESPAWN_GUARD_OPERATOR_REQUEUE_KINDS or ( + kind == "dependency_wait" and (payload or {}).get("kind") == "dependency" + ) or (kind == "reclaimed" and (payload or {}).get("manual") is True): + # Snapshot comment causality in the same transaction as operator intent. + # Old commented events cannot be correlated with comment rows reliably. + payload = dict(payload or {}) + payload["after_comment_id"] = conn.execute( + "SELECT COALESCE(MAX(id), 0) FROM task_comments WHERE task_id = ?", (task_id,), + ).fetchone()[0] pl = json.dumps(payload, ensure_ascii=False) if payload else None conn.execute( "INSERT INTO task_events (task_id, run_id, kind, payload, created_at) " @@ -10466,6 +10476,44 @@ def request_changes( return True, implementer +def requeue_task( + conn: sqlite3.Connection, + task_id: str, + *, + actor: str, + reason: str, +) -> tuple[bool, Optional[str]]: + """Record operator intent to run a READY card now (``requeued`` event). + + The operator verb for a card that is already ``ready`` but deferred by the + respawn guard (typically ``active_pr``: the open PR is the fix-round + target). ``unblock``/``reopen``/``triage-resolve`` all require a non-ready + source state, which previously forced a block->unblock round trip just to + mint an intent event. Status is unchanged; ``requeued`` is in + ``_RESPAWN_GUARD_OPERATOR_REQUEUE_KINDS`` so the next dispatch tick spawns. + + Returns ``(True, None)`` on success, ``(False, reason)`` if refused. + """ + if not (reason or "").strip(): + return False, "a reason is required to requeue a task" + with write_txn(conn): + row = conn.execute( + "SELECT status FROM tasks WHERE id = ?", (task_id,) + ).fetchone() + if row is None: + return False, f"task {task_id} not found" + if row["status"] != "ready": + return False, ( + f"task {task_id} is {row['status']!r}; requeue only applies to " + f"'ready' tasks (use unblock/reopen/triage-resolve/promote " + f"for other states)" + ) + _append_event( + conn, task_id, "requeued", {"actor": actor, "reason": reason}, + ) + return True, None + + def reopen_task( conn: sqlite3.Connection, task_id: str, @@ -12312,8 +12360,8 @@ def schedule_task( # Within this window a GitHub PR URL in a comment blocks re-spawn. _RESPAWN_GUARD_PR_WINDOW = 86400 # 24 hours # Event kinds that mean "an OPERATOR deliberately asked for this task to run -# again". Any of these at/after the newest PR comment overrides the -# ``active_pr`` guard: the open PR is the fix-round target, not duplicate work. +# again". An unused event strictly AFTER the newest PR comment overrides +# ``active_pr`` for one spawn: the open PR is the fix-round target. # This is the TOTAL set of operator requeue verbs -- every CLI verb that moves a # task back toward ``ready`` by human intent must appear here, and # ``tests/hermes_cli/test_kanban_db.py::test_operator_requeue_verbs_all_override_active_pr`` @@ -12329,6 +12377,10 @@ def schedule_task( "review_reopened", "triage_resolved", "reopened", + # ``kanban requeue`` — the operator verb for a READY card (2026-09-23, + # t_7d7ff489): unblock/reopen/triage-resolve all need a non-ready source + # state, so a guarded ready card had no verb short of block->unblock. + "requeued", ) # Event kinds that make a stamped failure STALE for the ``blocker_auth`` and # ``rate_limit_cooldown`` rules when they land at/after the failing run ended: @@ -14955,6 +15007,44 @@ def _respawn_guard_failure_reset_after( ).fetchone() is not None +def _unused_operator_intent_after_pr(conn: sqlite3.Connection, task_id: str) -> bool: + """Whether the latest PR-bearing comment has an unconsumed resume intent. + + Event ids establish causality even when writes share a timestamp. A spawn + consumes the intent; automatic crash reclaim cannot reuse it. + """ + comments = conn.execute( + "SELECT id, author, body, created_at FROM task_comments " + "WHERE task_id = ? AND created_at >= ? ORDER BY id DESC", + (task_id, int(time.time()) - _RESPAWN_GUARD_PR_WINDOW), + ).fetchall() + pr_comment = next( + (c for c in comments if _RESPAWN_GUARD_PR_URL_RE.search(c["body"] or "")), None, + ) + if pr_comment is None: + return False + # The intent event snapshots the highest comment id atomically. No guess + # about which 'commented' event corresponds to this PR is needed: inline + # audit comments and historical trimmed bodies cannot skew the ordering. + # Pre-upgrade intent events have no marker; an equal-second tie resumes: + # one duplicate worker is recoverable, an indefinite guard is not. + kinds = ",".join("?" * len(_RESPAWN_GUARD_OPERATOR_REQUEUE_KINDS)) + return conn.execute( + "SELECT 1 FROM task_events i WHERE i.task_id = ? " + f"AND (i.kind IN ({kinds}) OR " + "(i.kind = 'reclaimed' AND json_extract(i.payload, '$.manual') = 1) OR " + "(i.kind = 'dependency_wait' AND json_extract(i.payload, '$.kind') = 'dependency' " + "AND EXISTS (SELECT 1 FROM task_events p WHERE p.task_id = i.task_id " + "AND p.kind = 'promoted' AND p.id > i.id))) " + "AND (json_extract(i.payload, '$.after_comment_id') >= ? OR " + "(json_type(i.payload, '$.after_comment_id') IS NULL AND i.created_at >= ?)) " + "AND NOT EXISTS (SELECT 1 FROM task_events s WHERE s.task_id = i.task_id " + "AND s.kind = 'spawned' AND s.id > i.id) LIMIT 1", + (task_id, *_RESPAWN_GUARD_OPERATOR_REQUEUE_KINDS, + pr_comment["id"], pr_comment["created_at"]), + ).fetchone() is not None + + def check_respawn_guard( conn: sqlite3.Connection, task_id: str, @@ -15151,37 +15241,19 @@ def check_respawn_guard( # 4. Recent GitHub PR comments. Guard while ANY referenced PR is open, # unparseable, unqueryable, or beyond this tick's query budget. The # duplicate-PR risk is gone only when ALL referenced PRs are closed. - # Exception: an explicit requeue at/after the newest PR comment means - # the open PR is the fix-round target, not duplicate work. Honor it - # before querying PR states (2026-09-07, clanker-voice-backlog - # t_800b8189: both unblock and changes_requested stranded PR #315). - # Unlike rule 3, this is not gated behind a completed run, so only - # operator-intent events count (including manual reclaim). Automatic - # reclaim after a worker dies with an open PR is the founding case; - # automatic dependency promotion and generic status events also defer. + # Exception: a fresh, unconsumed operator requeue AFTER the newest PR + # comment means the open PR is the fix-round target, not duplicate + # work. Worker dependency_wait followed by promotion grants the same + # one-shot continuation. Both are consumed by the next spawn. pr_cutoff = now - _RESPAWN_GUARD_PR_WINDOW pr_urls: list[str] = [] - newest_pr_at = 0 for c in conn.execute( - "SELECT body, created_at FROM task_comments " - "WHERE task_id = ? AND created_at >= ?", + "SELECT body FROM task_comments WHERE task_id = ? AND created_at >= ?", (task_id, pr_cutoff), ).fetchall(): - body = c["body"] or "" - urls = [match.group(0) for match in _RESPAWN_GUARD_PR_URL_RE.finditer(body)] - if urls: - pr_urls.extend(urls) - newest_pr_at = max(newest_pr_at, int(c["created_at"])) + pr_urls.extend(match.group(0) for match in _RESPAWN_GUARD_PR_URL_RE.finditer(c["body"] or "")) if pr_urls: - _kinds_sql = ",".join("?" * len(_RESPAWN_GUARD_OPERATOR_REQUEUE_KINDS)) - requeued_after = conn.execute( - "SELECT 1 FROM task_events " - "WHERE task_id = ? AND created_at >= ? " - f"AND (kind IN ({_kinds_sql}) OR (kind = 'reclaimed' " - "AND json_extract(payload, '$.manual') = 1)) LIMIT 1", - (task_id, newest_pr_at, *_RESPAWN_GUARD_OPERATOR_REQUEUE_KINDS), - ).fetchone() - if requeued_after: + if _unused_operator_intent_after_pr(conn, task_id): return None resolver = pr_state_resolver or _PrStateResolver() for url in dict.fromkeys(pr_urls): @@ -15195,6 +15267,107 @@ def check_respawn_guard( return None +# A READY+assigned card continuously deferred as ``respawn_guarded:active_pr`` +# for this long is STUCK, not cooling down: nothing automatic will clear it. +RESPAWN_GUARD_STUCK_SECONDS = 30 * 60 +# The newest guard event must be this fresh for the streak to be "current" +# (the dispatcher still re-evaluates it); a stale streak means the dispatcher +# itself is down, which other health lanes own. +_RESPAWN_GUARD_STUCK_FRESH_SECONDS = 10 * 60 + + +def render_operator_command(board: str, verb: str, *args: str) -> str: + """Render a runnable ``hermes kanban`` command for an operator page. + + The ONLY place an alert/hint may build a ``hermes kanban`` command + string. It always pins ``--board `` (the default board included), + so the command acts on the card's board no matter which board is current + where the operator pastes it. Arguments are shell-quoted. 2026-09-24, + t_7d7ff489 r5: a hand-assembled unscoped verb failed (rc1 "not found") + against a secondary-board card. + """ + return shlex.join(["hermes", "kanban", "--board", str(board), verb, *map(str, args)]) + + +# Event kinds that can change ``check_respawn_guard``'s ``active_pr`` answer: +# the intent/requeue kinds the guard itself reads, plus the worker's own +# dependency block and a spawn (which consumes intent). Only these restart +# the continuous-guard age in ``respawn_guard_stuck_tasks``; everything else +# (commented, heartbeat, linked, attached, ...) is data. Any trip away from +# READY returns through one of the requeue kinds, so status transitions are +# covered too. +_RESPAWN_GUARD_STUCK_RESET_KINDS: tuple[str, ...] = ( + *_RESPAWN_GUARD_FAILURE_RESET_KINDS, + "dependency_wait", + "spawned", +) + + +def respawn_guard_stuck_tasks( + conn: sqlite3.Connection, + *, + board: Optional[str] = None, + min_seconds: int = RESPAWN_GUARD_STUCK_SECONDS, + now: Optional[int] = None, +) -> list[dict]: + """Return ready+assigned+unclaimed cards stuck behind ``active_pr``. + + A card qualifies when it has been guarded with ``active_pr`` since the + last event that could have changed the guard's answer + (``_RESPAWN_GUARD_STUCK_RESET_KINDS``, or a guard decline for another + reason), the first such guard row is at least ``min_seconds`` old, and the + newest is recent. Data-only events (a progress comment, heartbeat, + attachment) do NOT restart the age. Each entry carries ``clear_verb``, + rendered by ``render_operator_command`` for ``board`` (defaults to the + current board; callers holding another board's connection must pass it). + + ``respawn_guarded`` is a benign decline for the stall streak, so without + this probe a card held by the guard is indistinguishable from a card that + is briefly cooling down. 2026-09-23, t_7d7ff489: two cards sat silent for + 8h and 14h. + """ + now = int(time.time()) if now is None else int(now) + board = board or get_current_board() + reset_marks = ", ".join("?" for _ in _RESPAWN_GUARD_STUCK_RESET_KINDS) + out: list[dict] = [] + for row in conn.execute( + "SELECT id, assignee FROM tasks WHERE status = 'ready' " + "AND assignee IS NOT NULL AND claim_lock IS NULL ORDER BY id" + ).fetchall(): + task_id = row["id"] + last_other = conn.execute( + "SELECT COALESCE(MAX(id), 0) AS m FROM task_events " + f"WHERE task_id = ? AND (kind IN ({reset_marks}) " + "OR (kind = 'respawn_guarded' " + "AND COALESCE(json_extract(payload, '$.reason'), '') != 'active_pr'))", + (task_id, *_RESPAWN_GUARD_STUCK_RESET_KINDS), + ).fetchone()["m"] + streak = conn.execute( + "SELECT MIN(created_at) AS first_at, MAX(created_at) AS last_at, " + "COUNT(*) AS n FROM task_events " + "WHERE task_id = ? AND id > ? AND kind = 'respawn_guarded'", + (task_id, int(last_other)), + ).fetchone() + if not streak or not streak["n"]: + continue + first_at = int(streak["first_at"]) + last_at = int(streak["last_at"]) + if now - first_at < min_seconds: + continue + if now - last_at > _RESPAWN_GUARD_STUCK_FRESH_SECONDS: + continue + out.append({ + "task_id": task_id, + "assignee": row["assignee"], + "reason": "active_pr", + "guarded_since": first_at, + "guarded_seconds": now - first_at, + "guard_events": int(streak["n"]), + "clear_verb": render_operator_command(board, "requeue", task_id, ""), + }) + return out + + def has_spawnable_ready(conn: sqlite3.Connection) -> bool: """Return True iff there is at least one ready+assigned+unclaimed task whose assignee maps to a real Hermes profile. diff --git a/tests/gateway/test_kanban_watchers_mixin.py b/tests/gateway/test_kanban_watchers_mixin.py index 1ba74a1054376..15f1cebd033ca 100644 --- a/tests/gateway/test_kanban_watchers_mixin.py +++ b/tests/gateway/test_kanban_watchers_mixin.py @@ -203,6 +203,79 @@ def run(argv, **kwargs): assert kwargs["stdin"] is subprocess.DEVNULL +def test_guard_stuck_notifier_pages_once_and_rearms(): + from gateway.kanban_watchers import _GuardStuckNotifier, _stall_streak_is_bad + item = {"task_id": "t_test", "clear_verb": 'hermes kanban requeue t_test ""'} + notifier = _GuardStuckNotifier() + sent = [] + def send(board, row): + sent.append((board, row)) + return True + assert notifier.observe([("default", item)], send) == 1 + assert notifier.observe([("default", item)], send) == 0 + assert sent[0][1]["clear_verb"] == 'hermes kanban requeue t_test ""' + assert _stall_streak_is_bad(True, True, [("default", _FakeResult())], guard_stuck=True) + assert notifier.observe([], send, observed_boards=set()) == 0 # lock/probe failure: unknown, not recovered + assert notifier.observe([("default", item)], send) == 0 + assert notifier.observe([], send, observed_boards={"default"}) == 0 # observed recovery + assert notifier.observe([("default", item)], send) == 1 + + +def test_guard_stuck_notifier_retries_failed_send_after_unobserved_tick(): + from gateway.kanban_watchers import _GuardStuckNotifier + item = {"task_id": "t_test", "clear_verb": 'hermes kanban requeue t_test ""'} + notifier = _GuardStuckNotifier() + calls = [] + def send(board, row): + calls.append(board) + return len(calls) > 1 + assert notifier.observe([("default", item)], send) == 0 + assert notifier.observe([], send, observed_boards=set()) == 0 + assert notifier.observe([("default", item)], send) == 1 + assert len(calls) == 2 + + +def test_guard_stuck_probe_distinguishes_empty_board_from_skipped_or_failed(monkeypatch): + from contextlib import contextmanager + from hermes_cli import kanban_db as kb + from gateway.kanban_watchers import _guard_stuck_cards + + @contextmanager + def connect(*, board): + if board == "failed": + raise OSError("probe failed") + yield object() + + monkeypatch.setattr(kb, "connect_closing", connect) + monkeypatch.setattr(kb, "respawn_guard_stuck_tasks", lambda conn, **kw: []) + cards, observed = _guard_stuck_cards([ + ("healthy", _FakeResult()), + ("locked", _FakeResult(skipped_locked=True)), + ("failed", _FakeResult()), + ]) + assert cards == [] + assert observed == {"healthy"} + + +def test_guard_stuck_sender_routes_to_alerts(tmp_path, monkeypatch): + import subprocess + from pathlib import Path + from types import SimpleNamespace + from gateway.kanban_watchers import _send_guard_stuck_alert + script = tmp_path / ".hermes" / "scripts" / "notify.py" + script.parent.mkdir(parents=True) + script.write_text("") + monkeypatch.setattr(Path, "home", lambda: tmp_path) + calls = [] + monkeypatch.setattr("gateway.kanban_watchers.subprocess.run", lambda argv, **kw: (calls.append((argv, kw)) or SimpleNamespace(returncode=0))) + assert _send_guard_stuck_alert("default", {"task_id": "t_test", "clear_verb": 'hermes kanban requeue t_test ""'}) + argv, kwargs = calls[0] + assert argv[argv.index("--channel") + 1] == "discord" + assert argv[argv.index("--sev") + 1] == "error" + assert 'hermes kanban requeue t_test ""' in argv[argv.index("--send") + 1] + assert kwargs["stdin"] is subprocess.DEVNULL + + def test_stall_respawn_guard_is_benign_not_bad(): res = _FakeResult(respawn_guarded=[("t1", "recent_success")]) assert _stall_streak_is_bad(True, False, [("b", res)]) is False diff --git a/tests/hermes_cli/test_kanban_cli.py b/tests/hermes_cli/test_kanban_cli.py index f78feab967853..1ac127fe67683 100644 --- a/tests/hermes_cli/test_kanban_cli.py +++ b/tests/hermes_cli/test_kanban_cli.py @@ -125,6 +125,20 @@ def test_kanban_show_text_renders_graph_with_open_connection(kanban_home): assert "Cannot operate on a closed database" not in output +def test_requeue_cli_records_operator_intent_for_ready_card(kanban_home, capsys): + parser = argparse.ArgumentParser(prog="hermes", add_help=False) + kc.build_parser(parser.add_subparsers(dest="command")) + with kb.connect_closing() as conn: + tid = kb.create_task(conn, title="resume", assignee="alice") + args = parser.parse_args(["kanban", "requeue", tid, "resume", "PR"]) + assert kc.kanban_command(args) == 0 + assert f"Requeued {tid}" in capsys.readouterr().out + with kb.connect_closing() as conn: + assert kb.list_events(conn, tid)[-1].kind == "requeued" + assert kb.list_events(conn, tid)[-1].payload["reason"] == "resume PR" + assert kc.kanban_command(parser.parse_args(["kanban", "requeue", tid, "again"])) == 0 + + def test_board_override_is_isolated_per_concurrent_call(kanban_home, monkeypatch): kb.create_board("alpha") kb.create_board("beta") diff --git a/tests/hermes_cli/test_kanban_core_functionality.py b/tests/hermes_cli/test_kanban_core_functionality.py index 0a47445ec1108..365c856b91284 100644 --- a/tests/hermes_cli/test_kanban_core_functionality.py +++ b/tests/hermes_cli/test_kanban_core_functionality.py @@ -1074,16 +1074,12 @@ def _connect(*args, **kwargs): raise sqlite3.DatabaseError("file is not a database") async def _to_thread(fn, *args, **kwargs): - # PR salvage (#32857 commit 7): the dispatcher now reaps zombies at - # the top of each tick via ``asyncio.to_thread(_kb.reap_worker_zombies)`` - # BEFORE the per-board tick work. Each tick now issues 3 ``to_thread`` - # calls (reaper + ``_tick_once`` + ``_ready_nonempty``) instead of 2, - # so this counter must reach 6 to allow the same 2 dispatch ticks the - # pre-reaper test expected at 4. Connect counts in the assertion below - # are unchanged. + # Stop only after both dispatch ticks and their ready/review probes. + # Additional per-tick telemetry calls (such as the guarded-card alert + # probe) must not shorten this two-tick corruption regression. calls["to_thread"] += 1 result = fn(*args, **kwargs) - if calls["to_thread"] >= 6: + if calls["connect"] >= 5: runner._running = False return result diff --git a/tests/hermes_cli/test_kanban_db.py b/tests/hermes_cli/test_kanban_db.py index 007915e266ad0..3445daa6c5263 100644 --- a/tests/hermes_cli/test_kanban_db.py +++ b/tests/hermes_cli/test_kanban_db.py @@ -3506,6 +3506,408 @@ def tick(): assert kb.check_respawn_guard(conn, task_id) is None +def test_dependency_wait_promoted_resumes_open_pr_once(kanban_home, all_assignees_spawnable, monkeypatch): + monkeypatch.setattr(kb, "_query_github_pr_state", lambda repo, number: "OPEN") + with kb.connect() as conn: + parent = kb.create_task(conn, title="parent", assignee="alice") + assert kb.complete_task(conn, parent) + child = kb.create_task(conn, title="child", assignee="alice", parents=[parent]) + assert kb.claim_task(conn, child) + kb.add_comment(conn, child, "alice", "https://github.com/o/r/pull/9") + assert kb.reopen_task(conn, parent, actor="operator", reason="rework") == (True, None) + assert kb.block_task(conn, child, reason="resume then complete", kind="dependency") + assert kb.complete_task(conn, parent) + assert kb.get_task(conn, child).status == "ready" + spawned = [] + result = kb.dispatch_once(conn, spawn_fn=lambda task, workspace, board=None: (spawned.append(task.id) or 42)) + assert child in spawned + assert result.spawned + # A second crash/reclaim must not get the same one-shot exemption. + conn.execute("UPDATE tasks SET status='ready', claim_lock=NULL, claim_expires=NULL, worker_pid=NULL, current_run_id=NULL WHERE id=?", (child,)) + conn.commit() + assert kb.check_respawn_guard(conn, child) == "active_pr" + + +def test_dependency_wait_ordinary_comment_after_block_resumes_same_pr(kanban_home, all_assignees_spawnable, monkeypatch): + monkeypatch.setattr(kb, "_query_github_pr_state", lambda repo, number: "OPEN") + with kb.connect() as conn: + parent = kb.create_task(conn, title="parent", assignee="alice") + assert kb.complete_task(conn, parent) + child = kb.create_task(conn, title="child", assignee="alice", parents=[parent]) + assert kb.claim_task(conn, child) + kb.add_comment(conn, child, "alice", "https://github.com/o/r/pull/9") + assert kb.reopen_task(conn, parent, actor="operator", reason="rework") == (True, None) + assert kb.block_task(conn, child, reason="resume", kind="dependency") + kb.add_comment(conn, child, "alice", "Waiting for parent; no new PR") + assert kb.complete_task(conn, parent) + spawned = [] + kb.dispatch_once(conn, spawn_fn=lambda task, workspace, board=None: (spawned.append(task.id) or 42)) + assert child in spawned + + +def test_dependency_wait_before_newer_pr_comment_does_not_resume(kanban_home, monkeypatch): + monkeypatch.setattr(kb, "_query_github_pr_state", lambda repo, number: "OPEN") + with kb.connect() as conn: + parent = kb.create_task(conn, title="parent", assignee="alice") + assert kb.complete_task(conn, parent) + child = kb.create_task(conn, title="child", assignee="alice", parents=[parent]) + assert kb.claim_task(conn, child) + kb.add_comment(conn, child, "alice", "https://github.com/o/r/pull/9") + assert kb.reopen_task(conn, parent, actor="operator", reason="rework") == (True, None) + assert kb.block_task(conn, child, reason="resume", kind="dependency") + kb.add_comment(conn, child, "alice", "newer https://github.com/o/r/pull/10") + assert kb.complete_task(conn, parent) + assert kb.check_respawn_guard(conn, child) == "active_pr" + + +def test_requeue_ready_card_overrides_active_pr(kanban_home, monkeypatch): + with kb.connect() as conn: + task_id, _ = _seed_task_with_open_pr(conn, kb, monkeypatch, int(time.time())) + assert kb.requeue_task(conn, task_id, actor="operator", reason="resume")[0] is False + conn.execute("UPDATE tasks SET status='ready', claim_lock=NULL, claim_expires=NULL, current_run_id=NULL WHERE id=?", (task_id,)) + conn.commit() + assert kb.check_respawn_guard(conn, task_id) == "active_pr" + assert kb.requeue_task(conn, task_id, actor="operator", reason="retry PR") == (True, None) + assert kb.list_events(conn, task_id)[-1].kind == "requeued" + assert kb.check_respawn_guard(conn, task_id) is None + + +@pytest.mark.parametrize("later_pr_second", [False, True]) +def test_requeue_intent_preceding_new_pr_is_not_reused(kanban_home, monkeypatch, later_pr_second): + now = int(time.time()) + monkeypatch.setattr(kb.time, "time", lambda: now) + with kb.connect() as conn: + task_id, _ = _seed_task_with_open_pr(conn, kb, monkeypatch, now) + conn.execute("UPDATE tasks SET status='ready', claim_lock=NULL, claim_expires=NULL, current_run_id=NULL WHERE id=?", (task_id,)) + conn.commit() + assert kb.requeue_task(conn, task_id, actor="operator", reason="continue PR 9") == (True, None) + assert kb.check_respawn_guard(conn, task_id) is None + if later_pr_second: + now += 1 + kb.add_comment(conn, task_id, "alice", "https://github.com/o/r/pull/10") + assert kb.check_respawn_guard(conn, task_id) == "active_pr" + + +@pytest.mark.parametrize("kind", kb._RESPAWN_GUARD_OPERATOR_REQUEUE_KINDS) +def test_every_operator_intent_is_ordered_and_consumed(kanban_home, monkeypatch, kind): + now = int(time.time()) + monkeypatch.setattr(kb.time, "time", lambda: now) + with kb.connect() as conn: + task_id, _ = _seed_task_with_open_pr(conn, kb, monkeypatch, now) + kb._append_event(conn, task_id, kind, {"actor": "operator"}) + intent = kb.list_events(conn, task_id)[-1] + assert intent.payload is not None + assert intent.payload["after_comment_id"] == conn.execute( + "SELECT MAX(id) FROM task_comments WHERE task_id=?", (task_id,), + ).fetchone()[0] + assert kb.check_respawn_guard(conn, task_id) is None + kb._append_event(conn, task_id, "spawned", {"pid": 99999999}) + assert kb.check_respawn_guard(conn, task_id) == "active_pr" + # Even an intent newer than PR 9 must not authorize PR 10. + kb._append_event(conn, task_id, kind, {"actor": "operator"}) + kb.add_comment(conn, task_id, "alice", "https://github.com/o/r/pull/10") + assert kb.check_respawn_guard(conn, task_id) == "active_pr" + + +@pytest.mark.parametrize("manual", [False, True]) +def test_reclaim_intent_only_if_manual_and_not_consumed(kanban_home, monkeypatch, manual): + now = int(time.time()) + monkeypatch.setattr(kb.time, "time", lambda: now) + with kb.connect() as conn: + task_id, _ = _seed_task_with_open_pr(conn, kb, monkeypatch, now) + kb._append_event(conn, task_id, "reclaimed", {"manual": manual}) + assert (kb.check_respawn_guard(conn, task_id) is None) is manual + kb._append_event(conn, task_id, "spawned", {"pid": 99999999}) + assert kb.check_respawn_guard(conn, task_id) == "active_pr" + + +def test_requeue_intent_consumed_after_dispatch_and_crash(kanban_home, all_assignees_spawnable, monkeypatch): + with kb.connect() as conn: + task_id, _ = _seed_task_with_open_pr(conn, kb, monkeypatch, int(time.time())) + conn.execute("UPDATE tasks SET status='ready', claim_lock=NULL, claim_expires=NULL, current_run_id=NULL WHERE id=?", (task_id,)) + conn.commit() + assert kb.requeue_task(conn, task_id, actor="operator", reason="continue PR 9") == (True, None) + spawned = [] + kb.dispatch_once(conn, spawn_fn=lambda task, workspace, board=None: (spawned.append(task.id) or 99999999)) + assert task_id in spawned + monkeypatch.setattr(kb, "_pid_alive", lambda pid: False) + monkeypatch.setattr(kb, "_resolve_crash_grace_seconds", lambda: 0) + assert task_id in kb.detect_crashed_workers(conn) + assert kb.get_task(conn, task_id).status == "ready" + assert kb.check_respawn_guard(conn, task_id) == "active_pr" + spawned.clear() + kb.dispatch_once(conn, spawn_fn=lambda task, workspace, board=None: (spawned.append(task.id) or 99999999)) + assert task_id not in spawned + + +def test_ready_requeue_after_inline_triage_comment_resumes_pr(kanban_home, all_assignees_spawnable, monkeypatch): + """An inline audit comment cannot shift the PR comment's causal event.""" + monkeypatch.setattr(kb, "_query_github_pr_state", lambda repo, number: "OPEN") + with kb.connect() as conn: + task_id = kb.create_task(conn, title="triage PR", assignee="alice") + assert kb.claim_task(conn, task_id) + assert kb.block_task(conn, task_id, reason="ruling one", kind="needs_input") + assert kb.unblock_task(conn, task_id) + assert kb.claim_task(conn, task_id) + assert kb.block_task(conn, task_id, reason="ruling two", kind="needs_input") + assert kb.triage_resolve_task(conn, task_id, to="todo", reason="resume", actor="qa") == (True, None) + kb.add_comment(conn, task_id, "qa", "https://github.com/o/r/pull/9") + assert kb.requeue_task(conn, task_id, actor="qa", reason="continue PR 9") == (True, None) + assert kb.check_respawn_guard(conn, task_id) is None + spawned = [] + kb.dispatch_once(conn, spawn_fn=lambda task, workspace, board=None: (spawned.append(task.id) or 99999999)) + assert task_id in spawned + + +def test_dependency_intent_not_reused_after_second_automatic_promotion(kanban_home, all_assignees_spawnable, monkeypatch): + from plugins.kanban.dashboard import plugin_api + + monkeypatch.setattr(kb, "_query_github_pr_state", lambda repo, number: "OPEN") + with kb.connect() as conn: + parent = kb.create_task(conn, title="parent", assignee="alice") + assert kb.complete_task(conn, parent) + child = kb.create_task(conn, title="child", assignee="alice", parents=[parent]) + assert kb.claim_task(conn, child) + kb.add_comment(conn, child, "alice", "https://github.com/o/r/pull/9") + assert kb.reopen_task(conn, parent, actor="qa", reason="first parent rework") == (True, None) + assert kb.block_task(conn, child, reason="resume after parent", kind="dependency") + assert kb.complete_task(conn, parent) + first = [] + kb.dispatch_once(conn, spawn_fn=lambda task, workspace, board=None: (first.append(task.id) or 99999999)) + assert child in first + assert plugin_api._set_status_direct(conn, parent, "todo") + assert kb.recompute_ready(conn) >= 1 + assert kb.complete_task(conn, parent) + assert kb.get_task(conn, child).status == "ready" + assert kb.check_respawn_guard(conn, child) == "active_pr" + second = [] + kb.dispatch_once(conn, spawn_fn=lambda task, workspace, board=None: (second.append(task.id) or 99999999)) + assert child not in second + + +def test_inline_same_author_and_length_cannot_impersonate_pr_event(kanban_home, monkeypatch): + now = int(time.time()) + monkeypatch.setattr(kb.time, "time", lambda: now) + monkeypatch.setattr(kb, "_query_github_pr_state", lambda repo, number: "OPEN") + with kb.connect() as conn: + task_id = kb.create_task(conn, title="audit", assignee="alice") + pr = "https://github.com/o/r/pull/9" + conn.execute( + "INSERT INTO task_comments (task_id, author, body, created_at) VALUES (?, ?, ?, ?)", + (task_id, "alice", "x" * len(pr), now), + ) + conn.commit() + kb.add_comment(conn, task_id, "alice", pr) + assert kb.requeue_task(conn, task_id, actor="operator", reason="resume") == (True, None) + assert kb.check_respawn_guard(conn, task_id) is None + kb.add_comment(conn, task_id, "alice", "https://github.com/o/r/pull/8") + assert kb.check_respawn_guard(conn, task_id) == "active_pr" + + +def test_legacy_pr_event_with_inline_comment_still_requeues(kanban_home, monkeypatch): + """Existing boards have commented events without a comment_id payload.""" + now = int(time.time()) + monkeypatch.setattr(kb.time, "time", lambda: now) + monkeypatch.setattr(kb, "_query_github_pr_state", lambda repo, number: "OPEN") + with kb.connect() as conn: + task_id = kb.create_task(conn, title="legacy PR", assignee="alice") + conn.execute( + "INSERT INTO task_comments (task_id, author, body, created_at) VALUES (?, ?, ?, ?)", + (task_id, "audit", "old inline note", now), + ) + conn.commit() + kb.add_comment(conn, task_id, "alice", "https://github.com/o/r/pull/9") + conn.execute( + "UPDATE task_events SET payload=json_remove(payload, '$.comment_id') " + "WHERE task_id=? AND kind='commented'", (task_id,), + ) + conn.commit() + assert kb.check_respawn_guard(conn, task_id) == "active_pr" + assert kb.requeue_task(conn, task_id, actor="operator", reason="continue") == (True, None) + assert kb.check_respawn_guard(conn, task_id) is None + + +def test_legacy_equal_length_inline_comment_does_not_block_requeue(kanban_home, monkeypatch): + now = int(time.time()) + monkeypatch.setattr(kb.time, "time", lambda: now) + monkeypatch.setattr(kb, "_query_github_pr_state", lambda repo, number: "OPEN") + with kb.connect() as conn: + task_id = kb.create_task(conn, title="legacy equal length", assignee="alice") + pr = "https://github.com/o/r/pull/9" + conn.execute( + "INSERT INTO task_comments (task_id, author, body, created_at) VALUES (?, ?, ?, ?)", + (task_id, "alice", "x" * len(pr), now), + ) + conn.commit() + kb.add_comment(conn, task_id, "alice", pr) + conn.execute( + "UPDATE task_events SET payload=json_remove(payload, '$.comment_id') " + "WHERE task_id=? AND kind='commented'", (task_id,), + ) + conn.commit() + assert kb.check_respawn_guard(conn, task_id) == "active_pr" + assert kb.requeue_task(conn, task_id, actor="operator", reason="continue") == (True, None) + assert kb.check_respawn_guard(conn, task_id) is None + kb.add_comment(conn, task_id, "alice", "https://github.com/o/r/pull/8") + assert kb.check_respawn_guard(conn, task_id) == "active_pr" + + +@pytest.mark.parametrize("inline_before", [False, True]) +@pytest.mark.parametrize("padded", [False, True]) +def test_historical_pr_dependency_wait_resumes_despite_unmappable_comment_event( + kanban_home, all_assignees_spawnable, monkeypatch, inline_before, padded, +): + """Old boards did not link commented events; trim/inline writes defeat correlation.""" + now = int(time.time()) + clock = {"now": now} + monkeypatch.setattr(kb.time, "time", lambda: clock["now"]) + monkeypatch.setattr(kb, "_query_github_pr_state", lambda repo, number: "OPEN") + with kb.connect() as conn: + parent = kb.create_task(conn, title="parent", assignee="alice") + assert kb.complete_task(conn, parent) + child = kb.create_task(conn, title="child", assignee="alice", parents=[parent]) + assert kb.claim_task(conn, child) + if inline_before: + conn.execute( + "INSERT INTO task_comments (task_id, author, body, created_at) VALUES (?, ?, ?, ?)", + (child, "alice", "x" * len("https://github.com/o/r/pull/9"), now), + ) + conn.commit() + pr = "https://github.com/o/r/pull/9" + kb.add_comment(conn, child, "alice", f" {pr} " if padded else pr) + conn.execute( + "UPDATE task_events SET payload=json_remove(payload, '$.comment_id') " + "WHERE task_id=? AND kind='commented'", (child,), + ) + conn.commit() + assert kb.reopen_task(conn, parent, actor="qa", reason="rework") == (True, None) + clock["now"] += 2 + assert kb.block_task(conn, child, reason="resume then complete", kind="dependency") + assert kb.complete_task(conn, parent) + spawned = [] + kb.dispatch_once(conn, spawn_fn=lambda task, workspace, board=None: (spawned.append(task.id) or 42)) + assert child in spawned + + +@pytest.mark.parametrize("later_second", [False, True]) +def test_preupgrade_intent_resumes_on_equal_second(kanban_home, monkeypatch, later_second): + now = int(time.time()) + clock = {"now": now} + monkeypatch.setattr(kb.time, "time", lambda: clock["now"]) + with kb.connect() as conn: + task_id, _ = _seed_task_with_open_pr(conn, kb, monkeypatch, now) + conn.execute("UPDATE tasks SET status='ready', claim_lock=NULL, claim_expires=NULL, current_run_id=NULL WHERE id=?", (task_id,)) + conn.commit() + if later_second: + clock["now"] += 2 + assert kb.requeue_task(conn, task_id, actor="operator", reason="legacy") == (True, None) + conn.execute( + "UPDATE task_events SET payload=json_remove(payload, '$.after_comment_id', '$.pr_comment_id') " + "WHERE task_id=? AND kind='requeued'", (task_id,), + ) + conn.commit() + assert kb.check_respawn_guard(conn, task_id) is None + + +def test_pr_intent_has_one_event_id_ordering_seam(): + """PR identity comes only from comments; no guessed comment/event join.""" + import ast + import inspect + source = inspect.getsource(kb.check_respawn_guard) + intent = inspect.getsource(kb._unused_operator_intent_after_pr) + tree = ast.parse(source + "\n" + intent) + sql_literals = [node.value.lower() for node in ast.walk(tree) + if isinstance(node, ast.Constant) and isinstance(node.value, str)] + assert source.count("_unused_operator_intent_after_pr(conn, task_id)") == 1 + assert "after_comment_id" in intent and "s.id > i.id" in intent + assert "json_type(i.payload, '$.after_comment_id') IS NULL AND i.created_at >= ?" in intent + assert not any("kind = 'commented'" in value for value in sql_literals) + assert not any("join task_comments" in value or "join task_events" in value + for value in sql_literals) + + +def test_guard_stuck_age_survives_progress_comment_during_real_dispatch(kanban_home, monkeypatch): + import hermes_cli.profiles as profmod + + now = int(time.time()) + monkeypatch.setattr(profmod, "profile_exists", lambda name: name == "alice") + monkeypatch.setattr(kb, "_query_github_pr_state", lambda *args: "OPEN") + with kb.connect() as conn: + plain = kb.create_task(conn, title="no comment", assignee="alice") + noted = kb.create_task(conn, title="progress comment", assignee="alice") + for tid in (plain, noted): + kb.add_comment(conn, tid, "qa", "https://github.com/o/r/pull/9") + spawn = lambda *args, **kw: (_ for _ in ()).throw(AssertionError("guarded card spawned")) + first = kb.dispatch_once(conn, spawn_fn=spawn) + assert {plain, noted} <= {tid for tid, reason in first.respawn_guarded if reason == "active_pr"} + conn.execute("UPDATE task_events SET created_at=? WHERE kind='respawn_guarded'", (now - 1861,)) + conn.commit() + kb.add_comment(conn, noted, "qa", "Progress only; same PR") + second = kb.dispatch_once(conn, spawn_fn=spawn) + assert {plain, noted} <= {tid for tid, reason in second.respawn_guarded if reason == "active_pr"} + stuck = kb.respawn_guard_stuck_tasks(conn, now=now) + assert {plain, noted} == {row["task_id"] for row in stuck} + assert all(row["guarded_seconds"] >= 1861 for row in stuck) + assert kb.requeue_task(conn, noted, actor="operator", reason="resume") == (True, None) + assert {row["task_id"] for row in kb.respawn_guard_stuck_tasks(conn, now=now)} == {plain} + + +def test_guard_stuck_recovery_command_runs_on_each_board(kanban_home, monkeypatch): + import shlex + kb.create_board("secondary") + monkeypatch.setenv("HERMES_KANBAN_SANDBOX", "1") + monkeypatch.delenv("HERMES_KANBAN_BOARD", raising=False) + now = int(time.time()) + for board in ("default", "secondary"): + with kb.connect_closing(board=board) as conn: + tid = kb.create_task(conn, title="stuck", assignee="alice") + kb._append_event(conn, tid, "respawn_guarded", {"reason": "active_pr"}) + conn.execute("UPDATE task_events SET created_at=? WHERE task_id=? AND kind='respawn_guarded'", (now - 1861, tid)) + kb._append_event(conn, tid, "respawn_guarded", {"reason": "active_pr"}) + item, = kb.respawn_guard_stuck_tasks(conn, board=board, now=now) + command = shlex.split(item["clear_verb"].replace("", "continue PR")) + assert command[:4] == ["hermes", "kanban", "--board", board] + result = subprocess.run( + [sys.executable, "-m", "hermes_cli.main", *command[1:]], + cwd=Path(__file__).resolve().parents[2], env=os.environ.copy(), + stdin=subprocess.DEVNULL, capture_output=True, text=True, timeout=60, + ) + assert result.returncode == 0, result.stderr + with kb.connect_closing(board=board) as conn: + assert kb.list_events(conn, tid)[-1].kind == "requeued" + assert kb.respawn_guard_stuck_tasks(conn, board=board, now=now) == [] + + +def test_guard_stuck_recovery_command_has_one_renderer(): + import ast + import inspect + from gateway import kanban_watchers + for module in (kb, kanban_watchers): + tree = ast.parse(inspect.getsource(module)) + builders = [node for node in ast.walk(tree) if isinstance(node, ast.JoinedStr) + and node.values and isinstance(node.values[0], ast.Constant) + and isinstance(node.values[0].value, str) + and node.values[0].value.startswith("hermes kanban ")] + assert all(any(isinstance(parent, ast.FunctionDef) and parent.name == "render_operator_command" + and node in ast.walk(parent) for parent in ast.walk(tree) + if isinstance(parent, ast.FunctionDef)) for node in builders) + + +def test_respawn_guard_stuck_threshold_and_reset(kanban_home): + now = int(time.time()) + with kb.connect() as conn: + tid = kb.create_task(conn, title="stuck", assignee="alice") + kb._append_event(conn, tid, "respawn_guarded", {"reason": "active_pr"}) + conn.execute("UPDATE task_events SET created_at=? WHERE task_id=? AND kind='respawn_guarded'", (now - 1860, tid)) + kb._append_event(conn, tid, "respawn_guarded", {"reason": "active_pr"}) + assert kb.respawn_guard_stuck_tasks(conn, now=now - 120) == [] + stuck = kb.respawn_guard_stuck_tasks(conn, now=now) + assert [x["task_id"] for x in stuck] == [tid] + assert stuck[0]["clear_verb"] == kb.render_operator_command("default", "requeue", tid, "") + kb._append_event(conn, tid, "requeued", {"actor": "operator", "reason": "retry"}) + assert kb.respawn_guard_stuck_tasks(conn, now=now) == [] + + def test_operator_requeue_kinds_constant_matches_verbs_that_emit_them(): """Every kind in the override set is actually emitted by kanban_db (no dead entries), and every operator requeue verb's event kind is in the set (no missing entries).""" @@ -3520,6 +3922,7 @@ def test_operator_requeue_kinds_constant_matches_verbs_that_emit_them(): "reopen_review_task": "review_reopened", "triage_resolve_task": "triage_resolved", "reopen_task": "reopened", + "requeue_task": "requeued", } for fn, kind in verb_kinds.items(): assert hasattr(kb, fn), fn diff --git a/tests/hermes_cli/test_kanban_triage_exit.py b/tests/hermes_cli/test_kanban_triage_exit.py index 65f59360744cf..6ef5c5e396e5a 100644 --- a/tests/hermes_cli/test_kanban_triage_exit.py +++ b/tests/hermes_cli/test_kanban_triage_exit.py @@ -398,12 +398,16 @@ def test_triage_resolve_records_who_and_why(kanban_home: Path) -> None: events = [e for e in kb.list_events(conn, parent) if e.kind == "triage_resolved"] assert len(events) == 1 + comments = kb.list_comments(conn, parent) + # Intent events snapshot max(task_comments.id) at emit time + # (respawn-guard PR ordering); the inline audit comment lands first. assert events[0].payload == { "to": "todo", "reason": "talked to the author; retry is fine", "actor": "ace", + "after_comment_id": max(c.id for c in comments), } - bodies = [c.body for c in kb.list_comments(conn, parent)] + bodies = [c.body for c in comments] assert any(b.startswith("TRIAGE-RESOLVE -> todo:") for b in bodies) From dc228d5810fefb652f74d6144e9b07b09d19d6ea Mon Sep 17 00:00:00 2001 From: Alexander Nikolas Date: Thu, 24 Sep 2026 13:08:04 +0000 Subject: [PATCH 5/7] fix(lcm): FTS parity COUNT(*) ran under _LOAD_LOCK on every engine load (freeze #3) (#966) * fix(lcm): FTS parity COUNT(*) ran under _LOAD_LOCK on every engine load (freeze #3) Card t_d3963974. Third Apollo boot-cost freeze. The cause: _fts_needs_rebuild_structural ran `SELECT COUNT(*) FROM messages` (SCAN messages USING COVERING INDEX, 2.5M rows) plus `COUNT(*) FROM messages_fts_docsize` on EVERY MessageStore/SummaryDAG construction, under plugins.context_engine._LOAD_LOCK. Measured on an APFS clone of the fleet DB: 13.4 s of a 17.9 s cold MessageStore() init. The two autocommit COUNTs could also straddle a concurrent ingest. They gave a false mismatch 15/300 times, and each mismatch triggered a full inline FTS drop+rebuild. That happened twice on 2026-09-24: held 779.8 s, 12 turns queued. Provenance: the count came in with the original vendor import 8b869633a4 (2026-06-16) and was carried unchanged through re-vendor 27b617846e. #887/#902/#903 did not touch it. #903's plan check exempted USING COVERING INDEX and skipped messages_fts*, so it passed on this code. Fix: - The parity check moves to _fts_count_parity_mismatch. It never runs on the throttle=True (load) path. A metadata marker (fts_parity_checked_at:) throttles it to once per LCM_FTS_PARITY_CHECK_INTERVAL_HOURS (default 6 h). When due, it runs on the existing background integrity thread (own connection). A mismatch sets the /lcm doctor integrity flag instead of rebuilding inline. Both counts are read in one snapshot. - Explicit repair (throttle=False) and /lcm doctor still run parity synchronously. - A no-op load writes nothing: - _clear_integrity_failed runs only after a real repair. Before, it also erased the background corruption flag on every load. - The messages_dedup_v1 and schema_version upserts are marker-gated. - The integrity claim uses a 1 s busy timeout, not 30 s. - Lifecycle GC (on_session_start, every agent init): - no longer holds BEGIN IMMEDIATE across two SELECT DISTINCT session_id full scans; - uses indexed per-session probes; - runs at most once per 6 h per process. - _backfill_search_content no longer rewrites NULL over NULL for undecryptable rows. That rewrite fired msg_fts_update on every boot. Test: test_lcm_init_cost_regression now traces engine construction + on_session_start on the loading thread. It fails on ANY SCAN of messages, messages_fts*, summary_nodes and nodes_fts*, covering index included (only LIMIT-bounded statements are exempt). It also asserts that a steady-state load needs no write lock and preserves the corruption flag. RED on df435998f9 (3 failed); GREEN with this change; tests/context_engine: 393 passed. * test(lcm): lock parity-race repro and document restart meltdown --------- Co-authored-by: Apollo --- docs/lcm-init-boot-cost-contract.md | 119 +++++++- plugins/context_engine/lcm/config.py | 4 + plugins/context_engine/lcm/db_bootstrap.py | 253 +++++++++++++--- plugins/context_engine/lcm/engine.py | 25 ++ plugins/context_engine/lcm/lifecycle_state.py | 132 ++++----- plugins/context_engine/lcm/store.py | 10 + .../test_lcm_init_cost_regression.py | 272 +++++++++++++++--- 7 files changed, 666 insertions(+), 149 deletions(-) diff --git a/docs/lcm-init-boot-cost-contract.md b/docs/lcm-init-boot-cost-contract.md index 79bf5ff0b1326..38e21c697abfc 100644 --- a/docs/lcm-init-boot-cost-contract.md +++ b/docs/lcm-init-boot-cost-contract.md @@ -9,6 +9,78 @@ process-wide engine-load lock. Each backfill was correct and cheap when it lande and nobody re-measured as the DB grew. Fixes: fork PRs #887 (`search_content`), #902 (`ingested_at`), and this document's regression layer. +## Freeze #3 (2026-09-24): parity COUNT plus a false-rebuild race + +This was **not generic I/O contention** and not “Kanban is too busy.” The +restart burst created many LCM engine loads and active ingests; the *code* turned +that combination into a false FTS parity mismatch and an enormous synchronous +index rebuild. Aegis also uses LCM, but its independent gateway/database and +small, low-concurrency workload do not exercise Apollo's 2.7 M-row DB with +simultaneous Kanban children. A healthy Aegis chat is therefore no control for +this load pattern. + +Measured on the live Apollo DB and an APFS clone, without mutating the live DB: + +- `EXPLAIN QUERY PLAN SELECT COUNT(*) FROM messages` → `SCAN TABLE messages + USING COVERING INDEX idx_msg_session_ts`; `messages_fts_docsize` → `SCAN + TABLE messages_fts_docsize`. A covering index is still a traversal of all + 2.7 M rows. Cold clone: `MessageStore()` took 17.9 s; these two SELECTs + occupied 11.1 s and 2.35 s. Warm-cache standalone counts (~0.07/0.05 s) + understated the contended restart cost. +- The original `_fts_needs_rebuild_structural` issued **two autocommit SELECTs**. + A concurrent valid message insert and FTS trigger commit between them made + the two snapshots disagree. Reproduced with a real SQLite writer: **15/300 + parity calls falsely requested rebuild**; a deterministic interleaving test + fails on fork/main and passes with both reads in one deferred read transaction. +- The real `apollo-loadlock-samples.log` sampled the lock holder at + `db_bootstrap.py:2885` (`_drop_fts_table`) at 05:07–05:10, then at `:3023` + (`INSERT INTO messages_fts(messages_fts) VALUES('rebuild')`) through 05:20; + `PHASE=context_engine_load_slow held=779.8s`. A second rebuild ran about + 05:22–05:28. Up to 12 other threads waited on `_LOAD_LOCK`. These are direct + stack samples of **rebuilding**, not an inference from a slow log. +- Two amplifiers were also observed: no-op engine loads unconditionally wrote + the `fts_integrity_failed` DELETE and the `messages_dedup_v1`/schema markers, + queuing behind the SQLite write lock; at session start, lifecycle GC ran + `SELECT DISTINCT session_id FROM messages/summary_nodes` under `BEGIN + IMMEDIATE` once its default 200-row threshold was exceeded (live: 11,108 + lifecycle rows). The three undecryptable NULL `search_content` rows were + point-updated to NULL on **every** load, firing FTS update triggers despite + no change. A separate cold-clone trace measured 56.7 s in one such FTS + shadow write. These are distinct from the parity root cause and all sit on + the same restart fan-out path. + +**Code provenance (git, not chronology-as-causality):** + +- `8b869633a4` (2026-06-16 initial LCM vendor) already has the two COUNTs in + `db_bootstrap.py:308,317` and `MessageStore`/`SummaryDAG` registration calls. + The parity design did **not** originate in September. +- `3174e25373` (2026-07-21) introduced the process-global `_LOAD_LOCK` to + prevent half-import races. `27b617846e` (2026-08-06 re-vendor) preserved the + COUNTs and the per-load FTS check; it did **not** newly introduce them. +- `d8b2d2448e` (#887, 2026-09-23) gated/indexed the `search_content` backfill; + `4964ea0518` (#902) marked the `ingested_at` backfill. Neither changed + `_fts_needs_rebuild_structural`. `4806d08c8b` (#903) added this init-cost + test and slow-load logging, but the test **exempted `USING COVERING INDEX` + and skipped SQL mentioning `messages_fts`**, so it passed the bad COUNTs. + This PR strengthens the existing gate, rather than calling those prior fixes + the cause of freeze #3. + +**Fix:** The engine-load path does only O(1) FTS shape/metadata checks. The +parity count is independently throttled (default 6 h, persisted per FTS table +in metadata), dispatched with the existing background integrity worker, and +retained on explicit `/lcm doctor` repair. Its two counts share one SQLite read +snapshot. No-op loads take no SQLite write lock, NULL-to-NULL backfill writes +are skipped, and empty-lifecycle GC uses indexed point probes and an +in-process 6 h throttle rather than an immediate full `messages` traversal. +A structural corruption/missing table still takes the existing repair path; +background findings still surface through `/lcm doctor`. + +**Scope of verification:** isolated worktree with `PYTHONPATH=`; +`tests/context_engine/` passes. No fork merge, deploy or gateway restart is +part of this PR. The final operational gate is a restart with concurrent +Kanban workers and a real reply from Apollo; tests and a clone cannot claim +that user-visible result in advance. + ## The contract 1. **`_init_db` is on every turn's critical path.** `load_context_engine()` runs it under @@ -20,16 +92,24 @@ and nobody re-measured as the DB grew. Fixes: fork PRs #887 (`search_content`), "run once" true across boots. `search_content` additionally uses a partial index (`idx_msg_search_content_null`) so the presence probe is O(1) even before the marker exists. 3. **Any `UPDATE`/`DELETE`/`SELECT` against `messages` on the init path must be either - row-bounded** (`WHERE store_id`/`session_id`, `LIMIT ?`) **or marker-gated.** + row-bounded** (`WHERE store_id`/`session_id`, `LIMIT ?`) **or moved off the load path.** + A covering-index scan is still O(rows). A marker does not make a full scan safe + under `_LOAD_LOCK` on the first load after a restart or marker expiry. 4. **Real work is batched and committed per batch** (`BACKFILL_BATCH_ROWS`), so a kill mid-backfill keeps its progress instead of redoing everything next boot. +5. **Concurrent reads must share one snapshot.** Separate autocommit parity counts + straddled a valid FTS-triggered ingest and falsely authorized a full inline rebuild. + A no-op load must not acquire the SQLite write lock or erase a background finding. -## The three enforcement layers (all in `tests/context_engine/`) +## The enforcement layers (all in `tests/context_engine/`) | Layer | File / test | What it catches | Proven red on | |---|---|---|---| | Source contract | `test_lcm_backfill_cost.py::test_init_path_has_no_unmarked_full_table_writes` | walks every method `_init_db` calls; any unbounded, unmarked `UPDATE`/`DELETE … messages` fails, naming the method | injected `UPDATE messages SET source=… WHERE source IS NULL` into `_ensure_source_column` | -| Query plan | `test_lcm_init_cost_regression.py::test_second_open_issues_no_full_scan_of_messages` | traces every statement a second open issues, `EXPLAIN`s each on a fresh connection, fails on a bare `SCAN messages`; **a statement that cannot be explained is a finding, never a skip** | the 2026-09-22-morning `store.py` (both scans named), and tonight's gate alone | +| Query plan | `test_lcm_init_cost_regression.py::test_second_open_issues_no_full_scan_of_guarded_tables` | traces every statement a steady-state engine construction **+ `on_session_start`** issues on the loading thread, `EXPLAIN`s each on a fresh connection, and fails on **any** `SCAN` of `messages`, `messages_fts*`, `summary_nodes`, `nodes_fts*` — **`USING COVERING INDEX` is NOT exempt** (a covering-index `COUNT(*)` still reads every row); only `LIMIT`-bounded statements are. **A statement that cannot be explained is a finding, never a skip** | the 2026-09-22-morning `store.py`; fork/main `df435998f9` (freeze #3: `COUNT(*) FROM messages` → `SCAN messages USING COVERING INDEX`, `COUNT(*) FROM messages_fts_docsize`, lifecycle-GC `SELECT DISTINCT session_id` ×2) | +| Write lock | `…::test_engine_construction_needs_no_write_lock` | a steady-state engine construction must succeed while another connection holds `BEGIN IMMEDIATE`, busy timeout 0 — i.e. a no-op load issues **no write** and can never queue behind an in-flight writer | fork/main `df435998f9` (unconditional `messages_dedup_v1` / `schema_version` upserts, `_clear_integrity_failed` DELETE) | +| Flag survival | `…::test_ordinary_open_keeps_background_corruption_flag` | an ordinary open must not erase the background scan's corruption flag | fork/main `df435998f9` | +| Parity race | `…::test_concurrent_ingest_between_parity_counts_cannot_trigger_rebuild` | commits a real message + FTS trigger between the two count reads; a valid ingest must not authorize rebuild | fork/main: `assert not needs_rebuild` fails; fixed: one read transaction succeeds | | Scale ratio | `…::test_init_time_does_not_scale_with_row_count` | 200 vs 20 000 rows, second-open time ratio must be < 5× | belt-and-suspenders; too small to feel a scan on its own | | Live signal | `plugins/context_engine/__init__.py` `PHASE=context_engine_load_slow` | any engine load that holds or waits on `_LOAD_LOCK` ≥ `HERMES_ENGINE_LOAD_SLOW_S` (5 s) logs one WARNING naming held/waited seconds and pointing here | — (observability, not a gate) | @@ -38,6 +118,31 @@ slowest surviving statement is a 67 ms FTS block write. `/tmp/lcm-init-trace.py` wrap `sqlite3.connect` with `set_trace_callback`, open `MessageStore(db_path=)`, sort by inter-statement wall time. +## Health checks that are O(rows) — the throttled lane (freeze #3) + +5. **A periodic health check is not a startup check either.** The FTS row-count parity check + (`_fts_count_parity_mismatch`: `COUNT(*) FROM ` + `COUNT(*) FROM _docsize`) + is O(rows) — measured 13.4 s of a 17.9 s cold `MessageStore()` init on an APFS clone of the + fleet DB. Until 2026-09-24 it lived inside `_fts_needs_rebuild_structural` and ran on **every** + `MessageStore`/`SummaryDAG` construction under `_LOAD_LOCK`. Now: + - the load path (`throttle=True`) runs only the O(schema) structural check; + - parity is due at most once per `LCM_FTS_PARITY_CHECK_INTERVAL_HOURS` (default **6 h**; `0` = + every startup but still in the background; `<0` = never on startup), tracked by the + `metadata` key `fts_parity_checked_at:`; + - when due it is dispatched to the same daemon thread as the deep integrity-check (own + connection, never under `_LOAD_LOCK`); a mismatch is recorded as the integrity-failed flag + for `/lcm doctor`, **not** rebuilt inline; + - the two COUNTs are read in one deferred transaction (one WAL snapshot). As two autocommit + reads, a concurrent ingest between them gave a false mismatch 15/300 times (5 %), and each + one triggered a full inline FTS rebuild (13 min + 6.5 min under `_LOAD_LOCK` on 2026-09-24); + - explicit `/lcm doctor repair apply` (`throttle=False`) still runs parity + deep check + synchronously. +6. **Per-session-start work is on the same critical path.** The empty-lifecycle GC + (`LifecycleStateStore.prune_empty_sessions`) no longer holds `BEGIN IMMEDIATE` across two + `SELECT DISTINCT session_id` full scans. It uses indexed per-session probes, takes the write + lock only when there is something to delete, and runs at most once per + `empty_lifecycle_gc_interval_hours` (default 6 h) per process. + ## Adding a new column with a legacy backfill — the recipe ```python @@ -67,4 +172,10 @@ Then run `tests/context_engine/test_lcm_backfill_cost.py` and - Incident 1: 2026-09-22 11:30–11:51 PDT, `search_content` scan, PR #887 (`d8b2d2448`). - Incident 2: 2026-09-22 20:56–21:20 and 21:28–21:38 PDT, `ingested_at` scan, PR #902 (`4964ea051`). -- Regression layer + slow-load signal: this PR. +- Regression layer + slow-load signal: PR #903 (`4806d08c8`). Its plan check exempted + `USING COVERING INDEX` and skipped every `messages_fts*` statement, so it passed on the freeze #3 code. +- Incident 3: 2026-09-24, FTS parity `COUNT(*)` on every load (card t_d3963974). 163× + `PHASE=context_engine_load_slow`, held 49–64 s, waited up to 120 s, and two false-mismatch + inline rebuilds (held 779.8 s). The count was introduced by the original vendor import + `8b869633a4` (2026-06-16, `_fts_needs_rebuild_structural`). It was carried unchanged through + re-vendor `27b617846e` and was not touched by #887/#902/#903. The DB grew until the count mattered. diff --git a/plugins/context_engine/lcm/config.py b/plugins/context_engine/lcm/config.py index b38064deeac93..9883e2793ff54 100644 --- a/plugins/context_engine/lcm/config.py +++ b/plugins/context_engine/lcm/config.py @@ -484,6 +484,7 @@ class _EnvFieldSpec: _EnvFieldSpec("doctor_clean_apply_enabled", "LCM_DOCTOR_CLEAN_APPLY_ENABLED", bool), _EnvFieldSpec("empty_lifecycle_gc_enabled", "LCM_EMPTY_LIFECYCLE_GC_ENABLED", bool), _EnvFieldSpec("empty_lifecycle_gc_threshold", "LCM_EMPTY_LIFECYCLE_GC_THRESHOLD", int), + _EnvFieldSpec("empty_lifecycle_gc_interval_hours", "LCM_EMPTY_LIFECYCLE_GC_INTERVAL_HOURS", float), _EnvFieldSpec("temporal_rollups_enabled", "LCM_TEMPORAL_ROLLUPS_ENABLED", bool), _EnvFieldSpec("rollup_daily_target_tokens", "LCM_ROLLUP_DAILY_TARGET_TOKENS", int), _EnvFieldSpec("rollup_daily_max_tokens", "LCM_ROLLUP_DAILY_MAX_TOKENS", int), @@ -904,6 +905,9 @@ class LCMConfig: # ingested its first message yet. Set to 0 only in trusted/test # environments that intentionally want immediate empty-row pruning. empty_lifecycle_gc_max_age_hours: float | None = 24.0 + # Minimum hours between GC passes per process (in-memory throttle). The + # pass runs from on_session_start on every agent init; <= 0 runs every time. + empty_lifecycle_gc_interval_hours: float = 6.0 # -- Temporal rollups --- # Disabled by default; the engine's ingest/build hooks are flag-gated. diff --git a/plugins/context_engine/lcm/db_bootstrap.py b/plugins/context_engine/lcm/db_bootstrap.py index b2253783140bd..428cd820e812c 100644 --- a/plugins/context_engine/lcm/db_bootstrap.py +++ b/plugins/context_engine/lcm/db_bootstrap.py @@ -2416,27 +2416,135 @@ def _fts_needs_rebuild_structural(conn: sqlite3.Connection, spec: ExternalConten column_names = {row[1] for row in columns if len(row) > 1} if spec.indexed_column not in column_names: return True - - content_count = conn.execute( - f"SELECT COUNT(*) FROM {quote_sql_identifier(spec.content_table)}" - ).fetchone()[0] - # For an external-content FTS5 table, ``COUNT(*) FROM `` reads - # through to the content table (so it can never reveal a lagging index) - # and is O(index size). The ``_docsize`` shadow table holds the - # true indexed-document count and is a cheap ordinary-table count. Its - # existence is already guaranteed by the shadow-table check above. - docsize_table = f"{spec.table_name}_docsize" - fts_count = conn.execute( - f"SELECT COUNT(*) FROM {quote_sql_identifier(docsize_table)}" - ).fetchone()[0] - if int(content_count or 0) != int(fts_count or 0): - return True except sqlite3.DatabaseError: return True return False +def _fts_count_parity_mismatch(conn: sqlite3.Connection, spec: ExternalContentFtsSpec) -> bool: + """True when the content table and the FTS index disagree on row count. + + O(rows): ``COUNT(*)`` on the content table is a full traversal (SQLite + answers it from the smallest covering index, which is still a scan of every + row — 2.5 M rows / 11 s cold on the fleet's largest DB), and the + ``_docsize`` shadow count is a second full table scan. NEVER call this + on the engine-load path: until 2026-09-24 it ran inside + ``_fts_needs_rebuild_structural`` on every ``MessageStore``/``SummaryDAG`` + construction, under ``plugins.context_engine._LOAD_LOCK`` — the third + Apollo boot-cost freeze (fork PR for card t_d3963974). It belongs to the + throttled parity lane (``_should_run_parity_check``, background thread) and + to explicit ``/lcm doctor`` paths only. + """ + # Both counts MUST come from one read snapshot. Issued as two autocommit + # statements, any ingest committing between them (the FTS insert trigger + # runs inside the ingest's own transaction, so the pair is always + # consistent at any single instant) made the counts differ — measured + # 15/300 calls (5 %) under a concurrent writer — and the caller answered + # with a FULL index rebuild: 13 min + 6.5 min on the fleet DB on + # 2026-09-24, holding _LOAD_LOCK and the SQLite write lock, up to 12 turns + # queued, every ingest failing "database is locked". A restart burst + # (many concurrent loads + ingests) made at least one such false rebuild + # near-certain. Wrapping the pair in a deferred transaction pins one WAL + # snapshot for both reads without taking the write lock. + opened_txn = False + try: + if not conn.in_transaction: + conn.execute("BEGIN") + opened_txn = True + try: + content_count = conn.execute( + f"SELECT COUNT(*) FROM {quote_sql_identifier(spec.content_table)}" + ).fetchone()[0] + # For an external-content FTS5 table, ``COUNT(*) FROM `` reads + # through to the content table (so it can never reveal a lagging + # index) and is O(index size). The ``_docsize`` shadow table + # holds the true indexed-document count. Its existence is + # guaranteed by the structural check callers run first. + docsize_table = f"{spec.table_name}_docsize" + fts_count = conn.execute( + f"SELECT COUNT(*) FROM {quote_sql_identifier(docsize_table)}" + ).fetchone()[0] + finally: + if opened_txn: + conn.execute("COMMIT") + except sqlite3.DatabaseError: + return True + return int(content_count or 0) != int(fts_count or 0) + + +PARITY_CHECK_INTERVAL_ENV = "LCM_FTS_PARITY_CHECK_INTERVAL_HOURS" +DEFAULT_PARITY_CHECK_INTERVAL_HOURS = 6.0 + + +def _parity_check_interval_hours() -> float: + """Hours between startup-dispatched FTS row-count parity checks. + + ``0`` checks (in the background) on every startup; negative never checks on + startup (parity is still verified by explicit ``/lcm doctor`` paths). + """ + raw = os.environ.get(PARITY_CHECK_INTERVAL_ENV) + if raw is None: + return DEFAULT_PARITY_CHECK_INTERVAL_HOURS + try: + value = float(raw) + except (TypeError, ValueError): + return DEFAULT_PARITY_CHECK_INTERVAL_HOURS + if not math.isfinite(value): + return DEFAULT_PARITY_CHECK_INTERVAL_HOURS + return value + + +def _parity_marker_key(spec: ExternalContentFtsSpec) -> str: + return f"fts_parity_checked_at:{spec.table_name}" + + +def _load_parity_checked_at( + conn: sqlite3.Connection, spec: ExternalContentFtsSpec +) -> float | None: + ensure_metadata_table(conn) + row = conn.execute( + "SELECT value FROM metadata WHERE key = ?", + (_parity_marker_key(spec),), + ).fetchone() + if not row or row[0] is None: + return None + try: + return float(row[0]) + except (TypeError, ValueError): + return None + + +def _record_parity_checked( + conn: sqlite3.Connection, spec: ExternalContentFtsSpec, *, now: float | None = None +) -> None: + ensure_metadata_table(conn) + current = time.time() if now is None else now + conn.execute( + """ + INSERT INTO metadata(key, value) + VALUES(?, ?) + ON CONFLICT(key) DO UPDATE SET value = excluded.value + """, + (_parity_marker_key(spec), str(current)), + ) + + +def _should_run_parity_check( + conn: sqlite3.Connection, spec: ExternalContentFtsSpec, *, now: float | None = None +) -> bool: + hours = _parity_check_interval_hours() + if hours == 0: + return True + if hours < 0: + return False + last = _load_parity_checked_at(conn, spec) + if last is None: + return True + current = time.time() if now is None else now + return (current - last) >= hours * 3600.0 + + INTEGRITY_CHECK_INTERVAL_ENV = "LCM_FTS_INTEGRITY_CHECK_INTERVAL_HOURS" DEFAULT_INTEGRITY_CHECK_INTERVAL_HOURS = 24.0 @@ -2649,7 +2757,7 @@ def _clear_scan_started( def _run_background_integrity_scan( - db_path: str, spec: ExternalContentFtsSpec, started_at: float + db_path: str, spec: ExternalContentFtsSpec, started_at: float, deep: bool = True ) -> None: """Daemon-thread body: deep-check ``spec`` on a private connection. @@ -2668,7 +2776,22 @@ def _run_background_integrity_scan( # detectable cross-process via the staleness window above. _record_scan_started(scan_conn, spec, now=started_at) scan_conn.commit() - result = check_external_content_fts_integrity(scan_conn, spec) + # Row-count parity (two O(rows) COUNTs) runs HERE, off the engine-load + # path, at most once per LCM_FTS_PARITY_CHECK_INTERVAL_HOURS. A + # mismatch is flagged for `/lcm doctor` exactly like a failed deep + # check; the deep FTS5 integrity-check itself only runs when ITS + # (longer) interval is due. + if _fts_needs_rebuild_structural(scan_conn, spec): + result = {"status": "fail", "detail": "structural repair needed"} + elif _fts_count_parity_mismatch(scan_conn, spec): + result = { + "status": "fail", + "detail": "content/index row-count mismatch (parity check)", + } + elif deep: + result = check_external_content_fts_integrity(scan_conn, spec) + else: + result = {"status": "parity_pass", "detail": ""} finally: scan_conn.close() @@ -2676,9 +2799,13 @@ def _run_background_integrity_scan( try: meta_conn.execute(f"PRAGMA busy_timeout={SQLITE_BUSY_TIMEOUT_MS}") status = result.get("status") + if status in ("pass", "parity_pass", "fail"): + _record_parity_checked(meta_conn, spec, now=started_at) if status == "pass": _record_integrity_checked(meta_conn, spec, now=started_at) _clear_integrity_failed(meta_conn, spec) + elif status == "parity_pass": + _clear_integrity_failed(meta_conn, spec) elif status == "fail": _record_integrity_failed( meta_conn, spec, detail=result.get("detail", ""), now=started_at @@ -2714,8 +2841,19 @@ def _run_background_integrity_scan( _integrity_scan_threads.pop(key, None) +# The cross-process claim stamp below is best-effort. It is written from the +# engine-load path, so it must never sit behind another writer for the full +# SQLITE_BUSY_TIMEOUT_MS (30 s): a held write lock (a deep scan in flight, an +# ingest batch) would turn one dispatch into a 30 s stall under _LOAD_LOCK. +INTEGRITY_CLAIM_BUSY_TIMEOUT_MS = 1_000 + + def _dispatch_background_integrity_scan( - conn: sqlite3.Connection, spec: ExternalContentFtsSpec, *, now: float | None = None + conn: sqlite3.Connection, + spec: ExternalContentFtsSpec, + *, + now: float | None = None, + deep: bool = True, ) -> bool: """Try to run the deep FTS integrity-check on a daemon thread. @@ -2746,13 +2884,13 @@ def _dispatch_background_integrity_scan( # no stamp and dispatch a duplicate deep scan (F6). Writing the stamp here # under BEGIN IMMEDIATE closes that window; best-effort (a transient lock # just falls back to the thread's own stamp). - claim_timeout = SQLITE_BUSY_TIMEOUT_MS / 1000.0 + claim_timeout = INTEGRITY_CLAIM_BUSY_TIMEOUT_MS / 1000.0 try: claim_conn = sqlite3.connect( db_path, timeout=claim_timeout, check_same_thread=False ) try: - claim_conn.execute(f"PRAGMA busy_timeout={SQLITE_BUSY_TIMEOUT_MS}") + claim_conn.execute(f"PRAGMA busy_timeout={INTEGRITY_CLAIM_BUSY_TIMEOUT_MS}") claim_conn.execute("BEGIN IMMEDIATE") _record_scan_started(claim_conn, spec, now=current) claim_conn.commit() @@ -2763,7 +2901,7 @@ def _dispatch_background_integrity_scan( thread = threading.Thread( target=_run_background_integrity_scan, - args=(db_path, spec, current), + args=(db_path, spec, current, deep), name=f"lcm-fts-integrity-{spec.table_name}", daemon=True, ) @@ -2792,21 +2930,40 @@ def _fts_needs_rebuild( ) -> bool: if _fts_needs_rebuild_structural(conn, spec): return True - # Structurally sound: the FTS5 integrity-check is O(index size) and was the - # dominant startup cost on large databases (issue #235). On the startup path - # (``throttle=True``) skip it when already checked within the interval. - # Explicit repair (e.g. ``/lcm doctor repair apply``) uses ``throttle=False`` - # so it always runs the deep check and can fix same-row-count drift that the - # structural checks cannot see. - if throttle and not _should_run_integrity_check(conn, spec, now=now): + if not throttle: + # Explicit repair (``/lcm doctor repair apply``): full synchronous + # verification — row-count parity, then the deep FTS5 integrity-check + # that can also see same-row-count drift. + if _fts_count_parity_mismatch(conn, spec): + _record_parity_checked(conn, spec, now=now) + return True + _record_parity_checked(conn, spec, now=now) + result = check_external_content_fts_integrity(conn, spec) + if result["status"] == "pass": + _record_integrity_checked(conn, spec, now=now) + return result["status"] == "fail" + + # Startup path (every engine load, under plugins.context_engine._LOAD_LOCK). + # Nothing here may cost O(rows): the structural check above is the only + # synchronous verification. Both O(rows) checks — the row-count parity + # (two full COUNTs; this ran on EVERY load until 2026-09-24, freeze #3) and + # the O(index) deep integrity-check (issue #235) — are throttled by their own + # markers and, when due, handed to a background thread that opens its own + # connection (issue #6). Findings are flagged in metadata for `/lcm doctor`. + parity_due = _should_run_parity_check(conn, spec, now=now) + deep_due = _should_run_integrity_check(conn, spec, now=now) + if not parity_due and not deep_due: return False - # The deep check is due. On the startup path, dispatch it to a background - # thread so the bind returns immediately (issue #6); the scan flags any - # corruption via metadata rather than rebuilding here. The kill-switch and - # non-file DBs fall back to the exact old synchronous behavior below. - if throttle and _background_integrity_enabled(): - if _dispatch_background_integrity_scan(conn, spec, now=now): + if _background_integrity_enabled(): + if _dispatch_background_integrity_scan(conn, spec, now=now, deep=deep_due): return False + # Kill-switch / non-file DB: synchronous fallback, still marker-throttled. + if _fts_count_parity_mismatch(conn, spec): + _record_parity_checked(conn, spec, now=now) + return True + _record_parity_checked(conn, spec, now=now) + if not deep_due: + return False result = check_external_content_fts_integrity(conn, spec) if result["status"] == "pass": _record_integrity_checked(conn, spec, now=now) @@ -2844,7 +3001,7 @@ def check_external_content_fts_integrity( behind on the shared connection. """ - if _fts_needs_rebuild_structural(conn, spec): + if _fts_needs_rebuild_structural(conn, spec) or _fts_count_parity_mismatch(conn, spec): return {"status": "fail", "detail": "structural repair needed"} savepoint = f"lcm_fts_integrity_{spec.table_name}" @@ -2976,8 +3133,13 @@ def _fts_stale_triggers(conn: sqlite3.Connection, spec: ExternalContentFtsSpec) def external_content_fts_needs_repair(conn: sqlite3.Connection, spec: ExternalContentFtsSpec) -> bool: + """Diagnostic (``/lcm doctor``) view: structure, row-count parity, triggers. + + O(rows) because of the parity count — never call from the engine-load path. + """ return ( _fts_needs_rebuild_structural(conn, spec) + or _fts_count_parity_mismatch(conn, spec) or _fts_missing_triggers(conn, spec) or _fts_stale_triggers(conn, spec) ) @@ -3042,7 +3204,15 @@ def repair_external_content_fts( # it in the SAME transaction that commits the rebuild so `/lcm doctor` stops # reporting issues-found (and the next self-healing scan is not pushed out a # full interval). Without this an explicit `repair apply` left the flag stuck. - _clear_integrity_failed(conn, spec) + # ONLY when something was actually repaired: a no-op pass (every ordinary + # engine load) must issue no write — an unconditional DELETE here needed the + # SQLite write lock on every load and sat behind any in-flight writer (deep + # integrity scan: measured 139 s holding RESERVED on the fleet DB; lifecycle + # GC scan under BEGIN IMMEDIATE) for up to busy_timeout — and it silently + # erased the background scan's corruption flag before `/lcm doctor` could + # ever show it. + if rebuilt or triggers_were_missing or triggers_were_stale: + _clear_integrity_failed(conn, spec) conn.commit() return { "rebuilt": rebuilt, @@ -3131,6 +3301,11 @@ def run_versioned_migrations(conn: sqlite3.Connection) -> None: # and idempotently under a NAMED marker so it can't collide. The columns are # additive ALTER TABLE ADD COLUMN, ignored by older readers. ensure_messages_dedup_columns(conn) - mark_migration_step_complete(conn, "messages_dedup_v1") - - set_schema_version(conn, current_version) + # Marker-gated: an unconditional upsert here took the write lock on every + # MessageStore/SummaryDAG/LifecycleStateStore construction (three per engine + # load), each able to stall for busy_timeout behind any concurrent writer. + if not is_migration_step_complete(conn, "messages_dedup_v1"): + mark_migration_step_complete(conn, "messages_dedup_v1") + + if get_schema_version(conn) != current_version: + set_schema_version(conn, current_version) diff --git a/plugins/context_engine/lcm/engine.py b/plugins/context_engine/lcm/engine.py index 41a6c8e9411ff..aa2f40a7a830a 100644 --- a/plugins/context_engine/lcm/engine.py +++ b/plugins/context_engine/lcm/engine.py @@ -458,6 +458,27 @@ def _merge_adjacent_assistant_messages( return collapsed +# Per-process throttle for the empty-lifecycle GC pass (keyed by DB path). The +# pass is bounded now (indexed probes), but it still walks every lifecycle row +# and runs from on_session_start on EVERY agent init; once per interval per +# process is plenty for garbage that accumulates over days. In-process on +# purpose: a durable marker would itself be a write on the session-start path. +_LIFECYCLE_GC_LAST_RUN: dict[str, float] = {} +_LIFECYCLE_GC_LOCK = threading.Lock() + + +def _lifecycle_gc_due(db_path: str, interval_hours: float) -> bool: + if interval_hours <= 0: + return True + now = time.time() + with _LIFECYCLE_GC_LOCK: + last = _LIFECYCLE_GC_LAST_RUN.get(db_path) + if last is not None and (now - last) < interval_hours * 3600.0: + return False + _LIFECYCLE_GC_LAST_RUN[db_path] = now + return True + + class LCMEngine(CompactionMixin, ResetStateMixin, ReconcileMixin, AuxiliarySessionMixin, PlaceholderLedgerMixin, BypassMixin, ContextEngine): """Lossless Context Management engine. @@ -2644,6 +2665,10 @@ def _bind_lifecycle_state( # don't accumulate forever. if ( self._config.empty_lifecycle_gc_enabled + and _lifecycle_gc_due( + str(getattr(self._lifecycle, "db_path", "")), + self._config.empty_lifecycle_gc_interval_hours, + ) and self._lifecycle.row_count() > self._config.empty_lifecycle_gc_threshold ): protected = {str(self._session_id)} if self._session_id else None diff --git a/plugins/context_engine/lcm/lifecycle_state.py b/plugins/context_engine/lcm/lifecycle_state.py index 282ed482643f6..8f1d58d1edaf8 100644 --- a/plugins/context_engine/lcm/lifecycle_state.py +++ b/plugins/context_engine/lcm/lifecycle_state.py @@ -720,83 +720,83 @@ def prune_empty_sessions( assert conn is not None protected = {str(s) for s in (protected_session_ids or ()) if s} - conn.execute("BEGIN IMMEDIATE") - try: - sessions_with_data: set[str] = set() - tables = { - row[0] for row in conn.execute( - "SELECT name FROM sqlite_master WHERE type='table'" - ).fetchall() - } + # Cost contract (fork, 2026-09-24, Apollo freeze #3): this runs from + # ``on_session_start`` on EVERY agent init once the table passes the GC + # threshold (fleet: 11 108 rows vs threshold 200 — i.e. always). It used + # to open ``BEGIN IMMEDIATE`` and then snapshot ``SELECT DISTINCT + # session_id FROM messages`` / ``summary_nodes`` — two full traversals + # of a 2.5 M-row table while HOLDING the SQLite write lock, so every + # engine load's own writes queued behind it (py-spy: 16/31 samples had a + # thread parked here). Now: candidates are found with cheap in-memory + # filters plus per-session INDEXED probes (``WHERE session_id = ? + # LIMIT 1``), outside any write transaction; the write lock is taken + # only when there is at least one row to delete, and each candidate is + # re-probed inside it before the DELETE. + tables = { + row[0] for row in conn.execute( + "SELECT name FROM sqlite_master WHERE type='table'" + ).fetchall() + } - def _session_has_data(session_id: str) -> bool: - if not session_id: - return False - if "messages" in tables and conn.execute( - "SELECT 1 FROM messages WHERE session_id = ? LIMIT 1", - (session_id,), - ).fetchone(): - return True - if "summary_nodes" in tables and conn.execute( - "SELECT 1 FROM summary_nodes WHERE session_id = ? LIMIT 1", - (session_id,), - ).fetchone(): - return True + def _session_has_data(session_id: str) -> bool: + if not session_id: return False + if "messages" in tables and conn.execute( + "SELECT 1 FROM messages WHERE session_id = ? LIMIT 1", + (session_id,), + ).fetchone(): + return True + if "summary_nodes" in tables and conn.execute( + "SELECT 1 FROM summary_nodes WHERE session_id = ? LIMIT 1", + (session_id,), + ).fetchone(): + return True + return False - if "messages" in tables: - for row in conn.execute( - "SELECT DISTINCT session_id FROM messages" - ).fetchall(): - sessions_with_data.add(str(row[0])) - if "summary_nodes" in tables: - for row in conn.execute( - "SELECT DISTINCT session_id FROM summary_nodes" - ).fetchall(): - sessions_with_data.add(str(row[0])) - - now = time.time() - max_age_seconds = ( - float(max_age_hours) * 3600.0 - if max_age_hours is not None - else None - ) - deleted = 0 - - rows = conn.execute( - "SELECT * FROM lcm_lifecycle_state" - ).fetchall() - for row in rows: - cur = str(row["current_session_id"] or "") - fin = str(row["last_finalized_session_id"] or "") - - if ((cur and cur in sessions_with_data) - or (fin and fin in sessions_with_data)): - continue + now = time.time() + max_age_seconds = ( + float(max_age_hours) * 3600.0 + if max_age_hours is not None + else None + ) - refs = {r for r in (cur, fin) if r} - if refs & protected: + candidates: list[tuple[str, str, str]] = [] + rows = conn.execute( + "SELECT conversation_id, current_session_id, last_finalized_session_id, " + "current_bound_at, last_finalized_at, updated_at FROM lcm_lifecycle_state" + ).fetchall() + for row in rows: + cur = str(row["current_session_id"] or "") + fin = str(row["last_finalized_session_id"] or "") + refs = {r for r in (cur, fin) if r} + if refs.intersection(protected): + continue + if max_age_seconds is not None: + row_age = ( + row["current_bound_at"] + or row["last_finalized_at"] + or row["updated_at"] + ) + if row_age is not None and (now - float(row_age)) < max_age_seconds: continue + if _session_has_data(cur) or _session_has_data(fin): + continue + candidates.append((str(row["conversation_id"]), cur, fin)) - if max_age_seconds is not None: - row_age = ( - row["current_bound_at"] - or row["last_finalized_at"] - or row["updated_at"] - ) - if row_age is not None and (now - float(row_age)) < max_age_seconds: - continue + if not candidates: + return 0 - # Recheck against the tables right before deletion. BEGIN - # IMMEDIATE blocks concurrent writers while this transaction is - # open; this fresh query also keeps the safety check honest if - # the broad snapshot logic above changes later. + deleted = 0 + conn.execute("BEGIN IMMEDIATE") + try: + for conversation_id, cur, fin in candidates: + # Recheck under the write lock: an ingest may have landed for + # this session between the read-only pass and now. if _session_has_data(cur) or _session_has_data(fin): continue - conn.execute( "DELETE FROM lcm_lifecycle_state WHERE conversation_id = ?", - (row["conversation_id"],), + (conversation_id,), ) deleted += 1 diff --git a/plugins/context_engine/lcm/store.py b/plugins/context_engine/lcm/store.py index 7b567b5e9e9af..99b031483f88f 100644 --- a/plugins/context_engine/lcm/store.py +++ b/plugins/context_engine/lcm/store.py @@ -490,6 +490,16 @@ def _backfill_search_content(self) -> None: search_content = _index_safe_text(plain_content, self._ingest_protection_config) except RuntimeError: search_content = None + if search_content is None: + # Undecryptable row: search_content is ALREADY NULL. Writing + # NULL over NULL is a no-op for the row but fires + # ``msg_fts_update`` (delete + re-insert into the FTS5 + # index). On the fleet DB (3 such rows, 2.5 M-doc index) + # that trigger write cost 4-57 s per boot holding the + # write lock — on EVERY engine load, since the rows stay + # NULL forever. Leave them alone; the loop's no-progress + # guard below terminates the pass. + continue try: self._conn.execute( "UPDATE messages SET search_content = ? WHERE store_id = ?", diff --git a/tests/context_engine/test_lcm_init_cost_regression.py b/tests/context_engine/test_lcm_init_cost_regression.py index ddfb748cd7817..afc114cd527ff 100644 --- a/tests/context_engine/test_lcm_init_cost_regression.py +++ b/tests/context_engine/test_lcm_init_cost_regression.py @@ -1,27 +1,67 @@ -"""REGRESSION: MessageStore init cost must not scale with the number of rows. +"""REGRESSION: LCM engine load / session-start cost must not scale with row count. -Both 2026-09-22 Apollo freezes were one-time backfills that re-scanned the whole -`messages` table on every boot (search_content: no index on the NULL predicate; -ingested_at: no done-marker). Each one was invisible to the unit suite because -fixtures have ten rows. This test builds a store with N rows and asserts that -opening it a SECOND time performs no statement whose cost is proportional to N — -measured two ways so the verdict does not depend on wall clock: +Three Apollo freezes in three days, all the same class — something on the +engine-load path (``plugins/context_engine/__init__.py::_LOAD_LOCK``, every +turn's ``init_agent`` waits on it) or the per-agent session-start path cost +O(rows) of a 2.5 M-row / 11 GB ``messages`` table, and fixtures with ten rows +could not see it: - 1. Trace every statement the reopen issues and EXPLAIN it: refuse any plan that - is a bare `SCAN messages` without `USING INDEX`. - 2. A ratio: init time at N=20 000 vs N=200 must be < 5x (a scan would be ~100x). + 1. 2026-09-22 search_content backfill probe: no index on the NULL predicate (#887). + 2. 2026-09-22 ingested_at backfill: no done-marker (#902). + 3. 2026-09-24 FTS row-count parity: ``SELECT COUNT(*) FROM messages`` + + ``COUNT(*) FROM messages_fts_docsize`` on EVERY load, inside + ``_fts_needs_rebuild_structural`` (card t_d3963974). The previous revision + of THIS test whitelisted ``USING COVERING INDEX`` and skipped every + ``messages_fts*`` statement — it was green on the exact code that froze + Apollo. Plus two write-lock amplifiers on the same paths: three + unconditional metadata upserts per load, and the lifecycle GC holding + ``BEGIN IMMEDIATE`` across two ``SELECT DISTINCT session_id`` full scans on + every session start. + +This test builds a store with N rows, then traces EVERYTHING a steady-state +engine construction + ``on_session_start`` issues and asserts, independently of +wall clock: + + 1. Query plan: no statement may traverse ``messages``, ``messages_fts*`` or + ``summary_nodes`` — ANY ``SCAN`` of those tables is a finding, covering + index or not (a covering-index COUNT still touches every row), unless the + statement is row-bounded by a ``LIMIT`` clause. + 2. Write lock: engine construction (the part under ``_LOAD_LOCK``) must + succeed while ANOTHER connection holds the SQLite write lock, with a zero + busy timeout — i.e. a no-op open issues no write and can never queue + behind an in-flight writer. + 3. A background-scan corruption flag survives an ordinary open (the old + unconditional ``_clear_integrity_failed`` erased it on every load). + 4. Scale ratio: 200 vs 20 000 rows, second-open time must be < 5x. Plus the source-contract lint (test_lcm_backfill_cost.py) that refuses any -unbounded, unmarked UPDATE/DELETE on the init path at all. Three layers because -two independent instances of this class shipped in one day. +unbounded, unmarked UPDATE/DELETE on the init path at all. """ from __future__ import annotations +import re import sqlite3 +import threading import time from pathlib import Path +from typing import cast + +import pytest + +from plugins.context_engine.lcm import db_bootstrap +from plugins.context_engine.lcm.config import LCMConfig +from plugins.context_engine.lcm.engine import LCMEngine +from plugins.context_engine.lcm.lifecycle_state import LifecycleStateStore +from plugins.context_engine.lcm.store import MessageStore, build_message_fts_spec -from plugins.context_engine.lcm.store import MessageStore +# Any full traversal of one of these tables on a per-load / per-session-start +# path is the freeze class. Both EXPLAIN output dialects are matched +# ("SCAN messages ..." on SQLite >= 3.36, "SCAN TABLE messages ..." before). +_GUARDED_TABLES = ("messages", "messages_fts", "summary_nodes", "nodes_fts") +_SCAN_RE = re.compile( + r"\bSCAN (?:TABLE )?(?:%s)(?:_\w+)?\b" % "|".join(_GUARDED_TABLES), re.IGNORECASE +) +_LIFECYCLE_ROWS = 250 # > LCMConfig.empty_lifecycle_gc_threshold (200): GC fires def _fill(db: Path, n: int) -> None: @@ -37,68 +77,211 @@ def _fill(db: Path, n: int) -> None: ) conn.commit() conn.close() + lifecycle = LifecycleStateStore(db) + for i in range(_LIFECYCLE_ROWS): + lifecycle.bind_session("empty-%d" % i, conversation_id="conv-%d" % i) + lifecycle.close() -def _traced_reopen(db: Path) -> tuple[float, list[str], MessageStore]: - """Reopen the store with a trace hook; return (seconds, [sql...], store). +def _close(engine: LCMEngine) -> None: + engine._close_storage() + + +def _engine(db: Path) -> LCMEngine: + return LCMEngine( + config=LCMConfig(database_path=str(db)), + hermes_home=str(db.parent), + ) - The STORE is returned (not its connection) so the caller keeps it alive: - an earlier revision returned `st._conn`, the store was garbage-collected, - the connection closed, and every EXPLAIN raised sqlite3.Error into a - `continue` — the check passed on the exact code that froze Apollo. + +def _traced_reopen(db: Path) -> tuple[float, list[str], LCMEngine]: + """Construct a fresh engine + bind a session with a trace hook. + + Returns (seconds, [sql...], engine). The ENGINE is returned (not a + connection) so the caller keeps it alive: an earlier revision returned + `st._conn`, the store was garbage-collected, the connection closed, and + every EXPLAIN raised sqlite3.Error into a `continue` — the check passed on + the exact code that froze Apollo. """ seen: list[str] = [] real_connect = sqlite3.connect + caller = threading.get_ident() def connect(*a, **k): c = real_connect(*a, **k) - c.set_trace_callback(lambda sql: seen.append(" ".join(sql.split()))) + + def trace(sql: str) -> None: + # Only statements issued on the LOADING thread count: that is the + # thread holding _LOAD_LOCK / running init_agent. Work the engine + # hands to its own background threads (the throttled FTS parity + + # integrity lane, which opens a private connection) is the fix, not + # the bug — it is joined below so it cannot leak into a later test. + if threading.get_ident() == caller: + seen.append(" ".join(sql.split())) + + c.set_trace_callback(trace) return c sqlite3.connect = connect try: t0 = time.perf_counter() - st = MessageStore(db_path=str(db)) + engine = _engine(db) + engine.on_session_start("probe-session", platform="cli") dt = time.perf_counter() - t0 - assert st._conn is not None - return dt, seen, st + return dt, seen, engine finally: sqlite3.connect = real_connect + db_bootstrap.join_background_integrity_scans(timeout=30.0) -def _plans_that_scan_messages(db: Path, sqls: list[str]) -> list[str]: - """Every statement in `sqls` that reads/writes `messages` via a full SCAN. +def _plans_that_scan_guarded_tables(db: Path, sqls: list[str]) -> list[str]: + """Every statement in `sqls` whose plan traverses a guarded table. EXPLAINs on a FRESH connection to the same file. A statement that cannot be explained is reported as a finding, never skipped — a probe that skips on - error is a probe that passes on the bug. + error is a probe that passes on the bug. ``USING COVERING INDEX`` is NOT an + exemption: ``SELECT COUNT(*) FROM messages`` plans as a covering-index scan + and still reads all 2.5 M rows (11 s cold on the fleet DB). The only + exemption is a row-bounded statement (a ``LIMIT`` clause), e.g. the O(1) + partial-index presence probe ``SELECT 1 FROM messages WHERE search_content + IS NULL LIMIT 1``. """ bad = [] conn = sqlite3.connect(str(db)) for sql in sqls: head = sql.split(" ", 1)[0].upper() - if head not in ("SELECT", "UPDATE", "DELETE") or " messages" not in sql.lower(): + if head not in ("SELECT", "UPDATE", "DELETE", "INSERT", "REPLACE"): + continue + lowered = sql.lower() + if not any(t in lowered for t in _GUARDED_TABLES): continue - if "sqlite_master" in sql or "lcm_migration_state" in sql or "messages_fts" in sql: + if "sqlite_master" in lowered or "lcm_migration_state" in lowered: continue + if sql.startswith("--"): + continue # FTS5-internal shadow statements echoed by the trace hook try: plan = " | ".join(r[3] for r in conn.execute("EXPLAIN QUERY PLAN " + sql).fetchall()) except sqlite3.Error as exc: - bad.append(f"{sql[:90]} -> COULD NOT EXPLAIN ({exc})") + bad.append(f"{sql[:100]} -> COULD NOT EXPLAIN ({exc})") continue - if "SCAN messages" in plan and "USING INDEX" not in plan and "USING COVERING INDEX" not in plan: - bad.append(f"{sql[:90]} -> {plan}") + if _SCAN_RE.search(plan) and " limit " not in lowered: + bad.append(f"{sql[:100]} -> {plan}") conn.close() return bad -def test_second_open_issues_no_full_scan_of_messages(tmp_path): +def test_second_open_issues_no_full_scan_of_guarded_tables(tmp_path): db = tmp_path / "lcm.db" _fill(db, 200) - _, sqls, st = _traced_reopen(db) - bad = _plans_that_scan_messages(db, sqls) - del st - assert not bad, "init path full-scans `messages` (this is the Apollo-freeze class):\n" + "\n".join(bad) + _, sqls, engine = _traced_reopen(db) + bad = _plans_that_scan_guarded_tables(db, sqls) + _close(engine) + assert not bad, ( + "engine load / session start full-scans a guarded table (the Apollo-freeze class):\n" + + "\n".join(bad) + ) + + +def test_engine_construction_needs_no_write_lock(tmp_path, monkeypatch): + """Steady-state engine construction must not need the SQLite write lock. + + Everything constructed here runs under ``_LOAD_LOCK`` on every turn. An + unconditional write (metadata DELETE / migration-marker upsert) queues + behind whoever holds the write lock — measured on the fleet DB: the + background FTS integrity-check holds it for 139 s, the old lifecycle GC for + the length of two full-table scans — and every turn waits with it. + """ + db = tmp_path / "lcm.db" + _fill(db, 200) + _close(_engine(db)) # first open may legitimately write markers; steady state is the second + real_connect = sqlite3.connect + + def connect(*a, **k): + k["timeout"] = 0.0 + return real_connect(*a, **k) + + monkeypatch.setattr(db_bootstrap, "SQLITE_BUSY_TIMEOUT_MS", 0) + monkeypatch.setattr(sqlite3, "connect", connect) + holder = real_connect(str(db), isolation_level=None) + holder.execute("BEGIN IMMEDIATE") + try: + try: + engine = _engine(db) + except sqlite3.OperationalError as exc: + pytest.fail( + f"engine construction needed the write lock (issued a write on the load path): {exc}" + ) + _close(engine) + finally: + holder.execute("ROLLBACK") + holder.close() + + +def test_ordinary_open_keeps_background_corruption_flag(tmp_path): + db = tmp_path / "lcm.db" + _fill(db, 200) + spec = build_message_fts_spec() + conn = sqlite3.connect(str(db)) + db_bootstrap._record_integrity_failed(conn, spec, detail="probe: index corrupt") + conn.commit() + conn.close() + st = MessageStore(db_path=str(db)) + assert st._conn is not None + flag = db_bootstrap.load_integrity_failed(st._conn, spec) + st.close() + assert flag is not None and "probe" in str(flag["detail"]), ( + "an ordinary (no-op) open erased the background scan's corruption flag" + ) + + +def test_concurrent_ingest_between_parity_counts_cannot_trigger_rebuild(tmp_path): + """The two parity reads must see one WAL snapshot, not two commits. + + On fork/main the first COUNT and the docsize COUNT are separate autocommit + statements. Force a real ingest/FTS-trigger commit between them; a false + mismatch returned True and the caller dropped+rebuilt the entire index + under _LOAD_LOCK. No mocked FTS, no timing race in the test. + """ + db = tmp_path / "lcm.db" + _fill(db, 200) + writer = sqlite3.connect(str(db)) + reader = sqlite3.connect(str(db)) + spec = build_message_fts_spec() + committed = False + + class InterleavedConnection: + def __init__(self, conn): + self._conn = conn + + @property + def in_transaction(self): + return self._conn.in_transaction + + def execute(self, sql, *args): + nonlocal committed + # Execute a genuine concurrent writer COMMIT after the first count + # has already completed and immediately before the second COUNT. + # A trace callback fires at statement start (too early), so it + # cannot prove the distinct-snapshot race. + if sql.strip().upper().startswith('SELECT COUNT(*) FROM "MESSAGES_FTS_DOCSIZE"'): + writer.execute( + "INSERT INTO messages(session_id, role, content, timestamp) " + "VALUES ('race', 'user', 'new turn', 1)" + ) + writer.commit() + committed = True + return self._conn.execute(sql, *args) + + try: + parity_check = getattr( + db_bootstrap, "_fts_count_parity_mismatch", db_bootstrap._fts_needs_rebuild_structural + ) + needs_rebuild = parity_check(cast(sqlite3.Connection, InterleavedConnection(reader)), spec) + assert committed, "probe never interleaved an ingest between the parity counts" + assert not needs_rebuild, "a concurrent valid FTS insert caused a false rebuild" + finally: + reader.close() + writer.close() def test_init_time_does_not_scale_with_row_count(tmp_path): @@ -107,10 +290,19 @@ def test_init_time_does_not_scale_with_row_count(tmp_path): _fill(small, 200) _fill(big, 20_000) # warm both once (first open may build indexes) then measure the steady-state second open - _traced_reopen(small) - _traced_reopen(big) - ts = min(_traced_reopen(small)[0] for _ in range(3)) - tb = min(_traced_reopen(big)[0] for _ in range(3)) + _close(_traced_reopen(small)[2]) + _close(_traced_reopen(big)[2]) + + def best(db): + times = [] + for _ in range(3): + dt, _, engine = _traced_reopen(db) + _close(engine) + times.append(dt) + return min(times) + + ts = best(small) + tb = best(big) ratio = tb / max(ts, 1e-4) # 100x rows; a full scan would be ~100x time. Healthy init is O(1) in rows. assert ratio < 5.0, f"init scales with row count: {ts:.4f}s @200 rows vs {tb:.4f}s @20000 rows (ratio {ratio:.1f}x)" From f40f21f4fe53e4d865911075315eb3924e855172 Mon Sep 17 00:00:00 2001 From: Kyzcreig <9063726+Kyzcreig@users.noreply.github.com> Date: Thu, 24 Sep 2026 03:29:44 -0700 Subject: [PATCH 6/7] fix(gateway): restart follow-ups keep adapter-granted admission; refused replays reported lost (t_43e058b7) Argus r8 N1 (t_e253d9d5): SessionSource.to_dict drops is_bot / role_authorized / delivered_via_upstream_relay / profile_route_rejected, so a spooled follow-up admitted only by ALLOW_BOTS, ALLOWED_ROLES or the relay was refused as "Unauthorized user" on boot replay, its spool file acked, and restart_followup_lost logged 0 lines. Trust model: to_dict stays wire-safe (unchanged). The spool record carries the flags in a separate `admission` block and the whole record is HMAC-SHA256'd with a per-home 0600 key (/gateway/restart_followups.key). On load the flags are restored only if the MAC verifies; otherwise no trust flag is restored (only fail-closed profile_route_rejected is honoured) and PHASE=restart_followup_untrusted is logged. Live policy is still re-evaluated by the normal intake. A replay the intake refuses (unauthorized / profile_route_rejected) now logs PHASE=restart_followup_lost with reason. MF (same review): AST contract that the post-turn draining site spools pending_event itself, not None. Verified: new real stop->boot e2e (human/bot/role/relay, forged, tampered, gate-closed-during-restart, to_dict class guard) 8/8; on base 3 admission arms fail, human control passes. Focused restart suites 49/49. Mutants: MAC unchecked, refusal unreported, admission unrestored, MF pending_event=None all KILLED. Argus probe_r8_source_authz_real_intake: B/R PRESERVED, CONTROL ok. Session/authz/startup-restore suites 445 passed. --- gateway/fork_ext/restart_followups.py | 100 +++++++ gateway/run.py | 46 +++- gateway/session.py | 3 + .../test_restart_followups_admission_e2e.py | 259 ++++++++++++++++++ ...test_restart_interrupt_intent_followups.py | 26 ++ 5 files changed, 431 insertions(+), 3 deletions(-) create mode 100644 tests/gateway/test_restart_followups_admission_e2e.py diff --git a/gateway/fork_ext/restart_followups.py b/gateway/fork_ext/restart_followups.py index b94a969b27432..3a1b68d27aef3 100644 --- a/gateway/fork_ext/restart_followups.py +++ b/gateway/fork_ext/restart_followups.py @@ -20,9 +20,12 @@ from __future__ import annotations +import hashlib +import hmac import json import logging import os +import secrets import time import uuid from pathlib import Path @@ -60,6 +63,88 @@ def spool_dir(home: Optional[Path] = None) -> Path: } +# SessionSource admission signals that ``SessionSource.to_dict`` deliberately +# does NOT serialise (t_43e058b7). Without them a follow-up admitted only by an +# adapter-granted flag (``{PLATFORM}_ALLOW_BOTS`` -> ``is_bot``, +# ``DISCORD_ALLOWED_ROLES`` -> ``role_authorized``, the authenticated relay -> +# ``delivered_via_upstream_relay``) is refused as "Unauthorized user" on replay. +# +# Trust model. ``to_dict`` stays wire-safe (a peer or a persisted session row +# must never be able to assert these). The restart spool instead records the +# transport's verdict in a separate ``admission`` block and binds the WHOLE +# record with an HMAC keyed by a per-home secret (``SPOOL_KEY_NAME``, 0600, +# created by the gateway itself). On load: +# * MAC verifies -> the admission flags are restored exactly as parked; +# the live policy (ALLOW_BOTS / ALLOWED_ROLES / relay adapter) is still +# re-evaluated by the normal intake, so a gate closed during the restart +# still refuses. +# * MAC missing / wrong (hand-written, edited, copied from another home, or +# written by a pre-fix build) -> NO trust flag is restored; only the +# fail-closed ``profile_route_rejected`` is honoured, since it can only +# tighten. A forged record therefore gains nothing it could not get by +# omitting the block. +# Anyone able to read the key can already edit this home's .env/config and +# grant themselves access directly, so the key adds no new trust root. +# A replay the intake still refuses is reported as ``restart_followup_lost`` +# by the runner, never silently acknowledged. +TRUST_GRANTING_ADMISSION_FIELDS = ("is_bot", "role_authorized", "delivered_via_upstream_relay") +FAIL_CLOSED_ADMISSION_FIELDS = ("profile_route_rejected",) +ADMISSION_FIELDS = TRUST_GRANTING_ADMISSION_FIELDS + FAIL_CLOSED_ADMISSION_FIELDS +SPOOL_KEY_NAME = "restart_followups.key" + + +def admission_fields(source: Any) -> Dict[str, bool]: + """The SessionSource admission flags, as strict bools (``is True``).""" + return {name: getattr(source, name, False) is True for name in ADMISSION_FIELDS} + + +def _spool_key(home: Optional[Path] = None, *, create: bool) -> Optional[bytes]: + path = spool_dir(home).parent / SPOOL_KEY_NAME + try: + return bytes.fromhex(path.read_text(encoding="ascii").strip()) + except FileNotFoundError: + if not create: + return None + except Exception: + logger.warning("restart follow-up spool key unreadable: %s", path, exc_info=True) + return None + try: + path.parent.mkdir(parents=True, exist_ok=True) + fd = os.open(str(path), os.O_WRONLY | os.O_CREAT | os.O_EXCL, 0o600) + with os.fdopen(fd, "w", encoding="ascii") as fh: + fh.write(secrets.token_hex(32)) + fh.flush() + os.fsync(fh.fileno()) + except FileExistsError: + pass # a concurrent writer created it first; read theirs + except Exception: + logger.warning("restart follow-up spool key could not be created: %s", path, exc_info=True) + return None + return _spool_key(home, create=False) + + +def _record_mac(key: bytes, record: Dict[str, Any]) -> str: + body = {k: v for k, v in record.items() if k != "mac" and not k.startswith("_")} + payload = json.dumps(body, sort_keys=True, separators=(",", ":")).encode("utf-8") + return hmac.new(key, payload, hashlib.sha256).hexdigest() + + +def restored_admission(record: Dict[str, Any]) -> Dict[str, bool]: + """Admission flags a loaded record may apply to its rebuilt SessionSource.""" + claimed = record.get("admission") + if not isinstance(claimed, dict): + return {} + if record.get("_admission_verified") is True: + return {name: claimed.get(name) is True for name in ADMISSION_FIELDS} + if any(claimed.get(name) is True for name in TRUST_GRANTING_ADMISSION_FIELDS): + logger.warning( + "PHASE=restart_followup_untrusted session=%s: admission flags are not " + "vouched for by this home's spool key; replaying WITHOUT them", + record.get("session_key"), + ) + return {name: True for name in FAIL_CLOSED_ADMISSION_FIELDS if claimed.get(name) is True} + + def event_fields(event: Any) -> Tuple[Optional[Dict[str, Any]], Optional[str]]: """Serialise every carried MessageEvent field. @@ -117,11 +202,14 @@ def spool_followup( home: Optional[Path] = None, now: Optional[float] = None, event: Optional[Dict[str, Any]] = None, + admission: Optional[Dict[str, bool]] = None, ) -> Optional[Path]: """Durably record ONE follow-up. Returns the file path, or None on failure. ``event`` is the ``event_fields`` dict of the parked MessageEvent; without it the record replays as a plain user text message (version 1 shape). + ``admission`` is ``admission_fields(source)``; it is stored MAC-bound (see + the trust model above) and only restored when the MAC verifies. """ if not session_key or not isinstance(text, str): return None @@ -142,6 +230,11 @@ def spool_followup( } if event is not None: record["event"] = event + if admission: + record["admission"] = {k: admission.get(k) is True for k in ADMISSION_FIELDS} + key = _spool_key(home, create=True) + if key is not None: + record["mac"] = _record_mac(key, record) try: directory = spool_dir(home) directory.mkdir(parents=True, exist_ok=True) @@ -177,6 +270,7 @@ def take_followups( except Exception: return records, stale current = time.time() if now is None else float(now) + key = _spool_key(home, create=False) for path in files: try: record = json.loads(path.read_text(encoding="utf-8")) @@ -193,6 +287,12 @@ def take_followups( stale += 1 path.rename(path.with_suffix(".stale")) continue + mac = record.get("mac") + record["_admission_verified"] = bool( + key is not None + and isinstance(mac, str) + and hmac.compare_digest(mac, _record_mac(key, record)) + ) record["_spool_path"] = str(path) records.append(record) except Exception: diff --git a/gateway/run.py b/gateway/run.py index 4fa5ca5582e33..8aea888f8e3ad 100644 --- a/gateway/run.py +++ b/gateway/run.py @@ -15777,7 +15777,11 @@ async def _preserve_followup_across_restart( event that was parked. An event with a field that cannot be stored durably is refused and logged as lost by field name. """ - from gateway.fork_ext.restart_followups import event_fields, spool_followup + from gateway.fork_ext.restart_followups import ( + admission_fields, + event_fields, + spool_followup, + ) fields = None if pending_event is not None: @@ -15835,6 +15839,10 @@ async def _preserve_followup_across_restart( src_dict, reason=self._status_action_label(), event=fields, + # Adapter-granted admission (is_bot / role_authorized / + # relay) that SessionSource.to_dict never serialises; + # MAC-bound so a forged record cannot assert it (t_43e058b7). + admission=admission_fields(src), ) except Exception: logger.debug("restart follow-up spool failed", exc_info=True) @@ -15924,7 +15932,11 @@ async def _spool_one_adapter_pending(self, adapter: Any, seen: Optional[set] = N async def _load_restart_followups(self) -> int: """Queue follow-ups spooled by the previous life into startup restore.""" try: - from gateway.fork_ext.restart_followups import event_kwargs, take_followups + from gateway.fork_ext.restart_followups import ( + event_kwargs, + restored_admission, + take_followups, + ) records, stale = await asyncio.to_thread(take_followups) except Exception: @@ -15936,9 +15948,15 @@ async def _load_restart_followups(self) -> int: carried = record.get("event") kwargs = event_kwargs(carried) if isinstance(carried, dict) else {} kwargs.setdefault("message_type", MessageType.TEXT) + source = SessionSource.from_dict(record["source"]) + for flag, value in restored_admission(record).items(): + setattr(source, flag, value) + # In-process only: lets the intake report a replay it refuses + # as restart_followup_lost (the spool file is already acked). + source._restart_followup_session = record.get("session_key") event = MessageEvent( text=record["text"], - source=SessionSource.from_dict(record["source"]), + source=source, **kwargs, ) event._hermes_restart_followup_path = record["_spool_path"] @@ -15958,6 +15976,25 @@ async def _load_restart_followups(self) -> int: ) return queued + def _report_refused_restart_followup(self, source: Any, reason: str) -> None: + """A replayed restart follow-up refused at intake is LOST, never silent. + + Its spool file was acknowledged when the adapter accepted the replay, + so this log line is the only remaining trace (t_43e058b7). + """ + session = getattr(source, "_restart_followup_session", None) + if not session: + return + logger.error( + "PHASE=restart_followup_lost session=%s reason=%s platform=%s chat=%s " + "user=%s: replayed follow-up refused at intake; it is DROPPED", + session, + reason, + getattr(getattr(source, "platform", None), "value", "unknown"), + getattr(source, "chat_id", None), + getattr(source, "user_id", None), + ) + def _queue_startup_restore_event(self, event: MessageEvent) -> None: queue = getattr(self, "_startup_restore_queue", None) if queue is None: @@ -22839,6 +22876,7 @@ async def _handle_message(self, event: MessageEvent) -> Optional[str]: "Dropping inbound message because its explicit profile route " "targets an unserved profile" ) + self._report_refused_restart_followup(source, "profile_route_rejected") return None # Internal events (e.g. background-process completion notifications) @@ -22935,9 +22973,11 @@ async def _handle_message(self, event: MessageEvent) -> Optional[str]: # sender). Defer to _is_user_authorized so that path runs. if not self._is_user_authorized_for_source(source): logger.debug("Ignoring message with no user_id from %s", source.platform.value) + self._report_refused_restart_followup(source, "unauthorized") return None elif not self._is_user_authorized_for_source(source): logger.warning("Unauthorized user: %s (%s) on %s", source.user_id, source.user_name, source.platform.value) + self._report_refused_restart_followup(source, "unauthorized") # In DMs: offer pairing code. In groups: silently ignore. if ( source.chat_type == "dm" diff --git a/gateway/session.py b/gateway/session.py index 937591d555e2b..f16e0863749dc 100644 --- a/gateway/session.py +++ b/gateway/session.py @@ -244,6 +244,9 @@ class SessionSource: # Set locally by the relay transport (``ws_transport._event_from_wire``); # deliberately excluded from ``to_dict``/``from_dict`` so a peer can never # forge it across the wire or have it restored from persistence. + # Sole exception: the gateway's own restart spool carries it (with is_bot / + # role_authorized) in a separate MAC-bound ``admission`` block and restores + # it only when that MAC verifies — see gateway/fork_ext/restart_followups.py. delivered_via_upstream_relay: bool = False def __post_init__(self) -> None: diff --git a/tests/gateway/test_restart_followups_admission_e2e.py b/tests/gateway/test_restart_followups_admission_e2e.py new file mode 100644 index 0000000000000..3ca2bd2b7de24 --- /dev/null +++ b/tests/gateway/test_restart_followups_admission_e2e.py @@ -0,0 +1,259 @@ +"""Restart follow-ups keep adapter-granted admission across the spool (t_43e058b7). + +Argus r8 N1 (t_e253d9d5): a follow-up admitted only by an adapter-granted +SessionSource flag (``is_bot`` under DISCORD_ALLOW_BOTS, ``role_authorized`` +under DISCORD_ALLOWED_ROLES, ``delivered_via_upstream_relay`` from the relay) +lost that flag in ``SessionSource.to_dict`` -> spool -> ``from_dict``, was +refused as "Unauthorized user" on boot replay, its spool file was acked anyway +and ``restart_followup_lost`` logged 0 lines. + +Everything is the production path on a throwaway home: park on the real +adapter slot, real ``GatewayRunner.stop(restart=True)``, real ``start()`` -> +loader -> drain -> REAL ``BasePlatformAdapter.handle_message`` -> runner +intake/authz. The only stub is ``_handle_message_with_agent`` (the LLM turn), +replaced by a recorder: "reached the agent" is the oracle. +""" + +import asyncio +import json +import logging + +import pytest + +from gateway.config import GatewayConfig, Platform, PlatformConfig +from gateway.fork_ext import restart_followups as rf +from gateway.platforms.base import BasePlatformAdapter, MessageEvent, MessageType, SendResult +from gateway.run import GatewayRunner +from gateway.session import SessionSource + +LOST = "PHASE=restart_followup_lost" +UNTRUSTED = "PHASE=restart_followup_untrusted" + + +class _Capture(logging.Handler): + def __init__(self): + super().__init__(logging.DEBUG) + self.lines = [] + + def emit(self, record): + try: + self.lines.append(record.getMessage()) + except Exception: + pass + + +class _FakeAdapter(BasePlatformAdapter): + """Fake transport; ``handle_message`` is NOT overridden (real intake).""" + + def __init__(self, platform): + super().__init__(PlatformConfig(enabled=True, token="synthetic"), platform) + + async def connect(self, *, is_reconnect=False): + self._mark_connected() + return True + + async def disconnect(self): + self._mark_disconnected() + + async def send(self, chat_id, content, reply_to=None, metadata=None): + return SendResult(success=True, message_id="1") + + async def send_typing(self, chat_id, metadata=None): + return None + + async def get_chat_info(self, chat_id): + return {"id": chat_id} + + +_CAP = _Capture() + + +def _runner(home, reached, platforms): + runner = GatewayRunner(GatewayConfig( + platforms={p: PlatformConfig(enabled=True, token="synthetic") for p in platforms}, + sessions_dir=home / "sessions", + )) + + async def _no_secondary(): + return 0 + + async def _recorder(event, source, quick_key, run_generation): + reached.append(event.text) + return None + + runner._start_secondary_profile_adapters = _no_secondary + runner._create_adapter = lambda platform, config: _FakeAdapter(platform) + runner._handle_message_with_agent = _recorder + return runner + + +def _event(user_id, chat_id, **flags): + src = SessionSource( + platform=Platform.DISCORD, chat_id=chat_id, chat_type="group", + guild_id="g1", user_id=user_id, **flags, + ) + return MessageEvent(text=f"follow-up from {user_id}", message_type=MessageType.TEXT, source=src) + + +@pytest.fixture +def home(tmp_path, monkeypatch): + monkeypatch.setenv("HERMES_HOME", str(tmp_path)) + monkeypatch.delenv("HERMES_PROFILE", raising=False) + for name in ("GATEWAY_ALLOW_ALL_USERS", "DISCORD_ALLOW_ALL_USERS", "DISCORD_ALLOWED_ROLES", + "GATEWAY_ALLOWED_USERS", "DISCORD_ALLOW_BOTS"): + monkeypatch.delenv(name, raising=False) + monkeypatch.setenv("DISCORD_ALLOWED_USERS", "human-1") + monkeypatch.setenv("DISCORD_ALLOW_BOTS", "mentions") + (tmp_path / "logs").mkdir() + cap = _CAP + cap.lines.clear() + root = logging.getLogger() + old_level = root.level + root.addHandler(cap) + root.setLevel(logging.DEBUG) + yield tmp_path + root.removeHandler(cap) + root.setLevel(old_level) + + +async def _park_and_stop(home, event, platforms): + first = _runner(home, [], platforms) + await asyncio.wait_for(first.start(), timeout=90) + key = f"agent:main:discord:group:{event.source.chat_id}:{event.source.user_id}" + first.adapters[Platform.DISCORD]._pending_messages[key] = event + await asyncio.wait_for(first.stop(restart=True, service_restart=False), timeout=90) + return sorted(rf.spool_dir().glob("*.json")) + + +async def _boot(home, platforms, before_boot=None): + if before_boot is not None: + before_boot() + reached = [] + mark = len(_CAP.lines) + boot = _runner(home, reached, platforms) + try: + await asyncio.wait_for(boot.start(), timeout=90) + for _ in range(150): + if reached: + break + await asyncio.sleep(0.1) + await asyncio.sleep(0.5) # a late refusal / duplicate would land here + finally: + await asyncio.wait_for(boot.stop(), timeout=60) + lines = _CAP.lines[mark:] + return reached, lines, sorted(rf.spool_dir().glob("*.json")) + + +ARMS = { + "human-control": (_event("human-1", "700"), (Platform.DISCORD,)), + "bot-allow-bots": (_event("bot-777", "701", is_bot=True), (Platform.DISCORD,)), + "role-authorized": (_event("role-user-5", "702", role_authorized=True), (Platform.DISCORD,)), + "relay": (_event("relay-user-9", "703", delivered_via_upstream_relay=True), + (Platform.DISCORD, Platform.RELAY)), +} + + +@pytest.mark.asyncio +@pytest.mark.parametrize("arm", sorted(ARMS)) +async def test_admitted_followup_is_delivered_after_real_restart(home, arm): + event, platforms = ARMS[arm] + spooled = await _park_and_stop(home, event, platforms) + assert len(spooled) == 1 + record = json.loads(spooled[0].read_text()) + # The wire/persistence shape of the source is unchanged: flags live only + # in the MAC-bound admission block. + wire_forbidden = {"is_bot", "role_authorized", "delivered_via_upstream_relay", "profile_route_rejected"} + assert not wire_forbidden & set(record["source"]) + if arm != "human-control": # the control needs no carried flag + assert isinstance(record.get("mac"), str) + + reached, lines, left = await _boot(home, platforms) + + assert reached == [event.text], [ln for ln in lines if "Unauthorized" in ln or LOST in ln] + assert not [ln for ln in lines if LOST in ln] + assert not [ln for ln in lines if "Unauthorized user" in ln] + assert left == [] + + +@pytest.mark.asyncio +async def test_forged_record_gains_no_trust_and_is_reported_lost(home): + """A hand-written record claiming is_bot (no valid MAC) is NOT admitted, + and the refusal is reported, not silently acked.""" + # A legit spool first, so the home HAS a key a forger could target. + spooled = await _park_and_stop(home, _event("human-1", "700"), (Platform.DISCORD,)) + assert len(spooled) == 1 + spooled[0].unlink() + src = SessionSource(platform=Platform.DISCORD, chat_id="704", chat_type="group", + guild_id="g1", user_id="forger-1") + record = { + "version": 2, "session_key": "agent:main:discord:group:704:forger-1", + "text": "forged follow-up", "source": src.to_dict(), "reason": "restart", + "ts": __import__("time").time(), "pid": 1, + "admission": {"is_bot": True, "role_authorized": True, + "delivered_via_upstream_relay": False, "profile_route_rejected": False}, + "mac": "0" * 64, + } + rf.spool_dir().mkdir(parents=True, exist_ok=True) + (rf.spool_dir() / "00000000000000000001-forged00.json").write_text(json.dumps(record)) + + reached, lines, _left = await _boot(home, (Platform.DISCORD,)) + + assert reached == [] + assert [ln for ln in lines if UNTRUSTED in ln] + lost = [ln for ln in lines if LOST in ln] + assert len(lost) == 1 and "reason=unauthorized" in lost[0] and "forger-1" in lost[0] + + +@pytest.mark.asyncio +async def test_tampered_record_loses_its_trust(home): + """Editing a legitimately MAC'd bot record (retarget the sender) voids the MAC.""" + spooled = await _park_and_stop(home, _event("bot-777", "701", is_bot=True), (Platform.DISCORD,)) + record = json.loads(spooled[0].read_text()) + record["source"]["user_id"] = "someone-else" + spooled[0].write_text(json.dumps(record)) + + reached, lines, _left = await _boot(home, (Platform.DISCORD,)) + + assert reached == [] + assert [ln for ln in lines if UNTRUSTED in ln] + assert len([ln for ln in lines if LOST in ln]) == 1 + + +@pytest.mark.asyncio +async def test_gate_closed_during_restart_refusal_is_reported_lost(home, monkeypatch): + """Admissible at park; the operator closed DISCORD_ALLOW_BOTS before boot. + Live policy still wins (refused) and the loss is reported, never silent.""" + spooled = await _park_and_stop(home, _event("bot-777", "701", is_bot=True), (Platform.DISCORD,)) + assert len(spooled) == 1 + + reached, lines, left = await _boot( + home, (Platform.DISCORD,), before_boot=lambda: monkeypatch.delenv("DISCORD_ALLOW_BOTS"), + ) + + assert reached == [] + assert not [ln for ln in lines if UNTRUSTED in ln] # MAC was valid + lost = [ln for ln in lines if LOST in ln] + assert len(lost) == 1, lines + assert "reason=unauthorized" in lost[0] and "bot-777" in lost[0] + assert left == [] + + +def test_admission_roundtrip_covers_every_field_to_dict_drops(home): + """Class guard: every SessionSource field that to_dict/from_dict loses and + that gates admission is carried by the spool's admission block.""" + import dataclasses + + all_on = {} + for f in dataclasses.fields(SessionSource): + if f.type in (bool, "bool"): + all_on[f.name] = True + src = SessionSource(platform=Platform.DISCORD, chat_id="1", user_id="u", **all_on) + back = SessionSource.from_dict(src.to_dict()) + lost = {name for name in all_on if getattr(back, name) is not True} + assert lost <= set(rf.ADMISSION_FIELDS), lost - set(rf.ADMISSION_FIELDS) + + path = rf.spool_followup("k", "t", src.to_dict(), admission=rf.admission_fields(src)) + (record,), _ = rf.take_followups() + assert record["_admission_verified"] is True + assert rf.restored_admission(record) == {name: True for name in rf.ADMISSION_FIELDS} + assert path is not None diff --git a/tests/gateway/test_restart_interrupt_intent_followups.py b/tests/gateway/test_restart_interrupt_intent_followups.py index b71e454155f9a..c19a9b6188a25 100644 --- a/tests/gateway/test_restart_interrupt_intent_followups.py +++ b/tests/gateway/test_restart_interrupt_intent_followups.py @@ -255,6 +255,32 @@ def test_draining_site_preserves_instead_of_discarding(): assert "await self._preserve_followup_across_restart(" in src[start:end] +def test_draining_site_spools_the_parked_event_itself(): + """Event identity at the post-turn draining site (Argus r8 MF, t_43e058b7): + the spool must receive ``pending_event`` (the parked MessageEvent: type, + media, internal, metadata, source admission), not ``None`` + the derived + ``pending`` string. Mutating the argument to ``None`` survived 40/40.""" + import ast + + src = RUN_PY.read_text(encoding="utf-8") + head = "if self._draining and (pending_event or pending):" + start = src.find(head) + assert start != -1, "draining follow-up branch not found" + end = src.find("if pending_event or pending:", start + len(head)) + line_start = src.rfind("\n", 0, start) + 1 + branch = ast.parse(__import__("textwrap").dedent(src[line_start:end]).rstrip() + "\n") + calls = [ + n for n in ast.walk(branch) + if isinstance(n, ast.Call) + and isinstance(n.func, ast.Attribute) + and n.func.attr == "_preserve_followup_across_restart" + ] + assert len(calls) == 1 + args = calls[0].args + assert [type(a).__name__ for a in args[:3]] == ["Name", "Name", "Name"], ast.dump(calls[0]) + assert [a.id for a in args[:3]] == ["session_key", "pending_event", "pending"] + + # -- ASK 4 / requester logging: in-band restart is attributable ------------- From f3f95d848e979be0ffae89aca1a38ac105b1fd2f Mon Sep 17 00:00:00 2001 From: Kyzcreig <9063726+Kyzcreig@users.noreply.github.com> Date: Thu, 24 Sep 2026 06:46:10 -0700 Subject: [PATCH 7/7] fix(gateway): reject torn spool keys and gate replay refusals Verified: 57 focused restart tests passed; forged invalid-key, tampered-admission, and two refusal-site arms exercised via real restart. --- gateway/fork_ext/restart_followups.py | 66 ++++++++-- .../test_restart_followups_admission_e2e.py | 115 ++++++++++++++++++ 2 files changed, 170 insertions(+), 11 deletions(-) diff --git a/gateway/fork_ext/restart_followups.py b/gateway/fork_ext/restart_followups.py index 3a1b68d27aef3..e1e62c2f32320 100644 --- a/gateway/fork_ext/restart_followups.py +++ b/gateway/fork_ext/restart_followups.py @@ -98,29 +98,73 @@ def admission_fields(source: Any) -> Dict[str, bool]: return {name: getattr(source, name, False) is True for name in ADMISSION_FIELDS} -def _spool_key(home: Optional[Path] = None, *, create: bool) -> Optional[bytes]: - path = spool_dir(home).parent / SPOOL_KEY_NAME +SPOOL_KEY_MIN_BYTES = 32 + + +def _read_spool_key(path: Path) -> Tuple[Optional[bytes], bool]: + """``(key, present)``. A present key that is empty, torn, non-hex or + shorter than ``SPOOL_KEY_MIN_BYTES`` is INVALID and returns ``(None, + True)``: an empty key would let anyone forge ``HMAC(b"", body)``.""" try: - return bytes.fromhex(path.read_text(encoding="ascii").strip()) + raw = path.read_text(encoding="ascii").strip() except FileNotFoundError: - if not create: - return None + return None, False except Exception: logger.warning("restart follow-up spool key unreadable: %s", path, exc_info=True) - return None + return None, True + try: + key = bytes.fromhex(raw) + except ValueError: + key = b"" + if len(key) < SPOOL_KEY_MIN_BYTES: + logger.error( + "PHASE=restart_followup_key_invalid path=%s: spool key is empty/short/" + "not hex; no spooled admission flag will be trusted until it is replaced", + path, + ) + return None, True + return key, True + + +def _spool_key(home: Optional[Path] = None, *, create: bool) -> Optional[bytes]: + """The per-home spool MAC key, or None (fail closed: nothing is trusted). + + Creation is atomic: the key is written + fsynced to a private temp file and + ``os.link``-ed into place, so a reader never sees a partial key. With + ``create=True`` a present-but-INVALID key (torn by a pre-fix build, edited) + is replaced atomically by a fresh one; records MAC'd under it were never + trusted anyway. With ``create=False`` (boot load) an invalid key is only + reported and everything fails closed. + """ + path = spool_dir(home).parent / SPOOL_KEY_NAME + key, present = _read_spool_key(path) + if key is not None or not create: + return key + tmp = path.with_name(f".{SPOOL_KEY_NAME}.{os.getpid()}.{uuid.uuid4().hex[:8]}.tmp") try: path.parent.mkdir(parents=True, exist_ok=True) - fd = os.open(str(path), os.O_WRONLY | os.O_CREAT | os.O_EXCL, 0o600) + fd = os.open(str(tmp), os.O_WRONLY | os.O_CREAT | os.O_EXCL, 0o600) with os.fdopen(fd, "w", encoding="ascii") as fh: - fh.write(secrets.token_hex(32)) + fh.write(secrets.token_hex(SPOOL_KEY_MIN_BYTES)) fh.flush() os.fsync(fh.fileno()) - except FileExistsError: - pass # a concurrent writer created it first; read theirs + if present: + os.replace(tmp, path) # heal an invalid key + logger.warning("PHASE=restart_followup_key_replaced path=%s", path) + else: + try: + os.link(tmp, path) + except FileExistsError: + pass # a concurrent writer won; use theirs except Exception: logger.warning("restart follow-up spool key could not be created: %s", path, exc_info=True) return None - return _spool_key(home, create=False) + finally: + try: + tmp.unlink() + except OSError: + pass + return _read_spool_key(path)[0] def _record_mac(key: bytes, record: Dict[str, Any]) -> str: diff --git a/tests/gateway/test_restart_followups_admission_e2e.py b/tests/gateway/test_restart_followups_admission_e2e.py index 3ca2bd2b7de24..c467fc00d41ef 100644 --- a/tests/gateway/test_restart_followups_admission_e2e.py +++ b/tests/gateway/test_restart_followups_admission_e2e.py @@ -257,3 +257,118 @@ def test_admission_roundtrip_covers_every_field_to_dict_drops(home): assert record["_admission_verified"] is True assert rf.restored_admission(record) == {name: True for name in rf.ADMISSION_FIELDS} assert path is not None + + +def _write_forged(mac_key, chat_id="704", user_id="forger-1"): + import hashlib + import hmac + import time + + src = SessionSource(platform=Platform.DISCORD, chat_id=chat_id, chat_type="group", + guild_id="g1", user_id=user_id) + record = { + "version": 2, "session_key": f"agent:main:discord:group:{chat_id}:{user_id}", + "text": "forged follow-up", "source": src.to_dict(), "reason": "restart", + "ts": time.time(), "pid": 1, + "admission": {"is_bot": True, "role_authorized": True, + "delivered_via_upstream_relay": True, "profile_route_rejected": False}, + } + body = json.dumps(record, sort_keys=True, separators=(",", ":")).encode() + record["mac"] = hmac.new(mac_key, body, hashlib.sha256).hexdigest() + rf.spool_dir().mkdir(parents=True, exist_ok=True) + (rf.spool_dir() / "00000000000000000001-forged00.json").write_text(json.dumps(record)) + + +# Argus r1 F1: a present-but-invalid key (torn 0-byte create, short, non-hex) +# must NOT be used as an HMAC key; a record forged under it gains nothing. +INVALID_KEYS = { + "empty": ("", b""), + "short": ("ab" * 8, bytes.fromhex("ab" * 8)), + "non-hex": ("zz-not-hex", b"zz-not-hex"), +} + + +@pytest.mark.asyncio +@pytest.mark.parametrize("kind", sorted(INVALID_KEYS)) +async def test_record_forged_under_invalid_key_gains_no_trust(home, kind): + text, mac_key = INVALID_KEYS[kind] + keyp = rf.spool_dir().parent / rf.SPOOL_KEY_NAME + keyp.parent.mkdir(parents=True, exist_ok=True) + keyp.write_text(text) + _write_forged(mac_key) + + reached, lines, _left = await _boot(home, (Platform.DISCORD,)) + + assert reached == [] + assert [ln for ln in lines if UNTRUSTED in ln] + lost = [ln for ln in lines if LOST in ln] + assert len(lost) == 1 and "reason=unauthorized" in lost[0] and "forger-1" in lost[0], lost + + +def test_invalid_key_is_replaced_atomically_on_next_spool(home): + keyp = rf.spool_dir().parent / rf.SPOOL_KEY_NAME + keyp.parent.mkdir(parents=True, exist_ok=True) + keyp.write_text("") + assert rf._spool_key(create=False) is None # boot load: fail closed, no repair + assert keyp.read_text() == "" + src = {"platform": "discord", "chat_id": "701", "user_id": "bot-777"} + rf.spool_followup("k", "t", src, admission={"is_bot": True}) + assert len(bytes.fromhex(keyp.read_text())) >= rf.SPOOL_KEY_MIN_BYTES + assert keyp.stat().st_mode & 0o777 == 0o600 + (record,), _ = rf.take_followups() + assert record["_admission_verified"] is True + assert not list(keyp.parent.glob(".*.tmp")) + + +# Argus r1 F2: the MAC must cover the admission block itself. +@pytest.mark.asyncio +@pytest.mark.parametrize("flag", ["is_bot", "role_authorized"]) +async def test_admission_flag_flipped_on_legit_record_is_rejected(home, flag): + spooled = await _park_and_stop(home, _event("stranger-3", "705"), (Platform.DISCORD,)) + assert len(spooled) == 1 + record = json.loads(spooled[0].read_text()) + assert isinstance(record.get("mac"), str) and record["admission"][flag] is False + record["admission"][flag] = True + spooled[0].write_text(json.dumps(record)) + + reached, lines, _left = await _boot(home, (Platform.DISCORD,)) + + assert reached == [] + assert [ln for ln in lines if UNTRUSTED in ln] + lost = [ln for ln in lines if LOST in ln] + assert len(lost) == 1 and "reason=unauthorized" in lost[0] and "stranger-3" in lost[0], lost + + +# Argus r1 F3: every intake refusal site reports the loss. +@pytest.mark.asyncio +async def test_no_user_id_followup_refused_on_replay_is_reported_lost(home, monkeypatch): + # The operator closes the allow-all gate between parking and replay. + monkeypatch.setenv("DISCORD_ALLOW_ALL_USERS", "true") + spooled = await _park_and_stop(home, _event(None, "706"), (Platform.DISCORD,)) + assert len(spooled) == 1 + + reached, lines, left = await _boot( + home, (Platform.DISCORD,), before_boot=lambda: monkeypatch.delenv("DISCORD_ALLOW_ALL_USERS"), + ) + + assert reached == [] + lost = [ln for ln in lines if LOST in ln] + assert len(lost) == 1 and "reason=unauthorized" in lost[0] and "chat=706" in lost[0], lines + assert left == [] + + +@pytest.mark.asyncio +async def test_profile_route_rejected_followup_is_reported_lost(home): + spooled = await _park_and_stop( + home, _event("human-1", "707", profile_route_rejected=True), (Platform.DISCORD,), + ) + assert len(spooled) == 1 + record = json.loads(spooled[0].read_text()) + assert record["admission"]["profile_route_rejected"] is True and isinstance(record.get("mac"), str) + + reached, lines, left = await _boot(home, (Platform.DISCORD,)) + + assert reached == [] + lost = [ln for ln in lines if LOST in ln] + assert len(lost) == 1 and "reason=profile_route_rejected" in lost[0], lines + assert left == []