diff --git a/cmd/mesh-controller/build.go b/cmd/mesh-controller/build.go index 54d75cb..8b4ed60 100644 --- a/cmd/mesh-controller/build.go +++ b/cmd/mesh-controller/build.go @@ -720,6 +720,8 @@ type answers struct { plans []inventory.Plan // paused is whether the build seat takes work, which a plan waiting on it says (ADR 0219). paused pauseView + // tierBounds is how long each repository's plan tier may take before it is late (novox/hq issue 296). + tierBounds tierBounds // refused is why a machine cannot be worked out at all, by name. A different thing from every // other answer here: those are about a machine that was told something, and this is about one // that cannot be told anything — it never reaches waiting, because nothing was computed for it diff --git a/cmd/mesh-controller/plan_clock_test.go b/cmd/mesh-controller/plan_clock_test.go new file mode 100644 index 0000000..26dc614 --- /dev/null +++ b/cmd/mesh-controller/plan_clock_test.go @@ -0,0 +1,121 @@ +package main + +import ( + "strings" + "testing" + "time" + + "github.com/novox/mesh-controller/internal/catalogue" + "github.com/novox/mesh-controller/internal/inventory" + "github.com/novox/mesh-controller/internal/link" +) + +// novox/hq issue 296: a plan saved a few seconds ago that has stood in its tier for forty minutes says +// forty minutes, and LATE — the line counted from the last save, which every advance made. +func TestAPlansLineCountsFromItsTierNotFromItsLastSave(t *testing.T) { + now := time.Date(2026, 10, 7, 20, 30, 0, 0, time.UTC) + asked := now.Add(-40 * time.Minute) + p := inventory.Plan{ID: "plan-t", Repository: "novox/mesh-catalog", Commit: "3ad22356", State: inventory.PlanBuilding, + Created: now.Add(-40 * time.Minute), Updated: now.Add(-3 * time.Second), TierEntered: now.Add(-40 * time.Minute), + Tiers: [][]string{{"a"}}, Modules: map[string]*inventory.PlanModule{"a": {State: "asked", AskedAt: &asked}}} + + line := planLine(p, now) + if !strings.Contains(line, "building for 40m0s") || !strings.Contains(line, "LATE") { + t.Fatalf("a plan in its tier for 40m, saved 3s ago, reads %q", line) + } + st := planStatuses([]inventory.Plan{p}, now, pauseView{}, nil)[0] + if !st.Late || !st.Since.Equal(p.TierEntered) { + t.Errorf("status --json says %+v", st) + } + if _, late := openPlans([]inventory.Plan{p}, now, pauseView{}, nil); late != 1 { + t.Errorf("status counted %d late", late) + } + + // LATE is the stalled condition said on the line: the same start and the same bound, measured or not. + bounds := boundsOf([]inventory.Duration{{Subject: p.Repository, Took: 20 * time.Minute}}) + if got := bounds.of(p.Repository); got != time.Hour { + t.Fatalf("a repository whose tiers took 20m is given %s", got) + } + if got := bounds.of("novox/other"); got != tierAtLeast { + t.Fatalf("a repository with nothing measured is given %s", got) + } + for _, in := range []time.Duration{40 * time.Minute, 70 * time.Minute} { + q := p + q.TierEntered = now.Add(-in) + bound := bounds.of(q.Repository) + late := strings.Contains(planLineWith(q, now, pauseView{}, bound), "LATE") + stalled := len(watchPlans(&signalFacts{now: now, plans: []planFacts{{id: q.ID, repository: q.Repository, + commit: q.Commit, tiers: 1, entered: inTierSince(q), bound: bound}}})) == 1 + if late != stalled || late != (in > bound) { + t.Errorf("in its tier %s with a bound of %s: LATE %v, stalled %v", in, bound, late, stalled) + } + } + + // A plan read without its tier's stamp counts from its last save, the only time it has. + old := p + old.TierEntered = time.Time{} + if line := planLine(old, now); !strings.Contains(line, "for 3s") || strings.Contains(line, "LATE") { + t.Errorf("a plan without its tier's stamp reads %q", line) + } + + // A walk that waited for its delivery's word counts its wait from when it was opened, and its tier + // from the word. + waiting := p + waiting.Delivery = &inventory.PlanDelivery{Awaits: catalogue.DeliverySeat} + waiting.Modules = map[string]*inventory.PlanModule{} + if line := planLine(waiting, now); !strings.Contains(line, "for 40m0s") || strings.Contains(line, "LATE") { + t.Errorf("a walk waiting 40m reads %q", line) + } + if st := planStatuses([]inventory.Plan{waiting}, now, pauseView{}, nil)[0]; st.Late { + t.Errorf("a waiting walk is called late: %+v", st) + } + let := now.Add(-5 * time.Minute) + gone := p + gone.Delivery = &inventory.PlanDelivery{Awaits: catalogue.DeliverySeat, Go: &let} + if line := planLine(gone, now); !strings.Contains(line, "building for 5m0s") || strings.Contains(line, "LATE") { + t.Errorf("a walk let go 5m ago, opened 40m ago, reads %q", line) + } +} + +// novox/hq issue 296: a plan whose tier stands still is not written again by every advance — its revision, +// its last save and its `plan-moved` stay where its last change left them. +func TestAPlanStandingStillIsNotSavedAgain(t *testing.T) { + open := aMesh(t) + ctx := t.Context() + inv := open.inventory + asked := asksRecorded(t) + if err := inv.RegisterModule(ctx, catalogue.Manifest{Module: "app", Version: "1"}, + inventory.Source{Repository: "novox/mesh-catalog", Seat: "git", Path: "modules/app", Ref: "main", + BuiltFrom: "c0", Head: "c0"}); err != nil { + t.Fatal(err) + } + m := link.SourceMoved{Owner: "novox", Repo: "mesh-catalog", Base: "main", Commit: "c1aaaaaaaa", + Paths: []string{"modules/app/index.ts"}, ModuleDirs: []string{"modules/app"}, ModuleDirsSaid: true} + if err := (following{open: open}).SourceMoved(ctx, m); err != nil { + t.Fatal(err) + } + advanceHeld(ctx, open) + recent, err := inv.RecentPlans(ctx, 1) + if err != nil || len(recent) != 1 || len(*asked) != 1 { + t.Fatalf("no plan building: %v %v, asked %v", recent, err, *asked) + } + before := recent[0] + if before.State != inventory.PlanBuilding || before.Modules["app"] == nil || before.Modules["app"].State != "asked" { + t.Fatalf("the plan is not waiting on its build: %+v", before) + } + + for range 3 { + advanceHeld(ctx, open) + } + after, err := inv.PlanByID(ctx, before.ID) + if err != nil { + t.Fatal(err) + } + if after.Revision != before.Revision || !after.Updated.Equal(before.Updated) { + t.Fatalf("a plan that did not move was saved again: revision %d → %d, saved %s → %s", + before.Revision, after.Revision, before.Updated, after.Updated) + } + if len(*asked) != 1 { + t.Fatalf("advancing asked again: %v", *asked) + } +} diff --git a/cmd/mesh-controller/queue_test.go b/cmd/mesh-controller/queue_test.go index 0db0ce0..0a7235a 100644 --- a/cmd/mesh-controller/queue_test.go +++ b/cmd/mesh-controller/queue_test.go @@ -276,21 +276,21 @@ func TestAPlanWaitingOnAPausedSeatSaysSoAndIsNotLate(t *testing.T) { Modules: map[string]*inventory.PlanModule{"a": {State: "asked", AskedAt: &asked}}} all := pauseOf([]string{"g14", "ace"}, map[string]link.HolderState{"ace": {Paused: true}, "g14": {Paused: true}}) - line := planLineWith(p, now, all) + line := planLineWith(p, now, all, tierAtLeast) if !strings.Contains(line, "waiting: the build seat is paused on ace, g14 (asked 12m0s ago)") || strings.Contains(line, "LATE") { t.Errorf("a plan on a paused seat reads %q", line) } - if st := planStatuses([]inventory.Plan{p}, now, all)[0]; st.Late || !strings.Contains(st.Waiting, "paused on ace, g14") { + if st := planStatuses([]inventory.Plan{p}, now, all, nil)[0]; st.Late || !strings.Contains(st.Waiting, "paused on ace, g14") { t.Errorf("status --json says %+v", st) } - if _, late := openPlans([]inventory.Plan{p}, all); late != 0 { + if _, late := openPlans([]inventory.Plan{p}, now, all, nil); late != 0 { t.Errorf("a plan waiting on a paused seat counted late") } longAgo := now.Add(-25 * time.Hour) forgotten := p forgotten.Modules = map[string]*inventory.PlanModule{"a": {State: "asked", AskedAt: &longAgo}} - if line := planLineWith(forgotten, now, all); !strings.Contains(line, "PAUSED OVER A DAY") || strings.Contains(line, "LATE") { + if line := planLineWith(forgotten, now, all, tierAtLeast); !strings.Contains(line, "PAUSED OVER A DAY") || strings.Contains(line, "LATE") { t.Errorf("a plan paused over a day reads %q", line) } @@ -298,10 +298,10 @@ func TestAPlanWaitingOnAPausedSeatSaysSoAndIsNotLate(t *testing.T) { if some.All || !reflect.DeepEqual(some.Nodes, []string{"ace"}) { t.Fatalf("%+v", some) } - if line := planLineWith(p, now, some); !strings.Contains(line, "LATE") { + if line := planLineWith(p, now, some, tierAtLeast); !strings.Contains(line, "LATE") { t.Errorf("a seat paused on one holder of two made the plan not late: %q", line) } - if st := planStatuses([]inventory.Plan{p}, now, some)[0]; !st.Late { + if st := planStatuses([]inventory.Plan{p}, now, some, nil)[0]; !st.Late { t.Errorf("status --json: %+v", st) } // A plan rolling out, or with nothing asked, is not waiting on the seat. diff --git a/cmd/mesh-controller/readable.go b/cmd/mesh-controller/readable.go index e7a84d4..e7f8d8a 100644 --- a/cmd/mesh-controller/readable.go +++ b/cmd/mesh-controller/readable.go @@ -199,7 +199,7 @@ func statusAsJSON(asked answers) ([]byte, error) { out := meshStatus{Machines: len(nodes), Wrong: []machineDoing{}, Quiet: []machineQuiet{}, Behind: []moduleBehind{}, Waiting: []machineWaiting{}, Reported: []machineReported{}, Unresolved: []machineUnresolved{}, - Network: asked.network, Adopted: adoptedNodes(nodes), Plans: planStatuses(asked.plans, time.Now(), asked.paused)} + Network: asked.network, Adopted: adoptedNodes(nodes), Plans: planStatuses(asked.plans, time.Now(), asked.paused, asked.tierBounds)} // In a stated order, so two readings of an unchanged mesh are the same document. untakenNodes := make([]string, 0, len(asked.untaken)) for name := range asked.untaken { diff --git a/cmd/mesh-controller/release_plan.go b/cmd/mesh-controller/release_plan.go index c8d2c9c..d928968 100644 --- a/cmd/mesh-controller/release_plan.go +++ b/cmd/mesh-controller/release_plan.go @@ -2,6 +2,7 @@ package main import ( "context" + "encoding/json" "errors" "flag" "fmt" @@ -506,23 +507,32 @@ func advanceHeld(ctx context.Context, open *stores) { for i := range plans { p := &plans[i] for p.Open() { + // **Saved only when the step changed it** (novox/hq issue 296). Every step was saved, and + // the steps run on every tick and after every build outcome on the mesh: a plan whose tier + // stood still for half an hour was written every few seconds, its revision moved, `plan-moved` + // said on the bus, and its last save read as when it began building. + before := planSnapshot(*p) moved, err := advanceOnce(ctx, open, p, edges, rollsOut) if err != nil { fmt.Printf("%s: %v\n", p.ID, err) // Kept in the plan, so `plans` says why it has not moved rather than the log alone; // the state is left as it was and the step is tried again on the next tick. p.Note = "tier " + fmt.Sprint(p.Tier) + ": " + err.Error() + " — tried again" - if err := inv.SavePlan(ctx, p); err != nil { - fmt.Printf("%s: cannot keep the plan: %v\n", p.ID, err) + if planSnapshot(*p) != before { + if err := inv.SavePlan(ctx, p); err != nil { + fmt.Printf("%s: cannot keep the plan: %v\n", p.ID, err) + } } break } if p.State == inventory.PlanFailed { sayUnsent(p, rollsOut) } - if err := inv.SavePlan(ctx, p); err != nil { - fmt.Printf("%s: cannot keep the plan: %v\n", p.ID, err) - break + if planSnapshot(*p) != before { + if err := inv.SavePlan(ctx, p); err != nil { + fmt.Printf("%s: cannot keep the plan: %v\n", p.ID, err) + break + } } if !moved { break @@ -531,6 +541,18 @@ func advanceHeld(ctx context.Context, open *stores) { } } +// planSnapshot is a plan as a save would write it, to compare before and after a step: what the store +// stamps itself (when it was saved, its revision and epoch, when its tier was entered) is left out. +func planSnapshot(p inventory.Plan) string { + p.Updated, p.Revision, p.Epoch, p.TierEntered = time.Time{}, 0, 0, time.Time{} + b, err := json.Marshal(p) + if err != nil { + // Unreadable is never the same: the plan is saved, as every step was before. + return fmt.Sprintf("unmarshallable %p %v", &p, err) + } + return string(b) +} + // advanceOnce takes one step of one plan and says whether anything changed. func advanceOnce(ctx context.Context, open *stores, p *inventory.Plan, edges []inventory.Edge, rollsOut func(string) bool) (bool, error) { @@ -1070,12 +1092,37 @@ func planTicker(ctx context.Context, open *stores) { } } -// planLine is one plan as `status` says it. -func planLine(p inventory.Plan, now time.Time) string { return planLineWith(p, now, pauseView{}) } +// planLine is one plan as `status` says it, given the least bound of a tier. +func planLine(p inventory.Plan, now time.Time) string { + return planLineWith(p, now, pauseView{}, tierAtLeast) +} + +// inTierSince is when a plan began waiting on what it waits on now, which `plans`, `status` and the +// watchdog of a plan's progress (S3) all count from (novox/hq issue 296): a walk waiting for its +// delivery's word from when it was opened, as S16 counts; any other plan from when it entered its tier, +// or, when the delivery let it go after that, from the go. Never from the plan's last save: a plan is +// saved for many reasons while its tier stands still, and a clock reset by each save said a build queued +// for minutes had been building for a few seconds. A plan read without the stamp (one from before it +// was kept) counts from its last save, the only time it has. +func inTierSince(p inventory.Plan) time.Time { + if p.Waiting() { + return p.Created + } + since := p.TierEntered + if since.IsZero() { + since = p.Updated + } + if d := p.Delivery; d != nil && d.Go != nil && d.Go.After(since) { + since = *d.Go + } + return since +} // planLineWith is planLine knowing whether the build seat is paused (novox/hq ADR 0219): a plan -// waiting on builds nobody will take until a person resumes the seat says so, and is not late. -func planLineWith(p inventory.Plan, now time.Time, pause pauseView) string { +// waiting on builds nobody will take until a person resumes the seat says so, and is not late. bound is +// the plan's tier bound, the one its stalled condition is raised at (tierBounds): LATE is that condition +// said on the line (novox/hq issue 296). +func planLineWith(p inventory.Plan, now time.Time, pause pauseView, bound time.Duration) string { where := fmt.Sprintf("tier %d of %d", min(p.Tier+1, len(p.Tiers)), len(p.Tiers)) switch p.State { case inventory.PlanDone: @@ -1085,7 +1132,7 @@ func planLineWith(p inventory.Plan, now time.Time, pause pauseView) string { case inventory.PlanSuperseded: return fmt.Sprintf("%s %s %s", p.Repository, short(p.Commit), p.Note) } - since := now.Sub(p.Updated).Round(time.Second) + since := now.Sub(inTierSince(p)).Round(time.Second) if p.Waiting() { // Waiting for its delivery's word is no lateness of the walk's (novox/hq ADR 0239). return fmt.Sprintf("%s %s %s, %s, for %s", p.Repository, short(p.Commit), where, waitingNote(p), since) @@ -1094,7 +1141,7 @@ func planLineWith(p inventory.Plan, now time.Time, pause pauseView) string { return fmt.Sprintf("%s %s %s, %s", p.Repository, short(p.Commit), where, waiting) } late := "" - if since > planWaitBound { + if since > bound { late = " — LATE" } what := "building" @@ -1167,17 +1214,19 @@ type planStatus struct { Late bool `json:"late"` } -func planStatuses(plans []inventory.Plan, now time.Time, pause pauseView) []planStatus { +func planStatuses(plans []inventory.Plan, now time.Time, pause pauseView, bounds tierBounds) []planStatus { out := make([]planStatus, 0, len(plans)) for _, p := range plans { ps := planStatus{ID: p.ID, Repository: p.Repository, Commit: p.Commit, State: p.State, Tier: p.Tier, Tiers: len(p.Tiers), Since: p.Updated} if p.Open() { + ps.Since = inTierSince(p) ps.Waiting = p.Note if ps.Waiting == "" { ps.Waiting = "builds of tier " + fmt.Sprint(p.Tier) } - ps.Late = now.Sub(p.Updated) > planWaitBound + // A walk waiting for its delivery's word is no tier late (ADR 0239): S16 is its watchdog. + ps.Late = !p.Waiting() && now.Sub(ps.Since) > bounds.of(p.Repository) // Paused is a person's decision, not lateness (novox/hq ADR 0219). if waiting, paused := pausedWaiting(p, pause, now); paused { ps.Waiting, ps.Late = waiting, false @@ -1189,16 +1238,16 @@ func planStatuses(plans []inventory.Plan, now time.Time, pause pauseView) []plan } // openPlans is the open plans among the recent ones, and how many have waited past the bound. -func openPlans(plans []inventory.Plan, pause pauseView) ([]inventory.Plan, int) { +func openPlans(plans []inventory.Plan, now time.Time, pause pauseView, bounds tierBounds) ([]inventory.Plan, int) { var open []inventory.Plan late := 0 for _, p := range plans { if p.Open() { open = append(open, p) - if _, paused := pausedWaiting(p, pause, time.Now()); paused { + if _, paused := pausedWaiting(p, pause, now); paused || p.Waiting() { continue } - if time.Since(p.Updated) > planWaitBound { + if now.Sub(inTierSince(p)) > bounds.of(p.Repository) { late++ } } @@ -1240,7 +1289,9 @@ func plansCommand(ctx context.Context, args []string) error { if err != nil { return err } - fmt.Printf("%s — %s\n", p.ID, planLineWith(p, now, buildSeatPause(ctx, inv, []inventory.Plan{p}))) + bounds := readTierBounds(ctx, inv, now) + fmt.Printf("%s — %s\n", p.ID, planLineWith(p, now, buildSeatPause(ctx, inv, []inventory.Plan{p}), + bounds.of(p.Repository))) if r := p.Release; r != nil { // A release plan's walk (ADR 0236): machines done, the one judged, those to come. fmt.Printf(" machines in order: %s; done: %s; skipped: %s\n", strings.Join(r.Order, ", "), @@ -1369,8 +1420,9 @@ func plansCommand(ctx context.Context, args []string) error { return nil } pause := buildSeatPause(ctx, inv, plans) + bounds := readTierBounds(ctx, inv, now) for _, p := range plans { - fmt.Printf("%-28s %s\n", p.ID, planLineWith(p, now, pause)) + fmt.Printf("%-28s %s\n", p.ID, planLineWith(p, now, pause, bounds.of(p.Repository))) } return nil } diff --git a/cmd/mesh-controller/status.go b/cmd/mesh-controller/status.go index 8025552..fc7e18d 100644 --- a/cmd/mesh-controller/status.go +++ b/cmd/mesh-controller/status.go @@ -143,14 +143,14 @@ func printStatus(asked answers) error { len(quiet), strings.Join(said, "\n ")) } - if open, late := openPlans(asked.plans, asked.paused); len(open) > 0 { + if open, late := openPlans(asked.plans, time.Now(), asked.paused, asked.tierBounds); len(open) > 0 { fmt.Printf("%d plan(s) open", len(open)) if late > 0 { - fmt.Printf(", %d waiting past %s", late, planWaitBound) + fmt.Printf(", %d in a tier past its bound", late) } fmt.Println(":") for _, p := range open { - fmt.Printf(" %s\n", planLineWith(p, time.Now(), asked.paused)) + fmt.Printf(" %s\n", planLineWith(p, time.Now(), asked.paused, asked.tierBounds.of(p.Repository))) } fmt.Println() } @@ -472,6 +472,8 @@ func theThreeQuestions(ctx context.Context, open *stores) (answers, error) { } // Whether the build seat takes work, for a plan waiting on it (novox/hq ADR 0219). out.paused = buildSeatPause(ctx, inv, out.plans) + // And how long a tier may take, the bound a plan is late at (novox/hq issue 296). + out.tierBounds = readTierBounds(ctx, inv, time.Now()) // And how many repairs were done by hand this week (novox/hq to-be 45 §7) — where there is a bus // to read the log from; a process with none has no log to count. if _, onBus := broker.BusAddress(); onBus == nil { diff --git a/cmd/mesh-controller/watchdogs.go b/cmd/mesh-controller/watchdogs.go index dc196b3..7223329 100644 --- a/cmd/mesh-controller/watchdogs.go +++ b/cmd/mesh-controller/watchdogs.go @@ -439,13 +439,9 @@ func gatherPlans(ctx context.Context, inv *inventory.Inventory, now time.Time) ( if len(plans) == 0 { return nil, nil, nil } - tiers, err := inv.Durations(ctx, inventory.DurationPlanTier, now.Add(-14*24*time.Hour)) + bounds, err := measuredTierBounds(ctx, inv, now) if err != nil { - return nil, nil, fmt.Errorf("the measured plan tiers cannot be read: %w", err) - } - measured := map[string][]time.Duration{} - for _, d := range tiers { - measured[d.Subject] = append(measured[d.Subject], d.Took) + return nil, nil, err } pause := buildSeatPause(ctx, inv, plans) var out []planFacts @@ -459,13 +455,59 @@ func gatherPlans(ctx context.Context, inv *inventory.Inventory, now time.Time) ( continue } _, paused := pausedWaiting(p, pause, now) + bound := bounds.of(p.Repository) out = append(out, planFacts{id: p.ID, repository: p.Repository, commit: p.Commit, tier: p.Tier, - tiers: len(p.Tiers), entered: p.TierEntered, bound: max(tierAtLeast, 3*p90(measured[p.Repository])), - waiting: planLineWith(p, now, pause), paused: paused}) + tiers: len(p.Tiers), entered: inTierSince(p), bound: bound, + waiting: planLineWith(p, now, pause, bound), paused: paused}) } return out, waits, nil } +// tierBounds is how long a plan's tier may take before it is stalled (S3) and `plans` and `status` call +// it LATE, by repository: three times the ninetieth percentile of the tiers measured for it, and never +// less than tierAtLeast. One bound for the watchdog and the lines a person reads, so the two cannot +// disagree about one plan (novox/hq issue 296). A repository nothing was measured for, or a nil +// tierBounds, is given tierAtLeast. +type tierBounds map[string]time.Duration + +func (b tierBounds) of(repository string) time.Duration { + if d, ok := b[repository]; ok { + return d + } + return tierAtLeast +} + +// measuredTierBounds is the tier bounds from the last fourteen days of measured plan tiers. +func measuredTierBounds(ctx context.Context, inv *inventory.Inventory, now time.Time) (tierBounds, error) { + tiers, err := inv.Durations(ctx, inventory.DurationPlanTier, now.Add(-14*24*time.Hour)) + if err != nil { + return nil, fmt.Errorf("the measured plan tiers cannot be read: %w", err) + } + return boundsOf(tiers), nil +} + +// readTierBounds is measuredTierBounds for a line a person reads: what cannot be read is said, and +// every plan is then given the least bound, as the watchdog gives a repository nothing was measured for. +func readTierBounds(ctx context.Context, inv *inventory.Inventory, now time.Time) tierBounds { + bounds, err := measuredTierBounds(ctx, inv, now) + if err != nil { + fmt.Fprintf(os.Stderr, "%v; a plan is called late past %s\n", err, tierAtLeast) + } + return bounds +} + +func boundsOf(tiers []inventory.Duration) tierBounds { + measured := map[string][]time.Duration{} + for _, d := range tiers { + measured[d.Subject] = append(measured[d.Subject], d.Took) + } + out := tierBounds{} + for repository, took := range measured { + out[repository] = max(tierAtLeast, 3*p90(took)) + } + return out +} + // p90 is the ninetieth percentile of measurements; zero for none. func p90(took []time.Duration) time.Duration { if len(took) == 0 {