spinifex/tests/e2e/storagefault/stop_start_durability_test.go

//go:build e2e

package storagefault

import (
	"context"
	"fmt"
	"os"
	"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"
)

const (
	// patternDevice is the guest-visible attach point for the pattern volume.
	patternDevice = "/dev/sdg"

	// patternVolumeSizeGiB sizes the volume holding the known pattern.
	patternVolumeSizeGiB = 1

	// patternMiB is how much of the device the pattern covers. Large enough to
	// span many 4 KiB blocks and several 4 MiB chunks, small enough to write
	// and re-read in seconds.
	patternMiB = 64

	// stopStartTimeout bounds a StopInstances or StartInstances round trip.
	// Generous because the stop is deliberately made to run against a backend
	// that cannot answer, which is the slowest this path ever gets.
	stopStartTimeout = 10 * time.Minute

	// nodeConfigPath is where the installed layout keeps the cluster config an
	// spx subcommand run over SSH has to be pointed at.
	nodeConfigPath = "/etc/spinifex/spinifex.toml"
)

// viperblockBaseDir is where a node keeps per-volume local state. Overridable
// for a cluster laid out differently, but this is the installed default and
// what the seal receipt sits beside.
func viperblockBaseDir() string {
	if v := os.Getenv("SPINIFEX_VIPERBLOCK_BASEDIR"); v != "" {
		return v
	}
	return "/var/lib/spinifex/viperblock"
}

// TestStopStartPreservesWritesOnSameNode proves the recovery path the whole
// dirty-volume design rests on: when a seal fails, the local WAL is kept and a
// restart on the same node recovers from it with nothing lost.
//
// Expected to pass against the current engine. It is here because the
// cross-node test below is only meaningful if this one holds — a fix that
// refused every start would make that test green while making the platform
// worse.
func TestStopStartPreservesWritesOnSameNode(t *testing.T) {
	fix := requireStorageFaultFixture(t)
	requireNoneFrozen(t, fix)

	instanceID, tgt := ensureFaultInstance(t, fix)
	hostNode := harness.InstanceHostingNode(t, fix.Cluster, instanceID)
	if hostNode == nil {
		t.Fatalf("cannot identify the node hosting %s, so its local state cannot be inspected", instanceID)
	}

	az := harness.DiscoverDefaultAZ(t, fix.Harness)
	volID := harness.EnsureVolume(t, fix.Harness, az, patternVolumeSizeGiB)

	before := harness.GuestDiskSet(t, tgt)
	harness.AttachVolumeWait(t, fix.AWS, volID, instanceID, patternDevice)
	dev := harness.WaitForNewGuestDisk(t, tgt, before, 90*time.Second)
	t.Cleanup(func() { harness.DetachVolumeWait(t, fix.AWS, volID) })

	want := writePattern(t, tgt, dev)
	harness.Detail(t, "instance", instanceID, "volume", volID, "host_node", hostNode.Name, "sha256", want)

	freezeSet, why := freezeSetFor(fix, hostNode)
	harness.Step(t, "freezing predastore on %s (%s) so the seal cannot complete", nodeNames(freezeSet), why)
	freezePredastore(t, fix, freezeSet)

	harness.Step(t, "stopping %s with the backend frozen", instanceID)
	stopErr := stopInstance(t, fix, instanceID)
	t.Logf("StopInstances returned: %v", errOrOK(stopErr))

	assertLocalStateKept(t, fix, hostNode, volID)

	thawPredastore(t, fix, freezeSet)
	time.Sleep(recoverySettle)

	harness.Step(t, "starting %s again on the same node", instanceID)
	startInstance(t, fix, instanceID)
	inst := harness.WaitForInstanceState(t, fix.AWS, instanceID, "running")
	host, port := harness.InstancePublicSSHHost(t, inst)
	if !harness.TryGuestSSHReady(host, port, "ubuntu", tgt.KeyPath, 5*time.Minute) {
		t.Fatalf("guest did not come back after a same-node restart%s", consoleTail(fix, instanceID))
	}
	tgt = harness.SSHTarget{User: "ubuntu", Host: host, Port: port, KeyPath: tgt.KeyPath}

	got := readPattern(t, tgt, dev)
	if got != want {
		t.Errorf("a same-node restart after a failed seal lost data: sha256 was %s, now %s.\n"+
			"This breaks the premise the dirty-volume design rests on — the local WAL is supposed "+
			"to be kept and recovered from on exactly this path.", want, got)
		return
	}
	harness.Step(t, "same-node restart recovered every acknowledged write from local state")
}

