fix(appliance): narrate the slow image load, and say so on every console when setup stops (#1028)

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"

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)