From 76afc136f355854ae38443849d4117fe4f1cfe72 Mon Sep 17 00:00:00 2001 From: Teknium <127238744+teknium1@users.noreply.github.com> Date: Sun, 4 Oct 2026 15:42:56 -0700 Subject: [PATCH] fix(update): a launch recovering an unready SCM service no longer stalls on it R8 re-review M3. Since D4b a running service stays owed until its gateway is ready, and `update_pause_record.recover()` runs before every non-update command: each launch re-claimed the debt and waited the full 60 s readiness budget (+2 s confirm), with no backoff, for as long as the service's gateway stayed unhealthy. - A recovering launch (`token["recovery"]`) probes readiness for 5 s; the 60 s wait stays with `hermes update`. - A service found running but unready records `service_retry` {attempts, next_at} on the token (60 s, doubling, capped at 1 h). A recovering launch inside that window skips a still-running service at once and keeps it owed; a stopped one is still started. Success clears the entry. Test (native Windows, real SCM service whose gateway never comes up, two real recovering launches): test_a_launch_recovering_an_unready_service_keeps_the_debt_without_stalling. (cherry picked from commit 823c214534e5f8d301097c063cfc79ebbfddc13c) --- hermes_cli/update_cmd_windows.py | 43 ++++++++++++++-- .../test_update_pause_debt_windows_live.py | 51 +++++++++++++++++++ 2 files changed, 90 insertions(+), 4 deletions(-) diff --git a/hermes_cli/update_cmd_windows.py b/hermes_cli/update_cmd_windows.py index 7ff26be200..647f6b40f9 100644 --- a/hermes_cli/update_cmd_windows.py +++ b/hermes_cli/update_cmd_windows.py @@ -1242,9 +1242,15 @@ def _refresh_bootstrap_cache_scripts(branch: str = "main") -> None: _SERVICE_READY_TIMEOUT_S = 60.0 +# A launch recovering an orphaned pause (``update_pause_record.recover``, before every command) +# only probes briefly, and a service whose gateway stays unready is re-probed with backoff; the +# full wait belongs to ``hermes update`` itself. +_SERVICE_READY_PROBE_S = 5.0 +_SERVICE_RETRY_BASE_S = 60.0 +_SERVICE_RETRY_MAX_S = 3600.0 -def _service_gateway_ready(name: str, profile: str | None) -> list[int]: +def _service_gateway_ready(name: str, profile: str | None, timeout_s: float | None = None) -> list[int]: """The stable gateway *name*'s service process supervises (in *profile*'s home when known): SCM ``running`` proves only the wrapper started, not that the gateway it hosts came up.""" from hermes_cli import gateway_windows @@ -1265,23 +1271,48 @@ def _service_gateway_ready(name: str, profile: str | None) -> list[int]: home = Path(get_profile_dir(profile)) if profile else None return gateway_windows._wait_for_gateway_ready( - timeout_s=_SERVICE_READY_TIMEOUT_S, home=home, all_profiles=home is None, pid_filter=under_service) + timeout_s=_SERVICE_READY_TIMEOUT_S if timeout_s is None else timeout_s, home=home, + all_profiles=home is None, pid_filter=under_service) + + +def _service_running(name: str) -> bool: + try: + return _win_service(name)[1].status() == "running" + except Exception: + return False def _resume_windows_services(token: dict) -> None: """Restart the SCM services recorded on *token*; one leaves the token only once the gateway it - supervises is ready. Failed ones stay on the token so a retry sees them.""" + supervises is ready. Failed ones stay on the token so a retry sees them. + + A recovering launch (``token["recovery"]``) probes readiness briefly, and a running service + whose gateway was not ready is not re-probed before its backoff (``service_retry``) elapses: + the debt stays owed without stalling every command.""" from hermes_cli.update_cmd import _start_windows_gateway_service services = list(token.get("services") or []) token.setdefault("expected_services", list(services)) verified_restarts = list(token.get("restarted_services") or []) + retry = {name: state for name, state in (token.get("service_retry") or {}).items() if name in services} + recovering = bool(token.get("recovery")) restarted_services = [] failed_services = [] for service_name in map(str, services): + backoff = retry.get(service_name) or {} try: + if recovering and _time.time() < float(backoff.get("next_at") or 0) and _service_running(service_name): + failed_services.append(service_name) + print(f" ⚠ Windows gateway service {service_name}: its gateway was not ready; " + f"next check after {int(float(backoff['next_at']) - _time.time())}s") + continue _start_windows_gateway_service(service_name) - if not _service_gateway_ready(service_name, (token.get("service_profiles") or {}).get(service_name)): + if not _service_gateway_ready(service_name, (token.get("service_profiles") or {}).get(service_name), + _SERVICE_READY_PROBE_S if recovering else None): + attempts = int(backoff.get("attempts") or 0) + 1 + retry[service_name] = {"attempts": attempts, "next_at": _time.time() + min( + _SERVICE_RETRY_BASE_S * 2 ** min(attempts - 1, 6), _SERVICE_RETRY_MAX_S)} raise RuntimeError(f"Windows service {service_name} is running but its gateway did not become ready") + retry.pop(service_name, None) restarted_services.append(service_name) if service_name not in verified_restarts: verified_restarts.append(service_name) @@ -1291,6 +1322,10 @@ def _resume_windows_services(token: dict) -> None: failed_services.append(service_name) token["restarted_services"] = verified_restarts token["services"] = failed_services + if retry: + token["service_retry"] = retry + else: + token.pop("service_retry", None) if failed_services: raise RuntimeError("Could not restart Windows gateway service(s): " + ", ".join(failed_services)) if restarted_services: diff --git a/tests/hermes_cli/test_update_pause_debt_windows_live.py b/tests/hermes_cli/test_update_pause_debt_windows_live.py index 875952d701..3e39da19cc 100644 --- a/tests/hermes_cli/test_update_pause_debt_windows_live.py +++ b/tests/hermes_cli/test_update_pause_debt_windows_live.py @@ -10,6 +10,7 @@ Windows readers hold them, a real SCM service, real processes and taskkill. Noth from __future__ import annotations +import json import os import subprocess import sys @@ -200,6 +201,56 @@ def test_a_running_service_owes_its_gateway_until_that_gateway_is_ready(tmp_path _sc("delete", name) +_RECOVERING_LAUNCH = """ +import json, time +from hermes_cli import update_pause_record as r +started = time.monotonic() +r.recover(["status"]) +print(json.dumps({"seconds": time.monotonic() - started, + "owed": [body["token"].get("services") for _src, body in r.orphans()]})) +""" + + +def test_a_launch_recovering_an_unready_service_keeps_the_debt_without_stalling(tmp_path, monkeypatch, service_wrapper): + """Two CLI launches in a row recover an orphaned pause whose SCM service runs but whose gateway + never comes up: the debt stays owed, and neither launch waits out the update's full readiness budget.""" + home = tmp_path / "home" + home.mkdir() + monkeypatch.setenv("HERMES_HOME", str(home)) + bin_dir = tmp_path / "svc" + bin_dir.mkdir() + exe = bin_dir / "wrapper.exe" + exe.write_bytes(service_wrapper.read_bytes()) + (bin_dir / "child.txt").write_text("\n".join([sys.executable, "-c \"import time; time.sleep(900)\"", str(REPO)]) + "\n", + encoding="utf-8") + name = f"hermes-r9-recover-{os.getpid()}" + created = _sc("create", name, "binPath=", f'"{exe}"', "start=", "demand") + assert created.returncode == 0, created.stdout + created.stderr + # The record a killed update left; the tree gate passes (HEAD and tracked changes as stamped). + pause_record.write(pause_record.stamp_tree({ + "resume_needed": True, "services": [name], "expected_services": [name], "restarted_services": [], + "service_profiles": {name: "default"}}), owner=pause_record.UNOWNED) + try: + launches = [] + for _ in range(2): + done = subprocess.run([sys.executable, "-c", _RECOVERING_LAUNCH], cwd=REPO, capture_output=True, + text=True, encoding="utf-8", errors="replace", timeout=300, + env={**os.environ, "HERMES_HOME": str(home), "PYTHONPATH": str(REPO)}) + assert done.returncode == 0, done.stdout + done.stderr + launches.append(json.loads(done.stdout.strip().splitlines()[-1])) + finally: + pid = 0 + with suppress(Exception): + pid = int(psutil.win_service_get(name).pid() or 0) # type: ignore[attr-defined] + if pid: + subprocess.run(["taskkill", "/T", "/F", "/PID", str(pid)], capture_output=True, check=False) + _sc("delete", name) + assert [launch["owed"] for launch in launches] == [[[name]], [[name]]], f"the unready service's debt was lost: {launches}" + first, second = (launch["seconds"] for launch in launches) + assert first < 40, f"the first launch stalled {first:.0f}s on the service's readiness" + assert second < 20, f"the next launch stalled {second:.0f}s on a service it had just found unready" + + def _logs(home: Path) -> str: return "\n".join(f"--- {p}\n{p.read_text(encoding='utf-8-sig', errors='replace')[-3000:]}" for p in sorted((home / "logs").glob("*.log")))