mesh-controller/internal/inventory/walkphases_test.go

package inventory

import (
	"encoding/json"
	"strings"
	"testing"
	"time"
)

// A walk recorded on the live mesh on 2026-10-10 (mesh-delivery, one tier, one machine), as `delivery walks`
// gave it, with the moments ADR 0282 adds: its window closed ninety seconds after its merge was heard, and it was
// cut eleven seconds later.
const recordedWalk = `{
  "id": "plan-1791654663505629616", "repository": "novox/mesh-catalog", "branch": "main",
  "commit": "a14fa306f262d88bdcca83432a70df353d2eceb0", "merged": "2026-10-10T17:50:53Z",
  "created": "2026-10-10T19:52:34.037755+02:00", "updated": "2026-10-10T19:55:37.974069+02:00",
  "state": "done", "tier": 1, "tiers": [["mesh-delivery"]],
  "modules": {"mesh-delivery": {"state": "built",
    "asked_at": "2026-10-10T17:52:34.209423145Z", "built_at": "2026-10-10T17:52:50.818011314Z",
    "sent_at": "2026-10-10T17:55:35.894985053Z", "first": ["novox"], "first_at": "2026-10-10T17:53:07.287136827Z",
    "gate": {"machines": ["novox"], "since": "2026-10-10T17:53:07.287136827Z", "passes": 3,
      "verdict": "passed", "judged_at": "2026-10-10T17:55:35.894985053Z"}}},
  "delivery": {"awaits": "", "merges": [{"repository": "novox/mesh-catalog",
    "commit": "a14fa306f262d88bdcca83432a70df353d2eceb0", "number": 187, "merged": "2026-10-10T17:50:53Z"}]},
  "times": {"window_closed": "2026-10-10T17:52:23Z", "cut": "2026-10-10T17:52:34.037755Z", "class": "core"}
}`

func walkOf(t *testing.T, raw string) Plan {
	t.Helper()
	var p Plan
	if err := json.Unmarshal([]byte(raw), &p); err != nil {
		t.Fatal(err)
	}
	return p
}

// sumsUp checks the phases' measured time and the unknown time add up to the total, to the millisecond.
func sumsUp(t *testing.T, w *WalkPhases) {
	t.Helper()
	if w.End == nil || w.From == nil {
		t.Fatalf("the walk has no end: %+v", w)
	}
	var sum int64
	for _, ph := range w.Phases {
		if ph.State == PhaseMeasured {
			if ph.Start == nil || ph.End == nil || ph.End.Sub(*ph.Start).Milliseconds() != ph.TookMS {
				t.Errorf("phase %s %d says %dms between %v and %v", ph.Name, ph.Tier, ph.TookMS, ph.Start, ph.End)
			}
			sum += ph.TookMS
		}
		if ph.State == PhaseUnknown && ph.TookMS != 0 {
			t.Errorf("an unknown phase %s says a time: %dms", ph.Name, ph.TookMS)
		}
	}
	if sum+w.UnknownMS != w.TotalMS || w.End.Sub(*w.From).Milliseconds() != w.TotalMS {
		t.Fatalf("the phases add up to %dms and %dms unknown, the total is %dms (%s): %+v", sum, w.UnknownMS,
			w.TotalMS, w.End.Sub(*w.From), w.Phases)
	}
}

func phase(w *WalkPhases, name string, tier int) WalkPhase {
	for _, ph := range w.Phases {
		if ph.Name == name && ph.Tier == tier {
			return ph
		}
	}
	return WalkPhase{}
}

// The phases of a recorded walk add up to its measured total: its merge at 17:50:53 to its verdict on its only
// machine at 17:55:35.894, 4m42.894s.
func TestARecordedWalksPhasesAddUpToItsTotal(t *testing.T) {
	w := walkOf(t, recordedWalk).WalkPhases(time.Date(2026, 10, 10, 18, 0, 0, 0, time.UTC), nil)
	sumsUp(t, w)
	if w.TotalMS != 282894 || w.Class != ClassCore || w.UnknownMS != 0 {
		t.Fatalf("total %dms (want 282894), class %q, unknown %d", w.TotalMS, w.Class, w.UnknownMS)
	}
	for name, want := range map[string]int64{PhaseWindow: 90000, PhaseQueued: 11037, PhaseBuild: 16781,
		PhaseSend: 16469, PhaseJudge: 148607, PhaseRest: 0} {
		tier := 0
		if name == PhaseWindow || name == PhaseQueued {
			tier = -1
		}
		if got := phase(w, name, tier); got.State != PhaseMeasured || got.TookMS != want {
			t.Errorf("%s: %s %dms, want measured %dms", name, got.State, got.TookMS, want)
		}
	}
	// The cut to the first ask (171ms) is a time no phase of ADR 0282's table names: it is counted in the build.
	if got := phase(w, PhaseWord, -1); got.State != PhaseNone {
		t.Errorf("a walk that waits for no word says its word phase %s", got.State)
	}
	if got := phase(w, PhaseApply, -1); got.State != PhaseNone || !strings.Contains(got.Said, "no machine beyond the first") {
		t.Errorf("one machine only: apply %s (%s)", got.State, got.Said)
	}
}