// TestCrossNodeStartAfterFailedSealTakesOverLoudly pins the trade the design
// makes. A volume whose seal failed has its freshest copy on one node, and
// starting it elsewhere opens an older checkpoint from the backend.
//
// Starting elsewhere is nonetheless the right outcome: instance start forwards
// to the node that last ran the instance and only falls back once that node has
// failed its window, so refusing here would leave the instance unable to run at
// all. What must never happen is the fallback being silent, so this asserts the
// takeover is logged and names the node whose writes were left behind.
func TestCrossNodeStartAfterFailedSealTakesOverLoudly(t *testing.T) {
	fix := requireStorageFaultFixture(t)
	if len(fix.Cluster.Nodes) < 3 {
		t.Skip("a cross-node start needs somewhere else to start: single-node clusters cannot reproduce this")
	}
	requireNoneFrozen(t, fix)

	instanceID, tgt := ensureFaultInstance(t, fix)
	hostNode := harness.InstanceHostingNode(t, fix.Cluster, instanceID)
	if hostNode == nil {
		t.Fatalf("cannot identify the node hosting %s", instanceID)
	}

	az := harness.DiscoverDefaultAZ(t, fix.Harness)
	volID := harness.EnsureVolume(t, fix.Harness, az, patternVolumeSizeGiB)

	before := harness.GuestDiskSet(t, tgt)
	harness.AttachVolumeWait(t, fix.AWS, volID, instanceID, patternDevice)
	dev := harness.WaitForNewGuestDisk(t, tgt, before, 90*time.Second)
	t.Cleanup(func() { harness.DetachVolumeWait(t, fix.AWS, volID) })

	want := writePattern(t, tgt, dev)
	harness.Detail(t, "instance", instanceID, "volume", volID, "host_node", hostNode.Name, "sha256", want)

	freezeSet, _ := freezeSetFor(fix, hostNode)
	freezePredastore(t, fix, freezeSet)

	harness.Step(t, "stopping %s with the backend frozen, so the seal fails", instanceID)
	_ = stopInstance(t, fix, instanceID)
	assertLocalStateKept(t, fix, hostNode, volID)

	thawPredastore(t, fix, freezeSet)
	time.Sleep(recoverySettle)

	// Read after the thaw has settled, not before it. A marker is written when
	// a volume opens and cleared by the seal, and the seal the stop gave up
	// waiting for can still finish once the backend answers again. Only what
	// survives that is genuinely left behind for the takeover to be loud about.
	unsealed := requireUnsealedVolumes(t, fix, hostNode)

	// The node has to be gone, not merely quiet. A live viperblockd goes on
	// renewing the lease on a volume whose seal failed, and that refusal is
	// correct: the node could still be writing.
	harness.Step(t, "taking %s out so the start has to happen elsewhere", hostNode.Name)
	isolateNode(t, fix, *hostNode)

	if startErr := startInstance(t, fix, instanceID); startErr != nil {
		t.Fatalf("the start was refused, so the instance can run nowhere while %s is down: %v\n"+
			"Falling back to the backend checkpoint is the intended behaviour here.", hostNode.Name, startErr)
	}

	inst := harness.WaitForInstanceState(t, fix.AWS, instanceID, "running")
	landed := harness.InstanceHostingNode(t, fix.Cluster, instanceID)
	if landed != nil && landed.Index == hostNode.Index {
		t.Skipf("the instance started on %s again, so no cross-node start happened and this test proved nothing", hostNode.Name)
	}
	harness.Step(t, "the instance started on %s while %s was down", nodeName(landed), hostNode.Name)

	// The loss is accepted; being unable to see it is not. This is the only
	// record that the volume opened from an older checkpoint than existed.
	assertTakeoverLogged(t, fix, landed, hostNode, unsealed)

	host, port := harness.InstancePublicSSHHost(t, inst)
	if !harness.TryGuestSSHReady(host, port, "ubuntu", tgt.KeyPath, 5*time.Minute) {
		t.Errorf("the cross-node start was allowed and the guest never came back: opening from the "+
			"backend checkpoint has to yield a bootable volume, not an unusable one.%s",
			consoleTail(fix, instanceID))
		return
	}
	tgt = harness.SSHTarget{User: "ubuntu", Host: host, Port: port, KeyPath: tgt.KeyPath}

	// Reading the pattern needs sudo, which the checkpoint may predate. Losing it
	// is the same accepted rollback, but only once cloud-init is ruled out: a guest
	// that found no datasource is the keyless-boot bug, not a storage outcome.
	if !guestSudoReady(tgt) {
		ds := guestDatasource(tgt)
		if strings.Contains(ds, "DataSourceNone") || ds == "" {
			t.Errorf("the guest came back unable to sudo and cloud-init found no datasource, so this "+
				"is IMDS failing to answer, not the checkpoint rolling back: %q%s", ds,
				consoleTail(fix, instanceID))
			return
		}
		harness.Step(t, "the pattern cannot be read: the root filesystem opened from a checkpoint "+
			"predating cloud-init's sudoers drop-in, the same documented cost as the pattern "+
			"changing. cloud-init did find its datasource (%s), so metadata was served.", ds)
		return
	}

	if got := readPattern(t, tgt, dev); got == want {
		harness.Step(t, "the pattern also survived the takeover: %s had sealed enough of it", hostNode.Name)
	} else {
		harness.Step(t, "the pattern changed across the takeover (was %s, now %s), which is the "+
			"documented cost of starting from the backend checkpoint", want, got)
	}
}

