mesh-controller/internal/inventory/walkphases_582_test.go

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)
	}
}