// Two tiers, a machine of the rest each, both reports read: every phase measured, the walk ends at the last
// report applied, and the phases add up.
func TestAWalkOfTwoTiersEndsAtItsRestsLastReport(t *testing.T) {
	at := func(s string) *time.Time {
		v, err := time.Parse(time.RFC3339Nano, "2026-10-10T18:"+s+"Z")
		if err != nil {
			t.Fatal(err)
		}
		return &v
	}
	p := Plan{ID: "plan-2", State: PlanDone, Tier: 2, Tiers: [][]string{{"a"}, {"b"}}, Created: *at("01:40"),
		Delivery: &PlanDelivery{Merges: []PlanMerge{{Repository: "novox/x", Commit: "c1", Merged: *at("00:00")},
			{Repository: "novox/x", Commit: "c0", Merged: *at("00:30")}}},
		Times: &PlanTimes{WindowClosed: at("01:30"), Cut: at("01:40"), Class: ClassLeaf},
		Modules: map[string]*PlanModule{
			"a": {State: "built", AskedAt: at("01:41"), BuiltAt: at("02:05"), FirstAt: at("02:20"), SentAt: at("05:00"),
				Gate: &PlanGate{JudgedAt: at("04:50")}, Rest: map[string]SentDeclaration{"ace": {Digest: "d1"}}},
			"b": {State: "built", AskedAt: at("05:10"), BuiltAt: at("05:40"), FirstAt: at("05:50"), SentAt: at("08:00.5"),
				Gate: &PlanGate{JudgedAt: at("07:59")}, Rest: map[string]SentDeclaration{"shanks": {Digest: "d2"}}},
		}}
	reports := map[string]AppliedReport{"ace": {At: *at("05:12"), Outcome: OutcomeApplied},
		"shanks": {At: *at("08:15.25"), Outcome: OutcomeApplied}}
	w := p.WalkPhases(*at("30:00"), func(node string, _ time.Time) (AppliedReport, bool) {
		r, ok := reports[node]
		return r, ok
	})
	sumsUp(t, w)
	if w.TotalMS != (8*time.Minute + 15250*time.Millisecond).Milliseconds() {
		t.Fatalf("the walk's delivery time runs from its earliest merge to the last report: %s", w.Total)
	}
	if got := phase(w, PhaseBetween, 1); got.TookMS != 10000 {
		t.Errorf("between the tiers: %dms", got.TookMS)
	}
	if got := phase(w, PhaseApply, -1); got.State != PhaseMeasured || got.TookMS != 14750 {
		t.Errorf("apply: %s %dms", got.State, got.TookMS)
	}
	if len(w.Merges) != 2 {
		t.Errorf("each merge's start is said, for its own delivery time: %+v", w.Merges)
	}
	// A report not yet in: the walk has no end, and its apply is unknown — never zero.
	delete(reports, "shanks")
	w = p.WalkPhases(*at("10:00"), func(node string, _ time.Time) (AppliedReport, bool) {
		r, ok := reports[node]
		return r, ok
	})
	if w.End != nil || w.TotalMS != 0 {
		t.Fatalf("a walk whose rest has not reported has no end: %+v", w)
	}
	if got := phase(w, PhaseApply, -1); got.State != PhaseUnknown || got.TookMS != 0 || !strings.Contains(got.Said, "shanks") {
		t.Errorf("apply while shanks has not reported: %+v", got)
	}
	// Silent past the bound: listed, not waited for.
	w = p.WalkPhases(at("08:00.5").Add(ApplySilentAfter+time.Second), func(node string, _ time.Time) (AppliedReport, bool) {
		r, ok := reports[node]
		return r, ok
	})
	sumsUp(t, w)
	if len(w.Silent) != 1 || w.Silent[0] != "shanks" {
		t.Errorf("a machine silent past the bound is said, not waited for: %+v", w.Silent)
	}
	// A failed report: the walk has no end, said.
	reports["shanks"] = AppliedReport{At: *at("08:10"), Outcome: OutcomeFailed}
	w = p.WalkPhases(*at("30:00"), func(node string, _ time.Time) (AppliedReport, bool) {
		r, ok := reports[node]
		return r, ok
	})
	if w.End != nil || !strings.Contains(phase(w, PhaseApply, -1).Said, "shanks (failed)") {
		t.Errorf("a failed apply ends nothing: %+v", phase(w, PhaseApply, -1))
	}
}