// guestSudoReady reports whether the guest can still sudo without a password.
// A volume opened from the backend checkpoint may predate cloud-init writing
// /etc/sudoers.d/90-cloud-init-users, which no read of the device can tell apart.
func guestSudoReady(tgt harness.SSHTarget) bool {
	_, err := harness.GuestExecTimeout(tgt, "sudo -n true", 60*time.Second)
	return err == nil
}

// guestDatasource returns what cloud-init recorded for this boot. result.json is
// the file that names the datasource and is world-readable; status --long is the
// fallback. This is the discriminator between a rollback and IMDS never answering.
func guestDatasource(tgt harness.SSHTarget) string {
	out, err := harness.GuestExecTimeout(tgt,
		"cat /run/cloud-init/result.json 2>/dev/null; cloud-init status --long 2>/dev/null",
		60*time.Second)
	if err != nil {
		return ""
	}
	return strings.Join(strings.Fields(out), " ")
}

// assertTakeoverLogged fails unless the node that opened the volume said so.
//
// This is the whole guarantee. Losing the previous holder's unsealed writes is
// a deliberate trade against the instance not running at all, and it is only
// defensible while an operator can find out it happened.
func assertTakeoverLogged(t *testing.T, fix *Fixture, landed, previous *harness.Node, unsealed []string) {
	t.Helper()
	if landed == nil {
		return
	}

	ctx, cancel := context.WithTimeout(context.Background(), 60*time.Second)
	defer cancel()

	cmd := "sudo journalctl -u spinifex-viperblock -u spinifex-daemon --since '-10 min' --no-pager 2>/dev/null | " +
		"grep -i 'last held by another node' | tail -20"
	out, err := fix.SSH.Run(ctx, *landed, cmd)
	if err != nil {
		t.Errorf("could not read %s's journal to confirm the takeover was logged: %v", landed.Name, err)
		return
	}

	// Any one of them: the instance's volumes are sealed together and the
	// guarantee is that the operator is told, not that every volume is named.
	journal := string(out)
	var named string
	for _, volID := range unsealed {
		if strings.Contains(journal, volID) {
			named = volID
			break
		}
	}
	if named == "" {
		t.Errorf("%s opened %s from the backend checkpoint while %s held unsealed writes, and logged "+
			"nothing about it. The loss is acceptable; a silent loss is not.",
			landed.Name, strings.Join(unsealed, ", "), previous.Name)
		return
	}
	// The marker records the spinifex node name, which is the host's own name
	// and not the harness's nodeN label, so accept either identity.
	if !strings.Contains(journal, previous.Name) && !strings.Contains(journal, previous.Addr) {
		t.Errorf("%s logged a takeover for %s but did not name %s (%s), so an operator cannot tell "+
			"whose writes were left behind:\n%s", landed.Name, named, previous.Name, previous.Addr, journal)
		return
	}
	harness.Step(t, "%s logged the takeover of %s and named %s", landed.Name, named, previous.Name)
}

