carlos / platform Public

moves: timings against budgets in the terminal log events (§13)

moves-phase1-6 Task 4. moves.Timings works out prepare, cut, land,
offline and a rollback's span, each beside its budget (cut_budget_s,
the landing deadline, the release deadline), from the record's own
journal times. TransitionOf adds them to the done and rolled_back
entries' Fields, so the box's outbox and the console's move_log_outbox
carry the same seconds whoever writes the entry. detail=1 shows them
from the logged entry (moves.TimingsOf), never worked out again.

Preflight L20: the landing deadline rule moves to
provision.LandingDeadlineOf (host's landingDeadlineOf and the console's
moveDeadlinePassed call it), and the three closes share
provision.MoveOfflineS with the timings. L29: moves.PreparingSince is
the one start of AbortDue and the console's 60-minute page.

No censused unit changes. No new sentence.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

claude 1 week ago c34b88d0c1461f102cf62325de61a46f4fe9ebdc parent dd8fc09

10 files changed, +508 −46

internal/console/apiinstancemove.go +34 −0
internal/console/apiinstancemove_test.go +58 −4
internal/console/movesrecovery.go +4 −16
internal/console/movesrecovery_test.go +31 −0
internal/host/movesland.go +4 −12
internal/moves/abort.go +10 −1
internal/moves/log.go +95 −0
internal/moves/timings_test.go +205 −0
internal/moves/transition.go +10 −2
internal/provision/provision.go +57 −11

diff --git a/internal/console/apiinstancemove.go b/internal/console/apiinstancemove.go

index f2eecc0d2..90cf4ec3a 100644

--- a/internal/console/apiinstancemove.go

+++ b/internal/console/apiinstancemove.go

@@ -1290,6 +1290,12 @@ type moveDetailBody struct {

// Log is every key under the move's log/ prefix, sorted (preflight L26:

// a move writes a few dozen; the CLI reads bodies only on demand).

Log []string `json:"log"`

+ // Timings are a closed move's timings against their budgets (Plan 6

+ // Task 4, moves.Timings), in seconds: the timing fields of its done or

+ // rolled_back log entry and nothing else of it, as the entry's writer

+ // worked them out from the record's journal. Absent until that entry

+ // is logged.

+ Timings map[string]float64 `json:"timings,omitempty"`

// WaitingForBox is the region a relocating move waits on for a live

// enrolled box (M-C22), empty otherwise and when it cannot be told.

WaitingForBox string `json:"waiting_for_box,omitempty"`

@@ -1433,6 +1439,15 @@ func (s *Server) writeMoveDetail(w http.ResponseWriter, r *http.Request, acct *A

}

slices.Sort(keys)

out.Detail.Log = append(out.Detail.Log, keys...)

+ if rec.Move == nil && rec.LastMove != nil {

+ timings, err := s.readMoveTimings(ctx, prefix, rec.LastMove.Outcome)

+ if err != nil {

+ log.Printf("console: api instance move %s/%s/%s: detail: timings of %s: %v", acct.Sqid, app, host, opID, err)

+ jsonError(w, http.StatusBadGateway, "could not read the move's reports. try again")

+ return

+ }

+ out.Detail.Timings = timings

+ }

}

