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.
This commit is contained in:
87
evals/update_streaming/live_output.py
Normal file
87
evals/update_streaming/live_output.py
Normal file
@@ -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()
|
||||
44
evals/update_streaming/watchdog.ps1
Normal file
44
evals/update_streaming/watchdog.ps1
Normal file
@@ -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
|
||||
}
|
||||
@@ -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/<branch> 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):
|
||||
|
||||
@@ -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
|
||||
|
||||
86
tests/hermes_cli/test_update_live_output.py
Normal file
86
tests/hermes_cli/test_update_live_output.py
Normal file
@@ -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")))
|
||||
@@ -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.
|
||||
|
||||
Reference in New Issue
Block a user