diff --git a/pithead b/pithead index 3553f102..5f321b4a 100755 --- a/pithead +++ b/pithead @@ -1987,7 +1987,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 @@ -2012,7 +2012,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. @@ -2175,8 +2199,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 cfcb2347..05206e3e 100755 --- a/tests/stack/run.sh +++ b/tests/stack/run.sh @@ -8796,6 +8796,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)