diff --git a/.github/e2e-cells.json b/.github/e2e-cells.json index cb8910329..27d5e24a8 100644 --- a/.github/e2e-cells.json +++ b/.github/e2e-cells.json @@ -130,7 +130,7 @@ "runner": "ci-single", "extra": "rds", "suite": "rds", - "timeout_minutes": 100 + "timeout_minutes": 120 }, { "cell": 29, diff --git a/.github/scripts/suite-sets.sh b/.github/scripts/suite-sets.sh index f0160d151..5cc68eb4c 100644 --- a/.github/scripts/suite-sets.sh +++ b/.github/scripts/suite-sets.sh @@ -77,8 +77,9 @@ e2e_suite_timeout() { # what the queue costs, not what the tests do: single tests logged 11m, 22m # and 26m waiting for budget. 17 tests at that concurrency is over an hour # before anything goes wrong, and the first pass to run deep into the suite - # still had three left at 60m. - rds) echo "90m" ;; + # still had three left at 60m. The loaded graceful-reboot case adds an + # instance that holds its slot through a pgbench load as well as a create. + rds) echo "105m" ;; # diskperf runs two 16 GiB fio profiles per repetition, each on a volume it # creates first. One pass is ~20 minutes on the bare-metal cell and a # baseline capture at SPINIFEX_DISKPERF_REPS=3 is three times that. diff --git a/spinifex/daemon/daemon_handlers_test.go b/spinifex/daemon/daemon_handlers_test.go index 888bb3620..32d6d1fa9 100644 --- a/spinifex/daemon/daemon_handlers_test.go +++ b/spinifex/daemon/daemon_handlers_test.go @@ -798,13 +798,14 @@ func TestHandleEC2Events_RebootRunningInstance(t *testing.T) { require.NoError(t, err) require.NotNil(t, reply) - // vm.Reboot returns a generic "QMP system_reset" error when the - // QMPClient encoder/decoder is nil, which handleRebootInstance maps - // to ServerInternal via its default branch. + // The daemon admits the reboot and runs it in the background, so the reply + // carries no error even though this guest's QMP client cannot be reset. A + // reply that waited for the guest would arrive after the caller gave up. var errResp map[string]any err = json.Unmarshal(reply.Data, &errResp) require.NoError(t, err) - assert.Equal(t, awserrors.ErrorServerInternal, errResp["Code"]) + assert.NotContains(t, errResp, "Code", "an admitted reboot must not answer with an error") + t.Cleanup(daemon.vmMgr.WaitForBackgroundWork) // Instance should remain in running state (reboot doesn't change state) var status vm.InstanceState diff --git a/spinifex/gateway/ec2/instance/RebootInstances.go b/spinifex/gateway/ec2/instance/RebootInstances.go index 1956e34fe..13ebd092a 100644 --- a/spinifex/gateway/ec2/instance/RebootInstances.go +++ b/spinifex/gateway/ec2/instance/RebootInstances.go @@ -15,6 +15,12 @@ import ( "github.com/nats-io/nats.go" ) +// rebootInstancesTimeout is the NATS request timeout, overridable in tests so +// the ErrTimeout path can be exercised without a real 5-second wait. The daemon +// admits a reboot and runs it in the background, so this bounds the admission +// and never the guest's shutdown. +var rebootInstancesTimeout = 5 * time.Second + func ValidateRebootInstancesInput(input *ec2.RebootInstancesInput) error { if input == nil { return errors.New(awserrors.ErrorInvalidParameterValue) @@ -59,10 +65,18 @@ func RebootInstances(ctx context.Context, input *ec2.RebootInstancesInput, natsC reqMsg.Data = jsonData reqMsg.Header.Set(utils.AccountIDHeader, accountID) utils.InjectTraceContext(ctx, reqMsg.Header) - msg, err := natsConn.RequestMsg(reqMsg, 5*time.Second) + msg, err := natsConn.RequestMsg(reqMsg, rebootInstancesTimeout) if err != nil { slog.ErrorContext(ctx, "RebootInstances: Failed to send command", "instance_id", instanceID, "err", err) + // Only the absence of a subscriber says anything about where the + // instance is. A timeout is a daemon that is slow or wedged, and + // calling that NotFound sends the caller after an entirely + // different fault than the one it hit. + if !errors.Is(err, nats.ErrNoResponders) { + return nil, errors.New(awserrors.ErrorServerInternal) + } + // No daemon subscription: check stopped-KV to return IncorrectInstanceState instead of NotFound. describeInput := &ec2.DescribeInstancesInput{ InstanceIds: []*string{&instanceID}, diff --git a/spinifex/gateway/ec2/instance/RebootInstances_test.go b/spinifex/gateway/ec2/instance/RebootInstances_test.go index c675fcc76..d5efb95fa 100644 --- a/spinifex/gateway/ec2/instance/RebootInstances_test.go +++ b/spinifex/gateway/ec2/instance/RebootInstances_test.go @@ -4,6 +4,7 @@ import ( "context" "encoding/json" "testing" + "time" "github.com/aws/aws-sdk-go/aws" "github.com/aws/aws-sdk-go/service/ec2" @@ -90,6 +91,31 @@ func TestRebootInstances_NATSRequestFails(t *testing.T) { assert.Equal(t, awserrors.ErrorInvalidInstanceIDNotFound, err.Error()) } +// TestRebootInstances_SlowDaemonIsNotAMissingInstance covers a daemon that +// holds the request open. Reporting that as NotFound names a fault the caller +// does not have and hides the one it does: the instance is there, the node +// answering for it is not answering. +func TestRebootInstances_SlowDaemonIsNotAMissingInstance(t *testing.T) { + _, nc := startTestNATSServer(t) + + previous := rebootInstancesTimeout + rebootInstancesTimeout = 50 * time.Millisecond + t.Cleanup(func() { rebootInstancesTimeout = previous }) + + instanceID := "i-slow" + // A live subscriber that never replies forces a real ErrTimeout rather + // than the immediate ErrNoResponders a missing subscriber would give. + _, err := nc.Subscribe("ec2.cmd."+instanceID, func(*nats.Msg) {}) + require.NoError(t, err) + + input := &ec2.RebootInstancesInput{ + InstanceIds: []*string{aws.String(instanceID)}, + } + _, err = RebootInstances(context.Background(), input, nc, "123456789012") + require.Error(t, err) + assert.Equal(t, awserrors.ErrorServerInternal, err.Error()) +} + func TestRebootInstances_StoppedInstance(t *testing.T) { t.Parallel() _, nc := startTestNATSServer(t) diff --git a/spinifex/handlers/ec2/instance/service_impl_test.go b/spinifex/handlers/ec2/instance/service_impl_test.go index db3554934..a483ea130 100644 --- a/spinifex/handlers/ec2/instance/service_impl_test.go +++ b/spinifex/handlers/ec2/instance/service_impl_test.go @@ -3854,15 +3854,33 @@ func TestRebootInstance_NotFound(t *testing.T) { assert.Equal(t, awserrors.ErrorInvalidInstanceIDNotFound, err.Error()) } -func TestRebootInstance_QMPFailureReturnsInternalError(t *testing.T) { +// TestRebootInstance_QMPFailureIsNotTheCallersToHear covers the async contract +// EC2 documents: the answer reports admission, so a reset that fails afterwards +// cannot be returned and must not hold the reply up either. The guest is left +// running and the heartbeat is what notices it never came back. +func TestRebootInstance_QMPFailureIsNotTheCallersToHear(t *testing.T) { id := "i-qmp-failure" instance := &vm.VM{ID: id, Status: vm.StateRunning} mgr := mgrWith(map[string]*vm.VM{id: instance}) + t.Cleanup(mgr.WaitForBackgroundWork) + svc := &InstanceServiceImpl{vmMgr: mgr} + + require.NoError(t, svc.RebootInstance(context.Background(), instance, spxtypes.EC2InstanceCommand{ID: id})) + assert.Equal(t, vm.StateRunning, mgr.Status(instance)) +} + +// TestRebootInstance_NotRunning asserts the second of the two failures that can +// still be reported, so a reboot of a stopped guest is refused rather than +// accepted and quietly dropped. +func TestRebootInstance_NotRunning(t *testing.T) { + id := "i-stopped" + instance := &vm.VM{ID: id, Status: vm.StateStopped} + mgr := mgrWith(map[string]*vm.VM{id: instance}) svc := &InstanceServiceImpl{vmMgr: mgr} err := svc.RebootInstance(context.Background(), instance, spxtypes.EC2InstanceCommand{ID: id}) require.Error(t, err) - assert.Equal(t, awserrors.ErrorServerInternal, err.Error()) + assert.Equal(t, awserrors.ErrorIncorrectInstanceState, err.Error()) } // TestStartInstance_NotFound verifies that a missing instance returns diff --git a/spinifex/qmp/qmp.go b/spinifex/qmp/qmp.go index 57daec50b..b362812b8 100644 --- a/spinifex/qmp/qmp.go +++ b/spinifex/qmp/qmp.go @@ -16,6 +16,7 @@ var CommandResponseTypes = map[string]unmarshalTarget{ "system_powerdown": &json.RawMessage{}, "system_reset": &json.RawMessage{}, "system_wakeup": &json.RawMessage{}, + "quit": &json.RawMessage{}, "query-block": &[]BlockDevice{}, diff --git a/spinifex/vm/lifecycle.go b/spinifex/vm/lifecycle.go index f0d2c367d..76c79d9ec 100644 --- a/spinifex/vm/lifecycle.go +++ b/spinifex/vm/lifecycle.go @@ -18,6 +18,7 @@ import ( "time" "github.com/mulgadc/spinifex/spinifex/instancetypes" + "github.com/mulgadc/spinifex/spinifex/otelsetup" "github.com/mulgadc/spinifex/spinifex/qmp" "github.com/mulgadc/spinifex/spinifex/types" "github.com/mulgadc/spinifex/spinifex/utils" @@ -102,8 +103,15 @@ const ( rebootStatusPollInterval = 100 * time.Millisecond ) -// Reboot resets QEMU and verifies its vCPUs resume. The VM remains in -// StateRunning while firmware re-runs. +// rebootPowerdownTimeout is how long the guest gets to shut itself down before +// it is reset under. Nova's shutdown_timeout, and the same shape as the hard +// reboot AWS documents once a guest will not go quietly. +var rebootPowerdownTimeout = 60 * time.Second + +// Reboot admits a reboot and runs it in the background, the way EC2 does: the +// answer says the request was accepted, not that the guest is back. Asking a +// guest to shut down takes as long as the guest takes, which is far longer than +// any caller waits, so only the two admission failures can be reported at all. func (m *Manager) Reboot(ctx context.Context, id string) error { instance, ok := m.Get(id) if !ok { @@ -114,18 +122,61 @@ func (m *Manager) Reboot(ctx context.Context, id string) error { ErrInvalidTransition, id, status) } + // Tell the heartbeat this guest is meant to be stopped for a moment: it + // quits a guest it finds in the shutdown run state, which is the state a + // reboot passes through. Claiming the flag also serialises reboots, so a + // repeated request joins the one in flight instead of racing it. + if !instance.rebooting.CompareAndSwap(false, true) { + slog.InfoContext(ctx, "Reboot already in flight, ignoring the repeat", "instanceId", id) + return nil + } + + // Detached rather than derived: the caller is answered immediately, so its + // context is cancelled long before the guest has finished shutting down. + rebootCtx := context.WithoutCancel(ctx) + m.goroutineWg.Go(func() { + defer instance.rebooting.Store(false) + if err := m.rebootNow(rebootCtx, instance); err != nil { + // Nobody is left to return this to. The guest is either back or it + // is not, and the heartbeat is what notices the second case. + slog.ErrorContext(rebootCtx, "Reboot failed", "instanceId", id, "err", err) + } + }) + return nil +} + +// rebootNow asks the guest to shut itself down, then resets and resumes it in +// the same QEMU process. The VM remains in StateRunning throughout. A guest +// that will not power down inside its budget is hard-reset, and that is logged. +func (m *Manager) rebootNow(ctx context.Context, instance *VM) error { + // A reset alone never reaches the guest kernel, so it syncs nothing and + // every dirty page is lost. Ask first; reset only once asking has failed. + // A guest whose QEMU would exit rather than pause is reset without asking, + // because a powerdown there leaves nothing to reset and the guest down. + switch { + case !qemuPausesOnShutdown(instance): + slog.InfoContext(ctx, "Guest predates the paused-shutdown flag, hard-resetting", + "instanceId", instance.ID) + default: + if err := m.gracefulPowerdown(ctx, instance, rebootPowerdownTimeout); err != nil { + slog.WarnContext(ctx, "Guest did not power down for reboot, hard-resetting", + "instanceId", instance.ID, "budget_ms", otelsetup.Millis(rebootPowerdownTimeout), "err", err) + } + } + rebootCtx, cancel := context.WithTimeout(ctx, rebootRunningTimeout) defer cancel() if _, err := sendQMPCommandWithTimeout(rebootCtx, instance.QMPClient, - qmp.QMPCommand{Execute: "system_reset"}, id, contextTimeRemaining(rebootCtx)); err != nil { + qmp.QMPCommand{Execute: "system_reset"}, instance.ID, contextTimeRemaining(rebootCtx)); err != nil { return fmt.Errorf("QMP system_reset: %w", err) } return m.waitForQMPRunning(rebootCtx, instance, rebootStatusPollInterval) } -// waitForQMPRunning polls until QEMU reports running or ctx expires. Paused -// and prelaunch guests receive cont so a reset cannot leave their vCPUs parked. +// waitForQMPRunning polls until QEMU reports running or ctx expires. Paused, +// prelaunch and shutdown guests receive cont so a reset cannot leave their +// vCPUs parked — a reset from a powered-down guest lands in one of the three. func (m *Manager) waitForQMPRunning(ctx context.Context, instance *VM, pollInterval time.Duration) error { var lastStatus qmp.Status for { @@ -146,7 +197,8 @@ func (m *Manager) waitForQMPRunning(ctx context.Context, instance *VM, pollInter return nil } - if qmpStatus.Status == "paused" || qmpStatus.Status == "prelaunch" { + if qmpStatus.Status == "paused" || qmpStatus.Status == "prelaunch" || + qmpStatus.Status == qmpStatusShutdown { if status := m.Status(instance); status != StateRunning { return fmt.Errorf("%w: cannot resume instance %s in state %s", ErrInvalidTransition, instance.ID, status) @@ -944,7 +996,25 @@ func (m *Manager) qmpHeartbeatPoll(instance *VM) bool { return true } - if err == nil && !qmpStatus.Running && m.Status(instance) == StateRunning { + // A guest that powered itself off leaves QEMU paused rather than gone, + // because that window is what a reboot needs. Nobody is rebooting this one, + // so close it: quit lets the process exit and recovery proceed as before. + if err == nil && qmpStatus.Status == qmpStatusShutdown && + m.Status(instance) == StateRunning && !instance.rebooting.Load() { + slog.InfoContext(ctx, "Guest powered itself off, ending QEMU", "instance", instance.ID) + if _, quitErr := sendQMPCommand(ctx, instance.QMPClient, + qmp.QMPCommand{Execute: "quit"}, instance.ID); quitErr != nil { + slog.WarnContext(ctx, "QMP quit failed after guest shutdown", + "instance", instance.ID, "err", quitErr) + } + return true + } + + // A reboot in flight is meant to be stopped for a moment, so counting it as + // unresponsive would mark a healthy guest impaired for doing what it was + // asked. Reboot bounds its own window; this only declines to judge it. + if err == nil && !qmpStatus.Running && m.Status(instance) == StateRunning && + !instance.rebooting.Load() { err = fmt.Errorf("QMP reported non-running status %q", qmpStatus.Status) } if err != nil { diff --git a/spinifex/vm/shutdown.go b/spinifex/vm/shutdown.go index c687f5766..ac1c76907 100644 --- a/spinifex/vm/shutdown.go +++ b/spinifex/vm/shutdown.go @@ -6,6 +6,8 @@ import ( "fmt" "log/slog" "os" + "slices" + "strings" "sync" "time" @@ -19,6 +21,98 @@ import ( // disappear after system_powerdown before resorting to SIGKILL. const pidFileRemovalTimeout = 20 * time.Second +const ( + // powerdownResendInterval re-presses the virtual power button. A guest + // whose acpid has not started yet never sees the first one, so a single + // signal is not a shutdown request — it is a bet on the guest being ready. + powerdownResendInterval = 10 * time.Second + // powerdownPollInterval is how often the guest's run state is sampled + // while it shuts down. + powerdownPollInterval = 500 * time.Millisecond + // qmpStatusShutdown is the run state QEMU reports once a guest has powered + // itself off under -action shutdown=pause: stopped, but not yet gone. + qmpStatusShutdown = "shutdown" +) + +// errPowerdownTimedOut reports a guest still running at the end of its budget. +// Callers escalate: Stop to SIGKILL, Reboot to a hard reset. +var errPowerdownTimedOut = errors.New("guest did not power down within its budget") + +// qemuPausesOnShutdown reports whether this guest's QEMU was launched with the +// shutdown action that leaves it paused. A guest started before that flag +// exits on powerdown instead, and a reboot would have nothing left to reset. +// Indirected so a test can describe a guest without one running behind it. +var qemuPausesOnShutdown = func(instance *VM) bool { + pid, err := utils.ReadPidFile(instance.ID) + if err != nil || pid <= 0 { + return false + } + cmdline, err := os.ReadFile(fmt.Sprintf("/proc/%d/cmdline", pid)) + if err != nil { + return false + } + return cmdlineHasPauseAction(cmdline) +} + +// cmdlineHasPauseAction looks for the shutdown action in a NUL-separated +// /proc cmdline. Split out from the /proc read so the matching is testable. +func cmdlineHasPauseAction(cmdline []byte) bool { + return slices.Contains(strings.Split(string(cmdline), "\x00"), "shutdown=pause") +} + +// gracefulPowerdown presses the guest's power button until it shuts itself +// down, so it syncs and unmounts rather than losing its dirty pages. QEMU is +// left paused in the shutdown run state, not exited — the caller decides. +func (m *Manager) gracefulPowerdown(ctx context.Context, instance *VM, budget time.Duration) error { + return m.powerdownWithTuning(ctx, instance, budget, powerdownResendInterval, powerdownPollInterval) +} + +// powerdownWithTuning is gracefulPowerdown with its cadence supplied, so a test +// can drive the re-send and the budget without waiting out the real intervals. +func (m *Manager) powerdownWithTuning(ctx context.Context, instance *VM, + budget, resendInterval, pollInterval time.Duration) error { + if instance.QMPClient == nil { + return errors.New("no QMP client") + } + + deadline := time.Now().Add(budget) + var nextSend time.Time + for { + if !time.Now().Before(nextSend) { + if _, err := sendQMPCommand(ctx, instance.QMPClient, + qmp.QMPCommand{Execute: "system_powerdown"}, instance.ID); err != nil { + // A guest already on its way down rejects the second press, so + // this is only worth a debug line until the budget decides. + slog.Debug("QMP system_powerdown failed", "id", instance.ID, "err", err) + } + nextSend = time.Now().Add(resendInterval) + } + + status, err := queryQMPStatus(ctx, instance, qmpCommandTimeout) + if err == nil && status.Status == qmpStatusShutdown { + return nil + } + // The process going away is the other clean outcome: a guest can exit + // before the poll sees the run state, and on the fence path QEMU may + // have been reaped underneath us. + if !isInstanceProcessRunning(instance) { + return nil + } + if !time.Now().Before(deadline) { + return fmt.Errorf("%w: %s (last run state %q)", + errPowerdownTimedOut, budget, status.Status) + } + + timer := time.NewTimer(pollInterval) + select { + case <-ctx.Done(): + timer.Stop() + return ctx.Err() + case <-timer.C: + } + } +} + // Stop transitions a running instance to stopped: graceful QMP shutdown, volume // unmount, tap teardown, resource deallocation. Migrates to the "stopped" KV // bucket and fires OnInstanceDown. Returns ErrInstanceNotFound, @@ -517,9 +611,15 @@ func (m *Manager) shutdownAndUnmount(instance *VM) error { // unmount would seal this node's stale copy over theirs. func (m *Manager) shutdownQEMU(instance *VM) { if instance.QMPClient != nil { - if _, err := sendQMPCommand(context.Background(), instance.QMPClient, qmp.QMPCommand{Execute: "system_powerdown"}, instance.ID); err != nil { - slog.Warn("QMP system_powerdown failed (VM may already be stopped)", - "id", instance.ID, "err", err) + ctx := context.Background() + // The whole graceful budget is the pid-file wait it replaces, so a stop + // takes no longer than it used to. quit closes the paused-on-shutdown + // window a reboot needs and a stop does not. + if err := m.gracefulPowerdown(ctx, instance, pidFileRemovalTimeout); err != nil { + slog.Warn("Guest did not power down gracefully", "id", instance.ID, "err", err) + } else if _, err := sendQMPCommand(ctx, instance.QMPClient, + qmp.QMPCommand{Execute: "quit"}, instance.ID); err != nil { + slog.Warn("QMP quit failed (VM may already be stopped)", "id", instance.ID, "err", err) } } diff --git a/spinifex/vm/shutdown_test.go b/spinifex/vm/shutdown_test.go index 28366f623..71d0f2323 100644 --- a/spinifex/vm/shutdown_test.go +++ b/spinifex/vm/shutdown_test.go @@ -1366,10 +1366,10 @@ func TestShutdownAndUnmount_NilQMPClient_ProceedsToUnmount(t *testing.T) { } // TestShutdownAndUnmount_PowerdownSent_NoForceKill exercises the happy path: -// QMPClient is wired, system_powerdown is dispatched, the PID-file wait -// returns immediately (no PID file present), and the unmount step runs. -// The force-kill branch must not run because WaitForPidFileRemoval returned -// nil. +// QMPClient is wired, the guest is asked to power down and the paused QEMU is +// then quit, the PID-file wait returns immediately (no PID file present), and +// the unmount step runs. The force-kill branch must not run because +// WaitForPidFileRemoval returned nil. func TestShutdownAndUnmount_PowerdownSent_NoForceKill(t *testing.T) { t.Setenv("XDG_RUNTIME_DIR", t.TempDir()) recorder := &qmpRecorder{} @@ -1386,8 +1386,8 @@ func TestShutdownAndUnmount_PowerdownSent_NoForceKill(t *testing.T) { require.NoError(t, m.shutdownAndUnmount(instance)) - assert.Equal(t, []string{"system_powerdown"}, recorder.executes(), - "shutdownAndUnmount must dispatch exactly one system_powerdown QMP command") + assert.Equal(t, []string{"system_powerdown", "query-status", "quit"}, recorder.executes(), + "shutdownAndUnmount must ask the guest to power down, then end the paused QEMU") mounter.mu.Lock() defer mounter.mu.Unlock() @@ -1578,3 +1578,64 @@ func TestTerminate_SealFailure_Tolerated(t *testing.T) { assert.Equal(t, []string{"i-term-seal"}, cleaner.deleteVolumes, "terminate must still delete the volumes after a failed seal") } + +// TestGracefulPowerdown_ResendReachesALateGuest is the boot-race defect stated +// directly: a guest whose acpid has not started yet ignores the first power +// button. One signal would burn the whole budget and escalate to a kill on a +// guest that was only busy booting, so the button is pressed again. +func TestGracefulPowerdown_ResendReachesALateGuest(t *testing.T) { + t.Setenv("XDG_RUNTIME_DIR", t.TempDir()) + require.NoError(t, utils.WritePidFile("i-late", os.Getpid())) + t.Cleanup(func() { _ = utils.RemovePidFile("i-late") }) + + var presses int + recorder := &qmpRecorder{} + qmpClient, cancel := newMockQMPClient(t, func(cmd qmp.QMPCommand) map[string]any { + recorder.record(cmd) + if cmd.Execute == "system_powerdown" { + presses++ + return nil + } + if cmd.Execute != "query-status" { + return nil + } + // The guest only acts on the third press. + if presses < 3 { + return qmpStatusResponse("running", true) + } + return qmpStatusResponse(qmpStatusShutdown, false) + }) + defer cancel() + + m := NewManager() + instance := &VM{ID: "i-late", Status: StateRunning, QMPClient: qmpClient} + + err := m.powerdownWithTuning(t.Context(), instance, 5*time.Second, 5*time.Millisecond, time.Millisecond) + require.NoError(t, err, "a guest that honours a later press must still shut down gracefully") + assert.GreaterOrEqual(t, presses, 3, "the power button must be pressed again while the guest ignores it") +} + +// TestGracefulPowerdown_WedgedGuestTimesOut covers the other half: a guest that +// never answers must not be waited on forever. The error is what Stop escalates +// to SIGKILL on and Reboot escalates to a hard reset on. +func TestGracefulPowerdown_WedgedGuestTimesOut(t *testing.T) { + t.Setenv("XDG_RUNTIME_DIR", t.TempDir()) + require.NoError(t, utils.WritePidFile("i-wedged", os.Getpid())) + t.Cleanup(func() { _ = utils.RemovePidFile("i-wedged") }) + + qmpClient, cancel := newMockQMPClient(t, func(cmd qmp.QMPCommand) map[string]any { + if cmd.Execute == "query-status" { + return qmpStatusResponse("running", true) + } + return nil + }) + defer cancel() + + m := NewManager() + instance := &VM{ID: "i-wedged", Status: StateRunning, QMPClient: qmpClient} + + err := m.powerdownWithTuning(t.Context(), instance, 30*time.Millisecond, 5*time.Millisecond, time.Millisecond) + require.Error(t, err) + assert.ErrorIs(t, err, errPowerdownTimedOut) + assert.Contains(t, err.Error(), `last run state "running"`) +} diff --git a/spinifex/vm/vm.go b/spinifex/vm/vm.go index 72ee83fe5..58507a1c3 100644 --- a/spinifex/vm/vm.go +++ b/spinifex/vm/vm.go @@ -10,6 +10,7 @@ import ( "strconv" "strings" "sync" + "sync/atomic" "time" "github.com/aws/aws-sdk-go/aws" @@ -90,6 +91,11 @@ type VM struct { // Manager hands out a stable *VM, so the lock is shared across calls. attachMu sync.Mutex `json:"-"` + // rebooting marks the window in which this guest is expected to power + // itself off and be reset again. The heartbeat quits a guest it finds + // stopped in the shutdown run state, and a reboot passes through it. + rebooting atomic.Bool `json:"-"` + // DesiredState is the state this instance has been asked to be in, as // opposed to Status, which is the state it is observed to be in. DesiredState DesiredState `json:"desired_state,omitempty"` @@ -396,6 +402,11 @@ func (cfg *Config) Execute() (*exec.Cmd, error) { args = append(args, "-name", fmt.Sprintf("guest=%s,debug-threads=on", cfg.Name)) } + // A guest that powers itself off pauses QEMU instead of ending it. That + // window is what a graceful reboot needs — process, taps and drives all + // survive the guest's clean shutdown. Every other path closes it with quit. + args = append(args, "-action", "shutdown=pause") + if cfg.PIDFile != "" { args = append(args, "-pidfile", cfg.PIDFile) } diff --git a/spinifex/vm/vm_test.go b/spinifex/vm/vm_test.go index 1b3b6fed2..1a831c1db 100644 --- a/spinifex/vm/vm_test.go +++ b/spinifex/vm/vm_test.go @@ -58,6 +58,7 @@ func TestExecute(t *testing.T) { expectedArgs := []string{ "-name", "guest=test-vm,debug-threads=on", + "-action", "shutdown=pause", "-smp", "2", "-m", "1024", "-drive", "file=disk.img,format=qcow2", diff --git a/spinifex/vm/volumes_test.go b/spinifex/vm/volumes_test.go index dc923f2a3..152b47362 100644 --- a/spinifex/vm/volumes_test.go +++ b/spinifex/vm/volumes_test.go @@ -602,6 +602,16 @@ func TestReboot_InstanceNotFound(t *testing.T) { assert.ErrorIs(t, err, ErrInstanceNotFound) } +// pausingGuest makes qemuPausesOnShutdown describe this test's guest as one +// whose QEMU pauses on shutdown, which is what every guest launched by the +// current code does. Restores the real /proc check on cleanup. +func pausingGuest(t *testing.T) { + t.Helper() + previous := qemuPausesOnShutdown + qemuPausesOnShutdown = func(*VM) bool { return true } + t.Cleanup(func() { qemuPausesOnShutdown = previous }) +} + func TestReboot_NotRunning(t *testing.T) { m := NewManager() m.Insert(&VM{ID: "i-1", Status: StateStopped}) @@ -614,9 +624,11 @@ func TestReboot_NotRunning(t *testing.T) { // TestReboot_DoesNotFireHooks asserts that Manager.Reboot fires neither // OnInstanceUp nor OnInstanceDown. The hook contract requires // hooks to fire only on Pending→Running and terminal transitions; reboot keeps -// the VM in StateRunning across system_reset, so firing OnInstanceDown + -// OnInstanceUp would tear down per-instance NATS subs on every reboot. +// the VM in StateRunning across the powerdown and reset, so firing +// OnInstanceDown + OnInstanceUp would tear down per-instance NATS subs on +// every reboot. func TestReboot_DoesNotFireHooks(t *testing.T) { + pausingGuest(t) recorder := &qmpRecorder{} qmpClient, cancel := newMockQMPClient(t, func(cmd qmp.QMPCommand) map[string]any { recorder.record(cmd) @@ -636,17 +648,20 @@ func TestReboot_DoesNotFireHooks(t *testing.T) { m.Insert(&VM{ID: "i-1", Status: StateRunning, QMPClient: qmpClient}) require.NoError(t, m.Reboot(t.Context(), "i-1")) + m.WaitForBackgroundWork() assert.Equal(t, 0, upCalls, "Reboot must not fire OnInstanceUp") assert.Equal(t, 0, downCalls, "Reboot must not fire OnInstanceDown") - assert.Equal(t, []string{"system_reset", "query-status"}, recorder.executes(), - "Reboot must verify QEMU resumed after system_reset") + assert.Equal(t, []string{"system_powerdown", "query-status", "system_reset", "query-status"}, + recorder.executes(), + "Reboot must ask the guest down first, then verify QEMU resumed after system_reset") } // TestReboot_DoesNotChangeStatus asserts the VM stays in StateRunning across // reboot. Pairs with TestReboot_DoesNotFireHooks to lock down the hook // contract: status doesn't transition, so hooks shouldn't fire. func TestReboot_DoesNotChangeStatus(t *testing.T) { + pausingGuest(t) qmpClient, cancel := newMockQMPClient(t, func(cmd qmp.QMPCommand) map[string]any { if cmd.Execute == "query-status" { return qmpStatusResponse("running", true) @@ -659,6 +674,7 @@ func TestReboot_DoesNotChangeStatus(t *testing.T) { m.Insert(&VM{ID: "i-1", Status: StateRunning, QMPClient: qmpClient}) require.NoError(t, m.Reboot(t.Context(), "i-1")) + m.WaitForBackgroundWork() v, ok := m.Get("i-1") require.True(t, ok) @@ -666,6 +682,7 @@ func TestReboot_DoesNotChangeStatus(t *testing.T) { } func TestReboot_QMPFailureSurfacesError(t *testing.T) { + pausingGuest(t) qmpClient, cancel := newMockQMPClient(t, func(cmd qmp.QMPCommand) map[string]any { return map[string]any{ "error": map[string]any{ @@ -679,23 +696,37 @@ func TestReboot_QMPFailureSurfacesError(t *testing.T) { m := NewManager() m.Insert(&VM{ID: "i-1", Status: StateRunning, QMPClient: qmpClient}) - err := m.Reboot(t.Context(), "i-1") + instance, ok := m.Get("i-1") + require.True(t, ok) + err := m.rebootNow(t.Context(), instance) require.Error(t, err) assert.Contains(t, err.Error(), "QMP system_reset") } +// TestReboot_ResumesPausedRunstates drives the whole reboot: the guest reaches +// the shutdown runstate on its own, is reset, and lands parked in a runstate +// that needs cont before its vCPUs run again. func TestReboot_ResumesPausedRunstates(t *testing.T) { + pausingGuest(t) for _, runstate := range []string{"paused", "prelaunch"} { t.Run(runstate, func(t *testing.T) { recorder := &qmpRecorder{} - statusQueries := 0 + reset := false + postResetQueries := 0 qmpClient, cancel := newMockQMPClient(t, func(cmd qmp.QMPCommand) map[string]any { recorder.record(cmd) + if cmd.Execute == "system_reset" { + reset = true + return nil + } if cmd.Execute != "query-status" { return nil } - statusQueries++ - if statusQueries == 1 { + if !reset { + return qmpStatusResponse(qmpStatusShutdown, false) + } + postResetQueries++ + if postResetQueries == 1 { return qmpStatusResponse(runstate, false) } return qmpStatusResponse("running", true) @@ -706,12 +737,17 @@ func TestReboot_ResumesPausedRunstates(t *testing.T) { m.Insert(&VM{ID: "i-1", Status: StateRunning, QMPClient: qmpClient}) require.NoError(t, m.Reboot(t.Context(), "i-1")) - assert.Equal(t, []string{"system_reset", "query-status", "cont", "query-status"}, recorder.executes()) + m.WaitForBackgroundWork() + assert.Equal(t, []string{ + "system_powerdown", "query-status", + "system_reset", "query-status", "cont", "query-status", + }, recorder.executes()) }) } } func TestReboot_NonRunningTimesOut(t *testing.T) { + pausingGuest(t) qmpClient, cancel := newMockQMPClient(t, func(cmd qmp.QMPCommand) map[string]any { if cmd.Execute == "query-status" { return qmpStatusResponse("shutdown", false) @@ -725,13 +761,16 @@ func TestReboot_NonRunningTimesOut(t *testing.T) { ctx, cancelContext := context.WithTimeout(t.Context(), 25*time.Millisecond) defer cancelContext() - err := m.Reboot(ctx, "i-1") + instance, ok := m.Get("i-1") + require.True(t, ok) + err := m.rebootNow(ctx, instance) require.Error(t, err) assert.ErrorIs(t, err, context.DeadlineExceeded) assert.Contains(t, err.Error(), `last status "shutdown"`) } func TestReboot_MalformedStatusSurfacesError(t *testing.T) { + pausingGuest(t) qmpClient, cancel := newMockQMPClient(t, func(cmd qmp.QMPCommand) map[string]any { if cmd.Execute == "query-status" { return map[string]any{"return": map[string]any{}} @@ -743,12 +782,15 @@ func TestReboot_MalformedStatusSurfacesError(t *testing.T) { m := NewManager() m.Insert(&VM{ID: "i-1", Status: StateRunning, QMPClient: qmpClient}) - err := m.Reboot(t.Context(), "i-1") + instance, ok := m.Get("i-1") + require.True(t, ok) + err := m.rebootNow(t.Context(), instance) require.Error(t, err) assert.Contains(t, err.Error(), "missing status") } func TestReboot_ContFailureSurfacesError(t *testing.T) { + pausingGuest(t) qmpClient, cancel := newMockQMPClient(t, func(cmd qmp.QMPCommand) map[string]any { if cmd.Execute == "query-status" { return qmpStatusResponse("paused", false) @@ -765,31 +807,48 @@ func TestReboot_ContFailureSurfacesError(t *testing.T) { m := NewManager() m.Insert(&VM{ID: "i-1", Status: StateRunning, QMPClient: qmpClient}) - err := m.Reboot(t.Context(), "i-1") + instance, ok := m.Get("i-1") + require.True(t, ok) + err := m.rebootNow(t.Context(), instance) require.Error(t, err) assert.Contains(t, err.Error(), `QMP cont from status "paused"`) } func TestReboot_StateChangePreventsCont(t *testing.T) { + pausingGuest(t) var m *Manager recorder := &qmpRecorder{} + reset := false qmpClient, cancel := newMockQMPClient(t, func(cmd qmp.QMPCommand) map[string]any { recorder.record(cmd) - if cmd.Execute == "query-status" { - m.UpdateState("i-1", func(v *VM) { v.Status = StateStopping }) - return qmpStatusResponse("paused", false) + if cmd.Execute == "system_reset" { + reset = true + return nil } - return nil + if cmd.Execute != "query-status" { + return nil + } + if !reset { + return qmpStatusResponse(qmpStatusShutdown, false) + } + // A concurrent stop lands between the reset and the resume: cont must + // not run against an instance that is no longer meant to be running. + m.UpdateState("i-1", func(v *VM) { v.Status = StateStopping }) + return qmpStatusResponse("paused", false) }) defer cancel() m = NewManager() m.Insert(&VM{ID: "i-1", Status: StateRunning, QMPClient: qmpClient}) - err := m.Reboot(t.Context(), "i-1") + instance, ok := m.Get("i-1") + require.True(t, ok) + err := m.rebootNow(t.Context(), instance) require.Error(t, err) assert.ErrorIs(t, err, ErrInvalidTransition) - assert.Equal(t, []string{"system_reset", "query-status"}, recorder.executes()) + assert.Equal(t, []string{ + "system_powerdown", "query-status", "system_reset", "query-status", + }, recorder.executes()) } func TestQMPHeartbeatPoll_UsesRunstate(t *testing.T) { @@ -1569,3 +1628,204 @@ func TestDetachVolume_BlockdevDelAlreadyRemoved_IdempotentSuccess(t *testing.T) assert.Equal(t, []string{"vol-1"}, mounter.unmountedOne, "an already-removed block node must resume through to the unmount seal") } + +// TestReboot_WedgedGuestFallsBackToHardReset asserts the AWS contract: a guest +// that will not shut down cleanly is reset anyway rather than left running, and +// the instance stays in StateRunning throughout. +func TestReboot_WedgedGuestFallsBackToHardReset(t *testing.T) { + pausingGuest(t) + t.Setenv("XDG_RUNTIME_DIR", t.TempDir()) + require.NoError(t, utils.WritePidFile("i-1", os.Getpid())) + t.Cleanup(func() { _ = utils.RemovePidFile("i-1") }) + + previous := rebootPowerdownTimeout + rebootPowerdownTimeout = 30 * time.Millisecond + t.Cleanup(func() { rebootPowerdownTimeout = previous }) + + recorder := &qmpRecorder{} + qmpClient, cancel := newMockQMPClient(t, func(cmd qmp.QMPCommand) map[string]any { + recorder.record(cmd) + // The guest ignores the power button and never leaves the running run + // state, which is also how it reads coming back from the hard reset. + if cmd.Execute == "query-status" { + return qmpStatusResponse("running", true) + } + return nil + }) + defer cancel() + + m := NewManager() + m.Insert(&VM{ID: "i-1", Status: StateRunning, QMPClient: qmpClient}) + + require.NoError(t, m.Reboot(t.Context(), "i-1")) + m.WaitForBackgroundWork() + + assert.Contains(t, recorder.executes(), "system_reset", + "a guest that will not power down must still be reset") + v, ok := m.Get("i-1") + require.True(t, ok) + assert.Equal(t, StateRunning, m.Status(v)) +} + +// TestQMPHeartbeatPoll_QuitsGuestThatPoweredItselfOff covers the cost of the +// -action shutdown=pause flag: a guest that runs `poweroff` now leaves QEMU +// paused rather than gone, and something has to end it. +func TestQMPHeartbeatPoll_QuitsGuestThatPoweredItselfOff(t *testing.T) { + recorder := &qmpRecorder{} + qmpClient, cancel := newMockQMPClient(t, func(cmd qmp.QMPCommand) map[string]any { + recorder.record(cmd) + if cmd.Execute == "query-status" { + return qmpStatusResponse(qmpStatusShutdown, false) + } + return nil + }) + defer cancel() + + m := NewManager() + instance := &VM{ID: "i-1", Status: StateRunning, QMPClient: qmpClient} + m.Insert(instance) + + assert.True(t, m.qmpHeartbeatPoll(instance)) + assert.Equal(t, []string{"query-status", "quit"}, recorder.executes()) +} + +// TestQMPHeartbeatPoll_LeavesARebootingGuestAlone is the other side of it. A +// reboot passes through the same run state on purpose, so quitting on sight +// would destroy the guest the reboot was about to bring back. +func TestQMPHeartbeatPoll_LeavesARebootingGuestAlone(t *testing.T) { + recorder := &qmpRecorder{} + qmpClient, cancel := newMockQMPClient(t, func(cmd qmp.QMPCommand) map[string]any { + recorder.record(cmd) + if cmd.Execute == "query-status" { + return qmpStatusResponse(qmpStatusShutdown, false) + } + return nil + }) + defer cancel() + + m := NewManager() + instance := &VM{ID: "i-1", Status: StateRunning, QMPClient: qmpClient} + instance.rebooting.Store(true) + m.Insert(instance) + + assert.True(t, m.qmpHeartbeatPoll(instance)) + assert.Equal(t, []string{"query-status"}, recorder.executes(), + "a rebooting guest must not be quit, and must not be counted unresponsive") + assert.Zero(t, instance.Health.QMPConsecutiveFailures, + "a reboot in flight is not a failed heartbeat") +} + +// TestReboot_PreFlagGuestSkipsPowerdown covers the upgrade window. A guest +// launched before -action shutdown=pause exits on powerdown rather than +// pausing, so asking it to shut down would leave nothing to reset and the +// guest down. Those are reset without asking, exactly as they were before. +func TestReboot_PreFlagGuestSkipsPowerdown(t *testing.T) { + previous := qemuPausesOnShutdown + qemuPausesOnShutdown = func(*VM) bool { return false } + t.Cleanup(func() { qemuPausesOnShutdown = previous }) + + recorder := &qmpRecorder{} + qmpClient, cancel := newMockQMPClient(t, func(cmd qmp.QMPCommand) map[string]any { + recorder.record(cmd) + if cmd.Execute == "query-status" { + return qmpStatusResponse("running", true) + } + return nil + }) + defer cancel() + + m := NewManager() + m.Insert(&VM{ID: "i-1", Status: StateRunning, QMPClient: qmpClient}) + + require.NoError(t, m.Reboot(t.Context(), "i-1")) + m.WaitForBackgroundWork() + assert.Equal(t, []string{"system_reset", "query-status"}, recorder.executes(), + "a guest that would exit on powerdown must not be asked to power down") +} + +// TestReboot_AnswersBeforeTheGuestIsBack is the contract EC2 documents: the +// reply says the request was accepted. A guest takes tens of seconds to shut +// down and the caller's request times out long before that, so a Reboot that +// waited would report a reboot that had in fact succeeded as a failure. +func TestReboot_AnswersBeforeTheGuestIsBack(t *testing.T) { + pausingGuest(t) + release := make(chan struct{}) + qmpClient, cancel := newMockQMPClient(t, func(cmd qmp.QMPCommand) map[string]any { + if cmd.Execute == "query-status" { + // The guest holds the power button down until the test lets go, + // standing in for the seconds a real one spends shutting down. + <-release + return qmpStatusResponse("running", true) + } + return nil + }) + defer cancel() + + m := NewManager() + m.Insert(&VM{ID: "i-1", Status: StateRunning, QMPClient: qmpClient}) + + done := make(chan error, 1) + go func() { done <- m.Reboot(t.Context(), "i-1") }() + + select { + case err := <-done: + require.NoError(t, err) + case <-time.After(5 * time.Second): + close(release) + t.Fatal("Reboot blocked on the guest shutting down; callers time out well inside that") + } + close(release) + m.WaitForBackgroundWork() +} + +// TestReboot_RepeatJoinsTheOneInFlight asserts two reboots of one guest do not +// race each other through the powerdown and reset. +func TestReboot_RepeatJoinsTheOneInFlight(t *testing.T) { + pausingGuest(t) + release := make(chan struct{}) + recorder := &qmpRecorder{} + qmpClient, cancel := newMockQMPClient(t, func(cmd qmp.QMPCommand) map[string]any { + recorder.record(cmd) + if cmd.Execute == "query-status" { + <-release + return qmpStatusResponse("running", true) + } + return nil + }) + defer cancel() + + m := NewManager() + m.Insert(&VM{ID: "i-1", Status: StateRunning, QMPClient: qmpClient}) + + require.NoError(t, m.Reboot(t.Context(), "i-1")) + require.NoError(t, m.Reboot(t.Context(), "i-1")) + close(release) + m.WaitForBackgroundWork() + + var resets int + for _, execute := range recorder.executes() { + if execute == "system_reset" { + resets++ + } + } + assert.Equal(t, 1, resets, "the repeat must join the reboot in flight, not start a second") +} + +func TestCmdlineHasPauseAction(t *testing.T) { + for name, tc := range map[string]struct { + cmdline string + want bool + }{ + "present": {"qemu-system-x86_64\x00-action\x00shutdown=pause\x00-smp\x002", true}, + "absent": {"qemu-system-x86_64\x00-smp\x002", false}, + "other action": {"qemu-system-x86_64\x00-action\x00reboot=shutdown", false}, + // A substring match would accept this and reboot would then hang + // waiting for a pause that never comes. + "substring only": {"qemu-system-x86_64\x00-name\x00guest=shutdown=paused", false}, + "empty": {"", false}, + } { + t.Run(name, func(t *testing.T) { + assert.Equal(t, tc.want, cmdlineHasPauseAction([]byte(tc.cmdline))) + }) + } +} diff --git a/tests/e2e/harness/rds_client.go b/tests/e2e/harness/rds_client.go index 679d4d31b..871956b13 100644 --- a/tests/e2e/harness/rds_client.go +++ b/tests/e2e/harness/rds_client.go @@ -60,6 +60,9 @@ export DEBIAN_FRONTEND=noninteractive apt-get update -y || exit 10 apt-get install -y postgresql-client || exit 11 apt-get install -y mariadb-client || exit 12 +# pgbench ships in contrib, not the client package, and a load phase has no +# other way to dirty an engine's buffer pool from outside it. +apt-get install -y postgresql-contrib || exit 13 echo done > %[1]s `, rdsClientStatusFile, rdsClientExitCodeFile) @@ -310,6 +313,35 @@ func psqlCommand(conn PSQLConn, sql string) string { return strings.Join(env, " ") + " " + strings.Join(args, " ") } +// pgbenchTimeout bounds one load phase. Initialising a scale factor's worth of +// rows and then driving the buffer pool dirty are both minutes of guest I/O on +// these hosts rather than seconds. +const pgbenchTimeout = 20 * time.Minute + +// PGBench runs pgbench in the client guest against conn, and returns its output. +// The password goes through the environment for the same reason psql's does. +func PGBench(t *testing.T, tgt SSHTarget, conn PSQLConn, args ...string) string { + t.Helper() + port := conn.Port + if port == 0 { + port = PostgresEnginePort + } + command := strings.Join(append([]string{ + "PGPASSWORD=" + ShellQuote(conn.Password), + "PGCONNECT_TIMEOUT=30", + "pgbench", + "--host", ShellQuote(conn.Host), + "--port", strconv.FormatInt(port, 10), + "--username", ShellQuote(conn.User), + }, append(args, ShellQuote(conn.DBName))...), " ") + + out, err := GuestExecTimeout(tgt, command, pgbenchTimeout) + if err != nil { + t.Fatalf("pgbench %v against %s:%d/%s: %v\n%s", args, conn.Host, port, conn.DBName, err, out) + } + return out +} + // ResolveInGuest returns the addresses host resolves to inside the guest. // // This is the only resolution that proves anything about the guest's DNS path diff --git a/tests/e2e/rds/graceful_reboot_test.go b/tests/e2e/rds/graceful_reboot_test.go new file mode 100644 index 000000000..9d02ba8dd --- /dev/null +++ b/tests/e2e/rds/graceful_reboot_test.go @@ -0,0 +1,126 @@ +//go:build e2e + +package rds + +import ( + "fmt" + "strconv" + "strings" + "testing" + "time" + + "github.com/aws/aws-sdk-go/aws" + "github.com/aws/aws-sdk-go/service/rds" + "github.com/mulgadc/spinifex/tests/e2e/harness" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +const ( + // The scale factor to build the database at. pgbench costs roughly 16 MiB + // per unit, so this puts the data comfortably past the 256 MiB of shared + // buffers a floor instance gets — the pool is then full of pages the engine + // has to write out on the way down, rather than a dataset that fits. + gracefulRebootScale = 25 + + // How long the read-write run drives the instance for, to leave the buffer + // pool dirty at the moment the reboot arrives. + gracefulRebootDirtyRun = "45" + + // The probe table and how many rows go in it. + gracefulRebootTable = "e2e_graceful_reboot_probe" + gracefulRebootRows = 1000 +) + +// TestLoadedGracefulReboot reboots a loaded PostgreSQL instance and asserts the +// engine was asked to shut down rather than reset under. +// +// The probe is an UNLOGGED table, and the choice is the whole test. PostgreSQL +// writes no WAL for one, so its contents are durable exactly when the engine +// shuts down cleanly: a clean shutdown checkpoints them, and crash recovery +// truncates every unlogged relation unconditionally. The row count afterwards is +// therefore a direct read of which of the two happened. +// +// The obvious assertions do not work. Rows committed normally survive a hard +// reset too — that is what the WAL is for — so a test that writes, resets and +// finds its data would pass against a reset that lost the guest's entire page +// cache. `synchronous_commit = off` does expose the gap, but only for the few +// hundred milliseconds before the WAL writer flushes, so whether it catches a +// hard reset depends on how fast the reset arrives. An unlogged table has no +// such window. +func TestLoadedGracefulReboot(t *testing.T) { + f := requireRDSFixture(t) + t.Parallel() + reserveDBVMs(t, dbClass) + + id := fmt.Sprintf("%s-gracereboot-%d", dbInstancePfx, time.Now().Unix()) + + harness.Phase(t, "Creating DB instance %q", id) + createDBInstance(t, f, id) + client := rdsClient(t, f) + + instance := waitForAvailable(t, f, id) + conn := harness.PSQLConnFor(t, instance, dbMasterUser, dbMasterPassword, dbName) + + harness.Phase(t, "Loading %q past its shared buffers", id) + sharedBuffers := queryBytes(t, client, conn, + "SELECT setting::bigint * 8192 FROM pg_settings WHERE name = 'shared_buffers';") + harness.Detail(t, "shared_buffers_bytes", sharedBuffers) + + harness.Step(t, "pgbench -i -s %d", gracefulRebootScale) + harness.PGBench(t, client, conn, "-i", "-q", "-s", strconv.Itoa(gracefulRebootScale)) + + // Assert the load is testing something. A scale factor that quietly built a + // database smaller than the buffer pool leaves nothing to write out on the + // way down, and the test's name stops matching what it does. + dbBytes := queryBytes(t, client, conn, "SELECT pg_database_size(current_database());") + harness.Detail(t, "database_bytes", dbBytes) + require.Greaterf(t, dbBytes, sharedBuffers, + "the load built %d bytes against %d bytes of shared buffers, so the pool was never under pressure "+ + "and this run does not exercise a loaded shutdown", dbBytes, sharedBuffers) + + harness.Step(t, "pgbench -T %s to dirty the buffer pool", gracefulRebootDirtyRun) + harness.PGBench(t, client, conn, "-T", gracefulRebootDirtyRun, "-c", "4", "-j", "2") + + harness.Phase(t, "Writing the unlogged probe") + harness.PSQL(t, client, conn, fmt.Sprintf( + "CREATE UNLOGGED TABLE %s (id int primary key, at timestamptz default now()); "+ + "INSERT INTO %s (id) SELECT generate_series(1, %d);", + gracefulRebootTable, gracefulRebootTable, gracefulRebootRows)) + + require.Equalf(t, gracefulRebootRows, countRows(t, client, conn, gracefulRebootTable), + "the probe table did not hold its rows before the reboot, so nothing after this proves anything") + + before := postmasterStartTime(t, client, conn) + + harness.Phase(t, "Rebooting %q while its buffer pool is dirty", id) + _, err := f.AWS.RDS.RebootDBInstance(&rds.RebootDBInstanceInput{DBInstanceIdentifier: aws.String(id)}) + require.NoError(t, err, "reboot-db-instance") + waitForAvailable(t, f, id) + + // Without this the row count proves nothing: an engine that never restarted + // would of course still hold them. + after := postmasterStartTime(t, client, conn) + require.NotEqual(t, before, after, + "pg_postmaster_start_time() did not move, so the engine never restarted and the probe is meaningless") + + assert.Equalf(t, gracefulRebootRows, countRows(t, client, conn, gracefulRebootTable), + "the unlogged probe table lost its rows across the reboot, which is what PostgreSQL does to one "+ + "on crash recovery — the engine was reset rather than asked to shut down") +} + +// queryBytes runs a single-value query and returns it as an integer. +func queryBytes(t *testing.T, tgt harness.SSHTarget, conn harness.PSQLConn, sql string) int64 { + t.Helper() + out := strings.TrimSpace(harness.PSQL(t, tgt, conn, sql)) + n, err := strconv.ParseInt(out, 10, 64) + require.NoErrorf(t, err, "parse %q as an integer", out) + return n +} + +// countRows returns how many rows table holds. An unlogged table truncated by +// crash recovery still exists, so this reads zero rather than failing. +func countRows(t *testing.T, tgt harness.SSHTarget, conn harness.PSQLConn, table string) int { + t.Helper() + return int(queryBytes(t, tgt, conn, "SELECT count(*) FROM "+table+";")) +} diff --git a/tests/e2e/reboot/guestshutdown_test.go b/tests/e2e/reboot/guestshutdown_test.go new file mode 100644 index 000000000..d4d2b55c5 --- /dev/null +++ b/tests/e2e/reboot/guestshutdown_test.go @@ -0,0 +1,364 @@ +//go:build e2e + +package reboot + +import ( + "context" + "encoding/base64" + "fmt" + "os" + "strconv" + "strings" + "testing" + "time" + + "github.com/aws/aws-sdk-go/aws" + "github.com/aws/aws-sdk-go/service/ec2" + "github.com/mulgadc/spinifex/tests/e2e/harness" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +const ( + guestShutdownKeyName = "guest-shutdown-e2e-key" + guestShutdownSGName = "guest-shutdown-e2e-sg" + guestShutdownVPCCIDR = "10.211.0.0/16" + guestShutdownSubnetCIDR = "10.211.1.0/24" + + // The slow guest's shutdown hook writes one fsynced line a second for this + // long. Comfortably inside the budget the daemon gives a guest, and far + // enough past a normal shutdown that a reset rather than a wait is + // unmistakable in the line count that survives. + slowShutdownSeconds = 25 + + // What the file must hold afterwards. Short of the full run so a slow guest + // under CI load is not failed for losing the last second or two, but far + // enough above zero that a hard reset cannot reach it. + slowShutdownMinLines = 20 + + // The budget the daemon gives a guest to power down for a reboot. Not + // imported: this is the e2e suite's own statement of the contract, and a + // change to the constant should fail here rather than pass silently. + guestPowerdownBudget = 60 * time.Second + + // How long a guest gets to answer on a new boot ID. The wedged variant + // spends its whole budget before the reset and only then boots. + guestRebootBudget = 5 * time.Minute + + // The line the daemon logs when it gives up asking and resets the guest. + hardResetLogLine = "Guest did not power down for reboot" +) + +// slowShutdownUserData installs a guest that takes its time going down and +// leaves a record of how long it was given. Each line is fsynced, so the file +// that survives is a direct measure of how much of the shutdown actually ran: +// a reset at the first poll leaves none of it. +// +// Ordinary service dependencies on purpose — the unit is stopped early in the +// shutdown transaction, while the root filesystem is still writable. +var slowShutdownUserData = fmt.Sprintf(`#!/bin/bash +set -e +cat > /usr/local/bin/slow-shutdown <<'EOS' +#!/bin/sh +i=0 +while [ $i -lt %[1]d ]; do + i=$((i+1)) + date +%%s >> %[2]s + sync %[2]s + sleep 1 +done +EOS +chmod +x /usr/local/bin/slow-shutdown +cat > /etc/systemd/system/slow-shutdown.service <<'UNIT' +[Unit] +Description=Guest shutdown probe + +[Service] +Type=oneshot +RemainAfterExit=yes +ExecStart=/bin/true +ExecStop=/usr/local/bin/slow-shutdown +TimeoutStopSec=120 + +[Install] +WantedBy=multi-user.target +UNIT +rm -f %[2]s +systemctl daemon-reload +systemctl enable --now slow-shutdown.service +touch /run/guest-shutdown-ready +`, slowShutdownSeconds, slowShutdownProbeFile) + +const slowShutdownProbeFile = "/var/lib/slow-shutdown.log" + +// wedgedUserData installs a guest that never acknowledges the power button. +// systemd-logind is what turns an ACPI power-button event into a shutdown on +// these images; acpid is disabled too so the answer does not depend on which +// of the two the image happens to ship. +const wedgedUserData = `#!/bin/bash +set -e +mkdir -p /etc/systemd/logind.conf.d +cat > /etc/systemd/logind.conf.d/99-ignore-power.conf <<'EOF' +[Login] +HandlePowerKey=ignore +HandlePowerKeyLongPress=ignore +EOF +systemctl disable --now acpid 2>/dev/null || true +systemctl restart systemd-logind +touch /run/guest-shutdown-ready +` + +// TestGuestShutdownBudget proves the two paths a guest reboot can take, against +// real guests rather than a mocked QMP socket. +// +// A reset alone never reaches the guest kernel, so it syncs nothing. The +// primitive therefore asks the guest to shut down and only resets it once +// asking has failed — and the two cases that separates are a guest that is slow +// and must be waited for, and one that will never answer and must be reset +// anyway. Each is asserted on the evidence only it can produce. +func TestGuestShutdownBudget(t *testing.T) { + env := harness.LoadEnv(t) + requireRunnerMode(t, env) + + fix := &fixture{ + env: env, + artifacts: harness.ArtifactDir(t, env), + ssh: harness.NewPeerSSH(), + preIPs: map[string]string{}, + timeouts: timeouts{ + instanceRunning: durationEnv("INSTANCE_RUNNING_SECS", 120*time.Second), + }, + } + + resolveTrust(t, fix) + fix.aws = harness.NewAWSClient(t, env) + t.Cleanup(func() { cleanup(t, fix) }) + + harness.Phase(t, "Prerequisites") + ctx, cancel := context.WithTimeout(context.Background(), 20*time.Second) + require.NoError(t, fix.ssh.Ping(ctx, fix.env.WANHost), "ssh to %s", fix.env.WANHost) + cancel() + + fix.instanceType = discoverNanoInstanceType(t, fix.aws) + fix.amiID = discoverAMI(t, fix.aws) + harness.Detail(t, "instance_type", fix.instanceType) + harness.Detail(t, "ami", fix.amiID) + provisionKeyPair(t, fix, guestShutdownKeyName) + + harness.Phase(t, "VPC + subnet + security group") + provisionNetwork(t, fix, netNames{ + sg: guestShutdownSGName, + sgDesc: "Guest shutdown budget E2E", + vpcCIDR: guestShutdownVPCCIDR, + subnetCIDR: guestShutdownSubnetCIDR, + }) + + t.Run("SlowGuestIsWaitedForAndKeepsWhatItWrote", func(t *testing.T) { + id, pub := launchProbeGuest(t, fix, slowShutdownUserData, "slow") + + before := time.Now() + bootID := rebootAndWaitForNewBootID(t, fix, id, pub) + elapsed := time.Since(before) + harness.Detail(t, "reboot_elapsed_secs", int(elapsed.Seconds())) + harness.Detail(t, "post_reboot_boot_id", bootID) + + // The file is the assertion. Every line was fsynced during shutdown, so + // its length is how much of that shutdown the guest was allowed to run. + lines := countProbeLines(t, fix, pub) + harness.Detail(t, "shutdown_probe_lines", lines) + assert.GreaterOrEqualf(t, lines, slowShutdownMinLines, + "the guest wrote %d fsynced lines during shutdown, wanted at least %d — "+ + "a guest reset instead of asked never runs its shutdown at all", + lines, slowShutdownMinLines) + + // Assert the test tested something: a shutdown that finished in a + // second has not exercised a slow one, whatever the line count says. + assert.GreaterOrEqualf(t, elapsed, time.Duration(slowShutdownMinLines)*time.Second, + "the whole reboot took %s, which is less than the shutdown hook alone should have taken — "+ + "the slow guest was not slow and this run proves nothing", elapsed) + + // The other half of the contract: a guest that went down on its own + // must not also have been reported as one that would not. + journal := daemonJournalFor(t, fix, id) + assert.NotContainsf(t, journal, hardResetLogLine, + "the daemon logged the hard-reset fallback for %s, but this guest shut down inside its budget", id) + }) + + t.Run("WedgedGuestIsResetOnceItsBudgetExpires", func(t *testing.T) { + id, pub := launchProbeGuest(t, fix, wedgedUserData, "wedged") + + before := time.Now() + bootID := rebootAndWaitForNewBootID(t, fix, id, pub) + elapsed := time.Since(before) + harness.Detail(t, "reboot_elapsed_secs", int(elapsed.Seconds())) + harness.Detail(t, "post_reboot_boot_id", bootID) + + // A guest that will not go quietly is still rebooted — that is the AWS + // contract, and it is what stops one wedged guest becoming an outage. + // Reaching a new boot ID above is that assertion. + assert.GreaterOrEqualf(t, elapsed, guestPowerdownBudget, + "the reboot took %s, less than the %s budget, so the guest was reset without being asked first — "+ + "the whole point is that asking comes first", elapsed, guestPowerdownBudget) + + journal := daemonJournalFor(t, fix, id) + assert.Containsf(t, journal, hardResetLogLine, + "the daemon reset %s without logging why; a guest that never honours ACPI has to be visible, "+ + "not silently hard-reset forever", id) + }) +} + +// launchProbeGuest boots one guest on the given user-data and waits until its +// setup has reported itself done, so a test never measures a shutdown against a +// guest that had not finished being configured. +func launchProbeGuest(t *testing.T, fix *fixture, userData, label string) (id, pub string) { + t.Helper() + harness.Step(t, "launching the %s guest", label) + + // e2e:allow-create — the guest is the subject: each variant carries its own + // shutdown behaviour in user-data, so a memoised fixture guest is the wrong + // shape and sharing one between the variants would erase the difference. + out, err := fix.aws.EC2.RunInstances(&ec2.RunInstancesInput{ //nolint:staticcheck // e2e:allow-create + ImageId: aws.String(fix.amiID), + InstanceType: aws.String(fix.instanceType), + KeyName: aws.String(fix.keyPairName), + SubnetId: aws.String(fix.subnetID), + SecurityGroupIds: []*string{aws.String(fix.sgID)}, + UserData: aws.String(base64.StdEncoding.EncodeToString([]byte(userData))), + MinCount: aws.Int64(1), + MaxCount: aws.Int64(1), + }) + require.NoErrorf(t, err, "run-instances %s", label) + require.NotEmpty(t, out.Instances) + id = aws.StringValue(out.Instances[0].InstanceId) + fix.appInstanceIDs = append(fix.appInstanceIDs, id) + harness.Detail(t, label+"_instance", id) + + harness.WaitForInstanceRunning(t, fix.aws, id, fix.timeouts.instanceRunning) + pub = describePublicIP(t, fix.aws, id) + require.NotEmptyf(t, pub, "%s has no PublicIpAddress", id) + + // The sentinel is written at the end of user-data, so waiting for it waits + // for the shutdown hook to be installed rather than for SSH alone. + harness.Step(t, "waiting for the %s guest's setup to finish", label) + deadline := time.Now().Add(5 * time.Minute) + for { + out, err := runInGuest(fix, pub, "test -e /run/guest-shutdown-ready && echo ready") + if err == nil && strings.Contains(out, "ready") { + return id, pub + } + if time.Now().After(deadline) { + t.Fatalf("%s guest %s never finished its user-data setup (last output %q, err: %v)", + label, id, strings.TrimSpace(out), err) + } + time.Sleep(5 * time.Second) + } +} + +// rebootAndWaitForNewBootID reboots the guest and blocks until it answers with a +// boot ID other than the one it held, which is the only positive proof that the +// guest actually rebooted rather than never having gone down. +func rebootAndWaitForNewBootID(t *testing.T, fix *fixture, id, pub string) string { + t.Helper() + + previous := readBootID(t, fix, pub) + require.NotEmptyf(t, previous, "%s returned an empty boot ID before the reboot", id) + harness.Detail(t, "pre_reboot_boot_id", previous) + + harness.Step(t, "reboot-instances %s", id) + _, err := fix.aws.EC2.RebootInstances(&ec2.RebootInstancesInput{ + InstanceIds: []*string{aws.String(id)}, + }) + require.NoErrorf(t, err, "reboot-instances %s", id) + + deadline := time.Now().Add(guestRebootBudget) + var lastID string + var lastErr error + for { + out, err := runInGuest(fix, pub, "cat /proc/sys/kernel/random/boot_id") + lastErr = err + if err == nil { + lastID = lastNonEmptyLine(out) + if lastID != "" && lastID != previous { + return lastID + } + } + if time.Now().After(deadline) { + // "Never came back" and "came back on the same boot" are different + // faults, and one message for both would name neither. + if lastID == previous { + t.Fatalf("%s still holds boot ID %s after %s, so the reboot never reached the guest kernel", + id, previous, guestRebootBudget) + } + t.Fatalf("%s never answered SSH with a boot ID within %s (last error: %v)", + id, guestRebootBudget, lastErr) + } + time.Sleep(3 * time.Second) + } +} + +func readBootID(t *testing.T, fix *fixture, pub string) string { + t.Helper() + out, err := runInGuest(fix, pub, "cat /proc/sys/kernel/random/boot_id") + require.NoError(t, err, "read boot ID from the guest") + return lastNonEmptyLine(out) +} + +// countProbeLines reads how many fsynced lines the shutdown hook managed to +// write. A missing file means none of it ran, which is the same finding as an +// empty one and is reported as zero rather than as an error. +func countProbeLines(t *testing.T, fix *fixture, pub string) int { + t.Helper() + out, err := runInGuest(fix, pub, "wc -l < "+slowShutdownProbeFile+" 2>/dev/null || echo 0") + require.NoError(t, err, "read the shutdown probe file") + n, err := strconv.Atoi(lastNonEmptyLine(out)) + require.NoErrorf(t, err, "parse the shutdown probe line count from %q", out) + return n +} + +// daemonJournalFor returns the daemon's log lines mentioning one instance. The +// suite runs on the CI runner, so this hops through the node. +func daemonJournalFor(t *testing.T, fix *fixture, id string) string { + t.Helper() + ctx, cancel := context.WithTimeout(context.Background(), 60*time.Second) + defer cancel() + + cmd := "sudo journalctl -u spinifex-daemon --since '-15 min' --no-pager 2>/dev/null | grep -F " + id + " || true" + out, err := fix.ssh.Run(ctx, fix.env.WANHost, cmd) + require.NoErrorf(t, err, "read the daemon journal for %s", id) + harness.DumpFile(t, fix.artifacts, fmt.Sprintf("journal-%s.txt", id), out) + return string(out) +} + +// runInGuest runs one command inside a guest, hopping through the node: the +// runner has no route to a guest's address and the node does. +func runInGuest(fix *fixture, pub, command string) (string, error) { + keyData, err := os.ReadFile(fix.privateKeyPath) + if err != nil { + return "", fmt.Errorf("read guest key: %w", err) + } + remoteKey := "/tmp/guest-shutdown-e2e.pem" + outer := fmt.Sprintf(`set -e +umask 077 && printf '%%s' '%s' | base64 -d > %s && chmod 600 %s +ssh -i %s -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o LogLevel=ERROR \ + -o ConnectTimeout=8 -o BatchMode=yes ubuntu@%s bash -s <<'EOFCMD' +%s +EOFCMD +`, base64.StdEncoding.EncodeToString(keyData), remoteKey, remoteKey, remoteKey, pub, command) + + ctx, cancel := context.WithTimeout(context.Background(), 90*time.Second) + defer cancel() + out, err := fix.ssh.Run(ctx, fix.env.WANHost, outer) + return string(out), err +} + +// lastNonEmptyLine takes the final line with content, so an SSH banner or a +// warning ahead of the answer does not become the answer. +func lastNonEmptyLine(s string) string { + lines := strings.Split(s, "\n") + for i := len(lines) - 1; i >= 0; i-- { + if trimmed := strings.TrimSpace(lines[i]); trimmed != "" { + return trimmed + } + } + return "" +} diff --git a/tests/e2e/reboot/reboot_test.go b/tests/e2e/reboot/reboot_test.go index 09c29210d..e75a9baeb 100644 --- a/tests/e2e/reboot/reboot_test.go +++ b/tests/e2e/reboot/reboot_test.go @@ -94,6 +94,7 @@ type fixture struct { appInstanceIDs []string preIPs map[string]string + keyPairName string // the pair this fixture created, and the one cleanup removes privateKeyPath string // local PEM written from CreateKeyPair KeyMaterial tgArn string @@ -263,21 +264,52 @@ func phase0Prereqs(t *testing.T, fix *fixture) { fix.amiID = discoverAMI(t, fix.aws) harness.Detail(t, "ami", fix.amiID) - // Capture KeyMaterial so post-reboot diagnostics can SSH into guest VMs. - _, _ = fix.aws.EC2.DeleteKeyPair(&ec2.DeleteKeyPairInput{KeyName: aws.String(keyName)}) - kpOut, err := fix.aws.EC2.CreateKeyPair(&ec2.CreateKeyPairInput{KeyName: aws.String(keyName)}) - require.NoErrorf(t, err, "create-key-pair %s", keyName) + provisionKeyPair(t, fix, keyName) +} + +// provisionKeyPair creates a key pair and keeps its material, so a test can SSH +// into the guests it launches. Recreated rather than reused: the material is +// returned once, at creation, and a pair left behind by an earlier run cannot +// be read back. +func provisionKeyPair(t *testing.T, fix *fixture, name string) { + t.Helper() + _, _ = fix.aws.EC2.DeleteKeyPair(&ec2.DeleteKeyPairInput{KeyName: aws.String(name)}) + kpOut, err := fix.aws.EC2.CreateKeyPair(&ec2.CreateKeyPairInput{KeyName: aws.String(name)}) + require.NoErrorf(t, err, "create-key-pair %s", name) material := aws.StringValue(kpOut.KeyMaterial) - require.NotEmptyf(t, material, "create-key-pair %s returned no KeyMaterial", keyName) - fix.privateKeyPath = filepath.Join(fix.artifacts, keyName+".pem") + require.NotEmptyf(t, material, "create-key-pair %s returned no KeyMaterial", name) + fix.keyPairName = name + fix.privateKeyPath = filepath.Join(fix.artifacts, name+".pem") require.NoError(t, os.WriteFile(fix.privateKeyPath, []byte(material), 0o600), "write private key") - harness.Detail(t, "key_pair", keyName) + harness.Detail(t, "key_pair", name) } func phase1Network(t *testing.T, fix *fixture) { t.Helper() + provisionNetwork(t, fix, netNames{ + sg: sgName, + sgDesc: "Reboot E2E shared SG (ALB + app instances)", + vpcCIDR: vpcCIDR, + subnetCIDR: subnetCIDR, + }) +} - vpcOut, err := fix.aws.EC2.CreateVpc(&ec2.CreateVpcInput{CidrBlock: aws.String(vpcCIDR)}) +// netNames is the set of names one test's network is built under. Each test in +// this package brings its own, so tearing one down cannot take the other's VPC. +type netNames struct { + sg string + sgDesc string + vpcCIDR string + subnetCIDR string +} + +// provisionNetwork builds a VPC, a public subnet and a security group admitting +// tcp/80 and tcp/22 from anywhere — 22 so the test and its diagnostics can SSH +// into the guests it launches. +func provisionNetwork(t *testing.T, fix *fixture, names netNames) { + t.Helper() + + vpcOut, err := fix.aws.EC2.CreateVpc(&ec2.CreateVpcInput{CidrBlock: aws.String(names.vpcCIDR)}) require.NoError(t, err, "create-vpc") fix.vpcID = aws.StringValue(vpcOut.Vpc.VpcId) harness.Detail(t, "vpc", fix.vpcID) @@ -294,7 +326,7 @@ func phase1Network(t *testing.T, fix *fixture) { subnetOut, err := fix.aws.EC2.CreateSubnet(&ec2.CreateSubnetInput{ VpcId: aws.String(fix.vpcID), - CidrBlock: aws.String(subnetCIDR), + CidrBlock: aws.String(names.subnetCIDR), }) require.NoError(t, err, "create-subnet") fix.subnetID = aws.StringValue(subnetOut.Subnet.SubnetId) @@ -305,8 +337,8 @@ func phase1Network(t *testing.T, fix *fixture) { harness.Detail(t, "subnet", fix.subnetID) sgOut, err := fix.aws.EC2.CreateSecurityGroup(&ec2.CreateSecurityGroupInput{ - GroupName: aws.String(sgName), - Description: aws.String("Reboot E2E shared SG (ALB + app instances)"), + GroupName: aws.String(names.sg), + Description: aws.String(names.sgDesc), VpcId: aws.String(fix.vpcID), }) require.NoError(t, err, "create-security-group") @@ -1406,7 +1438,9 @@ func cleanup(t *testing.T, fix *fixture) { harness.WaitForInstanceTerminated(t, fix.aws, fix.appInstanceIDs, 60*time.Second) } - _, _ = fix.aws.EC2.DeleteKeyPair(&ec2.DeleteKeyPairInput{KeyName: aws.String(keyName)}) + if fix.keyPairName != "" { + _, _ = fix.aws.EC2.DeleteKeyPair(&ec2.DeleteKeyPairInput{KeyName: aws.String(fix.keyPairName)}) + } // SG must come after instances + ALB ENIs are gone. if fix.sgID != "" { diff --git a/tests/e2e/single/guestchurn_test.go b/tests/e2e/single/guestchurn_test.go index d64efb8c3..39b57199b 100644 --- a/tests/e2e/single/guestchurn_test.go +++ b/tests/e2e/single/guestchurn_test.go @@ -531,6 +531,14 @@ func runGuestChurnRound(t *testing.T, fix *Fixture, instanceID, origType, keyPat host, port := harness.InstancePublicSSHHost(t, inst) waitForSSHReady(t, host, port, keyPath) + // The boot ID is what proves a reboot happened. Uptime cannot on its + // own: a reboot is asynchronous, so the guest answering shortly after + // the call may still be the one that has not shut down yet. + preBootID := strings.TrimSpace(runSSH(t, + harness.SSHTarget{User: "ubuntu", Host: host, Port: port, KeyPath: keyPath}, + "cat /proc/sys/kernel/random/boot_id")) + require.NotEmpty(t, preBootID, "guest returned an empty boot ID before the reboot") + // Capture pre-reboot private IP for the post-reboot identity check. preDesc, err := fix.AWS.EC2.DescribeInstances(&ec2.DescribeInstancesInput{ InstanceIds: []*string{aws.String(instanceID)}, @@ -573,6 +581,10 @@ func runGuestChurnRound(t *testing.T, fix *Fixture, instanceID, origType, keyPat waitForSSHReady(t, host, port, keyPath) tgt := harness.SSHTarget{User: "ubuntu", Host: host, Port: port, KeyPath: keyPath} + waitForNewBootID(t, tgt, preBootID) + + // Now that the guest is known to be on a new boot, uptime is a second + // reading of the same fact rather than a guess at it. harness.Step(t, "ssh uptime") uptimeOut := strings.TrimSpace(runSSH(t, tgt, "cat /proc/uptime | cut -d. -f1")) uptimeSecs, err := strconv.ParseInt(uptimeOut, 10, 64) @@ -591,6 +603,44 @@ func runGuestChurnRound(t *testing.T, fix *Fixture, instanceID, origType, keyPat verifySentinel(t, "Reboot") } +// rebootBootIDTimeout covers a guest asked to shut down cleanly, the reset it +// gets if it will not, and the boot after either. +const rebootBootIDTimeout = 3 * time.Minute + +// waitForNewBootID blocks until the guest answers SSH holding a boot ID other +// than the one it had. "Reachable" and "rebooted" are different facts while a +// reboot is in flight, and only the second one is worth asserting on. +func waitForNewBootID(t *testing.T, tgt harness.SSHTarget, previous string) string { + t.Helper() + harness.Step(t, "waiting for the guest to come back on a new boot ID") + deadline := time.Now().Add(rebootBootIDTimeout) + var lastID string + var lastErr error + for { + out, err := runSSHQuiet(tgt, "cat /proc/sys/kernel/random/boot_id") + lastErr = err + if err == nil { + lastID = strings.TrimSpace(out) + if lastID != "" && lastID != previous { + harness.Detail(t, "post_reboot_boot_id", lastID) + return lastID + } + } + if time.Now().After(deadline) { + // "Never answered" and "answered holding the old boot ID" are + // different faults — a guest that did not come back versus a reset + // that never reached it — and one message for both names neither. + if lastID == previous { + t.Fatalf("guest still holds boot ID %s after %s, so it never rebooted", + previous, rebootBootIDTimeout) + } + t.Fatalf("guest never answered SSH with a boot ID within %s (last error: %v)", + rebootBootIDTimeout, lastErr) + } + time.Sleep(2 * time.Second) + } +} + // describeSingletonInstance returns the current *ec2.Instance for // instanceID. Any perturbation of the singleton can change its public hostfwd // endpoint (type change, reboot, stop/start), so callers re-describe rather diff --git a/tests/e2e/single/rebootliveness_test.go b/tests/e2e/single/rebootliveness_test.go index d550ddf30..13797b277 100644 --- a/tests/e2e/single/rebootliveness_test.go +++ b/tests/e2e/single/rebootliveness_test.go @@ -54,19 +54,39 @@ func runEarlyRebootLiveness(t *testing.T, fix *Fixture) { } deadline := time.Now().Add(earlyRebootRecoveryTimeout) + // "SSH never answered" and "SSH answered with the boot ID it had before" + // are different faults — a guest that never came back versus a reset that + // never reached it — and one message for both names neither. + var ( + reachedOnce bool + lastBootID string + lastSSHErr error + ) for { ctx, cancel := context.WithTimeout(t.Context(), 5*time.Second) out, sshErr := harness.RunGuestSSH(ctx, tgt, "cat /proc/sys/kernel/random/boot_id") cancel() + lastSSHErr = sshErr if sshErr == nil { + reachedOnce = true newBootID := strings.TrimSpace(string(out)) + lastBootID = newBootID if newBootID != "" && newBootID != bootID { harness.Detail(t, "reboot_outcome", "resumed", "boot_id", newBootID) return } } if time.Now().After(deadline) { - t.Fatalf("reboot API succeeded but guest boot ID did not change within %s", earlyRebootRecoveryTimeout) + harness.DumpInstanceConsole(t, fix.AWS, instanceID, + fix.ArtifactDir(t), "early-reboot-console.log") + if !reachedOnce { + t.Fatalf("reboot API succeeded but the guest never answered SSH again within %s "+ + "(boot ID before the reboot %s, last SSH error: %v)", + earlyRebootRecoveryTimeout, bootID, lastSSHErr) + } + t.Fatalf("reboot API succeeded but the guest answered SSH still holding boot ID %s after %s "+ + "(so the reset never reached the guest kernel; last read %q)", + bootID, earlyRebootRecoveryTimeout, lastBootID) } time.Sleep(2 * time.Second) }