Skip to content

test/storm: shared WaitForLogin SSH fallback for reboot waits #695

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Draft
bfjelds wants to merge 1 commit into
base: main
Choose a base branch
from
Draft

test/storm: shared WaitForLogin SSH fallback for reboot waits #695

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
22 changes: 19 additions & 3 deletions tools/storm/rollback/tests/helper.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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") {
Expand All @@ -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)
}
Expand Down Expand Up @@ -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
Expand All @@ -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)
}
Expand Down Expand Up @@ -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
Expand All @@ -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)
}
Expand Down
125 changes: 2 additions & 123 deletions tools/storm/servicing/tests/update.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -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")
Expand Down Expand Up @@ -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)
}
}
}
6 changes: 6 additions & 0 deletions tools/storm/utils/vm/qemu/qemu.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
148 changes: 148 additions & 0 deletions tools/storm/utils/vm/wait_login.go
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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)
}
}
}
Loading