// requireUnsealedVolumes returns the volumes the cluster records node as
// holding writes the backend may not have, and skips the test if there are none.
//
// The stop returning an error does not establish this. The unmount is a NATS
// request, and its caller giving up says nothing about the seal behind it, so
// local state kept with no seal receipt is equally what an in-flight seal looks
// like. A marker that is still there once the backend is answering again is not.
//
// Which volume is left unsealed is not the test's to choose. Freezing
// predastore fails a seal that has to read from it — a root volume loading its
// AMI snapshot — while a blank attached volume can seal straight through the
// outage. That is correct behaviour, so the takeover is asserted against
// whatever was actually left behind rather than a volume picked in advance.
func requireUnsealedVolumes(t *testing.T, fix *Fixture, node *harness.Node) []string {
	t.Helper()

	held := unsealedVolumesHeldBy(t, fix, node)
	if len(held) == 0 {
		t.Skipf("no seal failed on %s while the backend was frozen, so there are no unsealed writes "+
			"to take over and this test would assert a warning that would be wrong", node.Name)
	}
	harness.Step(t, "%s still holds unsealed writes for %s after the backend came back",
		node.Name, strings.Join(held, ", "))
	return held
}

// unsealedVolumesHeldBy reads the cluster's unsealed-volume report from node and
// returns the volumes it names node as holding. The report is a block per
// volume: the id on its own line, then indented fields.
func unsealedVolumesHeldBy(t *testing.T, fix *Fixture, node *harness.Node) []string {
	t.Helper()

	ctx, cancel := context.WithTimeout(context.Background(), 60*time.Second)
	defer cancel()

	out, err := fix.SSH.Run(ctx, *node, "sudo spx admin volumes unsealed --config "+nodeConfigPath)
	if err != nil {
		// The node is up and the report reads NATS, not the frozen backend, so
		// this is worth seeing rather than retrying silently.
		t.Logf("could not read the unsealed volumes from %s: %v", node.Name, err)
		return nil
	}

	var held []string
	current := ""
	for line := range strings.SplitSeq(string(out), "\n") {
		trimmed := strings.TrimSpace(line)
		switch {
		case strings.HasPrefix(trimmed, "vol-") && !strings.Contains(trimmed, " "):
			current = trimmed
		case current != "" && strings.HasPrefix(trimmed, "held by:"):
			owner := strings.TrimSpace(strings.TrimPrefix(trimmed, "held by:"))
			if owner == node.Name || owner == node.Addr {
				held = append(held, current)
			}
			current = ""
		}
	}
	return held
}

// assertLocalStateKept checks the node kept the volume's local files and wrote
// no seal receipt. Both are what a correctly failed seal leaves behind, and
// together they are the ground truth a cluster-visible marker would index.
func assertLocalStateKept(t *testing.T, fix *Fixture, node *harness.Node, volID string) {
	t.Helper()
	ctx, cancel := context.WithTimeout(context.Background(), 60*time.Second)
	defer cancel()

	base := viperblockBaseDir()
	dirCmd := fmt.Sprintf("sudo test -d %s/%s && echo PRESENT || echo ABSENT", base, volID)
	dirOut, err := fix.SSH.Run(ctx, *node, dirCmd)
	if err != nil {
		t.Fatalf("inspect local volume state on %s: %v", node.Name, err)
	}
	receiptCmd := fmt.Sprintf("sudo test -f %s/%s.sealed && echo PRESENT || echo ABSENT", base, volID)
	receiptOut, err := fix.SSH.Run(ctx, *node, receiptCmd)
	if err != nil {
		t.Fatalf("inspect seal receipt on %s: %v", node.Name, err)
	}

	local := strings.TrimSpace(string(dirOut))
	receipt := strings.TrimSpace(string(receiptOut))
	harness.Detail(t, "node", node.Name, "local_state", local, "seal_receipt", receipt)

	if receipt == "PRESENT" {
		t.Errorf("a seal receipt exists for %s on %s even though the backend was frozen: "+
			"the seal reported success it cannot have had", volID, node.Name)
	}
	if local == "ABSENT" {
		t.Errorf("%s kept no local state for %s after a failed seal. The un-uploaded writes were the "+
			"only current copy and they have been deleted — this is unrecoverable data loss, not a routing bug.",
			node.Name, volID)
	}
}

