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)
This commit is contained in:
@@ -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:
|
||||
|
||||
@@ -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")))
|
||||
|
||||
Reference in New Issue
Block a user