From e9541d213f17219e9a7ce5d231999cd9edce0905 Mon Sep 17 00:00:00 2001 From: Teknium <127238744+teknium1@users.noreply.github.com> Date: Tue, 1 Sep 2026 09:58:10 -0700 Subject: [PATCH] =?UTF-8?q?fix(gateway):=20never=20print=20=E2=9C=93=20for?= =?UTF-8?q?=20a=20Windows=20gateway=20that=20dies=20after=20the=20liveness?= =?UTF-8?q?=20poll?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The 6s post-spawn liveness poll (#86687) returned on the FIRST process-table hit, so a gateway created and then killed moments later — e.g. by the parent shell's Job Object teardown when CREATE_BREAKAWAY_FROM_JOB is denied — still earned a "✓ Gateway started" line (#91675 hole a). And no poll can ever observe a death that happens AFTER the CLI process exits, which is exactly when the Job Object teardown fires. Two layers: 1. _wait_for_gateway_ready now treats the first hit as provisional: the gateway must stay visible through a 2s confirmation window (_confirm_gateway_stable) before it is reported ready; a death during confirmation resumes polling until the deadline. Failure output is an honest ✗ with the Job Object explanation and the schtasks /Run recovery command when a Scheduled Task exists. 2. Start attestation (report-async-death): every ✓ persists state/gateway.start-attestation.json with the vouched-for PIDs. The next `gateway start`/`gateway status` invocation checks it — if the attested PIDs are gone with no clean-exit record in the lifecycle ledger, the CLI reports (once) that the previous ✓ was false and prints the schtasks recovery hint. `gateway stop` and a clean lifecycle-ledger exit clear the marker silently. Also: when _spawn_detached had to retry without CREATE_BREAKAWAY_FROM_JOB, the ✓ now carries an explicit "could not break away from this shell's Job Object" warning, and the post-update cold-start ✓ (update_cmd) writes the same attestation marker. Sub-symptom (b) of #91675 (post-update cold-start only resumes the active profile) is handled separately by PR #99685. Fixes #91675 --- hermes_cli/gateway_windows.py | 248 +++++++++++++++++- hermes_cli/update_cmd.py | 9 + .../test_gateway_start_attestation.py | 191 ++++++++++++++ 3 files changed, 441 insertions(+), 7 deletions(-) create mode 100644 tests/hermes_cli/test_gateway_start_attestation.py diff --git a/hermes_cli/gateway_windows.py b/hermes_cli/gateway_windows.py index e9ca230f7b..b2ddf9fea6 100644 --- a/hermes_cli/gateway_windows.py +++ b/hermes_cli/gateway_windows.py @@ -59,6 +59,12 @@ _FALLBACK_PATTERNS = re.compile( ) _ACCESS_DENIED_PATTERN = re.compile(r"(access is denied|acceso denegado)", re.IGNORECASE) +# Set by _spawn_detached() when the breakaway spawn failed and it had to +# retry WITHOUT CREATE_BREAKAWAY_FROM_JOB — meaning the child stays inside +# the parent's Job Object and may be killed when this shell exits (#91675). +# Dict (not bare bool) so the flag is mutable without ``global``. +_LAST_SPAWN_BREAKAWAY_FALLBACK: dict = {"fallback": False} + _TASK_NAME_DEFAULT = "Hermes_Gateway" _TASK_DESCRIPTION = "Hermes Agent Gateway - Messaging Platform Integration" _TASK_LOGON_DELAY = "PT30S" @@ -957,6 +963,7 @@ def _spawn_detached(script_path: Path | None = None) -> int: stdout=log_fh, stderr=log_fh, ) + _LAST_SPAWN_BREAKAWAY_FALLBACK["fallback"] = False except OSError as exc: # CREATE_BREAKAWAY_FROM_JOB can fail with "access denied" when the # parent's job object doesn't permit breakaway (some Windows @@ -984,6 +991,7 @@ def _spawn_detached(script_path: Path | None = None) -> int: stdout=log_fh, stderr=log_fh, ) + _LAST_SPAWN_BREAKAWAY_FALLBACK["fallback"] = True return proc.pid @@ -1178,33 +1186,249 @@ def install( raise RuntimeError(f"Windows gateway install failed: {detail}") -def _wait_for_gateway_ready(timeout_s: float = 6.0, interval_s: float = 0.4) -> list[int]: +def _confirm_gateway_stable( + initial_pids: list[int], confirm_s: float, interval_s: float +) -> list[int]: + """Re-check a freshly detected gateway for ``confirm_s`` seconds. + + A single process-table hit only proves the child was *created*, not that + it survived startup — a gateway that crashes moments after spawn (or is + reaped by the parent shell's Job Object, #91675/#84185) passes a + first-hit poll and then dies. Require the gateway to stay visible for + the whole confirmation window before we vouch for it. Returns the last + observed PID list, or ``[]`` if the gateway vanished mid-window. + """ + if confirm_s <= 0: + return initial_pids + from hermes_cli.gateway import find_gateway_pids + + pids = initial_pids + confirm_deadline = time.monotonic() + confirm_s + while time.monotonic() < confirm_deadline: + time.sleep(interval_s) + pids = list(find_gateway_pids()) + if not pids: + return [] + return pids + + +def _wait_for_gateway_ready( + timeout_s: float = 6.0, + interval_s: float = 0.4, + confirm_s: float = 2.0, +) -> list[int]: """Poll for a live gateway process for up to ``timeout_s`` seconds. - Returns the list of PIDs found. Empty list means nothing came up in - time — the caller should surface that to the user as a failed start. + A first process-table hit is treated as *provisional*: the gateway must + then stay visible for ``confirm_s`` more seconds before we report it + ready (see :func:`_confirm_gateway_stable` — a child that dies right + after spawn must not earn a ✓, #91675). If it vanishes during the + confirmation window, polling resumes until the deadline. + + Returns the list of PIDs found. Empty list means nothing (stable) came + up in time — the caller should surface that to the user as a failed + start. """ from hermes_cli.gateway import find_gateway_pids - deadline = time.time() + timeout_s - while time.time() < deadline: + deadline = time.monotonic() + timeout_s + while time.monotonic() < deadline: pids = list(find_gateway_pids()) if pids: - return pids + confirmed = _confirm_gateway_stable(pids, confirm_s, interval_s) + if confirmed: + return confirmed + continue # died during confirmation — keep polling until deadline time.sleep(interval_s) return [] +# --------------------------------------------------------------------------- +# Start attestation — honest reporting for deaths AFTER the liveness poll +# --------------------------------------------------------------------------- +# +# The liveness poll (even with the confirmation window above) cannot observe +# a death that happens after this CLI process exits — the exact #91675 +# failure mode, where the parent shell's Job Object tears the gateway down +# on CLI exit. So every ✓ persists a small attestation marker recording +# which PIDs we vouched for. The NEXT gateway CLI invocation checks the +# marker: if those PIDs are gone and the lifecycle ledger shows no clean +# exit for them, the earlier ✓ was a lie and we say so — once — with the +# schtasks recovery hint. + +_START_ATTESTATION_RELATIVE = ("state", "gateway.start-attestation.json") + + +def _start_attestation_path() -> Path: + from hermes_cli.config import get_hermes_home + + return Path(get_hermes_home()).joinpath(*_START_ATTESTATION_RELATIVE) + + +def _write_start_attestation(pids: list[int], via: str) -> None: + """Persist the PIDs a ✓ vouched for. Best-effort, never raises.""" + import json as _json + from datetime import datetime, timezone + + try: + path = _start_attestation_path() + path.parent.mkdir(parents=True, exist_ok=True) + payload = { + "pids": [int(p) for p in pids], + "via": via, + "ts": datetime.now(timezone.utc).isoformat(), + } + tmp = path.with_suffix(".json.tmp") + tmp.write_text(_json.dumps(payload), encoding="utf-8") + tmp.replace(path) + except Exception: + logger.debug("Failed to write gateway start attestation", exc_info=True) + + +def _clear_start_attestation() -> None: + try: + _start_attestation_path().unlink(missing_ok=True) + except OSError: + pass + + +def _attested_pid_exited_cleanly(pid: int) -> bool: + """True when the lifecycle ledger shows a clean exit for ``pid``.""" + import json as _json + + try: + from gateway.lifecycle_ledger import get_lifecycle_sentinel_path + from hermes_cli.config import get_hermes_home + + sentinel_path = get_lifecycle_sentinel_path(Path(get_hermes_home())) + data = _json.loads(sentinel_path.read_text(encoding="utf-8")) + except Exception: + return False + return ( + isinstance(data, dict) + and data.get("phase") == "exited" + and data.get("pid") == pid + ) + + +def check_start_attestation(current_pids: list[int] | None = None) -> str | None: + """Surface (once) a gateway that died after a ✓ was printed for it. + + Reads the attestation marker left by the last successful-looking start. + Outcomes: + + * gateway currently running → the start held (or the service healed it); + clear the marker silently. + * attested PIDs all gone, lifecycle ledger shows a clean exit for one of + them → planned stop; clear silently. + * attested PIDs all gone with NO clean-exit record → the previous ✓ was + false (#91675: parent Job Object teardown killed the child after the + poll). Return a warning string and consume the marker so it prints + exactly once. + + Never raises. + """ + import json as _json + + try: + path = _start_attestation_path() + data = _json.loads(path.read_text(encoding="utf-8")) + except (OSError, ValueError): + return None + if not isinstance(data, dict): + _clear_start_attestation() + return None + attested = [p for p in data.get("pids", []) if isinstance(p, int)] + if not attested: + _clear_start_attestation() + return None + + if current_pids is None: + try: + from hermes_cli.gateway import find_gateway_pids + + current_pids = list(find_gateway_pids()) + except Exception: + return None + + if current_pids: + # Gateway is up — the previous start held, or something restarted it. + _clear_start_attestation() + return None + + if any(_attested_pid_exited_cleanly(pid) for pid in attested): + _clear_start_attestation() + return None + + _clear_start_attestation() + via = data.get("via") or "direct spawn" + ts = data.get("ts") or "unknown time" + lines = [ + f"⚠ The previous gateway start ({via}, {ts}) reported success, but the " + f"process (PID {', '.join(map(str, attested))}) died without a clean " + "shutdown record.", + " This usually means the shell that ran `hermes gateway start` was inside " + "a Windows Job Object that killed the gateway on exit (#91675).", + ] + try: + if is_task_registered(): + lines.append( + f" Recovery: schtasks /Run /TN {get_task_name()} " + "(Task Scheduler starts the gateway outside any Job Object)" + ) + except Exception: + pass + return "\n".join(lines) + + +def _print_start_attestation_warning() -> None: + """Print the stale-attestation warning if one is pending. Never raises.""" + try: + warning = check_start_attestation() + except Exception: + return + if warning: + print(warning) + + def _report_gateway_start(via: str) -> None: pids = _wait_for_gateway_ready() if pids: print(f"✓ Gateway started via {via} (PID: {', '.join(map(str, pids))})") + if _LAST_SPAWN_BREAKAWAY_FALLBACK.get("fallback"): + print( + "⚠ The gateway could not break away from this shell's Job Object; " + "it may be killed when this shell exits." + ) + try: + if is_task_registered(): + print( + f" If it dies, start it with: schtasks /Run /TN {get_task_name()}" + ) + except Exception: + pass + _write_start_attestation(pids, via) else: - print(f"⚠ Launched gateway via {via}, but no process detected after 6s.") + print( + f"✗ Gateway start via {via} FAILED — no stable gateway process " + "detected within the verification window." + ) + print( + " (The process may have been created and then killed — e.g. by a " + "parent Job Object, #91675.)" + ) print(" Check the log for startup errors:") from hermes_cli.config import get_hermes_home print(f" type {Path(get_hermes_home())}\\logs\\gateway.log") print(f" type {Path(get_hermes_home())}\\logs\\gateway-stdio.log") + try: + if is_task_registered(): + print( + f" Recovery: schtasks /Run /TN {get_task_name()} " + "(starts the gateway outside any Job Object)" + ) + except Exception: + pass def _print_next_steps() -> None: @@ -1448,6 +1672,9 @@ def _print_deep_probes() -> None: def status(deep: bool = False) -> None: """Print a status report for the Windows gateway service.""" _assert_windows() + # Surface (once) any gateway that died after a previous start printed ✓ + # — the poll can't see deaths that happen after the CLI exits (#91675). + _print_start_attestation_warning() task_name = get_task_name() task_installed = is_task_registered() startup_installed = is_startup_entry_installed() @@ -1491,6 +1718,9 @@ def status(deep: bool = False) -> None: def start() -> None: """Start the gateway using the canonical detached Windows launch path.""" _assert_windows() + # Report (once) if the LAST start's ✓ turned out to be false — the child + # died after the poll window, e.g. parent Job Object teardown (#91675). + _print_start_attestation_warning() running_pids = _gateway_pids() if running_pids: print(f"✓ Gateway already running (PID: {', '.join(map(str, running_pids))})") @@ -1629,6 +1859,10 @@ def stop() -> None: _assert_windows() from gateway.status import get_running_pid + # A user-initiated stop is a planned death: the attestation from the + # last start must not later be reported as a silent crash (#91675). + _clear_start_attestation() + # Phase 1: ask the running gateway (if any) to drain itself by writing # the planned-stop marker, then wait briefly for it to exit cleanly. # On clean exit, sessions land with resume_pending=True and the next diff --git a/hermes_cli/update_cmd.py b/hermes_cli/update_cmd.py index 7c7125cbd9..f0a825b32b 100644 --- a/hermes_cli/update_cmd.py +++ b/hermes_cli/update_cmd.py @@ -6753,6 +6753,15 @@ def _cold_start_windows_gateway_after_update() -> bool: "✓ Gateway started via cold-start after update " f"(PID: {', '.join(map(str, ready_pids))})" ) + # Persist the PIDs this ✓ vouched for so a death AFTER the updater exits + # (parent Job Object teardown, #91675) is reported by the next CLI + # invocation instead of staying silent. Best-effort. + try: + gateway_windows._write_start_attestation( + ready_pids, "cold-start after update" + ) + except Exception: + pass return True diff --git a/tests/hermes_cli/test_gateway_start_attestation.py b/tests/hermes_cli/test_gateway_start_attestation.py new file mode 100644 index 0000000000..38df762d44 --- /dev/null +++ b/tests/hermes_cli/test_gateway_start_attestation.py @@ -0,0 +1,191 @@ +"""Tests for the #91675 gateway-start honesty fixes. + +Two holes closed by the fix: + +1. ``_wait_for_gateway_ready`` returned on the FIRST process-table hit, so a + gateway that spawned and then died moments later (parent Job Object + teardown) still earned a ✓. The poll now requires the gateway to stay + visible for a confirmation window before it is reported ready. +2. A death AFTER the CLI process exits can never be seen by any poll. Every + ✓ now persists a start-attestation marker; the next CLI invocation checks + it and reports the silent death (once) unless the lifecycle ledger shows + a clean exit. + +All timing knobs are shrunk so no test sleeps longer than ~1s. +""" + +import json + +import pytest + +import hermes_cli.gateway_windows as gateway_windows + + +# --------------------------------------------------------------------------- +# _wait_for_gateway_ready: confirmation window +# --------------------------------------------------------------------------- + + +def _install_pid_sequence(monkeypatch, snapshots): + """find_gateway_pids returns successive snapshots (last one repeats).""" + calls = {"n": 0} + + def _fake(*args, **kwargs): + idx = min(calls["n"], len(snapshots) - 1) + calls["n"] += 1 + return list(snapshots[idx]) + + monkeypatch.setattr("hermes_cli.gateway.find_gateway_pids", _fake) + return calls + + +def test_ready_poll_rejects_gateway_that_dies_during_confirmation(monkeypatch): + """First-hit-then-dead must NOT be reported ready (#91675 sabotage case). + + Pre-fix, the poll returned ``[4242]`` on the first snapshot and the CLI + printed ✓ for a process that was already doomed. + """ + _install_pid_sequence(monkeypatch, [[4242], [], [], []]) + monkeypatch.setattr(gateway_windows.time, "sleep", lambda s: None) + + pids = gateway_windows._wait_for_gateway_ready( + timeout_s=0.5, interval_s=0.01, confirm_s=0.2 + ) + assert pids == [] + + +def test_ready_poll_confirms_stable_gateway(monkeypatch): + """A gateway that stays visible through the confirmation window is ready.""" + _install_pid_sequence(monkeypatch, [[4242]]) + monkeypatch.setattr(gateway_windows.time, "sleep", lambda s: None) + + pids = gateway_windows._wait_for_gateway_ready( + timeout_s=0.5, interval_s=0.01, confirm_s=0.05 + ) + assert pids == [4242] + + +def test_ready_poll_recovers_when_gateway_respawns_within_deadline(monkeypatch): + """Death during confirmation resumes polling; a later stable gateway wins.""" + # hit → dead (confirmation fails) → nothing → new stable pid + _install_pid_sequence(monkeypatch, [[1], [], [], [2], [2], [2]]) + monkeypatch.setattr(gateway_windows.time, "sleep", lambda s: None) + + pids = gateway_windows._wait_for_gateway_ready( + timeout_s=1.0, interval_s=0.01, confirm_s=0.03 + ) + assert pids == [2] + + +def test_report_gateway_start_failure_is_loud_not_checkmark(monkeypatch, tmp_path, capsys): + """No stable gateway ⇒ ✗ failure line, never ✓ (#91675).""" + monkeypatch.setattr( + gateway_windows, "_wait_for_gateway_ready", lambda *a, **k: [] + ) + monkeypatch.setattr( + "hermes_cli.config.get_hermes_home", lambda: str(tmp_path) + ) + monkeypatch.setattr(gateway_windows, "is_task_registered", lambda: True) + monkeypatch.setattr(gateway_windows, "get_task_name", lambda: "Hermes_Gateway_x") + + gateway_windows._report_gateway_start("direct spawn (PID 7)") + out = capsys.readouterr().out + assert "✓" not in out + assert "FAILED" in out + assert "schtasks /Run /TN Hermes_Gateway_x" in out + + +# --------------------------------------------------------------------------- +# Start attestation: report-async-death on the next CLI invocation +# --------------------------------------------------------------------------- + + +@pytest.fixture +def attest_home(monkeypatch, tmp_path): + monkeypatch.setattr("hermes_cli.config.get_hermes_home", lambda: str(tmp_path)) + monkeypatch.setattr(gateway_windows, "is_task_registered", lambda: False) + return tmp_path + + +def test_success_report_writes_attestation(monkeypatch, attest_home, capsys): + monkeypatch.setattr( + gateway_windows, "_wait_for_gateway_ready", lambda *a, **k: [321] + ) + gateway_windows._LAST_SPAWN_BREAKAWAY_FALLBACK["fallback"] = False + gateway_windows._report_gateway_start("direct spawn (PID 321)") + assert "✓" in capsys.readouterr().out + + marker = attest_home / "state" / "gateway.start-attestation.json" + data = json.loads(marker.read_text(encoding="utf-8")) + assert data["pids"] == [321] + assert data["via"] == "direct spawn (PID 321)" + + +def test_attestation_reports_silent_death(attest_home): + """Attested PIDs gone + no clean-exit record ⇒ warning, marker consumed.""" + gateway_windows._write_start_attestation([555], "direct spawn (PID 555)") + + warning = gateway_windows.check_start_attestation(current_pids=[]) + assert warning is not None + assert "died without a clean shutdown record" in warning + assert "555" in warning + # Consumed: second check is silent. + assert gateway_windows.check_start_attestation(current_pids=[]) is None + + +def test_attestation_silent_when_gateway_running(attest_home): + gateway_windows._write_start_attestation([555], "direct spawn (PID 555)") + assert gateway_windows.check_start_attestation(current_pids=[555]) is None + # Marker cleared — a later dead scan must not resurrect the warning. + assert gateway_windows.check_start_attestation(current_pids=[]) is None + + +def test_attestation_silent_after_clean_ledger_exit(attest_home): + """A clean lifecycle-ledger exit for the attested PID is a planned stop.""" + gateway_windows._write_start_attestation([777], "direct spawn (PID 777)") + state = attest_home / "state" + state.mkdir(exist_ok=True) + (state / "gateway.lifecycle.json").write_text( + json.dumps({"phase": "exited", "pid": 777, "exit_reason": "graceful_shutdown"}), + encoding="utf-8", + ) + assert gateway_windows.check_start_attestation(current_pids=[]) is None + + +def test_attestation_warning_includes_schtasks_recovery(monkeypatch, attest_home): + monkeypatch.setattr(gateway_windows, "is_task_registered", lambda: True) + monkeypatch.setattr( + gateway_windows, "get_task_name", lambda: "Hermes_Gateway_arthur_tutor" + ) + gateway_windows._write_start_attestation([888], "direct spawn (PID 888)") + warning = gateway_windows.check_start_attestation(current_pids=[]) + assert "schtasks /Run /TN Hermes_Gateway_arthur_tutor" in warning + + +def test_attestation_tolerates_missing_and_garbage_marker(attest_home): + assert gateway_windows.check_start_attestation(current_pids=[]) is None + marker = attest_home / "state" / "gateway.start-attestation.json" + marker.parent.mkdir(exist_ok=True) + marker.write_text("not json", encoding="utf-8") + assert gateway_windows.check_start_attestation(current_pids=[]) is None + marker.write_text(json.dumps({"pids": []}), encoding="utf-8") + assert gateway_windows.check_start_attestation(current_pids=[]) is None + assert not marker.exists() + + +def test_breakaway_fallback_warns_even_on_success(monkeypatch, attest_home, capsys): + """When the spawn fell back to no-breakaway, the ✓ carries a Job warning.""" + monkeypatch.setattr( + gateway_windows, "_wait_for_gateway_ready", lambda *a, **k: [99] + ) + monkeypatch.setattr(gateway_windows, "is_task_registered", lambda: True) + monkeypatch.setattr(gateway_windows, "get_task_name", lambda: "Hermes_Gateway") + gateway_windows._LAST_SPAWN_BREAKAWAY_FALLBACK["fallback"] = True + try: + gateway_windows._report_gateway_start("direct spawn (PID 99)") + finally: + gateway_windows._LAST_SPAWN_BREAKAWAY_FALLBACK["fallback"] = False + out = capsys.readouterr().out + assert "✓" in out + assert "could not break away" in out + assert "schtasks /Run /TN Hermes_Gateway" in out