// writePattern fills the head of the device with a reproducible pattern,
// flushes it to the backend and returns its checksum. O_DIRECT plus an
// explicit flush is what makes the write acknowledged rather than merely
// buffered, which is the only kind this suite makes claims about.
func writePattern(t *testing.T, tgt harness.SSHTarget, dev string) string {
	t.Helper()
	cmd := fmt.Sprintf(
		"sudo dd if=/dev/urandom of=/dev/%s bs=1M count=%d oflag=direct status=none && "+
			"sudo blockdev --flushbufs /dev/%s && sync",
		dev, patternMiB, dev)
	out, err := harness.GuestExecTimeout(tgt, cmd, 5*time.Minute)
	if err != nil {
		t.Fatalf("write pattern to /dev/%s: %v\n%s\n%s", dev, err, out, deviceGeometry(tgt, dev))
	}
	return readPattern(t, tgt, dev)
}

// readPattern re-reads the pattern region and returns its checksum. The page
// cache is dropped first so the read comes from the device rather than from
// what was written before the restart.
//
// Not O_DIRECT: this image ships uutils dd, whose O_DIRECT read path only
// handles 512-byte transfers and fails EINVAL at 4k and above. Dropping the
// cache gives the same guarantee and works under either dd.
func readPattern(t *testing.T, tgt harness.SSHTarget, dev string) string {
	t.Helper()
	cmd := fmt.Sprintf(
		"set -o pipefail; sudo blockdev --flushbufs /dev/%[1]s && sync && "+
			"echo 3 | sudo tee /proc/sys/vm/drop_caches >/dev/null && "+
			"sudo dd if=/dev/%[1]s bs=1M count=%[2]d status=none | sha256sum | cut -d' ' -f1",
		dev, patternMiB)
	out, err := harness.GuestExecTimeout(tgt, cmd, 5*time.Minute)
	if err != nil {
		t.Fatalf("read pattern back from /dev/%s: %v\n%s\n%s", dev, err, out, deviceGeometry(tgt, dev))
	}
	sum := strings.TrimSpace(out)
	if len(sum) != 64 {
		t.Fatalf("expected a sha256 from /dev/%s, got %q\n%s", dev, sum, deviceGeometry(tgt, dev))
	}
	return sum
}

// stopInstance stops the instance and waits for it to settle. The error is
// returned rather than fatal: whether a stop against a dead backend succeeds
// or fails is one of the things under test.
func stopInstance(t *testing.T, fix *Fixture, instanceID string) error {
	t.Helper()
	if _, err := fix.AWS.EC2.StopInstances(&ec2.StopInstancesInput{
		InstanceIds: []*string{aws.String(instanceID)},
	}); err != nil {
		return err
	}
	deadline := time.Now().Add(stopStartTimeout)
	for time.Now().Before(deadline) {
		switch instanceStateOf(fix, instanceID) {
		case "stopped":
			return nil
		case "error":
			return fmt.Errorf("instance %s entered error state during stop", instanceID)
		}
		time.Sleep(10 * time.Second)
	}
	return fmt.Errorf("instance %s did not reach stopped within %s", instanceID, stopStartTimeout)
}

// startInstance starts the instance, returning the API error if the start is
// refused. A refusal is the desired behaviour for a dirty volume, so this is a
// value the caller inspects rather than a failure.
func startInstance(t *testing.T, fix *Fixture, instanceID string) error {
	t.Helper()
	_, err := fix.AWS.EC2.StartInstances(&ec2.StartInstancesInput{
		InstanceIds: []*string{aws.String(instanceID)},
	})
	return err
}

// isolatedUnits are the two services that have to be down for a node to look
// gone. The daemon so ec2.start.{lastNode} has no responder, and viperblock so
// nothing on this node keeps renewing the lease it holds on the volume.
//
// Not the whole target: predastore stays up so the node keeps serving its shard,
// which is what a node whose control plane died looks like from the cluster.
var isolatedUnits = []string{"spinifex-daemon", "spinifex-viperblock"}

