bootcheck: make the prompt wait survive a slow guest

Three bugs, all of which surfaced as a failed check somewhere other than
the command that was actually slow.

Wait-Prompt waited a fixed 20 s. These tests run under TCG, not KVM, and
a cold `ls /bin | wc -l` takes 23 s on the Fedora laptop measured with
the guest's own /proc/uptime -- it was over the wall every time. Raised
to 60 s; a long timeout only costs time when something is genuinely
wrong, a short one costs a false failure elsewhere.

It also matched a prompt anywhere in the transcript. Between writing a
command and the guest echoing it the log still ends with the previous
prompt, so it could return before the command had started and the next
one was typed on top of it. Anchor the match to text produced after the
command was sent.

On timeout it slept two seconds and typed regardless, which is what
turned one slow command into an interleaved transcript and a failure
attributed to a later check. Wait for output to stop arriving instead.

Report any command that never produced a prompt next to the result:
after one overrun every later check is reading a transcript that may be
interleaved, and that should not be something you have to notice in the
scrollback.

With this, -Fb -Tty -Usb -Sock -Evdev -Ps is 108 [ok], 0 misses.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
This commit is contained in:
Nexoniarz 2026-08-09 21:18:09 +02:00
commit 6e23d2a466
2 changed files with 89 additions and 18 deletions

View file

@ -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