diff --git a/.claude/memory/schos-bootcheck-trust.md b/.claude/memory/schos-bootcheck-trust.md index 17c66b0..154f057 100644 --- a/.claude/memory/schos-bootcheck-trust.md +++ b/.claude/memory/schos-bootcheck-trust.md @@ -4,7 +4,7 @@ description: bootcheck silently stopped running and five of seven modes asserted metadata: node_type: memory originSessionId: 9d8a2aef-bcf0-47a0-96c6-f706efab4a95 - modified: 2026-08-09T19:05:06.942Z + modified: 2026-08-09T19:17:56.770Z --- **A green run is only green if you counted the checks.** On 2026-08-09 the @@ -46,16 +46,27 @@ of success. Both of these produced clean-looking runs while testing nothing. **How to apply:** after any change to the harness itself, verify the check count, not just the absence of FAIL. -## The extended suite is timing-fragile on the Fedora laptop +## The extended suite was timing-fragile — fixed 2026-08-09 -`Wait-Prompt` waits a fixed **20 s**; measured on this machine with the guest's -own `/proc/uptime`, a cold `ls /bin | wc -l` takes **23 s** and took **51 s** -before the e820 work. When it overruns, the script sleeps 2 s and types anyway, -so the next command lands in a busy shell and the transcript interleaves — and -the check that fails is then some *later* one whose output is no longer -adjacent to its command. `yes writes through a pipe` failed this way while -`y`/`y` were plainly correct in the transcript. Treat a single FAIL in -`-Fb -Tty -Usb -Sock -Evdev -Ps` as suspect until the transcript is read. +`yes writes through a pipe` failed repeatedly on `-Fb -Tty -Usb -Sock -Evdev +-Ps` while `y`/`y` were plainly correct in the transcript. Three harness bugs, +all fixed in commit 4e0478c and its follow-up: + +1. **`Wait-Prompt` waited a fixed 20 s.** Measured from inside the guest, a cold + `ls /bin | wc -l` takes **23 s** here (**51 s** before the e820 work), so the + wall was always crossed. Now 60 s. +2. **It matched the prompt anywhere in the transcript.** Between sending a + command and the guest echoing it, the log still ends with the *previous* + prompt — so it could return before the command started. Now anchored to text + produced after the command was sent. +3. **On timeout it slept 2 s and typed anyway**, landing the next command in a + busy shell and interleaving the transcript, so the check that failed was a + *later* unrelated one. Now waits for output to stop growing. + +The run also names any command that produced no prompt, because after one +overrun every later check is reading a possibly-interleaved transcript. + +**Still treat a lone FAIL here as suspect until you have read the transcript.** **Leaked QEMU made this worse and is now fixed** (commit 4e0478c): the `finally` cannot run when the *script* is killed, so QEMU outlived it and, under diff --git a/tools/windows/bootcheck.ps1 b/tools/windows/bootcheck.ps1 index 50cd2da..5464ce5 100644 --- a/tools/windows/bootcheck.ps1 +++ b/tools/windows/bootcheck.ps1 @@ -308,6 +308,12 @@ $p = [System.Diagnostics.Process]::Start($psi) # cleaned up by the next one. Set-Content -Path $pidfile -Value $p.Id +# Commands that never produced a prompt. Collected rather than just printed: +# once one command overruns, every later check is reading a transcript that may +# be interleaved, so this has to be visible in the summary and not scrolled past +# in the middle of a long run. +$promptMisses = @() + try { Start-Sleep -Seconds $BootSeconds # wait for the shell prompt @@ -345,29 +351,74 @@ try { # This cannot read QEMU's stdout -- see the header; two attempts at that # deadlocked. It reads the logfile QEMU is writing instead, which is the # same bytes with none of the plumbing. - function Wait-Prompt([int]$TimeoutMs = 20000) { + function Read-Log { + try { $t = Get-Content $log -Raw -ErrorAction Stop } catch { return $null } + if ($null -eq $t) { return '' } + return $t + } + + # Wait for a prompt printed *after* $Since characters of transcript. + # + # Anchoring is not optional. Between writing a command to stdin and the + # guest echoing it, the transcript still ends with the *previous* prompt. + # Matching the whole file sees that stale prompt and returns immediately, + # so the next command is typed on top of one that has not started yet -- + # a false pass that corrupts everything after it. Only text produced since + # the command was sent counts. + # + # The timeout is 60 s rather than 20 s because these tests run under TCG, + # not KVM. Measured on the Fedora laptop with the guest's own /proc/uptime, + # a cold `ls /bin | wc -l` takes 23 s -- it was over the old wall every + # time, and before the region-based allocator landed it took 51 s. A + # timeout only costs time when something is genuinely wrong, whereas one + # that is too short costs a false failure somewhere else entirely. + function Wait-Prompt([int]$Since, [int]$TimeoutMs = 60000) { $deadline = (Get-Date).AddMilliseconds($TimeoutMs) while ((Get-Date) -lt $deadline) { Start-Sleep -Milliseconds 150 - $tail = '' - try { $tail = Get-Content $log -Raw -ErrorAction Stop } catch { continue } - if ($null -eq $tail) { continue } + $t = Read-Log + if ($null -eq $t -or $t.Length -le $Since) { continue } # A prompt at the very end, with nothing typed after it. - if ($tail -match '(?s)#[ ]?$') { return $true } + if ($t.Substring($Since) -match '(?s)#[ ]?$') { return $true } + } + return $false + } + + # Wait for the guest to stop producing output, used only when Wait-Prompt + # has given up. + # + # The old fallback slept two seconds and typed regardless, which is exactly + # how a slow command becomes a failure attributed to a later one: the tty + # echoes the new command, no reader takes it, and it arrives concatenated + # onto the next. Waiting for the transcript to stop growing at least means + # the shell is idle before anything else is sent. + function Wait-Quiet([int]$StableMs = 1500, [int]$TimeoutMs = 45000) { + $deadline = (Get-Date).AddMilliseconds($TimeoutMs) + $last = -1 + $lastChange = Get-Date + while ((Get-Date) -lt $deadline) { + Start-Sleep -Milliseconds 250 + $t = Read-Log + $len = if ($null -eq $t) { -1 } else { $t.Length } + if ($len -ne $last) { $last = $len; $lastChange = Get-Date; continue } + if (((Get-Date) - $lastChange).TotalMilliseconds -ge $StableMs) { return $true } } return $false } foreach ($cmd in $commands) { Write-Host " > $cmd" -ForegroundColor DarkGray + $pre = Read-Log + $since = if ($null -eq $pre) { 0 } else { $pre.Length } foreach ($ch in ($cmd + "`n").ToCharArray()) { $p.StandardInput.Write($ch) $p.StandardInput.Flush() Start-Sleep -Milliseconds 30 # no flow control: pace the input } - if (-not (Wait-Prompt)) { - Write-Host " (no prompt after '$cmd' -- continuing)" -ForegroundColor Yellow - Start-Sleep -Seconds 2 + if (-not (Wait-Prompt $since)) { + $promptMisses += $cmd + Write-Host " (no prompt after '$cmd' -- waiting for the guest to go quiet)" -ForegroundColor Yellow + Wait-Quiet | Out-Null } } @@ -583,5 +634,14 @@ if ($Evdev) { Expect 'value' 'events carry a value, not just a type' } +# A command that never produced a prompt does not fail on its own, but every +# check after it read a transcript that may be interleaved -- so say so next to +# the result rather than only in the scrollback. A FAIL below this line is +# suspect until the transcript has been read. +if ($promptMisses.Count) { + Write-Host "==> $($promptMisses.Count) command(s) never produced a prompt; later output may be interleaved:" -ForegroundColor Yellow + $promptMisses | ForEach-Object { Write-Host " $_" -ForegroundColor Yellow } +} + if ($script:fail) { exit 1 } Write-Host 'boot check passed' -ForegroundColor Green