From 84149ef33b229c7705308a38fc038f63b5cb4d75 Mon Sep 17 00:00:00 2001
From: Emir Beganovic <beganovic.emir@gmail.com>
Date: Mon, 5 Oct 2026 01:20:00 +0200
Subject: [PATCH] test/integration: wall-clock SSH wait with progress

wait_for_ssh counted only its sleeps toward the timeout. Under QEMU user
networking each attempt can also spend its whole ConnectTimeout waiting
for a banner, so a "300 s" wait ran for ten minutes or more without a
line of output. It now uses a wall-clock deadline, polls every 2 s, and
prints a progress line with a console screenshot every 30 s. When the
boot scenario times out it prints the serial console's last lines too.
---
 test/integration.d/base-test.sh | 18 ++++++++++++++----
 test/integration.d/boot-test.sh | 10 ++++++++--
 2 files changed, 22 insertions(+), 6 deletions(-)

diff --git a/test/integration.d/base-test.sh b/test/integration.d/base-test.sh
index 85367d7..901b9e5 100644
--- a/test/integration.d/base-test.sh
+++ b/test/integration.d/base-test.sh
@@ -285,8 +285,12 @@ ssh_sudo() {
   ssh_guest "echo $GUEST_PASSWORD | sudo -S -p '' bash -c $(printf %q "$1")"
 }
 
+# The deadline is wall-clock: under QEMU user networking every attempt can
+# spend its whole ConnectTimeout waiting for a banner, so counting only the
+# sleeps let a "300 s" wait run for ten minutes or more, silently.
 wait_for_ssh() {
-  local timeout="$1" failure_name="${2:-failure-ssh-timeout}" waited=0
+  local timeout="$1" failure_name="${2:-failure-ssh-timeout}"
+  local started=$SECONDS next_note=30 progress_name
 
   while ! ssh_guest true 2>/dev/null; do
     if ! vm_running; then
@@ -294,14 +298,20 @@ wait_for_ssh() {
       return 1
     fi
 
-    if ((waited >= timeout)); then
+    if ((SECONDS - started >= timeout)); then
       capture_console "$failure_name"
       echo "Timed out after ${timeout}s waiting for SSH" >&2
       return 1
     fi
 
-    sleep 5
-    ((waited += 5))
+    if ((SECONDS - started >= next_note)); then
+      printf -v progress_name 'waiting-ssh-%04ds' "$((SECONDS - started))"
+      capture_console "$progress_name"
+      echo "    ... waiting for SSH ($((SECONDS - started))s)"
+      ((next_note += 30))
+    fi
+
+    sleep 2
   done
 }
 
diff --git a/test/integration.d/boot-test.sh b/test/integration.d/boot-test.sh
index a912c8f..7bae941 100755
--- a/test/integration.d/boot-test.sh
+++ b/test/integration.d/boot-test.sh
@@ -12,9 +12,15 @@ base_image_ready || { echo "No base image; run this through ./test/integration"
 log "Booting the installed system"
 boot_started=$(date +%s%N)
 start_vm_from_base
-wait_for_ssh 300 failure-boot-ssh-timeout || exit 1
+if ! wait_for_ssh 300 failure-boot-ssh-timeout; then
+  # The console screenshot is saved; the serial log shows what the firmware,
+  # loader and kernel printed, which a screenshot of a hung boot often lacks.
+  echo "--- last lines of the serial console ---" >&2
+  tail -n 40 "$RUN_DIR/serial.log" >&2 2>/dev/null || true
+  exit 1
+fi
 boot_ms=$((($(date +%s%N) - boot_started) / 1000000))
-# Coarse: wait_for_ssh polls every 5 s. systemd-analyze below has the exact
+# Coarse: wait_for_ssh polls every 2 s. systemd-analyze below has the exact
 # firmware, loader, kernel and userspace split.
 log "SSH answered within ${boot_ms} ms of power-on"