package console import ( "context" "crypto/rand" "encoding/json" "errors" "fmt" "net/http" "os" "path/filepath" "strings" "sync" "testing" "time" "github.com/carlosframework/platform/internal/alerting" "github.com/carlosframework/platform/internal/hostclaim" "github.com/carlosframework/platform/internal/hostfence" "github.com/carlosframework/platform/internal/hostfloor" "github.com/carlosframework/platform/internal/hostops" "github.com/carlosframework/platform/internal/moves" "github.com/carlosframework/platform/internal/provision" "github.com/carlosframework/platform/internal/release" "github.com/carlosframework/platform/internal/svcrole" ) // The console's move pass (moves Plan 5 Task 7; claim Plan 10's // Recovery.Moves hook under the move-recovery grant). The decision table is // tested on values; every action is then driven end to end through the real // recovery pass (ControlWriter.RecoveryPass over hostops.Recovery.Pass) on a // host-claim console whose move the door started. // ---- the decision, on values ---- var mvT0 = time.Date(2026, 10, 10, 12, 0, 0, 0, time.UTC) func mvClaim(kind, phase string, mut ...func(*hostclaim.Claim)) *hostclaim.Claim { c := &hostclaim.Claim{Holder: &hostclaim.Holder{Incarnation: "inc"}, Op: hostclaim.Op{Kind: kind, Phase: phase, ID: "mv", Exec: "ie-box", Participants: []string{"ie-box", "uk-box"}, StartedAt: mvT0, Intent: map[string]string{"source": "ie-box", "target": "uk-box", "to": "uk"}}} for _, m := range mut { m(c) } return c } func mvRecord(state string, mut ...func(*provision.Record)) provision.Record { at := mvT0 r := provision.Record{Region: "ie", Move: &provision.MoveState{ID: "mv", Incarnation: "inc", From: "ie", To: "uk", State: state, RequestedAt: mvT0}} switch state { case provision.MoveLanding, provision.MoveCommitted: r.Region = "uk" r.Move.FlippedAt = &at } if state == provision.MoveCommitted { r.Move.CommittedAt = &at } if state == provision.MoveRollingBack { r.Move.FlippedAt = &at r.Move.Rollback = &provision.MoveRollback{ID: "rb", TargetPhase: provision.RbTargetReleasing, SourcePhase: provision.RbSourceWaiting} } for _, m := range mut { m(&r) } return r } func mvAt(d time.Duration) *time.Time { t := mvT0.Add(d); return &t } func TestRecoveryPassWritesOnlyDecidedHalves(t *testing.T) { now := mvT0.Add(time.Minute) for _, c := range []struct { name string claim *hostclaim.Claim rec provision.Record action moveRecoveryAction half hostops.MoveRecoveryClaimAction }{ {"record landing, claim moving/sealed: the flip half", mvClaim(hostclaim.KindMoving, hostclaim.PhaseSealed), mvRecord(provision.MoveLanding), moveActClaim, hostops.RecoveryMoveFlip}, {"record committed, claim landing/probed: the commit half", mvClaim(hostclaim.KindLanding, hostclaim.PhaseLandingProbed), mvRecord(provision.MoveCommitted), moveActClaim, hostops.RecoveryMoveCommit}, {"record rolling_back, claim landing: the rollback half", mvClaim(hostclaim.KindLanding, "probing"), mvRecord(provision.MoveRollingBack), moveActClaim, hostops.RecoveryMoveRollback}, {"record rolling_back, claim moving/sealed: RollBackFlipped (K22)", mvClaim(hostclaim.KindMoving, hostclaim.PhaseSealed), mvRecord(provision.MoveRollingBack), moveActClaim, hostops.RecoveryMoveRollback}, {"record landing, claim landing: in step", mvClaim(hostclaim.KindLanding, "probing"), mvRecord(provision.MoveLanding), moveActNone, ""}, {"record cutting, claim moving/sealed: no decision", mvClaim(hostclaim.KindMoving, hostclaim.PhaseSealed), mvRecord(provision.MoveCutting), moveActNone, ""}, {"record committed, claim landing/probing: the claim is behind the probe", mvClaim(hostclaim.KindLanding, "probing"), mvRecord(provision.MoveCommitted), moveActNone, ""}, {"record committed, claim landing/committed, stamps missing", mvClaim(hostclaim.KindLanding, hostclaim.PhaseCommitted), mvRecord(provision.MoveCommitted), moveActNone, ""}, {"record landing without its flip stamp", mvClaim(hostclaim.KindMoving, hostclaim.PhaseSealed), mvRecord(provision.MoveLanding, func(r *provision.Record) { r.Move.FlippedAt = nil }), moveActNone, ""}, {"record rolling_back in the target's region", mvClaim(hostclaim.KindLanding, "probing"), mvRecord(provision.MoveRollingBack, func(r *provision.Record) { r.Region = "uk" }), moveActNone, ""}, {"record preparing, claim moving: nothing yet", mvClaim(hostclaim.KindMoving, hostclaim.PhaseMoving), mvRecord(provision.MovePreparing), moveActNone, ""}, {"another move's record", mvClaim(hostclaim.KindMoving, hostclaim.PhaseSealed), mvRecord(provision.MoveLanding, func(r *provision.Record) { r.Move.ID = "other" }), moveActNone, ""}, {"another incarnation's record", mvClaim(hostclaim.KindMoving, hostclaim.PhaseSealed), mvRecord(provision.MoveLanding, func(r *provision.Record) { r.Move.Incarnation = "old" }), moveActNone, ""}, {"a relocating claim is region HA's", mvClaim(hostclaim.KindRelocating, "pinning"), mvRecord(provision.MoveRelocating), moveActNone, ""}, } { t.Run(c.name, func(t *testing.T) { got := decideMoveRecovery(moveRecoveryInput{Now: now, Claim: c.claim, Rec: c.rec}) if got.Action != c.action || got.Claim != c.half { t.Fatalf("decided %+v, want %s %s", got, c.action, c.half) } }) } } // One eligible action per observation, in the brief's order: a pending // claim half comes before the deadline, the deadline before a close, the // lost target's stamp before the close it enables. func TestRecoveryPassOneActionPerObservation(t *testing.T) { past := mvT0.Add(-time.Hour) // Flip half pending and the landing deadline passed: the half first. d := decideMoveRecovery(moveRecoveryInput{Now: mvT0, Claim: mvClaim(hostclaim.KindMoving, hostclaim.PhaseSealed), Rec: mvRecord(provision.MoveLanding, func(r *provision.Record) { r.Move.LandingDeadline = &past })}) if d.Action != moveActClaim || d.Claim != hostops.RecoveryMoveFlip { t.Fatalf("flip and deadline: %+v", d) } // With the claim in step, the deadline. d = decideMoveRecovery(moveRecoveryInput{Now: mvT0, Claim: mvClaim(hostclaim.KindLanding, "probing"), Rec: mvRecord(provision.MoveLanding, func(r *provision.Record) { r.Move.LandingDeadline = &past })}) if d.Action != moveActRecord || d.Record != hostops.RecoveryMoveDeadlineRollback { t.Fatalf("the deadline: %+v", d) } // The earlier of the cut and landing deadlines (J11). d = decideMoveRecovery(moveRecoveryInput{Now: mvT0, Claim: mvClaim(hostclaim.KindLanding, "probing"), Rec: mvRecord(provision.MoveLanding, func(r *provision.Record) { r.Move.CutDeadline = &past; r.Move.LandingDeadline = mvAt(time.Hour) })}) if d.Action != moveActRecord { t.Fatalf("the cut deadline: %+v", d) } // A lost, released target: the stamp, never the close it enables. lost := func(c *hostclaim.Claim) { c.Lost = []string{"uk-box"}; c.Op.Participants = []string{"ie-box"} } rb := func(r *provision.Record) { r.Move.Rollback.TargetPhase, r.Move.Rollback.SourcePhase = provision.RbTargetReleased, provision.RbSourceOpened r.Move.Rollback.RecoveredAt, r.Move.Rollback.OpenedAt = mvAt(0), mvAt(0) } d = decideMoveRecovery(moveRecoveryInput{Now: mvT0, Claim: mvClaim(hostclaim.KindRestoring, hostclaim.PhaseOpened, lost), Rec: mvRecord(provision.MoveRollingBack, rb)}) if d.Action != moveActStampLost { t.Fatalf("the lost target: %+v", d) } // A chore of the target's region still owed: neither. owed := func(c *hostclaim.Claim) { c.Obligations = []hostclaim.Obligation{{ID: "o", Op: "mv", Kind: "park-replica", Region: "uk", Owner: "region:uk"}} } d = decideMoveRecovery(moveRecoveryInput{Now: mvT0, Claim: mvClaim(hostclaim.KindRestoring, hostclaim.PhaseOpened, lost, owed), Rec: mvRecord(provision.MoveRollingBack, rb)}) if d.Action != moveActNone { t.Fatalf("the lost target with its region's chore owed: %+v", d) } // Every close waits for the op's chores (the grant's rule, M4). stamped := func(r *provision.Record) { r.Move.OpenedAt, r.Move.SourceParkedAt = mvAt(0), mvAt(0) } d = decideMoveRecovery(moveRecoveryInput{Now: mvT0, Claim: mvClaim(hostclaim.KindLanding, hostclaim.PhaseCommitted, owed), Rec: mvRecord(provision.MoveCommitted, stamped)}) if d.Action != moveActNone { t.Fatalf("a close with a chore owed: %+v", d) } d = decideMoveRecovery(moveRecoveryInput{Now: mvT0, Claim: mvClaim(hostclaim.KindLanding, hostclaim.PhaseCommitted), Rec: mvRecord(provision.MoveCommitted, stamped)}) if d.Action != moveActClose || d.Record != hostops.RecoveryMoveClose { t.Fatalf("the committed close: %+v", d) } for _, c := range []struct { claim *hostclaim.Claim rec provision.Record want hostops.MoveRecoveryRecordAction }{ {mvClaim(hostclaim.KindRestoring, hostclaim.PhaseOpened), mvRecord(provision.MoveRollingBack, rb, func(r *provision.Record) { r.Move.Rollback.TargetParkedAt = mvAt(0) }), hostops.RecoveryMoveRolledBackClose}, {mvClaim(hostclaim.KindReverting, hostclaim.PhaseOpened), mvRecord(provision.MoveReverting, func(r *provision.Record) { r.Move.ReopenedAt = mvAt(0) }), hostops.RecoveryMoveRevertClose}, } { if d := decideMoveRecovery(moveRecoveryInput{Now: mvT0, Claim: c.claim, Rec: c.rec}); d.Action != moveActClose || d.Record != c.want { t.Fatalf("%s/%s: %+v, want close %s", c.claim.Op.Kind, c.claim.Op.Phase, d, c.want) } } // An abort the console never closes (fix round 1, ruling 1): only the // source closes it, after it retired its own state. Due, it is at most // a page. if d := decideMoveRecovery(moveRecoveryInput{Now: mvT0, Claim: mvClaim(hostclaim.KindMoving, hostclaim.PhaseAborting), Rec: mvRecord(provision.MoveAborting)}); d.Action != moveActAbortOverdue || d.Record != "" { t.Fatalf("a due abort: %+v, want only the overdue check", d) } // The record closed, the claim not released: the release. closed := func(r *provision.Record) { r.Move, r.LastMove = nil, &provision.MoveOutcome{ID: "mv", Outcome: "done", At: mvT0} } d = decideMoveRecovery(moveRecoveryInput{Now: mvT0, Claim: mvClaim(hostclaim.KindLanding, hostclaim.PhaseCommitted), Rec: mvRecord(provision.MoveCommitted, closed)}) if d.Action != moveActClaim || d.Claim != hostops.RecoveryMoveRelease { t.Fatalf("the release from LastMove: %+v", d) } } // ---- the pass, end to end ---- // movePassWorld is a host-claim console whose move the request door // started (j17StartedMove), with the console's own move pass bound as the // Recovery.Moves hook, pages captured from the armed alert sinks, and the // pass's clock under the test's control. type movePassWorld struct { fx *consoleFixture id string auth hostclaim.FenceAuthority clock time.Time mu sync.Mutex pages []pagePayload } type pagePayload struct{ Kind, Level, Subject, Body string } func newMovePassWorld(t *testing.T, fx *consoleFixture, id string) *movePassWorld { t.Helper() w := &movePassWorld{fx: fx, id: id, clock: time.Now().UTC()} fx.srv.movesClock = func() time.Time { w.mu.Lock(); defer w.mu.Unlock(); return w.clock } alerting.Arm(&alerting.Sinks{WebhookURL: "http://pages.test/hook", Post: func(_ string, body []byte) error { var p pagePayload if err := json.Unmarshal(body, &p); err != nil { return err } w.mu.Lock() w.pages = append(w.pages, p) w.mu.Unlock() return nil }}) t.Cleanup(func() { alerting.Arm(nil) }) return w } func (w *movePassWorld) advance(d time.Duration) { w.mu.Lock() w.clock = w.clock.Add(d) w.mu.Unlock() } // pass runs one console recovery pass with only the moves hook live. func (w *movePassWorld) pass(t *testing.T) { t.Helper() a := w.fx.srv.cfg.ClaimAuthority nop := func(context.Context) error { return nil } nopObs := func(context.Context, hostclaim.Observed) error { return nil } r := hostops.Recovery{Moves: w.fx.srv.movesRecovery, MoveLogs: w.fx.srv.drainMoveLog, MoveFenceAuthority: w.auth, Controller: hostops.Controller{Store: w.fx.srv.cfg.Releases, Control: a.Control, Authority: a, Now: time.Now, NewID: claimOperationID}, Purge: nopObs, Placement: nopObs, SweepRecords: nop, SweepPurges: nop, SweepAdmissions: nop} if err := a.Control.RecoveryPass(context.Background(), r); err != nil { t.Fatalf("the recovery pass: %v", err) } } // passErr is one recovery pass, returning its error. func (w *movePassWorld) passErr() error { a := w.fx.srv.cfg.ClaimAuthority nop := func(context.Context) error { return nil } nopObs := func(context.Context, hostclaim.Observed) error { return nil } r := hostops.Recovery{Moves: w.fx.srv.movesRecovery, MoveLogs: w.fx.srv.drainMoveLog, MoveFenceAuthority: w.auth, Controller: hostops.Controller{Store: w.fx.srv.cfg.Releases, Control: a.Control, Authority: a, Now: time.Now, NewID: claimOperationID}, Purge: nopObs, Placement: nopObs, SweepRecords: nop, SweepPurges: nop, SweepAdmissions: nop} return a.Control.RecoveryPass(context.Background(), r) } func (w *movePassWorld) claim(t *testing.T) *hostclaim.Claim { t.Helper() o, err := hostclaim.Read(context.Background(), w.fx.rel, "acme.go.tito.io") if err != nil || o.Absent { t.Fatalf("read the claim: %v", err) } return o.Claim } func (w *movePassWorld) record(t *testing.T) provision.Record { t.Helper() rec, err := provision.GetRecord(context.Background(), w.fx.rel, "bab", "titogo", "acme.go.tito.io") if err != nil || rec == nil { t.Fatalf("read the record: %v", err) } return *rec } // setClaim rewrites the claim under the raw bucket, as a box would. func (w *movePassWorld) setClaim(t *testing.T, mut func(*hostclaim.Claim)) { t.Helper() ctx := context.Background() obs, err := hostclaim.Read(ctx, w.fx.rel, "acme.go.tito.io") if err != nil { t.Fatal(err) } if _, err := hostclaim.Update(ctx, w.fx.rel, obs, func(c *hostclaim.Claim) error { mut(c); return nil }); err != nil { t.Fatalf("rewrite the claim: %v", err) } } func (w *movePassWorld) startEffect(t *testing.T) hostops.Effect { t.Helper() a, err := hostops.ReadAdmission(context.Background(), w.fx.rel, "bab", "titogo", claimMoveAppID) if err != nil { t.Fatal(err) } return a.Value.Effects[w.id] } // setStartEffect rewrites the move-start effect of the admission object. func (w *movePassWorld) setStartEffect(t *testing.T, mut func(*hostops.Effect)) { t.Helper() ctx := context.Background() body, etag, err := w.fx.rel.Get(ctx, "apps/bab/titogo/admission.json") if err != nil { t.Fatal(err) } var a hostops.AppAdmission if err := json.Unmarshal(body, &a); err != nil { t.Fatal(err) } e := a.Effects[w.id] mut(&e) a.Effects[w.id] = e if body, err = json.Marshal(a); err != nil { t.Fatal(err) } if _, err := w.fx.rel.Put(ctx, "apps/bab/titogo/admission.json", body, etag); err != nil { t.Fatal(err) } } func (w *movePassWorld) paged(t *testing.T) []pagePayload { t.Helper() w.mu.Lock() defer w.mu.Unlock() return append([]pagePayload(nil), w.pages...) } func startedMovePass(t *testing.T, code string) *movePassWorld { t.Helper() fx, _, _, id := j17StartedMove(t, code) return newMovePassWorld(t, fx, id) } func landingMovePass(t *testing.T, code string) *movePassWorld { t.Helper() fx, _, _ := j4LandingMove(t, code) return newMovePassWorld(t, fx, j17MoveState(t, fx).ID) } func newRollbackID(t *testing.T) string { t.Helper() id, err := moves.NewRollbackID(rand.Reader) if err != nil { t.Fatal(err) } return id } // TestRecoveryPassRollsBackAtTheLandingDeadline: a landing past the earlier // of its deadlines is rolled back by the record (one pass), and the claim // follows on the next (the rollback half). Each pass writes one object. func TestRecoveryPassRollsBackAtTheLandingDeadline(t *testing.T) { w := landingMovePass(t, "code-mvpass-deadline") claim := claimBytes(t, w.fx, "acme.go.tito.io") w.pass(t) if m := w.record(t).Move; m.State != provision.MoveLanding { t.Fatalf("rolled back before the deadline: %+v", m) } past := time.Now().UTC().Add(-time.Minute) j17SetRecord(t, w.fx, func(r *provision.Record) { r.Move.LandingDeadline = &past }) w.pass(t) rec := w.record(t) if rec.Move.State != provision.MoveRollingBack || rec.Move.Rollback == nil || rec.Move.Rollback.Reason != provision.RollbackLandingDeadline || rec.Region != "ie" { t.Fatalf("the deadline's rollback: region %s %+v", rec.Region, rec.Move) } if claimBytes(t, w.fx, "acme.go.tito.io") != claim { t.Fatal("the pass that wrote the record wrote the claim too") } w.pass(t) c := w.claim(t) if c.Op.Kind != hostclaim.KindRestoring || c.Op.ID != w.id { t.Fatalf("the claim did not follow the rollback: %+v", c.Op) } if after := w.record(t); after.Move.Rollback.ID != rec.Move.Rollback.ID || after.RecordSeq != rec.RecordSeq { t.Fatalf("the claim's pass wrote the record: %+v", after.Move) } } // TestRecoveryPassSettlesAnOrphanStartThenReleases (K3): the request door's // record write was lost, so the claim is moving/"" and the record carries no // move, with the start effect uncertain. Under ten minutes the pass leaves // it. After, it settles the start not-applied from record_seq (no handle), // and on the next pass releases the claim to serving under the source. A // landing orphan is paged once and never released. func TestRecoveryPassSettlesAnOrphanStartThenReleases(t *testing.T) { w := startedMovePass(t, "code-mvpass-orphan") j17SetRecord(t, w.fx, func(r *provision.Record) { r.Move = nil }) w.setStartEffect(t, func(e *hostops.Effect) { e.State, e.ResultReference = "uncertain", "" }) w.pass(t) if c := w.claim(t); c.Op.Kind != hostclaim.KindMoving || w.startEffect(t).State != "uncertain" { t.Fatalf("acted inside ten minutes: claim %+v effect %+v", c.Op, w.startEffect(t)) } w.setClaim(t, func(c *hostclaim.Claim) { c.Op.StartedAt = time.Now().UTC().Add(-11 * time.Minute) }) w.pass(t) if e := w.startEffect(t); e.State != "complete" || e.ResultReference != "not-applied" { t.Fatalf("the start was not settled: %+v", e) } if c := w.claim(t); c.Op.Kind != hostclaim.KindMoving { t.Fatalf("the settling pass released too: %+v", c.Op) } w.pass(t) c := w.claim(t) if c.Op.Kind != hostclaim.KindServing || c.Op.Exec != "ie-box" || hostclaim.RequireReleasedMove(w.id)(c) != nil { t.Fatalf("the orphan was not released: %+v", c.Op) } if p := w.paged(t); len(p) != 0 { t.Fatalf("a moving orphan paged: %+v", p) } // A landing orphan pages once, and is left. l := landingMovePass(t, "code-mvpass-orphan-landing") j17SetRecord(t, l.fx, func(r *provision.Record) { r.Move = nil }) before := claimBytes(t, l.fx, "acme.go.tito.io") l.pass(t) l.pass(t) if claimBytes(t, l.fx, "acme.go.tito.io") != before { t.Fatal("a landing orphan's claim was written") } p := l.paged(t) if len(p) != 1 || p[0].Level != alerting.LevelIncident || !strings.Contains(p[0].Subject, "acme.go.tito.io") || !strings.Contains(p[0].Body, l.id) { t.Fatalf("the landing orphan's pages: %+v", p) } } // oneBoxFenceAuthority is c7MoveAuthority with the one-box-region check the // grant's Convert needs (the console's hostfence.ClaimFenceAuthority has // both). type oneBoxFenceAuthority struct{ c7MoveAuthority } func (oneBoxFenceAuthority) CheckOneBoxRegion(context.Context, string, string) error { return nil } // TestRecoveryPassConvertsAFencedSourceInTwoPasses (K13): a source // terminated before the flip. The first pass writes the record's relocation // decision, the second the claim's conversion to relocating. func TestRecoveryPassConvertsAFencedSourceInTwoPasses(t *testing.T) { w := startedMovePass(t, "code-mvpass-convert") w.auth = oneBoxFenceAuthority{c7MoveAuthority{region: "ie"}} w.pass(t) if m := w.record(t).Move; m.State != provision.MovePreparing { t.Fatalf("converted with no fence: %+v", m) } terminatedSourceFence(t, w.fx, "ie-box", "uk-box") w.pass(t) if m := w.record(t).Move; m.State != provision.MoveRelocating { t.Fatalf("the decision pass: %+v", m) } if c := w.claim(t); c.Op.Kind != hostclaim.KindMoving { t.Fatalf("the decision pass converted the claim: %+v", c.Op) } w.pass(t) if c := w.claim(t); c.Op.Kind != hostclaim.KindRelocating || c.Op.Phase != "pinning" || c.Op.ID != w.id { t.Fatalf("the conversion pass: %+v", c.Op) } w.pass(t) // a relocating claim is region HA's: nothing if c := w.claim(t); c.Op.Kind != hostclaim.KindRelocating { t.Fatalf("after the conversion: %+v", c.Op) } } // lostTargetRollback puts the landing world into a rollback whose target // box was lost and released: the source recovered and opened, the claim // restoring/opened under the source. func lostTargetRollback(t *testing.T, w *movePassWorld) { t.Helper() w.setClaim(t, func(c *hostclaim.Claim) { c.Op.Kind, c.Op.Phase, c.Op.Exec = hostclaim.KindRestoring, hostclaim.PhaseOpened, "ie-box" c.Lost = []string{"uk-box"} c.Op.Participants = []string{"ie-box"} c.Op.Intent["to"] = "uk" c.Obligations = nil }) rb, at := newRollbackID(t), time.Now().UTC().Add(-time.Hour) deadline := at.Add(15 * time.Minute) j17SetRecord(t, w.fx, func(r *provision.Record) { r.Region = "ie" r.Move.State = provision.MoveRollingBack r.Move.Rollback = &provision.MoveRollback{ID: rb, RequestedAt: &at, Reason: provision.RollbackDeclaredLost, TargetPhase: provision.RbTargetReleased, SourcePhase: provision.RbSourceOpened, RecoveredAt: &at, OpenedAt: &at, ReleaseDeadline: &deadline} }) } // TestRecoveryPassStampsALostTargetThenCloses (p10 Task G): with the target // lost and released and nothing of its box or region owed, the pass stamps // target_parked_at through the grant; the close follows once overdue, then // the release. func TestRecoveryPassStampsALostTargetThenCloses(t *testing.T) { w := landingMovePass(t, "code-mvpass-lost") lostTargetRollback(t, w) w.pass(t) rb := w.record(t).Move.Rollback if rb.TargetParkedAt == nil || rb.TargetPhase != provision.RbTargetCleaned { t.Fatalf("the lost target was not stamped: %+v", rb) } w.pass(t) if w.record(t).Move == nil { t.Fatal("closed inside the boxes' grace") } w.advance(moveCloseGrace + time.Minute) w.pass(t) rec := w.record(t) if rec.Move != nil || rec.LastMove == nil || rec.LastMove.Outcome != "rolled_back" { t.Fatalf("not closed: %+v %+v", rec.Move, rec.LastMove) } if c := w.claim(t); c.Op.Kind != hostclaim.KindRestoring { t.Fatalf("the close's pass released too: %+v", c.Op) } w.pass(t) if c := w.claim(t); c.Op.Kind != hostclaim.KindServing || c.Op.Exec != "ie-box" { t.Fatalf("not released: %+v", c.Op) } } // committedAndOpened puts the landing world at a committed, opened and // source-parked move with nothing owed: the close is due. func committedAndOpened(t *testing.T, w *movePassWorld) { t.Helper() w.setClaim(t, func(c *hostclaim.Claim) { c.Op.Phase, c.Obligations = hostclaim.PhaseCommitted, nil }) at := time.Now().UTC().Add(-time.Hour) j17SetRecord(t, w.fx, func(r *provision.Record) { r.Move.State, r.Move.LandingPhase = provision.MoveCommitted, provision.LandProbed r.Move.CommittedAt, r.Move.OpenedAt, r.Move.SourceParkedAt = &at, &at, &at }) } // TestRecoveryPassFinishesTheClose: a close the boxes did not write within // moveCloseGrace is overdue. The pass pages it once, closes the record // (LastMove done) and, on the next pass, releases under the target. func TestRecoveryPassFinishesTheClose(t *testing.T) { w := landingMovePass(t, "code-mvpass-close") committedAndOpened(t, w) w.pass(t) if w.record(t).Move == nil || len(w.paged(t)) != 0 { t.Fatalf("closed or paged inside the grace: %+v", w.paged(t)) } w.advance(moveCloseGrace + time.Minute) w.pass(t) rec := w.record(t) if rec.Move != nil || rec.LastMove == nil || rec.LastMove.ID != w.id || rec.LastMove.Outcome != "done" { t.Fatalf("not closed: %+v %+v", rec.Move, rec.LastMove) } if c := w.claim(t); c.Op.Kind != hostclaim.KindLanding || c.Op.Phase != hostclaim.PhaseCommitted { t.Fatalf("released in the close's pass: %+v", c.Op) } if p := w.paged(t); len(p) != 1 || p[0].Level != alerting.LevelWarning || !strings.Contains(p[0].Body, w.id) { t.Fatalf("the overdue close's page: %+v", p) } w.pass(t) c := w.claim(t) if c.Op.Kind != hostclaim.KindServing || c.Op.Exec != "uk-box" || hostclaim.RequireReleasedMove(w.id)(c) != nil { t.Fatalf("not released under the target: %+v", c.Op) } if len(w.paged(t)) != 1 { t.Fatalf("paged again: %+v", w.paged(t)) } } // TestRecordFirstCloseCrashIsFinishedByThePass (ruling M4): a box closed the // record and crashed before the claim's release. The record carries // LastMove and no move; the claim is still in the move's closing op. The // console's pass releases from LastMove, under the executor the outcome // names, with no grace (the release is the record's decision). func TestRecordFirstCloseCrashIsFinishedByThePass(t *testing.T) { for _, c := range []struct { name, outcome, exec string setup func(*testing.T, *movePassWorld) }{ {"committed", "done", "uk-box", func(t *testing.T, w *movePassWorld) { w.setClaim(t, func(c *hostclaim.Claim) { c.Op.Phase, c.Obligations = hostclaim.PhaseCommitted, nil }) }}, {"rolled back", "rolled_back", "ie-box", func(t *testing.T, w *movePassWorld) { w.setClaim(t, func(c *hostclaim.Claim) { c.Op.Kind, c.Op.Phase, c.Op.Exec, c.Obligations = hostclaim.KindRestoring, hostclaim.PhaseOpened, "ie-box", nil }) }}, } { t.Run(c.name, func(t *testing.T) { w := landingMovePass(t, "code-mvpass-crash-"+strings.ReplaceAll(c.name, " ", "-")) c.setup(t, w) j17SetRecord(t, w.fx, func(r *provision.Record) { if c.outcome == "rolled_back" { r.Region = "ie" } r.Move, r.LastMove = nil, &provision.MoveOutcome{ID: w.id, Outcome: c.outcome, At: time.Now().UTC()} }) w.pass(t) got := w.claim(t) if got.Op.Kind != hostclaim.KindServing || got.Op.Exec != c.exec || hostclaim.RequireReleasedMove(w.id)(got) != nil { t.Fatalf("not released: %+v", got.Op) } }) } t.Run("reverted", func(t *testing.T) { w := startedMovePass(t, "code-mvpass-crash-reverted") w.setClaim(t, func(c *hostclaim.Claim) { c.Op.Kind, c.Op.Phase, c.Obligations = hostclaim.KindReverting, hostclaim.PhaseOpened, nil if c.Op.Journal == nil { c.Op.Journal = map[string]string{} } c.Op.Journal[hostclaim.JournalRevPhase] = hostclaim.PhaseOpened }) j17SetRecord(t, w.fx, func(r *provision.Record) { r.Move, r.LastMove = nil, &provision.MoveOutcome{ID: w.id, Outcome: "rolled_back", At: time.Now().UTC()} }) w.pass(t) got := w.claim(t) if got.Op.Kind != hostclaim.KindServing || got.Op.Exec != "ie-box" || hostclaim.RequireReleasedMove(w.id)(got) != nil { t.Fatalf("not released: %+v", got.Op) } }) t.Run("aborted", func(t *testing.T) { w := startedMovePass(t, "code-mvpass-crash-aborted") w.setClaim(t, func(c *hostclaim.Claim) { c.Op.Phase, c.Obligations = hostclaim.PhaseAborting, nil }) j17SetRecord(t, w.fx, func(r *provision.Record) { r.Move, r.LastMove = nil, &provision.MoveOutcome{ID: w.id, Outcome: "aborted", At: time.Now().UTC()} }) w.pass(t) got := w.claim(t) if got.Op.Kind != hostclaim.KindServing || got.Op.Exec != "ie-box" || hostclaim.RequireReleasedMove(w.id)(got) != nil { t.Fatalf("not released: %+v", got.Op) } }) } // TestRecoveryPassAbortsAfterSixHours (K18): a move still preparing // moves.AbortAfter after its request is aborted through ConsoleMove; before // that the pass pages once at an hour and writes nothing. // Preflight L29: the 60-minute preparing page and the six-hour abort run // from one start, moves.PreparingSince (the later of the request and the // readiness), so the two can never disagree about how long a move prepared. func TestPreparingPageRunsFromPreparingSince(t *testing.T) { ready := mvAt(30 * time.Minute) for name, c := range map[string]struct { ready *time.Time at time.Duration want bool }{ "an hour after the request": {nil, time.Hour, true}, "short of it": {nil, time.Hour - time.Second, false}, "an hour after the request, ready 30": {ready, time.Hour, false}, "an hour after the readiness": {ready, 90 * time.Minute, true}, } { rec := mvRecord(provision.MovePreparing, func(r *provision.Record) { r.Move.ReadyAt = c.ready }) now := mvT0.Add(c.at) d := decideMoveRecovery(moveRecoveryInput{Now: now, Claim: mvClaim(hostclaim.KindMoving, hostclaim.PhaseMoving), Rec: rec}) paged := false for _, k := range d.Pages { paged = paged || k == movePagePreparing } if paged != c.want { t.Errorf("%s: preparing page %v, want %v (pages %v)", name, paged, c.want, d.Pages) } if since := moves.PreparingSince(rec.Move); paged != !now.Before(since.Add(movePreparingPage)) { t.Errorf("%s: the page does not run from moves.PreparingSince (%v)", name, since) } } } func TestRecoveryPassAbortsAfterSixHours(t *testing.T) { w := startedMovePass(t, "code-mvpass-abort") claim := claimBytes(t, w.fx, "acme.go.tito.io") requested := w.record(t).Move.RequestedAt w.advance(30 * time.Minute) w.pass(t) if len(w.paged(t)) != 0 { t.Fatalf("paged at 30 minutes: %+v", w.paged(t)) } w.advance(time.Hour) w.pass(t) w.pass(t) if m := w.record(t).Move; m.State != provision.MovePreparing { t.Fatalf("aborted early: %+v", m) } p := w.paged(t) if len(p) != 1 || p[0].Level != alerting.LevelWarning || !strings.Contains(p[0].Subject, "acme.go.tito.io") { t.Fatalf("the hour's page: %+v", p) } w.mu.Lock() w.clock = requested.Add(moves.AbortAfter + time.Minute) w.mu.Unlock() w.pass(t) if m := w.record(t).Move; m.State != provision.MoveAborting { t.Fatalf("not aborted at six hours: %+v", m) } if claimBytes(t, w.fx, "acme.go.tito.io") != claim { t.Fatal("the abort wrote the claim (the source's abort takes it to aborting)") } } // TestRecoveryPassNeverClosesAnAbort (fix round 1, ruling 1): the source's // retirement of its own state is blocked, so it never closes the aborting // record, though nothing is owed under the op. The console does not close // it either: once the abort has been due past the lane's horizon (the // claim's quiet_after for the target region) plus moveCloseGrace, it pages // once, and the record stays aborting. func TestRecoveryPassNeverClosesAnAbort(t *testing.T) { w := startedMovePass(t, "code-mvpass-abort-blocked") horizon := w.clock.Add(20 * time.Minute) w.setClaim(t, func(c *hostclaim.Claim) { c.Op.Phase, c.Obligations = hostclaim.PhaseAborting, nil if c.QuietAfter == nil { c.QuietAfter = map[string]time.Time{} } c.QuietAfter["uk"] = horizon }) j17SetRecord(t, w.fx, func(r *provision.Record) { r.Move.State = provision.MoveAborting }) claim := claimBytes(t, w.fx, "acme.go.tito.io") w.pass(t) w.advance(moveCloseGrace + time.Minute) w.pass(t) if len(w.paged(t)) != 0 { t.Fatalf("paged before the lane's horizon plus the grace: %+v", w.paged(t)) } w.advance(20 * time.Minute) // past quiet_after + the grace w.pass(t) w.advance(2 * time.Hour) w.pass(t) w.pass(t) if m := w.record(t).Move; m == nil || m.State != provision.MoveAborting { t.Fatalf("the console closed the abort: %+v %+v", m, w.record(t).LastMove) } if claimBytes(t, w.fx, "acme.go.tito.io") != claim { t.Fatal("the console wrote the aborting claim") } p := w.paged(t) if len(p) != 1 || p[0].Level != alerting.LevelWarning || !strings.Contains(p[0].Body, w.id) || !strings.Contains(p[0].Body, "ie-box") { t.Fatalf("the overdue abort's pages: %+v", p) } } // TestConsolePagesThroughAlerting (ยง13, M14; fix round 1, ruling 3): the // pass pages through alerting.Page on the armed sinks. A rollback waiting // past its release deadline is an incident, paged again only a full hour // after the last attempt: two passes either side of a whole hour since the // deadline do not both page. The last attempt's time is durable, in the // console's store, so a restarted console keeps the spacing. func TestConsolePagesThroughAlerting(t *testing.T) { w := landingMovePass(t, "code-mvpass-pages") rb, at := newRollbackID(t), w.clock.Add(-74*time.Minute) deadline := at.Add(15 * time.Minute) // 59 minutes ago j17SetRecord(t, w.fx, func(r *provision.Record) { r.Region = "ie" r.Move.State = provision.MoveRollingBack r.Move.Rollback = &provision.MoveRollback{ID: rb, RequestedAt: &at, Reason: provision.RollbackLandingDeadline, TargetPhase: provision.RbTargetReleasing, SourcePhase: provision.RbSourceWaiting, ReleaseDeadline: &deadline} }) w.setClaim(t, func(c *hostclaim.Claim) { c.Op.Kind, c.Op.Phase = hostclaim.KindRestoring, hostclaim.PhaseClaimed }) first := w.clock w.pass(t) p := w.paged(t) if len(p) != 1 || p[0].Kind != "page" || p[0].Level != alerting.LevelIncident || !strings.Contains(p[0].Subject, "uk") || !strings.Contains(p[0].Body, w.id) { t.Fatalf("the release deadline's page: %+v", p) } // Across the whole hour since the deadline (59 to 61 minutes): no page. w.advance(2 * time.Minute) w.pass(t) if len(w.paged(t)) != 1 { t.Fatalf("paged again two minutes later, across the hour since the deadline: %+v", w.paged(t)) } // A restarted console: the in-memory state is gone, the store is not. w.fx.srv.moveCloseSeen = nil if last, ok, err := w.fx.st.MovePageAttempt("release-deadline acme.go.tito.io " + w.id); err != nil || !ok || !last.Equal(first.Truncate(time.Second)) { t.Fatalf("the last attempt's durable time: %v %v %v, want %v", last, ok, err, first) } w.advance(56 * time.Minute) // 58 minutes after the first page w.pass(t) if len(w.paged(t)) != 1 { t.Fatalf("paged again inside the hour: %+v", w.paged(t)) } w.advance(3 * time.Minute) // 61 minutes after the first page w.pass(t) if len(w.paged(t)) != 2 { t.Fatalf("not paged again a full hour after the last attempt: %+v", w.paged(t)) } } // moveLogOf is the move's log as written to the deployment bucket. func moveLogOf(t *testing.T, w *movePassWorld) map[string]moves.LogEvent { t.Helper() got, err := moves.ReadLog(context.Background(), w.fx.rel, moves.ReportPrefix("bab", "titogo", "acme.go.tito.io", w.id)) if err != nil { t.Fatal(err) } out := map[string]moves.LogEvent{} for _, ev := range got { out[ev.Identity] = ev } return out } // Plan 6 Task 3 fix round 1, ruling 3, and fix round 3: the console's move // pass logs the transitions it makes: the close and the claim's release after // it, the landing deadline's rollback, and the six-hour abort. Each entry is // the console's, under the identity the box would give it, queued in the // console's outbox and delivered by the pass's drainer (drainMoveLog). func TestRecoveryPassWritesTheMoveLog(t *testing.T) { t.Run("close and release", func(t *testing.T) { w := landingMovePass(t, "code-mvpass-log-close") committedAndOpened(t, w) w.pass(t) // the close's grace runs from the pass's first sighting w.advance(moveCloseGrace + time.Minute) w.pass(t) // the close w.pass(t) // the claim's release log := moveLogOf(t, w) done, released := log["done"], log["claim-released"] if done.Event != "done" || done.Actor != "console" || done.Op != w.id || released.Event != "claim_released" || released.Actor != "console" { t.Fatalf("log %+v", log) } if done.Fields["offline_s"] == "" || done.Fields["from"] != "ie" { t.Fatalf("the close's entry lacks its evidence: %+v", done.Fields) } noPendingLog(t, w) }) t.Run("deadline rollback", func(t *testing.T) { w := landingMovePass(t, "code-mvpass-log-deadline") past := time.Now().UTC().Add(-time.Minute) j17SetRecord(t, w.fx, func(r *provision.Record) { r.Move.LandingDeadline = &past }) w.pass(t) if ev := moveLogOf(t, w)["rolling_back"]; ev.Event != "rolling_back" || ev.Actor != "console" || ev.Fields["reason"] == "" { t.Fatalf("log %+v", moveLogOf(t, w)) } }) t.Run("six-hour abort", func(t *testing.T) { w := startedMovePass(t, "code-mvpass-log-abort") requested := w.record(t).Move.RequestedAt w.mu.Lock() w.clock = requested.Add(moves.AbortAfter + time.Minute) w.mu.Unlock() w.pass(t) if ev := moveLogOf(t, w)["aborting"]; ev.Event != "aborting" || ev.Actor != "console" { t.Fatalf("log %+v", moveLogOf(t, w)) } }) } // blockMoveLog makes every write under the move's log fail (a file where // its directory goes) until the returned func is called. func blockMoveLog(t *testing.T, w *movePassWorld) func() { t.Helper() root := w.fx.rel.(*deletableStore).root p := filepath.Join(root, filepath.FromSlash(moves.ReportPrefix("bab", "titogo", "acme.go.tito.io", w.id)+"log")) if err := os.MkdirAll(filepath.Dir(p), 0o755); err != nil { t.Fatal(err) } if err := os.WriteFile(p, nil, 0o644); err != nil { t.Fatal(err) } return func() { if err := os.Remove(p); err != nil { t.Fatal(err) } } } // blockMoveLogEntry makes the write of one entry fail (a directory where its // object goes) until the returned func is called. func blockMoveLogEntry(t *testing.T, w *movePassWorld, name string) func() { t.Helper() root := w.fx.rel.(*deletableStore).root p := filepath.Join(root, filepath.FromSlash(moves.LogKeyFor(moves.ReportPrefix("bab", "titogo", "acme.go.tito.io", w.id), name))) if err := os.MkdirAll(p, 0o755); err != nil { t.Fatal(err) } return func() { if err := os.Remove(p); err != nil { t.Fatal(err) } } } func pendingLog(t *testing.T, w *movePassWorld) []string { t.Helper() got, err := w.fx.st.MoveLogPending("acme.go.tito.io", w.id) if err != nil { t.Fatal(err) } var names []string for _, e := range got { n := e.Name if !e.Confirmed { n += "(unconfirmed)" } if e.Held { n += "(held)" } names = append(names, n) } return names } func noPendingLog(t *testing.T, w *movePassWorld) { t.Helper() if p := pendingLog(t, w); len(p) != 0 { t.Fatalf("entries still pending: %v", p) } } // Fix round 3, ruling 1: the console's log delivery is the pass's drainer, // independent of any move's state or grant, and no release waits for it. A // row whose write fails is retried with backoff, indefinitely, and warned of // once in the journal when it is an hour old; it is still delivered after // the claim's release. func TestRecoveryPassLogOutboxRetries(t *testing.T) { journal := captureLog(t) w := landingMovePass(t, "code-mvpass-outbox-close") committedAndOpened(t, w) w.pass(t) w.advance(moveCloseGrace + time.Minute) unblock := blockMoveLog(t, w) w.pass(t) // the close; its entry is queued and its delivery fails if rec := w.record(t); rec.Move != nil { t.Fatalf("not closed: %+v", rec.Move) } w.pass(t) // the release does not wait for the log if c := w.claim(t); c.Op.Kind != hostclaim.KindServing { t.Fatalf("the release waited for the log: %+v", c.Op) } if p := pendingLog(t, w); strings.Join(p, " ") != "done claim-released" { t.Fatalf("pending %v, want the close's and the release's entries", p) } for i := 0; i < 8; i++ { // over an hour of failing passes w.advance(10 * time.Minute) w.pass(t) } for i := 0; i < 6; i++ { // and more failed attempts after the warning w.advance(30 * time.Minute) w.pass(t) } if n := strings.Count(journal.String(), "unwritten for over an hour"); n != 2 { t.Fatalf("%d hour-old warnings, want one per row:\n%s", n, journal.String()) } unblock() w.advance(2 * time.Hour) // past any backoff w.pass(t) log := moveLogOf(t, w) if log["done"].Actor != "console" || log["claim-released"].Event != "claim_released" { t.Fatalf("log %+v", log) } noPendingLog(t, w) } // Fix round 3, ruling 2: claim_released is published only from a successful // release. The pass queues it unconfirmed before the release and confirms it // after; the drainer delivers confirmed rows only, and settles an unconfirmed // one by the claim. func TestClaimReleasedIsPublishedOnlyAfterTheRelease(t *testing.T) { closed := func(t *testing.T, code string) *movePassWorld { w := landingMovePass(t, code) committedAndOpened(t, w) w.pass(t) w.advance(moveCloseGrace + time.Minute) w.pass(t) // the close return w } t.Run("a release that fails publishes nothing", func(t *testing.T) { w := closed(t, "code-mvpass-release-fails") w.fx.srv.moveReleaseFault = func() error { return hostops.ErrPending } w.pass(t) if c := w.claim(t); c.Op.Kind == hostclaim.KindServing { t.Fatal("released despite the fault") } if _, ok := moveLogOf(t, w)["claim-released"]; ok { t.Fatal("claim_released published for a release that failed") } if p := pendingLog(t, w); strings.Join(p, " ") != "claim-released(unconfirmed)" { t.Fatalf("pending %v", p) } w.pass(t) // the claim is still held: the row is left for the release if _, ok := moveLogOf(t, w)["claim-released"]; ok { t.Fatal("claim_released published while the claim is held") } w.fx.srv.moveReleaseFault = nil w.pass(t) if ev := moveLogOf(t, w)["claim-released"]; ev.Event != "claim_released" { t.Fatalf("not published after the release: %+v", moveLogOf(t, w)) } noPendingLog(t, w) }) t.Run("a crash between the release and its confirmation", func(t *testing.T) { w := closed(t, "code-mvpass-release-crash") unblock := blockMoveLogEntry(t, w, "claim-released") w.pass(t) // the release; its entry is confirmed, its delivery fails if c := w.claim(t); c.Op.Kind != hostclaim.KindServing { t.Fatalf("not released: %+v", c.Op) } // As if the console stopped after the release and before the confirm. if _, err := w.fx.st.db.Exec(`UPDATE move_log_outbox SET confirmed = 0 WHERE op = ? AND name = 'claim-released'`, w.id); err != nil { t.Fatal(err) } unblock() w.advance(2 * time.Hour) w.pass(t) if ev := moveLogOf(t, w)["claim-released"]; ev.Event != "claim_released" { t.Fatalf("the released claim's entry was not confirmed and published: %+v", moveLogOf(t, w)) } noPendingLog(t, w) }) t.Run("an unconfirmed row whose claim another move holds", func(t *testing.T) { journal := captureLog(t) w := closed(t, "code-mvpass-release-other") body := []byte(`{"v":1}`) if err := w.fx.st.QueueMoveLog("acme.go.tito.io", "mv_another", "claim-released", w.claim(t).Holder.Incarnation, body, false, w.clock); err != nil { t.Fatal(err) } w.pass(t) got, err := w.fx.st.MoveLogPending("acme.go.tito.io", "mv_another") if err != nil || len(got) != 0 { t.Fatalf("pending %+v %v", got, err) } if !strings.Contains(journal.String(), "mv_another") { t.Fatalf("no journal line for the dropped row:\n%s", journal.String()) } }) } // Fix round 4, ruling 2: a row the drainer cannot settle yet (unconfirmed, // its claim still the move's) takes the same backoff and one-hour warning as // a failed delivery, and the batch picks rows by their next attempt, so a // full batch of them never starves a confirmed row. func TestUnresolvedMoveLogRowsDoNotStarveTheBatch(t *testing.T) { journal := captureLog(t) w := landingMovePass(t, "code-mvpass-starve") body := func(name string) []byte { b, err := json.Marshal(moves.LogEvent{V: 1, Op: w.id, Host: "acme.go.tito.io", Event: "x", Identity: name, Actor: "console", At: w.clock}) if err != nil { t.Fatal(err) } return b } inc := w.claim(t).Holder.Incarnation for i := 0; i < moveLogDrainBatch; i++ { name := fmt.Sprintf("held-%03d", i) if err := w.fx.st.QueueMoveLog("acme.go.tito.io", w.id, name, inc, body(name), false, w.clock); err != nil { t.Fatal(err) } } if err := w.fx.st.QueueMoveLog("acme.go.tito.io", w.id, "late", inc, body("late"), true, w.clock); err != nil { t.Fatal(err) } for i := 0; i < 2 && moveLogOf(t, w)["late"].Identity == ""; i++ { w.pass(t) } if moveLogOf(t, w)["late"].Identity != "late" { t.Fatal("the confirmed row was starved by a full batch of unresolved rows") } // The unresolved rows are warned of once, an hour on. for i := 0; i < 10; i++ { w.advance(30 * time.Minute) w.pass(t) } if n := strings.Count(journal.String(), "unwritten for over an hour"); n != moveLogDrainBatch { t.Fatalf("%d hour-old warnings, want one per unresolved row (%d)", n, moveLogDrainBatch) } } // Fix round 4, ruling (b): a real CAS conflict inside g.Claim. Another writer // updates the claim between the grant's observation and the release's CAS, // so the release fails: nothing is published, the row stays unconfirmed, // and a later pass releases, confirms and publishes it. func TestReleaseCASConflictPublishesNothing(t *testing.T) { w := landingMovePass(t, "code-mvpass-release-cas") committedAndOpened(t, w) w.pass(t) w.advance(moveCloseGrace + time.Minute) w.pass(t) // the close d := w.fx.rel.(*deletableStore) claimKey, err := hostclaim.Key("acme.go.tito.io") if err != nil { t.Fatal(err) } conflicts := 0 d.putHook = func(ctx context.Context, key string) { if key != claimKey || conflicts > 0 { return } conflicts++ body, etag, err := d.Store.Get(ctx, key) if err != nil { t.Fatal(err) } // The concurrent writer: the same claim, rewritten, so its version // moves on under the release's CAS. if _, err := d.Store.Put(ctx, key, append(body, '\n'), etag); err != nil { t.Fatal(err) } } err = w.passErr() d.putHook = nil if conflicts != 1 || !errors.Is(err, release.ErrCASConflict) { t.Fatalf("the release's claim CAS: conflicts=%d err=%v, want a CAS conflict", conflicts, err) } if c := w.claim(t); c.Op.Kind == hostclaim.KindServing { t.Fatal("released despite the conflict") } if _, ok := moveLogOf(t, w)["claim-released"]; ok { t.Fatal("claim_released published for a release that lost its CAS") } if p := pendingLog(t, w); strings.Join(p, " ") != "claim-released(unconfirmed)" { t.Fatalf("pending %v", p) } w.advance(2 * time.Hour) // past the unresolved row's backoff w.pass(t) if c := w.claim(t); c.Op.Kind != hostclaim.KindServing { t.Fatalf("not released on the next pass: %+v", c.Op) } if ev := moveLogOf(t, w)["claim-released"]; ev.Event != "claim_released" { t.Fatalf("not published after the release: %+v", moveLogOf(t, w)) } noPendingLog(t, w) } // Fix round 4, ruling 3: a row is bound to the instance incarnation its // move's evidence carried, and the writer takes the account and app from the // host's claim only when its holder is that incarnation, for a move its // record names. A row for another app's host, a row whose instance was // recreated under the same names, and the rows of a retired instance are // never written, and are dropped. func TestMoveLogRowsAreBoundToTheirIncarnation(t *testing.T) { w := landingMovePass(t, "code-mvpass-tenancy") inc := w.claim(t).Holder.Incarnation entry := func(host, op, name string) []byte { b, err := json.Marshal(moves.LogEvent{V: 1, Op: op, Host: host, Event: "x", Identity: name, Actor: "console", At: w.clock}) if err != nil { t.Fatal(err) } return b } queue := func(host, op, name, inc string) { t.Helper() if err := w.fx.st.QueueMoveLog(host, op, name, inc, entry(host, op, name), true, w.clock); err != nil { t.Fatal(err) } } // Another app's host (the fixture's kass instance, which has no claim // here), under this instance's incarnation. queue("kass.carlosapp.dev", w.id, "elsewhere", inc) // This host, after a recreation under the same names: another incarnation. queue("acme.go.tito.io", w.id, "stale", strings.Repeat("ef", 32)) // This host and incarnation, but a move its record never named. queue("acme.go.tito.io", "mv_forged", "forged", inc) // The instance's own row, written. queue("acme.go.tito.io", w.id, "genuine", inc) w.pass(t) log := moveLogOf(t, w) if log["genuine"].Identity != "genuine" || log["stale"].Identity != "" { t.Fatalf("log %+v", log) } if forged, err := moves.ReadLog(context.Background(), w.fx.rel, moves.ReportPrefix("bab", "titogo", "acme.go.tito.io", "mv_forged")); err != nil || len(forged) != 0 { t.Fatalf("a move the record never named was logged: %+v %v", forged, err) } // Final fix, ruling 1: a confirmed row the writer refuses is never // deleted; it is held, with its bytes, until its incarnation's purge. held := func(host, op string) []string { t.Helper() got, err := w.fx.st.MoveLogPending(host, op) if err != nil { t.Fatal(err) } var names []string for _, e := range got { if !e.Held { t.Fatalf("%s %s %s refused but not held: %+v", host, op, e.Name, e) } names = append(names, e.Name) } return names } if h := held("acme.go.tito.io", w.id); strings.Join(h, " ") != "stale" { t.Fatalf("held %v, want the stale incarnation's row", h) } if h := held("acme.go.tito.io", "mv_forged"); strings.Join(h, " ") != "forged" { t.Fatalf("held %v, want the forged move's row", h) } if h := held("kass.carlosapp.dev", w.id); strings.Join(h, " ") != "elsewhere" { t.Fatalf("held %v, want the other app's host's row", h) } // A claim gone (retired outside the console's door): the instance's own // row is held too, never written. queue("acme.go.tito.io", w.id, "retired", inc) claimKey, err := hostclaim.Key("acme.go.tito.io") if err != nil { t.Fatal(err) } if err := w.fx.rel.Delete(context.Background(), claimKey); err != nil { t.Fatal(err) } if err := w.passErr(); err != nil { t.Fatal(err) } if h := held("acme.go.tito.io", w.id); strings.Join(h, " ") != "stale retired" { t.Fatalf("held %v", h) } if moveLogOf(t, w)["retired"].Identity != "" { t.Fatal("a row whose claim is gone was written") } } // Final fix, ruling 1: a confirmed row whose delivery failed, and whose move // a later move then replaced as the record's last, is refused by the writer // (the record names neither) and held: never written, never retried, warned // of once, its bytes kept until its incarnation's purge. func TestARefusedConfirmedRowIsHeldNotDeleted(t *testing.T) { journal := captureLog(t) w := landingMovePass(t, "code-mvpass-held") committedAndOpened(t, w) w.pass(t) w.advance(moveCloseGrace + time.Minute) unblock := blockMoveLog(t, w) w.pass(t) // the close; its entry's delivery fails w.pass(t) // the release inc := w.claim(t).Holder.Incarnation j17SetRecord(t, w.fx, func(r *provision.Record) { r.LastMove = &provision.MoveOutcome{ID: "mv_later", Outcome: "done", At: time.Now().UTC()} }) unblock() for i := 0; i < 3; i++ { w.advance(2 * time.Hour) w.pass(t) } if _, ok := moveLogOf(t, w)["done"]; ok { t.Fatal("a row whose move the record no longer names was written") } got, err := w.fx.st.MoveLogPending("acme.go.tito.io", w.id) if err != nil { t.Fatal(err) } var done *MoveLogPendingEntry for i := range got { if got[i].Name == "done" { done = &got[i] } } if done == nil || !done.Held || !done.Confirmed || len(done.Body) == 0 { t.Fatalf("the refused row was not kept and held: %+v", got) } if n := strings.Count(journal.String(), "the log of move "+w.id+" at done is held"); n != 1 { t.Fatalf("%d held warnings, want one:\n%s", n, journal.String()) } if err := w.fx.st.PurgeMoveLogIncarnation("acme.go.tito.io", inc); err != nil { t.Fatal(err) } if got, _ := w.fx.st.MoveLogPending("acme.go.tito.io", w.id); len(got) != 0 { t.Fatalf("the incarnation's purge left %+v", got) } } // declaredLostEntries counts the move's log objects named // rolling_back-target-lost. func declaredLostEntries(t *testing.T, w *movePassWorld) int { t.Helper() got, err := moves.ReadLog(context.Background(), w.fx.rel, moves.ReportPrefix("bab", "titogo", "acme.go.tito.io", w.id)) if err != nil { t.Fatal(err) } n := 0 for _, ev := range got { if ev.Identity == "rolling_back-target-lost" { n++ } } return n } // Final review I4: declared_lost is logged by the console that performs the // declaration, as claim_released is: queued unconfirmed before the // declaration, confirmed once it succeeds, and a row left unconfirmed is // settled by a later pass from the loss the claim records. The declaration // moves the target on to released within the request, so no box pass ever // sees it lost; the event is still logged, once. func TestDeclaredLostIsLoggedByTheConsole(t *testing.T) { declare := func(t *testing.T, code string) (*movePassWorld, string, string, hostfence.Submission) { t.Helper() fx, token, moveURL := j4LandingMove(t, code) w := newMovePassWorld(t, fx, j17MoveState(t, fx).ID) c, _, out := rawReq(t, http.MethodPost, moveURL+"/resolve", token, `{"declare_lost":"uk-box"}`) if c != http.StatusOK { t.Fatalf("inspect = %d %s", c, out) } return w, token, moveURL, j4Submission(t, fx, out) } t.Run("the declaration completes before any box pass", func(t *testing.T) { w, token, moveURL, sub := declare(t, "code-mvlog-declared") body := j4Body(t, map[string]any{"declare_lost": "uk-box", "submission": sub}) if c, _, out := rawReq(t, http.MethodPost, moveURL+"/resolve", token, body); c != http.StatusAccepted { t.Fatalf("declare = %d %s", c, out) } if rb := w.record(t).Move.Rollback; rb == nil || rb.TargetPhase != provision.RbTargetReleased { t.Fatalf("the declaration did not move the target on: %+v", rb) } w.pass(t) ev := moveLogOf(t, w)["rolling_back-target-lost"] if ev.Event != "declared_lost" || ev.Actor != "console" || ev.Op != w.id || ev.Fields["from"] != "ie" || ev.Fields["to"] != "uk" { t.Fatalf("declared_lost %+v in %+v", ev, moveLogOf(t, w)) } // A replay of the same declaration, and more passes, log nothing more. if c, _, out := rawReq(t, http.MethodPost, moveURL+"/resolve", token, body); c != http.StatusAccepted { t.Fatalf("replay = %d %s", c, out) } w.pass(t) w.pass(t) if n := declaredLostEntries(t, w); n != 1 { t.Fatalf("%d declared_lost entries, want one", n) } noPendingLog(t, w) }) t.Run("a crash between the declaration and its confirmation", func(t *testing.T) { w, token, moveURL, sub := declare(t, "code-mvlog-declared-crash") if c, _, out := rawReq(t, http.MethodPost, moveURL+"/resolve", token, j4Body(t, map[string]any{"declare_lost": "uk-box", "submission": sub})); c != http.StatusAccepted { t.Fatalf("declare = %d %s", c, out) } // As if the console stopped after the declaration and before the // confirm. res, err := w.fx.st.db.Exec(`UPDATE move_log_outbox SET confirmed = 0 WHERE op = ? AND name = 'rolling_back-target-lost'`, w.id) if err != nil { t.Fatal(err) } if n, _ := res.RowsAffected(); n != 1 { t.Fatalf("the declaration queued %d rows, want one", n) } w.pass(t) if ev := moveLogOf(t, w)["rolling_back-target-lost"]; ev.Event != "declared_lost" { t.Fatalf("the committed loss's entry was not settled and published: %+v", moveLogOf(t, w)) } noPendingLog(t, w) }) t.Run("a declaration that is refused publishes nothing", func(t *testing.T) { w, token, moveURL, sub := declare(t, "code-mvlog-declared-stale") j17SetRecord(t, w.fx, func(r *provision.Record) { r.Move.LandingPhase = provision.LandProbed }) if c, _, out := rawReq(t, http.MethodPost, moveURL+"/resolve", token, j4Body(t, map[string]any{"declare_lost": "uk-box", "submission": sub})); c != http.StatusConflict { t.Fatalf("stale = %d %s", c, out) } if p := pendingLog(t, w); strings.Join(p, " ") != "rolling_back-target-lost(unconfirmed)" { t.Fatalf("pending %v, want the declaration's row unconfirmed", p) } // Final re-review 1, I4: the move can still be declared lost, so the // row is kept, unpublished, however many passes run. w.pass(t) w.advance(2 * time.Hour) w.pass(t) if n := declaredLostEntries(t, w); n != 0 { t.Fatalf("a refused declaration published %d entries", n) } if p := pendingLog(t, w); strings.Join(p, " ") != "rolling_back-target-lost(unconfirmed)" { t.Fatalf("pending %v, want the row kept while the move can still be declared lost", p) } // The claim gone (the incarnation retired): the row is dropped. key, err := hostclaim.Key("acme.go.tito.io") if err != nil { t.Fatal(err) } if err := w.fx.rel.Delete(context.Background(), key); err != nil { t.Fatal(err) } w.advance(2 * time.Hour) w.pass(t) noPendingLog(t, w) }) // Final re-review 1, I4: the drainer reads the claim with no loss in it; // the declaration then commits and confirms its row; the drainer, going on // from its earlier read, must not drop the row. It survives and is // published once. t.Run("a declaration that commits while the drainer settles its row", func(t *testing.T) { w, token, moveURL, sub := declare(t, "code-mvlog-declared-race") rec := w.record(t) e, ok := moves.DeclaredLost(rec.Move) if !ok { t.Fatal("no entry for the fixture's move") } // A declaration in flight: its row queued, its claim CAS not yet. o := hostops.ConsoleMoveObservation{Host: rec.Host, OpID: rec.Move.ID, Incarnation: rec.Move.Incarnation} w.fx.srv.queueMoveLogAs(o, e, w.fx.srv.movesNow(), false) declared := false w.fx.srv.moveLogSettleHook = func() { if declared { return } declared = true if c, _, out := rawReq(t, http.MethodPost, moveURL+"/resolve", token, j4Body(t, map[string]any{"declare_lost": "uk-box", "submission": sub})); c != http.StatusAccepted { t.Errorf("declare = %d %s", c, out) } } w.pass(t) if !declared { t.Fatal("the drainer never settled the row") } if p := pendingLog(t, w); strings.Join(p, " ") != "rolling_back-target-lost" { t.Fatalf("pending %v: the row the declaration confirmed was dropped", p) } w.advance(2 * time.Hour) w.pass(t) w.pass(t) if n := declaredLostEntries(t, w); n != 1 { t.Fatalf("%d declared_lost entries, want one", n) } noPendingLog(t, w) }) // Final re-review 1, I4: a declaration whose row cannot be queued is // refused, through either door, and nothing is declared. t.Run("a row that cannot be queued refuses the declaration", func(t *testing.T) { for _, door := range []string{"move", "host"} { t.Run(door, func(t *testing.T) { w, token, moveURL, sub := declare(t, "code-mvlog-declared-noqueue-"+door) url, body := moveURL+"/resolve", j4Body(t, map[string]any{"declare_lost": "uk-box", "submission": sub}) if door == "host" { url, body = j4HostDoor(t, w.fx), j4Body(t, map[string]any{"action": "declare-lost", "submission": sub}) } before := j4World(t, w.fx) if _, err := w.fx.st.db.Exec(`DROP TABLE move_log_outbox`); err != nil { t.Fatal(err) } if c, _, out := rawReq(t, http.MethodPost, url, token, body); c == http.StatusAccepted || c == http.StatusOK { t.Fatalf("declare with no outbox = %d %s, want a refusal", c, out) } if j4World(t, w.fx) != before { t.Fatal("a declaration whose log row could not be queued wrote") } }) } }) } // j4HostDoor registers the host operator door on fx (NewServer registers it // only with the host claim on at build) and returns its resolve URL for the // j4 host. func j4HostDoor(t *testing.T, fx *consoleFixture) string { t.Helper() fx.srv.cfg.Bucket = moveTestBucket fx.srv.cliRoute("POST /api/cli/ops/hosts/{host}/resolve/inspect", svcrole.Set{}, fx.srv.handleAPIHostResolveInspect) fx.srv.cliRoute("POST /api/cli/ops/hosts/{host}/resolve", svcrole.Set{}, fx.srv.handleAPIHostResolve) if err := hostfloor.Publish(context.Background(), fx.rel, release.RootSigner(fx.priv), moveTestBucket, hostfloor.Floor{Min: 1, MinRelease: "v1.0.0"}); err != nil { t.Fatal(err) } return fx.ts.URL + "/api/cli/ops/hosts/" + j4Host + "/resolve" } // Final re-review 1, N1: only a declaration whose signed consequence is the // loss of the move's target (the rollback path, move-target-lost) is // declared_lost. A destroyed-local-only declaration, here for a committed // move's retired source, changes no move state and logs no move event, // through either door. func TestDestroyedLocalOnlyLogsNoMoveEvent(t *testing.T) { for _, door := range []string{"move", "host"} { t.Run(door, func(t *testing.T) { ctx := context.Background() fx, token, moveURL := j4LandingMove(t, "code-mvlog-localonly-"+door) w := newMovePassWorld(t, fx, j17MoveState(t, fx).ID) obs, err := hostclaim.Read(ctx, fx.rel, j4Host) if err != nil { t.Fatal(err) } if _, err := hostclaim.Update(ctx, fx.rel, obs, func(c *hostclaim.Claim) error { c.Op.Phase = hostclaim.PhaseCommitted c.Obligations = append(c.Obligations, hostclaim.Obligation{ID: "local", Op: w.id, Kind: "park-local", Box: "ie-box", Retirement: "ret-local", Owner: "box:ie-box"}) return nil }); err != nil { t.Fatal(err) } committed := time.Now().UTC() j17SetRecord(t, fx, func(r *provision.Record) { r.Move.State, r.Move.CommittedAt = provision.MoveCommitted, &committed }) inspectURL, inspectBody, declURL := moveURL+"/resolve", `{"declare_lost":"ie-box"}`, moveURL+"/resolve" if door == "host" { base := j4HostDoor(t, fx) inspectURL, inspectBody, declURL = base+"/inspect", `{"action":"declare-lost","box":"ie-box"}`, base } c, _, out := rawReq(t, http.MethodPost, inspectURL, token, inspectBody) if c != http.StatusOK || !strings.Contains(out, "destroyed-local-only") { t.Fatalf("inspect = %d %s, want a destroyed-local-only challenge", c, out) } sub := j4Submission(t, fx, out) body := j4Body(t, map[string]any{"declare_lost": "ie-box", "submission": sub}) if door == "host" { body = j4Body(t, map[string]any{"action": "declare-lost", "submission": sub}) } if c, _, out := rawReq(t, http.MethodPost, declURL, token, body); c != http.StatusAccepted && c != http.StatusOK { t.Fatalf("declare = %d %s", c, out) } if m := w.record(t).Move; m.State != provision.MoveCommitted { t.Fatalf("a local-only declaration changed the move: %+v", m) } if p := pendingLog(t, w); len(p) != 0 { t.Fatalf("a local-only declaration queued %v", p) } w.pass(t) if n := declaredLostEntries(t, w); n != 0 { t.Fatalf("a local-only declaration logged %d declared_lost entries", n) } }) } } // ---- the target fence (moves after claim Plan 12, Task 5, ruling Q8) ---- // mvTargetFence is a target fence reference, on values. var mvTargetFence = hostclaim.FenceRef{Enrollment: strings.Repeat("b", 32), Key: "control/box-fences/" + strings.Repeat("b", 32) + ".json", SHA256: strings.Repeat("c", 64)} // TestRecoveryPassTargetFenceDecision: on values, when the target's fence has // a step left for the grant, and where it sits in the order (Q8): after the // flip, ahead of the claim's rollback half and the deadline's rollback, and // never once the record carries the consumed fence as its evidence. A dirty // target's fence comes after the rollback half, since the grant takes // neither half of it. func TestRecoveryPassTargetFenceDecision(t *testing.T) { ref := mvTargetFence past := mvT0.Add(-time.Hour) target := func(phase string, dirty bool) func(*provision.Record) { return func(r *provision.Record) { r.Move.Rollback.TargetPhase, r.Move.Rollback.Dirty = phase, dirty } } lost := func(key string) func(*provision.Record) { return func(r *provision.Record) { r.Move.Rollback.TargetPhase, r.Move.Rollback.LossRef = provision.RbTargetLost, key } } committedLoss := func(r *provision.Record) { r.Move.Rollback.TargetPhase, r.Move.Rollback.LossRef, r.Move.Rollback.Evidence = provision.RbTargetReleased, ref.Key, ref.Key } restoring := func(phase, exec string) *hostclaim.Claim { return mvClaim(hostclaim.KindRestoring, phase, func(c *hostclaim.Claim) { c.Op.Exec = exec }) } for _, c := range []struct { name string claim *hostclaim.Claim rec provision.Record consumed bool action moveRecoveryAction half hostops.MoveRecoveryClaimAction }{ {"moving/sealed, record landing: the flip, never the fence", mvClaim(hostclaim.KindMoving, hostclaim.PhaseSealed), mvRecord(provision.MoveLanding), false, moveActClaim, hostops.RecoveryMoveFlip}, {"a landing: the fence rolls the record back", mvClaim(hostclaim.KindLanding, "probing"), mvRecord(provision.MoveLanding), false, moveActFence, ""}, {"a landing past its deadline: the fence, not the deadline's rollback", mvClaim(hostclaim.KindLanding, "probing"), mvRecord(provision.MoveLanding, func(r *provision.Record) { r.Move.LandingDeadline = &past }), false, moveActFence, ""}, {"rolling back, the claim landing: the fence, not the rollback half", mvClaim(hostclaim.KindLanding, "probing"), mvRecord(provision.MoveRollingBack), false, moveActFence, ""}, {"rolling back, the target lost under this fence: the fence (its claim half)", mvClaim(hostclaim.KindLanding, "probing"), mvRecord(provision.MoveRollingBack, lost(ref.Key)), false, moveActFence, ""}, {"rolling back, the target lost under another loss (J4): not the fence", restoring(hostclaim.PhaseReleased, "none"), mvRecord(provision.MoveRollingBack, lost("control/host-loss/other")), false, moveActNone, ""}, {"released clean, the claim restoring/releasing under the target: the fence", restoring(hostclaim.PhaseReleasing, "uk-box"), mvRecord(provision.MoveRollingBack, target(provision.RbTargetReleased, false)), false, moveActFence, ""}, {"released clean, the claim past releasing: not the fence", restoring(hostclaim.PhaseClaimed, "ie-box"), mvRecord(provision.MoveRollingBack, target(provision.RbTargetReleased, false)), false, moveActNone, ""}, {"cleaned: nothing left for the fence", restoring(hostclaim.PhaseOpened, "ie-box"), mvRecord(provision.MoveRollingBack, target(provision.RbTargetCleaned, false)), false, moveActNone, ""}, {"dirty, the claim landing: the rollback half first", mvClaim(hostclaim.KindLanding, "probing"), mvRecord(provision.MoveRollingBack, target(provision.RbTargetReleased, true)), false, moveActClaim, hostops.RecoveryMoveRollback}, {"dirty, the claim restoring: the fence (which leaves it to J4)", restoring(hostclaim.PhaseReleasing, "uk-box"), mvRecord(provision.MoveRollingBack, target(provision.RbTargetReleased, true)), false, moveActFence, ""}, {"a committed landing: never the fence", mvClaim(hostclaim.KindLanding, hostclaim.PhaseCommitted), mvRecord(provision.MoveLanding), false, moveActNone, ""}, {"consumed, the loss not yet on the record: the fence", restoring(hostclaim.PhaseReleased, "none"), mvRecord(provision.MoveRollingBack, lost(ref.Key)), true, moveActFence, ""}, {"consumed, LossRef and Evidence the fence: stop", restoring(hostclaim.PhaseReleased, "none"), mvRecord(provision.MoveRollingBack, committedLoss), true, moveActNone, ""}, {"consumed, the target released on its own evidence: stop", restoring(hostclaim.PhaseReleased, "none"), mvRecord(provision.MoveRollingBack, target(provision.RbTargetReleased, false)), true, moveActNone, ""}, } { t.Run(c.name, func(t *testing.T) { got := decideMoveRecovery(moveRecoveryInput{Now: mvT0, Claim: c.claim, Rec: c.rec, TargetFence: &ref, TargetFenceConsumed: c.consumed}) if got.Action != c.action || got.Claim != c.half || got.Record != "" { t.Fatalf("decided %+v, want %s %s", got, c.action, c.half) } }) } // With no fence, a landing past its deadline is the deadline's rollback, // as before. d := decideMoveRecovery(moveRecoveryInput{Now: mvT0, Claim: mvClaim(hostclaim.KindLanding, "probing"), Rec: mvRecord(provision.MoveLanding, func(r *provision.Record) { r.Move.LandingDeadline = &past })}) if d.Action != moveActRecord || d.Record != hostops.RecoveryMoveDeadlineRollback { t.Fatalf("no fence, past the deadline: %+v", d) } } // fencedTargetWorld is the landing world (j4LandingMove) with its target, // uk-box, terminated: the regional worker's fence for it in the bucket, and // the pass's fence authority binding it to uk. calls lists the fences the // pass's fence calls named. func fencedTargetWorld(t *testing.T, code string) (*movePassWorld, hostclaim.FenceRef, func() []hostclaim.FenceRef) { t.Helper() w := landingMovePass(t, code) w.auth = oneBoxFenceAuthority{c7MoveAuthority{region: "uk"}} ref := terminatedSourceFence(t, w.fx, "uk-box", "ie-box") if c := w.claim(t); c.Op.Intent["target_enrollment"] != ref.Enrollment { t.Fatalf("the fence is not the target's: %s, claim %s", ref.Enrollment, c.Op.Intent["target_enrollment"]) } var mu sync.Mutex var seen []hostclaim.FenceRef w.fx.srv.moveFenceCall = func(r hostclaim.FenceRef) { mu.Lock(); seen = append(seen, r); mu.Unlock() } return w, ref, func() []hostclaim.FenceRef { mu.Lock() defer mu.Unlock() return append([]hostclaim.FenceRef(nil), seen...) } } // TestRecoveryPassReleasesAFencedTargetInThreePasses (Q8): a landing whose // target was terminated. The grant takes one step a pass, record first: the // record's rollback with the target lost under the fence, then the claim's // release that consumes it, then the record's loss commit (released, the // fence as its evidence). Each pass writes one object; the fourth writes // nothing. The console logs its writes: the rollback, the claim's rollback // and the target's release. func TestRecoveryPassReleasesAFencedTargetInThreePasses(t *testing.T) { w, ref, calls := fencedTargetWorld(t, "code-mvpass-fence") claim := claimBytes(t, w.fx, j4Host) w.pass(t) rec := w.record(t) rb := rec.Move.Rollback if rec.Move.State != provision.MoveRollingBack || rec.Region != "ie" || rb == nil || rb.Reason != provision.RollbackTargetFenced || rb.TargetPhase != provision.RbTargetLost || rb.LossRef != ref.Key { t.Fatalf("the first pass: region %s %+v %+v", rec.Region, rec.Move, rb) } if claimBytes(t, w.fx, j4Host) != claim { t.Fatal("the record's pass wrote the claim too") } w.pass(t) c := w.claim(t) if got, ok := hostclaim.ConsumedMoveTargetFence(c); !ok || got != ref || c.Op.Kind != hostclaim.KindRestoring { t.Fatalf("the second pass did not consume the fence: %+v %v %+v", got, ok, c.Op) } if after := w.record(t); after.RecordSeq != rec.RecordSeq { t.Fatalf("the claim's pass wrote the record: %d after %d", after.RecordSeq, rec.RecordSeq) } claim = claimBytes(t, w.fx, j4Host) w.pass(t) rec = w.record(t) rb = rec.Move.Rollback if rb.TargetPhase != provision.RbTargetReleased || rb.Dirty || rb.Evidence != ref.Key || rb.LossRef != ref.Key { t.Fatalf("the third pass did not commit the loss on the record: %+v", rb) } if claimBytes(t, w.fx, j4Host) != claim { t.Fatal("the record's loss commit wrote the claim") } w.pass(t) if after := w.record(t); after.RecordSeq != rec.RecordSeq || claimBytes(t, w.fx, j4Host) != claim { t.Fatalf("the fourth pass wrote: record %d after %d", after.RecordSeq, rec.RecordSeq) } for i, r := range calls() { if r != ref { t.Fatalf("call %d named %+v, not the target's fence %+v", i, r, ref) } } log := moveLogOf(t, w) if ev := log["rolling_back"]; ev.Actor != "console" || ev.Fields["reason"] != provision.RollbackTargetFenced { t.Fatalf("the fenced rollback's entry: %+v in %+v", ev, log) } if ev := log["rolling_back-target-released"]; ev.Actor != "console" || ev.Event != provision.RbTargetReleased { t.Fatalf("the loss commit's entry: %+v in %+v", ev, log) } if ev := log["claim-rollback"]; ev.Actor != "console" || ev.Event != "claim_rollback" { t.Fatalf("the claim release's rollback entry: %+v in %+v", ev, log) } if p := w.paged(t); len(p) != 0 { t.Fatalf("a clean fenced target paged: %+v", p) } } // TestRecoveryPassFenceBeatsTheDeadlineRollback (Q8): a landing past its // deadline whose target was terminated is rolled back by the fence (the // grant does both halves), not by the deadline. func TestRecoveryPassFenceBeatsTheDeadlineRollback(t *testing.T) { w, ref, _ := fencedTargetWorld(t, "code-mvpass-fence-deadline") past := time.Now().UTC().Add(-time.Minute) j17SetRecord(t, w.fx, func(r *provision.Record) { r.Move.LandingDeadline = &past }) w.pass(t) rb := w.record(t).Move.Rollback if rb == nil || rb.Reason != provision.RollbackTargetFenced || rb.TargetPhase != provision.RbTargetLost || rb.LossRef != ref.Key { t.Fatalf("the deadline won: %+v", rb) } } // TestRecoveryPassFlipsBeforeTheFence (Q8): with the claim still moving/sealed // and the record landing, the pass writes the flip and does not call the // fence (the grant refuses a moving claim). The fence follows on the next // pass. func TestRecoveryPassFlipsBeforeTheFence(t *testing.T) { d := decideMoveRecovery(moveRecoveryInput{Now: mvT0, Claim: mvClaim(hostclaim.KindMoving, hostclaim.PhaseSealed), Rec: mvRecord(provision.MoveLanding), TargetFence: &mvTargetFence}) if d.Action != moveActClaim || d.Claim != hostops.RecoveryMoveFlip { t.Fatalf("decided %+v, want the flip", d) } w, ref, calls := fencedTargetWorld(t, "code-mvpass-fence-flip") w.setClaim(t, func(c *hostclaim.Claim) { c.Op.Kind, c.Op.Phase, c.Op.Exec = hostclaim.KindMoving, hostclaim.PhaseSealed, "" c.Op.Participants = []string{"ie-box", "uk-box"} }) w.pass(t) if c := w.claim(t); c.Op.Kind != hostclaim.KindLanding { t.Fatalf("not flipped: %+v", c.Op) } if n := len(calls()); n != 0 { t.Fatalf("the flip's pass called the fence %d times", n) } if m := w.record(t).Move; m.State != provision.MoveLanding { t.Fatalf("the flip's pass rolled the record back: %+v", m) } w.pass(t) if rb := w.record(t).Move.Rollback; rb == nil || rb.LossRef != ref.Key { t.Fatalf("the fence did not follow the flip: %+v", rb) } } // TestRecoveryPassLeavesADirtyFencedTargetToJ4AndPagesOnce (Q8): a target // terminated after it released dirty holds writes the source does not have. // The grant refuses it (no return lane can be built from a dead box), so the // pass writes nothing for the fence, pages once that an operator must declare // the target lost, and leaves it for J4. func TestRecoveryPassLeavesADirtyFencedTargetToJ4AndPagesOnce(t *testing.T) { w, _, calls := fencedTargetWorld(t, "code-mvpass-fence-dirty") rbID := dirtyFencedRollback(t, w) w.pass(t) // the claim's rollback half, which the fence does not take for a dirty target if c := w.claim(t); c.Op.Kind != hostclaim.KindRestoring || c.Op.Intent["rollback"] != rbID { t.Fatalf("the rollback half: %+v", c.Op) } if n := len(calls()); n != 0 { t.Fatalf("the fence was called before the rollback half: %d", n) } claim, rec := claimBytes(t, w.fx, j4Host), w.record(t) w.pass(t) w.pass(t) w.advance(2 * time.Hour) w.pass(t) if n := len(calls()); n == 0 { t.Fatal("the fence was never tried: its verification is the page's evidence") } if after := w.record(t); after.RecordSeq != rec.RecordSeq || claimBytes(t, w.fx, j4Host) != claim { t.Fatalf("a dirty fenced target was written: %+v", after.Move.Rollback) } p := w.paged(t) if len(p) != 1 { t.Fatalf("pages %+v, want one", p) } subject, body := moveTargetFencedDirtyPage(j4Host, w.id, "uk-box", "uk", "ie") if p[0].Level != alerting.LevelIncident || p[0].Subject != subject || p[0].Body != body { t.Fatalf("the page: %+v", p[0]) } if !strings.Contains(body, "--declare-lost uk-box") || !strings.Contains(body, j4Host) { t.Fatalf("the page does not say how to declare the target lost: %q", body) } } // dirtyFencedRollback puts the fenced world at a rollback whose target // released dirty, the claim still landing, and returns the rollback's id. func dirtyFencedRollback(t *testing.T, w *movePassWorld) string { t.Helper() rbID, at := newRollbackID(t), time.Now().UTC().Add(-time.Minute) deadline := at.Add(time.Hour) j17SetRecord(t, w.fx, func(r *provision.Record) { r.Region = "ie" r.Move.State = provision.MoveRollingBack r.Move.Rollback = &provision.MoveRollback{ID: rbID, RequestedAt: &at, Reason: provision.RollbackLandingDeadline, TargetPhase: provision.RbTargetReleased, Dirty: true, SourcePhase: provision.RbSourceWaiting, ReleaseDeadline: &deadline} }) return rbID } // TestRecoveryPassPagesOnlyAVerifiedDirtyTarget (Task 5 fix round 1, item // 1): the dirty page rests only on the grant's verified-dirty outcome. The // move's registration withdrawn from the admission between the pass's // observation and the fence call makes the grant answer ErrPending before it // verifies anything: the pass sends no page, then or on a later pass. func TestRecoveryPassPagesOnlyAVerifiedDirtyTarget(t *testing.T) { w, _, calls := fencedTargetWorld(t, "code-mvpass-fence-dirty-admission") dirtyFencedRollback(t, w) w.pass(t) // the claim's rollback half ctx := context.Background() withdraw := func(hostclaim.FenceRef) { body, etag, err := w.fx.rel.Get(ctx, "apps/bab/titogo/admission.json") if err != nil { t.Error(err) return } var a hostops.AppAdmission if err := json.Unmarshal(body, &a); err != nil { t.Error(err) return } if _, ok := a.Registrations[w.id]; !ok { return } delete(a.Registrations, w.id) if body, err = json.Marshal(a); err != nil { t.Error(err) return } if _, err := w.fx.rel.Put(ctx, "apps/bab/titogo/admission.json", body, etag); err != nil { t.Error(err) } } w.fx.srv.moveFenceCall = withdraw w.pass(t) w.pass(t) if len(calls()) != 0 { t.Fatal("the seam was replaced; the world's own counter should not run") } if p := w.paged(t); len(p) != 0 { t.Fatalf("paged without a verified fence: %+v", p) } } // TestRecoveryPassLogsOnlyItsOwnFenceWrites (Task 5 fix round 1, item 2): // the console logs a fence step from the grant's own evidence, never from a // record read after it. A box's record write that lands just after the // grant's write (the claim's release, then the record's rollback) is not // logged as the console's, and the console's own entries are all there: // claim_rollback for the claim's step, rolling_back for the record's. func TestRecoveryPassLogsOnlyItsOwnFenceWrites(t *testing.T) { recordKey := provision.RecordKey("bab", "titogo", j4Host) claimKey, err := hostclaim.Key(j4Host) if err != nil { t.Fatal(err) } // landAfter writes the record once, as the source box would (its // rollback's source phase), right after the next accepted Put of key. landAfter := func(t *testing.T, w *movePassWorld, key string) *bool { t.Helper() st := w.fx.rel.(*deletableStore) landed := new(bool) st.afterPut = func(_ context.Context, k string) { if k != key { return } st.afterPut = nil *landed = true j17SetRecord(t, w.fx, func(r *provision.Record) { if r.Move != nil && r.Move.Rollback != nil { r.Move.Rollback.SourcePhase = provision.RbSourceRestoring } }) } t.Cleanup(func() { st.afterPut = nil }) return landed } notTheConsoles := func(t *testing.T, w *movePassWorld) { t.Helper() if ev, ok := moveLogOf(t, w)["rolling_back-source-"+provision.RbSourceRestoring]; ok { t.Fatalf("the box's write was logged as the console's: %+v", ev) } } t.Run("the claim's step", func(t *testing.T) { w, _, _ := fencedTargetWorld(t, "code-mvpass-fence-log-claim") w.pass(t) // the record's rollback landed := landAfter(t, w, claimKey) w.pass(t) // the claim's release, which rolls the landing claim back if !*landed { t.Fatal("the box's write did not land after the claim's step") } if ev := moveLogOf(t, w)["claim-rollback"]; ev.Actor != "console" || ev.Event != "claim_rollback" { t.Fatalf("the claim's rollback was not logged: %+v in %+v", ev, moveLogOf(t, w)) } notTheConsoles(t, w) }) t.Run("the record's step", func(t *testing.T) { w, _, _ := fencedTargetWorld(t, "code-mvpass-fence-log-record") landed := landAfter(t, w, recordKey) w.pass(t) // the record's rollback if !*landed { t.Fatal("the box's write did not land after the record's step") } log := moveLogOf(t, w) if ev := log["rolling_back"]; ev.Actor != "console" || ev.Fields["reason"] != provision.RollbackTargetFenced { t.Fatalf("the fenced rollback was not logged: %+v in %+v", ev, log) } if _, ok := log["claim-rollback"]; ok { t.Fatalf("a record step logged a claim rollback: %+v", log) } notTheConsoles(t, w) }) } // TestRecoveryPassStopsCallingTheFenceOnceConsumed (Q8): once the claim // carries the consumed fence and the record its loss (LossRef and Evidence // the fence's key), the pass never calls the fence again. func TestRecoveryPassStopsCallingTheFenceOnceConsumed(t *testing.T) { w, ref, calls := fencedTargetWorld(t, "code-mvpass-fence-stop") for range 3 { w.pass(t) } if rb := w.record(t).Move.Rollback; rb == nil || rb.LossRef != ref.Key || rb.Evidence != ref.Key { t.Fatalf("not at the stop condition: %+v", rb) } n := len(calls()) if n != 3 { t.Fatalf("%d fence calls for three steps", n) } for range 3 { w.pass(t) } if got := len(calls()); got != n { t.Fatalf("the fence was called %d more times after its loss was committed", got-n) } } // TestRecoveryPassReadsTheConsumedFenceNotTheBucket (Q8): after the claim // consumed the fence, the pass takes the reference from the claim, never the // bucket: the fence object deleted, the record's loss commit still follows. func TestRecoveryPassReadsTheConsumedFenceNotTheBucket(t *testing.T) { w, ref, calls := fencedTargetWorld(t, "code-mvpass-fence-consumed") w.pass(t) w.pass(t) if _, ok := hostclaim.ConsumedMoveTargetFence(w.claim(t)); !ok { t.Fatal("the fence was not consumed in two passes") } if err := w.fx.rel.(*deletableStore).Delete(context.Background(), ref.Key); err != nil { t.Fatal(err) } w.pass(t) if rb := w.record(t).Move.Rollback; rb == nil || rb.TargetPhase != provision.RbTargetReleased || rb.Evidence != ref.Key { t.Fatalf("the loss commit did not follow the deleted fence: %+v", rb) } if got := calls(); len(got) != 3 || got[2] != ref { t.Fatalf("the third call: %+v", got) } }