diff --git a/spinifex/daemon/instance_membership.go b/spinifex/daemon/instance_membership.go index d7460a08b..b2d2561f7 100644 --- a/spinifex/daemon/instance_membership.go +++ b/spinifex/daemon/instance_membership.go @@ -44,6 +44,10 @@ func runsOn(record *vm.InstanceRecord, nodeID string) bool { // drained for maintenance leaves them observed-stopped but still wanted — both // are recoveries. What is excluded is an instance nobody wants running: an // operator stop, or a terminate already under way. +// +// A fenced instance is excluded for the same reason the restore path excludes +// it. The fence does not seal, so no node can show the volumes are mountable, +// and taking it over is how an unproven state becomes a destroyed one. func recoverable(record *vm.InstanceRecord) bool { if record == nil || record.Spec.DesiredState != vm.DesiredRunning { return false @@ -55,6 +59,9 @@ func recoverable(record *vm.InstanceRecord) bool { case vm.StateTerminated, vm.StateShuttingDown: return false } + if vm.VolumeFenced(record.Status.Instance) { + return false + } return !storageFaulted(record) } diff --git a/spinifex/daemon/instance_recovery_test.go b/spinifex/daemon/instance_recovery_test.go index 621307509..e81f95917 100644 --- a/spinifex/daemon/instance_recovery_test.go +++ b/spinifex/daemon/instance_recovery_test.go @@ -15,6 +15,8 @@ import ( "testing" "time" + "github.com/aws/aws-sdk-go/aws" + "github.com/aws/aws-sdk-go/service/ec2" "github.com/mulgadc/spinifex/spinifex/awserrors" "github.com/mulgadc/spinifex/spinifex/config" handlers_ec2_instance "github.com/mulgadc/spinifex/spinifex/handlers/ec2/instance" @@ -149,6 +151,33 @@ func TestAnInstancePausedOnItsStorageIsNotMoved(t *testing.T) { "only the guest whose storage was answering is worth moving") } +// A fenced guest is the case the storage-fault guard does not catch: the fence +// kills the export rather than pausing the guest, so it publishes no I/O error +// and reads as an ordinary desired-running instance on a node that has died. +func TestAFencedInstanceIsNotMoved(t *testing.T) { + fenced := runningOn("i-fenced", "node-1") + fenced.Status.Status = vm.StateError + fenced.Status.Instance = &ec2.Instance{StateReason: &ec2.StateReason{ + Code: aws.String("Server.VolumeFenced"), + Message: aws.String("the lease moved while this node had it open"), + }} + + // Errored for a reason that is not a fence, which is what the exclusion has + // to be narrower than: a launch that failed is still worth another node. + failed := runningOn("i-failed", "node-1") + failed.Status.Status = vm.StateError + failed.Status.Instance = &ec2.Instance{StateReason: &ec2.StateReason{ + Code: aws.String("Server.RecoveryFailed"), + }} + + r := recoveryFixture("node-2") + got := twice(r, []*vm.InstanceRecord{fenced, failed}, stale) + + require.Len(t, got, 1) + assert.Equal(t, "i-failed", got[0].record.Metadata.Name, + "a fenced guest's volumes were never sealed, so moving it is how an unproven state becomes a destroyed one") +} + // A guest that had recovered from an earlier pause is an ordinary candidate. // IOErrorSince clears on the first running poll, so a non-zero value means the // storage was still failing when the owner last wrote. diff --git a/spinifex/services/viperblockd/volume_lease.go b/spinifex/services/viperblockd/volume_lease.go index dc50fd242..3166fdcee 100644 --- a/spinifex/services/viperblockd/volume_lease.go +++ b/spinifex/services/viperblockd/volume_lease.go @@ -56,20 +56,39 @@ func leaseStoreUnavailable(err error) bool { // until the entry ages out. const volumeLeaseTTL = 45 * time.Second -// volumeLeaseRenewInterval keeps a live holder's entry young. Well inside the -// TTL so one missed renewal does not surrender the lease. -const volumeLeaseRenewInterval = 15 * time.Second +// volumeLeaseRenewInterval keeps a live holder's entry young. It also bounds +// how stale a confirmation can be when an outage starts, which is subtracted +// from validity to give the outage this lease survives. +const volumeLeaseRenewInterval = 10 * time.Second -// volumeLeaseRenewTimeout bounds one renewal attempt. Without it a JetStream -// call that hangs holds the renewal goroutine past the point where the server -// has already given the entry away, and the holder never notices. -const volumeLeaseRenewTimeout = 5 * time.Second +// volumeLeaseRenewTimeout bounds one renewal attempt, and is set above +// deviceStallBound so a renewal that begins inside a stall can still be +// answered once the stall clears instead of being certain to fail. +const volumeLeaseRenewTimeout = 12 * time.Second // volumeLeaseValidity is how long a holder may keep writing after its last -// *confirmed* renewal. Set below volumeLeaseTTL on purpose: a server-side TTL -// is not a lease unless the holder stops before the server may re-grant, so the -// difference is the margin covering scheduling delay and request latency. -const volumeLeaseValidity = 30 * time.Second +// *confirmed* renewal. Set volumeLeaseAcquireMargin below volumeLeaseTTL: a +// server-side TTL is not a lease unless the holder stops before the re-grant. +const volumeLeaseValidity = 40 * time.Second + +// volumeLeaseAcquireMargin is the gap left between validity and the server TTL. +// It covers scheduling delay and request latency on this side, and the entry +// still has to age out before a peer can claim it. +const volumeLeaseAcquireMargin = 5 * time.Second + +// deviceStallBound is the longest one stalled I/O lasts under JetStream, from +// nvme_core.io_timeout on the hosts we run. Measured as a late completion and +// never a controller reset, so a renewal that waits one out is answered. +const deviceStallBound = 10 * time.Second + +// jetstreamOutageBound is the longest window of unwritable JetStream observed +// on those hosts, and the quantity the lease actually has to survive: several +// sequential writes each waiting out deviceStallBound, not one stall. +// +// Both are properties of the hosts rather than settings of ours, so neither is +// applied anywhere — they are asserted against, which is what fails the build +// when the sizing above stops covering what the storage does. +const jetstreamOutageBound = 30 * time.Second // volumeLeaseCheckInterval is how often validity is tested. Shorter than the // renewal interval so a lapsed holder is fenced on its own schedule rather than @@ -182,6 +201,11 @@ type volumeLease struct { // refs counts opens on this node sharing the lease. The lease is released // when the last one lets go. refs int + // failures counts renewals that have failed in a row, and failingSince is + // when the run started. They exist to measure the outage: a surrender + // always reports validity, so only a recovery can report a real length. + failures int + failingSince time.Time } // acquire claims volumeName for this node, or reports who has it. Repeat @@ -344,26 +368,45 @@ func (l *volumeLeases) release(ctx context.Context, lease *volumeLease) { // first indefinitely while the server hands the entry to somebody else, and // only the second stops it. func (lease *volumeLease) renewLoop(ctx context.Context) { - defer close(lease.done) - ticker := time.NewTicker(volumeLeaseCheckInterval) defer ticker.Stop() + // The renewal runs on its own goroutine so a JetStream call that blocks for + // its whole timeout cannot delay the validity check. Waiting for it before + // closing done leaves release reading a settled revision. + var renewing sync.WaitGroup + defer func() { + renewing.Wait() + close(lease.done) + }() + + // Buffered, so a renewal that finishes after the loop has gone still sends + // its answer and exits rather than leaking on an unread channel. One slot is + // enough because only one renewal is ever in flight. + outcome := make(chan bool, 1) + inFlight := false + for { select { case <-ctx.Done(): return + case stillOurs := <-outcome: + inFlight = false + if !stillOurs { + return + } case <-ticker.C: if lease.expiredLocally() { lease.surrender(ctx) return } - if time.Since(lease.lastConfirmed()) < volumeLeaseRenewInterval { + if inFlight || time.Since(lease.lastConfirmed()) < volumeLeaseRenewInterval { continue } - if !lease.renew(ctx) { - return - } + inFlight = true + renewing.Go(func() { + outcome <- lease.renew(ctx) + }) } } } @@ -388,11 +431,20 @@ func (lease *volumeLease) surrender(ctx context.Context) { lease.mu.Lock() lease.lost = true since := time.Since(lease.confirmed) + attempts := lease.failures + failingFor := time.Duration(0) + if attempts > 0 { + failingFor = time.Since(lease.failingSince) + } lease.mu.Unlock() + // unconfirmed_for_ms is pinned at validity by construction, so it cannot + // report how long the store was unwritable. failing_for_ms is the part that + // was observed, and it is a lower bound: the outage outlived the lease. slog.Error("volume lease could not be confirmed before its TTL, surrendering the volume", "volume", lease.volume, "generation", lease.generation, - "unconfirmed_for_ms", otelsetup.Millis(since), "ttl_ms", otelsetup.Millis(volumeLeaseTTL)) + "unconfirmed_for_ms", otelsetup.Millis(since), "ttl_ms", otelsetup.Millis(volumeLeaseTTL), + "attempts", attempts, "failing_for_ms", otelsetup.Millis(failingFor)) if onLost := lease.leases.onLost; onLost != nil { go onLost(context.WithoutCancel(ctx), lease.volume, leaseLostStalled) @@ -428,7 +480,13 @@ func (lease *volumeLease) renew(ctx context.Context) bool { lease.mu.Lock() lease.revision = renewed lease.confirmed = time.Now() + attempts, outage := lease.failures, time.Since(lease.failingSince) + lease.failures, lease.failingSince = 0, time.Time{} lease.mu.Unlock() + if attempts > 0 { + slog.Warn("volume lease: renewals recovered, so the store was unwritable for this long", + "volume", lease.volume, "attempts", attempts, "outage_ms", otelsetup.Millis(outage)) + } return true case errors.Is(err, context.Canceled): return false @@ -442,7 +500,15 @@ func (lease *volumeLease) renew(ctx context.Context) bool { default: // A transient JetStream error is not a lost lease. Keep renewing; the // TTL is several intervals wide, so there is room to recover. - slog.Warn("volume lease: renewal failed", "volume", lease.volume, "err", err) + lease.mu.Lock() + if lease.failures == 0 { + lease.failingSince = time.Now() + } + lease.failures++ + attempts, failingFor := lease.failures, time.Since(lease.failingSince) + lease.mu.Unlock() + slog.Warn("volume lease: renewal failed", "volume", lease.volume, + "consecutive", attempts, "failing_for_ms", otelsetup.Millis(failingFor), "err", err) return true } } diff --git a/spinifex/services/viperblockd/volume_lease_test.go b/spinifex/services/viperblockd/volume_lease_test.go index 62dc02b8c..b3fbaa302 100644 --- a/spinifex/services/viperblockd/volume_lease_test.go +++ b/spinifex/services/viperblockd/volume_lease_test.go @@ -6,6 +6,7 @@ import ( "errors" "fmt" "os" + "sync" "testing" "time" @@ -446,8 +447,24 @@ func TestVolumeLease_ValidityIsBoundedBelowTheServerTTL(t *testing.T) { "a renewal that comes due after validity lapses can never confirm one in time") require.Less(t, volumeLeaseCheckInterval, volumeLeaseValidity-volumeLeaseRenewInterval, "validity has to be tested at least once between a missed renewal and the deadline it enforces") - require.Less(t, volumeLeaseRenewTimeout, volumeLeaseCheckInterval+volumeLeaseRenewInterval, - "an unbounded renewal holds the goroutine past the point the entry may have been re-granted") + require.Equal(t, volumeLeaseTTL, volumeLeaseValidity+volumeLeaseAcquireMargin, + "the margin between validity and the server TTL is the whole reason a holder stops before its successor starts") +} + +// TestVolumeLease_SurvivesTheOutageTheHostProduces is the sizing this lease is +// for. A confirmation can already be volumeLeaseRenewInterval old when an +// outage begins, so what it survives is validity minus that interval, and that +// has to cover the whole unwritable window rather than one stalled write. +func TestVolumeLease_SurvivesTheOutageTheHostProduces(t *testing.T) { + tolerated := volumeLeaseValidity - volumeLeaseRenewInterval + require.GreaterOrEqual(t, tolerated, jetstreamOutageBound, + "a lease that cannot outlast the outages these hosts produce surrenders volumes no peer has taken") + require.Greater(t, volumeLeaseRenewTimeout, deviceStallBound, + "a renewal budget inside the stall bound is certain to fail whenever it begins during a stall") + require.Less(t, 2*volumeLeaseRenewTimeout, tolerated, + "a renewal and the re-read behind it share this budget, and together they must still fit inside what the lease tolerates") + require.Greater(t, jetstreamOutageBound, deviceStallBound, + "the outage is a run of stalled writes, so sizing against one stall is sizing against the wrong quantity") } // TestVolumeLease_UnconfirmedRenewalSurrendersTheVolume is the partition case @@ -495,6 +512,88 @@ func TestVolumeLease_UnconfirmedRenewalSurrendersTheVolume(t *testing.T) { assert.True(t, lease.lost, "a surrendered lease must be marked lost so release cannot delete the successor's entry") } +// blockingKV holds Update until the test releases it, and reports whether a +// call is in flight. A renewal is the only thing that writes here, so the flag +// says whether the renewal goroutine is still inside JetStream. +type blockingKV struct { + jetstream.KeyValue + + release chan struct{} + + mu sync.Mutex + inFlight bool +} + +func (k *blockingKV) Update(ctx context.Context, _ string, _ []byte, _ uint64) (uint64, error) { + k.mu.Lock() + k.inFlight = true + k.mu.Unlock() + defer func() { + k.mu.Lock() + k.inFlight = false + k.mu.Unlock() + }() + + select { + case <-k.release: + return 0, nil + case <-ctx.Done(): + return 0, ctx.Err() + } +} + +func (k *blockingKV) updateInFlight() bool { + k.mu.Lock() + defer k.mu.Unlock() + return k.inFlight +} + +// TestVolumeLease_ValidityIsEnforcedWhileARenewalIsBlocked is why the renewal +// does not run on the loop's goroutine. A renewal may now block for longer than +// a device stall, and the holder has to stop writing on validity regardless — +// so the surrender has to land while that renewal is still inside JetStream. +// +// Takes volumeLeaseValidity to run, because the clock it asserts is the real +// one. A stall injector that could compress it is Phase 3 of the KV review. +func TestVolumeLease_ValidityIsEnforcedWhileARenewalIsBlocked(t *testing.T) { + _, natsURL := setupEmbeddedNATS(t) + leases := newTestLeases(t, natsURL, "node-a") + + const volumeName = "vol-leaseblockedrenewal" + lost := make(chan leaseLossKind, 1) + leases.onLost = func(_ context.Context, _ string, kind leaseLossKind) { lost <- kind } + + lease, err := leases.acquire(t.Context(), volumeName) + require.NoError(t, err) + + // Stop the loop acquire started so this test owns the only one running, then + // swap in a store that never answers a renewal. + lease.stop() + <-lease.done + + blocking := &blockingKV{KeyValue: leases.kv, release: make(chan struct{})} + t.Cleanup(func() { close(blocking.release) }) + leases.kv = blocking + + // Old enough that a renewal comes due on the next check and validity lapses + // on the one after, so the renewal is in flight when the deadline arrives. + lease.mu.Lock() + lease.confirmed = time.Now().Add(-(volumeLeaseValidity - volumeLeaseCheckInterval - time.Second)) + lease.done = make(chan struct{}) + lease.mu.Unlock() + + go lease.renewLoop(t.Context()) + + select { + case kind := <-lost: + assert.Equal(t, leaseLostStalled, kind, "a blocked renewal is not a peer taking the volume") + assert.True(t, blocking.updateInFlight(), + "the surrender waited for the renewal to return, so validity was enforced late and the guest kept writing past it") + case <-time.After(volumeLeaseValidity + volumeLeaseRenewTimeout): + t.Fatal("validity lapsed and nothing surrendered the volume, so a blocked renewal can hold a lease open indefinitely") + } +} + // TestVolumeLease_SurrenderedLeaseIsNotDeletedOnRelease covers what happens // after. The entry may already belong to another node, so deleting it on the // way out would evict a live holder and hand the volume to a third opener. diff --git a/spinifex/vm/fence.go b/spinifex/vm/fence.go index 833998a46..72ad4a00d 100644 --- a/spinifex/vm/fence.go +++ b/spinifex/vm/fence.go @@ -13,6 +13,21 @@ import ( // recover the guest" from "another node owns this guest's disks now". const fenceStateReasonCode = "Server.VolumeFenced" +// VolumeFenced reports whether this is the record of an instance a fence +// stopped. It reads the projection because that is where the fence writes the +// reason, and both the node's own VM and the cluster record carry one. +// +// It exists to keep a fenced instance out of every automatic relaunch. A fence +// deliberately does not seal, so the volumes it leaves behind are a state +// nothing has proven mountable, and relaunching is how that becomes permanent. +// Restarting one is an operator's decision made against the volumes. +func VolumeFenced(projection *ec2.Instance) bool { + if projection == nil || projection.StateReason == nil { + return false + } + return aws.StringValue(projection.StateReason.Code) == fenceStateReasonCode +} + // FenceVolume stops the guest running against volumeID on this node, because // the volume's lease has moved and this node is no longer its owner. // diff --git a/spinifex/vm/fence_test.go b/spinifex/vm/fence_test.go index b5f220298..165931e09 100644 --- a/spinifex/vm/fence_test.go +++ b/spinifex/vm/fence_test.go @@ -5,7 +5,9 @@ package vm import ( "testing" + "time" + "github.com/aws/aws-sdk-go/aws" "github.com/aws/aws-sdk-go/service/ec2" "github.com/mulgadc/spinifex/spinifex/types" "github.com/stretchr/testify/assert" @@ -101,6 +103,44 @@ func TestFenceVolume_LeavesATerminalInstanceAlone(t *testing.T) { } } +// TestResumeRecoveryFailed_RefusesAFencedInstance is the relaunch a daemon +// start would otherwise perform. The fence does not seal, so the volumes are a +// state nothing has shown is mountable, and relaunching makes that permanent. +func TestResumeRecoveryFailed_RefusesAFencedInstance(t *testing.T) { + m := NewManagerWithDeps(Deps{NodeID: "node-a"}) + instance := vmUsingVolume("i-fenced", "vol-fenced") + m.Insert(instance) + + m.FenceVolume(t.Context(), "vol-fenced", "lease moved to node-b") + m.goroutineWg.Wait() + + // Older than RestartWindow with the budget already spent, which is the state + // a fence days in the past leaves: the window resets and reports a budget, + // so nothing else in this path would refuse the relaunch. + m.Inspect(instance, func(v *VM) { + v.Health.FirstCrashTime = time.Now().Add(-10 * RestartWindow) + v.Health.CrashCount = MaxRestartsInWindow + 1 + }) + + assert.False(t, m.resumeRecoveryFailed(instance)) + assert.Equal(t, StateError, m.Status(instance), + "a refused resume has to leave the instance where the fence left it") +} + +// The refusal has to be narrower than StateError. A recovery that failed for its +// own reasons is what the restart budget exists for, and reading every error as +// a fence would make StateError permanent for all of them. +func TestResumeRecoveryFailed_StillRetriesAnErrorThatIsNotAFence(t *testing.T) { + m := NewManagerWithDeps(Deps{NodeID: "node-a"}) + instance := vmUsingVolume("i-failed", "vol-failed") + instance.Status = StateError + instance.Instance.StateReason = &ec2.StateReason{Code: aws.String("Server.RecoveryFailed")} + m.Insert(instance) + + assert.True(t, m.resumeRecoveryFailed(instance)) + assert.Equal(t, StatePending, m.Status(instance)) +} + // TestInstanceUsingVolume_MatchesOnAnyAttachedVolume covers the lookup. A guest // is fenced for its data disk as readily as its root, so a match on any // attached volume has to count. diff --git a/spinifex/vm/restore.go b/spinifex/vm/restore.go index d26fc444e..7a3d8ba05 100644 --- a/spinifex/vm/restore.go +++ b/spinifex/vm/restore.go @@ -248,7 +248,16 @@ func (m *Manager) classifyRestoredInstances() []*VM { // restore relaunches it, spending one restart from the same window a crash // restart spends. Returns false when the window has run out, which is what // keeps a genuinely broken instance from relaunching on every daemon start. +// +// A fenced instance is refused outright rather than budgeted. The window +// forgives on a clock, so days after a fence it reports a full budget and would +// relaunch a guest against volumes nothing has shown are mountable. func (m *Manager) resumeRecoveryFailed(instance *VM) bool { + if VolumeFenced(instance.Instance) { + slog.Warn("Instance was fenced, so this restore leaves it alone (operator must retry or terminate)", + "instance", instance.ID, "lastNode", instance.LastNode) + return false + } if !rollRestartWindow(instance, time.Now()) { return false }