From c0c6b3154314b9715a0302e91c4f43903825317b Mon Sep 17 00:00:00 2001 From: Teknium <127238744+teknium1@users.noreply.github.com> Date: Mon, 7 Sep 2026 03:16:21 -0700 Subject: [PATCH] fix(update): stream build progress without concealing silent stalls Retain partial-line output, UTF-8 decoding, failure output and cancellation cleanup. Based on streaming investigations by Artemonim (#101850) and lEWFkRAD (#104843); gateway tee adapted from fangliquanflq (#97402). Live Linux child/tee probe: withheld or dropped on base, visible in 0.02 seconds after. Campaign-locked tests and native Windows proof are pending. --- evals/update_streaming/live_output.py | 87 +++++++++++++++++++ evals/update_streaming/watchdog.ps1 | 44 ++++++++++ hermes_cli/update_cmd.py | 55 ++++++++---- .../test_update_hangup_protection.py | 5 +- tests/hermes_cli/test_update_live_output.py | 86 ++++++++++++++++++ website/docs/user-guide/desktop.md | 7 ++ 6 files changed, 266 insertions(+), 18 deletions(-) create mode 100644 evals/update_streaming/live_output.py create mode 100644 evals/update_streaming/watchdog.ps1 create mode 100644 tests/hermes_cli/test_update_live_output.py diff --git a/evals/update_streaming/live_output.py b/evals/update_streaming/live_output.py new file mode 100644 index 0000000000..efdeb73c1a --- /dev/null +++ b/evals/update_streaming/live_output.py @@ -0,0 +1,87 @@ +"""Disposable subprocess/tee probe; never invokes an actual update. + +Run with the checkout's Python. --step drives the native Windows hand-off +watchdog fixture; otherwise print a live before/after JSON receipt. +""" +import argparse +import io +import json +import os +from pathlib import Path +import subprocess +import sys +import tempfile +import threading +import time + +ROOT = Path(__file__).resolve().parents[2] +sys.path.insert(0, str(ROOT)) + + +def run_child(mode): + if mode == "silent": + time.sleep(12) + else: + for _ in range(24): + os.write(1, b"build-progress ") + time.sleep(.5) + return 7 + + +def step(mode): + from hermes_cli.main_dashboard import _install_hangup_protection, _finalize_update_output + from hermes_cli.main import _run_logged_subprocess + state = _install_hangup_protection(gateway_mode=True) + try: + return _run_logged_subprocess([sys.executable, __file__, "--child", mode]).returncode + finally: + _finalize_update_output(state) + + +def probe(): + from hermes_cli.main_dashboard import _install_hangup_protection, _finalize_update_output + from hermes_cli.main import _run_logged_subprocess + receipts = [] + for gateway in (False, True): + with tempfile.TemporaryDirectory(prefix="update-output-") as temp: + os.environ["HERMES_HOME"] = temp + os.environ["HOME"] = temp + os.environ["USERPROFILE"] = temp + screen, original = io.StringIO(), sys.stdout + sys.stdout = screen + state = _install_hangup_protection(gateway_mode=gateway) + result = [] + started = time.monotonic() + thread = threading.Thread(target=lambda: result.append(_run_logged_subprocess( + [sys.executable, __file__, "--child", "progress"]))) + thread.start() + log = Path(temp) / "logs" / "update.log" + while time.monotonic() - started < 5: + text = log.read_text(encoding="utf-8") if log.exists() else "" + if "build-progress" in text: + break + time.sleep(.02) + early = "build-progress" in text + observed = time.monotonic() - started + alive = thread.is_alive() + thread.join(20) + _finalize_update_output(state) + sys.stdout = original + assert not thread.is_alive() + receipts.append(dict(gateway=gateway, progress_before_exit=early, + observed_seconds=round(observed, 3), alive_at_observation=alive, + exit_code=result[0].returncode, captured_progress=result[0].stdout.count("build-progress"), + screen_bytes=len(screen.getvalue()), log_bytes=log.stat().st_size if log.exists() else 0)) + print(json.dumps({"platform":sys.platform,"rows":receipts}, indent=2)) + + +if __name__ == "__main__": + parser = argparse.ArgumentParser() + parser.add_argument("--child", choices=("silent", "progress")) + parser.add_argument("--step", choices=("silent", "progress")) + args = parser.parse_args() + if args.child: + raise SystemExit(run_child(args.child)) + if args.step: + raise SystemExit(step(args.step)) + probe() diff --git a/evals/update_streaming/watchdog.ps1 b/evals/update_streaming/watchdog.ps1 new file mode 100644 index 0000000000..0f3cd76456 --- /dev/null +++ b/evals/update_streaming/watchdog.ps1 @@ -0,0 +1,44 @@ +param([string]$Python, [string]$Receipt, [int]$ExpectedProgressCode = 7) +$ErrorActionPreference = 'Stop' +$repo = (Resolve-Path (Join-Path $PSScriptRoot '../..')).Path +$temp = Join-Path ([IO.Path]::GetTempPath()) ('update-watchdog-' + [guid]::NewGuid()) +New-Item -ItemType Directory $temp | Out-Null +$env:HOME = $temp +$env:USERPROFILE = $temp +$env:HERMES_HOME = $temp +$LogDir = Join-Path $temp 'logs' +New-Item -ItemType Directory $LogDir | Out-Null +$script:Ui = $null +$script:TreeSafeToFinalize = $true +function Write-HandoffLog([string]$Message) { + Add-Content -LiteralPath (Join-Path $temp 'handoff.log') -Value $Message -Encoding UTF8 +} +# Execute the maintained process/job/watchdog boundary, not a reimplementation. +# Deliberately omit all actual update, service, marker and Desktop launch phases. +$source = [IO.File]::ReadAllText((Join-Path $repo 'scripts/desktop-update/windows.ps1')) +$start = $source.IndexOf('$script:StepDrainGraceSeconds = 20') +$end = $source.IndexOf('$finalCode = 1', $start) +if ($start -lt 0 -or $end -lt $start) { throw 'SETUP FAIL: handoff boundary not found' } +. ([scriptblock]::Create($source.Substring($start, $end - $start))) +$script:StepIdleTimeoutSeconds = 3 +$script:StepDrainGraceSeconds = 2 +$rows = @() +try { + foreach ($mode in @('progress', 'silent')) { + Remove-Item -LiteralPath $script:StepProgressLogPath -ErrorAction SilentlyContinue + $clock = [Diagnostics.Stopwatch]::StartNew() + $result = Invoke-HermesStep $Python @((Join-Path $PSScriptRoot 'live_output.py'), '--step', $mode) $mode + $rows += @{ mode=$mode; code=$result.Code; seconds=$clock.Elapsed.TotalSeconds; tree_quiesced=$result.TreeQuiesced; job_assigned=$result.StartedAfterJobAssignment; output=$result.Output } + } + @{ platform='native Windows'; python=$Python; rows=$rows } | ConvertTo-Json -Depth 5 | Set-Content -LiteralPath $Receipt -Encoding UTF8 + if ($rows[0].code -ne $ExpectedProgressCode) { throw "progress code $($rows[0].code), expected $ExpectedProgressCode" } + if ($rows[1].code -ne 124) { throw "silent child escaped watchdog: $($rows[1].code)" } + foreach ($row in $rows) { + if (-not $row.tree_quiesced -or -not $row.job_assigned) { throw 'unsafe child lifecycle' } + if ($row.output.Length -ne 0) { throw 'build output leaked to screen pipe' } + } + Write-Host ('VERDICT: progress={0}, silent=124; private Windows job quiesced' -f $rows[0].code) +} finally { + Copy-Item -LiteralPath (Join-Path $temp 'handoff.log') -Destination ($Receipt + '.log') -ErrorAction SilentlyContinue + Remove-Item -LiteralPath $temp -Recurse -Force +} diff --git a/hermes_cli/update_cmd.py b/hermes_cli/update_cmd.py index 14068d1cdd..beba4e72bf 100644 --- a/hermes_cli/update_cmd.py +++ b/hermes_cli/update_cmd.py @@ -415,25 +415,50 @@ def _log_only_write(text: str) -> None: return stream = _m().sys.stdout log_file = getattr(stream, "_log", None) - if log_file is None: - return with suppress(Exception): - log_file.write(text if text.endswith("\n") else text + "\n") - log_file.flush() + if log_file is None: + log_path = get_hermes_home() / "logs" / "update.log" + log_path.parent.mkdir(parents=True, exist_ok=True) + with log_path.open("a", encoding="utf-8") as fallback: + fallback.write(text) + else: + log_file.write(text) + log_file.flush() def _run_logged_subprocess(cmd, *, cwd=None, env=None): - """Run ``cmd`` with combined output captured into update.log only; returns the - ``CompletedProcess`` so the caller can surface the output on failure.""" - # Check if there are updates. On shallow checkouts `rev-list --count` walks the truncated graph and can - # report the entire remote ancestry (e.g. "Found 9980 new commit(s)" on a depth-1 install — #53479). The - # zero/nonzero gate is still sound (HEAD == origin/ counts 0), so keep it, but treat the shallow - # NUMBER as unknown and recover the real one via the GitHub compare API when possible. - result = subprocess.run( - cmd, cwd=cwd, env=env, check=False, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, - text=True, encoding="utf-8", errors="replace") - _log_only_write(result.stdout or "") - return result + """Stream combined build output to update.log, retaining it for failure reporting.""" + import codecs + import io + from hermes_cli._subprocess_compat import kill_process_tree, windows_hide_flags + + child_env = dict(os.environ if env is None else env) + child_env.setdefault("PYTHONUNBUFFERED", "1") + spawn = {"creationflags": windows_hide_flags()} if os.name == "nt" else {"process_group": 0} + proc = subprocess.Popen( + cmd, cwd=cwd, env=child_env, stdin=subprocess.DEVNULL, + stdout=subprocess.PIPE, stderr=subprocess.STDOUT, **spawn) + # read1 delivers partial lines too; incremental decoding preserves split UTF-8 + # and the universal-newline behavior callers previously got from text=True. + decoder = io.IncrementalNewlineDecoder(codecs.getincrementaldecoder("utf-8")("replace"), True) + output = [] + try: + while True: + chunk = proc.stdout.read1(8192) + text = decoder.decode(chunk, final=not chunk) + output.append(text) + _log_only_write(text) + if not chunk: + break + return subprocess.CompletedProcess(cmd, proc.wait(), stdout="".join(output)) + except BaseException: + # Unlike Popen.__exit__, do not wait for a cancelled build to finish. + kill_process_tree(proc) + with suppress(subprocess.TimeoutExpired): + proc.wait(timeout=5) + raise + finally: + proc.stdout.close() def _cmd_update_check(branch: str = "main", *, branch_explicit: bool = False): diff --git a/tests/hermes_cli/test_update_hangup_protection.py b/tests/hermes_cli/test_update_hangup_protection.py index 4d42445f7f..61a6f48958 100644 --- a/tests/hermes_cli/test_update_hangup_protection.py +++ b/tests/hermes_cli/test_update_hangup_protection.py @@ -199,9 +199,8 @@ class TestFinalizeUpdateOutput: class TestLogOnlyWrite: - def test_noop_without_update_stream(self, monkeypatch): - """When stdout isn't the mirroring update stream (no ``_log``), it must - be a silent no-op rather than crash.""" + def test_plain_stdout_keeps_build_output_off_screen(self, monkeypatch): + """An unwrapped stdout must not receive log-only build output.""" plain = io.StringIO() monkeypatch.setattr(sys, "stdout", plain) _log_only_write("something") # should not raise diff --git a/tests/hermes_cli/test_update_live_output.py b/tests/hermes_cli/test_update_live_output.py new file mode 100644 index 0000000000..dc47113998 --- /dev/null +++ b/tests/hermes_cli/test_update_live_output.py @@ -0,0 +1,86 @@ +"""Live output must reach disk before exit, without concealing silence.""" +import io +import os +from pathlib import Path +import subprocess +import sys +import threading +import time + +import pytest + +from hermes_cli import main_dashboard as output +from hermes_cli import update_cmd + + +@pytest.mark.parametrize("gateway", [False, True, None]) +def test_child_progress_reaches_log_before_exit(tmp_path, monkeypatch, gateway): + monkeypatch.setenv("HERMES_HOME", str(tmp_path)) + terminal = io.StringIO() + monkeypatch.setattr(sys, "stdout", terminal) + state = output._install_hangup_protection(gateway) if gateway is not None else None + log = tmp_path / "logs" / "update.log" + release = tmp_path / "release" + ready = tmp_path / "ready" + script = tmp_path / "child.py" + script.write_text( + "import os, pathlib, sys, time\n" + f"pathlib.Path({str(ready)!r}).touch()\n" + "os.write(1, b'progress: ' + bytes([0xe2, 0x82]))\n" + "time.sleep(.1)\n" + "os.write(2, bytes([0xac, 0xff]))\n" + f"while not pathlib.Path({str(release)!r}).exists(): time.sleep(.02)\n" + "print(' done', flush=True)\n" + "sys.exit(7)\n", encoding="utf-8") + results = [] + worker = threading.Thread(target=lambda: results.append( + update_cmd._run_logged_subprocess([sys.executable, str(script)]))) + try: + worker.start() + deadline = time.monotonic() + 10 + while time.monotonic() < deadline: + text = log.read_text(encoding="utf-8") if log.exists() else "" + if "progress: €�" in text: + break + time.sleep(.02) + assert ready.exists(), "child fixture never started" + assert "progress: €�" in text, "output withheld while child waits for release" + assert worker.is_alive() + size = log.stat().st_size + time.sleep(.3) + assert log.stat().st_size == size, "silence must not manufacture progress" + assert terminal.getvalue() == "" + if gateway is not None: + assert state["installed"] + print("update stage", flush=True) + assert "update stage" in log.read_text(encoding="utf-8") + finally: + release.touch() + worker.join(10) + output._finalize_update_output(state) + assert not worker.is_alive() + assert results[0].returncode == 7 + assert results[0].stdout == "progress: €� done\n" + assert results[0].stderr is None + + +def test_cancelled_output_reader_reaps_child(tmp_path, monkeypatch): + pidfile = tmp_path / "pid" + child = tmp_path / "cancel_child.py" + child.write_text( + "import os, pathlib, time\n" + f"pathlib.Path({str(pidfile)!r}).write_text(str(os.getpid()), encoding='utf-8')\n" + "print('started', flush=True)\n" + "time.sleep(30)\n", encoding="utf-8") + + class CancelLog: + def write(self, text): + raise KeyboardInterrupt + + monkeypatch.setattr(sys, "stdout", output._UpdateOutputStream(io.StringIO(), CancelLog())) + started = time.monotonic() + with pytest.raises(KeyboardInterrupt): + update_cmd._run_logged_subprocess([sys.executable, str(child)]) + assert time.monotonic() - started < 10 + import psutil + assert not psutil.pid_exists(int(pidfile.read_text(encoding="utf-8"))) diff --git a/website/docs/user-guide/desktop.md b/website/docs/user-guide/desktop.md index fac37285e9..5f18c6279b 100644 --- a/website/docs/user-guide/desktop.md +++ b/website/docs/user-guide/desktop.md @@ -272,6 +272,13 @@ chats decide who replies: [Bot Mode: A Roster of Agents](./bot-mode.md). The app checks for updates in the background and offers a one-click update when one is ready. +During a local update, detailed build output streams into the active profile's +`logs/update.log`, including detached `--gateway` updates. It stays out of the +terminal but is available for troubleshooting before the build finishes. The +Windows hand-off counts new output in this log as progress; a child that produces +no output is still subject to the idle watchdog. Process liveness alone does not +reset that watchdog, and cancelling an update does not wait for its build to finish. + The desktop app and the Hermes backend it talks to update on separate clocks — the app package on your machine, the backend wherever it runs. When more than one update target exists (a remote gateway, or several registered gateways), the update affordances (**Update now** on the About panel, the ⌘K **Update Hermes** row, and the update-ready toast) update **everything**: the connected backend first, then every other eligible registered gateway (Hermes Cloud entries are platform-managed and skipped), and the desktop app itself last, since applying the client update relaunches the app. Single-machine installs keep the one-button experience. After any backend update, the app also re-checks its own version and warns with a one-click **Update desktop app** action if the GUI is still behind — so updating a remote backend can never silently leave you on a stale desktop build.