package inventory import ( "strings" "testing" "time" ) // novox/hq issue 582: the walk's own record of its send to the rest is made after every machine of the rest was // sent, and that send took 19 to 28 s on 2026-10-12. The machine sent first reported 5 s after its own send, long // before the walk's record; read from the walk's record, its report was missed and the walk ended at another walk's // send to it, minutes later. A walk of one tier and three machines of the rest, the send to the rest taking 20 s. type sendRest582 struct { judged, walkSent time.Time walk Plan rows map[string][]Duration } func walk582(t *testing.T) sendRest582 { t.Helper() judged := time.Date(2026, 10, 12, 17, 45, 35, 137000000, time.UTC) ownSend := map[string]time.Duration{"g14": 500 * time.Millisecond, "novox": 10 * time.Second, "shanks": 20 * time.Second} walkSent := judged.Add(20200 * time.Millisecond) merged := judged.Add(-10 * time.Minute) built, first := judged.Add(-3*time.Minute), judged.Add(-2*time.Minute) rest := map[string]SentDeclaration{} rows := map[string][]Duration{} took := map[string]time.Duration{"g14": 5 * time.Second, "novox": 13 * time.Second, "shanks": 15 * time.Second} for i, n := range []string{"g14", "novox", "shanks"} { at := judged.Add(ownSend[n]) digest := "walk-" + n rest[n] = SentDeclaration{Digest: digest, Sequence: int64(647 + i), At: at} rows[n] = append(rows[n], // This walk's send, and its report. Duration{Kind: DurationApply, Subject: n, Node: n, Ref: digest + "@" + at.Format("2006-01-02T15:04:05.000000"), Started: at, Took: took[n], Detail: OutcomeApplied}, // The next walk's send to the same machine, nine minutes later, and its report. Duration{Kind: DurationApply, Subject: n, Node: n, Ref: "next-" + n + "@x", Started: judged.Add(9*time.Minute + ownSend[n]), Took: 4 * time.Second, Detail: OutcomeApplied}) } p := Plan{ID: "plan-582", State: PlanDone, Tier: 1, Tiers: [][]string{{"build-agent"}}, Created: merged, Delivery: &PlanDelivery{Merges: []PlanMerge{{Repository: "novox/mesh-controller", Commit: "c", Merged: merged}}}, Times: &PlanTimes{Cut: &merged, Class: ClassCore}, Modules: map[string]*PlanModule{"build-agent": {State: "built", AskedAt: &merged, BuiltAt: &built, FirstAt: &first, SentAt: &walkSent, Gate: &PlanGate{JudgedAt: &judged}, Rest: rest}}} return sendRest582{judged: judged, walkSent: walkSent, walk: p, rows: rows} } // lookup answers from the rows as the controller's durations would. func (w sendRest582) lookup(node string, send SentDeclaration, walkSent time.Time) (AppliedReport, bool) { return FirstReportOf(w.rows[node], send, walkSent) } // The apply phase ends at the last machine's own report of this walk's send — shanks, sent at the end of the 20 s // and reporting 15 s later — and never at the next walk's send; every machine's report is shown. func TestTheApplyPhaseEndsAtEachMachinesOwnReport(t *testing.T) { c := walk582(t) w := c.walk.WalkPhases(c.judged.Add(time.Hour), c.lookup) sumsUp(t, w) want := c.judged.Add(35 * time.Second) // shanks: sent 20 s after the judgement, reported 15 s later if !w.End.Equal(want) { t.Fatalf("the walk ends at %s, want %s: its rest %+v", w.End, want, w.Rest) } if got := phase(w, PhaseApply, -1); got.State != PhaseMeasured || got.TookMS != want.Sub(c.walkSent).Milliseconds() { t.Fatalf("apply: %+v", got) } if len(w.Rest) != 3 || len(w.Silent) != 0 { t.Fatalf("every machine of the rest is shown with its report: %+v, silent %v", w.Rest, w.Silent) } g14 := w.Rest[0] if g14.Node != "g14" || g14.State != RestApplied || g14.Reported == nil || !g14.Reported.Equal(c.judged.Add(5500*time.Millisecond)) || g14.Took != "5s" || g14.Sequence != 647 || !g14.Sent.Equal(c.judged.Add(500*time.Millisecond)) || g14.SentSaid != "" { t.Fatalf("g14, sent first and reporting 5 s after its own send: %+v", g14) } } // A walk kept before its machines' own send times were: matched by the declaration it sent, within restSendBound // of its record of the send, so the machine sent first is still found; a walk that kept neither is read as before. func TestAnOlderWalkIsReadByWhatItSent(t *testing.T) { c := walk582(t) for n, s := range c.walk.Modules["build-agent"].Rest { s.At = time.Time{} c.walk.Modules["build-agent"].Rest[n] = s } w := c.walk.WalkPhases(c.judged.Add(time.Hour), c.lookup) sumsUp(t, w) if !w.End.Equal(c.judged.Add(35 * time.Second)) { t.Fatalf("by the declaration sent: end %s, rest %+v", w.End, w.Rest) } if !strings.Contains(w.Rest[0].SentSaid, "walk's record") || !w.Rest[0].Sent.Equal(c.walkSent) { t.Fatalf("a send time not kept is said: %+v", w.Rest[0]) } // Nothing of the send kept: the first report no earlier than appliedSlack before the walk's record, as before. if r, ok := FirstReportOf(c.rows["shanks"], SentDeclaration{}, c.walkSent); !ok || !r.At.Equal(c.judged.Add(35*time.Second)) { t.Fatalf("a walk that kept nothing of its send: %+v %v", r, ok) } } // A machine that said nothing of this walk's send is waiting, then silent past ApplySilentAfter: the report of a // later send to it is never taken as this walk's, and never moves the walk's end. func TestALaterSendsReportIsNeverThisWalks(t *testing.T) { c := walk582(t) c.rows["g14"] = c.rows["g14"][1:] // g14 slept through this walk's send; the next walk's send it reported w := c.walk.WalkPhases(c.judged.Add(5*time.Minute), c.lookup) if w.End != nil || !strings.Contains(phase(w, PhaseApply, -1).Said, "waiting for g14") { t.Fatalf("g14 not heard from yet: end %v, apply %+v", w.End, phase(w, PhaseApply, -1)) } w = c.walk.WalkPhases(c.judged.Add(time.Hour), c.lookup) sumsUp(t, w) if len(w.Silent) != 1 || w.Silent[0] != "g14" || !w.End.Equal(c.judged.Add(35*time.Second)) { t.Fatalf("g14 silent, the end at shanks' report: silent %v, end %s", w.Silent, w.End) } if w.Rest[0].State != RestSilent || w.Rest[0].Reported != nil { t.Fatalf("g14's later report taken as this walk's: %+v", w.Rest[0]) } } // A machine sent by two tiers of one walk that said nothing of the first send has said it of the second, which // carries the first tier's build too. func TestAMachineSentTwiceByOneWalkIsHeardByItsLaterSend(t *testing.T) { c := walk582(t) second := c.judged.Add(4 * time.Minute) secondSent := second.Add(time.Second) c.walk.Tiers = append(c.walk.Tiers, []string{"route-proxy"}) c.walk.Tier = 2 asked, built := c.judged.Add(time.Minute), c.judged.Add(2*time.Minute) first := built.Add(time.Second) c.walk.Modules["route-proxy"] = &PlanModule{State: "built", AskedAt: &asked, BuiltAt: &built, FirstAt: &first, SentAt: &secondSent, Gate: &PlanGate{JudgedAt: &second}, Rest: map[string]SentDeclaration{"novox": {Digest: "walk-novox-2", Sequence: 1554, At: second.Add(500 * time.Millisecond)}}} c.rows["novox"] = []Duration{{Kind: DurationApply, Subject: "novox", Ref: "walk-novox-2@x", Started: second.Add(500 * time.Millisecond), Took: 14 * time.Second, Detail: OutcomeApplied}} w := c.walk.WalkPhases(c.judged.Add(time.Hour), c.lookup) sumsUp(t, w) want := second.Add(14500 * time.Millisecond) if !w.End.Equal(want) || len(w.Silent) != 0 { t.Fatalf("end %s (want %s), silent %v, rest %+v", w.End, want, w.Silent, w.Rest) } for _, r := range w.Rest { if r.Node == "novox" && (r.State != RestApplied || !r.Reported.Equal(want)) { t.Fatalf("novox, heard by its later send of this walk: %+v", r) } } } // The store: a machine's own send time is read with what it was sent, and its `apply` duration is found by it — // the send and the duration start at one moment, the node's sent_at. func TestAWalksRestIsReadFromEachMachinesOwnSend(t *testing.T) { inv := ForTest(t) ctx := t.Context() record, err := inv.AddNode(ctx, "g14") if err != nil { t.Fatal(err) } if _, err := inv.NextSequence(ctx, record.ID); err != nil { t.Fatal(err) } if err := inv.RecordSent(ctx, record.ID, "d-582", map[string]string{"build-agent": "c1"}); err != nil { t.Fatal(err) } sent, found, err := inv.SentTo(ctx, "g14") if err != nil || !found || sent.At.IsZero() || sent.Digest != "d-582" { t.Fatalf("the machine's own send time: %+v %v %v", sent, found, err) } if _, ok, err := inv.FirstAppliedAfter(ctx, "g14", sent, sent.At.Add(20*time.Second)); err != nil || ok { t.Fatalf("no report yet: %v %v", ok, err) } if err := inv.RecordApplyDuration(ctx, "g14", "d-582", OutcomeApplied); err != nil { t.Fatal(err) } // The walk's record of its send, 20 s after the machine's own: still found, by the machine's own send. r, ok, err := inv.FirstAppliedAfter(ctx, "g14", sent, sent.At.Add(20*time.Second)) if err != nil || !ok || r.Outcome != OutcomeApplied || r.At.Before(sent.At) { t.Fatalf("the machine's own report of its send: %+v %v %v", r, ok, err) } // A later send, reported: never this walk's. if err := inv.RecordSent(ctx, record.ID, "d-next", map[string]string{"build-agent": "c2"}); err != nil { t.Fatal(err) } if err := inv.RecordApplyDuration(ctx, "g14", "d-next", OutcomeApplied); err != nil { t.Fatal(err) } again, _, _ := inv.FirstAppliedAfter(ctx, "g14", sent, sent.At.Add(20*time.Second)) if !again.At.Equal(r.At) { t.Fatalf("a later send's report read as this walk's: %+v, was %+v", again, r) } }