// leaseExpiryBudget is how long to wait for an unrenewed volume lease to age
// out of JetStream once its holder is gone. Comfortably past the 45s TTL, since
// the entry only disappears on the bucket's own schedule.
const leaseExpiryBudget = 75 * time.Second

// isolateNode stops the control-plane services on node and restores them on
// cleanup, then waits for the volume lease the node held to expire.
//
// Waiting is the point. Without it the start elsewhere is refused by a lease
// that is simply still current, which says nothing about what happens when its
// holder is not coming back.
func isolateNode(t *testing.T, fix *Fixture, node harness.Node) {
	t.Helper()
	t.Cleanup(func() {
		ctx, cancel := context.WithTimeout(context.Background(), 180*time.Second)
		defer cancel()
		for _, unit := range isolatedUnits {
			if _, err := fix.SSH.Run(ctx, node, "sudo systemctl start "+unit); err != nil {
				t.Errorf("could not restart %s on %s — the node is left without it: %v", unit, node.Name, err)
				continue
			}
			t.Logf("restarted %s on %s", unit, node.Name)
		}
	})

	ctx, cancel := context.WithTimeout(context.Background(), 180*time.Second)
	defer cancel()
	for _, unit := range isolatedUnits {
		if _, err := fix.SSH.Run(ctx, node, "sudo systemctl stop "+unit); err != nil {
			t.Fatalf("stop %s on %s: %v", unit, node.Name, err)
		}
	}

	harness.Step(t, "waiting %s for %s's volume lease to age out", leaseExpiryBudget, node.Name)
	time.Sleep(leaseExpiryBudget)
}

func errOrOK(err error) string {
	if err == nil {
		return "success"
	}
	return err.Error()
}

// consoleTail returns the guest's serial console for a restart that never
// answered SSH, formatted to append to a failure message. Whether the kernel
// booted and stalled or never got that far is only visible here, and the log is
// gone once the fixture terminates the instance.
func consoleTail(fix *Fixture, instanceID string) string {
	console, err := harness.InstanceConsole(fix.AWS, instanceID)
	if err != nil {
		return fmt.Sprintf("\nconsole unavailable: %v", err)
	}
	if strings.TrimSpace(console) == "" {
		return "\nconsole was empty, so the guest produced no serial output at all"
	}
	const tailBytes = 4096
	if len(console) > tailBytes {
		console = console[len(console)-tailBytes:]
	}
	return "\nguest console (last " + fmt.Sprint(len(console)) + " bytes):\n" + console
}

// deviceGeometry reports what the guest kernel thinks the device is, for a
// pattern write or read that failed. An alignment or size mismatch is the usual
// cause of an EINVAL on an O_DIRECT transfer, and neither is visible in dd's
// own message.
func deviceGeometry(tgt harness.SSHTarget, dev string) string {
	cmd := fmt.Sprintf(
		"for p in getsize64 getss getpbsz getiomin getioopt; do "+
			"printf '%%s=%%s ' $p $(sudo blockdev --$p /dev/%[1]s 2>&1); done; echo; "+
			"dd --version | head -1; "+
			"echo -n 'direct 512:  '; sudo dd if=/dev/%[1]s bs=512 count=1 iflag=direct of=/dev/null 2>&1 | tail -1; "+
			"echo -n 'direct 4k:   '; sudo dd if=/dev/%[1]s bs=4k  count=1 iflag=direct of=/dev/null 2>&1 | tail -1; "+
			"echo -n 'direct 1M:   '; sudo dd if=/dev/%[1]s bs=1M  count=1 iflag=direct of=/dev/null 2>&1 | tail -1; "+
			"echo -n 'buffered 1M: '; sudo dd if=/dev/%[1]s bs=1M  count=1 of=/dev/null 2>&1 | tail -1",
		dev)
	out, err := harness.GuestExecTimeout(tgt, cmd, time.Minute)
	if err != nil {
		return fmt.Sprintf("device geometry unavailable: %v\n%s", err, out)
	}
	return "device geometry:\n" + out
}