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. """