moves-phase1-6 Task 3 fix round 1: retryable log writes, recovery attempts, console outcomes, shared templates
- A log write is remembered only once it succeeds; a failure retries at the next sighting. A terminal event drops the move's memo entries. - Recovery probe attempts log probe_attempt-<epoch>-<n> from the attempt journal (movesProbeAttempts.RecoveryAttempt). - The console move pass logs its closes, the deadline rollback, the six-hour abort and the claim's release and rollback, through MoveRecoveryGrant.Log (create-only, the move's own prefix, while the hook runs). - moves.TransitionOf names transitions for box and console alike, with the evidence's digests, a stuck's role and the recovery timings. - Shared operator templates in internal/moves/operatorcopy.go (L12); move.go and the member stream use them; File cells moved. The home region is "the home region" (MV-N381, pending). The copy gate reads calls into registered templates of another package.
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
17 files changed,
+1017
−240
approved_moves_copy_scan_test.go+122 −3approved_moves_copy_test.go+10 −2docs/superpowers/plans/2026-10-06-moves-phase1-copy.md+9 −8internal/console/movesrecovery.go+61 −2internal/console/movesrecovery_test.go+54 −0internal/host/movesevents.go+107 −198internal/host/movesevents_test.go+248 −3internal/host/movespass.go+1 −1internal/host/movesprobeattempts.go+31 −2internal/host/movesrecover_test.go+2 −1internal/host/movesrevert_test.go+2 −1internal/host/movesrollback_test.go+2 −1internal/hostops/move_recovery_grant.go+27 −2internal/hostops/move_recovery_grant_test.go+61 −0internal/moves/operatorcopy.go+66 −0internal/moves/transition.go+205 −0move.go+9 −16
diff --git a/approved_moves_copy_scan_test.go b/approved_moves_copy_scan_test.go| index 3139e1279..1de9a25b0 100644 |
| --- a/approved_moves_copy_scan_test.go |
| +++ b/approved_moves_copy_scan_test.go |
| @@ -8,6 +8,7 @@ import ( |
| "go/token" |
| "os" |
| "path/filepath" |
| + "slices" |
| "sort" |
| "strconv" |
| "strings" |
| @@ -1333,6 +1334,12 @@ func (c *evalCtx) resolveCallees(e *ast.CallExpr) ([]*ast.FuncDecl, *problem) { |
| // Hard: an error's text is never a placeholder either. |
| return nil, &problem{fmt.Sprintf("%s forwards an error's text", render(e)), true} |
| } |
| + if d, ok, prob := c.importedCallee(fn); ok { |
| + if prob != nil { |
| + return nil, prob |
| + } |
| + return []*ast.FuncDecl{d}, nil |
| + } |
| if x, ok := fn.X.(*ast.Ident); ok && c.fd != nil && declCount(c.fd, x.Name) > 1 { |
| // The gate types a receiver by its first declaration. A receiver |
| // declared again (if m := supplied; ...) may be another type. |
| @@ -1360,6 +1367,86 @@ func (c *evalCtx) resolveCallees(e *ast.CallExpr) ([]*ast.FuncDecl, *problem) { |
| return bad("%s is not a call the gate can read", render(e)) |
| } |
| +// movesModule is the module path a cross-package call must stay inside. |
| +const movesModule = "github.com/carlosframework/platform/" |
| + |
| +// movesImportCache holds each scanned file's imports, name to path. |
| +var movesImportCache = map[string]map[string]string{} |
| + |
| +// fileImports reads file's imports: each one's name (its alias, or its |
| +// path's last element) to its path. |
| +func (c *evalCtx) fileImports() map[string]string { |
| + path := c.u.at(c.file) |
| + if m, ok := movesImportCache[path]; ok { |
| + return m |
| + } |
| + m := map[string]string{} |
| + movesImportCache[path] = m |
| + f, err := parser.ParseFile(token.NewFileSet(), path, nil, parser.ImportsOnly) |
| + if err != nil { |
| + c.u.t.Fatal(err) |
| + } |
| + for _, im := range f.Imports { |
| + p := strings.Trim(im.Path.Value, `"`) |
| + name := p[strings.LastIndex(p, "/")+1:] |
| + if im.Name != nil { |
| + name = im.Name.Name |
| + } |
| + m[name] = p |
| + } |
| + return m |
| +} |
| + |
| +// importedCallee resolves pkg.Func, a call into another package of this |
| +// module (Task 3 fix round 1: the shared templates of |
| +// internal/moves/operatorcopy.go). ok is false when fn is not such a call: |
| +// its X names something this function or package declares, or no import. |
| +// The callee's file must itself be scanned, so its sentences answer to the |
| +// record like any other; a callee anywhere else is refused, as a call out of |
| +// the package always was; so is one the record does not register as |
| +// returning sentences (movesReturnedSentences), so a call into the module's |
| +// other code stays out of the package. The callee is read in its own package's context |
| +// (callDecl's newCtx), with this call's arguments bound. |
| +func (c *evalCtx) importedCallee(fn *ast.SelectorExpr) (d *ast.FuncDecl, ok bool, prob *problem) { |
| + x, isIdent := fn.X.(*ast.Ident) |
| + if !isIdent { |
| + return nil, false, nil |
| + } |
| + if _, local := c.locals[x.Name]; local || (c.fd != nil && declCount(c.fd, x.Name) > 0) { |
| + return nil, false, nil |
| + } |
| + if _, v := c.pkg.vars[x.Name]; v { |
| + return nil, false, nil |
| + } |
| + path, imported := c.fileImports()[x.Name] |
| + if !imported || !strings.HasPrefix(path, movesModule) { |
| + return nil, false, nil |
| + } |
| + dir := strings.TrimPrefix(path, movesModule) |
| + registered := false |
| + for f, fns := range movesReturnedSentences { |
| + if filepath.Dir(f) == dir && fns[fn.Sel.Name] { |
| + registered = true |
| + } |
| + } |
| + if !registered { |
| + return nil, false, nil |
| + } |
| + if _, err := os.Stat(c.u.at(dir)); err != nil { |
| + return nil, false, nil |
| + } |
| + pkg := loadMovesPkg(c.u.t, c.u.at(dir)) |
| + d, found := pkg.funcs[fn.Sel.Name] |
| + if !found { |
| + return nil, false, nil |
| + } |
| + dfile := strings.TrimPrefix(movesFset.Position(d.Pos()).Filename, c.u.root+"/") |
| + if !slices.Contains(c.u.files, dfile) || !movesReturnedSentences[dfile][fn.Sel.Name] { |
| + return nil, false, nil |
| + } |
| + return d, true, nil |
| +} |
| + |
| // declCount counts the declarations of name in fd: its receiver, parameters |
| // and named results, and in its body every := , var, range variable and |
| // closure parameter or result. A := that redeclares in the same scope counts |
| @@ -1565,9 +1652,17 @@ func (c *evalCtx) callDecl(d *ast.FuncDecl, call *ast.CallExpr, pos, depth int) |
| var probs []problem |
| for i, p := range params { |
| if i < len(call.Args) { |
| - a, pr := c.operand(call.Args[i], depth+1) |
| - hc.bind[p] = a |
| - probs = append(probs, pr...) |
| + if onlyFormatArg(d, p) { |
| + // A parameter the helper only passes to a format call as an |
| + // argument is a placeholder there, read as a direct format |
| + // call reads its arguments: for an error's text (below), not |
| + // as a sentence. |
| + hc.bind[p] = []string{wild} |
| + } else { |
| + a, pr := c.operand(call.Args[i], depth+1) |
| + hc.bind[p] = a |
| + probs = append(probs, pr...) |
| + } |
| // An argument that is an error's text may still only select among |
| // sentences; it is refused where the helper puts it in one. |
| if why := dataWhy(c.errorText(call.Args[i], 0)); why != "" { |
| @@ -1611,6 +1706,30 @@ func (c *evalCtx) callDecl(d *ast.FuncDecl, call *ast.CallExpr, pos, depth int) |
| return alts, probs |
| } |
| +// onlyFormatArg is true when every use of the parameter p in d's body is an |
| +// argument, not the format, of a format call (operatorcopy.go's templates). |
| +func onlyFormatArg(d *ast.FuncDecl, p string) bool { |
| + uses, asArg := 0, 0 |
| + ast.Inspect(d.Body, func(n ast.Node) bool { |
| + switch n := n.(type) { |
| + case *ast.Ident: |
| + if n.Name == p { |
| + uses++ |
| + } |
| + case *ast.CallExpr: |
| + if isFormatCall(n) { |
| + for _, a := range n.Args[1:] { |
| + if id, ok := a.(*ast.Ident); ok && id.Name == p { |
| + asArg++ |
| + } |
| + } |
| + } |
| + } |
| + return true |
| + }) |
| + return uses > 0 && uses == asArg && declCount(d, p) == 1 |
| +} |
| + |
| // ---- guarded echo (a mapping helper) ---- |
| func (c *evalCtx) guardedEcho(id *ast.Ident) bool { |
diff --git a/approved_moves_copy_test.go b/approved_moves_copy_test.go| index cca8c8d2c..cf515305c 100644 |
| --- a/approved_moves_copy_test.go |
| +++ b/approved_moves_copy_test.go |
| @@ -81,7 +81,7 @@ var movesCopyIDs = []string{ |
| "MV-N357", "MV-N358", "MV-N359", "MV-N360", "MV-N361", "MV-N362", "MV-N363", "MV-N364", |
| "MV-N365", "MV-N366", "MV-N367", "MV-N368", "MV-N369", "MV-N370", "MV-N371", |
| "MV-N372", "MV-N373", "MV-N374", "MV-N375", "MV-N376", "MV-N377", "MV-N378", "MV-N379", |
| - "MV-N380", |
| + "MV-N380", "MV-N381", |
| } |
| // copyRow is one row of the record. The File cell is the file the sentence is |
| @@ -660,6 +660,7 @@ var movesScanFiles = []string{ |
| "internal/moves/lease.go", |
| "internal/moves/log.go", |
| "internal/moves/ltxbuild.go", |
| + "internal/moves/operatorcopy.go", |
| "internal/moves/parkscope.go", |
| "internal/moves/probe.go", |
| "internal/moves/readiness.go", |
| @@ -671,6 +672,7 @@ var movesScanFiles = []string{ |
| "internal/moves/startcheck.go", |
| "internal/moves/switch.go", |
| "internal/moves/timers.go", |
| + "internal/moves/transition.go", |
| "internal/provision/provision.go", |
| "internal/provision/reconcile.go", |
| "internal/registry/registry.go", |
| @@ -767,8 +769,14 @@ var movesReturnedSentences = map[string]map[string]bool{ |
| "t6NoRoom": true, "t8Count": true, "t12NotQuiet": true, "replicaReason": true}, |
| "internal/host/movesrollback.go": {"stuckPage": true}, |
| // memberLine is what an app's members read for a move event (Plan 6 |
| - // Task 3, preflight L9). |
| + // Task 3, preflight L9), each from a shared template below. |
| "internal/host/movesevents.go": {"memberLine": true}, |
| + // The operator sentences `carlos move` and the member stream share |
| + // (preflight L12, Task 3 fix round 1): one template each, which the |
| + // copy record names. The gate reads a call to one from either package |
| + // (resolveCallees' cross-package rule). |
| + "internal/moves/operatorcopy.go": {"MoveStartingLine": true, "CutStartingLine": true, "FlippedLine": true, |
| + "MovedLine": true, "MovingBackLine": true, "MovedBackLine": true, "StuckMemberLine": true}, |
| // moveDeleteRefusal is M-C19, which the delete door answers (Task 2b). |
| "internal/console/apiinstancemove.go": {"moveDeleteRefusal": true}, |
| // The console's move pass pages (Plan 5 Task 7, MV-N325 to MV-N334). |
diff --git a/docs/superpowers/plans/2026-10-06-moves-phase1-copy.md b/docs/superpowers/plans/2026-10-06-moves-phase1-copy.md| index efeb5d740..9dc8faacf 100644 |
| --- a/docs/superpowers/plans/2026-10-06-moves-phase1-copy.md |
| +++ b/docs/superpowers/plans/2026-10-06-moves-phase1-copy.md |
| @@ -13,15 +13,15 @@ Columns: id, file, text, status. |
| | id | file | text | status | |
| |---|---|---|---| |
| -| M-C1 | move.go | Moving <host> from <from> to <to>. | approved | |
| +| M-C1 | internal/moves/operatorcopy.go | Moving <host> from <from> to <to>. | approved | |
| | M-C2 | move.go | Copying data. <host> keeps serving while this runs. | approved | |
| | M-C3 | move.go | Checking that <to> can run <host>. | approved | |
| | M-C4 | move.go | <to> cannot take this move yet: <check>. | approved | |
| -| M-C5 | move.go | <to> is ready. Starting the cut. <host> will be offline for about <estimate>. | approved | |
| -| M-C6 | move.go | Stopped in <from>. Starting in <to>. | approved | |
| -| M-C7 | move.go | Moved. <host> is served from <to>. It was offline for <seconds> seconds. | approved | |
| -| M-C8 | move.go | <to> could not start <host>: <reason>. Moving it back to <from>. | approved | |
| -| M-C9 | move.go | <host> is back in <from> and serving. Nothing was lost. | approved | |
| +| M-C5 | internal/moves/operatorcopy.go | <to> is ready. Starting the cut. <host> will be offline for about <estimate>. | approved | |
| +| M-C6 | internal/moves/operatorcopy.go | Stopped in <from>. Starting in <to>. | approved | |
| +| M-C7 | internal/moves/operatorcopy.go | Moved. <host> is served from <to>. It was offline for <seconds> seconds. | approved | |
| +| M-C8 | internal/moves/operatorcopy.go | <to> could not start <host>: <reason>. Moving it back to <from>. | approved | |
| +| M-C9 | internal/moves/operatorcopy.go | <host> is back in <from> and serving. Nothing was lost. | approved | |
| | M-C10 | move.go | Waiting for <box> in <to> to confirm it has stopped <host>. <host> is offline. | approved | |
| | M-C11 | move.go | <host> could not start in <to> or in <from>. It is offline. Run carlos move resolve --host <host> --retry once the cause is fixed. | approved | |
| | M-C12 | move.go | Ready to cut. Run carlos move cut --host <host> when you are ready. | approved | |
| @@ -299,7 +299,7 @@ Task 7's pages, the console's move pass (`internal/console/movesrecovery.go`, § |
| ## Plan 6 |
| -(completed by Plan 6 Task 7. Task 2 takes MV-N319 to MV-N324, and made the abort door speak M-C13 on a console without the host claim, so M-C13 is now approved verbatim. Task 2b made the delete door speak M-C19 through moveDeleteRefusal in internal/console/apiinstancemove.go, so its File cell moves there (preflight L6) and it is approved verbatim. Task 1a takes MV-N350 to MV-N371 and Task 1b MV-N372 to MV-N379, Task 3 MV-N380 (the member line for stuck, preflight L9) (Plan 5 owns MV-N325 to MV-N349) for `carlos move` (move.go, and its usage line in main.go), and speaks M-C1 to M-C12 and M-C22 verbatim from move.go, so those rows are approved. Task 1b speaks M-C18 verbatim from move.go and MV-N11 from the resolve door of a console without the host claim, so both are approved) |
| +(completed by Plan 6 Task 7. Task 2 takes MV-N319 to MV-N324, and made the abort door speak M-C13 on a console without the host claim, so M-C13 is now approved verbatim. Task 2b made the delete door speak M-C19 through moveDeleteRefusal in internal/console/apiinstancemove.go, so its File cell moves there (preflight L6) and it is approved verbatim. Task 1a takes MV-N350 to MV-N371 and Task 1b MV-N372 to MV-N379, Task 3 MV-N380 (the member line for stuck, preflight L9) and MV-N381 (the name a member line gives the home region, which a box knows only as the record's empty region; Task 3 fix round 1, ruling 4). Task 3 fix round 1 (ruling 6, preflight L12) moved M-C1 and M-C5 to M-C9 into shared templates in internal/moves/operatorcopy.go, which both move.go and the member stream (internal/host/movesevents.go) call, so their File cells, and MV-N380's, name that file; their text is unchanged (Plan 5 owns MV-N325 to MV-N349) for `carlos move` (move.go, and its usage line in main.go), and speaks M-C1 to M-C12 and M-C22 verbatim from move.go, so those rows are approved. Task 1b speaks M-C18 verbatim from move.go and MV-N11 from the resolve door of a console without the host claim, so both are approved) |
| | id | file | text | status | |
| |---|---|---|---| |
| @@ -334,7 +334,8 @@ Task 7's pages, the console's move pass (`internal/console/movesrecovery.go`, § |
| | MV-N377 | move.go | The console asks to confirm a loss carlos move does not know. Use carlos ops host resolve. | pending | |
| | MV-N378 | move.go | carlos move resolve takes --retry or --declare-lost, not both. | pending | |
| | MV-N379 | move.go | The move changed since it was read. Nothing was declared. Run the command again. | pending | |
| -| MV-N380 | internal/host/movesevents.go | <host> could not start in <to> or in <from>. It is offline. An operator has been paged. | pending | |
| +| MV-N380 | internal/moves/operatorcopy.go | <host> could not start in <to> or in <from>. It is offline. An operator has been paged. | pending | |
| +| MV-N381 | internal/moves/operatorcopy.go | the home region | pending | |
| ## Review of 2026-10-09 |
diff --git a/internal/console/movesrecovery.go b/internal/console/movesrecovery.go| index db883ea40..080fa5570 100644 |
| --- a/internal/console/movesrecovery.go |
| +++ b/internal/console/movesrecovery.go |
| @@ -327,11 +327,20 @@ func (s *Server) movesRecovery(ctx context.Context, g *hostops.MoveRecoveryGrant |
| return err |
| } |
| log.Printf("console: moves: %s: move %s is still preparing after %s; aborted", o.Host, o.OpID, moves.AbortAfter) |
| + s.logMoveWrite(ctx, g, o, rec) |
| return nil |
| case moveActClaim: |
| - return g.Claim(ctx, d.Claim) |
| + if err := g.Claim(ctx, d.Claim); err != nil { |
| + return err |
| + } |
| + s.logMoveClaim(ctx, g, o, rec, d.Claim) |
| + return nil |
| case moveActRecord: |
| - return g.Record(ctx, d.Record) |
| + if err := g.Record(ctx, d.Record); err != nil { |
| + return err |
| + } |
| + s.logMoveWrite(ctx, g, o, rec) |
| + return nil |
| case moveActStampLost: |
| if s.stampLostMoveTarget == nil { |
| return hostops.ErrContract |
| @@ -345,6 +354,7 @@ func (s *Server) movesRecovery(ctx context.Context, g *hostops.MoveRecoveryGrant |
| return err |
| } |
| log.Printf("console: moves: %s: move %s closed by the console (%s); the release follows", o.Host, o.OpID, d.Record) |
| + s.logMoveWrite(ctx, g, o, rec) |
| s.pageMove(ctx, movePageCloseOverdue, o, c, rec, now) |
| return nil |
| case moveActAbortOverdue: |
| @@ -514,3 +524,52 @@ func moveAbortOverduePage(host, id, to, box string) (subject, body string) { |
| id, host, to, box, box, box) |
| return subject, body |
| } |
| + |
| +// The move log of the console's own move writes (Plan 6 Task 3, fix round 1, |
| +// ruling 3): the six-hour abort, the landing deadline's rollback, the closes, |
| +// and the claim's release and rollback. The console has no member sink; the |
| +// durable log under the move's report prefix is what counts, written through |
| +// the grant (MoveRecoveryGrant.Log, moves.WriteLog), which names no store. |
| +// Each entry is named as a box's write of the same transition would be |
| +// (moves.TransitionOf) and written create-only, so a box that also logs it |
| +// changes nothing. A failed write is logged and not retried: the pass that |
| +// made the write does not see it again. |
| + |
| +// logMoveWrite logs the record write this pass just made: rec as the pass |
| +// read it, against the record now. |
| +func (s *Server) logMoveWrite(ctx context.Context, g *hostops.MoveRecoveryGrant, o hostops.ConsoleMoveObservation, rec provision.Record) { |
| + after, err := provision.GetRecord(ctx, s.cfg.Releases, o.Account, o.App, o.Host) |
| + if err != nil { |
| + log.Printf("console: moves: %s: the log of move %s: the record: %v", o.Host, o.OpID, err) |
| + return |
| + } |
| + if e, ok := moves.TransitionOf(rec, *after); ok { |
| + s.writeMoveLog(ctx, g, o, e) |
| + } |
| +} |
| + |
| +// logMoveClaim logs a claim write that ends or turns the move: the release |
| +// after a close (or of a start never applied) and the claim's rollback. |
| +func (s *Server) logMoveClaim(ctx context.Context, g *hostops.MoveRecoveryGrant, o hostops.ConsoleMoveObservation, rec provision.Record, action hostops.MoveRecoveryClaimAction) { |
| + var e moves.Transition |
| + switch action { |
| + case hostops.RecoveryMoveRelease, hostops.RecoveryMoveReleaseNotApplied: |
| + e = moves.Transition{Op: o.OpID, Event: "claim_released", Identity: "claim-released"} |
| + case hostops.RecoveryMoveRollback: |
| + e = moves.Transition{Op: o.OpID, Event: "claim_rollback", Identity: "claim-rollback"} |
| + default: |
| + return |
| + } |
| + if m := rec.Move; m != nil { |
| + e.Fields = map[string]string{"from": m.From, "to": m.To} |
| + } |
| + s.writeMoveLog(ctx, g, o, e) |
| +} |
| + |
| +// writeMoveLog writes one console entry. |
| +func (s *Server) writeMoveLog(ctx context.Context, g *hostops.MoveRecoveryGrant, o hostops.ConsoleMoveObservation, e moves.Transition) { |
| + ev := moves.LogEvent{V: 1, Op: e.Op, Host: o.Host, Event: e.Event, Identity: e.Identity, Actor: "console", At: s.movesNow().UTC(), Fields: e.Fields} |
| + if _, err := g.Log(ctx, ev); err != nil { |
| + log.Printf("console: moves: %s: the log of move %s at %s: %v", o.Host, o.OpID, e.Identity, err) |
| + } |
| +} |
diff --git a/internal/console/movesrecovery_test.go b/internal/console/movesrecovery_test.go| index 0e43f0ce7..3148590e4 100644 |
| --- a/internal/console/movesrecovery_test.go |
| +++ b/internal/console/movesrecovery_test.go |
| @@ -719,3 +719,57 @@ func TestConsolePagesThroughAlerting(t *testing.T) { |
| 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: the console's move pass writes the |
| +// durable move log for 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. |
| +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) |
| + } |
| + }) |
| + 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" { |
| + 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)) |
| + } |
| + }) |
| +} |
diff --git a/internal/host/movesevents.go b/internal/host/movesevents.go| index 0ef9d2166..619b61736 100644 |
| --- a/internal/host/movesevents.go |
| +++ b/internal/host/movesevents.go |
| @@ -6,6 +6,7 @@ import ( |
| "log" |
| "math" |
| "strconv" |
| + "strings" |
| "github.com/carlosframework/platform/internal/activator" |
| "github.com/carlosframework/platform/internal/hostclaim" |
| @@ -18,155 +19,35 @@ import ( |
| // |
| // Every record write a box makes for a move goes through observedMove, which |
| // keeps the record as the write found it; logTransition names what the write |
| -// did, from that record and the one written: one event, one identity |
| -// (moves.LogEvent). Transitions another writer made (the console's request, |
| +// did (moves.TransitionOf, which the console's move pass shares): one event, |
| +// one identity. Transitions another writer made (the console's request, |
| // manual cut, abort and retry; a declared loss) are seen by the box's own |
| -// pass (observeMove) and named the same way. The identity is the log object's |
| -// key, written create-only behind moveCfg.LogEvent (moveLogWriter in |
| -// production), and only the writer that created the object tells the app's |
| -// members (preflight L9, L27). A worker also remembers what it logged, so a |
| -// pass that sees the same transition again does not even try. |
| +// pass (observeMove) and named the same way. A recovery probe's starts are |
| +// the attempt journal's (movesProbeAttempts.RecoveryAttempt, |
| +// recoveryAttemptLogger). The identity is the log object's key, written |
| +// create-only behind moveCfg.LogEvent (moveLogWriter in production), and |
| +// only the writer that created the object tells the app's members (preflight |
| +// L9, L27). |
| // |
| -// Recovery probe attempts are not logged: their counter is the recovery's own |
| -// attempt journal, not the record (Plan 6 Task 3 report). |
| +// A worker remembers the identities whose objects exist (created, or found |
| +// there), so a pass that sees the same transition again does not even try; |
| +// a write that failed is not remembered, so the next sighting tries again. |
| +// A move's identities are forgotten once its terminal outcome is logged: |
| +// create-only storage still refuses a replay. |
| -// moveLogEntry is what one transition is in the log. |
| -type moveLogEntry struct { |
| - op, event, identity string |
| - fields map[string]string |
| -} |
| - |
| -// movePhaseOf is the phase a record's state is at: the cut's, the landing's, |
| -// or (rolling back) the target's and the source's. |
| -func movePhaseOf(m *provision.MoveState) (phase, target, source string) { |
| - switch m.State { |
| - case provision.MoveCutting: |
| - return m.CutPhase, "", "" |
| - case provision.MoveLanding: |
| - return m.LandingPhase, "", "" |
| - case provision.MoveRollingBack: |
| - if m.Rollback != nil { |
| - return "", m.Rollback.TargetPhase, m.Rollback.SourcePhase |
| - } |
| - } |
| - return "", "", "" |
| -} |
| - |
| -func moveRegions(m *provision.MoveState) map[string]string { |
| - return map[string]string{"from": m.From, "to": m.To} |
| -} |
| - |
| -// moveTransition names the transition from before to after, one record write: |
| -// before as the write found it, after as written. ok is false when the write |
| -// changed nothing the log records (a pin, recovery inputs, a replay). |
| -func moveTransition(before, after provision.Record) (moveLogEntry, bool) { |
| - bm, am := before.Move, after.Move |
| - if am == nil { |
| - // A close clears the move and leaves its outcome (D11). |
| - if bm == nil || after.LastMove == nil || after.LastMove.ID != bm.ID || bm.ID == "" { |
| - return moveLogEntry{}, false |
| - } |
| - f := moveRegions(bm) |
| - f["offline_s"] = strconv.FormatFloat(after.LastMove.OfflineS, 'f', -1, 64) |
| - return moveLogEntry{op: bm.ID, event: after.LastMove.Outcome, identity: after.LastMove.Outcome, fields: f}, true |
| - } |
| - if am.ID == "" || (bm != nil && bm.ID != am.ID) { |
| - return moveLogEntry{}, false |
| - } |
| - e := moveLogEntry{op: am.ID, fields: moveRegions(am)} |
| - if bm == nil { |
| - bm = &provision.MoveState{} |
| - } |
| - switch { |
| - case am.State == provision.MoveStuck: |
| - if bm.State == provision.MoveStuck { |
| - return moveLogEntry{}, false |
| - } |
| - e.event, e.identity = "stuck", "stuck-"+strconv.FormatUint(am.RecoveryRetryEpoch, 10) |
| - return e, true |
| - case am.State == provision.MoveLanding && am.Landing != nil && (bm.Landing == nil || am.Landing.Attempts > bm.Landing.Attempts) && am.Landing.Attempts > 0: |
| - e.event, e.identity = "probe_attempt", "probe_attempt-"+strconv.Itoa(am.Landing.Attempts) |
| - return e, true |
| - case bm.State == provision.MoveCutting && am.State == provision.MoveLanding: |
| - // The flip is the record's one write from cutting to landing. |
| - e.event, e.identity = "flipped", "cutting-flipped" |
| - return e, true |
| - case am.State == provision.MoveCommitted && bm.State == provision.MoveCommitted: |
| - switch { |
| - case am.SourceParkedAt != nil && bm.SourceParkedAt == nil: |
| - e.event, e.identity = "source_parked", "committed-source_parked" |
| - case am.OpenedAt != nil && bm.OpenedAt == nil: |
| - e.event, e.identity = "opened", "committed-opened" |
| - if am.CutAt != nil { |
| - e.fields["offline_s"] = strconv.FormatInt(int64(am.OpenedAt.Sub(*am.CutAt).Seconds()), 10) |
| - } |
| - default: |
| - return moveLogEntry{}, false |
| - } |
| - return e, true |
| - case am.State == provision.MoveReverting && bm.State == provision.MoveReverting: |
| - if am.ReopenedAt == nil || bm.ReopenedAt != nil { |
| - return moveLogEntry{}, false |
| - } |
| - e.event, e.identity = "rev_opened", "reverting-opened" |
| - return e, true |
| - } |
| - phase, target, source := movePhaseOf(am) |
| - bphase, btarget, bsource := movePhaseOf(bm) |
| - if am.State == bm.State { |
| - switch { |
| - case am.State == provision.MoveRollingBack && target != btarget: |
| - e.event, e.identity = target, "rolling_back-target-"+target |
| - if target == provision.RbTargetLost { |
| - e.event = "declared_lost" |
| - } |
| - case am.State == provision.MoveRollingBack && source != bsource: |
| - e.event, e.identity = source, "rolling_back-source-"+source |
| - if source == provision.RbSourceOpened { |
| - e.fields["offline_s"] = moveOfflineSince(am) |
| - } |
| - case phase != bphase && phase != "": |
| - e.event, e.identity = phase, am.State+"-"+phase |
| - if am.State == provision.MoveCutting && phase == provision.CutRequested { |
| - e.event = "cut_requested" |
| - } |
| - default: |
| - return moveLogEntry{}, false |
| - } |
| - return e, true |
| - } |
| - // A new state. |
| - switch am.State { |
| - case provision.MovePreparing: |
| - e.event, e.identity = "requested", "requested" |
| - case provision.MoveCutting: |
| - e.event, e.identity = phase, "cutting-"+phase |
| - if phase == provision.CutRequested || phase == "" { |
| - e.event, e.identity = "cut_requested", "cutting-requested" |
| - } |
| - case provision.MoveLanding: |
| - e.event, e.identity = phase, "landing-"+phase |
| - case provision.MoveRollingBack: |
| - e.event, e.identity = "rolling_back", "rolling_back" |
| - default: |
| - // ready, committed, aborting, reverting, relocating: the state is the |
| - // event. |
| - e.event, e.identity = am.State, am.State |
| - } |
| - return e, true |
| -} |
| - |
| -// moveOfflineSince is the seconds from the cut to the source's reopen, for a |
| -// rollback's open, as the close counts it. |
| -func moveOfflineSince(m *provision.MoveState) string { |
| - if m.CutAt == nil || m.Rollback == nil || m.Rollback.OpenedAt == nil { |
| - return "" |
| +// observedMove wraps a record mutation so *pre keeps the record as the write |
| +// found it: the transition's before, for the log. |
| +func observedMove(pre *provision.Record, mut func(*provision.Record) error) func(*provision.Record) error { |
| + return func(rec *provision.Record) error { |
| + *pre = *rec |
| + pre.Move = copyMove(rec.Move) |
| + return mut(rec) |
| } |
| - return strconv.FormatInt(int64(m.Rollback.OpenedAt.Sub(*m.CutAt).Seconds()), 10) |
| } |
| -// copyMove is a deep enough copy of a move for moveTransition: the fields it |
| -// compares, safe from a mutation that edits the journal in place. |
| +// copyMove is a deep enough copy of a move for moves.TransitionOf: the fields |
| +// it compares and reads, safe from a mutation that edits the journal in |
| +// place. |
| func copyMove(m *provision.MoveState) *provision.MoveState { |
| if m == nil { |
| return nil |
| @@ -180,22 +61,16 @@ func copyMove(m *provision.MoveState) *provision.MoveState { |
| l := *m.Landing |
| c.Landing = &l |
| } |
| - return &c |
| -} |
| - |
| -// observedMove wraps a record mutation so *pre keeps the record as the write |
| -// found it: the transition's before, for the log. |
| -func observedMove(pre *provision.Record, mut func(*provision.Record) error) func(*provision.Record) error { |
| - return func(rec *provision.Record) error { |
| - *pre = *rec |
| - pre.Move = copyMove(rec.Move) |
| - return mut(rec) |
| + if m.Source != nil { |
| + src := *m.Source |
| + c.Source = &src |
| } |
| + return &c |
| } |
| -// logTransition logs the transition one write made (moveTransition). |
| +// logTransition logs the transition one write made. |
| func (w *movesWorker) logTransition(ctx context.Context, s release.Store, before, after provision.Record) { |
| - if e, ok := moveTransition(before, after); ok { |
| + if e, ok := moves.TransitionOf(before, after); ok { |
| w.record(ctx, s, after, e) |
| } |
| } |
| @@ -220,7 +95,8 @@ func (w *movesWorker) observeMove(ctx context.Context, s release.Store, rec prov |
| w.logTransition(ctx, s, before, rec) |
| } |
| if m.RecoveryRetryEpoch > 0 && m.State != provision.MoveStuck { |
| - w.record(ctx, s, rec, moveLogEntry{op: m.ID, event: "retry", identity: "retry-" + strconv.FormatUint(m.RecoveryRetryEpoch, 10), fields: moveRegions(m)}) |
| + w.record(ctx, s, rec, moves.Transition{Op: m.ID, Event: "retry", Identity: "retry-" + strconv.FormatUint(m.RecoveryRetryEpoch, 10), |
| + Fields: map[string]string{"from": m.From, "to": m.To}}) |
| } |
| } |
| @@ -237,87 +113,128 @@ func (w *movesWorker) logRevPhase(ctx context.Context, s release.Store, rec prov |
| if p == "" || p == phase(before) || rec.Move == nil || rec.Move.ID == "" { |
| return |
| } |
| - w.record(ctx, s, rec, moveLogEntry{op: rec.Move.ID, event: "rev_" + p, identity: "reverting-" + p, fields: moveRegions(rec.Move)}) |
| + w.record(ctx, s, rec, moves.Transition{Op: rec.Move.ID, Event: "rev_" + p, Identity: "reverting-" + p, |
| + Fields: map[string]string{"from": rec.Move.From, "to": rec.Move.To}}) |
| +} |
| + |
| +// recoveryAttemptLogger is the attempt journal's RecoveryAttempt hook for |
| +// this worker: each recovery probe start the journal counts is |
| +// probe_attempt-<epoch>-<n> (preflight L11), the starts of one wake |
| +// included. s is the store the log is written to. |
| +func (w *movesWorker) recoveryAttemptLogger(s release.Store) func(ctx context.Context, rec provision.Record, epoch uint64, n int) { |
| + return func(ctx context.Context, rec provision.Record, epoch uint64, n int) { |
| + if rec.Move == nil || rec.Move.ID == "" { |
| + return |
| + } |
| + w.record(ctx, s, rec, moves.Transition{Op: rec.Move.ID, Event: "probe_attempt", |
| + Identity: "probe_attempt-" + strconv.FormatUint(epoch, 10) + "-" + strconv.Itoa(n), |
| + Fields: map[string]string{"from": rec.Move.From, "to": rec.Move.To}}) |
| + } |
| } |
| -// record hands one entry to the LogEvent hook, once per worker: a pass that |
| -// sees the same transition again does not write it again. With no hook (a |
| -// test's worker) the event is a log line. |
| -func (w *movesWorker) record(ctx context.Context, s release.Store, rec provision.Record, e moveLogEntry) { |
| - key := rec.Host + "/" + e.op + "/" + e.identity |
| - if _, seen := w.logged.LoadOrStore(key, true); seen { |
| +// terminalEvents are the events that end a move's log. |
| +var terminalEvents = map[string]bool{"done": true, "rolled_back": true, "aborted": true} |
| + |
| +// record hands one entry to the LogEvent hook unless this worker already |
| +// knows its object exists. Only a hook that succeeded (the object created, |
| +// or found there) is remembered. With no hook (a test's worker) the event is |
| +// a log line. |
| +func (w *movesWorker) record(ctx context.Context, s release.Store, rec provision.Record, e moves.Transition) { |
| + key := rec.Host + "/" + e.Op + "/" + e.Identity |
| + if _, seen := w.logged.Load(key); seen { |
| return |
| } |
| - ev := moves.LogEvent{V: 1, Op: e.op, Host: rec.Host, Event: e.event, Identity: e.identity, Actor: w.cfg.Box, Fields: e.fields} |
| + ev := moves.LogEvent{V: 1, Op: e.Op, Host: rec.Host, Event: e.Event, Identity: e.Identity, Actor: w.cfg.Box, Fields: e.Fields} |
| if w.cfg.Now != nil { |
| ev.At = w.cfg.Now().UTC() |
| } |
| if f := w.cfg.LogEvent; f != nil { |
| - f(ctx, s, rec, ev) |
| + if err := f(ctx, s, rec, ev); err != nil { |
| + log.Printf("moves: %s: the log of %s at %s waits for the next sighting: %v", rec.Host, e.Op, e.Identity, err) |
| + return |
| + } |
| + } else { |
| + log.Printf("moves: %s: %s %s (%s)", rec.Host, e.Op, e.Event, e.Identity) |
| + } |
| + if terminalEvents[e.Event] { |
| + w.forgetMove(rec.Host, e.Op) |
| return |
| } |
| - log.Printf("moves: %s: %s %s (%s)", rec.Host, e.op, e.event, e.identity) |
| + w.logged.Store(key, true) |
| +} |
| + |
| +// forgetMove drops a closed move's remembered identities. |
| +func (w *movesWorker) forgetMove(host, op string) { |
| + prefix := host + "/" + op + "/" |
| + w.logged.Range(func(k, _ any) bool { |
| + if strings.HasPrefix(k.(string), prefix) { |
| + w.logged.Delete(k) |
| + } |
| + return true |
| + }) |
| } |
| // moveLogWriter is the production LogEvent: the object, create-only, under |
| // the move's report prefix in the deployment bucket, and the member event |
| -// when this writer created it. A failed write is logged; the next pass that |
| -// sees the transition does not try again (the worker remembers it), so a lost |
| -// object is a gap in the log, never a second event. |
| -func moveLogWriter(sink activator.EventSink) func(context.Context, release.Store, provision.Record, moves.LogEvent) { |
| - return func(ctx context.Context, s release.Store, rec provision.Record, ev moves.LogEvent) { |
| +// when this writer created it. A storage failure is returned, so the worker |
| +// tries the transition again at its next sighting. |
| +func moveLogWriter(sink activator.EventSink) func(context.Context, release.Store, provision.Record, moves.LogEvent) error { |
| + return func(ctx context.Context, s release.Store, rec provision.Record, ev moves.LogEvent) error { |
| if s == nil { |
| - return |
| + return fmt.Errorf("moves: no store for the log of %s", ev.Op) |
| } |
| created, err := moves.WriteLog(ctx, s, moves.ReportPrefix(rec.Account, rec.App, rec.Host, ev.Op), ev) |
| if err != nil { |
| - log.Printf("moves: %s: the log of %s at %s: %v", rec.Host, ev.Op, ev.Identity, err) |
| - return |
| + return err |
| } |
| if !created || sink == nil { |
| - return |
| + return nil |
| } |
| if line, ok := memberLine(ev, rec); ok { |
| sink.Event(rec.Account, rec.App, rec.Host, memberLevel(ev.Event), line) |
| } |
| + return nil |
| } |
| } |
| // memberLine is what the app's members read for an event (preflight L9: M-C1, |
| -// M-C5, M-C6, M-C7, M-C8, M-C9, and for stuck a line with no operator command |
| -// in it, MV-N380). ok is false for an event members are not told of, and for |
| -// one whose regions the record names only as the home's "". Its level is |
| +// M-C5, M-C6, M-C7, M-C8, M-C9, and for stuck MV-N380, a line with no |
| +// operator command in it), from the shared templates (moves/operatorcopy.go, |
| +// L12). A region the record names as the home's "" is moves.HomeRegionText. |
| +// ok is false for an event members are not told of. Its level is |
| // memberLevel's. |
| func memberLine(ev moves.LogEvent, rec provision.Record) (line string, ok bool) { |
| - host, from, to := rec.Host, ev.Fields["from"], ev.Fields["to"] |
| - if from == "" || to == "" { |
| - return "", false |
| - } |
| + host := rec.Host |
| + from, to := moves.RegionText(ev.Fields["from"]), moves.RegionText(ev.Fields["to"]) |
| switch ev.Event { |
| case "requested": |
| - return fmt.Sprintf("Moving %s from %s to %s.", host, from, to), true |
| + return moves.MoveStartingLine(host, from, to), true |
| case "admitted": |
| if rec.Move == nil || rec.Move.CutBudgetS <= 0 { |
| return "", false |
| } |
| - return fmt.Sprintf("%s is ready. Starting the cut. %s will be offline for about %s.", to, host, memberEstimate(rec.Move.CutBudgetS)), true |
| + return moves.CutStartingLine(to, host, moves.CutBudgetText(rec.Move.CutBudgetS)), true |
| case "flipped": |
| - return fmt.Sprintf("Stopped in %s. Starting in %s.", from, to), true |
| + return moves.FlippedLine(from, to), true |
| case "done": |
| offline, err := strconv.ParseFloat(ev.Fields["offline_s"], 64) |
| if err != nil { |
| return "", false |
| } |
| - return fmt.Sprintf("Moved. %s is served from %s. It was offline for %d seconds.", host, to, int(math.Round(offline))), true |
| + return moves.MovedLine(host, to, int(math.Round(offline))), true |
| case "rolling_back": |
| - if rec.Move == nil || rec.Move.Rollback == nil || rec.Move.Rollback.Reason == "" { |
| + reason := ev.Fields["reason"] |
| + if reason == "" && rec.Move != nil && rec.Move.Rollback != nil { |
| + reason = rec.Move.Rollback.Reason |
| + } |
| + if reason == "" { |
| return "", false |
| } |
| - return fmt.Sprintf("%s could not start %s: %s. Moving it back to %s.", to, host, rec.Move.Rollback.Reason, from), true |
| + return moves.MovingBackLine(to, host, reason, from), true |
| case "rolled_back": |
| - return fmt.Sprintf("%s is back in %s and serving. Nothing was lost.", host, from), true |
| + return moves.MovedBackLine(host, from), true |
| case "stuck": |
| - return fmt.Sprintf("%s could not start in %s or in %s. It is offline. An operator has been paged.", host, to, from), true |
| + return moves.StuckMemberLine(host, to, from), true |
| } |
| return "", false |
| } |
| @@ -332,11 +249,3 @@ func memberLevel(event string) string { |
| } |
| return "info" |
| } |
| - |
| -// memberEstimate renders a cut budget for M-C5, as the CLI does. |
| -func memberEstimate(seconds int) string { |
| - if seconds < 90 { |
| - return fmt.Sprintf("%d seconds", seconds) |
| - } |
| - return fmt.Sprintf("%d minutes", (seconds+59)/60) |
| -} |
diff --git a/internal/host/movesevents_test.go b/internal/host/movesevents_test.go| index 44bda05aa..631d30b10 100644 |
| --- a/internal/host/movesevents_test.go |
| +++ b/internal/host/movesevents_test.go |
| @@ -2,10 +2,15 @@ package host |
| import ( |
| "context" |
| + "errors" |
| + "fmt" |
| "strings" |
| "testing" |
| "time" |
| + "github.com/carlosframework/platform/internal/hostclaim" |
| + "github.com/carlosframework/platform/internal/park" |
| + |
| "github.com/carlosframework/platform/internal/lease" |
| "github.com/carlosframework/platform/internal/moves" |
| "github.com/carlosframework/platform/internal/provision" |
| @@ -88,8 +93,9 @@ func eventWorker(got *[]moves.LogEvent) *movesWorker { |
| w := &movesWorker{mirrors: map[string]lease.MirrorStore{}} |
| w.cfg.Box = "box-test" |
| w.cfg.Now = func() time.Time { return time.Unix(1_800_000_100, 0).UTC() } |
| - w.cfg.LogEvent = func(_ context.Context, _ release.Store, _ provision.Record, ev moves.LogEvent) { |
| + w.cfg.LogEvent = func(_ context.Context, _ release.Store, _ provision.Record, ev moves.LogEvent) error { |
| *got = append(*got, ev) |
| + return nil |
| } |
| return w |
| } |
| @@ -105,10 +111,14 @@ func TestEveryTransitionEmitsOneEvent(t *testing.T) { |
| w.observeMove(ctx, nil, flow[0]) |
| for i := 1; i < len(flow); i++ { |
| w.logTransition(ctx, nil, flow[i-1], flow[i]) |
| - // A status poll, a pass that changes nothing, a replayed write. |
| + // A status poll, a pass that changes nothing, a replayed write. A |
| + // closed move's identities are forgotten (create-only storage refuses |
| + // a replay of the close), so the close is not replayed here. |
| w.observeMove(ctx, nil, flow[i]) |
| w.logTransition(ctx, nil, flow[i], flow[i]) |
| - w.logTransition(ctx, nil, flow[i-1], flow[i]) |
| + if i < len(flow)-1 { |
| + w.logTransition(ctx, nil, flow[i-1], flow[i]) |
| + } |
| } |
| var events []string |
| for _, ev := range got { |
| @@ -266,3 +276,238 @@ func TestMemberLines(t *testing.T) { |
| } |
| } |
| } |
| + |
| +// ---- Task 3 fix round 1 ---- |
| + |
| +// Ruling 1: an identity is done only once its object exists. A write that |
| +// fails stays pending, and the next sighting tries again. |
| +func TestFailedLogWriteStaysPending(t *testing.T) { |
| + ctx := context.Background() |
| + calls := 0 |
| + w := &movesWorker{mirrors: map[string]lease.MirrorStore{}} |
| + w.cfg.Now = time.Now |
| + w.cfg.LogEvent = func(context.Context, release.Store, provision.Record, moves.LogEvent) error { |
| + calls++ |
| + if calls == 1 { |
| + return errors.New("the bucket is down") |
| + } |
| + return nil |
| + } |
| + rec := mvEvRec(provision.MovePreparing, nil) |
| + w.observeMove(ctx, nil, rec) |
| + w.observeMove(ctx, nil, rec) |
| + w.observeMove(ctx, nil, rec) |
| + if calls != 2 { |
| + t.Fatalf("the hook was called %d times, want a failure, a retry that succeeds, and nothing after", calls) |
| + } |
| +} |
| + |
| +// Ruling 7: a move's identities are forgotten once its terminal outcome is |
| +// logged (create-only storage still refuses a replay). |
| +func TestLogMemoForgetsAClosedMove(t *testing.T) { |
| + ctx := context.Background() |
| + var got []moves.LogEvent |
| + w := eventWorker(&got) |
| + flow := doneFlow() |
| + w.observeMove(ctx, nil, flow[0]) |
| + for i := 1; i < len(flow); i++ { |
| + w.logTransition(ctx, nil, flow[i-1], flow[i]) |
| + } |
| + n := 0 |
| + w.logged.Range(func(k, _ any) bool { n++; return true }) |
| + if n != 0 { |
| + t.Fatalf("%d identities remembered after the close", n) |
| + } |
| +} |
| + |
| +// Ruling 4: the box knows the home region only as "", so the member line |
| +// names it with the reviewed phrase (MV-N381), never dropping the line. |
| +func TestHomeRegionMemberLines(t *testing.T) { |
| + fromHome := mvEvRec(provision.MovePreparing, func(m *provision.MoveState) { m.From = "" }) |
| + toHome := mvEvRec(provision.MovePreparing, func(m *provision.MoveState) { m.To = "" }) |
| + for _, c := range []struct { |
| + rec provision.Record |
| + event string |
| + want string |
| + }{ |
| + {fromHome, "requested", "Moving acme.go.tito.io from the home region to uk."}, |
| + {toHome, "requested", "Moving acme.go.tito.io from ie to the home region."}, |
| + {toHome, "flipped", "Stopped in ie. Starting in the home region."}, |
| + } { |
| + ev := moves.LogEvent{Event: c.event, Fields: map[string]string{"from": c.rec.Move.From, "to": c.rec.Move.To}} |
| + if line, ok := memberLine(ev, c.rec); !ok || line != c.want { |
| + t.Errorf("%s: %q %v, want %q", c.event, line, ok, c.want) |
| + } |
| + } |
| +} |
| + |
| +// Ruling 5: the events carry the transition's evidence. The cut's stopped |
| +// carries the source's digests, the landing's probed the installed |
| +// database, a stuck its role, and the source's recovered the recovery's |
| +// timing. |
| +func TestEventsCarryTheirEvidence(t *testing.T) { |
| + ctx := context.Background() |
| + var got []moves.LogEvent |
| + w := eventWorker(&got) |
| + cut := func(phase string, src *provision.MoveSource) provision.Record { |
| + return mvEvRec(provision.MoveCutting, func(m *provision.MoveState) { m.CutPhase, m.Source = phase, src }) |
| + } |
| + src := &provision.MoveSource{FinalTXID: 42, DBSHA256: strings.Repeat("d", 64), TimersSHA256: strings.Repeat("e", 64), |
| + Files: &provision.MoveFilesDigest{Plain: strings.Repeat("f", 64)}, Evidence: "moves/x/stopped-source.json"} |
| + w.logTransition(ctx, nil, cut(provision.CutStopping, nil), cut(provision.CutStopped, src)) |
| + land := func(phase, db string) provision.Record { |
| + return mvEvRec(provision.MoveLanding, func(m *provision.MoveState) { |
| + m.LandingPhase = phase |
| + m.Landing = &provision.MoveLandingJournal{InstalledDBSHA256: db, Attempts: 1} |
| + }) |
| + } |
| + w.logTransition(ctx, nil, land(provision.LandProbing, strings.Repeat("a", 64)), land(provision.LandProbed, strings.Repeat("a", 64))) |
| + rb := func(target, source string, stuck bool) provision.Record { |
| + state := provision.MoveRollingBack |
| + if stuck { |
| + state = provision.MoveStuck |
| + } |
| + return mvEvRec(state, func(m *provision.MoveState) { |
| + m.CutAt = mvEvAt(10) |
| + m.Rollback = &provision.MoveRollback{ID: "rb_x", RequestedAt: mvEvAt(30), TargetPhase: target, SourcePhase: source} |
| + if source == provision.RbSourceRecovered { |
| + m.Rollback.RecoveredAt = mvEvAt(70) |
| + } |
| + }) |
| + } |
| + w.logTransition(ctx, nil, rb(provision.RbTargetReturning, provision.RbSourceWaiting, false), rb(provision.RbTargetReturning, provision.RbSourceWaiting, true)) |
| + w.logTransition(ctx, nil, rb(provision.RbTargetCleaned, provision.RbSourceProbed, false), rb(provision.RbTargetCleaned, provision.RbSourceRecovered, false)) |
| + // The source's stuck, on another box's worker (the target's stuck above |
| + // is stuck-0 in this one). |
| + eventWorker(&got).logTransition(ctx, nil, rb(provision.RbTargetCleaned, provision.RbSourceVerified, false), rb(provision.RbTargetCleaned, provision.RbSourceVerified, true)) |
| + by := map[string]map[string]string{} |
| + for _, ev := range got { |
| + by[ev.Identity] = ev.Fields |
| + } |
| + if f := by["cutting-stopped"]; f["db_sha256"] != src.DBSHA256 || f["final_txid"] != "42" || f["files_plain"] != src.Files.Plain || f["timers_sha256"] != src.TimersSHA256 { |
| + t.Errorf("stopped carries %v", f) |
| + } |
| + if f := by["landing-probed"]; f["installed_db_sha256"] != strings.Repeat("a", 64) { |
| + t.Errorf("probed carries %v", f) |
| + } |
| + if f := by["rolling_back-source-recovered"]; f["recovery_s"] != "40" || f["offline_s"] != "60" { |
| + t.Errorf("recovered carries %v, want recovery_s 40 (rollback request to recovered) and offline_s 60 (cut to recovered)", f) |
| + } |
| + var roles []string |
| + for _, ev := range got { |
| + if ev.Event == "stuck" { |
| + roles = append(roles, ev.Fields["role"]) |
| + } |
| + } |
| + if strings.Join(roles, " ") != "target source" { |
| + t.Errorf("stuck roles %v, want the target's (at returning), then the source's", roles) |
| + } |
| +} |
| + |
| +// Ruling 2: each recovery probe start the attempt journal counts is a log |
| +// event, probe_attempt-<epoch>-<n>, the starts of one wake included; a |
| +// reservation that only validates writes none. |
| +func TestRecoveryProbeAttemptsAreLogged(t *testing.T) { |
| + f := recoveryPAFixture(t, hostclaim.KindRestoring) |
| + var got []string |
| + hook := func(_ context.Context, rec provision.Record, epoch uint64, n int) { |
| + got = append(got, fmt.Sprintf("%s %d-%d", rec.Host, epoch, n)) |
| + } |
| + f.ops = f.attempts() |
| + f.ops.RecoveryAttempt = hook |
| + for n := 0; n < 3; n++ { |
| + if _, err := f.ops.OpenProbe(t.Context(), f.start, time.Now()); err != nil { |
| + t.Fatal(err) |
| + } |
| + if err := f.ops.Reserve(t.Context(), f.start, n); err != nil { |
| + t.Fatalf("start %d: %v", n, err) |
| + } |
| + if n == 0 { |
| + if err := f.ops.Reserve(t.Context(), f.start, 0); err != nil { |
| + t.Fatal(err) |
| + } |
| + } |
| + if err := f.ops.Failed(t.Context(), f.start, n); err != nil { |
| + t.Fatal(err) |
| + } |
| + } |
| + want := []string{f.rec.Host + " 0-1", f.rec.Host + " 0-2", f.rec.Host + " 0-3"} |
| + if strings.Join(got, ",") != strings.Join(want, ",") { |
| + t.Fatalf("attempts %v, want %v", got, want) |
| + } |
| + |
| + // The worker's hook names them probe_attempt-<epoch>-<n>. |
| + var evs []moves.LogEvent |
| + w := eventWorker(&evs) |
| + w.recoveryAttemptLogger(nil)(context.Background(), *f.rec, 2, 4) |
| + if len(evs) != 1 || evs[0].Event != "probe_attempt" || evs[0].Identity != "probe_attempt-2-4" { |
| + t.Fatalf("logged %+v", evs) |
| + } |
| +} |
| + |
| +// Ruling 7: the real writers log, through the move harness. The landing |
| +// harness drives the source's readiness, the console's cut, the cut and the |
| +// flip, then the landing to installed; the close harness the probe, the |
| +// commit, the open, the source's park and the close. A writer whose log |
| +// call went missing drops out of the list. |
| +func TestRealWritersLogEveryTransition(t *testing.T) { |
| + t.Run("readiness to installed", func(t *testing.T) { |
| + h := newLandingHarness(t) |
| + var got []moves.LogEvent |
| + h.cfg.LogEvent = func(_ context.Context, _ release.Store, _ provision.Record, ev moves.LogEvent) error { |
| + got = append(got, ev) |
| + return nil |
| + } |
| + h.flip(t) |
| + h.land(t) |
| + h.installed(t) |
| + wantSubsequence(t, got, "ready", "cut_requested", "admitted", "stopping", "stopped", "staged", "archived", "flipped", "parking", "building", "published", "local", "configured", "restored") |
| + }) |
| + t.Run("probe to done", func(t *testing.T) { |
| + h := newCloseHarness(t) |
| + var got []moves.LogEvent |
| + h.cfg.LogEvent = func(_ context.Context, _ release.Store, _ provision.Record, ev moves.LogEvent) error { |
| + got = append(got, ev) |
| + return nil |
| + } |
| + h.land(t) |
| + h.committedAndOpen(t) |
| + h.sourcePass(t) |
| + h.land(t) |
| + lane := h.chore(t, "uk", true) |
| + h.clockPast(lane.Park.EvidenceAt.Add(park.SignatureAge + lane.Park.RequestLimit)) |
| + h.land(t) |
| + src := h.chore(t, "ie", false) |
| + h.clockPast(src.Park.EvidenceAt.Add(park.SignatureAge + src.Park.RequestLimit)) |
| + if err := h.regionalAck(t, src); err != nil { |
| + t.Fatal(err) |
| + } |
| + h.land(t) |
| + h.done(t) |
| + wantSubsequence(t, got, "probing", "probe_attempt", "probed", "committed", "opened", "source_parked", "done") |
| + }) |
| +} |
| + |
| +// wantSubsequence requires want's events, in order, among got's, and no |
| +// identity twice. |
| +func wantSubsequence(t *testing.T, got []moves.LogEvent, want ...string) { |
| + t.Helper() |
| + var events []string |
| + seen := map[string]bool{} |
| + for _, ev := range got { |
| + events = append(events, ev.Event) |
| + if seen[ev.Identity] { |
| + t.Errorf("identity %q twice", ev.Identity) |
| + } |
| + seen[ev.Identity] = true |
| + } |
| + i := 0 |
| + for _, e := range events { |
| + if i < len(want) && e == want[i] { |
| + i++ |
| + } |
| + } |
| + if i != len(want) { |
| + t.Fatalf("events %v lack %v in order (matched %d)", events, want, i) |
| + } |
| +} |
diff --git a/internal/host/movespass.go b/internal/host/movespass.go| index 90d9dcb8a..adb7e8555 100644 |
| --- a/internal/host/movespass.go |
| +++ b/internal/host/movespass.go |
| @@ -623,7 +623,7 @@ type moveCfg struct { |
| // DeleteHeld above; ParkLeases nil leaves it unarmed in production |
| // (rollbackTargetArmed). rbFault is its test seam, nil in production. |
| HandHold func(host, status, toOp, fromOp string, validate func() error) (bool, error) |
| - LogEvent func(ctx context.Context, s release.Store, rec provision.Record, ev moves.LogEvent) |
| + LogEvent func(ctx context.Context, s release.Store, rec provision.Record, ev moves.LogEvent) error |
| Events activator.EventSink |
| rbFault func(point string) error |
diff --git a/internal/host/movesprobeattempts.go b/internal/host/movesprobeattempts.go| index 32c793799..826dda6bb 100644 |
| --- a/internal/host/movesprobeattempts.go |
| +++ b/internal/host/movesprobeattempts.go |
| @@ -4,6 +4,7 @@ import ( |
| "context" |
| "encoding/json" |
| "fmt" |
| + "log" |
| "os/exec" |
| "strconv" |
| "sync" |
| @@ -67,6 +68,11 @@ type movesProbeAttempts struct { |
| // moves.SettleSeconds. Ready bounds that request; zero is |
| // moves.ProbeSeconds. |
| Settle, Ready time.Duration |
| + // RecoveryAttempt, when set, is told of each recovery probe start this |
| + // journal counts: the record, its recovery retry epoch and the start's |
| + // number (the move log's probe_attempt-<epoch>-<n>, Plan 6 Task 3; |
| + // movesWorker.recoveryAttemptLogger). Whoever builds the journal sets it. |
| + RecoveryAttempt func(ctx context.Context, rec provision.Record, epoch uint64, n int) |
| mu sync.Mutex |
| current map[string]boundAttempt |
| @@ -296,7 +302,7 @@ func sameStartOwner(a hostclaim.WakeRetryAttempt, s OperationStart, digest strin |
| // Reserve journals start n of this admission before it runs. Start 0 is |
| // reserved by the first Reserve(0) of the admission and validated by every |
| // later one; start n > 0 only after start n-1 was settled failed. |
| -func (p *movesProbeAttempts) Reserve(ctx context.Context, s OperationStart, n int) error { |
| +func (p *movesProbeAttempts) Reserve(ctx context.Context, s OperationStart, n int) (retErr error) { |
| k, recoveryKey, err := p.bound(ctx, s) |
| if err != nil { |
| return err |
| @@ -344,6 +350,7 @@ func (p *movesProbeAttempts) Reserve(ctx context.Context, s OperationStart, n in |
| } |
| } |
| if st.Attempt.ID == "" { |
| + counted := 0 |
| if k < 0 { |
| count, err := recoveryAttemptCount(j, recoveryKey) |
| if err != nil { |
| @@ -352,8 +359,14 @@ func (p *movesProbeAttempts) Reserve(ctx context.Context, s OperationStart, n in |
| if count >= recoveryProbeAttempts { |
| return ErrRecoveryProbeExhausted |
| } |
| - j.Mark(recoveryKey, strconv.Itoa(count+1)) |
| + counted = count + 1 |
| + j.Mark(recoveryKey, strconv.Itoa(counted)) |
| } |
| + defer func() { |
| + if counted > 0 && retErr == nil { |
| + p.recoveryAttempted(ctx, s, counted) |
| + } |
| + }() |
| o := s.Owner |
| st.Attempt = hostclaim.WakeRetryAttempt{ID: p.NewID(), Box: o.Box, Enrollment: o.Enrollment, BootID: o.BootID, ControllerID: o.ControllerID, Session: o.Session, InvocationID: p.NewID(), LaunchInputs: digest} |
| if st.Attempt.ID == "" || st.Attempt.InvocationID == "" || st.Attempt.ID == st.Attempt.InvocationID { |
| @@ -565,3 +578,19 @@ func recoveryAttemptCount(j *moves.Journal, key string) (int, error) { |
| } |
| return n, nil |
| } |
| + |
| +// recoveryAttempted tells RecoveryAttempt of start n of a recovery probe, |
| +// read against the record its admission names (for the retry epoch). A |
| +// record that cannot be read is logged, and the start is not reported. |
| +func (p *movesProbeAttempts) recoveryAttempted(ctx context.Context, s OperationStart, n int) { |
| + if p.RecoveryAttempt == nil || p.Records == nil || s.Admitted.Claim == nil || s.Admitted.Claim.Holder == nil { |
| + return |
| + } |
| + h := s.Admitted.Claim.Holder |
| + rec, err := p.Records(ctx, h.Account, h.App, s.Admitted.Host) |
| + if err != nil || rec == nil || rec.Move == nil { |
| + log.Printf("moves: %s: the log of recovery probe start %d: the record: %v", s.Admitted.Host, n, err) |
| + return |
| + } |
| + p.RecoveryAttempt(ctx, *rec, rec.Move.RecoveryRetryEpoch, n) |
| +} |
diff --git a/internal/host/movesrecover_test.go b/internal/host/movesrecover_test.go| index ea13ad5e4..5c31b20a4 100644 |
| --- a/internal/host/movesrecover_test.go |
| +++ b/internal/host/movesrecover_test.go |
| @@ -150,8 +150,9 @@ func (h *recoverHarness) sourceCfg(t *testing.T) moveCfg { |
| h.srcRoute.Status, h.srcRoute.HoldOp = "ready", "" |
| return true, nil |
| } |
| - c.LogEvent = func(_ context.Context, _ release.Store, _ provision.Record, ev moves.LogEvent) { |
| + c.LogEvent = func(_ context.Context, _ release.Store, _ provision.Record, ev moves.LogEvent) error { |
| h.sEvents = append(h.sEvents, ev.Event) |
| + return nil |
| } |
| c.Page = h.pages.hook() |
| c.recoveryProbe = func(ctx context.Context, _ release.Store, rec provision.Record, req recoveryProbeRequest) (recoveryProbeOutcome, error) { |
diff --git a/internal/host/movesrevert_test.go b/internal/host/movesrevert_test.go| index a291bcde2..4f4b19225 100644 |
| --- a/internal/host/movesrevert_test.go |
| +++ b/internal/host/movesrevert_test.go |
| @@ -132,8 +132,9 @@ func (h *revertHarness) arm(t *testing.T) { |
| h.route.Status, h.route.HoldOp = "ready", "" |
| return true, nil |
| } |
| - h.cfg.LogEvent = func(_ context.Context, _ release.Store, _ provision.Record, ev moves.LogEvent) { |
| + h.cfg.LogEvent = func(_ context.Context, _ release.Store, _ provision.Record, ev moves.LogEvent) error { |
| h.events = append(h.events, ev.Event) |
| + return nil |
| } |
| h.cfg.recoveryProbe = func(ctx context.Context, _ release.Store, _ provision.Record, req recoveryProbeRequest) (recoveryProbeOutcome, error) { |
| h.probes = append(h.probes, req) |
diff --git a/internal/host/movesrollback_test.go b/internal/host/movesrollback_test.go| index e38120f9d..63260f601 100644 |
| --- a/internal/host/movesrollback_test.go |
| +++ b/internal/host/movesrollback_test.go |
| @@ -136,8 +136,9 @@ func (h *rollbackHarness) rollbackCfg(t *testing.T) moveCfg { |
| h.rowGone = true |
| return true, nil |
| } |
| - c.LogEvent = func(_ context.Context, _ release.Store, _ provision.Record, ev moves.LogEvent) { |
| + c.LogEvent = func(_ context.Context, _ release.Store, _ provision.Record, ev moves.LogEvent) error { |
| h.events = append(h.events, ev.Event) |
| + return nil |
| } |
| c.Page = h.pages.hook() |
| c.rbFault = func(point string) error { |
diff --git a/internal/hostops/move_recovery_grant.go b/internal/hostops/move_recovery_grant.go| index c8d4ca78b..b0dd28552 100644 |
| --- a/internal/hostops/move_recovery_grant.go |
| +++ b/internal/hostops/move_recovery_grant.go |
| @@ -32,6 +32,9 @@ type MoveRecoveryGrant struct { |
| type moveRecoveryGrantState struct { |
| mu sync.Mutex |
| active bool |
| + // running is true while the hook that holds the grant runs: the life of |
| + // Log, which outlives the one mutation active allows. |
| + running bool |
| } |
| func moveRecoveryKind(kind string) bool { |
| @@ -87,9 +90,9 @@ func runMoveRecovery(ctx context.Context, obs hostclaim.Observed, hook func(cont |
| if len(authorities) == 1 { |
| authority = authorities[0] |
| } |
| - g := &MoveRecoveryGrant{state: &moveRecoveryGrantState{active: true}, w: w, scope: scope, authority: authority, o: ConsoleMoveObservation{Account: h.Account, App: h.App, AppID: c.Op.Intent["app_id"], Host: obs.Host, Incarnation: h.Incarnation, OpID: c.Op.ID, ClaimETag: obs.ETag, RecordETag: r.ETag, RecordSeq: seq}} |
| + g := &MoveRecoveryGrant{state: &moveRecoveryGrantState{active: true, running: true}, w: w, scope: scope, authority: authority, o: ConsoleMoveObservation{Account: h.Account, App: h.App, AppID: c.Op.Intent["app_id"], Host: obs.Host, Incarnation: h.Incarnation, OpID: c.Op.ID, ClaimETag: obs.ETag, RecordETag: r.ETag, RecordSeq: seq}} |
| state := g.state |
| - defer func() { state.mu.Lock(); state.active = false; state.mu.Unlock() }() |
| + defer func() { state.mu.Lock(); state.active, state.running = false, false; state.mu.Unlock() }() |
| // The owner receives only this capability, never the minting context. |
| ctx = context.WithValue(ctx, lifecycleGrantKey{}, []lifecycleGrant(nil)) |
| ctx = context.WithValue(ctx, moveRecoveryPassKey{}, (*moveRecoveryPassScope)(nil)) |
| @@ -122,6 +125,28 @@ func (g *MoveRecoveryGrant) current(ctx context.Context) (hostclaim.Observed, Re |
| return o, r, rec, err |
| } |
| +// Log writes one entry of this move's log (Plan 6 Task 3): create-only |
| +// (moves.WriteLog), under this grant's move's own report prefix, while the |
| +// hook that holds the grant runs, after its mutation as before it. It is the |
| +// pass's one write beside the record and the claim; an entry is a record of |
| +// a transition, never an input to one, so it needs no fresh observation. |
| +// created is false when the entry was already there. |
| +func (g *MoveRecoveryGrant) Log(ctx context.Context, ev moves.LogEvent) (created bool, err error) { |
| + if g == nil || g.state == nil || g.w == nil { |
| + return false, ErrPending |
| + } |
| + g.state.mu.Lock() |
| + running := g.state.running |
| + g.state.mu.Unlock() |
| + if !running { |
| + return false, ErrPending |
| + } |
| + if ev.Op != g.o.OpID || ev.Host != g.o.Host { |
| + return false, ErrIdentity |
| + } |
| + return moves.WriteLog(ctx, g.w.raw, moves.ReportPrefix(g.o.Account, g.o.App, g.o.Host, g.o.OpID), ev) |
| +} |
| + |
| // Observation contains values, never authority. |
| func (g *MoveRecoveryGrant) Observation() ConsoleMoveObservation { return g.o } |
diff --git a/internal/hostops/move_recovery_grant_test.go b/internal/hostops/move_recovery_grant_test.go| index 470289fc4..ab7898158 100644 |
| --- a/internal/hostops/move_recovery_grant_test.go |
| +++ b/internal/hostops/move_recovery_grant_test.go |
| @@ -8,6 +8,7 @@ import ( |
| "time" |
| "github.com/carlosframework/platform/internal/hostclaim" |
| + "github.com/carlosframework/platform/internal/moves" |
| "github.com/carlosframework/platform/internal/provision" |
| "github.com/carlosframework/platform/internal/release" |
| ) |
| @@ -182,6 +183,66 @@ func TestMoveRecoveryRecordCloseThenRelease(t *testing.T) { |
| } |
| } |
| +// Plan 6 Task 3 fix round 1, ruling 3: the grant's Log writes this move's |
| +// log, create-only, under its own report prefix, after the grant's one |
| +// mutation as before it, and only while its hook runs. |
| +func TestMoveRecoveryGrantLogsItsOwnMove(t *testing.T) { |
| + w := newC7World(t, func(c *hostclaim.Claim, r *provision.Record, _ *AppAdmission) { |
| + c.Op.Kind, c.Op.Phase, c.Op.Exec = hostclaim.KindLanding, hostclaim.PhaseCommitted, "target" |
| + c.Obligations = nil |
| + r.Region = "uk" |
| + r.Move.State = provision.MoveCommitted |
| + now := r.CreatedAt |
| + r.Move.CommittedAt = &now |
| + r.Move.OpenedAt = &now |
| + r.Move.SourceParkedAt = &now |
| + }) |
| + ctx := context.Background() |
| + ev := moves.LogEvent{V: 1, Op: "move", Host: w.host, Event: "done", Identity: "done", Actor: "console", At: w.now} |
| + var saved *MoveRecoveryGrant |
| + var created, again bool |
| + var other, wrongHost error |
| + err := w.control.RunRecovery(ctx, func(ctx context.Context) error { |
| + return runMoveRecovery(ctx, w.claim(t), func(ctx context.Context, g *MoveRecoveryGrant) error { |
| + saved = g |
| + if err := g.Record(ctx, RecoveryMoveClose); err != nil { |
| + return err |
| + } |
| + var err error |
| + if created, err = g.Log(ctx, ev); err != nil { |
| + return err |
| + } |
| + if again, err = g.Log(ctx, ev); err != nil { |
| + return err |
| + } |
| + o := ev |
| + o.Op = "other" |
| + _, other = g.Log(ctx, o) |
| + h := ev |
| + h.Host = "elsewhere.example" |
| + _, wrongHost = g.Log(ctx, h) |
| + return nil |
| + }) |
| + }) |
| + if err != nil { |
| + t.Fatal(err) |
| + } |
| + if !created || again { |
| + t.Fatalf("created=%v, a replay created=%v", created, again) |
| + } |
| + if !errors.Is(other, ErrIdentity) || !errors.Is(wrongHost, ErrIdentity) { |
| + t.Fatalf("another move's log: %v, another host's: %v", other, wrongHost) |
| + } |
| + got, err := moves.ReadLog(ctx, w.raw, moves.ReportPrefix("bab", "app", w.host, "move")) |
| + if err != nil || len(got) != 1 || got[0].Identity != "done" || got[0].Actor != "console" { |
| + t.Fatalf("log %+v %v", got, err) |
| + } |
| + ev.Identity, ev.Event = "claim-released", "claim_released" |
| + if _, err := saved.Log(ctx, ev); !errors.Is(err, ErrPending) { |
| + t.Fatalf("a grant kept past its hook logged: %v", err) |
| + } |
| +} |
| + |
| func TestMoveRecoveryStartRequiresDurableBaseAndHonorsAppliedJournal(t *testing.T) { |
| for _, marker := range []string{"missing-base", "applied-effect", "issued"} { |
| t.Run(marker, func(t *testing.T) { |
diff --git a/internal/moves/operatorcopy.go b/internal/moves/operatorcopy.go| new file mode 100644 |
| index 000000000..c20af81ab |
| --- /dev/null |
| +++ b/internal/moves/operatorcopy.go |
| @@ -0,0 +1,66 @@ |
| +package moves |
| + |
| +import "fmt" |
| + |
| +// The operator sentences two packages speak (preflight L12): the carlos move |
| +// CLI (package main) and the app's member stream (internal/host). One |
| +// template each, so the copy record names this file for them. A sentence |
| +// only one of them speaks stays in that file. |
| + |
| +// MoveStartingLine is M-C1. |
| +func MoveStartingLine(host, from, to string) string { |
| + return fmt.Sprintf("Moving %s from %s to %s.", host, from, to) |
| +} |
| + |
| +// CutStartingLine is M-C5; estimate is CutBudgetText's. |
| +func CutStartingLine(to, host, estimate string) string { |
| + return fmt.Sprintf("%s is ready. Starting the cut. %s will be offline for about %s.", to, host, estimate) |
| +} |
| + |
| +// FlippedLine is M-C6. |
| +func FlippedLine(from, to string) string { |
| + return fmt.Sprintf("Stopped in %s. Starting in %s.", from, to) |
| +} |
| + |
| +// MovedLine is M-C7. |
| +func MovedLine(host, to string, offlineSeconds int) string { |
| + return fmt.Sprintf("Moved. %s is served from %s. It was offline for %d seconds.", host, to, offlineSeconds) |
| +} |
| + |
| +// MovingBackLine is M-C8; reason is a recorded rollback sentence. |
| +func MovingBackLine(to, host, reason, from string) string { |
| + return fmt.Sprintf("%s could not start %s: %s. Moving it back to %s.", to, host, reason, from) |
| +} |
| + |
| +// MovedBackLine is M-C9. |
| +func MovedBackLine(host, from string) string { |
| + return fmt.Sprintf("%s is back in %s and serving. Nothing was lost.", host, from) |
| +} |
| + |
| +// StuckMemberLine is what members read for a stuck move (MV-N380): M-C11 |
| +// without the operator's command. |
| +func StuckMemberLine(host, to, from string) string { |
| + return fmt.Sprintf("%s could not start in %s or in %s. It is offline. An operator has been paged.", host, to, from) |
| +} |
| + |
| +// CutBudgetText renders a cut budget for M-C5. |
| +func CutBudgetText(seconds int) string { |
| + if seconds < 90 { |
| + return fmt.Sprintf("%d seconds", seconds) |
| + } |
| + return fmt.Sprintf("%d minutes", (seconds+59)/60) |
| +} |
| + |
| +// HomeRegionText names the home region where only its code, "", is known |
| +// (MV-N381): a box knows the deployment's home only as the record's empty |
| +// region. |
| +const HomeRegionText = "the home region" |
| + |
| +// RegionText is a region as a sentence names it: its code, or |
| +// HomeRegionText for the home's "". |
| +func RegionText(code string) string { |
| + if code == "" { |
| + return HomeRegionText |
| + } |
| + return code |
| +} |
diff --git a/internal/moves/transition.go b/internal/moves/transition.go| new file mode 100644 |
| index 000000000..db7e27c9c |
| --- /dev/null |
| +++ b/internal/moves/transition.go |
| @@ -0,0 +1,205 @@ |
| +package moves |
| + |
| +import ( |
| + "strconv" |
| + |
| + "github.com/carlosframework/platform/internal/provision" |
| +) |
| + |
| +// Transition is what one record write did to a move, as the move log names |
| +// it (log.go): the move, the event, the identity that keys its log object, |
| +// and the fields it carries (the regions, the evidence's digests, timings, |
| +// a stuck's role). The box's writers and the console's move pass name their |
| +// writes with it, so a transition has one identity whoever writes it. |
| +type Transition struct { |
| + Op, Event, Identity string |
| + Fields map[string]string |
| +} |
| + |
| +// phaseOf is the phase a move's state is at: the cut's, the landing's, or |
| +// (rolling back) the target's and the source's. |
| +func phaseOf(m *provision.MoveState) (phase, target, source string) { |
| + switch m.State { |
| + case provision.MoveCutting: |
| + return m.CutPhase, "", "" |
| + case provision.MoveLanding: |
| + return m.LandingPhase, "", "" |
| + case provision.MoveRollingBack: |
| + if m.Rollback != nil { |
| + return "", m.Rollback.TargetPhase, m.Rollback.SourcePhase |
| + } |
| + } |
| + return "", "", "" |
| +} |
| + |
| +// transitionFields are a move's regions and the digests its evidence has |
| +// recorded so far: the source's stop (final TXID, database, files, timers), |
| +// the landing's installed database, the pinned inputs (release, env |
| +// report). |
| +func transitionFields(m *provision.MoveState) map[string]string { |
| + f := map[string]string{"from": m.From, "to": m.To} |
| + set := func(k, v string) { |
| + if v != "" { |
| + f[k] = v |
| + } |
| + } |
| + if s := m.Source; s != nil { |
| + if s.FinalTXID != 0 { |
| + f["final_txid"] = strconv.FormatUint(s.FinalTXID, 10) |
| + } |
| + set("db_sha256", s.DBSHA256) |
| + set("timers_sha256", s.TimersSHA256) |
| + if s.Files != nil { |
| + set("files_plain", s.Files.Plain) |
| + } |
| + } |
| + if l := m.Landing; l != nil { |
| + set("installed_db_sha256", l.InstalledDBSHA256) |
| + } |
| + if in := m.Inputs; in != nil { |
| + set("release", in.Release) |
| + set("env_report", in.EnvReport) |
| + } |
| + return f |
| +} |
| + |
| +// seconds is b - a in whole seconds, "" unless both are known. |
| +func seconds(a, b interface{ Unix() int64 }) string { |
| + return strconv.FormatInt(b.Unix()-a.Unix(), 10) |
| +} |
| + |
| +// TransitionOf names the transition from before to after, one record write: |
| +// before as the write found it, after as written. ok is false when the |
| +// write changed nothing the log records (a pin, recovery inputs, a replay). |
| +// |
| +// Identities: <state>-<phase> for a phase step (a rollback names the half |
| +// that moved, rolling_back-target-<p> or rolling_back-source-<p>), the |
| +// flip as cutting-flipped, committed-opened and committed-source_parked, |
| +// reverting-opened, probe_attempt-<n> for the landing's n-th probe, |
| +// stuck-<epoch> keyed by the record's recovery retry epoch, the new state |
| +// itself (requested for preparing, cutting-requested, ready, aborting, |
| +// reverting, relocating, rolling_back), and the terminal outcome (done, |
| +// rolled_back, aborted). |
| +func TransitionOf(before, after provision.Record) (Transition, bool) { |
| + bm, am := before.Move, after.Move |
| + if am == nil { |
| + // A close clears the move and leaves its outcome (D11). |
| + if bm == nil || after.LastMove == nil || after.LastMove.ID != bm.ID || bm.ID == "" { |
| + return Transition{}, false |
| + } |
| + f := transitionFields(bm) |
| + f["offline_s"] = strconv.FormatFloat(after.LastMove.OfflineS, 'f', -1, 64) |
| + return Transition{Op: bm.ID, Event: after.LastMove.Outcome, Identity: after.LastMove.Outcome, Fields: f}, true |
| + } |
| + if am.ID == "" || (bm != nil && bm.ID != am.ID) { |
| + return Transition{}, false |
| + } |
| + e := Transition{Op: am.ID, Fields: transitionFields(am)} |
| + if bm == nil { |
| + bm = &provision.MoveState{} |
| + } |
| + switch { |
| + case am.State == provision.MoveStuck: |
| + if bm.State == provision.MoveStuck { |
| + return Transition{}, false |
| + } |
| + e.Event, e.Identity = "stuck", "stuck-"+strconv.FormatUint(am.RecoveryRetryEpoch, 10) |
| + // A rollback's target stops for an operator only at its return |
| + // (returning); every other stuck is the source's. |
| + e.Fields["role"] = "source" |
| + if am.Rollback != nil && am.Rollback.TargetPhase == provision.RbTargetReturning { |
| + e.Fields["role"] = "target" |
| + } |
| + if am.StuckReason != "" { |
| + e.Fields["reason"] = am.StuckReason |
| + } |
| + return e, true |
| + case am.State == provision.MoveLanding && am.Landing != nil && am.Landing.Attempts > 0 && (bm.Landing == nil || am.Landing.Attempts > bm.Landing.Attempts): |
| + e.Event, e.Identity = "probe_attempt", "probe_attempt-"+strconv.Itoa(am.Landing.Attempts) |
| + return e, true |
| + case bm.State == provision.MoveCutting && am.State == provision.MoveLanding: |
| + e.Event, e.Identity = "flipped", "cutting-flipped" |
| + return e, true |
| + case am.State == provision.MoveCommitted && bm.State == provision.MoveCommitted: |
| + switch { |
| + case am.SourceParkedAt != nil && bm.SourceParkedAt == nil: |
| + e.Event, e.Identity = "source_parked", "committed-source_parked" |
| + case am.OpenedAt != nil && bm.OpenedAt == nil: |
| + e.Event, e.Identity = "opened", "committed-opened" |
| + if am.CutAt != nil { |
| + e.Fields["offline_s"] = seconds(*am.CutAt, *am.OpenedAt) |
| + } |
| + default: |
| + return Transition{}, false |
| + } |
| + return e, true |
| + case am.State == provision.MoveReverting && bm.State == provision.MoveReverting: |
| + if am.ReopenedAt == nil || bm.ReopenedAt != nil { |
| + return Transition{}, false |
| + } |
| + e.Event, e.Identity = "rev_opened", "reverting-opened" |
| + if am.CutAt != nil { |
| + e.Fields["offline_s"] = seconds(*am.CutAt, *am.ReopenedAt) |
| + } |
| + return e, true |
| + } |
| + phase, target, source := phaseOf(am) |
| + bphase, btarget, bsource := phaseOf(bm) |
| + if am.State == bm.State { |
| + switch { |
| + case am.State == provision.MoveRollingBack && target != btarget: |
| + e.Event, e.Identity = target, "rolling_back-target-"+target |
| + if target == provision.RbTargetLost { |
| + e.Event = "declared_lost" |
| + } |
| + case am.State == provision.MoveRollingBack && source != bsource: |
| + e.Event, e.Identity = source, "rolling_back-source-"+source |
| + rb := am.Rollback |
| + switch source { |
| + case provision.RbSourceRecovered: |
| + if rb.RecoveredAt != nil { |
| + if rb.RequestedAt != nil { |
| + e.Fields["recovery_s"] = seconds(*rb.RequestedAt, *rb.RecoveredAt) |
| + } |
| + if am.CutAt != nil { |
| + e.Fields["offline_s"] = seconds(*am.CutAt, *rb.RecoveredAt) |
| + } |
| + } |
| + case provision.RbSourceOpened: |
| + if rb.OpenedAt != nil && am.CutAt != nil { |
| + e.Fields["offline_s"] = seconds(*am.CutAt, *rb.OpenedAt) |
| + } |
| + } |
| + case phase != bphase && phase != "": |
| + e.Event, e.Identity = phase, am.State+"-"+phase |
| + if am.State == provision.MoveCutting && phase == provision.CutRequested { |
| + e.Event = "cut_requested" |
| + } |
| + default: |
| + return Transition{}, false |
| + } |
| + return e, true |
| + } |
| + // A new state. |
| + switch am.State { |
| + case provision.MovePreparing: |
| + e.Event, e.Identity = "requested", "requested" |
| + case provision.MoveCutting: |
| + e.Event, e.Identity = phase, "cutting-"+phase |
| + if phase == provision.CutRequested || phase == "" { |
| + e.Event, e.Identity = "cut_requested", "cutting-requested" |
| + } |
| + case provision.MoveLanding: |
| + e.Event, e.Identity = phase, "landing-"+phase |
| + case provision.MoveRollingBack: |
| + e.Event, e.Identity = "rolling_back", "rolling_back" |
| + if am.Rollback != nil && am.Rollback.Reason != "" { |
| + e.Fields["reason"] = am.Rollback.Reason |
| + } |
| + default: |
| + // ready, committed, aborting, reverting, relocating: the state is the |
| + // event. |
| + e.Event, e.Identity = am.State, am.State |
| + } |
| + return e, true |
| +} |
diff --git a/move.go b/move.go| index 1edb02327..670426511 100644 |
| --- a/move.go |
| +++ b/move.go |
| @@ -20,6 +20,7 @@ import ( |
| "github.com/carlosframework/platform/internal/awsinv" |
| "github.com/carlosframework/platform/internal/hostfence" |
| "github.com/carlosframework/platform/internal/hostresolve" |
| + "github.com/carlosframework/platform/internal/moves" |
| ) |
| // `carlos move` (spec §12, moves Phase 1 Plan 6 Task 1a): request a move of |
| @@ -576,7 +577,7 @@ func (m *mover) accepted(ctx context.Context, r moveReply, wait, request bool) i |
| } |
| w.learn(a) |
| if request && w.first("start") { |
| - moveSay(m.out, fmt.Sprintf("Moving %s from %s to %s.", m.host, w.fromRegion, w.toRegion)) |
| + moveSay(m.out, moves.MoveStartingLine(m.host, w.fromRegion, w.toRegion)) |
| } |
| return w.run(ctx) |
| } |
| @@ -694,7 +695,7 @@ func (w *moveWatch) observe(a moveAnswer) int { |
| j = &moveJournal{} |
| } |
| if w.first("start") { |
| - moveSay(w.m.out, fmt.Sprintf("Moving %s from %s to %s.", host, from, to)) |
| + moveSay(w.m.out, moves.MoveStartingLine(host, from, to)) |
| } |
| switch a.State { |
| case "preparing": |
| @@ -726,12 +727,12 @@ func (w *moveWatch) observe(a moveAnswer) int { |
| case "cutting": |
| if j.CutPhase != "" && j.CutPhase != "requested" && j.CutBudgetS > 0 { |
| if w.first("cut") { |
| - moveSay(w.m.out, fmt.Sprintf("%s is ready. Starting the cut. %s will be offline for about %s.", to, host, moveEstimate(j.CutBudgetS))) |
| + moveSay(w.m.out, moves.CutStartingLine(to, host, moves.CutBudgetText(j.CutBudgetS))) |
| } |
| } |
| case "landing", "committed": |
| if w.first("landing") { |
| - moveSay(w.m.out, fmt.Sprintf("Stopped in %s. Starting in %s.", from, to)) |
| + moveSay(w.m.out, moves.FlippedLine(from, to)) |
| } |
| case "rolling_back", "reverting": |
| reason := j.Reason |
| @@ -740,7 +741,7 @@ func (w *moveWatch) observe(a moveAnswer) int { |
| } |
| if reason != "" { |
| if w.first("rollback") { |
| - moveSay(w.m.out, fmt.Sprintf("%s could not start %s: %s. Moving it back to %s.", to, host, reason, from)) |
| + moveSay(w.m.out, moves.MovingBackLine(to, host, reason, from)) |
| } |
| } |
| if rb := j.Rollback; rb != nil && rb.ReleaseDeadline != nil && time.Now().After(*rb.ReleaseDeadline) && rb.TargetPhase == "releasing" { |
| @@ -787,7 +788,7 @@ func (w *moveWatch) outcome(a moveAnswer) int { |
| if to == "" { |
| return w.outcomeLine(l, moveExitDone) |
| } |
| - moveSay(w.m.out, fmt.Sprintf("Moved. %s is served from %s. It was offline for %d seconds.", host, to, int(math.Round(l.OfflineS)))) |
| + moveSay(w.m.out, moves.MovedLine(host, to, int(math.Round(l.OfflineS)))) |
| return moveExitDone |
| case "rolled_back": |
| if from == "" { |
| @@ -796,9 +797,9 @@ func (w *moveWatch) outcome(a moveAnswer) int { |
| // M-C8 for a rollback the wait missed only when the outcome carries |
| // its reason (ruling 4), and only with its destination known. |
| if l.Reason != "" && to != "" && w.first("rollback") { |
| - moveSay(w.m.out, fmt.Sprintf("%s could not start %s: %s. Moving it back to %s.", to, host, l.Reason, from)) |
| + moveSay(w.m.out, moves.MovingBackLine(to, host, l.Reason, from)) |
| } |
| - moveSay(w.m.out, fmt.Sprintf("%s is back in %s and serving. Nothing was lost.", host, from)) |
| + moveSay(w.m.out, moves.MovedBackLine(host, from)) |
| return moveExitRolled |
| case "aborted": |
| if from == "" { |
| @@ -818,14 +819,6 @@ func (w *moveWatch) outcomeLine(l *moveOutcome, code int) int { |
| return code |
| } |
| -// moveEstimate renders a cut budget for M-C5. |
| -func moveEstimate(seconds int) string { |
| - if seconds < 90 { |
| - return fmt.Sprintf("%d seconds", seconds) |
| - } |
| - return fmt.Sprintf("%d minutes", (seconds+59)/60) |
| -} |
| - |
| // declareLost is carlos move resolve --declare-lost <box> (Task 1b): claim |
| // Plan 10's move door, inspect then declare, through declareHostLoss, the |
| // half carlos ops host resolve shares. The operator types the host name to |