Merge pull request 'Count a plan's time from its tier, and save it only when a step changed it (hq issue 296)' (#119) from fix/plans-timer-counts-from-tier into main

This commit was merged in pull request #119.
This commit is contained in:
2026-10-07 19:04:57 +00:00
8 changed files with 259 additions and 39 deletions
+2
View File
@@ -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
+121
View File
@@ -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)
}
}
+6 -6
View File
@@ -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.
+1 -1
View File
@@ -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 {
+1 -1
View File
@@ -246,7 +246,7 @@ func ungatedIn(ctx context.Context, open *stores, names []string, addedHolder st
}
}
if len(refused) > 0 {
return nil, fmt.Errorf("%w: %s — a release plan sends them, one machine at a time, each judged (novox/hq ADR "+
return nil, fmt.Errorf("%w: %s — a walk sends them, one machine at a time, each judged (novox/hq ADR "+
"0236); `upgrade backlog` lists them", errUngated, strings.Join(refused, "; "))
}
return kept, nil
+73 -20
View File
@@ -2,6 +2,7 @@ package main
import (
"context"
"encoding/json"
"errors"
"flag"
"fmt"
@@ -506,23 +507,33 @@ 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.
// the state is left as it was and the step is tried again on the next tick. Said and
// kept when it is new: the same refusal on every tick is one fact, not one per 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 {
fmt.Printf("%s: %v\n", p.ID, err)
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 +542,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 +1093,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 +1133,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 +1142,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 +1215,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 +1239,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 +1290,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 +1421,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
}
+5 -3
View File
@@ -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 {
+50 -8
View File
@@ -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 {