From 50d3c53f6cd7c547a9add82704f5ecfbe7c57207 Mon Sep 17 00:00:00 2001 From: Teknium <127238744+teknium1@users.noreply.github.com> Date: Wed, 26 Aug 2026 15:35:58 -0700 Subject: [PATCH] fix(update): count logs/update.log growth as watchdog progress The #95625 watchdog cancels a step after StepIdleTimeoutSeconds (300s) with no stdout/stderr. But a real `hermes update` is stdout-silent for 40+ minutes by design: the Electron/vite build streams to logs/update.log, not the child's pipes (hermes_cli/update_cmd.py's update-log tee). An output-only ceiling would therefore kill every healthy large update at 5 minutes and mark it exit 124. The drain now fingerprints logs/update.log (size + mtime) and, when the idle ceiling is otherwise reached, treats growth of that file as progress: reset the clock instead of terminating the tree. The stat runs only once the ceiling fires, so the hot drain path never touches the filesystem. HERMES_UPDATE_STEP_IDLE_SECONDS remains the override; HERMES_UPDATE_PROGRESS_LOG points the self-test at its own file. TDD proof: -SelfTestPipeDrain gains a fourth arm, logstall -- a step that is silent on its pipes but appends to the progress log every second and must reach its natural exit 3, never 124. Linux CI pins the same contract at source level (TestIdleWatchdogCountsUpdateLogGrowth); sabotage-verified: making the log-growth consult inert fails test_stall_branch_consults_log_growth_before_terminating. --- scripts/desktop-update/windows.ps1 | 110 +++++++++++++++--- .../test_desktop_update_windows_pipe_drain.py | 75 ++++++++++++ 2 files changed, 172 insertions(+), 13 deletions(-) diff --git a/scripts/desktop-update/windows.ps1 b/scripts/desktop-update/windows.ps1 index 587b7b7471..5ed91c952e 100644 --- a/scripts/desktop-update/windows.ps1 +++ b/scripts/desktop-update/windows.ps1 @@ -721,6 +721,33 @@ if ($env:HERMES_UPDATE_STEP_IDLE_SECONDS) { } } +# Silence on the pipes is NOT silence in the update. `hermes update` captures +# the (very loud) Electron/vite build into logs/update.log instead of its own +# stdout (hermes_cli/update_cmd.py, the update-log tee), so a real update is +# routinely stdout-silent for 40+ minutes while demonstrably progressing. An +# idle ceiling that watched only stdout/stderr would cancel every healthy +# large update at StepIdleTimeoutSeconds. The drain therefore also counts +# growth of this file (size or mtime) as progress before declaring a stall. +# Overridable so the pipe-drain self-test can point it at its own file; not +# documented as a user knob. +$script:StepProgressLogPath = Join-Path $LogDir "update.log" +if ($env:HERMES_UPDATE_PROGRESS_LOG) { + $script:StepProgressLogPath = $env:HERMES_UPDATE_PROGRESS_LOG +} + +function Get-StepProgressLogStamp { + # Size + mtime fingerprint of the update log; $null when absent or + # unreadable. Comparing fingerprints between passes is how the idle + # watchdog sees a build that streams to update.log instead of stdout. + try { + $fi = New-Object System.IO.FileInfo($script:StepProgressLogPath) + if (-not $fi.Exists) { return $null } + return ('{0}:{1}' -f $fi.Length, $fi.LastWriteTimeUtc.Ticks) + } catch { + return $null + } +} + if (-not ("HermesUpdateJob" -as [type])) { Add-Type -TypeDefinition @' using System; @@ -999,6 +1026,7 @@ function Invoke-HermesStep([string]$Exe, [string[]]$HermesArgs, [string]$Tag) { $abandonAt = $null $abandoned = $false $lastProgressAt = Get-Date + $progressLogStamp = Get-StepProgressLogStamp $stalled = $false while ($true) { $moved = $false @@ -1016,17 +1044,31 @@ function Invoke-HermesStep([string]$Exe, [string[]]$HermesArgs, [string]$Tag) { break } } elseif (-not $stalled -and $job -ne [IntPtr]::Zero -and ((Get-Date) - $lastProgressAt).TotalSeconds -ge $script:StepIdleTimeoutSeconds) { - # The child is alive but has produced no observable progress for - # the whole bound. Terminate the job, not just its direct process: - # retrying while a descendant still mutates the checkout, venv, or - # release tree can overlap two installers and corrupt the install. - Write-HandoffLog ("{0}!| step stalled: no stdout/stderr for {1}s while pid {2} remained alive; cancelling its process tree." -f $Tag, $script:StepIdleTimeoutSeconds, $proc.Id) - $stalled = [HermesUpdateJob]::TerminateAndWait($job, 124, 10000) - if (-not $stalled) { - Write-HandoffLog ("{0}!| process-tree cancellation could not prove quiescence; refusing the timeout retry." -f $Tag) - $script:TreeSafeToFinalize = $false - [HermesUpdateJob]::Close($job) - throw "Unable to quiesce stalled update process tree" + # Quiet pipes are how a healthy `hermes update` looks for 40+ + # minutes: its build output streams to logs/update.log, not the + # child's stdout. Growth of that file is progress -- reset the + # clock instead of cancelling. Stat'd only once the ceiling is + # otherwise reached (at most once per 150ms pass after that), so + # the hot drain path never touches the filesystem. + $currentLogStamp = Get-StepProgressLogStamp + if ($currentLogStamp -ne $progressLogStamp) { + $progressLogStamp = $currentLogStamp + $lastProgressAt = Get-Date + } else { + # The child is alive but has produced no observable progress + # -- neither on its pipes nor in the update log -- for the + # whole bound. Terminate the job, not just its direct process: + # retrying while a descendant still mutates the checkout, + # venv, or release tree can overlap two installers and + # corrupt the install. + Write-HandoffLog ("{0}!| step stalled: no stdout/stderr for {1}s and no update.log growth while pid {2} remained alive; cancelling its process tree." -f $Tag, $script:StepIdleTimeoutSeconds, $proc.Id) + $stalled = [HermesUpdateJob]::TerminateAndWait($job, 124, 10000) + if (-not $stalled) { + Write-HandoffLog ("{0}!| process-tree cancellation could not prove quiescence; refusing the timeout retry." -f $Tag) + $script:TreeSafeToFinalize = $false + [HermesUpdateJob]::Close($job) + throw "Unable to quiesce stalled update process tree" + } } } # Only idle when both pipes came up empty this pass, and idle on the @@ -1131,6 +1173,11 @@ if ($SelfTestUi) { # stall -- a step that remains alive after its visible work and emits no more # output. Guards #95589: the hand-off must terminate it and reach its # retry/finally recovery rather than strand the Desktop. +# logstall -- a step that is silent on its pipes but keeps growing the +# update log, the shape of every real `hermes update` build (output +# goes to logs/update.log, not stdout, for 40+ minutes). Guards the +# watchdog's other cliff: the idle ceiling must count update.log +# growth as progress and must NOT kill the healthy step. if ($SelfTestPipeDrain) { New-Item -ItemType Directory -Path $LogDir -Force -ErrorAction SilentlyContinue | Out-Null $hold = 60 @@ -1146,6 +1193,8 @@ if ($SelfTestPipeDrain) { $stallPs1 = Join-Path $TempDir "hermes-step-stall-$stamp.ps1" $stallPidFile = Join-Path $TempDir "hermes-step-stall-$stamp.pid" $stallGrandchildPidFile = Join-Path $TempDir "hermes-step-stall-grandchild-$stamp.pid" + $logStallPs1 = Join-Path $TempDir "hermes-step-logstall-$stamp.ps1" + $logStallProgress = Join-Path $TempDir "hermes-step-logstall-$stamp.update.log" # UseShellExecute=$false with no redirection is what makes the grandchild # inherit our stdout/stderr -- the whole point of the fixture. Anything # that redirects (Start-Process, subprocess with stdout=DEVNULL) would @@ -1190,10 +1239,24 @@ Write-Output "step entered silent finalization" [Console]::Out.Flush() Start-Sleep -Seconds $Hold exit 0 +'@ + # Pipe-silent but log-writing: one stdout line, then only Add-Content to + # the progress log every second. With Hold far above the idle ceiling, + # surviving to exit 3 proves the watchdog counted the log growth. + $logStallSource = @' +param([int]$Hold, [string]$ProgressLog) +Write-Output "silent but logging" +[Console]::Out.Flush() +for ($i = 0; $i -lt $Hold; $i++) { + Add-Content -LiteralPath $ProgressLog -Value ("build tick {0}" -f $i) + Start-Sleep -Seconds 1 +} +exit 3 '@ [System.IO.File]::WriteAllText($childPs1, $childSource) [System.IO.File]::WriteAllText($floodPs1, $floodSource) [System.IO.File]::WriteAllText($stallPs1, $stallSource) + [System.IO.File]::WriteAllText($logStallPs1, $logStallSource) $sw = [System.Diagnostics.Stopwatch]::StartNew() $res = Invoke-HermesStep $powershell @( "-NoProfile", "-ExecutionPolicy", "Bypass", "-File", $childPs1, @@ -1242,7 +1305,24 @@ exit 0 $stallGrandchildAlive = $stallGrandchildPid -gt 0 -and [bool](Get-Process -Id $stallGrandchildPid -ErrorAction SilentlyContinue) if ($stallGrandchildAlive) { Stop-Process -Id $stallGrandchildPid -Force -ErrorAction SilentlyContinue } - Remove-Item -LiteralPath $childPs1, $floodPs1, $stallPs1, $pidFile, $stallPidFile, $stallGrandchildPidFile -Force -ErrorAction SilentlyContinue + # logstall arm: point the watchdog's progress log at the fixture's file + # for exactly this step, restore afterwards so the other arms' contract + # (no update.log in play) is untouched. + $savedProgressLogPath = $script:StepProgressLogPath + $script:StepProgressLogPath = $logStallProgress + $logStallSw = [System.Diagnostics.Stopwatch]::StartNew() + try { + $logstall = Invoke-HermesStep $powershell @( + "-NoProfile", "-ExecutionPolicy", "Bypass", "-File", $logStallPs1, + "-Hold", [string]$hold, "-ProgressLog", $logStallProgress + ) "logstall" + } finally { + $script:StepProgressLogPath = $savedProgressLogPath + } + $logStallSw.Stop() + $logStallElapsed = [Math]::Round($logStallSw.Elapsed.TotalSeconds, 2) + + Remove-Item -LiteralPath $childPs1, $floodPs1, $stallPs1, $logStallPs1, $pidFile, $stallPidFile, $stallGrandchildPidFile, $logStallProgress -Force -ErrorAction SilentlyContinue # The grandchild still being alive at return is what makes this a proof # rather than a timing coincidence: the pipe was demonstrably still open. @@ -1266,8 +1346,12 @@ exit 0 if ($stallGrandchildAlive) { $problems += "stalled descendant pid $stallGrandchildPid remained alive after Invoke-HermesStep returned" } if (-not $stall.TreeQuiesced) { $problems += "stall arm returned without proving its process tree quiescent" } if (-not $stall.StartedAfterJobAssignment) { $problems += "stall arm started before cancellation-job assignment" } + $logStallBudget = $hold + 60 + if ($logstall.Code -ne 3) { $problems += "logstall arm exit code $($logstall.Code), expected 3 -- the idle watchdog killed a pipe-silent step whose progress was visible as update.log growth (the shape of every real 40+ min build)" } + if ($logstall.Output -notmatch "silent but logging") { $problems += "logstall arm step output was lost" } + if ($logStallElapsed -ge $logStallBudget) { $problems += "logstall arm returned in ${logStallElapsed}s, over the ${logStallBudget}s budget" } - $detail = "leak: elapsed=${elapsed}s budget=${budget}s code=$($res.Code) grandchildAlive=$leakAlive | flood: ${floodKb}KB in ${floodElapsed}s budget=${floodBudget}s bytes=$floodBytes code=$($flood.Code) | stall: elapsed=${stallElapsed}s budget=${stallBudget}s code=$($stall.Code) childAlive=$stallAlive descendantAlive=$stallGrandchildAlive quiesced=$($stall.TreeQuiesced)" + $detail = "leak: elapsed=${elapsed}s budget=${budget}s code=$($res.Code) grandchildAlive=$leakAlive | flood: ${floodKb}KB in ${floodElapsed}s budget=${floodBudget}s bytes=$floodBytes code=$($flood.Code) | stall: elapsed=${stallElapsed}s budget=${stallBudget}s code=$($stall.Code) childAlive=$stallAlive descendantAlive=$stallGrandchildAlive quiesced=$($stall.TreeQuiesced) | logstall: elapsed=${logStallElapsed}s budget=${logStallBudget}s code=$($logstall.Code)" if ($problems.Count -gt 0) { Write-Host "PIPE-DRAIN SELF-TEST: FAIL $detail -- $($problems -join '; ')" exit 1 diff --git a/tests/test_desktop_update_windows_pipe_drain.py b/tests/test_desktop_update_windows_pipe_drain.py index a77948f598..d3cd1e8ee8 100644 --- a/tests/test_desktop_update_windows_pipe_drain.py +++ b/tests/test_desktop_update_windows_pipe_drain.py @@ -56,6 +56,74 @@ REPO_ROOT = Path(__file__).resolve().parent.parent WINDOWS_PS1 = REPO_ROOT / "scripts" / "desktop-update" / "windows.ps1" +class TestIdleWatchdogCountsUpdateLogGrowth: + """The idle watchdog must count logs/update.log growth as progress. + + Real updates are stdout-silent for 40+ minutes: ``hermes update`` captures + the (very loud) Electron/vite build into ``logs/update.log`` — NOT the + child's stdout (``hermes_cli/update_cmd.py``, the update-log tee) — so the + step's pipes go quiet for the whole build while the update is demonstrably + progressing. A no-output ceiling that watches only stdout/stderr would + kill every healthy large update at ``StepIdleTimeoutSeconds`` and mark it + exit 124. + + These are source-contract assertions (the executable proof is the + ``logstall`` arm of ``-SelfTestPipeDrain``, ``windows_only`` below): + Linux CI cannot run the PowerShell hand-off, but it CAN pin that the + drain loop consults update-log growth before terminating the tree. + Sabotage-proof: removing the ``Get-StepProgressLogStamp`` consult from + the stall branch, dropping the ``logstall`` self-test arm, or dropping + the ``HERMES_UPDATE_STEP_IDLE_SECONDS`` override each fails a test here. + """ + + def _src(self) -> str: + return WINDOWS_PS1.read_text(encoding="utf-8") + + def test_progress_log_default_is_update_log(self): + src = self._src() + assert '$script:StepProgressLogPath = Join-Path $LogDir "update.log"' in src + + def test_progress_log_overridable_for_self_test(self): + assert "HERMES_UPDATE_PROGRESS_LOG" in self._src() + + def test_idle_override_env_retained(self): + # The user/test-facing idle override must survive the amendment. + assert "HERMES_UPDATE_STEP_IDLE_SECONDS" in self._src() + + def test_stall_branch_consults_log_growth_before_terminating(self): + src = self._src() + assert "function Get-StepProgressLogStamp" in src + # The consult must sit inside the idle-ceiling branch, upstream of + # TerminateAndWait: growth resets the progress clock instead of + # cancelling the tree. Pin the exact consult + compare + reset shape + # so an inert consult (or a removed one) fails here. + msg = ( + "the idle watchdog no longer checks logs/update.log growth " + "before declaring a stall -- a healthy 40+ min build whose " + "output goes to update.log would be killed at the idle ceiling" + ) + assert "$currentLogStamp = Get-StepProgressLogStamp" in src, msg + assert "if ($currentLogStamp -ne $progressLogStamp)" in src, msg + # The growth check must gate the termination: compare-and-reset + # appears before the 124 tree-termination inside the drain loop. + consult = src.index("if ($currentLogStamp -ne $progressLogStamp)") + terminate = src.index("TerminateAndWait($job, 124") + assert consult < terminate, msg + # And the clock actually resets on growth. + growth_block = src[consult:terminate] + assert "$progressLogStamp = $currentLogStamp" in growth_block, msg + assert "$lastProgressAt = Get-Date" in growth_block, msg + + def test_self_test_has_silent_but_logging_arm(self): + src = self._src() + assert "logstall" in src, ( + "-SelfTestPipeDrain lost its silent-but-logging arm: the fixture " + "no longer proves that a step which is quiet on its pipes but " + "growing update.log is NOT killed by the idle watchdog" + ) + assert "silent but logging" in src + + @pytest.mark.windows_only def test_update_step_survives_pipe_leak_flood_and_live_child_stall( tmp_path: Path, @@ -83,6 +151,13 @@ def test_update_step_survives_pipe_leak_flood_and_live_child_stall( output, and report quiescence only after both processes are gone. This is the invariant that permits retry. + *logstall* -- a step that is silent on its pipes but appends to the + progress log (pointed at the fixture's own file) every second, exiting 3. + This is the shape of every real ``hermes update`` build: output streams to + ``logs/update.log``, not stdout, for 40+ minutes. The idle watchdog must + count that growth as progress and let the step run to its natural exit + instead of killing it at the ceiling with 124. + The existing leak/flood arms retain their measured Windows 11 / PowerShell 5.1 budgets; the stall arm uses the same real runner and process table. """