From c05ecb1ac67b31592e1499fefafae3909522dcd8 Mon Sep 17 00:00:00 2001 From: Vijit Singh Date: Sun, 16 Aug 2026 09:49:44 -0500 Subject: [PATCH] fix(appliance): narrate the slow image load, and say so on every console when setup stops (#1028) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two halves of the same problem: a first boot that is working and a first boot that has died looked identical on the console, and both looked like "still starting". The load. `podman load` prints nothing a console ever sees, and on USB media the step runs for minutes — 3m47s measured on the HP bench — behind a line promising "a minute or two". A working box was read as hung twice, once from the console photo and once live. A rising elapsed count is the whole fix: it is the one thing that separates slow from stuck. Every 30s, so a four-minute load costs eight lines. The heartbeat is the background job and the load stays in the FOREGROUND. Backgrounding the load and polling it with `kill -0` looks equivalent and is not: a finished-but-unwaited child is a zombie that still answers, so a fast load would pay a full sleep interval for work already done. Keeping the load in front also preserves its exit status untouched. The failure. `error` writes to stderr, which systemd routes to /dev/console — ONE device, whichever the kernel cmdline named last. On a box whose monitor is not that device a fatal failure is invisible, so the newest line on screen stays "preparing the setup page" and a stopped box reads as a slow one for as long as the operator is willing to wait. That is exactly how a three-minute failure was mistaken for an hour of progress. The wizard's fatal path now says it through _console, which reaches every physical console, and names the command that explains why. Four unit tests, including the fast-load case that fails if the zombie race is reintroduced. The heartbeat interval takes a test seam so the slow case runs in seconds rather than minutes. Co-Authored-By: Claude Opus 5 --- pithead | 40 +++++++++++++++++++++++++++++++++++++--- tests/stack/run.sh | 43 +++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 80 insertions(+), 3 deletions(-) diff --git a/pithead b/pithead index 8dd8cd98..8f55556b 100755 --- a/pithead +++ b/pithead @@ -1972,7 +1972,7 @@ repair_broken_image_store() { # $1: container engine load_baked_images() { # $1 (optional): image ref whose absence forces a load despite a matching digest local required="${1:-}" dir="${PITHEAD_IMAGES_DIR:-/opt/pithead/images}" - local engine archive sha rec recorded + local engine archive sha rec recorded load_pid t0 load_rc engine=$(container_engine) # Before trusting any digest record: a record describes what was LOADED, and the check below # only asks whether the image still EXISTS. A store damaged as described above satisfies both @@ -1997,7 +1997,31 @@ load_baked_images() { # $1 (optional): image ref whose absence forces a load des # The single slowest step of a first or post-update boot, and the one worth narrating. _console "Loading this build's container images ($(basename "$archive")) — the slow part..." mkdir -p "$PWD/data" 2>/dev/null || true - if "$engine" load -i "$archive" >/dev/null 2>&1; then + # `podman load` prints nothing a console ever sees, and on USB media this step runs for + # MINUTES — measured at 3m47s on the bench, behind a line promising "a minute or two". + # A box that is working then looks exactly like a box that has hung, and it was read as + # hung twice. A rising elapsed count is the whole fix: it is the one thing that tells + # slow apart from stuck. 30s, so a four-minute load costs eight lines, not sixteen. + # + # The HEARTBEAT is what gets backgrounded, never the load: keeping the load in the + # foreground preserves its exit status exactly, and sidesteps the zombie race that + # polling a background pid with `kill -0` would introduce (a reaped-but-not-yet-waited + # child still answers, so a FAST load would pay a full sleep for nothing). + t0=$(date +%s) + ( + while :; do + sleep "${PITHEAD_LOAD_HEARTBEAT_SECS:-30}" + _console " still loading — $(($(date +%s) - t0))s elapsed, this is normal on USB media" + done + ) & + load_pid=$! + load_rc=0 + "$engine" load -i "$archive" >/dev/null 2>&1 || load_rc=$? + # Stopped on BOTH paths, and before the branch, so no arm can leak a heartbeat that + # narrates a load which already finished. + kill "$load_pid" 2>/dev/null || true + wait "$load_pid" 2>/dev/null || true + if [ "$load_rc" -eq 0 ]; then printf '%s' "$sha" >"$rec" 2>/dev/null || true # unrecorded -> reloads next boot else # No record on failure, on purpose: the next boot must retry, not skip. @@ -2160,8 +2184,18 @@ firstboot_wizard() { -e WIZARD_TLS_CERT="${cert_fp:+/wizard-spool/wizard.crt}" \ -e WIZARD_TLS_KEY="${cert_fp:+/wizard-spool/wizard.key}" \ -v "$spool":/wizard-spool \ - "$image" -m mining_dashboard.wizard >/dev/null || + "$image" -m mining_dashboard.wizard >/dev/null || { + # `error` writes to stderr, which systemd routes to /dev/console — ONE device, + # whichever the kernel cmdline named LAST. On a box whose monitor is not that device + # the failure is invisible, so the newest thing on screen stays "preparing the setup + # page" and a STOPPED box reads as a slow one for as long as the operator is willing + # to wait. That is how a three-minute failure was mistaken for an hour of progress. + # _console reaches every physical console, which is the whole point here. + _console "" "Setup has STOPPED — this box is no longer preparing a page." \ + "The container engine could not start the setup page." \ + "Diagnose with: journalctl -u pithead-firstboot -b" error "Could not start the wizard container ($engine, $image). Pre-seed config.json or run '$0 firstboot-wizard --cli'." + } local mdns_name scheme mdns_name="$(hostname).local" scheme="http" diff --git a/tests/stack/run.sh b/tests/stack/run.sh index 4f4e2245..95481a69 100755 --- a/tests/stack/run.sh +++ b/tests/stack/run.sh @@ -8684,6 +8684,49 @@ unset -f rbl mk_store rm -rf "$RSB" unset RSB +echo "== unit: load_baked_images — a slow load narrates itself, a fast one stays quiet ==" +# `podman load` prints nothing a console sees and runs for MINUTES on USB media (3m47s measured +# on the bench) behind a line promising "a minute or two" — so a working box looked hung, twice. +# A rising elapsed count is what tells slow apart from stuck. The load stays in the FOREGROUND +# and the heartbeat is the background job: polling a backgrounded load with `kill -0` would make +# a fast load pay a full sleep, because a finished-but-unwaited child still answers. +HSB=$(mktemp -d) +mkdir -p "$HSB/images" "$HSB/bin" "$HSB/data" +printf 'archive' >"$HSB/images/dashboard.tar.gz" +cat >"$HSB/bin/podman" <<'EOF' +#!/usr/bin/env bash +case "$1" in +info) printf '%s\n' "${FAKE_GRAPHROOT:-}" ;; +image) exit 1 ;; +load) sleep "${FAKE_LOAD_SECS:-0}" ;; +rm) exit 0 ;; +esac +EOF +chmod +x "$HSB/bin/podman" +export PITHEAD_IMAGES_DIR="$HSB/images" FAKE_GRAPHROOT="" PITHEAD_LOAD_HEARTBEAT_SECS=1 +hbl() { PITHEAD_ENGINE=podman PATH="$HSB/bin:$PATH" run_sourced "$HSB" load_baked_images 2>&1; } + +export FAKE_LOAD_SECS=3 +hout=$(hbl) +assert_contains "a slow load reports it is still working" "$hout" "still loading" +assert_contains "the heartbeat carries elapsed seconds" "$hout" "elapsed" + +rm -f "$HSB/data/.loaded-dashboard.tar.gz.sha" +export FAKE_LOAD_SECS=0 +hstart=$(date +%s) +hout=$(hbl) +hlen=$(($(date +%s) - hstart)) +printf '%s' "$hout" | grep -q "still loading" && + bad "a fast load stays quiet" "heartbeat fired anyway" || + ok "a fast load stays quiet — no heartbeat for work already done" +[ "$hlen" -lt 3 ] && + ok "a fast load does not wait on the heartbeat interval (${hlen}s)" || + bad "a fast load returns promptly" "took ${hlen}s" +unset PITHEAD_IMAGES_DIR FAKE_GRAPHROOT PITHEAD_LOAD_HEARTBEAT_SECS FAKE_LOAD_SECS +unset -f hbl +rm -rf "$HSB" +unset HSB hout hstart hlen + echo "== unit: pre-seeding from the installation medium ==" # The ESP is FAT and anyone can write it, so both readers treat its contents as input, not truth. PSD=$(mktemp -d)