utils/vmbox/lib/run.sh
Krzysztof kuhy Rudnicki cb3c985ee6 vmbox: 3-4x faster runs, a read-only host package cache, and vm scp
`vm run` took 41s cold / 30s warm to run `true`. Both were vmbox waiting on
itself. Now 12s / 0s, with all five shutdown verdicts re-tested unchanged.

- _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 up,
  where that marker is never going to appear. It now settles only when the
  guest has actually stopped, or when ssh returned 255 (what a successful
  poweroff looks like from the host).

- The ssh readiness polls used a 5s ConnectTimeout. QEMU's user-mode
  networking ACCEPTS the forwarded connection while the guest still has
  nothing on :22, so each probe blocked for the full timeout instead of
  failing fast: a guest reachable at ~10s was reported up at ~45s. Fixed in
  both the sandbox and build paths, via an env override -- ssh honours the
  FIRST value for an option, so a second -o could not have worked.

Making runs fast exposed a race: sshd now answers BEFORE tty1's autologin has
started Xorg, so the X environment could be missing on the first run after a
boot. `VMBOX_X_WAIT=<seconds>` waits for the session; it defaults to 0 so an
ordinary run never pays for a graphical session it is not using.

Build: the host's /var/cache/pacman/pkg is offered to the build guest
read-only (`readonly=on` AND an `ro` mount, because it is the real host cache)
as an extra CacheDir after the guest's own writable one, so a package the host
lacks still downloads rather than failing the build. This removes the 396 MiB
the build used to fetch. Host cache verified byte-for-byte identical across
four builds: same file count, same size, same mtime.

Build time itself moved only 103.8s -> 100.3s. Per-phase timings (also added
here) show why: 47s of it is the build guest's cloud-init first boot, and that
is NOT datasource probing -- `cloud-init analyze blame` totals 2.27s. Left
unexplained rather than guessed at; SESSION_RESULTS.md records the evidence.

Also: `vm scp`, which lib/ssh.sh could always do but the CLI never exposed,
and provision.sh split at the 250-line cap.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01VdyMBGCrGVGDWtJ9xe48f3
2026-08-22 23:17:21 +02:00

207 lines
8.6 KiB
Bash

