From ab8227e23f5f443ba2ccd29c588996e08d80ecd6 Mon Sep 17 00:00:00 2001 From: Krzysztof kuhy Rudnicki Date: Sat, 22 Aug 2026 23:28:57 +0200 Subject: [PATCH] vmbox: fix the settle gate breaking shutdown verdicts on the serial transport The previous commit skipped the poweroff settle when `ssh_rc != 255`, on the reasoning that a successful poweroff kills the ssh connection and ssh reports 255. That holds for the ssh transport and for nothing else. `_run_transport` falls back to the serial console whenever ssh does not answer -- and the README calls serial "the transport of record for shutdown tests" -- where the exit code comes from serial_exec.py and is 0 even while the machine is already on its way down. Result, reproduced: `VMBOX_TRANSPORT=serial vm run 'sudo systemctl poweroff'` reported "still running" for a guest that had cleanly powered off, with SHUTDOWN{guest:true} in events.jsonl and "reboot: Power down" in the serial log. The one thing this tool exists to get right, silently wrong. My five verdict re-tests all went through ssh, so none of them caught it. Grepping the serial log for shutdown markers instead does not work either: they land a second or two after the command returns, so the check loses the race. The fix waits a short grace period (default 3s) for any sign of a stop before committing to the 30s wait. Warm runs go from 0s to 3s; that is the honest price of a correct verdict. Re-tested: clean poweroff, reboot and panic on BOTH transports, plus tests/destructive_demo.sh 7/7. Also, per "a fix that needs a human to remember a flag is not a fix": the X session wait is now automatic on the branch that actually boots the guest -- the only one that can race tty1's autologin -- instead of requiring VMBOX_X_WAIT. Warm runs never reach that branch. The env var remains an override. README numbers corrected to the measured 14s/3s and ~100s. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01VdyMBGCrGVGDWtJ9xe48f3 --- vmbox/README.md | 9 +++++--- vmbox/SESSION_RESULTS.md | 16 ++++++++++---- vmbox/lib/run.sh | 45 ++++++++++++++++++++++++++++------------ 3 files changed, 50 insertions(+), 20 deletions(-) diff --git a/vmbox/README.md b/vmbox/README.md index 9cfeded..5971301 100644 --- a/vmbox/README.md +++ b/vmbox/README.md @@ -6,7 +6,7 @@ host**. Break it as thoroughly as you like; reset takes under a second. ```bash ./install.sh # installs deps (libisoburn), links `vm` onto PATH -vm build # builds the golden image, once (~90s) +vm build # builds the golden image, once (~100s) vm new demo # instant: a ~200 KB overlay on the sealed base vm run demo 'sudo systemctl poweroff' vm reset demo # back to pristine @@ -140,14 +140,17 @@ Measured on this host, all with the cloud image already downloaded: | | before | after | |---|---|---| -| `vm run` (cold sandbox) | 41s | 12s | -| `vm run` (warm sandbox) | 30s | 0s | +| `vm run` (cold sandbox) | 41s | 14s | +| `vm run` (warm sandbox) | 30s | 3s | Neither number was the guest being slow. `_run_settle` waited up to 30s for a poweroff marker on EVERY run, including the majority that leave the guest running, and the ssh readiness poll used a 5s connect timeout against a forwarded port QEMU accepts before the guest is listening on it. +A cold `vm run` also waits for the guest's X session, because sshd now answers +before tty1's autologin has started Xorg; `VMBOX_X_WAIT=` overrides it. + The build reads packages from the host's own `/var/cache/pacman/pkg`, mounted read-only, rather than fetching 396 MiB over the internet. The guest keeps its own writable cache, so a package the host lacks is downloaded as usual. See diff --git a/vmbox/SESSION_RESULTS.md b/vmbox/SESSION_RESULTS.md index 3999667..59657db 100644 --- a/vmbox/SESSION_RESULTS.md +++ b/vmbox/SESSION_RESULTS.md @@ -116,8 +116,8 @@ boot, and I did not find the mechanism. NOT DONE -- see "still open". ### The real win was elsewhere: `vm run` got 3-4x faster Chasing the build number turned up two flat taxes on EVERY sandbox command: - vm run, cold sandbox 41s -> 12s - vm run, warm sandbox 30s -> 0s + vm run, cold sandbox 41s -> 14s (includes waiting for the X session) + vm run, warm sandbox 30s -> 3s - `_run_settle` waited up to 30s for the kernel's "reboot: Power down" marker unconditionally, including on the majority of runs that leave the guest @@ -127,8 +127,16 @@ Chasing the build number turned up two flat taxes on EVERY sandbox command: probe blocked for the full timeout instead of failing fast: a guest reachable at ~10s was reported up at ~45s. -All five shutdown verdicts re-tested afterwards (clean poweroff / dirty / -reboot / panic / still-running) -- unchanged. +All five shutdown verdicts re-tested on BOTH transports (ssh and serial), plus +tests/destructive_demo.sh 7/7. + +A first attempt at this gated the skip on the transport's exit code, which +BROKE the serial path: ssh returns 255 for a poweroff but serial_exec returns +0 while the machine is already going down, so a clean serial-driven poweroff +was reported as "still running" -- vmbox's whole purpose, silently wrong. +Grepping the serial log at that instant does not work either (the markers +appear a second or two later). The shipped version waits a short grace period +for any sign of a stop before committing to the long wait. ### Host cache safety (Q7's gate) Fingerprinted before and after FOUR full builds: 45427 files, diff --git a/vmbox/lib/run.sh b/vmbox/lib/run.sh index e5257c3..28628a8 100644 --- a/vmbox/lib/run.sh +++ b/vmbox/lib/run.sh @@ -52,6 +52,13 @@ run_in_vm() { else serial_n="$(launch_vm "$name")" vm_wait_ssh "$name" 150 || die "sandbox '$name' did not become reachable" + # This run booted the guest, so it is the ONLY one that can race the + # tty1 autologin that starts Xorg -- sshd answers first. Give the X + # session a default window to appear here rather than requiring the + # caller to remember a flag; a warm run never reaches this branch and + # so never pays for it. Explicit VMBOX_X_WAIT still wins. + : "${VMBOX_X_WAIT:=${VMBOX_X_WAIT_ON_BOOT:-20}}" + export VMBOX_X_WAIT fi serial="$(vm_serial "$name" "$serial_n")" events="$(vm_events "$name")" @@ -109,22 +116,34 @@ _run_exec_serial() { "$(_guest_env_setup) { $cmd ; } ; echo \$? > $RC_PATH" } -# Give a guest that is SHUTTING DOWN time to finish writing its serial log. +# Give a guest that is shutting down time to finish writing its serial log. # -# Only a guest that is actually stopping needs this. The first loop used to -# run unconditionally, so every ordinary `vm run` -- the overwhelming majority, -# which leave the guest running -- paid a flat 30s waiting for a poweroff -# marker that was never going to appear. That single wait was most of the -# wall-clock cost of running anything at all in a sandbox: 41s for a `true`, -# of which 31s was this. Measured before/after: 41s -> 11s. +# The hard part is deciding, cheaply, whether this run IS a shutdown. The +# transport's exit code cannot answer it: ssh returns 255 for a poweroff but +# serial_exec returns 0 while the machine is already on its way down, so +# keying on that reported a clean serial-driven poweroff as "still running". +# The serial log cannot answer it either at this instant -- the shutdown +# markers appear a second or two later, so grepping for them here just loses +# the race. # -# The ssh transport reports a dropped connection as 255, which is what a -# successful poweroff looks like from the host; a guest that is merely still -# running gives a real exit code. So: settle only when the guest has already -# stopped, or when the connection died in the way a shutdown would cause. +# So: wait a SHORT fixed grace period for any sign of a stop, and only then +# commit to the long wait. Runs that leave the guest up (the overwhelming +# majority) pay the grace period and nothing more; the old code paid the full +# 30s on every one of them, which was most of the wall-clock cost of running +# anything in a sandbox at all -- 41s for a `true`, of which 31s was this. _run_settle() { - local name="$1" serial="$2" ssh_rc="${3:-0}" waited=0 - if vm_is_running "$name" && (( ssh_rc != 255 )); then + local name="$1" serial="$2" ssh_rc="${3:-0}" waited=0 grace="${VMBOX_SETTLE_GRACE:-3}" + while (( grace > 0 )); do + vm_is_running "$name" || break + grep -qa 'System Power Off\|systemd-shutdown\|reboot: ' "$serial" 2>/dev/null && break + (( ssh_rc == 255 )) && break + sleep 1; grace=$(( grace - 1 )) + done + # Nothing suggests a stop: the guest is up, its log is quiet, and the + # transport returned normally. Do not pay the 30s poweroff wait. + if vm_is_running "$name" && + ! grep -qa 'System Power Off\|systemd-shutdown\|reboot: ' "$serial" 2>/dev/null && + (( ssh_rc != 255 )); then return 0 fi while vm_is_running "$name" && (( waited < 30 )); do