jochen
12d4025d30
#206's own walk kept its first send 783 ms before its build, and delivery walks said send-first measured at -783 ms. A moment recorded before the one before it now makes both phases unknown: the earlier one's time joins the unknown time, the later one has none, and the walk goes on from the later moment. Measured phases and unknown time still add up to the total.
331 lines
15 KiB
Go
331 lines
15 KiB
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)
|
|
}
|
|
}
|
|
|
|
// Moments out of order — #206's own walk on 2026-10-10 kept its first send 783 ms before its build — are said
|
|
// unknown, never a negative phase: the phase before is unknown and its time joins the unknown time, the phase
|
|
// out of order has no time, and the phases still add up to the total.
|
|
func TestMomentsOutOfOrderAreUnknownNeverNegative(t *testing.T) {
|
|
p := walkOf(t, recordedWalk)
|
|
built := time.Date(2026, 10, 10, 17, 53, 8, 70000000, time.UTC) // 783 ms after its first send
|
|
p.Modules["mesh-delivery"].BuiltAt = &built
|
|
w := p.WalkPhases(time.Date(2026, 10, 10, 18, 0, 0, 0, time.UTC), nil)
|
|
sumsUp(t, w)
|
|
for _, ph := range w.Phases {
|
|
if ph.TookMS < 0 {
|
|
t.Fatalf("a negative phase: %+v", ph)
|
|
}
|
|
}
|
|
build, send := phase(w, PhaseBuild, 0), phase(w, PhaseSend, 0)
|
|
if build.State != PhaseUnknown || send.State != PhaseUnknown || send.TookMS != 0 ||
|
|
!strings.Contains(send.Said, "out of order") || !strings.Contains(build.Said, "out of order") {
|
|
t.Fatalf("build %+v, send-first %+v", build, send)
|
|
}
|
|
// The build's span (cut to its later moment) is unknown time; the judgement is measured from the later moment.
|
|
if w.UnknownMS != built.Sub(time.Date(2026, 10, 10, 17, 52, 34, 37000000, time.UTC)).Milliseconds() {
|
|
t.Fatalf("unknown %dms", w.UnknownMS)
|
|
}
|
|
if j := phase(w, PhaseJudge, 0); j.State != PhaseMeasured || j.Start == nil || !j.Start.Equal(built) {
|
|
t.Fatalf("the judgement is measured from the later moment: %+v", j)
|
|
}
|
|
}
|