From 33b1231299c2dfe133734c8ea1b3eea1898132ee Mon Sep 17 00:00:00 2001 From: Brian Fjeldstad Date: Wed, 24 Jun 2026 21:55:37 +0000 Subject: [PATCH] test/storm: shared WaitForLogin SSH fallback for reboot waits Introduce stormvm.WaitForLoginWithSshFallback, a single helper for waiting on a VM to return after a reboot. On QEMU it waits for the serial "login:" prompt and, if that times out, falls back to confirming the reboot over SSH by comparing "uptime --since" before and after. This tolerates the known serial-getty udev race (systemd#10850, ~2% of boots) where dev-ttyS0.device is skipped so serial-getty never starts even though the VM is healthy. On genuine failure it captures a screenshot and scans the serial log for dracut/initramfs symptoms (CheckSerialLogForDracutIssues, bug 15086). It also proactively (re)starts serial-getty@ttyS0 so later boots are detected via the serial log, and handles the Azure platform via SSH liveness polling. Consolidate both test suites onto the shared helper: - rollback tests (helper.go): the update, rollback, and split-rollback reboot paths now call WaitForLoginWithSshFallback instead of QemuConfig.WaitForLogin. - servicing tests (update.go): the finalize-reboot path now calls the shared helper, removing ~90 lines of inline SSH-fallback logic and the duplicated local checkSerialLogForDracutIssues. Also remove the stale local serial.log accumulator before each WaitForLogin (qemu.go) so every saved NNN-serial.log contains only that boot rather than accumulating output from all prior iterations. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- tools/storm/rollback/tests/helper.go | 22 +++- tools/storm/servicing/tests/update.go | 125 +--------------------- tools/storm/utils/vm/qemu/qemu.go | 6 ++ tools/storm/utils/vm/wait_login.go | 148 ++++++++++++++++++++++++++ 4 files changed, 175 insertions(+), 126 deletions(-) create mode 100644 tools/storm/utils/vm/wait_login.go diff --git a/tools/storm/rollback/tests/helper.go b/tools/storm/rollback/tests/helper.go index f7c0caa5ba..91d3400bfe 100644 --- a/tools/storm/rollback/tests/helper.go +++ b/tools/storm/rollback/tests/helper.go @@ -161,6 +161,12 @@ func (u *UpdateTest) doUpdateTest() error { // Invoke trident update updateCmd := fmt.Sprintf("sudo trident -v trace grpc-client update %s", vmHostConfigPath) logrus.Tracef("Invoking `trident update` on VM: '%s'", updateCmd) + // Capture "uptime --since" before the reboot so the shared WaitForLogin + // fallback can definitively confirm the VM rebooted if serial-getty fails. + preRebootUptime := "" + if uptimeOut, uptimeErr := stormssh.SshCommand(u.VMConfig.VMConfig, u.VMIP, "uptime --since"); uptimeErr == nil { + preRebootUptime = strings.TrimSpace(uptimeOut) + } updateOutput, err := stormssh.SshCommandCombinedOutput(u.VMConfig.VMConfig, u.VMIP, updateCmd) logrus.Tracef("Update output (%v):\n%s", err, updateOutput) if strings.Contains(updateOutput, "Trident failed due to a servicing error") { @@ -179,7 +185,7 @@ func (u *UpdateTest) doUpdateTest() error { if u.ExpectReboot { // Wait for update to complete logrus.Tracef("Waiting for VM to come back up after update") - err = u.VMConfig.QemuConfig.WaitForLogin(u.VMConfig.VMConfig.Name, u.TestConfig.OutputPath, u.TestConfig.Verbose, 0) + err = stormvm.WaitForLoginWithSshFallback(u.VMConfig, u.VMIP, preRebootUptime, 0, u.TestConfig.OutputPath, u.TestConfig.Verbose) if err != nil { return fmt.Errorf("VM did not come back up after update: %w", err) } @@ -222,6 +228,11 @@ func (u *UpdateTest) doRollbackTest( rollbackCommand = fmt.Sprintf("%s %s", rollbackCommand, rollbackExpectation) } logrus.Tracef("Invoking `%s` on VM", rollbackCommand) + // Capture "uptime --since" before the reboot for the shared WaitForLogin fallback. + preRebootUptime := "" + if uptimeOut, uptimeErr := stormssh.SshCommand(u.VMConfig.VMConfig, u.VMIP, "uptime --since"); uptimeErr == nil { + preRebootUptime = strings.TrimSpace(uptimeOut) + } updateOutput, err := stormssh.SshCommand(u.VMConfig.VMConfig, u.VMIP, rollbackCommand) if !rollbackNeedsReboot && err != nil { // Ignore error from ssh if reboot was expected, but otherwise @@ -233,7 +244,7 @@ func (u *UpdateTest) doRollbackTest( if rollbackNeedsReboot { // Wait for rollback to complete logrus.Tracef("Waiting for VM to come back up after rollback") - err = u.VMConfig.QemuConfig.WaitForLogin(u.VMConfig.VMConfig.Name, u.TestConfig.OutputPath, u.TestConfig.Verbose, 0) + err = stormvm.WaitForLoginWithSshFallback(u.VMConfig, u.VMIP, preRebootUptime, 0, u.TestConfig.OutputPath, u.TestConfig.Verbose) if err != nil { return fmt.Errorf("VM did not come back up after rollback: %w", err) } @@ -275,6 +286,11 @@ func (u *UpdateTest) doSplitRollbackTest( // Invoke trident rollback --allowed-operations finalize rollbackCommand = "sudo trident rollback --allowed-operations finalize" logrus.Tracef("Invoking `%s` on VM", rollbackCommand) + // Capture "uptime --since" before the reboot for the shared WaitForLogin fallback. + preRebootUptime := "" + if uptimeOut, uptimeErr := stormssh.SshCommand(u.VMConfig.VMConfig, u.VMIP, "uptime --since"); uptimeErr == nil { + preRebootUptime = strings.TrimSpace(uptimeOut) + } updateOutput, err = stormssh.SshCommand(u.VMConfig.VMConfig, u.VMIP, rollbackCommand) if !rollbackNeedsReboot && err != nil { // Ignore error from ssh if reboot was expected, but otherwise @@ -286,7 +302,7 @@ func (u *UpdateTest) doSplitRollbackTest( if rollbackNeedsReboot { // Wait for rollback to complete logrus.Tracef("Waiting for VM to come back up after rollback") - err = u.VMConfig.QemuConfig.WaitForLogin(u.VMConfig.VMConfig.Name, u.TestConfig.OutputPath, u.TestConfig.Verbose, 0) + err = stormvm.WaitForLoginWithSshFallback(u.VMConfig, u.VMIP, preRebootUptime, 0, u.TestConfig.OutputPath, u.TestConfig.Verbose) if err != nil { return fmt.Errorf("VM did not come back up after rollback: %w", err) } diff --git a/tools/storm/servicing/tests/update.go b/tools/storm/servicing/tests/update.go index 5cf6a1f37f..efd9188ca8 100644 --- a/tools/storm/servicing/tests/update.go +++ b/tools/storm/servicing/tests/update.go @@ -10,7 +10,6 @@ import ( "strings" "time" stormsvcconfig "tridenttools/storm/servicing/utils/config" - stormutils "tridenttools/storm/utils" stormfile "tridenttools/storm/utils/file" stormnetlisten "tridenttools/storm/utils/netlisten" stormssh "tridenttools/storm/utils/ssh" @@ -304,95 +303,8 @@ func innerUpdateLoop(testConfig stormsvcconfig.TestConfig, vmConfig stormvmconfi } logrus.Tracef("Wait for VM to come back up after finalize reboot") - if vmConfig.VMConfig.Platform == stormvmconfig.PlatformQEMU { - err := vmConfig.QemuConfig.WaitForLogin(vmConfig.VMConfig.Name, testConfig.OutputPath, testConfig.Verbose, i) - if err != nil { - // Serial login detection failed — the "login:" prompt did not appear - // in the serial log within the timeout period. - // - // Root cause: serial-getty@ttyS0.service depends on systemd's - // dev-ttyS0.device unit, which is auto-generated when udev reports - // /dev/ttyS0. If udev is slightly slow creating the device node, - // systemd's ConditionPathExists=/dev/ttyS0 check fails and the - // device unit is skipped — so serial-getty never starts and no - // "login:" appears on the serial console, even though the VM is - // fully healthy with working networking. - // - // This is a known systemd race condition (~2% of boots): - // https://github.com/systemd/systemd/issues/10850 - // - // Fallback: verify the VM rebooted by comparing "uptime --since" - // before and after the reboot. If the value changed, the VM is - // confirmed alive and we can proceed. - logrus.Warnf("Serial login detection failed for iteration %d, attempting SSH fallback: %v", i, err) - - sshFallbackSuccess := false - for j := 0; j < 10; j++ { - output, sshErr := stormssh.SshCommand(vmConfig.VMConfig, vmIP, "uptime --since") - if sshErr == nil { - postRebootUptime := strings.TrimSpace(output) - if preRebootUptime != "" && postRebootUptime != preRebootUptime { - logrus.Infof("SSH fallback: VM rebooted (uptime --since changed from %q to %q)", preRebootUptime, postRebootUptime) - sshFallbackSuccess = true - break - } else if preRebootUptime == "" { - // No pre-reboot uptime captured — accept any SSH response - logrus.Infof("SSH fallback: VM reachable via SSH (uptime --since: %s, no pre-reboot baseline)", postRebootUptime) - sshFallbackSuccess = true - break - } - logrus.Warnf("SSH fallback: uptime --since unchanged (%q) — VM may not have rebooted yet", postRebootUptime) - } - time.Sleep(3 * time.Second) - } - - if !sshFallbackSuccess { - // VM is genuinely unreachable — capture diagnostics - if captureErr := stormutils.CaptureScreenshot( - vmConfig.VMConfig.Name, - testConfig.OutputPath, - fmt.Sprintf("%03d-vm-failure-after-update.png", i), - ); captureErr != nil { - logrus.Warnf("failed to capture screenshot: %v", captureErr) - } - // Check serial log for dracut-initqueue timeout patterns that indicate - // stale disk UUIDs in initramfs (see bug 15086). - // Use the saved copy since WaitForLogin truncates the original. - if testConfig.OutputPath != "" { - savedSerialLog := filepath.Join(testConfig.OutputPath, fmt.Sprintf("%03d-serial.log", i)) - checkSerialLogForDracutIssues(savedSerialLog, i) - } - return fmt.Errorf("VM did not come back up after update for iteration %d: %w", i, err) - } - logrus.Warnf("SSH fallback succeeded for iteration %d — VM is healthy but serial-getty did not start (ttyS0 device likely skipped by systemd)", i) - } - - // Proactively ensure serial-getty@ttyS0 is running after every boot. - // This is a no-op if already running. When systemd skips - // dev-ttyS0.device due to the udev race condition described above - // (https://github.com/systemd/systemd/issues/10850), this restarts - // serial-getty so subsequent iterations detect "login:" normally - // via the serial log, avoiding repeated SSH fallbacks. - if _, gettErr := stormssh.SshCommand(vmConfig.VMConfig, vmIP, "sudo systemctl start serial-getty@ttyS0.service"); gettErr != nil { - logrus.Tracef("serial-getty@ttyS0 start attempt: %v (may already be running)", gettErr) - } - } else if vmConfig.VMConfig.Platform == stormvmconfig.PlatformAzure { - time.Sleep(15 * time.Second) - - success := false - for j := 0; j < 10; j++ { - if _, err = stormssh.SshCommand(vmConfig.VMConfig, vmIP, "hostname"); err == nil { - success = true - break - } - time.Sleep(5 * time.Second) // Wait for the VM to stabilize - } - - if !success { - logrus.Info("Azure VM did not come back up after update") - logrus.Errorf("Azure VM did not come back up after update for iteration %d", i) - return fmt.Errorf("azure VM did not come back up after update for iteration %d", i) - } + if err := stormvm.WaitForLoginWithSshFallback(vmConfig, vmIP, preRebootUptime, i, testConfig.OutputPath, testConfig.Verbose); err != nil { + return fmt.Errorf("VM did not come back up after finalize reboot for iteration %d: %w", i, err) } logrus.Tracef("Check if VM IP has changed after update") @@ -544,36 +456,3 @@ func validateRollback(cfg stormvmconfig.VMConfig, vmIP string) error { logrus.Info("Rollback validation succeeded") return nil } - -// checkSerialLogForDracutIssues scans the serial log for patterns that indicate -// initramfs is stuck waiting for a device, which is the symptom of bug 15086 -// (stale disk UUIDs embedded in initramfs by dracut). -func checkSerialLogForDracutIssues(serialLogPath string, iteration int) { - if serialLogPath == "" { - return - } - data, err := os.ReadFile(serialLogPath) - if err != nil { - logrus.Warnf("Could not read serial log for dracut analysis: %v", err) - return - } - content := string(data) - - dracutPatterns := []struct { - pattern string - message string - }{ - {"dracut-initqueue[", "dracut-initqueue warning detected — initramfs may be waiting for a device"}, - {"Could not boot", "dracut 'Could not boot' error detected"}, - {"Starting dracut emergency shell", "dracut emergency shell activated — boot failed in initramfs"}, - {"Warning: /dev/disk/by", "dracut warning about /dev/disk/by-* path — possible stale UUID reference"}, - {"rd.break", "rd.break detected — initramfs dropped to debug shell"}, - {"Timed out waiting for device", "dracut timed out waiting for device — likely stale UUID in initramfs (bug 15086)"}, - } - - for _, dp := range dracutPatterns { - if strings.Contains(content, dp.pattern) { - logrus.Errorf("INITRAMFS DIAGNOSTIC (iteration %d): %s (matched '%s' in serial log)", iteration, dp.message, dp.pattern) - } - } -} diff --git a/tools/storm/utils/vm/qemu/qemu.go b/tools/storm/utils/vm/qemu/qemu.go index fcec985b9e..8f973aa76f 100644 --- a/tools/storm/utils/vm/qemu/qemu.go +++ b/tools/storm/utils/vm/qemu/qemu.go @@ -342,6 +342,12 @@ func (cfg QemuConfig) TruncateLog(vmName string) error { func (cfg QemuConfig) WaitForLogin(vmName string, outputPath string, verbose bool, iteration int) error { localSerialLog := "./serial.log" + // Each iteration's snapshot must contain only this boot. printAndSave opens + // localSerialLog with O_APPEND, so remove any file left by a prior iteration; + // otherwise every saved NNN-serial.log accumulates all earlier boots. + if rmErr := os.Remove(localSerialLog); rmErr != nil && !os.IsNotExist(rmErr) { + logrus.Warnf("Failed to remove stale serial log accumulator %q: %v", localSerialLog, rmErr) + } // Wait for login prompt to appear in the serial log and save the log to localSerialLog waitErr := innerWaitForLogin(cfg.SerialLog, verbose, iteration, localSerialLog) // Copy serial log to output directory if specified diff --git a/tools/storm/utils/vm/wait_login.go b/tools/storm/utils/vm/wait_login.go new file mode 100644 index 0000000000..a82247b487 --- /dev/null +++ b/tools/storm/utils/vm/wait_login.go @@ -0,0 +1,148 @@ +package vm + +import ( + "fmt" + "os" + "path/filepath" + "strings" + "time" + + stormutils "tridenttools/storm/utils" + stormssh "tridenttools/storm/utils/ssh" + stormvmconfig "tridenttools/storm/utils/vm/config" + + "github.com/sirupsen/logrus" +) + +// WaitForLoginWithSshFallback waits for the VM to come back up after a reboot. +// +// On QEMU it waits for the serial "login:" prompt; if serial login detection +// times out it falls back to confirming the VM rebooted via SSH +// ("uptime --since"), tolerating known flaky-boot races such as the +// serial-getty udev race (systemd#10850) and the intermittent Azure Linux 4 +// generator-sandbox freeze that triggers a watchdog reset + reboot. On Azure it +// polls SSH for liveness. +// +// preRebootUptime is the "uptime --since" value captured before the reboot was +// triggered; when non-empty it is used to confirm the value changed (proving a +// reboot occurred). Pass "" to accept any SSH reachability as success. +// +// On QEMU it also proactively (re)starts serial-getty@ttyS0 so subsequent boots +// are detected via the serial log. On genuine failure it captures a screenshot +// and scans the serial log for dracut/initramfs issues. +func WaitForLoginWithSshFallback(vmConfig stormvmconfig.AllVMConfig, vmIP string, preRebootUptime string, iteration int, outputPath string, verbose bool) error { + if vmConfig.VMConfig.Platform == stormvmconfig.PlatformAzure { + time.Sleep(15 * time.Second) + for j := 0; j < 10; j++ { + if _, err := stormssh.SshCommand(vmConfig.VMConfig, vmIP, "hostname"); err == nil { + return nil + } + time.Sleep(5 * time.Second) // Wait for the VM to stabilize + } + return fmt.Errorf("azure VM did not come back up after reboot for iteration %d", iteration) + } + + err := vmConfig.QemuConfig.WaitForLogin(vmConfig.VMConfig.Name, outputPath, verbose, iteration) + if err != nil { + // Serial login detection failed — the "login:" prompt did not appear in + // the serial log within the timeout period. + // + // Known causes: + // - serial-getty@ttyS0.service depends on the auto-generated + // dev-ttyS0.device unit; if udev is slow creating /dev/ttyS0, + // systemd's ConditionPathExists check fails and serial-getty never + // starts, so no "login:" appears even though the VM is healthy + // (systemd#10850, ~2% of boots). + // - On Azure Linux 4, systemd's manager startup intermittently fails + // to fork its generator sandbox (EPROTO) and freezes PID1; the UEFI + // watchdog then resets the VM, which reboots and recovers. That + // freeze+reset+reboot cycle can exceed the serial wait window. + // + // Fallback: confirm the VM rebooted by comparing "uptime --since" before + // and after the reboot. If the value changed (or we have no baseline and + // SSH is reachable), the VM is confirmed alive and we can proceed. + logrus.Warnf("Serial login detection failed for iteration %d, attempting SSH fallback: %v", iteration, err) + + sshFallbackSuccess := false + for j := 0; j < 10; j++ { + output, sshErr := stormssh.SshCommand(vmConfig.VMConfig, vmIP, "uptime --since") + if sshErr == nil { + postRebootUptime := strings.TrimSpace(output) + if preRebootUptime != "" && postRebootUptime != preRebootUptime { + logrus.Infof("SSH fallback: VM rebooted (uptime --since changed from %q to %q)", preRebootUptime, postRebootUptime) + sshFallbackSuccess = true + break + } else if preRebootUptime == "" { + // No pre-reboot uptime captured — accept any SSH response + logrus.Infof("SSH fallback: VM reachable via SSH (uptime --since: %s, no pre-reboot baseline)", postRebootUptime) + sshFallbackSuccess = true + break + } + logrus.Warnf("SSH fallback: uptime --since unchanged (%q) — VM may not have rebooted yet", postRebootUptime) + } + time.Sleep(3 * time.Second) + } + + if !sshFallbackSuccess { + // VM is genuinely unreachable — capture diagnostics + if captureErr := stormutils.CaptureScreenshot( + vmConfig.VMConfig.Name, + outputPath, + fmt.Sprintf("%03d-vm-failure-after-reboot.png", iteration), + ); captureErr != nil { + logrus.Warnf("failed to capture screenshot: %v", captureErr) + } + // Check serial log for dracut-initqueue timeout patterns that indicate + // stale disk UUIDs in initramfs (see bug 15086). Use the saved copy + // since WaitForLogin truncates the original. + if outputPath != "" { + savedSerialLog := filepath.Join(outputPath, fmt.Sprintf("%03d-serial.log", iteration)) + CheckSerialLogForDracutIssues(savedSerialLog, iteration) + } + return fmt.Errorf("VM did not come back up after reboot for iteration %d: %w", iteration, err) + } + logrus.Warnf("SSH fallback succeeded for iteration %d — VM is healthy but serial-getty did not start (ttyS0 device likely skipped by systemd)", iteration) + } + + // Proactively ensure serial-getty@ttyS0 is running after every boot. This is + // a no-op if already running. When systemd skips dev-ttyS0.device due to the + // udev race condition (systemd#10850), this restarts serial-getty so + // subsequent iterations detect "login:" normally via the serial log. + if _, gettErr := stormssh.SshCommand(vmConfig.VMConfig, vmIP, "sudo systemctl start serial-getty@ttyS0.service"); gettErr != nil { + logrus.Tracef("serial-getty@ttyS0 start attempt: %v (may already be running)", gettErr) + } + return nil +} + +// CheckSerialLogForDracutIssues scans a saved serial log for dracut/initramfs +// failure patterns (e.g. stale UUIDs in initramfs, bug 15086) and logs a +// diagnostic for each match. +func CheckSerialLogForDracutIssues(serialLogPath string, iteration int) { + if serialLogPath == "" { + return + } + data, err := os.ReadFile(serialLogPath) + if err != nil { + logrus.Warnf("Could not read serial log for dracut analysis: %v", err) + return + } + content := string(data) + + dracutPatterns := []struct { + pattern string + message string + }{ + {"dracut-initqueue[", "dracut-initqueue warning detected — initramfs may be waiting for a device"}, + {"Could not boot", "dracut 'Could not boot' error detected"}, + {"Starting dracut emergency shell", "dracut emergency shell activated — boot failed in initramfs"}, + {"Warning: /dev/disk/by", "dracut warning about /dev/disk/by-* path — possible stale UUID reference"}, + {"rd.break", "rd.break detected — initramfs dropped to debug shell"}, + {"Timed out waiting for device", "dracut timed out waiting for device — likely stale UUID in initramfs (bug 15086)"}, + } + + for _, dp := range dracutPatterns { + if strings.Contains(content, dp.pattern) { + logrus.Errorf("INITRAMFS DIAGNOSTIC (iteration %d): %s (matched '%s' in serial log)", iteration, dp.message, dp.pattern) + } + } +}