Show progress while the smoketest waits on a VM

The waits for SSH, GNOME and a reboot say what they're waiting for and
repeat it once a minute, and the base build says when it's waiting for
cloud-init, installing GNOME and shutting down.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

lib/smoketest.sh

@@ -261,7 +261,9 @@ build_base_image() {
     vm_start "$build" "$build/disk.qcow2" -cdrom "$build/seed.iso"
     trap vm_kill EXIT
     wait_for_ssh
+    echo "Waiting for cloud-init to set up the VM's user..."
     vm_ssh 'cloud-init status --wait' < /dev/null > /dev/null || true
+    echo "Installing GNOME (vm/provision.sh)..."
     vm_put "$(sibling_dir)/vm/provision.sh" /tmp/provision.sh || die "Couldn't copy provision.sh to the VM."
     vm_exec 'sudo bash /tmp/provision.sh' || die "Provisioning failed; see $build/build.log"
     vm_stop

lib/vm.sh

@@ -109,26 +109,51 @@ vm_ssh_command() {
   echo "ssh -i $SSH_KEY -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -p $VM_PORT $VM_USER@127.0.0.1"
 }
 
+# Progress for the long waits: wait_begin says what it's waiting for, and
+# wait_tick, called in the wait's loop, says so again once a minute
+wait_begin() {
+  WAIT_WHAT="$1"
+  WAIT_START=$SECONDS
+  WAIT_NEXT=$((SECONDS + 60))
+  echo "$1..."
+}
+
+wait_tick() {
+  (( SECONDS >= WAIT_NEXT )) || return 0
+  echo "  still $WAIT_WHAT ($(( (SECONDS - WAIT_START) / 60 )) min)"
+  WAIT_NEXT=$((WAIT_NEXT + 60))
+}
+
+wait_done() {
+  echo "  done after $(( SECONDS - WAIT_START ))s"
+}
+
 wait_for_ssh() {
   local deadline=$((SECONDS + VM_SSH_TIMEOUT))
+  wait_begin "waiting for the VM to boot and answer on SSH (its console: $VM_DIR/serial.log)"
   until vm_ssh true < /dev/null 2> /dev/null; do
     vm_running || die "The VM stopped. Its console log: $VM_DIR/serial.log"
     (( SECONDS < deadline )) || die "The VM didn't answer on SSH. Its console log: $VM_DIR/serial.log"
+    wait_tick
     sleep 5
   done
+  wait_done
 }
 
 # Wait for the automatic GNOME login. Not fatal: the health checks catch a
 # desktop that didn't start.
 wait_for_desktop() {
   local deadline=$((SECONDS + VM_DESKTOP_TIMEOUT))
+  wait_begin "waiting for GNOME to start in the VM"
   until vm_ssh "pgrep -u $VM_USER -x gnome-shell" < /dev/null &> /dev/null; do
     if (( SECONDS >= deadline )); then
       echo "Warning: GNOME didn't start in the VM within ${VM_DESKTOP_TIMEOUT}s."
       return 0
     fi
+    wait_tick
     sleep 5
   done
+  wait_done
 }
 
 vm_wait_up() {
@@ -160,17 +185,21 @@ vm_reboot() {
   echo "== reboot"
   before="$(vm_boot_id)"
   vm_ssh 'sudo systemctl reboot' < /dev/null &> /dev/null || true
+  wait_begin "waiting for the VM to come back"
   until [ "$(vm_boot_id)" != "$before" ] && [ -n "$(vm_boot_id)" ]; do
     vm_running || die "The VM stopped while rebooting. Its console log: $VM_DIR/serial.log"
     (( SECONDS < deadline )) || die "The VM didn't come back after rebooting. Its console log: $VM_DIR/serial.log"
+    wait_tick
     sleep 5
   done
+  wait_done
   wait_for_desktop
 }
 
 # Shut the VM down cleanly (so its disk can be kept), killing it if it hangs
 vm_stop() {
   vm_running || return 0
+  echo "Shutting down the VM..."
   vm_ssh 'sudo systemctl poweroff' < /dev/null &> /dev/null || true
   local deadline=$((SECONDS + 120))
   while vm_running && (( SECONDS < deadline )); do

tests/smoketest.bats

@@ -170,3 +170,14 @@ last_run() {
   [[ "$output" == *"base       built"* ]]
   [[ "$output" == *"installed  not built"* ]]
 }
+
+@test "long waits say what they're waiting for, then again once a minute" {
+  run bash -c 'source "$1"; wait_begin "waiting for X"; wait_tick
+    SECONDS=61; wait_tick; wait_tick; SECONDS=125; wait_tick; wait_done' _ "$PROJECT/lib/vm.sh"
+  [ "$status" -eq 0 ]
+  [ "${lines[0]}" = "waiting for X..." ]
+  [ "${lines[1]}" = "  still waiting for X (1 min)" ]
+  [ "${lines[2]}" = "  still waiting for X (2 min)" ]
+  [[ "${lines[3]}" == "  done after "*s ]]
+  [ "${#lines[@]}" -eq 4 ]
+}