CI: wait for Xen to start before waiting for test to complete

Add additional stage in console output parsing - wait for first message
from Xen. The message is defined via BOOT_MSG variable. This has two
effects:
- distinguishes failing Xen to load at all from later test failures
- resets timeout when Xen starts loading

The latter is especially relevant for hardware tests where firmware +
network boot may take some time before Xen starts booting. The two-stage
timeout is more robust solution than increasing the overall timeout.
The issue has been observed on some dom0pvh-hvm jobs, at least on
runners hw3 and hw11. This patch is a first stage before qubes-x86-64.sh
is switched to use expect in the next stage.

While at it, consistently use 'expect -re' for all matches. This
especially allows matching newlines ("\n"), which will become relevant
in the next patch. And document variables used in console.exp.

Signed-off-by: Marek Marczykowski-Górecki <marmarek@invisiblethingslab.com>
Reviewed-by: Andrew Cooper <andrew.cooper3@citrix.com>

automation/scripts/console.exp

@@ -1,4 +1,17 @@
 #!/usr/bin/env expect
+#
+# Variables used by this script:
+# - TEST_TIMEOUT: timeout between each *_MSG match
+# - TEST_TIMEOUT_OVERRIDE: when set, overrides TEST_TIMEOUT
+# - TEST_LOG: save console log to this file
+# - TEST_CMD: commands that prints test system console output to stdout - in
+#   qemu tests that's usually qemu itself (with -serial stdio), in hardware
+#   tests that's a command to read serial console
+# - UBOOT_CMD (optional): command to enter at u-boot prompt
+# - BOOT_MSG (optional): initial Xen message to wait for (aka sign-of-life)
+# - LOG_MSG (optional): final console message to wait for
+# - PASSED: message to look for to consider test a success; if LOG_MSG is set,
+#   both LOG_MSG and PASSED must appear (in any order) for test to succeed
 
 if {[info exists env(TEST_TIMEOUT_OVERRIDE)]} {
     set timeout $env(TEST_TIMEOUT_OVERRIDE)
@@ -28,21 +41,25 @@ if {[info exists env(UBOOT_CMD)]} {
     send "$env(UBOOT_CMD)\r"
 }
 
+if {[info exists env(BOOT_MSG)]} {
+    expect -re "$env(BOOT_MSG)"
+}
+
 if {[info exists env(LOG_MSG)]} {
     expect {
-        "$env(PASSED)" {
-            expect "$env(LOG_MSG)"
+        -re "$env(PASSED)" {
+            expect -re "$env(LOG_MSG)"
             exit 0
         }
-        "$env(LOG_MSG)" {
-            expect "$env(PASSED)"
+        -re "$env(LOG_MSG)" {
+            expect -re "$env(PASSED)"
             exit 0
         }
     }
 }
 
 expect {
-    "$env(PASSED)" {
+    -re "$env(PASSED)" {
         exit 0
     }
 }

automation/scripts/qemu-alpine-x86_64.sh

@@ -85,6 +85,7 @@ export TEST_CMD="qemu-system-x86_64 \
     -netdev user,id=n0,tftp=binaries,bootfile=/pxelinux.0"
 
 export TEST_LOG="smoke.serial"
+export BOOT_MSG="Latest ChangeSet: "
 export LOG_MSG="Domain-0"
 export PASSED="BusyBox"
 

automation/scripts/qemu-smoke-dom0-arm32.sh

@@ -92,6 +92,7 @@ export TEST_CMD="./qemu-system-arm \
 
 export UBOOT_CMD="virtio scan; dhcp; tftpb 0x40000000 boot.scr; source 0x40000000"
 export TEST_LOG="${serial_log}"
+export BOOT_MSG="Latest ChangeSet: "
 export LOG_MSG="Domain-0"
 export PASSED="/ #"
 

automation/scripts/qemu-smoke-dom0-arm64.sh

@@ -104,6 +104,7 @@ export TEST_CMD="./binaries/qemu-system-aarch64 \
     -bios /usr/lib/u-boot/qemu_arm64/u-boot.bin"
 
 export UBOOT_CMD="virtio scan; dhcp; tftpb 0x40000000 boot.scr; source 0x40000000"
+export BOOT_MSG="Latest ChangeSet: "
 export TEST_LOG="smoke.serial"
 export LOG_MSG="Domain-0"
 export PASSED="BusyBox"

automation/scripts/qemu-smoke-dom0less-arm32.sh

@@ -144,6 +144,7 @@ export TEST_CMD="./qemu-system-arm \
     -bios /usr/lib/u-boot/qemu_arm/u-boot.bin"
 
 export UBOOT_CMD="virtio scan; dhcp; tftpb 0x40000000 boot.scr; source 0x40000000"
+export BOOT_MSG="Latest ChangeSet: "
 export TEST_LOG="${serial_log}"
 export LOG_MSG="${dom0_prompt}"
 export PASSED="${passed}"

automation/scripts/qemu-xtf-dom0less-arm64.sh

@@ -61,6 +61,7 @@ export TEST_CMD="./binaries/qemu-system-aarch64 \
     -bios /usr/lib/u-boot/qemu_arm64/u-boot.bin"
 
 export UBOOT_CMD="virtio scan; dhcp; tftpb 0x40000000 boot.scr; source 0x40000000"
+export BOOT_MSG="Latest ChangeSet: "
 export TEST_LOG="smoke.serial"
 export PASSED="${passed}"
 

automation/scripts/xilinx-smoke-dom0-x86_64.sh

@@ -159,6 +159,7 @@ stty -F ${SERIAL_DEV} 57600
 
 # Capture test result and power off board before exiting.
 export PASSED="${PASS_MSG}"
+export BOOT_MSG="Latest ChangeSet: "
 export TEST_CMD="cat ${SERIAL_DEV}"
 export TEST_LOG="smoke.serial"
 

automation/scripts/xilinx-smoke-dom0less-arm64.sh

@@ -140,6 +140,7 @@ stty -F ${SERIAL_DEV} 115200
 
 # Capture test result and power off board before exiting.
 export PASSED="${passed}"
+export BOOT_MSG="Latest ChangeSet: "
 export LOG_MSG="Welcome to Alpine Linux"
 export TEST_CMD="cat ${SERIAL_DEV}"
 export TEST_LOG="smoke.serial"