// A moment that is missing makes the phases around it unknown, and their span unknown time: never a zero.
func TestAMissingMomentIsUnknownNeverZero(t *testing.T) {
	p := walkOf(t, recordedWalk)
	p.Modules["mesh-delivery"].BuiltAt = nil
	w := p.WalkPhases(time.Date(2026, 10, 10, 18, 0, 0, 0, time.UTC), nil)
	sumsUp(t, w)
	if got := phase(w, PhaseBuild, 0); got.State != PhaseUnknown || got.TookMS != 0 {
		t.Errorf("a build without its moment: %+v", got)
	}
	if got := phase(w, PhaseSend, 0); got.State != PhaseUnknown {
		t.Errorf("the send after a build without its moment: %+v", got)
	}
	if w.UnknownMS != 16781+16469 {
		t.Errorf("the unknown time is the span between the moments around it: %dms", w.UnknownMS)
	}
	// A walk kept before ADR 0282: its window and its wait together, and its apply unknown.
	p = walkOf(t, recordedWalk)
	p.Times = nil
	w = p.WalkPhases(time.Date(2026, 10, 10, 18, 0, 0, 0, time.UTC), nil)
	if got := phase(w, PhaseWindow, -1); got.State != PhaseUnknown {
		t.Errorf("a window not kept: %+v", got)
	}
	if got := phase(w, PhaseApply, -1); got.State != PhaseUnknown || w.End != nil {
		t.Errorf("a rest not kept: %+v, end %v", got, w.End)
	}
}

// An open walk is said open since its last moment, with no end.
func TestAnOpenWalkHasNoEnd(t *testing.T) {
	p := walkOf(t, recordedWalk)
	p.State, p.Tier = PlanRolling, 0
	p.Modules["mesh-delivery"].SentAt = nil
	p.Modules["mesh-delivery"].Gate.JudgedAt = nil
	w := p.WalkPhases(time.Date(2026, 10, 10, 17, 54, 0, 0, time.UTC), nil)
	if w.End != nil || !strings.HasPrefix(w.Said, "its end is unknown") && !strings.HasPrefix(w.Said, "open") {
		t.Fatalf("an open walk: %+v", w)
	}
	if got := phase(w, PhaseBuild, 0); got.State != PhaseMeasured {
		t.Errorf("an open walk's phases so far are measured: %+v", got)
	}
}

// A gate keeps every pass and the first reading after one that did not pass, at most maxReadings.
func TestAGateKeepsItsReadings(t *testing.T) {
	var g PlanGate
	t0 := time.Date(2026, 10, 10, 18, 0, 0, 0, time.UTC)
	g.Read(t0, false, "starting")
	g.Read(t0.Add(time.Second), false, "starting")
	g.Read(t0.Add(40*time.Second), true, "")
	g.Read(t0.Add(80*time.Second), true, "")
	g.Read(t0.Add(81*time.Second), false, "gone")
	g.Read(t0.Add(82*time.Second), false, "gone")
	if len(g.Readings) != 4 || g.Readings[0].Said != "starting" || !g.Readings[2].Healthy || g.Readings[3].Said != "gone" {
		t.Fatalf("readings: %+v", g.Readings)
	}
	for i := 0; i < 50; i++ {
		g.Read(t0.Add(time.Duration(100+i)*time.Second), true, "")
	}
	if len(g.Readings) != maxReadings {
		t.Fatalf("readings are bounded: %d", len(g.Readings))
	}
}

