diff --git a/build/systemd/spinifex-shutdown.service b/build/systemd/spinifex-shutdown.service index 7099be5aa..b78f28a50 100644 --- a/build/systemd/spinifex-shutdown.service +++ b/build/systemd/spinifex-shutdown.service @@ -11,11 +11,11 @@ RemainAfterExit=yes ExecStart=/bin/true # ExecStop fires on ANY target stop, including the stop half of `systemctl # restart spinifex.target` (a rolling deploy) -- PartOf propagates regardless -# of whether the host is actually going down. --only-if-host-stopping drains -# only when systemd itself is unwinding into shutdown.target; a plain restart -# or `systemctl stop spinifex.target` falls through so QEMU/nbdkit survive -# (KillMode=process) and the daemon reconnects to them on the way back up. -ExecStop=/usr/local/bin/spx admin node drain --local --timeout=120s --only-if-host-stopping +# of whether the host is actually going down. --unless-restarting drains on a +# real shutdown/reboot and on a plain `systemctl stop spinifex.target`; it +# skips only when a restart of the stack is already queued, so QEMU/nbdkit +# survive (KillMode=process) and the daemon reconnects on the way back up. +ExecStop=/usr/local/bin/spx admin node drain --local --timeout=120s --unless-restarting TimeoutStopSec=180 [Install] diff --git a/build/systemd/spinifex-viperblock.service b/build/systemd/spinifex-viperblock.service index 71f83c62f..3e9c424c9 100644 --- a/build/systemd/spinifex-viperblock.service +++ b/build/systemd/spinifex-viperblock.service @@ -23,8 +23,10 @@ MemoryMax=25% # way guest QEMU survives a daemon restart. Tearing one out mid-write corrupts # that guest's filesystem; idle nbdkit is reaped explicitly on shutdown. KillMode=process -# Bounds this process's own WAL drain, which the plugin caps at 20s. -TimeoutStopSec=30 +# One worst-case nbdkit reap: killProcessGracePeriod (120s, utils.KillProcess) +# plus its own shutdownDrainTimeout (20s, viperblock/nbd) and headroom — must +# strictly exceed 120s now shutdownVolumes reaps concurrently, not serially. +TimeoutStopSec=150 EnvironmentFile=/etc/spinifex/systemd.env Environment=SPINIFEX_CONFIG_PATH=/etc/spinifex/spinifex.toml Environment=SPINIFEX_BASE_DIR=/var/lib/spinifex/viperblock/ diff --git a/cmd/spinifex/cmd/admin.go b/cmd/spinifex/cmd/admin.go index 06544fd8e..951661402 100644 --- a/cmd/spinifex/cmd/admin.go +++ b/cmd/spinifex/cmd/admin.go @@ -118,8 +118,9 @@ var nodeDrainCmd = &cobra.Command{ its guests via QMP and unmount their volumes (flushing the viperblock WAL) while every service is still running. STORAGE/PERSIST/INFRA are left to systemd's ordered unit teardown. This is what spinifex-shutdown.service's ExecStop runs, -with --only-if-host-stopping so it only drains on a genuine host -shutdown/reboot -- not on a plain "systemctl restart/stop spinifex.target". +with --unless-restarting so it drains on a genuine host shutdown/reboot and on +a plain "systemctl stop spinifex.target", but skips the drain when a restart +of the stack (e.g. "systemctl restart spinifex.target") is already queued. Run by hand without that flag, it always drains unconditionally.`, Run: runNodeDrainLocal, } @@ -283,7 +284,9 @@ func init() { nodeCmd.AddCommand(nodeDrainCmd) nodeDrainCmd.Flags().Bool("local", false, "Drain the local node only (required)") nodeDrainCmd.Flags().Duration("timeout", 120*time.Second, "Maximum time to wait per phase") - nodeDrainCmd.Flags().Bool("only-if-host-stopping", false, "Skip the drain unless systemd is unwinding into shutdown.target (real reboot/poweroff); unset, always drains") + nodeDrainCmd.Flags().Bool("unless-restarting", false, "Drain on a real host shutdown or a plain target stop; skip only when a restart of the stack is already queued. Unset, always drains") + nodeDrainCmd.Flags().Bool("only-if-host-stopping", false, "Deprecated: use --unless-restarting") + _ = nodeDrainCmd.Flags().MarkDeprecated("only-if-host-stopping", "use --unless-restarting instead") nodeCmd.AddCommand(nodeJSProbeCmd) nodeJSProbeCmd.Flags().Duration("timeout", 10*time.Second, "Maximum time to wait for the canary round-trip") diff --git a/cmd/spinifex/cmd/cluster.go b/cmd/spinifex/cmd/cluster.go index 8eeb93d19..47f4b56ef 100644 --- a/cmd/spinifex/cmd/cluster.go +++ b/cmd/spinifex/cmd/cluster.go @@ -3,13 +3,16 @@ package cmd import ( "encoding/json" "fmt" + "log/slog" "os" "os/exec" + "sort" "strings" "time" "github.com/mulgadc/spinifex/spinifex/daemon" "github.com/mulgadc/spinifex/spinifex/network/external/dhcp" + "github.com/mulgadc/spinifex/spinifex/types" "github.com/nats-io/nats.go" "github.com/spf13/cobra" ) @@ -50,6 +53,80 @@ func hostIsStopping() (bool, error) { return out == "stopping", nil } +// systemctlListJobs is overridable in tests so stackIsRestarting does not +// need a real systemd. Output is one line per pending job in the form +// "JOB UNIT TYPE STATE" (systemctl list-jobs --no-legend --no-pager). +var systemctlListJobs = func() (string, error) { + out, err := exec.Command("systemctl", "list-jobs", "--no-legend", "--no-pager").Output() + return string(out), err +} + +// stackIsRestarting reports whether a pending systemd job shows the spinifex +// stack is already coming back: a queued START job for spinifex.target +// (its stop leg resolves instantly, so only the start job stays pending +// during `systemctl restart`), or a queued RESTART job for +// spinifex-shutdown.service itself (PartOf propagates target-to-member +// only, so a direct unit restart looks different). No pending jobs is a +// clean "not restarting"; output with no recognizable job line is an error. +func stackIsRestarting() (bool, error) { + out, err := systemctlListJobs() + if err != nil { + return false, fmt.Errorf("systemctl list-jobs: %w", err) + } + + trimmed := strings.TrimSpace(out) + if trimmed == "" { + return false, nil + } + + sawParseableLine := false + for line := range strings.SplitSeq(trimmed, "\n") { + fields := strings.Fields(line) + if len(fields) < 4 { + continue + } + sawParseableLine = true + unit, jobType := fields[1], fields[2] + if unit == "spinifex.target" && jobType == "start" { + return true, nil + } + if unit == "spinifex-shutdown.service" && jobType == "restart" { + return true, nil + } + } + if !sawParseableLine { + return false, fmt.Errorf("systemctl list-jobs: no parseable job lines in output %q", trimmed) + } + return false, nil +} + +// shouldDrainOnStop decides whether a spinifex.target stop should drain +// local guests. A real host shutdown always drains. Otherwise a plain +// target stop drains too, since nothing then guarantees the stack comes +// back; only a systemd job proving a restart is already queued skips it. +// Any step systemctl cannot answer fails toward draining: a spurious drain +// only costs a graceful stop and relaunch, a skipped one costs a guest's +// data path. +func shouldDrainOnStop() (drain bool, reason string) { + stopping, err := hostIsStopping() + if err != nil { + return true, fmt.Sprintf("could not determine host shutdown state, draining: %v", err) + } + if stopping { + return true, "host is shutting down (reboot/poweroff)" + } + + restarting, err := stackIsRestarting() + if err != nil { + return true, fmt.Sprintf("could not determine whether the spinifex stack is restarting, draining: %v", err) + } + if restarting { + return false, "a restart of the spinifex stack is already queued" + } + + return true, "plain target stop with no restart queued" +} + // runClusterShutdown orchestrates a phased, coordinated shutdown of the cluster. func runClusterShutdown(cmd *cobra.Command, args []string) { force, _ := cmd.Flags().GetBool("force") @@ -206,22 +283,26 @@ func runClusterShutdown(cmd *cobra.Command, args []string) { func runNodeDrainLocal(cmd *cobra.Command, args []string) { local, _ := cmd.Flags().GetBool("local") timeout, _ := cmd.Flags().GetDuration("timeout") - onlyIfHostStopping, _ := cmd.Flags().GetBool("only-if-host-stopping") + unlessRestarting, _ := cmd.Flags().GetBool("unless-restarting") + // --only-if-host-stopping is a deprecated alias for --unless-restarting; + // OR it in so a mixed-version node/unit-file pairing during a partial + // upgrade still gets a gate rather than silently always draining. + deprecatedOnlyIfHostStopping, _ := cmd.Flags().GetBool("only-if-host-stopping") + unlessRestarting = unlessRestarting || deprecatedOnlyIfHostStopping if !local { fmt.Fprintln(os.Stderr, "Error: node drain currently supports only --local") os.Exit(1) } // Unset (an operator running this by hand), the command drains - // unconditionally. Set, it skips anything short of a real host shutdown, - // since PartOf=spinifex.target fires ExecStop on restarts too. - if onlyIfHostStopping { - stopping, err := hostIsStopping() - if err != nil { - fmt.Fprintf(os.Stderr, "Warning: could not determine host shutdown state: %v\n", err) - } - if !stopping { - fmt.Println("Host is not shutting down; skipping guest drain.") + // unconditionally. Set, it drains on a real host shutdown and on a plain + // target stop, and skips only when a restart of the stack is already + // queued. + if unlessRestarting { + drain, reason := shouldDrainOnStop() + if !drain { + fmt.Printf("Skipping guest drain: %s. Guests are left running for the stack to reattach to.\n", reason) + warnIfGuestsLeftRunning() return } } @@ -247,7 +328,12 @@ func runNodeDrainLocal(cmd *cobra.Command, args []string) { ack, err := collectLocalShutdownACK(nc, topic, reqData, node, timeout) if err != nil { - fmt.Fprintf(os.Stderr, "[%s] %v\n", strings.ToUpper(phase), err) + // Non-zero marks spinifex-shutdown.service failed (visible via + // `systemctl --failed`) without blocking the target's teardown; + // exiting 0 would hide guests left running as storage vanishes. + slog.Error("drain phase failed: no ACK from local daemon before timeout; guests may be left running while storage is about to be torn down", + "phase", phase, "node", node, "timeout", timeout, "error", err) + reportGuestsLeftRunning(true, fmt.Sprintf("[%s] drain failed: guests left running with storage about to be torn down", strings.ToUpper(phase))) os.Exit(1) } if ack.Error != "" { @@ -264,18 +350,131 @@ func runNodeDrainLocal(cmd *cobra.Command, args []string) { fmt.Printf("Local node %q drained; systemd may now stop storage services\n", node) } -// collectLocalShutdownACK publishes a shutdown-phase request and returns the ACK -// from the local node, ignoring ACKs from any other node. Returns an error if -// the local node does not respond within timeout. -func collectLocalShutdownACK(nc *nats.Conn, topic string, reqData []byte, node string, timeout time.Duration) (daemon.ShutdownACK, error) { - acks, err := collectShutdownACKs(nc, topic, reqData, 1, node, timeout) +// guestEnumerationTimeout bounds how long a skipped drain waits on the +// spinifex.node.vms fan-out before giving up. It is intentionally short and +// independent of the drain --timeout: this only runs when the drain itself +// is being skipped, so it must never itself stall the stop. A var (like +// systemIsSystemRunning) so tests do not have to wait out a real timeout. +var guestEnumerationTimeout = 3 * time.Second + +// vmStatusRunning mirrors vm.StateRunning's wire value. Not imported directly +// to avoid pulling the vm package into the CLI: VMInfo.Status crosses NATS as +// a plain string. +const vmStatusRunning = "running" + +// reportGuestsLeftRunning names, at the given severity, every guest still +// running on this node, reusing the spinifex.node.vms fan-out `spx get vms` +// already relies on. Enumeration failures always warn, never escalate. +func reportGuestsLeftRunning(severe bool, msg string) { + cfg, nc, err := loadConfigAndConnectFn() if err != nil { - return daemon.ShutdownACK{}, err + slog.Warn("could not connect to check for guests left running", "error", err) + return } - if len(acks) == 0 { - return daemon.ShutdownACK{}, fmt.Errorf("timeout waiting for local node %q ACK", node) + defer nc.Close() + node := cfg.Node + + responses, err := collectResponses(nc, "spinifex.node.vms", guestEnumerationTimeout) + if err != nil { + slog.Warn("could not enumerate local guests", "node", node, "error", err) + return } - return acks[0], nil + + var running []string + for _, data := range responses { + var resp types.NodeVMsResponse + if err := json.Unmarshal(data, &resp); err != nil { + continue + } + if resp.Node != node { + continue + } + for _, v := range resp.VMs { + if v.Status == vmStatusRunning { + running = append(running, v.InstanceID) + } + } + } + + if len(running) == 0 { + return + } + sort.Strings(running) + if severe { + slog.Error(msg, "node", node, "instances", running) + } else { + slog.Warn(msg, "node", node, "instances", running) + } +} + +// warnIfGuestsLeftRunning reports, at WARN level, every guest still running +// on this node when the drain gate has just decided to skip a stop because a +// restart is already queued. +func warnIfGuestsLeftRunning() { + reportGuestsLeftRunning(false, "skipped drain leaves guests running unsupervised; they will lose their data path if the spinifex stack does not come back") +} + +// localShutdownACKRetryBaseDelay/MaxDelay set the backoff between GATE/DRAIN +// ACK attempts: NATS bounces a request instantly when nothing is subscribed +// yet, so a single miss right after a daemon restart is not a real failure. +var ( + localShutdownACKRetryBaseDelay = 250 * time.Millisecond + localShutdownACKRetryMaxDelay = 2 * time.Second +) + +// collectShutdownACKsFn indirects collectShutdownACKs so tests can simulate a +// slow-to-resubscribe daemon without a real NATS round trip. +var collectShutdownACKsFn = collectShutdownACKs + +// collectLocalShutdownACK publishes a shutdown-phase request and returns the +// ACK from the local node, retrying with backoff bounded by timeout as a +// whole. Returns an error once the budget is exhausted with no ACK. +func collectLocalShutdownACK(nc *nats.Conn, topic string, reqData []byte, node string, timeout time.Duration) (daemon.ShutdownACK, error) { + deadline := time.Now().Add(timeout) + delay := localShutdownACKRetryBaseDelay + attempts := 0 + loggedRetry := false + + for { + remaining := time.Until(deadline) + if remaining <= 0 { + break + } + attempts++ + + acks, err := collectShutdownACKsFn(nc, topic, reqData, 1, node, remaining) + if err != nil { + return daemon.ShutdownACK{}, fmt.Errorf("collecting ACK from local node %q: %w", node, err) + } + if len(acks) > 0 { + return acks[0], nil + } + + remaining = time.Until(deadline) + if remaining <= 0 { + break + } + // Log once, not per attempt: this runs in ExecStop, so its output + // lands in the journal on every single stop, and most stops recover + // within the first attempt or two. + if !loggedRetry { + slog.Warn("no ACK yet for local node, retrying (daemon may still be re-subscribing)", + "node", node, "topic", topic) + loggedRetry = true + } + + sleep := min(delay, remaining) + time.Sleep(sleep) + delay *= 2 + if delay > localShutdownACKRetryMaxDelay { + delay = localShutdownACKRetryMaxDelay + } + } + + if attempts == 0 { + return daemon.ShutdownACK{}, fmt.Errorf("no time budget to wait for local node %q ACK (timeout=%s)", node, timeout) + } + return daemon.ShutdownACK{}, fmt.Errorf("no ACK from local node %q after %d attempt(s) within %s", node, attempts, timeout) } // runClusterDrainDHCP asks every vpcd to DHCPRELEASE all external-pool leases diff --git a/cmd/spinifex/cmd/cluster_test.go b/cmd/spinifex/cmd/cluster_test.go index 72d55c050..1ea806afc 100644 --- a/cmd/spinifex/cmd/cluster_test.go +++ b/cmd/spinifex/cmd/cluster_test.go @@ -1,13 +1,18 @@ package cmd import ( + "bytes" "encoding/json" "errors" + "log/slog" "testing" "time" + "github.com/mulgadc/spinifex/spinifex/config" + "github.com/mulgadc/spinifex/spinifex/daemon" "github.com/mulgadc/spinifex/spinifex/network/external/dhcp" "github.com/mulgadc/spinifex/spinifex/testutil" + "github.com/mulgadc/spinifex/spinifex/types" "github.com/nats-io/nats.go" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -93,3 +98,351 @@ func TestHostIsStopping(t *testing.T) { }) } } + +// TestStackIsRestarting covers every systemctl list-jobs shape the +// stop-vs-restart gate must distinguish: a queued target restart, a direct +// restart of the shutdown unit itself (PartOf propagates target-to-member +// only, so that shows up differently), a plain stop with only stop jobs, no +// pending jobs at all, an unreachable systemctl, and output with no +// parseable job line. +func TestStackIsRestarting(t *testing.T) { + orig := systemctlListJobs + t.Cleanup(func() { systemctlListJobs = orig }) + + cases := []struct { + name string + out string + err error + wantRestarting bool + wantErr bool + }{ + { + name: "target restart queued", + out: "1655 spinifex-shutdown.service restart running\n" + + "1654 spinifex-other.service restart waiting\n" + + "1636 spinifex.target start waiting\n", + wantRestarting: true, + }, + { + name: "direct restart of shutdown unit", + out: "1617 spinifex-shutdown.service restart running\n", + wantRestarting: true, + }, + { + name: "plain stop, only stop jobs", + out: "1617 spinifex-shutdown.service stop running\n" + + "1616 spinifex-other.service stop waiting\n", + wantRestarting: false, + }, + { + name: "no pending jobs", + out: "", + wantRestarting: false, + }, + { + name: "whitespace-only output", + out: " \n\t\n", + wantRestarting: false, + }, + { + name: "systemctl unreachable", + out: "", + err: errors.New("exec: \"systemctl\": executable file not found in $PATH"), + wantErr: true, + }, + { + name: "unparseable output", + out: "totally broken\n", + wantErr: true, + }, + } + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + systemctlListJobs = func() (string, error) { return tc.out, tc.err } + restarting, err := stackIsRestarting() + assert.Equal(t, tc.wantRestarting, restarting) + if tc.wantErr { + assert.Error(t, err) + } else { + assert.NoError(t, err) + } + }) + } +} + +// TestShouldDrainOnStop covers the full stop-vs-restart decision: a real +// shutdown short-circuits the job-list check entirely, a plain stop and both +// restart shapes route correctly, and every "cannot determine" case fails +// toward draining. +func TestShouldDrainOnStop(t *testing.T) { + origState := systemIsSystemRunning + origJobs := systemctlListJobs + t.Cleanup(func() { + systemIsSystemRunning = origState + systemctlListJobs = origJobs + }) + + t.Run("real shutdown short-circuits list-jobs", func(t *testing.T) { + systemIsSystemRunning = func() (string, error) { return "stopping", errors.New("exit status 1") } + systemctlListJobs = func() (string, error) { + t.Fatal("stackIsRestarting must not run once hostIsStopping is true") + return "", nil + } + drain, reason := shouldDrainOnStop() + assert.True(t, drain) + assert.NotEmpty(t, reason) + }) + + cases := []struct { + name string + state string + stateErr error + jobs string + jobsErr error + wantDrain bool + }{ + { + name: "plain stop, no restart queued", + state: "running", + jobs: "1617 spinifex-shutdown.service stop running\n", + wantDrain: true, + }, + { + name: "target restart queued", + state: "running", + jobs: "1636 spinifex.target start waiting\n", + wantDrain: false, + }, + { + name: "direct restart of shutdown unit", + state: "running", + jobs: "1617 spinifex-shutdown.service restart running\n", + wantDrain: false, + }, + { + name: "unknown host state", + state: "banana", + wantDrain: true, + }, + { + name: "is-system-running unreachable", + state: "", + stateErr: errors.New("exec: \"systemctl\": executable file not found in $PATH"), + wantDrain: true, + }, + { + name: "list-jobs unreachable", + state: "running", + jobsErr: errors.New("exec: \"systemctl\": executable file not found in $PATH"), + wantDrain: true, + }, + } + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + systemIsSystemRunning = func() (string, error) { return tc.state, tc.stateErr } + systemctlListJobs = func() (string, error) { return tc.jobs, tc.jobsErr } + drain, reason := shouldDrainOnStop() + assert.Equal(t, tc.wantDrain, drain) + assert.NotEmpty(t, reason) + }) + } +} + +// TestNodeDrainCmdDeprecatedFlagAlias asserts --only-if-host-stopping still +// exists and works (a node running the new unit file against an old spx +// binary, or the reverse during a partial upgrade, must not break) but is +// marked deprecated in favour of --unless-restarting. +func TestNodeDrainCmdDeprecatedFlagAlias(t *testing.T) { + unlessRestarting := nodeDrainCmd.Flags().Lookup("unless-restarting") + require.NotNil(t, unlessRestarting) + assert.Empty(t, unlessRestarting.Deprecated) + + legacy := nodeDrainCmd.Flags().Lookup("only-if-host-stopping") + require.NotNil(t, legacy) + assert.NotEmpty(t, legacy.Deprecated) +} + +// captureSlog swaps the default slog logger for a text handler writing into +// a buffer for the duration of fn, then restores it. +func captureSlog(t *testing.T, fn func()) string { + t.Helper() + var buf bytes.Buffer + orig := slog.Default() + slog.SetDefault(slog.New(slog.NewTextHandler(&buf, nil))) + t.Cleanup(func() { slog.SetDefault(orig) }) + + fn() + + return buf.String() +} + +// TestWarnIfGuestsLeftRunningNamesRunningGuests asserts the skip branch +// enumerates via the same spinifex.node.vms fan-out spx get vms uses, warns +// at WARN level, and names only the running instance, not the stopped one. +func TestWarnIfGuestsLeftRunningNamesRunningGuests(t *testing.T) { + origTimeout := guestEnumerationTimeout + guestEnumerationTimeout = 200 * time.Millisecond + t.Cleanup(func() { guestEnumerationTimeout = origTimeout }) + + _, nc, _ := testutil.StartTestJetStream(t) + stubConnect(t, &config.ClusterConfig{Node: "node1"}, nc, nil) + + sub, err := nc.Subscribe("spinifex.node.vms", func(msg *nats.Msg) { + resp := types.NodeVMsResponse{ + Node: "node1", + VMs: []types.VMInfo{ + {InstanceID: "i-running", Status: vmStatusRunning}, + {InstanceID: "i-stopped", Status: "stopped"}, + }, + } + body, _ := json.Marshal(resp) + _ = msg.Respond(body) + }) + require.NoError(t, err) + t.Cleanup(func() { _ = sub.Unsubscribe() }) + + out := captureSlog(t, warnIfGuestsLeftRunning) + + assert.Contains(t, out, "i-running") + assert.NotContains(t, out, "i-stopped") + assert.Contains(t, out, "WARN") +} + +// TestWarnIfGuestsLeftRunningNoGuestsIsSilent asserts a node with no +// running guests produces no warning. +func TestWarnIfGuestsLeftRunningNoGuestsIsSilent(t *testing.T) { + origTimeout := guestEnumerationTimeout + guestEnumerationTimeout = 200 * time.Millisecond + t.Cleanup(func() { guestEnumerationTimeout = origTimeout }) + + _, nc, _ := testutil.StartTestJetStream(t) + stubConnect(t, &config.ClusterConfig{Node: "node1"}, nc, nil) + + sub, err := nc.Subscribe("spinifex.node.vms", func(msg *nats.Msg) { + resp := types.NodeVMsResponse{ + Node: "node1", + VMs: []types.VMInfo{{InstanceID: "i-stopped", Status: "stopped"}}, + } + body, _ := json.Marshal(resp) + _ = msg.Respond(body) + }) + require.NoError(t, err) + t.Cleanup(func() { _ = sub.Unsubscribe() }) + + out := captureSlog(t, warnIfGuestsLeftRunning) + assert.Empty(t, out) +} + +// TestWarnIfGuestsLeftRunningConnectFailureWarnsNotFails asserts that a +// failure to even connect for enumeration is itself warned about rather +// than treated as fatal — a skipped drain must never block the stop. +func TestWarnIfGuestsLeftRunningConnectFailureWarnsNotFails(t *testing.T) { + stubConnect(t, nil, nil, errors.New("connect refused")) + + out := captureSlog(t, warnIfGuestsLeftRunning) + assert.Contains(t, out, "could not connect") +} + +// stubCollectShutdownACKsFn swaps collectShutdownACKsFn for fn and restores +// the original on cleanup, so collectLocalShutdownACK's retry loop can be +// driven deterministically without a real NATS round trip. +func stubCollectShutdownACKsFn(t *testing.T, fn func(nc *nats.Conn, topic string, reqData []byte, nodeCount int, nodeFilter string, timeout time.Duration) ([]daemon.ShutdownACK, error)) { + t.Helper() + orig := collectShutdownACKsFn + t.Cleanup(func() { collectShutdownACKsFn = orig }) + collectShutdownACKsFn = fn +} + +// shrinkLocalShutdownACKBackoff overrides the GATE/DRAIN retry backoff to +// millisecond-scale values for the duration of the test so retry tests do +// not pay for the real 250ms-2s production backoff. +func shrinkLocalShutdownACKBackoff(t *testing.T) { + t.Helper() + origBase, origCap := localShutdownACKRetryBaseDelay, localShutdownACKRetryMaxDelay + localShutdownACKRetryBaseDelay = time.Millisecond + localShutdownACKRetryMaxDelay = 5 * time.Millisecond + t.Cleanup(func() { + localShutdownACKRetryBaseDelay = origBase + localShutdownACKRetryMaxDelay = origCap + }) +} + +// TestCollectLocalShutdownACKRetriesUntilACK covers the actual bug: the +// daemon may not have re-subscribed right after a restart, so the first +// attempt(s) get no ACK. The ACK on the third attempt must still succeed. +func TestCollectLocalShutdownACKRetriesUntilACK(t *testing.T) { + shrinkLocalShutdownACKBackoff(t) + + var calls int + stubCollectShutdownACKsFn(t, func(nc *nats.Conn, topic string, reqData []byte, nodeCount int, nodeFilter string, timeout time.Duration) ([]daemon.ShutdownACK, error) { + calls++ + if calls < 3 { + return nil, nil // daemon not re-subscribed yet: no ACK, no error + } + return []daemon.ShutdownACK{{Node: nodeFilter, Phase: "gate"}}, nil + }) + + ack, err := collectLocalShutdownACK(nil, "spinifex.cluster.shutdown.gate", []byte(`{}`), "node1", time.Second) + require.NoError(t, err) + assert.Equal(t, "node1", ack.Node) + assert.Equal(t, 3, calls) +} + +// TestCollectLocalShutdownACKExhaustedReturnsWithinBudget covers a daemon +// that never re-subscribes: the call must return promptly once the budget +// elapses, not hang, with a non-nil error so the failure path fires. +func TestCollectLocalShutdownACKExhaustedReturnsWithinBudget(t *testing.T) { + shrinkLocalShutdownACKBackoff(t) + + var calls int + stubCollectShutdownACKsFn(t, func(nc *nats.Conn, topic string, reqData []byte, nodeCount int, nodeFilter string, timeout time.Duration) ([]daemon.ShutdownACK, error) { + calls++ + return nil, nil // daemon never comes back within the budget + }) + + budget := 60 * time.Millisecond + start := time.Now() + ack, err := collectLocalShutdownACK(nil, "spinifex.cluster.shutdown.gate", []byte(`{}`), "node1", budget) + elapsed := time.Since(start) + + require.Error(t, err) + assert.Equal(t, daemon.ShutdownACK{}, ack) + assert.Contains(t, err.Error(), "node1") + assert.Greater(t, calls, 1, "must have retried, not failed on the first miss") + // The retry loop must not run appreciably past the configured budget. + assert.Less(t, elapsed, budget+150*time.Millisecond) +} + +// TestReportGuestsLeftRunningSevereLogsErrorAndNamesGuests covers the +// "drain failed" path sharing warnIfGuestsLeftRunning's enumeration: severe +// must log at ERROR, not WARN, and still name only the running instance. +func TestReportGuestsLeftRunningSevereLogsErrorAndNamesGuests(t *testing.T) { + origTimeout := guestEnumerationTimeout + guestEnumerationTimeout = 200 * time.Millisecond + t.Cleanup(func() { guestEnumerationTimeout = origTimeout }) + + _, nc, _ := testutil.StartTestJetStream(t) + stubConnect(t, &config.ClusterConfig{Node: "node1"}, nc, nil) + + sub, err := nc.Subscribe("spinifex.node.vms", func(msg *nats.Msg) { + resp := types.NodeVMsResponse{ + Node: "node1", + VMs: []types.VMInfo{ + {InstanceID: "i-abandoned", Status: vmStatusRunning}, + {InstanceID: "i-stopped", Status: "stopped"}, + }, + } + body, _ := json.Marshal(resp) + _ = msg.Respond(body) + }) + require.NoError(t, err) + t.Cleanup(func() { _ = sub.Unsubscribe() }) + + out := captureSlog(t, func() { + reportGuestsLeftRunning(true, "drain failed: guests left running with storage about to be torn down") + }) + + assert.Contains(t, out, "ERROR") + assert.Contains(t, out, "i-abandoned") + assert.NotContains(t, out, "i-stopped") +} diff --git a/docs/admin/host-lifecycle/README.md b/docs/admin/host-lifecycle/README.md new file mode 100644 index 000000000..62eb8e20f --- /dev/null +++ b/docs/admin/host-lifecycle/README.md @@ -0,0 +1,190 @@ +--- +title: "Host and Guest Lifecycle" +description: "The contract between Spinifex host service lifecycle events and running guest EC2 instances." +category: "Admin" +tags: + - lifecycle + - shutdown + - systemd + - guests +resources: + - title: "Spinifex Repository" + url: "https://github.com/mulgadc/spinifex" + - title: "Updating Spinifex" + url: "/docs/admin/update" +--- + +# Host and Guest Lifecycle + +> The contract between Spinifex host service lifecycle events and running guest EC2 instances. + +## Table of Contents + +- [Overview](#overview) +- [The Contract](#the-contract) +- [Older Releases: `systemctl stop spinifex.target`](#older-releases-systemctl-stop-spinifextarget) +- [Why Guests Outlive the Daemon](#why-guests-outlive-the-daemon) +- [Checking State](#checking-state) +- [Maintenance Runbooks](#maintenance-runbooks) + +--- + +## Overview + +`spinifex.target` groups every Spinifex service on a node: `spinifex-nats`, +`spinifex-predastore`, `spinifex-northstar`, `spinifex-viperblock`, +`spinifex-daemon`, `spinifex-awsgw`, `spinifex-vpcd`, `spinifex-ui`, +`spinifex-qmp-collector`, `spinifex-shutdown`, and the +`spinifex-nats-watchdog` timer. A guest EC2 instance is a `qemu-system-x86_64` +process launched by `spinifex-daemon` — it is not itself a systemd unit, and +it is deliberately allowed to keep running after the service that launched it +stops. + +The one idea to hold onto: guests outlive the daemon by design, so what +happens to a running guest depends entirely on which lifecycle event +triggered the stop, not on whether "Spinifex" as a whole looks like it is +still running. + +## The Contract + +| Event | What happens to running guests | Is storage available afterwards | What the operator must do | +|---|---|---|---| +| Host `reboot` / `poweroff` / `halt` | Drained gracefully — QMP `system_powerdown`, volumes unmounted, WAL flushed — by `spinifex-shutdown.service`'s `ExecStop` | n/a, the host is going down | Nothing extra | +| `systemctl restart spinifex.target` | Survive. Not rebooted. Reattached over QMP by `Manager.Restore` when the daemon comes back | Yes, within seconds | Nothing extra — this is the supported way to pick up a config change | +| `systemctl stop spinifex.target` | Drained the same as a host shutdown, because nothing guarantees the stack comes back on its own | No, not until the stack is started again | Nothing extra — but see [Older Releases](#older-releases-systemctl-stop-spinifextarget) if the node predates this behaviour | +| `systemctl restart spinifex-daemon.service` (daemon only) | Survive via `KillMode=process`. Reattached by `Manager.Restore` | Yes, throughout | Nothing extra | +| Daemon crash / SIGKILL | Survive | Yes, throughout — the crash only takes down the daemon | Nothing — crash recovery reattaches automatically on the next daemon start | +| Host power loss | Die with the host. No drain is possible | No, until the host boots and services start again | Expect `Manager.Restore` to run crash recovery on boot. Guest filesystems may need an fsck the same as after any unclean power cut | +| `spx admin cluster shutdown` | Stopped in the DRAIN phase, before storage (STORAGE, PERSIST) and control-plane (INFRA) services stop | n/a, the cluster is being taken down | Nothing extra — this is the correct command for taking a whole cluster down | + +## Older Releases: `systemctl stop spinifex.target` + +> [!WARNING] +> **Releases from v1.15.0 up to the release carrying this page do NOT drain on a plain `systemctl stop spinifex.target`.** Running guests get no signal at all — no QMP `system_powerdown`, no SIGTERM. Predastore and viperblock stop underneath the guest, leaving it with no data path, while QEMU keeps running. Drives are launched with `cache=none,werror=report,rerror=report`, so I/O errors are reported into the guest instead of pausing it — the guest keeps running and keeps believing it has a disk. Anything written after storage goes away is lost, and a guest filesystem that takes I/O errors on its journal can be left inconsistent. + +**Cause:** on those releases `spinifex-shutdown.service`'s `ExecStop` ran +`spx admin node drain --local --timeout=120s --only-if-host-stopping`, which +drains only when `systemctl is-system-running` reports the literal state +`stopping`. That is true for a real reboot/poweroff but not for a plain +`systemctl stop spinifex.target` — systemd reports `running` for both a plain +stop and the stop half of a restart, so the gate could not tell them apart. It +skipped the drain and logged `Host is not shutting down; skipping guest +drain.` The gate now also reads systemd's pending job list, which does +distinguish the two. + +To check which behaviour a node has, look at its unit: + +```bash +systemctl cat spinifex-shutdown.service | grep ExecStop +``` + +`--unless-restarting` drains on a plain stop; `--only-if-host-stopping` does +not. **On a node still showing `--only-if-host-stopping`, drain guests +explicitly before stopping the target.** + +1. Stop the instances first, via the AWS-compatible API: + + ```bash + aws ec2 stop-instances --instance-ids i-0123456789abcdef0 + ``` + + Or run the drain command by hand on the node — invoked without a gate flag + it drains unconditionally: + + ```bash + sudo spx admin node drain --local + ``` + +2. Confirm no guests are left running: + + ```bash + ps auxw | grep qemu-system + ``` + +3. Only then stop the target: + + ```bash + sudo systemctl stop spinifex.target + ``` + +This does not apply to `systemctl restart spinifex.target` — the restart row +in the contract table above is unaffected, since the same gate is what makes +guests survive a restart intact. + +## Why Guests Outlive the Daemon + +`KillMode=process` is set on `spinifex-daemon.service` and +`spinifex-viperblock.service`. It tells systemd to signal only the unit's +main process and leave everything else in its cgroup alone, so guest QEMU +processes and any nbdkit backend still serving a guest survive a restart of +the service that spawned them. This is deliberate: a control-plane restart or +upgrade must never interrupt a customer workload just because the daemon that +launched it needed to bounce. + +On the way back up, `Manager.Restore` reconnects to each surviving guest over +QMP rather than relaunching it, so the guest is never rebooted by a daemon or +target restart. + +This is what makes the restart row in the contract table safe, and it holds +only as long as storage comes back with the daemon — a daemon-only restart +never takes predastore or viperblock down, and a target restart brings them +back within seconds. It does not hold for an event that leaves storage down +indefinitely, which is exactly the deviation described above. + +## Checking State + +```bash +# Service status for the whole stack +systemctl status spinifex.target + +# Is systemd mid-shutdown, or just running? +systemctl is-system-running + +# Any guest QEMU processes still alive +ps auxw | grep qemu-system + +# Guest state as Spinifex sees it (node, status, health) +spx get vms + +# EC2-API view of instance state +aws ec2 describe-instances + +# Confirm whether the last target stop actually drained guests +journalctl -u spinifex-shutdown -b +# Look for: "Host is not shutting down; skipping guest drain." +``` + +## Maintenance Runbooks + +### Apply a Config Change + +1. Edit `/etc/spinifex/spinifex.toml`. +2. Apply it: + + ```bash + sudo systemctl restart spinifex.target + ``` + +Guests survive this restart — they are not rebooted, and storage returns +within seconds. This is the supported way to pick up a config change; see +the restart row in [The Contract](#the-contract). + +### Take a Node Down for Hardware Maintenance + +1. Stop or reboot the host — both drain running guests first: + + ```bash + sudo systemctl stop spinifex.target # taking the node fully out of service + sudo reboot # or, for a reboot + ``` + +2. Confirm nothing is left running: + + ```bash + ps auxw | grep qemu-system + ``` + +The drain is automatic on both paths. Stop the instances yourself first only +if you want them to stay stopped when the node returns, or if the node still +runs an older build — see [Older Releases](#older-releases-systemctl-stop-spinifextarget) +above. diff --git a/docs/admin/update/README.md b/docs/admin/update/README.md index 58879354a..6c06dac67 100644 --- a/docs/admin/update/README.md +++ b/docs/admin/update/README.md @@ -95,6 +95,8 @@ Migrations modify config files on disk but do not restart running services. Appl sudo systemctl restart spinifex.target ``` +A restart preserves any running guests — they are not rebooted, and storage returns within seconds. See [Host and Guest Lifecycle](/docs/admin/host-lifecycle) for the full contract. + ## Troubleshooting ### No Pending Config Migrations @@ -125,3 +127,5 @@ Migrations edit config files on disk but the running daemons continue to use the ```bash sudo systemctl restart spinifex.target ``` + +A restart preserves any running guests — they are not rebooted, and storage returns within seconds. See [Host and Guest Lifecycle](/docs/admin/host-lifecycle) for the full contract. diff --git a/spinifex/services/viperblockd/shutdown_test.go b/spinifex/services/viperblockd/shutdown_test.go index 508260008..9a38178a7 100644 --- a/spinifex/services/viperblockd/shutdown_test.go +++ b/spinifex/services/viperblockd/shutdown_test.go @@ -1,11 +1,13 @@ package viperblockd import ( + "fmt" "net" "os/exec" "path/filepath" "syscall" "testing" + "time" ) // alive reports whether pid is still a live process. @@ -51,6 +53,48 @@ func TestShutdownVolumes_IdleKilled(t *testing.T) { } } +// TestShutdownVolumes_ReapsConcurrently proves the idle-volume reap fans out +// rather than running serially: N volumes whose fake nbdkit each take +// `delay` to die must all be reaped in about one delay's worth of wall time, +// not delay*N — a serial loop is what let one slow nbdkit blow the unit's +// TimeoutStopSec budget on a node with several mounted volumes. +func TestShutdownVolumes_ReapsConcurrently(t *testing.T) { + const n = 3 + const delay = 150 * time.Millisecond + + volumes := make([]MountedVolume, n) + for i := range n { + // Idle-spin so the process only ever dies via its TERM trap, ~delay + // after SIGTERM actually arrives — standing in for nbdkit's own + // bounded shutdown drain (never dies on its own schedule). + script := fmt.Sprintf("trap 'sleep %f; exit 0' TERM; while true; do sleep 0.01; done", delay.Seconds()) + cmd := exec.Command("sh", "-c", script) + if err := cmd.Start(); err != nil { + t.Fatalf("start sleeper %d: %v", i, err) + } + pid := cmd.Process.Pid + t.Cleanup(func() { _ = cmd.Process.Kill() }) + go func() { _, _ = cmd.Process.Wait() }() + volumes[i] = MountedVolume{Name: fmt.Sprintf("vol-%d", i), PID: pid} + } + + start := time.Now() + shutdownVolumes(volumes, func(MountedVolume) bool { return false }) + elapsed := time.Since(start) + + for _, v := range volumes { + if alive(v.PID) { + t.Fatalf("volume %s was not reaped", v.Name) + } + } + + // Concurrent reap: ~one delay plus poll jitter. Serial reap of n volumes + // would take ~n*delay (450ms here) — well past this bound. + if bound := 2 * delay; elapsed > bound { + t.Fatalf("shutdownVolumes took %v to reap %d volumes at %v each (bound %v) — looks serial, not concurrent", elapsed, n, delay, bound) + } +} + // TestNbdkitInUse_ConnectedClientDetected proves nbdkitInUse parses ss output // and detects a live client on the unix socket — a guest still attached. The // state column is field[1] (field[0] is the netid), so a wrong index here diff --git a/spinifex/services/viperblockd/viperblockd.go b/spinifex/services/viperblockd/viperblockd.go index ac8f2e449..025eba3b9 100644 --- a/spinifex/services/viperblockd/viperblockd.go +++ b/spinifex/services/viperblockd/viperblockd.go @@ -1172,7 +1172,13 @@ func launchService(cfg *Config) (err error) { // nbdkit for volumes with no attached guest (inUse false). Killing an nbdkit a // guest is still writing through corrupts that guest's filesystem; the graceful // drain (or unmount) path owns reaping in-use nbdkit after the guest is gone. +// +// The reap itself fans out one goroutine per idle volume so the wall-clock +// cost is bounded by the slowest single nbdkit's utils.KillProcess grace, not +// the sum across every mounted volume — the caller returns (and the process +// exits) only once every goroutine below has finished. func shutdownVolumes(volumes []MountedVolume, inUse func(MountedVolume) bool) { + var wg sync.WaitGroup for _, volume := range volumes { if volume.VB != nil { volume.VB.StopChunkUploader() @@ -1183,11 +1189,16 @@ func shutdownVolumes(volumes []MountedVolume, inUse func(MountedVolume) bool) { "pid", volume.PID, "name", volume.Name, "socket", volume.Socket) continue } - slog.Info("Killing idle nbdkit process", "pid", volume.PID, "name", volume.Name) - if err := utils.KillProcess(volume.PID); err != nil { - slog.Error("Failed to kill nbdkit process", "pid", volume.PID, "err", err) - } + wg.Add(1) + go func(volume MountedVolume) { + defer wg.Done() + slog.Info("Killing idle nbdkit process", "pid", volume.PID, "name", volume.Name) + if err := utils.KillProcess(volume.PID); err != nil { + slog.Error("Failed to kill nbdkit process", "pid", volume.PID, "err", err) + } + }(volume) } + wg.Wait() } // nbdkitInUse best-effort reports whether nbdkit's NBD endpoint still has a diff --git a/spinifex/systemd/units_invariants_test.go b/spinifex/systemd/units_invariants_test.go index fb755edee..37a395c75 100644 --- a/spinifex/systemd/units_invariants_test.go +++ b/spinifex/systemd/units_invariants_test.go @@ -6,8 +6,10 @@ import ( "regexp" "runtime" "slices" + "strconv" "strings" "testing" + "time" ) // unitsDir locates build/systemd by walking up from this test file. @@ -53,6 +55,23 @@ func unitFiles(t *testing.T, dir string) []string { return out } +// timeoutStopSec parses a unit's TimeoutStopSec= value (this repo always +// writes plain seconds, no unit suffix) into a time.Duration. +func timeoutStopSec(t *testing.T, unit string) time.Duration { + t.Helper() + for l := range strings.SplitSeq(unit, "\n") { + if v, ok := strings.CutPrefix(strings.TrimSpace(l), "TimeoutStopSec="); ok { + n, err := strconv.Atoi(v) + if err != nil { + t.Fatalf("parse TimeoutStopSec=%q: %v", v, err) + } + return time.Duration(n) * time.Second + } + } + t.Fatal("unit has no TimeoutStopSec=") + return 0 +} + // hasDirective reports whether unit carries an exact directive line (trimmed). func hasDirective(unit, line string) bool { for l := range strings.SplitSeq(unit, "\n") { @@ -195,8 +214,8 @@ func TestOptionalNorthstarActivation(t *testing.T) { // oneshot orders After= the storage/daemon units (so a target/host stop runs its // ExecStop drain first, while those services are still up), the daemon keeps // KillMode=process (guests survive a daemon restart — DDIL reattach), and -// ExecStop passes --only-if-host-stopping so PartOf=spinifex.target firing on -// every target stop (restart included) does not drain guests that stay up. +// ExecStop passes --unless-restarting so PartOf=spinifex.target firing on +// every target stop only skips the drain when a restart is already queued. func TestGracefulDrainOrdering(t *testing.T) { dir := unitsDir(t) @@ -220,8 +239,8 @@ func TestGracefulDrainOrdering(t *testing.T) { t.Errorf("spinifex-shutdown.service After= must include %s so the drain stops before it", dep) } } - if !hasDirective(drain, "ExecStop=/usr/local/bin/spx admin node drain --local --timeout=120s --only-if-host-stopping") { - t.Error("spinifex-shutdown.service must run spx admin node drain --local --only-if-host-stopping on stop via ExecStop") + if !hasDirective(drain, "ExecStop=/usr/local/bin/spx admin node drain --local --timeout=120s --unless-restarting") { + t.Error("spinifex-shutdown.service must run spx admin node drain --local --unless-restarting on stop via ExecStop") } daemon := readUnit(t, dir, "spinifex-daemon.service") @@ -237,6 +256,14 @@ func TestGracefulDrainOrdering(t *testing.T) { t.Error("spinifex-viperblock.service must keep KillMode=process — in-use nbdkit survives a viperblock restart (DDIL)") } + // shutdownVolumes reaps idle nbdkit concurrently, so the unit only has to + // outlive the single slowest utils.KillProcess grace (120s), not that + // grace summed across every mounted volume. + const killProcessGracePeriod = 120 * time.Second + if got := timeoutStopSec(t, viperblock); got <= killProcessGracePeriod { + t.Errorf("spinifex-viperblock.service TimeoutStopSec=%v must strictly exceed the %v KillProcess grace period", got, killProcessGracePeriod) + } + target := readUnit(t, dir, "spinifex.target") if !strings.Contains(target, "spinifex-shutdown.service") { t.Error("spinifex.target Wants= must include spinifex-shutdown.service")