Merge pull request grml#328 from grml/tap

Improve test stability

tests/build-vm-and-test.sh

@@ -33,7 +33,7 @@ fi
 
 if [ "$1" == "setup" ]; then
   sudo apt-get update
-  sudo apt-get -qq -y install curl kpartx python3-pexpect python3-serial
+  sudo apt-get -qq -y install curl kpartx python3-serial
   DPKG_ARCHITECTURE=$(dpkg --print-architecture)
   if [ "${DPKG_ARCHITECTURE}" = "amd64" ]; then
     sudo apt-get -qq -y install qemu-system qemu-system-gui ovmf seabios

tests/serial-console-connection

@@ -1,21 +1,22 @@
 #!/usr/bin/env python3
 import argparse
+import re
 import serial
 import os
 import shutil
 import subprocess
 import sys
 import time
-from pexpect import fdpexpect
 
 parser = argparse.ArgumentParser(
     description="Connect to serial console to execute stuff",
     formatter_class=argparse.ArgumentDefaultsHelpFormatter,
 )
 parser.add_argument(
-    "--port",
+    "--qemu-log",
+    dest="qemu_log",
     required=True,
-    help="serial console device to connect " + "to (e.g. /dev/pts/X)",
+    help="QEMU log to look for serial port info in",
 )
 parser.add_argument(
     "--hostname", default="trixie", help="hostname of the system for login process"
@@ -59,27 +60,48 @@ def write_ser_line(ser, text):
     ser.flush()
 
 
-def login(ser, hostname, user, password, timeout=5):
+def wait_ser_text(ser, texts, timeout):
+    if isinstance(texts, str):
+        texts = [texts]
 
-    child = fdpexpect.fdspawn(ser.fileno())
-    child.sendline("\n")
+    ts_max = time.time() + timeout
+    ser.timeout = 1
+    texts_encoded = [text.encode("utf-8") for text in texts]
+    found = False
+    print(time.time(), "D: expecting one of", texts_encoded)
+    while ts_max > time.time() and found is False:
+        for line in ser.readlines():
+            print(time.time(), "<<", line)  # line will be a binary string
+            for index, text in enumerate(texts_encoded):
+                if text in line:
+                    found = texts[index]
+                    break
+    return found
 
-    try:
-        child.expect("%s@%s" % (user, hostname), timeout=timeout)
+
+def login(ser, hostname, user, password, timeout):
+    login_prompt = "%s login:" % hostname
+    shell_prompt = "%s@%s" % (user, hostname)
+
+    write_ser_line(ser, "")  # send newline
+
+    found = wait_ser_text(ser, [shell_prompt, login_prompt], timeout=timeout * 4)
+    if found == shell_prompt:
         return
-    except:
-        pass
+    elif found is False:
+        raise ValueError("timeout waiting for login prompt")
 
-    print("Waiting for login prompt...")
-    child.expect("%s login:" % hostname, timeout=timeout)
     print("Logging in...")
     write_ser_line(ser, user)
-    time.sleep(1)
+    if not wait_ser_text(ser, "Password:", timeout=timeout):
+        raise ValueError("timeout waiting for password prompt")
+
     write_ser_line(ser, password)
     time.sleep(1)
 
-    print("Waiting for shell prompt...")
-    child.expect("%s@%s" % (user, hostname), timeout=timeout)
+    print(time.time(), "Waiting for shell prompt...")
+    if not wait_ser_text(ser, shell_prompt, timeout=timeout * 4):
+        raise ValueError("timeout waiting for shell prompt")
 
 
 def capture_vnc_screenshot(screenshot_file):
@@ -97,15 +119,42 @@ def capture_vnc_screenshot(screenshot_file):
         print("Screenshot file '%s' available" % os.path.abspath(screenshot_file))
 
 
+def find_serial_port_from_qemu_log(qemu_log, tries):
+    port = None
+    for i in range(tries):
+        print("Waiting for qemu to present serial console [try %s]" % (i, ))
+        with open(qemu_log, "r", encoding="utf-8") as fp:
+            qemu_log_messages = fp.read().splitlines()
+        for line in qemu_log_messages:
+            m = re.match("char device redirected to ([^ ]+)", line)
+            if m:
+                port = m.group(1)
+                break
+        if port:
+            break
+        time.sleep(5)
+
+    print("qemu log (up to char device redirect) follows:")
+    print("\n".join(qemu_log_messages))
+    print()
+    return port  # might be None, caller has to deal with it
+
+
 def main():
     args = parser.parse_args()
     hostname = args.hostname
     password = args.password
-    port = args.port
+    qemu_log = args.qemu_log
     user = args.user
     commands = args.command
     screenshot_file = args.screenshot
 
+    port = find_serial_port_from_qemu_log(qemu_log, args.tries)
+    if not port:
+        print()
+        print("E: no serial port found in qemu log", qemu_log)
+        sys.exit(1)
+
     ser = serial.Serial(port, 115200)
     ser.flushInput()
     ser.flushOutput()
@@ -115,19 +164,19 @@ def main():
     for i in range(args.tries):
         try:
             print("Logging into %s via serial console [try %s]" % (port, i))
-            login(ser, hostname, user, password)
+            login(ser, hostname, user, password, 30)
             success = True
             break
         except Exception as except_inst:
-            print("Login failure (try %s):" % (i,), except_inst, file=sys.stderr)
+            print("Login failure (try %s):" % (i,), except_inst)
             time.sleep(5)
         if time.time() - ts_start > args.timeout:
-            print("Timeout reached waiting for login prompt", file=sys.stderr)
+            print("E: Timeout reached waiting for login prompt")
             break
 
     if success:
         write_ser_line(ser, "")
-        ser.timeout = 5
+        ser.timeout = 30
         print_ser_lines(ser)
         print("Running commands...")
         for command in commands:
@@ -140,6 +189,7 @@ def main():
             # after poweroff, the serial device will probably vanish. do not attempt reading from it anymore.
 
     if not success:
+        print("W: Running tests failed, saving screenshot")
         capture_vnc_screenshot(screenshot_file)
         sys.exit(1)
 

tests/test-vm.sh

@@ -42,25 +42,26 @@ cat <<EOT > "$TEST_TMPDIR"/testrunner
 #!/bin/bash
 # Do not set -eu, we want to continue even if individual commands fail.
 set -x
-echo "INSIDE_VM $0 running"
+echo "INSIDE_VM \$0 running \$(date -R)"
 mkdir results
 
 # Collect information from VM first
-lsb_release -a > results/lsb_release.txt
+cat /etc/os-release > results/os-release.txt
+dpkg -l > results/dpkg-l.txt
 uname -a > results/uname-a.txt
 systemctl list-units > results/systemctl_list-units.txt
 systemctl status > results/systemctl_status.txt
 fdisk -l > results/fdisk-l.txt
 hostname -f > results/hostname-f.txt 2>&1
 journalctl -b > results/journalctl-b.txt
-dpkg -l > results/dpkg-l.txt
 
 # Run tests
-./goss --gossfile goss.yaml validate --format tap > results/goss.tap
+echo "INSIDE_VM starting goss \$(date -R)"
+./goss --gossfile goss.yaml validate --format tap > results/goss.tap 2> results/goss.err
 # Detection of testrunner success hinges on goss.exitcode file.
 echo \$? > results/goss.exitcode
 
-echo "INSIDE_VM $0 finished"
+echo "INSIDE_VM \$0 finished \$(date -R)"
 EOT
 chmod a+rx "$TEST_TMPDIR"/testrunner
 
@@ -76,17 +77,17 @@ if [ "${DPKG_ARCHITECTURE}" = "amd64" ]; then
 elif [ "${DPKG_ARCHITECTURE}" = "arm64" ]; then
     cp /usr/share/AAVMF/AAVMF_VARS.fd efi_vars.fd
     qemu_command=( qemu-system-aarch64 )
-    qemu_command+=( -machine type=virt,gic-version=max,accel=kvm:tcg )
+    qemu_command+=( -machine "type=virt,gic-version=max,accel=kvm:tcg" )
     qemu_command+=( -drive "if=pflash,format=raw,unit=0,file.filename=/usr/share/AAVMF/AAVMF_CODE.no-secboot.fd,file.locking=off,readonly=on" )
-    qemu_command+=( -drive "if=pflash,unit=1,file=efi_vars.fd" )
+    qemu_command+=( -drive "if=pflash,format=raw,unit=1,file=efi_vars.fd" )
 else
     echo "E: unsupported ${DPKG_ARCHITECTURE}"
     exit 1
 fi
 qemu_command+=( -cpu max )
 qemu_command+=( -smp 2 )
 qemu_command+=( -m 2048 )
-qemu_command+=( -hda "${VM_IMAGE}" )
+qemu_command+=( -drive "file=${VM_IMAGE},format=raw,index=0,media=disk" )
 qemu_command+=( -virtfs "local,path=${TEST_TMPDIR},mount_tag=${MOUNT_TAG},security_model=none,id=host0" )
 qemu_command+=( -nographic )
 qemu_command+=( -display none )
@@ -96,68 +97,26 @@ qemu_command+=( -serial pty )
 "${qemu_command[@]}" &>qemu.log &
 QEMU_PID="$!"
 
-timeout=30
-success=0
-while [ "$timeout" -gt 0 ] ; do
-  ((timeout--))
-  if grep -q 'char device redirected to ' qemu.log ; then
-    success=1
-    sleep 1
-    break
-  else
-    echo "No serial console from Qemu found yet [$timeout retries left]"
-    sleep 1
-  fi
-done
-
-if [ "$success" = "1" ] ; then
-  serial_port=$(awk '/char device redirected/ {print $5}' qemu.log)
-else
-  echo "Error: Failed to identify serial console port." >&2
-  cat qemu.log
-  exit 1
-fi
-
-timeout=30
-success=0
-while [ "$timeout" -gt 0 ] ; do
-  ((timeout--))
-  if [ -c "$serial_port" ] ; then
-    success=1
-    sleep 1
-    break
-  else
-    echo "No block device for serial console found yet [$timeout retries left]"
-    sleep 1
-  fi
-done
-
-if [ "$success" = "0" ] ; then
-  echo "Error: can't access serial console block device." >&2
-  exit 1
-fi
-
 RC=0
 "$TEST_PWD"/tests/serial-console-connection \
   --tries 180 \
   --screenshot "$TEST_PWD/tests/screenshot.jpg" \
-  --port "$serial_port" \
+  --qemu-log qemu.log \
   --hostname "$VM_HOSTNAME" \
   --poweroff \
   "mount -t 9p -o trans=virtio,version=9p2000.L,msize=512000,rw $MOUNT_TAG /mnt && cd /mnt && ./testrunner" || RC=$?
 
 if [ ! -d results ] || [ ! -f ./results/goss.tap ] || [ ! -f ./results/goss.exitcode ]; then
   echo "Running tests inside VM failed for unknown reason" >&2
   RC=1
+  cat results/goss.err || true
 else
   RC=$(cat results/goss.exitcode)
   echo "goss exitcode: $RC"
 
   cat results/goss.tap
 fi
 
-echo "Finished serial console connection [timeout=${timeout}]."
-
 # in case of errors we might have captured a screenshot via VNC
 if [ -r "${TEST_PWD}"/tests/screenshot.jpg ] ; then
   cp "${TEST_PWD}"/tests/screenshot.jpg "${TESTS_RESULTSDIR}"