// A walk's moments are kept and read back with it; a machine's first report after a send is read from the
// controller's apply durations.
func TestAWalksMomentsAreKeptAndItsRestsReportRead(t *testing.T) {
	inv := ForTest(t)
	ctx := t.Context()
	p := walkOf(t, recordedWalk)
	p.Revision, p.Epoch = 0, 0
	if err := inv.SavePlan(ctx, &p); err != nil {
		t.Fatal(err)
	}
	back, err := inv.PlanByID(ctx, p.ID)
	if err != nil || back.Times == nil || back.Times.Class != ClassCore || back.Times.WindowClosed == nil ||
		!back.Times.WindowClosed.Equal(*p.Times.WindowClosed) {
		t.Fatalf("the walk's moments were not kept: %v %+v", err, back.Times)
	}
	if back.Delivery.Merges[0].Merged.IsZero() {
		t.Fatal("a merge's time was not kept")
	}
	sent := time.Now().UTC().Add(-time.Minute).Truncate(time.Millisecond)
	if _, ok, err := inv.FirstAppliedAfter(ctx, "ace", sent); err != nil || ok {
		t.Fatalf("no report yet: %v %v", ok, err)
	}
	for _, d := range []Duration{
		{Kind: DurationApply, Subject: "ace", Node: "ace", Ref: "old@1", Started: sent.Add(-time.Hour), Took: time.Second, Detail: OutcomeApplied},
		{Kind: DurationApply, Subject: "ace", Node: "ace", Ref: "d1@2", Started: sent.Add(-time.Second), Took: 12 * time.Second, Detail: OutcomeApplied},
	} {
		if err := inv.RecordDuration(ctx, d); err != nil {
			t.Fatal(err)
		}
	}
	r, ok, err := inv.FirstAppliedAfter(ctx, "ace", sent)
	if err != nil || !ok || r.Outcome != OutcomeApplied || !r.At.Equal(sent.Add(11*time.Second)) {
		t.Fatalf("the report after the send: %+v %v %v", r, ok, err)
	}
	if anyKept, total, err := inv.WalkPhasesKept(ctx, p.ID); err != nil || anyKept || total {
		t.Fatalf("nothing kept yet: %v %v %v", anyKept, total, err)
	}
	if err := inv.RecordDuration(ctx, Duration{Kind: DurationWalkPhase, Subject: "core/total", Ref: p.ID + "/total",
		Started: sent, Took: time.Minute}); err != nil {
		t.Fatal(err)
	}
	if anyKept, total, err := inv.WalkPhasesKept(ctx, p.ID); err != nil || !anyKept || !total {
		t.Fatalf("the total kept: %v %v %v", anyKept, total, err)
	}
}

// A machine that slept past the bound and reported later is listed silent: its late report never moves the
// walk's end; and a report sent past the bound is not read as the walk's.
func TestALateReportIsSilentNotTheEnd(t *testing.T) {
	sent := time.Date(2026, 10, 10, 18, 0, 0, 0, time.UTC)
	p := walkOf(t, recordedWalk)
	p.Modules["mesh-delivery"].SentAt = &sent
	p.Modules["mesh-delivery"].Rest = map[string]SentDeclaration{"laptop": {Digest: "d"}, "server": {Digest: "e"}}
	w := p.WalkPhases(sent.Add(3*time.Hour), func(node string, _ time.Time) (AppliedReport, bool) {
		if node == "server" {
			return AppliedReport{At: sent.Add(20 * time.Second), Outcome: OutcomeApplied}, true
		}
		return AppliedReport{At: sent.Add(2 * time.Hour), Outcome: OutcomeApplied}, true
	})
	if len(w.Silent) != 1 || w.Silent[0] != "laptop" || w.End == nil || !w.End.Equal(sent.Add(20*time.Second)) {
		t.Fatalf("a late report: silent %v, end %v", w.Silent, w.End)
	}
	inv := ForTest(t)
	ctx := t.Context()
	if err := inv.RecordDuration(ctx, Duration{Kind: DurationApply, Subject: "laptop", Node: "laptop", Ref: "late@1",
		Started: sent.Add(time.Hour), Took: time.Second, Detail: OutcomeApplied}); err != nil {
		t.Fatal(err)
	}
	if _, ok, err := inv.FirstAppliedAfter(ctx, "laptop", sent); err != nil || ok {
		t.Fatalf("a send past the bound read as the walk's: %v %v", ok, err)
	}
}