Files
mesh-controller/internal/inventory/walkphases_582_test.go
T
mesh-tools 97a2d841c7 Land feature 57's controller work on its release branch
The controller plans config, templates and moved providers' provisions,
hands bus accounts to the vault and judges the new manifest words, on the
feature's SDK and node-engine validator (feature 57, config and provisioning).
2026-10-15 21:27:33 +00:00

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