#!/bin/bash
# ============================================================================
# vmbox: run a command in a sandbox and report what happened to the machine.
#
# The hard case is a command that powers the guest off (the whole point of the
# tool). ssh cannot report that: the connection dies with the machine and
# returns 255, the same value it returns for a crash or a dropped link. So the
# exit code is written to disk INSIDE the guest, and recovered afterwards from
# the overlay -- which survives the poweroff -- while the verdict comes from
# host-side QMP/serial evidence.
# ============================================================================
# shellcheck source=common.sh
source "$(dirname "${BASH_SOURCE[0]}")/common.sh"
source "$(dirname "${BASH_SOURCE[0]}")/launch.sh"
source "$(dirname "${BASH_SOURCE[0]}")/ssh.sh"
source "$(dirname "${BASH_SOURCE[0]}")/verdict.sh"
readonly RC_PATH="/var/tmp/vmbox.rc"
# Sourced before every guest command so X11 tests can reach the guest's own
# i3 session. `sh -c` reads no profile, so without this DISPLAY/XAUTHORITY are
# unset and every X tool fails as if the sandbox had no X server at all.
# The `[ -f ]` guard is load-bearing, not defensive dressing: in POSIX sh, `.`
# on a missing file is a SPECIAL BUILTIN error that exits the shell outright,
# and `|| true` does NOT rescue it. Written that way, every `vm run` against a
# base image predating this snippet silently produced no output at all.
# Built at call time, not as a constant, so the host's VMBOX_X_WAIT is baked
# in by VALUE -- a single-quoted constant would ship the literal ${...} text.
_guest_env_setup() {
printf 'export VMBOX_X_WAIT=%s; [ -f /etc/profile.d/vmbox-x11.sh ] && . /etc/profile.d/vmbox-x11.sh;' \
"${VMBOX_X_WAIT:-0}"
}
# Transport for guest commands. Serial is the default for shutdown work: it
# keeps printing through the poweroff that kills ssh, and it still works when
# sshd does not. ssh stays available as the faster path for bulk work.
readonly VMBOX_TRANSPORT="${VMBOX_TRANSPORT:-auto}"
readonly VMBOX_RUN_TIMEOUT="${VMBOX_RUN_TIMEOUT:-600}"
# Bounds for the post-verdict exit-code recovery boot (see _run_recover_rc).
readonly RECOVER_SSH_TIMEOUT="${VMBOX_RECOVER_SSH_TIMEOUT:-60}"
readonly RECOVER_SERIAL_TIMEOUT="${VMBOX_RECOVER_SERIAL_TIMEOUT:-30}"
run_in_vm() {
local name
name="$(validate_vm_name "${1:-}")"; shift || true
require_vm "$name"
[[ $# -gt 0 ]] || die "usage: vm run <name> <command...>"
local serial_n serial events
if vm_is_running "$name"; then
serial_n="$(( $(vm_next_serial "$name") - 1 ))"
(( serial_n < 0 )) && serial_n=0
else
serial_n="$(launch_vm "$name")"
vm_wait_ssh "$name" 150 || die "sandbox '$name' did not become reachable"
fi
serial="$(vm_serial "$name" "$serial_n")"
events="$(vm_events "$name")"
# Record where the verdict should start reading, so a previous boot's
# shutdown event is never mistaken for this run's outcome.
local events_before=0
[[ -f "$events" ]] && events_before=$(wc -l < "$events")
log "Running in '$name': $*"
# `|| ssh_rc=$?` is load-bearing: under `set -e` a bare call would abort
# the script when ssh returns 255 -- which is precisely what a SUCCESSFUL
# guest poweroff causes. The verdict would then never be printed for the
# one case this tool exists to report on.
local ssh_rc=0
_run_exec "$name" "$@" || ssh_rc=$?
_run_settle "$name" "$serial" "$ssh_rc" || true
local frc=0
_run_finish "$name" "$serial" "$events" "$events_before" "$ssh_rc" || frc=$?
return "$frc"
}
# stdin is closed: several target installers prompt, and an inherited terminal
# would make them block forever instead of taking their default.
_run_exec() {
local name="$1"; shift
local cmd="$*"
case "$(_run_transport "$name")" in
serial) _run_exec_serial "$name" "$cmd" ;;
*) vm_ssh_exec "$name" \
"sh -c '$(_guest_env_setup) { $cmd; } ; echo \$? | sudo tee $RC_PATH >/dev/null' </dev/null" \
</dev/null ;;
esac
}
# Prefer ssh when it answers (faster, cleaner), else drive the serial console.
_run_transport() {
local name="$1"
case "$VMBOX_TRANSPORT" in
ssh|serial) printf '%s' "$VMBOX_TRANSPORT"; return ;;
esac
if vm_ssh_exec "$name" -o BatchMode=yes -o ConnectTimeout=4 true 2>/dev/null; then
printf 'ssh'
else
printf 'serial'
fi
}
_run_exec_serial() {
local name="$1" cmd="$2" console
console="$(vm_console "$name")"
[[ -S "$console" ]] || die "no serial console socket for '$name'"
python3 "$VMBOX_LIB_DIR/serial_exec.py" "$console" \
"$(_guest_env_setup) { $cmd ; } ; echo \$? > $RC_PATH"
}
# 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 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.
_run_settle() {
local name="$1" serial="$2" ssh_rc="${3:-0}" waited=0
if vm_is_running "$name" && (( ssh_rc != 255 )); then
return 0
fi
while vm_is_running "$name" && (( waited < 30 )); do
grep -qa "$POWEROFF_MARKER" "$serial" 2>/dev/null && break
sleep 1; waited=$(( waited + 1 ))
done
# Let qemu actually exit after the marker appears.
waited=0
while vm_is_running "$name" && (( waited < 15 )); do
grep -qa "$POWEROFF_MARKER" "$serial" 2>/dev/null || break
sleep 1; waited=$(( waited + 1 ))
done
}
_run_finish() {
local name="$1" serial="$2" events="$3" events_before="$4" ssh_rc="$5"
# Only consider events produced by THIS run.
local scoped="$events.scoped"
if [[ -f "$events" ]]; then
tail -n +$(( events_before + 1 )) "$events" > "$scoped" 2>/dev/null || : > "$scoped"
else
: > "$scoped"
fi
echo
local vrc=0
verdict_report "$name" "$serial" "$scoped" || vrc=$?
rm -f "$scoped"
# If the guest stopped, recover the real exit code from the overlay.
if ! vm_is_running "$name"; then
local rc
rc="$(_run_recover_rc "$name")"
if [[ -n "$rc" ]]; then
log "command exit code (recovered from the stopped guest): $rc"
return "$rc"
fi
log "no exit code recorded (the command never returned before the machine stopped)"
return "$vrc"
fi
if (( ssh_rc == 255 )); then
warn "ssh reported 255 but the guest is still running -- connection issue, not a shutdown"
fi
return "$ssh_rc"
}
# Boot the sandbox again just far enough to read the recorded exit code.
# The overlay survives the poweroff, so the value written before the machine
# stopped is still there.
#
# Every wait here is BOUNDED, because this runs after the verdict has already
# been printed: it is a best-effort nicety, never a reason to hang. The guest
# being tested may well be unbootable -- that is a normal outcome for a
# sandbox, not an error. A boot-repair run that deleted /boot/vmlinuz left a
# guest sitting at a GRUB prompt, and the unbounded console read then blocked
# for 480s AFTER "VERDICT: clean poweroff" had been reported, which reads as
# a hung tool rather than a recovered exit code.
_run_recover_rc() {
local name="$1" rc="" console
launch_vm "$name" >/dev/null 2>&1 || return 0
if vm_wait_ssh "$name" "$RECOVER_SSH_TIMEOUT"; then
rc="$(vm_ssh_exec "$name" "cat $RC_PATH 2>/dev/null" 2>/dev/null | tr -dc '0-9')"
else
# ssh may be broken or simply slower than the console; the serial
# shell can read the file just as well -- but only give it a short
# window, since an unbootable guest never produces a prompt at all.
console="$(vm_console "$name")"
if [[ -S "$console" ]]; then
rc="$(VMBOX_SERIAL_PROMPT_TIMEOUT="$RECOVER_SERIAL_TIMEOUT" \
VMBOX_SERIAL_RUN_TIMEOUT="$RECOVER_SERIAL_TIMEOUT" \
python3 "$VMBOX_LIB_DIR/serial_exec.py" "$console" \
"cat $RC_PATH 2>/dev/null" 2>/dev/null | grep -oE '^[0-9]+' | head -1)"
fi
fi
printf '%s' "$rc"
}