Files
mesh-controller/internal/inventory/walkphases_582_test.go
T

211 lines
9.9 KiB
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)
}
}
// Issue 840 (ADR 0362): the walk's report of a machine is asked for with only the provisioned modules the walk sent
// there, never every module the machine's declaration hands to the provisioner.
func TestTheRestIsAskedAboutTheModulesTheWalkSent(t *testing.T) {
c := walk582(t)
rest := c.walk.Modules["build-agent"].Rest
for n, s := range rest {
s.Provisioned = map[string]string{"build-agent": "t1", "other": "t2"}
rest[n] = s
}
asked := 0
c.walk.WalkPhases(c.judged.Add(time.Hour), func(node string, send SentDeclaration, walkSent time.Time) (AppliedReport, bool) {
asked++
if len(send.Provisioned) != 1 || send.Provisioned["build-agent"] != "t1" {
t.Fatalf("%s is asked about %v", node, send.Provisioned)
}
return c.lookup(node, send, walkSent)
})
if asked == 0 {
t.Fatal("no machine was asked")
}
}