Files
Ben Duncan 021f439bab feat: recover instances automatically from a node that stopped heartbeating (#1111)
* feat: recover instances automatically from a node that stopped heartbeating

A node that dies hard takes its guests with it, and nothing brings them back
until an operator brings that node back. Every daemon now runs the same small
reconciler: it reads the instance records, selects desired-running instances
whose owner is stale, and relaunches them here.

The claim is a CAS on Status.LastNode and that is the whole of the
coordination. Several survivors race one instance, exactly one revision wins,
and the losers find a record naming a live owner and stop considering it. A
claimant that dies mid-launch leaves the record naming a node that is itself
stale, which is the same candidate the next pass derives again, so there is no
lease to expire and nothing to reconcile by hand.

Ownership is not permission to write. The volume leases still decide whether the
guest can move, and VolumeMounter.Mount runs before startQEMU, so an attempt
that loses the volume race has touched no tap, no OVS port and no OVN binding.

A storage failure is not a host failure and wants the opposite response. A guest
paused by werror=stop publishes Health.IOErrorSince, and a record carrying it is
refused: the volumes are the same objects in the same store from anywhere, so
relaunching moves the pause rather than ending it. A node whose own object store
is not answering stands down entirely, which separates a store broken here from
a store broken everywhere without either having to be diagnosed. A launch that
does not complete backs this node off that instance, doubling to a cap, because
nothing on the mount path can yet say which of the two it hit.

Recovery is off by default and inert below three nodes. It also waits until it
has seen its peers live, or five minutes, so the first node back from a
coordinated shutdown does not recover guests from nodes that are still booting.

* test: prove instance recovery moves a host failure and refuses a storage failure

The e2e half of automatic instance recovery, asserted from both sides because a reconciler that cannot tell the two failures apart passes one and fails the other. InstanceAutoRecovery takes a node down and requires the guest back on exactly one survivor, identified by the qemu process rather than by what the API reports. InstanceRecoveryRefusesStorageFault stops predastore cluster-wide first, so the guest is paused by werror=stop when its node goes away, and requires that nothing moves.

Also fixes the settle window, which re-evaluated every pass and so held a daemon back for its first five minutes over exactly the failure the reconciler exists to handle. It now latches once every peer has been seen live.

harness.InstanceHostingNodes replaces the single-node lookup so a caller can assert there is exactly one host rather than assume it, and skip a node it has deliberately taken down.

* fix: make automatic instance recovery a cluster-wide setting

Recovery was read from the per-node Config, so it had to be written three times on a three-node cluster, once inside each [nodes.<name>] table. A top-level [recovery] table — the obvious thing to write, and what the e2e suite writes — was parsed into nothing and the daemon reported recovery disabled on every node with the setting plainly in the file.

Cluster-wide is also the honest shape. A node with recovery off is not opting out of anything: recovery is what survivors do to a dead node's instances, so the setting belongs where there is one of it.

* test: drive real I/O into the storage-fault case, and freeze the store rather than stop it

Measured on a three-node cluster: predastore stopped cluster-wide for twelve minutes against idle guests paused none of them. Viperblock serves what it has cached and an idle guest issues nothing that reaches the object store, so the test asserted that nothing moved in a run where nothing was ever faulted.

The victim now launches with cloud-init user-data that writes to its root volume continuously. User-data rather than SSH because a routed-NAT cell gives guests no public address, so a test that had to log in could not run on half of them.

The fault is SIGSTOP rather than a unit stop, for the reason the storagefault suite already gives: a frozen process holds its connections open and answers nothing. Under that fault and that load the first BLOCK_IO_ERROR arrived 4m47s later, so the pause budget is now ten minutes rather than three.

* test: give instance recovery its own suite and its own nightly cell

Both tests take a node away and one of them freezes predastore cluster-wide, so anything sharing the environment reports that outage as its own failure — the same argument storagefault already makes for being its own package. They are also slow by nature: a dead owner has to be seen stale twice, a guest has to boot, and the storage case waits for a pause measured at 4m47s and then holds four minutes to prove nothing moved. Roughly twenty minutes on top of a permutation cell budgeted at thirty-five.

Cell 31 is three-node and static, matching storagefault's, with a 75-minute job budget over a 60-minute suite timeout. The suite is eligible on multi-node environments and deliberately not in the nightly permutation set.

* fix: give a guest long enough to open a volume the object store is slow to serve

QEMU opens every drive before its monitor answers a greeting, so the QMP
greeting deadline is really a deadline on opening the guest's volumes. At 30s
it was shorter than a cold viperblock open costs on a cluster that has lost a
node, where every object read is served degraded: measured at 35s with one node
of three away. The launch killed the guest five seconds short of ready and then
did it again on every retry, which is a recovery that can never complete.

A network-backed drive now gets its own deadline for the same reason VFIO
already had one — synchronous work before the monitor answers — and the
instancerecovery suite is what found it.

Also make the suite's predastore thaw best effort per node. It runs after a
node has been taken away, where there is no process to signal, and a node it
cannot reach must not stop it restoring the rest.

* docs: name the two newest cells in the dispatch input

The cells input is the operator's index of what a number means, and it stopped
at 29 while 30 and 31 were added.

* test: prove the guest is writing before freezing the store in the recovery suite

The storage-fault test froze the object store as soon as RunInstances reported
running, which is when QEMU has launched rather than when the guest has booted.
On the nightly cluster the freeze landed while the guest was still in UEFI, so
the only drive it could reach was the EFI varstore — and pflash has no
werror=stop to pause on, so the guest never paused and the test reported a
product failure it had caused itself.

The load driver now prints to the serial console after each pass it has written
and synced, and the test waits for that before freezing. The console is read
through GetConsoleOutput, so this still needs no login and still runs on cells
whose guests have no public address.

* feat: recover instances automatically with nothing to configure

The switch is gone. An instance whose host has failed is down whether or
not recovery is enabled, so the only outcome a disabled reconciler can
produce is leaving it down — which is the state recovery exists to end,
not a safer one to fall back to.

Against that, the switch cost a cluster that can be configured into
never recovering anything, with no symptom until a node dies. This
feature already hit that once: a top-level table parsed into nothing and
every node reported recovery off with the setting plainly in the file.

What makes recovery inert is now only facts about the cluster — no
cluster config, no JetStream, or fewer than three nodes — and each says
in the log which one applied. The e2e no longer writes config or
restarts daemons: it waits for every node to report the reconciler
active on a cluster nothing configured, so reintroducing a switch fails
there as well as in the unit tests.

* feat: stop retrying a recovery that is never going to work

Every failed attempt used to go to the same exponential backoff and stay
there. An instance nothing could launch was retried every fifteen
minutes forever, still observed-running on a node that is gone, with no
account of it anywhere the customer or an operator would look.

A failure is now classified and counted. Two classes are read from what
the launch actually reports: the node it was taken from still holds a
volume lease, which clears on that lease's clock and is retried on a
faster one, and this node has no room, which another survivor may. There
is no terminal class, because nothing on this path can prove one — the
launch collapses everything else into ServerInternal, so a verdict of
"never going to work" would be a guess, and the guess that abandons a
recoverable instance is the expensive one.

The budget bounds the unknown case instead. Every class counts against
it, since a class that did not would be the old unbounded retry under a
narrower condition. Exhausting it leaves the instance where AWS leaves
one whose host failed and could not be brought back: stopped, carrying a
StateReason that names the cause and the last error, one StartInstances
from running again. Writing the desired state down is also what makes
one node's decision cluster-wide, because selection reads desired state
— the same property the claim already has.

A record another node has since claimed is never touched, so a node
exhausting its attempts cannot stop a guest that is now running
elsewhere.

* fix: give a guest the time for every cost it pays before its monitor answers

A GPU instance booting from a network-backed root volume pays both
costs: QEMU opens every drive across the object store and then pins the
whole of guest RAM, one after the other, all before the monitor answers.
The deadline took whichever was larger, so such a guest was given less
time than it needs.

That the two floors are both 180s is why nothing has been seen yet — the
VFIO branch has always returned at least the network-drive deadline. It
is the same defect either way, and the symptom when it lands is a GPU
instance SIGKILLed on every attempt while its plain sibling launches,
which reads as a GPU fault rather than as a deadline.

The costs are now added, the plain QEMU startup is counted once rather
than replaced, and the cap covers both floors together so it cannot clip
a guest before either cost has been waited out.

* test: assert the AWS-visible arc of a host failure end to end

A customer cannot see which host an instance is on, and AWS never tells
them. What they can see is DescribeInstanceStatus, so that is where a
recovery has to be provable, and the suite never looked at it.

Three frames are now required, in order: running with system-status ok
before anything is broken, system-status impaired while the owning node
is gone, and ok again once a survivor is running it. The middle frame is
the one worth having — the window opens when the owner's heartbeat goes
stale, which is strictly before any survivor may claim, and closes when
the relaunch registers, so it is bounded rather than lucky. Reporting ok
throughout would be the more comfortable lie.

The availability zone is compared across the first and last frames as
well. A recovery that crossed one would break every placement promise
made to the customer, and nothing else in the suite would have noticed.

* test: prove a half-healthy node fences itself and is never a second writer

The two existing recovery cases take a node away by stopping its services,
which is the failure this feature handles least interestingly: a node that is
gone has no opinion about who owns its volumes. The one that matters is the node
that is still up, still running QEMU, still answering its own local clients, and
simply cannot reach consensus. That is the state in which two nodes can each
believe they own a volume, and the only thing between that and a corrupted disk
is that the partitioned node gives up first, on a clock it can evaluate without
reaching anything.

So this drops NATS on 4222 and 4248 between one node and its peers and nothing
else, then asserts the ordering the safety argument rests on rather than the
outcome it produces. A watch samples every node every three seconds for the
whole run, including the heal, and fails on any single sample naming two hosts.
Two guests writing one volume through one object store is data loss already
under way, not a race that resolves, and no point-in-time assertion can see one
that appeared between its own samples.

The injector takes its own nft table rather than touching inet spinifex_filter,
because a test that flushed the node's real firewall would leave it either
unfirewalled or misfirewalled with no sign of which, and a separate table at
priority -300 heals in one atomic delete. A transient systemd timer removes it
independently, so a cancelled workflow does not leave a node cut off from its
cluster until somebody notices. It proves SSH still works and proves a peer port
is genuinely unreachable before anything is asserted, since a rule set that
installed cleanly and dropped nothing would read as the system tolerating a
partition.

The suite budget goes to 90m and cell 31 to 105m to fit the third case.

* fix: move an instance's boot state, volumes, logical port and address with it

A record-driven launch assumes the node reading the record is the node that wrote
it. On a daemon restart that holds. On a recovery onto a survivor it does not, and
five things follow from it — one that stops a moved instance booting at all, and
four that stop it running anywhere.

A load balancer never comes back from a host failure. Its boot configuration is a
set of files under the runtime directory and the record holds their paths, so the
survivor restores paths that exist only on the node that died. The hook that
rebuilds them was reachable from Restore alone, and the cross-node path goes
straight to vmMgr.Run — so QEMU is handed a netcfg, an agent env and a CA cert
that are not there. The gateway URL baked into that env names the creating node's
management bridge as well, which the rebuild corrects because it rebuilds from
whichever node is running it. Firing the hook on both paths fixes both, and a
rebuild that fails now refuses the launch: a guest that boots without its network
configuration is worse than one that does not boot, because the records would say
it recovered.

The export outlives the guest and holds the volume lease. A returning node is
healthy, so it renews that lease indefinitely and the new owner never acquires:
the guest is stopped here and refused there, recovery spends its attempt budget on
a volume that was never going to be free, and gives up on an instance that was
never unrecoverable. So the export is given up too, over a new node-addressed
request that tears it down exactly as the fence does. Deliberately not an unmount
— an unmount seals, this node's block map is the stale one, and sealing publishes
it over the winner's. Unlike the fence it deletes the lease key rather than
leaving it to expire, because the lease is still this node's to hand back.

The tap outlives the guest, and the tap is what claims the instance's OVN logical
port. The binding names one chassis, so two nodes offering the same iface-id do
not split the traffic — they contend, and the address answers from whichever won
last. It also blocks the layer above: the external IP's host ingress is pruned on
the evidence that the owning guest sits on another chassis, and that stays false
while this node is still claiming the port.

The management address outlives the guest as a cluster-wide reservation, and the
release was unconditional. br-mgmt is one flat L2 segment, so the node an instance
left was freeing an address still in use and offering it to the next instance
anywhere. Only the node an entry names may release it now, with the takeover
recorded on arrival so the node actually running the instance can still give the
address back. An entry written before the node field existed names nobody and
stays releasable, because there is no other holder to collide with.

The fence path already cleaned up the tap, so the release fix repairs that path
too.

* test: prove a load balancer keeps its name, its address and its traffic when its host dies

Takes away the node running an internet-facing ALB and asserts the four things a
customer of one actually holds: the name keeps resolving, the address behind it
does not move, requests through the name are answered again without anybody being
called, and the backends are healthy again from the recovered load balancer's
point of view.

The backends are placed around the load balancer rather than beside it. A load
balancer lands wherever a node answers its queue group, so its node is discovered
and the backends are relaunched until both are elsewhere; one on the node about to
be taken away would be recovered too, and the run could not then tell an ALB that
came back serving from one that came back with nothing to serve.

DNS is asked of a node's own northstar over the wire, and the HTTP probes resolve
through the same server, so the claim under test is what this cluster answers for
a name rather than what the machine running the tests was configured to forward
to. A watch samples every surviving node every five seconds for the whole run,
because an answer that went missing or pointed elsewhere for one reconcile pass is
the outage, and no single sample reaches it.

The returning node then has to give up what it no longer owns: no second copy of
the guest, and no tap still claiming the load balancer's logical port, since OVN
binds a port to one chassis and a second claimant contends for it rather than
splitting the traffic. The last assertion is that the name still serves with that
node back in the cluster.

* docs: name the new cell in the nightly's cell list

* test: stop the disk-load guest from filling the console it is judged by

The load generator announced every write, once a second, for as long as the
test ran. The console is a ring buffer this suite reads back, so an hour of
that pushes out everything explaining a failure, including the kernel's own
account of the I/O error the test exists to produce. Announce twenty times,
then keep writing quietly.

* docs: say what the OCI guide has been proven on, and what a host failure does

The guide read as a support statement for OCI rather than as an account of one
tested path, promised seven steps and then gave eight, and said nothing about
what happens to a guest or its public address when the node under it fails.
State the evidence, state that the nightly guards the datapath and not the
cloud, and give the failure behaviour as a table with the reason codes a
customer will actually see.

Also say plainly what the volume lease is: one running guest and a bounded,
logged window, not a write barrier the object store enforces. Someone sizing a
workload against this should read that before they read the table.

* docs: say why the mount classifier refuses to retry a lease another node holds

It reads as an omission — a lease held elsewhere is the most transient refusal
there is. It is not. This classifier drives the restore path, where the holder
is a node that is running the guest, so retrying would relaunch against a live
owner. Recovery wants the opposite and reads the refusal itself.

* feat: claim a recovered guest's public address in line, and verify it arrived

A recovered instance was reported running before anything moved its public
address off the node that died, so for up to fifteen seconds the records said
recovered and the address answered nothing. The recovery path now runs the
affinity pass itself, which is idempotent and is the same pass the ticker runs.

Two things the pass could not do before. It abandoned every remaining address
on the first API failure, though a throttle or a denial is per-object and the
guests behind the others are just as dark. And it trusted the move's own
response, which is OCI agreeing to the request rather than OCI having done it,
so an accepted move that never landed read as success. It now re-reads what OCI
delivers here and reports the difference.

An address that will not arrive makes the guest a system-status failure with the
time it went dark, the same shape AWS uses for a host-level fault. The guest
passes every check it can be asked about itself, which is exactly why reporting
it healthy was the worst available answer.

* feat: give a recovery attempt one trace across all three of its phases

The volumes opening, QEMU starting and its monitor answering already trace
themselves, but nothing tied them to the attempt that asked for them: three
orphan traces per recovery, no way to ask which phase a slow one spent its time
in, and nothing naming the node the guest came from. A span over the attempt
makes them its children, and the reconciler's own log lines carry its trace ID
because the handler stamps it from the context.

A failed attempt records the fault and the attempt count on the span, so the
budget running out is readable as a sequence rather than as twelve unrelated
warnings.

* fix: finish a fence once its writer finally exits

A kill that did not take effect was logged, counted and dropped. The export
stayed registered and the lease stayed held, which is correct while the writer
lives and wrong forever after it dies: a lease a healthy node keeps renewing
never expires, so the volume could not start anywhere.

The failure is now re-reported every 30 s until it resolves, and the teardown
completes as soon as the writer is confirmed gone. Only a delivered kill is
waited on — a refused one says nothing about what became of the writer.

* test: stop judging a detached stop or terminate on a transient state

Both tests read the instance state immediately after the ack, but the transition
runs on its own goroutine, so the read races it in both directions: too early
sees running, too late sees the final state. The race gate caught the first of
those on a loaded runner.

* fix: replicate the volume lease and dirty buckets across the cluster

Both were created with the default single replica, so both lived on one node.
That node holds the answer to "who may write this volume" and the marker every
mount reads, and losing it takes volume leasing and mounting down cluster-wide.
A partitioned node was fenced correctly and then no survivor could relaunch its
guest: every attempt failed on "read dirty mark: no responders available", for
ten minutes, until the budget ran out.

The replica count is now the cluster's node count, as the gateway's own buckets
already do. Existing buckets are raised in place rather than requiring a wipe.

The e2e diagnostics that should have said this are fixed too. The fence and the
surrender are logged by the storage service, not the daemon, so the assertions
read the wrong journal; and Eventuallyf evaluates its message at the call site,
so a ten-minute wait was explained by a log that stopped before it began.
2026-09-27 15:56:09 -05:00

492 lines
21 KiB
Go

//go:build e2e
package instancerecovery
import (
"context"
"encoding/base64"
"fmt"
"strings"
"sync"
"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 (
// recoveryJournalThisRun reads the daemon's log for its current invocation
// only. Scoping it that way is what lets a line logged once at startup be
// found on a daemon that has been up for days.
recoveryJournalThisRun = `sudo journalctl --no-pager ` +
`_SYSTEMD_INVOCATION_ID="$(systemctl show -p InvocationID --value spinifex-daemon)"`
// The same for the storage service. The lease, the surrender and the fence
// are its work: the daemon only hears the announcement afterwards, so its
// journal carries the consequence and never the reason.
recoveryStorageJournalThisRun = `sudo journalctl --no-pager ` +
`_SYSTEMD_INVOCATION_ID="$(systemctl show -p InvocationID --value spinifex-viperblock)"`
// The owner has to be seen stale across two passes before anything is
// claimed, then the volume leases have to expire before the launch can open
// them. That is roughly a minute of unavoidable waiting before the first
// attempt can succeed, and a boot on top of it.
recoveryBudget = 8 * time.Minute
// How long the guest is given to notice its storage has gone and pause.
// Generous because nothing about it is prompt: viperblock serves what it
// has cached, nbdkit waits out its reconnect delay, and only then does the
// error reach QEMU. Measured at 4m47s on a three-node cluster.
recoveryPauseBudget = 10 * time.Minute
// How long the guest is given to boot, run cloud-init, and announce that its
// first write landed. The announcement is the premise of the whole test, so
// this is generous and failing it is a hard error rather than a skip.
recoveryDiskLoadBudget = 6 * time.Minute
// diskLoadMarker is printed to the serial console by the load driver once a
// full 32 MiB pass has been written and synced, so it is proof the guest is
// driving its root volume rather than a claim that it was asked to.
diskLoadMarker = "spx-e2e-diskload: writing"
// diskLoadUserData starts a guest writing to its root volume and never
// stopping. An idle guest issues no I/O that reaches the object store, so
// freezing the store leaves it running and this test proves nothing;
// measured on a real cluster, an idle guest never paused at all.
//
// It is cloud-init rather than SSH into the guest on purpose: routed-NAT
// clusters give guests no public address, so a test that needed to log in
// could not run on half the cells. The console is readable the same way, by
// the API, so the marker travels the same path.
//
// The writing never stops and the announcing does. The console is a ring the
// whole test reads back, and a line a second for an hour pushes everything
// that explains a failure out of it — including the kernel's own account of
// the I/O error this test exists to produce.
diskLoadUserData = `#!/bin/bash
cat > /usr/local/sbin/spx-e2e-diskload <<'EOF'
#!/bin/bash
announce=20
while true; do
dd if=/dev/urandom of=/var/tmp/spx-e2e-load bs=1M count=32 oflag=direct conv=fsync 2>/dev/null
sync
if [ "$announce" -gt 0 ]; then
echo "spx-e2e-diskload: writing" > /dev/console
announce=$((announce - 1))
[ "$announce" -eq 0 ] && echo "spx-e2e-diskload: still writing, quietly from here" > /dev/console
fi
sleep 1
done
EOF
chmod +x /usr/local/sbin/spx-e2e-diskload
systemd-run --unit=spx-e2e-diskload /usr/local/sbin/spx-e2e-diskload
`
)
// runInstanceAutoRecovery proves a guest on a node that stops answering comes
// back on a survivor with no operator action.
//
// This is the one behaviour the feature exists for, and the only honest way to
// assert it is to look for the qemu process on the other nodes: the API
// reporting an instance running says where the records think it is, not where
// it is.
func runInstanceAutoRecovery(t *testing.T, fix *Fixture) {
harness.Phase(t, "Instance Auto-Recovery")
recoveryWaitActive(t, fix)
victim, instanceID := recoveryGuestOnAPeer(t, fix, "")
harness.Detail(t, "victim_node", victim.Name)
harness.Detail(t, "instance", instanceID)
cli := harness.AWSClientForGateway(t, fix.Env, fix.Cluster.Nodes[0])
healthy := recoveryRequireStatus(t, cli, instanceID, func(s harness.InstanceStatusSummary) bool {
return s.State == "running" && s.SystemStatus == "ok"
}, 3*time.Minute, "state=running with system-status=ok before anything is broken")
harness.Step(t, "stop the spinifex services on %s — the guest keeps running, nothing drains it", victim.Name)
harness.StopNode(t, victim)
t.Cleanup(func() { harness.StartNode(t, victim) })
fix.Cluster.WaitNATSPeers(t, 1, harness.WithTimeout(60*time.Second),
harness.WithPoll(2*time.Second), harness.WithSkipNodes(victim.Name))
// The AWS-visible half of a host failure, and the reason this is asserted
// before the recovery rather than after it: the window is real and bounded —
// it opens when the owner's heartbeat goes stale, which is strictly before any
// survivor may claim, and closes when the relaunch registers. A customer
// watching DescribeInstanceStatus is told the host is impaired, which is what
// AWS reports for exactly this fault and is all AWS ever discloses about a
// host. Reporting ok throughout would be the more comfortable lie.
recoveryRequireStatus(t, cli, instanceID, func(s harness.InstanceStatusSummary) bool {
return s.SystemStatus == "impaired" || s.SystemStatus == "insufficient-data"
}, 4*time.Minute, "system-status=impaired while its host is gone")
harness.Step(t, "wait for a survivor to claim and relaunch %s", instanceID)
var hosting []harness.Node
require.Eventuallyf(t, func() bool {
hosting = harness.InstanceHostingNodes(t, fix.Cluster, instanceID, []string{victim.Name})
return len(hosting) > 0
}, recoveryBudget, 15*time.Second,
"%s never came back on a survivor after %s stopped answering\n%s",
instanceID, victim.Name, lazyWhy(func() string { return recoveryWhy(t, fix, victim, instanceID) }))
require.Lenf(t, hosting, 1, "%s is running on more than one survivor: %v",
instanceID, recoveryNodeNames(hosting))
harness.Detail(t, "recovered_onto", hosting[0].Name)
harness.Step(t, "the gateway agrees the instance is running and names the new owner")
harness.WaitForInstanceState(t, cli, instanceID, "running")
// The other half of the parity, and the part that says the move finished
// rather than merely started. AWS never discloses which host an instance is
// on, so the customer-visible evidence that it moved is that the impairment
// ended while the instance kept running — and that the AZ did not change,
// because a recovery that crossed one would break every placement promise
// made to the customer.
recovered := recoveryRequireStatus(t, cli, instanceID, func(s harness.InstanceStatusSummary) bool {
return s.State == "running" && s.SystemStatus == "ok" && s.InstanceStatus != "impaired"
}, 5*time.Minute, "system-status back to ok on the survivor, with the instance still running")
assert.Equalf(t, healthy.AZ, recovered.AZ,
"%s came back in %s having been launched in %s; a recovery must not move an instance between availability zones",
instanceID, recovered.AZ, healthy.AZ)
harness.Step(t, "bring %s back and assert it does not relaunch what moved", victim.Name)
harness.StartNode(t, victim)
harness.WaitNodeServiceReady(t, victim, harness.WithTimeout(3*time.Minute))
fix.Cluster.WaitNATSPeers(t, 2, harness.WithTimeout(2*time.Minute), harness.WithPoll(2*time.Second))
// Give the returning node long enough to have got it wrong. Its restore runs
// early in startup, so a second copy would already be visible here.
time.Sleep(60 * time.Second)
after := harness.InstanceHostingNodes(t, fix.Cluster, instanceID, nil)
require.Lenf(t, after, 1,
"%s is running on %v after %s returned; a returning node must drop a local copy the records say moved",
instanceID, recoveryNodeNames(after), victim.Name)
assert.NotEqualf(t, victim.Name, after[0].Name,
"%s went back to %s, so the returning node relaunched it rather than forgetting it",
instanceID, victim.Name)
}
// runInstanceRecoveryRefusesStorageFault proves the opposite behaviour, and it
// is the one a reconciler that cannot tell its faults apart gets wrong.
//
// A guest whose object store has stopped answering is paused by werror=stop
// with its failed request held. Moving it relaunches it somewhere that will
// refuse it identically, having thrown away its RAM on the way. So nothing must
// move, and when the store comes back the guest must resume where it was.
func runInstanceRecoveryRefusesStorageFault(t *testing.T, fix *Fixture) {
harness.Phase(t, "Recovery Refuses a Storage Fault")
recoveryWaitActive(t, fix)
victim, instanceID := recoveryGuestOnAPeer(t, fix, diskLoadUserData)
harness.Detail(t, "victim_node", victim.Name)
harness.Detail(t, "instance", instanceID)
recoveryWaitForDiskLoad(t, fix, instanceID)
harness.Step(t, "freeze predastore on every node — the store is now broken cluster-wide")
restore := recoveryFreezeStore(t, fix)
harness.Step(t, "wait for %s to pause on its storage and publish that it did", instanceID)
require.Eventuallyf(t, func() bool {
return recoveryGuestIsPaused(t, victim, instanceID)
}, recoveryPauseBudget, 10*time.Second,
"%s never paused on io-error, so this run proves nothing about a storage fault", instanceID)
harness.Step(t, "stop the spinifex services on %s, leaving a stale owner and a broken store", victim.Name)
harness.StopNode(t, victim)
t.Cleanup(func() { harness.StartNode(t, victim) })
fix.Cluster.WaitNATSPeers(t, 1, harness.WithTimeout(60*time.Second),
harness.WithPoll(2*time.Second), harness.WithSkipNodes(victim.Name))
// Long enough that a reconciler which was going to move it would have. Two
// stale passes plus a lease TTL is about a minute; this is four.
harness.Step(t, "hold for %s and assert no survivor claims it", 4*time.Minute)
deadline := time.Now().Add(4 * time.Minute)
for time.Now().Before(deadline) {
hosting := harness.InstanceHostingNodes(t, fix.Cluster, instanceID, []string{victim.Name})
require.Emptyf(t, hosting,
"%s was relaunched on %v while the object store was refusing every node; "+
"moving a guest cannot fix a store that is broken everywhere, and it costs the guest its held request",
instanceID, recoveryNodeNames(hosting))
time.Sleep(20 * time.Second)
}
harness.Step(t, "bring the store back and assert the guest resumes rather than having moved")
restore()
harness.StartNode(t, victim)
harness.WaitNodeServiceReady(t, victim, harness.WithTimeout(3*time.Minute))
fix.Cluster.WaitNATSPeers(t, 2, harness.WithTimeout(2*time.Minute), harness.WithPoll(2*time.Second))
cli := harness.AWSClientForGateway(t, fix.Env, fix.Cluster.Nodes[0])
harness.WaitForInstanceState(t, cli, instanceID, "running")
require.Eventuallyf(t, func() bool {
return len(harness.InstanceHostingNodes(t, fix.Cluster, instanceID, nil)) == 1
}, 3*time.Minute, 15*time.Second,
"%s is not running on exactly one node once the store returned", instanceID)
}
// recoveryWaitActive waits until every node has recovery running, and nothing
// here turns it on: there is no setting to turn on.
//
// That absence is the assertion. A cluster installed by the ordinary path has
// recovery active on every node with no config written and no daemon restarted,
// so a build that reintroduced a switch would fail here rather than quietly
// leaving a dead node's guests down.
//
// Every node, not just the survivors, because any of them may be the one that
// claims. The reconciler is also inert until it has seen every peer live, so a
// run that started measuring before that would be measuring the settle window.
func recoveryWaitActive(t *testing.T, fix *Fixture) {
t.Helper()
harness.Step(t, "wait for all %d nodes to report recovery active, with no config written", len(fix.Cluster.Nodes))
for _, node := range fix.Cluster.Nodes {
n := node
require.Eventuallyf(t, func() bool {
out, err := recoveryRunErr(n, recoveryJournalThisRun)
return err == nil && strings.Contains(out, "recovery has seen every peer live")
}, 6*time.Minute, 5*time.Second,
"%s never reported recovery active, so either the settle window has not passed "+
"or recovery is off on a cluster nothing configured — and nothing below would be a test of it", n.Name)
}
}
// recoveryFreezeStore SIGSTOPs predastore on every node and returns the thaw,
// which is also registered as a cleanup so a failure anywhere restores it.
//
// SIGSTOP rather than stopping the unit, for the reason the storagefault suite
// gives: a stopped process holds its connections open and answers nothing,
// which is the outage that defeats code with no timeout. A clean stop refuses
// connections instead and is a different fault.
func recoveryFreezeStore(t *testing.T, fix *Fixture) func() {
t.Helper()
// Best effort per node, and never fatal. The thaw runs after a node has been
// taken away, where there is no process to signal — and a node it cannot
// reach must not stop it restoring the others, which is how a failure here
// would leave the cluster frozen for every test after it.
signal := func(sig string) {
for _, node := range fix.Cluster.Nodes {
if _, err := recoveryRunErr(node,
"PID=$(systemctl show spinifex-predastore -p MainPID --value); "+
"if [ \"$PID\" != 0 ]; then sudo kill -"+sig+" \"$PID\"; fi"); err != nil {
t.Logf("predastore %s on %s: %v", sig, node.Name, err)
}
}
}
var once sync.Once
thaw := func() { once.Do(func() { signal("CONT") }) }
t.Cleanup(thaw)
signal("STOP")
return thaw
}
// recoveryGuestOnAPeer launches guests until one lands on a node other than the
// first, and returns that node and instance. A non-empty userData is delivered
// to cloud-init.
//
// Not the first node: it is the operator gateway every assertion here is made
// through, and taking it down would remove the means of observing the result
// rather than test anything.
func recoveryGuestOnAPeer(t *testing.T, fix *Fixture, userData string) (harness.Node, string) {
t.Helper()
instType, arch := harness.DiscoverNanoInstanceType(t, fix.Harness)
amiID := harness.DiscoverUbuntuAMI(t, fix.Harness, arch)
keyName, _ := harness.EnsureKeyPair(t, fix.Harness)
def := harness.EnsureDefaultVPC(t, fix.Harness)
require.NotEmpty(t, def.SGID, "default SG required")
in := &ec2.RunInstancesInput{
ImageId: aws.String(amiID),
InstanceType: aws.String(instType),
KeyName: aws.String(keyName),
SubnetId: aws.String(def.SubnetID),
SecurityGroupIds: []*string{aws.String(def.SGID)},
MinCount: aws.Int64(1),
MaxCount: aws.Int64(1),
}
if userData != "" {
in.UserData = aws.String(base64.StdEncoding.EncodeToString([]byte(userData)))
}
for attempt := 1; attempt <= 6; attempt++ {
// A shared fixture cannot serve this: the guest has to be on a named node
// so that node can be taken away, and losing it is what is under test.
// e2e:allow-create
out, err := fix.AWS.EC2.RunInstances(in)
if err != nil {
if strings.Contains(err.Error(), "InsufficientInstanceCapacity") {
time.Sleep(10 * time.Second)
continue
}
t.Fatalf("launch a guest to recover: %v", err)
}
require.NotEmpty(t, out.Instances, "RunInstances returned no instance")
id := aws.StringValue(out.Instances[0].InstanceId)
t.Cleanup(func() {
_, _ = fix.AWS.EC2.TerminateInstances(&ec2.TerminateInstancesInput{
InstanceIds: []*string{aws.String(id)},
})
})
harness.WaitForInstanceState(t, fix.AWS, id, "running")
host := harness.InstanceHostingNode(t, fix.Cluster, id)
require.NotNilf(t, host, "%s is running but no node is hosting its qemu", id)
if host.Name != fix.Cluster.Nodes[0].Name {
return *host, id
}
t.Logf("recoveryGuestOnAPeer: %s landed on the gateway node, launching another", id)
}
t.Fatalf("no guest landed on a node other than %s in six attempts", fix.Cluster.Nodes[0].Name)
return harness.Node{}, ""
}
// recoveryWaitForDiskLoad blocks until the guest says on its console that it has
// written and synced a pass to its root volume.
//
// This is the test's own premise, and a run that froze the store before it was
// true proved nothing while reporting a product failure: the guest was still in
// UEFI, so the only thing the frozen store could reach was the EFI varstore, and
// pflash has no werror=stop to pause on. So a guest that never says it is
// writing fails here, where the message names the real problem.
func recoveryWaitForDiskLoad(t *testing.T, fix *Fixture, instanceID string) {
t.Helper()
harness.Step(t, "wait for %s to boot and start driving its root volume", instanceID)
var last string
require.Eventuallyf(t, func() bool {
console, err := harness.InstanceConsole(fix.AWS, instanceID)
if err != nil {
return false
}
last = console
return strings.Contains(console, diskLoadMarker)
}, recoveryDiskLoadBudget, 10*time.Second,
"%s never reported %q on its console, so its load driver never wrote to the root volume "+
"and freezing the store would prove nothing\nconsole tail:\n%s",
instanceID, diskLoadMarker, recoveryTail(last, 2000))
}
// recoveryTail returns the last n bytes of s, for a failure message that needs
// the end of a console rather than all of it.
func recoveryTail(s string, n int) string {
if len(s) <= n {
return s
}
return s[len(s)-n:]
}
// recoveryGuestIsPaused reports whether the node's daemon has seen this guest
// pause on an I/O error, which is what a broken object store looks like from
// the control plane. BLOCK_IO_ERROR is the QMP event and the other is the
// daemon's own line; either is the pause, and it stamps Health.IOErrorSince.
func recoveryGuestIsPaused(t *testing.T, node harness.Node, instanceID string) bool {
t.Helper()
out, err := recoveryRunErr(node,
"sudo journalctl -u spinifex-daemon --no-pager -n 2000 | grep -F "+harness.ShellQuote(instanceID))
if err != nil {
return false
}
return strings.Contains(out, "BLOCK_IO_ERROR") ||
strings.Contains(out, "Guest paused on a backend I/O error")
}
// recoveryWhy gathers what decides a recovery, for a failure message that does
// not send the reader to three journals to find out which step did not happen.
func recoveryWhy(t *testing.T, fix *Fixture, victim harness.Node, instanceID string) string {
t.Helper()
var b strings.Builder
for _, node := range fix.Cluster.Nodes {
if node.Name == victim.Name {
continue
}
for label, query := range map[string]string{
"recovery log": recoveryJournalThisRun + " | grep -iE 'recovery|claim|stopped heartbeating' | tail -20",
// A claim that succeeds and then cannot mount fails in the storage
// service, and the daemon records only that the attempt did not
// complete. Without this the reason is not in the failure at all.
"storage log": recoveryStorageJournalThisRun + " | grep -iE 'lease|dirty|mount' | tail -20",
} {
out, err := recoveryRunErr(node, query)
if err != nil {
out = "(" + err.Error() + ")"
}
fmt.Fprintf(&b, " %s %s:\n%s\n", node.Name, label, strings.TrimSpace(out))
}
}
return b.String()
}
// lazyWhy defers a diagnostic until the assertion formats it. require.Eventuallyf
// evaluates its message arguments at the call site, so a diagnostic passed
// directly describes the moment the wait began and never the failure — which is
// how a ten-minute wait came to be explained by a log that stopped before it.
type lazyWhy func() string
func (f lazyWhy) String() string { return f() }
func recoveryNodeNames(nodes []harness.Node) []string {
names := make([]string, 0, len(nodes))
for _, n := range nodes {
names = append(names, n.Name)
}
return names
}
func recoveryRun(t *testing.T, node harness.Node, cmd string) string {
t.Helper()
out, err := recoveryRunErr(node, cmd)
require.NoErrorf(t, err, "%s on %s: %s", cmd, node.Name, out)
return out
}
func recoveryRunErr(node harness.Node, cmd string) (string, error) {
ctx, cancel := context.WithTimeout(context.Background(), 90*time.Second)
defer cancel()
out, err := harness.NewPeerSSH().Run(ctx, node.Addr, cmd)
return string(out), err
}
// recoveryRequireStatus polls DescribeInstanceStatus until want is satisfied and
// returns the frame that satisfied it, failing the test with the last frame seen.
//
// The last frame is the whole value of this over a bare Eventually: "the status
// never became impaired" is not a finding on its own, and "it stayed ok while
// its host was gone" is.
func recoveryRequireStatus(t *testing.T, cli *harness.AWSClient, instanceID string,
want func(harness.InstanceStatusSummary) bool, budget time.Duration, describe string,
) harness.InstanceStatusSummary {
t.Helper()
harness.Step(t, "require %s reports %s", instanceID, describe)
var last harness.InstanceStatusSummary
var lastErr error
missing := false
require.Eventuallyf(t, func() bool {
summary, ok, err := harness.InstanceStatus(cli, instanceID)
lastErr, missing = err, !ok && err == nil
if err != nil || !ok {
return false
}
last = summary
return want(summary)
}, budget, 3*time.Second,
"%s never reported %s\nlast frame: %s\nabsent from the answer: %v\nlast error: %v",
instanceID, describe, last, missing, lastErr)
harness.Detail(t, "instance_status", last.String())
return last
}