if (rec.Move != nil && rec.Move.State == provision.MoveRelocating) || moveConvertedAfterCommit(rec, obs) {

out.State = provision.MoveRelocating

@@ -1448,6 +1463,25 @@ func (s *Server) writeMoveDetail(w http.ResponseWriter, r *http.Request, acct *A

writeJSON(w, http.StatusOK, out)

}

+// readMoveTimings is the timings a closed move's terminal log entry carries

+// (moves.TimingsOf over its Fields): nil for an outcome that carries none

+// (aborted), for an entry not logged yet, and for one that does not parse

+// (logged); an error when the read failed.

+func (s *Server) readMoveTimings(ctx context.Context, prefix, outcome string) (map[string]float64, error) {

+ if outcome != "done" && outcome != "rolled_back" {

+ return nil, nil

+ }

+ var ev moves.LogEvent

+ ok, err := s.readMoveReport(ctx, moves.LogKeyFor(prefix, outcome), &ev)

+ if !ok || err != nil {

+ return nil, err

+ }

+ if t := moves.TimingsOf(ev.Fields); len(t) > 0 {

+ return t, nil

+ }

+ return nil, nil

// readMoveReport reads one report: (false, nil) when it is absent or does

// not parse (logged), an error when the read failed.

func (s *Server) readMoveReport(ctx context.Context, key string, into any) (bool, error) {

diff --git a/internal/console/apiinstancemove_test.go b/internal/console/apiinstancemove_test.go

index dec908463..af45ff58c 100644

--- a/internal/console/apiinstancemove_test.go

+++ b/internal/console/apiinstancemove_test.go

@@ -1699,10 +1699,11 @@ type moveAnswer struct {

Source string `json:"source"`

Target string `json:"target"`

} `json:"evidence"`

- Log []string `json:"log"`

- WaitingForBox string `json:"waiting_for_box"`

- From string `json:"from"`

- Region string `json:"region"`

+ Log []string `json:"log"`

+ Timings map[string]float64 `json:"timings"`

+ WaitingForBox string `json:"waiting_for_box"`

+ From string `json:"from"`

+ Region string `json:"region"`

} `json:"detail"`

}

@@ -1964,6 +1965,59 @@ func TestMoveDetailLeaksNothing(t *testing.T) {

}

+// Plan 6 Task 4: once a move has closed done or rolled_back, detail=1 shows

+// its timings, read from the terminal log event's Fields: the box or the

+// console wrote them from the record's own journal times when it built the

+// entry (moves.Timings), and the door never works them out a second way.

+// Only the timing fields are shown, never the rest of the event; a move with

+// no terminal event logged yet, or one still in flight, shows none; a log

+// read that fails answers the reports' fixed sentence.

+func TestMoveDetailShowsTheTimings(t *testing.T) {

+ fx, token, moveURL := moveDoorWithClaim(t, "code-inst-move-timings")

+ ctx := context.Background()

+ readMoveAnswer(t, http.MethodPost, moveURL, token, `{"region":"uk","cut":"manual"}`, http.StatusAccepted)

+ mv := recordMove(t, fx)

+ if a, out := readMoveAnswer(t, http.MethodGet, moveURL+"?detail=1", token, "", http.StatusOK); a.Detail == nil || a.Detail.Timings != nil {

+ t.Fatalf("a move in flight shows timings: %s", out)

+ }

+ prefix := moves.ReportPrefix("bab", "titogo", "acme.go.tito.io", mv.ID)

+ setMove(t, fx, func(rec *provision.Record) {

+ rec.Move, rec.LastMove = nil, &provision.MoveOutcome{ID: mv.ID, Outcome: "done", At: time.Now().UTC(), OfflineS: 70.5}

+ })

+ if a, out := readMoveAnswer(t, http.MethodGet, moveURL+"?detail=1", token, "", http.StatusOK); a.Detail == nil || a.Detail.Timings != nil {

+ t.Fatalf("timings before the terminal event is logged: %s", out)

+ }

+ const digest = "c0ffee00c0ffee00c0ffee00c0ffee00c0ffee00c0ffee00c0ffee00c0ffee00"

+ ev := moves.LogEvent{V: 1, Op: mv.ID, Host: "acme.go.tito.io", Event: "done", Identity: "done", Actor: "uk-box", At: time.Now().UTC(),

+ Fields: map[string]string{"from": "ie", "to": "uk", "db_sha256": digest, "prepare_s": "300", "cut_s": "40", "cut_budget_s": "95",

+ "land_s": "30.5", "land_budget_s": "50", "offline_s": "70.5"}}

+ if _, err := moves.WriteLog(ctx, fx.rel, prefix, ev); err != nil {

+ t.Fatal(err)

+ }

+ a, out := readMoveAnswer(t, http.MethodGet, moveURL+"?detail=1", token, "", http.StatusOK)

+ want := map[string]float64{"prepare_s": 300, "cut_s": 40, "cut_budget_s": 95, "land_s": 30.5, "land_budget_s": 50, "offline_s": 70.5}

+ if a.Detail == nil || !reflect.DeepEqual(a.Detail.Timings, want) {

+ t.Fatalf("detail timings = %s, want %v", out, want)

+ }

+ if strings.Contains(out, digest) {

+ t.Fatalf("the detail shows the event's other fields: %s", out)

+ }

+ // A rolled_back close reads its own event, not the done one.

+ setMove(t, fx, func(rec *provision.Record) { rec.LastMove.Outcome = "rolled_back" })

+ if a, out := readMoveAnswer(t, http.MethodGet, moveURL+"?detail=1", token, "", http.StatusOK); a.Detail == nil || a.Detail.Timings != nil {

+ t.Fatalf("a rolled_back close shows the done event's timings: %s", out)

+ }

+ rb := ev

+ rb.Event, rb.Identity, rb.Fields = "rolled_back", "rolled_back", map[string]string{"offline_s": "210", "rollback_s": "135", "release_budget_s": "900"}

+ if _, err := moves.WriteLog(ctx, fx.rel, prefix, rb); err != nil {

+ t.Fatal(err)

+ }

+ if a, out := readMoveAnswer(t, http.MethodGet, moveURL+"?detail=1", token, "", http.StatusOK); a.Detail == nil ||

+ !reflect.DeepEqual(a.Detail.Timings, map[string]float64{"offline_s": 210, "rollback_s": 135, "release_budget_s": 900}) {

+ t.Fatalf("rolled_back timings = %s", out)

+ }

// Relocating (spec rev 7.20 §7.10, D16) and Paul's J3 (preflight L18): a

// move whose claim is relocating/pinning with exec "none" in a region with

// no live enrolled box reports waiting_for_box = that region: the source's

diff --git a/internal/console/movesrecovery.go b/internal/console/movesrecovery.go

index 0e6583b91..074e04689 100644

--- a/internal/console/movesrecovery.go

+++ b/internal/console/movesrecovery.go

@@ -178,7 +178,7 @@ func decideMoveRecovery(in moveRecoveryInput) moveRecoveryDecision {

if m.State == provision.MoveRollingBack && rb != nil && rb.ReleaseDeadline != nil && in.Now.After(*rb.ReleaseDeadline) && rb.TargetPhase == provision.RbTargetReleasing {

d.Pages = append(d.Pages, movePageReleaseDeadline)

}

- if m.State == provision.MovePreparing && !m.RequestedAt.IsZero() && !in.Now.Before(preparingSince(m).Add(movePreparingPage)) {

+ if m.State == provision.MovePreparing && !m.RequestedAt.IsZero() && !in.Now.Before(moves.PreparingSince(m).Add(movePreparingPage)) {

d.Pages = append(d.Pages, movePagePreparing)

}

owed := owedUnderOp(c, op.ID, nil)

@@ -216,23 +216,11 @@ func decideMoveRecovery(in moveRecoveryInput) moveRecoveryDecision {

return d

}

-// preparingSince is where a preparing move's clocks run from: the later of

-// its request and its readiness (moves.AbortDue's base, K18).

-func preparingSince(m *provision.MoveState) time.Time {

- from := m.RequestedAt

- if m.ReadyAt != nil && m.ReadyAt.After(from) {

- from = *m.ReadyAt

- }

- return from

// moveDeadlinePassed is the grant's deadline rule: the earlier of the cut and

-// landing deadlines (J11) is behind now.

+// landing deadlines (J11, provision.LandingDeadlineOf, the box's own rule) is

+// behind now.

func moveDeadlinePassed(m *provision.MoveState, now time.Time) bool {

- deadline := m.CutDeadline

- if l := m.LandingDeadline; l != nil && (deadline == nil || l.Before(*deadline)) {

- deadline = l

- }

+ deadline, _ := provision.LandingDeadlineOf(m)

return deadline != nil && now.After(*deadline)

}

diff --git a/internal/console/movesrecovery_test.go b/internal/console/movesrecovery_test.go

index 38468fc0a..2a08ec5db 100644

--- a/internal/console/movesrecovery_test.go

+++ b/internal/console/movesrecovery_test.go

@@ -618,6 +618,37 @@ func TestRecordFirstCloseCrashIsFinishedByThePass(t *testing.T) {

// 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")

diff --git a/internal/host/movesland.go b/internal/host/movesland.go

index 702c274f8..089364023 100644

--- a/internal/host/movesland.go

+++ b/internal/host/movesland.go

@@ -251,19 +251,11 @@ func (l *landingRun) step(ctx context.Context) (bool, error) {

}

// landingDeadlineOf is the deadline a landing before restored works to:

-// the earlier of the cut's absolute deadline and landing_deadline. Spec

-// §7.4 has every pre-commit phase on both participants check the absolute

-// deadline; the flip's landing_deadline is a second, separate bound, never

-// an extension of it (final review, finding 3). which names the one that

-// applies, for the log.

+// provision.LandingDeadlineOf, the earlier of the cut's absolute deadline

+// and landing_deadline, which the move's timings share (Plan 6 preflight

+// L20). which names the one that applies, for the log.

func landingDeadlineOf(m *provision.MoveState) (d *time.Time, which string) {

- if m.CutDeadline != nil {

- d, which = m.CutDeadline, "cut_deadline"

- }

- if m.LandingDeadline != nil && (d == nil || m.LandingDeadline.Before(*d)) {

- d, which = m.LandingDeadline, "landing_deadline"

- }

- return d, which

+ return provision.LandingDeadlineOf(m)

}

// pastDeadline reports whether the landing's deadline (landingDeadlineOf)

diff --git a/internal/moves/abort.go b/internal/moves/abort.go

index 60c136e20..7ba8d4c91 100644

--- a/internal/moves/abort.go

+++ b/internal/moves/abort.go

@@ -31,9 +31,18 @@ func AbortDue(rec provision.Record, now time.Time) bool {

if m == nil || m.Legacy() || m.State != provision.MovePreparing || m.RequestedAt.IsZero() {

return false

}

+ return !now.Before(PreparingSince(m).Add(AbortAfter))

+// PreparingSince is where a preparing move's clocks run from: the later of

+// its RequestedAt and its ReadyAt (ruling K18). The six-hour abort (AbortDue)

+// and the console's 60-minute page (§13) both measure from it, so the two

+// can never disagree about how long a move has prepared (Plan 6 preflight

+// L29).

+func PreparingSince(m *provision.MoveState) time.Time {

from := m.RequestedAt

if m.ReadyAt != nil && m.ReadyAt.After(from) {

from = *m.ReadyAt

}

- return !now.Before(from.Add(AbortAfter))

+ return from

}

diff --git a/internal/moves/log.go b/internal/moves/log.go

index 955306272..53cb3996e 100644

--- a/internal/moves/log.go

+++ b/internal/moves/log.go

@@ -7,9 +7,11 @@ import (

"fmt"

"os"

"sort"

+ "strconv"

"strings"

"time"

+ "github.com/carlosframework/platform/internal/provision"

"github.com/carlosframework/platform/internal/release"

)

@@ -97,3 +99,96 @@ func ReadLog(ctx context.Context, s release.Store, prefix string) ([]LogEvent, e

})

return out, nil

}

+// Timings (spec §13, Plan 6 Task 4): how long a move took, phase by phase,

+// each beside its budget, in seconds. They are worked out once, from the

+// record's own journal times, when the done or rolled_back entry is built

+// (TransitionOf, whoever writes it), never from a clock at delivery, and

+// carried in that entry's Fields; detail=1 shows them from there (TimingsOf).

+//

+// - prepare_s: requested_at to ready_at.

+// - cut_s: cut_at to flipped_at.

+// - land_s: flipped_at to opened_at, against land_budget_s, the landing

+// deadline (provision.LandingDeadlineOf: the earlier of cut_deadline and

+// landing_deadline) less flipped_at.

+// - offline_s: cut_at to the open, or to the source's reopen after a

+// rollback or a revert (provision.MoveOfflineS, the closes' own),

+// against cut_budget_s, the admitted stop-to-open estimate (T11).

+// - rollback_s: a rollback's decision (rollback.requested_at) to the

+// source's reopen (rollback.opened_at), against release_budget_s, its

+// release deadline less its decision. The record stamps no "released",

+// so the rollback is measured to the reopen, which comes only after the

+// target's release.

+//

+// A timing whose ends are not both stamped is left out, and so is a budget

+// the record does not carry.

+const (

+ TimingPrepare = "prepare_s"

+ TimingCut = "cut_s"

+ TimingCutBudget = "cut_budget_s"

+ TimingLand = "land_s"

+ TimingLandBudget = "land_budget_s"

+ TimingOffline = "offline_s"

+ TimingRollback = "rollback_s"

+ TimingReleaseBudget = "release_budget_s"

+// timingKeys are every key Timings may set.

+var timingKeys = []string{TimingPrepare, TimingCut, TimingCutBudget, TimingLand, TimingLandBudget, TimingOffline, TimingRollback, TimingReleaseBudget}

+// Timings is m's timings (see above); empty for no move.

+func Timings(m *provision.MoveState) map[string]float64 {

+ out := map[string]float64{}

+ if m == nil {

+ return out

+ }

+ span := func(key string, from, to *time.Time) {

+ if from != nil && to != nil {

+ out[key] = to.Sub(*from).Seconds()

+ }

+ if !m.RequestedAt.IsZero() {

+ span(TimingPrepare, &m.RequestedAt, m.ReadyAt)

+ }

+ span(TimingCut, m.CutAt, m.FlippedAt)

+ if m.CutBudgetS > 0 {

+ out[TimingCutBudget] = float64(m.CutBudgetS)

+ }

+ if m.State == provision.MoveCommitted {

+ span(TimingLand, m.FlippedAt, m.OpenedAt)

+ }

+ if d, _ := provision.LandingDeadlineOf(m); m.FlippedAt != nil {

+ span(TimingLandBudget, m.FlippedAt, d)

+ }

+ if s, ok := provision.MoveOfflineS(m); ok {

+ out[TimingOffline] = s

+ }

+ if rb := m.Rollback; rb != nil {

+ span(TimingRollback, rb.RequestedAt, rb.OpenedAt)

+ span(TimingReleaseBudget, rb.RequestedAt, rb.ReleaseDeadline)

+ }

+ return out

+// TimingsOf is the timings a logged entry's Fields carry: the timing keys

+// alone, each parsed back to seconds; anything else in the fields, and a

+// value that does not parse, is left out.

+func TimingsOf(fields map[string]string) map[string]float64 {

+ out := map[string]float64{}

+ for _, k := range timingKeys {

+ v, ok := fields[k]

+ if !ok {

+ continue

+ }

+ if f, err := strconv.ParseFloat(v, 64); err == nil {

+ out[k] = f

+ }

+ return out

+// timingText is a timing as a field's text: the shortest decimal that

+// parses back to it.

+func timingText(s float64) string {

+ return strconv.FormatFloat(s, 'f', -1, 64)

diff --git a/internal/moves/timings_test.go b/internal/moves/timings_test.go

new file mode 100644

index 000000000..1992f44ec

--- /dev/null

+++ b/internal/moves/timings_test.go

@@ -0,0 +1,205 @@

+package moves

+import (

+ "reflect"

+ "strconv"

+ "testing"

+ "time"

+ "github.com/carlosframework/platform/internal/provision"

+// The fixture journals of Plan 6 Task 4 (spec §13): one move per outcome,

+// with every stamp a known distance from the cut.

+const (

+ tmID = "mv_abcdefghijklmnopqrstuvwxyz"

+ tmInc = "inc-1"

+ tmRB = "rb_abcdefghijklmnopqrstuvwxyz"

+var tmT0 = time.Date(2026, 10, 11, 9, 0, 0, 0, time.UTC)

+func tmAt(d time.Duration) *time.Time { t := tmT0.Add(d); return &t }

+// tmCut is 10 minutes after the request; every later stamp is from it.

+func tmCut(d time.Duration) *time.Time { return tmAt(10*time.Minute + d) }

+// doneJournal: requested, ready 5 minutes later, cut 5 minutes after that

+// with a 95-second budget (cut_deadline 90 s after the cut, the open budget

+// off it), flipped 40 s in, a landing_deadline later than the cut's deadline

+// (so the cut's binds: 50 s after the flip), opened 70.5 s after the cut.

+func doneJournal() *provision.MoveState {

+ return &provision.MoveState{ID: tmID, Incarnation: tmInc, From: "ie", To: "uk", State: provision.MoveCommitted,

+ RequestedAt: tmT0, ReadyAt: tmAt(5 * time.Minute), CutAt: tmCut(0), CutBudgetS: 95, CutDeadline: tmCut(90 * time.Second),

+ FlippedAt: tmCut(40 * time.Second), LandingDeadline: tmCut(160 * time.Second),

+ CommittedAt: tmCut(65 * time.Second), OpenedAt: tmCut(70500 * time.Millisecond), SourceParkedAt: tmCut(5 * time.Minute)}

+// rolledBackJournal: the same cut and flip, a landing_deadline 30 s after

+// the flip (earlier than the cut's, so it binds), the rollback decided at 75

+// s with its 15-minute release deadline, the source recovered at 200 s and

+// reopened at 210 s, the target parked at 300 s.

+func rolledBackJournal() *provision.MoveState {

+ m := doneJournal()

+ m.State, m.CommittedAt, m.OpenedAt, m.SourceParkedAt = provision.MoveRollingBack, nil, nil, nil

+ m.LandingDeadline = tmCut(70 * time.Second)

+ m.Rollback = &provision.MoveRollback{ID: tmRB, Reason: provision.RollbackLandingDeadline, RequestedAt: tmCut(75 * time.Second),

+ ReleaseDeadline: tmCut(75*time.Second + 15*time.Minute), TargetPhase: provision.RbTargetCleaned, SourcePhase: provision.RbSourceOpened,

+ RecoveredAt: tmCut(200 * time.Second), OpenedAt: tmCut(210 * time.Second), TargetParkedAt: tmCut(300 * time.Second)}

+ return m

+// revertJournal: cut, never flipped, the source reopened 50 s after the cut.

+func revertJournal() *provision.MoveState {

+ m := doneJournal()

+ m.State, m.FlippedAt, m.LandingDeadline, m.CommittedAt, m.OpenedAt, m.SourceParkedAt = provision.MoveReverting, nil, nil, nil, nil, nil

+ m.ReopenedAt = tmCut(50 * time.Second)

+ return m

+// Plan 6 Task 4: a fixture journal yields the expected seconds, each beside

+// its budget: prepare (requested to ready), cut (cut_at to the flip), land

+// (the flip to the open) against the landing deadline (the earlier of the

+// cut's absolute deadline and landing_deadline, provision.LandingDeadlineOf),

+// offline (cut_at to the open, or to the source's reopen) against the cut's

+// admitted budget, and a rollback (its decision to the source's reopen)

+// against its release deadline.

+func TestTimingsOfAFixtureJournal(t *testing.T) {

+ for name, c := range map[string]struct {

+ m *provision.MoveState

+ want map[string]float64

+ }{

+ "done": {doneJournal(), map[string]float64{

+ "prepare_s": 300, "cut_s": 40, "cut_budget_s": 95, "land_s": 30.5, "land_budget_s": 50, "offline_s": 70.5}},

+ "rolled back after the flip": {rolledBackJournal(), map[string]float64{

+ "prepare_s": 300, "cut_s": 40, "cut_budget_s": 95, "land_budget_s": 30, "offline_s": 210,

+ "rollback_s": 135, "release_budget_s": 900}},

+ "reverted before the flip": {revertJournal(), map[string]float64{

+ "prepare_s": 300, "cut_budget_s": 95, "offline_s": 50}},

+ "nothing stamped but the request": {&provision.MoveState{ID: tmID, State: provision.MovePreparing, RequestedAt: tmT0}, map[string]float64{}},

+ "no move": {nil, map[string]float64{}},

+ } {

+ if got := Timings(c.m); !reflect.DeepEqual(got, c.want) {

+ t.Errorf("%s: Timings = %v, want %v", name, got, c.want)

+ }

+ // The landing deadline is provision's one rule (preflight L20): the

+ // earlier of the two, named.

+ for name, c := range map[string]struct {

+ m *provision.MoveState

+ want *time.Time

+ which string

+ }{

+ "the cut's binds": {doneJournal(), doneJournal().CutDeadline, "cut_deadline"},

+ "the landing's binds": {rolledBackJournal(), rolledBackJournal().LandingDeadline, "landing_deadline"},

+ "neither": {&provision.MoveState{}, nil, ""},

+ } {

+ d, which := provision.LandingDeadlineOf(c.m)

+ if which != c.which || (d == nil) != (c.want == nil) || (d != nil && !d.Equal(*c.want)) {

+ t.Errorf("%s: LandingDeadlineOf = %v %q, want %v %q", name, d, which, c.want, c.which)

+ }

+// Preflight L20: Timings' offline is the closes' own (provision.MoveOfflineS),

+// so it equals the LastMove.OfflineS each of the three closes records.

+func TestTimingsOfflineIsTheClosesOffline(t *testing.T) {

+ g := provision.MoveGuard{ID: tmID, Incarnation: tmInc}

+ now := *tmCut(time.Hour)

+ for name, c := range map[string]struct {

+ m *provision.MoveState

+ region string

+ close func(*provision.Record) error

+ }{

+ "MoveClose": {doneJournal(), "uk", provision.MoveClose(g, now)},

+ "MoveRolledBackClose": {rolledBackJournal(), "ie", provision.MoveRolledBackClose(g, now)},

+ "MoveRevertClose": {revertJournal(), "ie", provision.MoveRevertClose(g, now)},

+ } {

+ want := Timings(c.m)["offline_s"]

+ rec := provision.Record{Host: "a.go.example.com", Region: c.region, Move: c.m}

+ if err := c.close(&rec); err != nil {

+ t.Fatalf("%s: %v", name, err)

+ }

+ if rec.LastMove == nil || rec.LastMove.OfflineS != want || want == 0 {

+ t.Errorf("%s: the close recorded %+v, Timings says offline %v", name, rec.LastMove, want)

+ }

+// Plan 6 Task 4: the done and rolled_back log events carry the timings in

+// their Fields, from the record's own journal times (the close's before),

+// whoever writes them; an abort carries none.

+func TestTerminalTransitionsCarryTheTimings(t *testing.T) {

+ g := provision.MoveGuard{ID: tmID, Incarnation: tmInc}

+ now := *tmCut(time.Hour)

+ str := func(v float64) string { return strconv.FormatFloat(v, 'f', -1, 64) }

+ for name, c := range map[string]struct {

+ m *provision.MoveState

+ region string

+ close func(*provision.Record) error

+ want map[string]string

+ }{

+ "done": {doneJournal(), "uk", provision.MoveClose(g, now), map[string]string{

+ "prepare_s": "300", "cut_s": "40", "cut_budget_s": "95", "land_s": str(30.5), "land_budget_s": "50", "offline_s": str(70.5)}},

+ "rolled back": {rolledBackJournal(), "ie", provision.MoveRolledBackClose(g, now), map[string]string{

+ "prepare_s": "300", "cut_s": "40", "cut_budget_s": "95", "land_budget_s": "30", "offline_s": "210",

+ "rollback_s": "135", "release_budget_s": "900"}},

+ "reverted": {revertJournal(), "ie", provision.MoveRevertClose(g, now), map[string]string{

+ "prepare_s": "300", "cut_budget_s": "95", "offline_s": "50"}},

+ } {

+ before := provision.Record{Host: "a.go.example.com", Region: c.region, Move: c.m}

+ after := before

+ after.Move = c.m

+ if err := c.close(&after); err != nil {

+ t.Fatalf("%s: %v", name, err)

+ }

+ e, ok := TransitionOf(before, after)

+ if !ok || e.Identity != after.LastMove.Outcome {

+ t.Fatalf("%s: TransitionOf = %+v %v", name, e, ok)

+ }

+ for k, v := range c.want {

+ if e.Fields[k] != v {

+ t.Errorf("%s: Fields[%s] = %q, want %q (fields %v)", name, k, e.Fields[k], v, e.Fields)

+ }

+ if got := TimingsOf(e.Fields); !reflect.DeepEqual(got, Timings(c.m)) {

+ t.Errorf("%s: TimingsOf(Fields) = %v, want Timings %v", name, got, Timings(c.m))

+ }

+ // An abort's close names no timing, only the offline_s every close

+ // carries (Task 3: LastMove's).

+ m := &provision.MoveState{ID: tmID, Incarnation: tmInc, From: "ie", To: "uk", State: provision.MoveAborting, RequestedAt: tmT0, ReadyAt: tmAt(5 * time.Minute)}

+ before := provision.Record{Host: "a.go.example.com", Region: "ie", Move: m}

+ after := provision.Record{Host: "a.go.example.com", Region: "ie", LastMove: &provision.MoveOutcome{ID: tmID, Outcome: "aborted", At: now}}

+ e, ok := TransitionOf(before, after)

+ if !ok || e.Event != "aborted" {

+ t.Fatalf("the abort: %+v %v", e, ok)

+ }

+ if got := TimingsOf(e.Fields); !reflect.DeepEqual(got, map[string]float64{"offline_s": 0}) {

+ t.Errorf("an abort carries timings %v", got)

+ }

+// Preflight L29: a preparing move has one start, PreparingSince, which both

+// the six-hour abort (AbortDue) and the console's 60-minute page measure from.

+func TestPreparingSinceIsTheLaterOfRequestAndReady(t *testing.T) {

+ later := tmT0.Add(2 * time.Hour)

+ earlier := tmT0.Add(-time.Hour)

+ for name, c := range map[string]struct {

+ ready *time.Time

+ want time.Time

+ }{

+ "no ready": {nil, tmT0},

+ "a later ready": {&later, later},

+ "an earlier one": {&earlier, tmT0},

+ } {

+ m := &provision.MoveState{ID: tmID, State: provision.MovePreparing, RequestedAt: tmT0, ReadyAt: c.ready}

+ if got := PreparingSince(m); !got.Equal(c.want) {

+ t.Errorf("%s: PreparingSince = %v, want %v", name, got, c.want)

+ }

+ rec := provision.Record{Move: m}

+ if AbortDue(rec, c.want.Add(AbortAfter-time.Second)) || !AbortDue(rec, c.want.Add(AbortAfter)) {

+ t.Errorf("%s: AbortDue does not run from PreparingSince", name)

+ }

diff --git a/internal/moves/transition.go b/internal/moves/transition.go

index 94f9b7785..a682af150 100644

--- a/internal/moves/transition.go

+++ b/internal/moves/transition.go

@@ -86,7 +86,8 @@ func seconds(a, b interface{ Unix() int64 }) string {

// 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).

+// rolled_back, aborted). A done or rolled_back outcome carries the move's

+// timings (Timings) over the journal as the close found it.

func TransitionOf(before, after provision.Record) (Transition, bool) {

bm, am := before.Move, after.Move

if am == nil {

@@ -95,7 +96,14 @@ func TransitionOf(before, after provision.Record) (Transition, bool) {

return Transition{}, false

}

f := transitionFields(bm)

- f["offline_s"] = strconv.FormatFloat(after.LastMove.OfflineS, 'f', -1, 64)

+ if out := after.LastMove.Outcome; out == "done" || out == "rolled_back" {

+ // The timings (Plan 6 Task 4), from the journal the close

+ // found: the same for every writer of the entry.

+ for k, v := range Timings(bm) {

+ f[k] = timingText(v)

+ }

+ f["offline_s"] = timingText(after.LastMove.OfflineS)

return Transition{Op: bm.ID, Event: after.LastMove.Outcome, Identity: after.LastMove.Outcome, Incarnation: bm.Incarnation, Fields: f}, true

}

if am.ID == "" || (bm != nil && bm.ID != am.ID) {

diff --git a/internal/provision/provision.go b/internal/provision/provision.go

index fdbe6cd23..b9615a1d1 100644

--- a/internal/provision/provision.go

+++ b/internal/provision/provision.go

@@ -1786,12 +1786,58 @@ func MoveSourceParked(g MoveGuard, now time.Time) func(*Record) error {

return committedStamp(g, now, func(m *MoveState) **time.Time { return &m.SourceParkedAt })

}

+// LandingDeadlineOf is the deadline a landing before restored works to:

+// the earlier of the cut's absolute deadline and landing_deadline. Spec

+// §7.4 has every pre-commit phase on both participants check the absolute

+// deadline; the flip's landing_deadline is a second, separate bound, never

+// an extension of it (final review, finding 3). which names the one that

+// applies, for the log. The box's landing and rollback decisions (host's

+// landingDeadlineOf) and the move's timings (moves.Timings) share it

+// (Plan 6 preflight L20).

+func LandingDeadlineOf(m *MoveState) (d *time.Time, which string) {

+ if m.CutDeadline != nil {

+ d, which = m.CutDeadline, "cut_deadline"

+ }

+ if m.LandingDeadline != nil && (d == nil || m.LandingDeadline.Before(*d)) {

+ d, which = m.LandingDeadline, "landing_deadline"

+ }

+ return d, which

+// MoveOfflineS is a move's offline time as its close records it (index D11):

+// from cut_at to the open that ends the move. That is a committed move's

+// opened_at (MoveClose), a rollback's source reopen, rollback.opened_at

+// (MoveRolledBackClose), or a revert's reopened_at (MoveRevertClose). ok is

+// false while either end is unstamped. The three closes and the move's

+// timings (moves.Timings) share it (Plan 6 preflight L20).

+func MoveOfflineS(m *MoveState) (seconds float64, ok bool) {

+ if m == nil || m.CutAt == nil {

+ return 0, false

+ }

+ var end *time.Time

+ switch m.State {

+ case MoveCommitted:

+ end = m.OpenedAt

+ case MoveRollingBack:

+ if m.Rollback != nil {

+ end = m.Rollback.OpenedAt

+ }

+ case MoveReverting:

+ end = m.ReopenedAt

+ }

+ if end == nil {

+ return 0, false

+ }

+ return end.Sub(*m.CutAt).Seconds(), true

// MoveClose is the close (§7.9 step 5, index D11): a committed move with

// both obligations stamped clears Move and leaves the outcome in LastMove,

// in the same write. The region is already the target's from the flip; a

// record whose region is not is refused rather than closed on a lie. The

-// offline time is opened_at minus cut_at, zero when cut_at was never

-// stamped. Plan 5 calls it once no obligation under the move remains.

+// offline time is opened_at minus cut_at (MoveOfflineS), zero when cut_at

+// was never stamped. Plan 5 calls it once no obligation under the move

+// remains.

func MoveClose(g MoveGuard, now time.Time) func(*Record) error {

return func(rec *Record) error {

if err := g.check(rec); err != nil {

@@ -1805,8 +1851,8 @@ func MoveClose(g MoveGuard, now time.Time) func(*Record) error {

return fmt.Errorf("%w: the record's region is not the target's", ErrMoveConflict)

}

out := &MoveOutcome{ID: g.ID, Outcome: "done", At: now.UTC()}

- if m.CutAt != nil {

- out.OfflineS = m.OpenedAt.Sub(*m.CutAt).Seconds()

+ if s, ok := MoveOfflineS(m); ok {

+ out.OfflineS = s

}

rec.LastMove, rec.Move = out, nil

return nil

@@ -2301,7 +2347,7 @@ func MoveRollbackLossCommitted(g MoveGuard) func(*Record) error {

// target has parked clears Move and leaves the outcome in LastMove, in the

// same write. The region is already From (MoveRollBack); a record whose

// region is not is refused. The offline time is the rollback's OpenedAt

-// minus CutAt, zero when CutAt was never stamped.

+// minus CutAt (MoveOfflineS), zero when CutAt was never stamped.

func MoveRolledBackClose(g MoveGuard, now time.Time) func(*Record) error {

return func(rec *Record) error {

rb, err := rollingBack(g, rec)

@@ -2316,8 +2362,8 @@ func MoveRolledBackClose(g MoveGuard, now time.Time) func(*Record) error {

return fmt.Errorf("%w: the record's region is not the source's", ErrMoveConflict)

}

out := &MoveOutcome{ID: g.ID, Outcome: "rolled_back", At: now.UTC()}

- if m.CutAt != nil {

- out.OfflineS = rb.OpenedAt.Sub(*m.CutAt).Seconds()

+ if s, ok := MoveOfflineS(m); ok {

+ out.OfflineS = s

}

rec.LastMove, rec.Move = out, nil

return nil

@@ -2375,8 +2421,8 @@ func MoveRecordRevertInputs(g MoveGuard, in MoveInputs) func(*Record) error {

// MoveRevertClose is a revert's close (§7.4 reverting, index D11): the

// caller has seen the claim's rev_phase at opened; the record needs its

// ReopenedAt. Move is cleared and LastMove says rolled_back, the offline

-// time counted from CutAt to the reopen. A revert never flipped, so the

-// region is From; a record whose region is not is refused.

+// time counted from CutAt to the reopen (MoveOfflineS). A revert never

+// flipped, so the region is From; a record whose region is not is refused.

func MoveRevertClose(g MoveGuard, now time.Time) func(*Record) error {

return func(rec *Record) error {

if err := g.check(rec); err != nil {

@@ -2390,8 +2436,8 @@ func MoveRevertClose(g MoveGuard, now time.Time) func(*Record) error {

return fmt.Errorf("%w: the record's region is not the source's", ErrMoveConflict)

}

out := &MoveOutcome{ID: g.ID, Outcome: "rolled_back", At: now.UTC()}

- if m.CutAt != nil {

- out.OfflineS = m.ReopenedAt.Sub(*m.CutAt).Seconds()

+ if s, ok := MoveOfflineS(m); ok {

+ out.OfflineS = s

}

rec.LastMove, rec.Move = out, nil

return nil