diff --git a/cmd/mesh-host/engineseat.go b/cmd/mesh-host/engineseat.go index 443f0fc..f7c8b88 100644 --- a/cmd/mesh-host/engineseat.go +++ b/cmd/mesh-host/engineseat.go @@ -363,7 +363,8 @@ func packagesFrom(node string, session *link.Session, composer *atomic.Pointer[s } // composeCandidateFrom answers the verb compose-candidate (novox/hq ADR 0593 §7): the check's candidate composed on this -// node in shadow by the run's shadow, applying and writing nothing, within delivery.ComposeAnswerBound. The answer is +// node in shadow by the run's shadow, applying and writing nothing, within the shadow's own bound (shorter than +// delivery.ComposeAnswerBound, selfcompose candidateWithin). The answer is // the seat's shape (delivery.ComposeCandidateAnswer), checked as it is encoded; a node whose shadow does not run yet // answers unready, which the checker takes as no answer. func composeCandidateFrom(node string, shadow *atomic.Pointer[selfcompose.Shadow]) func(candidate string, input bool) (any, error) { diff --git a/internal/selfcompose/candidate.go b/internal/selfcompose/candidate.go index 6c6fe44..491e43c 100644 --- a/internal/selfcompose/candidate.go +++ b/internal/selfcompose/candidate.go @@ -6,7 +6,9 @@ import ( "errors" "fmt" "maps" + "slices" "sort" + "sync" "time" "git.novox.be/novox/mesh-sdk/go/delivery" @@ -28,17 +30,98 @@ import ( // errNotReady is a shadow that has not read every input yet. var errNotReady = errors.New("this node's shadow has not read every input yet") -// ComposeCandidate is the node's answer to ask, within delivery.ComposeAnswerBound (or ctx's deadline, if sooner). +// candidateWithin is the node's own bound on an answer to compose-candidate: shorter than the checker's +// (delivery.ComposeAnswerBound), because the bus lets the engine answer an ask only within a minute of it (the grants +// part's allow_responses ttl, mesh-grants ResponseTTL): an answer at the checker's 60 s bound was refused by the bus +// (issue 1126, 2026-11-03 01:17:04 on shanks, "Permissions Violation for Publish to _INBOX..."), so the checker heard +// nothing at all. A node not done by then answers unready, naming what it waits on. +var candidateWithin = delivery.ComposeAnswerBound - 10*time.Second + +// warmAtOnce is how many of the indexer's manifests the shadow reads at once before it composes a candidate. +const warmAtOnce = 8 + +// candidateRun is what one ask's compositions wait on: each scratch composer it made, the last the one composing now. +type candidateRun struct { + mu sync.Mutex + parts []*Composer +} + +func (r *candidateRun) add(c *Composer) *Composer { + r.mu.Lock() + defer r.mu.Unlock() + r.parts = append(r.parts, c) + return c +} + +// said is the run's waits in words: how many reads it waited on the bus or the vault for, and the longest; and, while +// one is still running (now), what it waits on and since when. +func (r *candidateRun) said(now time.Time) (waits string, on string) { + r.mu.Lock() + parts := slices.Clone(r.parts) + r.mu.Unlock() + n, longest, longestOn := 0, time.Duration(0), "" + for _, c := range parts { + c.doingMu.Lock() + n += c.waits.n + if c.waits.longest > longest { + longest, longestOn = c.waits.longest, c.waits.longestOn + } + if c.doing != "" { + on = fmt.Sprintf("%s (for %s)", c.doing, now.Sub(c.doingSince).Round(time.Millisecond)) + } else if on == "" && c.waits.lastOn != "" { + on = c.waits.lastOn + " (the last read)" + } + c.doingMu.Unlock() + } + waits = fmt.Sprintf("%d read(s) waited on", n) + if longestOn != "" { + waits += fmt.Sprintf(", the longest %s on %s", longest.Round(time.Millisecond), longestOn) + } + if on == "" { + on = "nothing it reads (composing)" + } + return waits, on +} + +// ComposeCandidate is the node's answer to ask, within candidateWithin (or ctx's deadline, if sooner). Each answer is +// said in one line, with what it waited on and for how long (issue 1126: ace, g14 and shanks answered nothing for a +// minute while nothing said why). An answer not composed within the bound is unready, naming what the node waits on. func (s *Shadow) ComposeCandidate(ctx context.Context, ask delivery.ComposeCandidateAsk) delivery.ComposeCandidateAnswer { - began := time.Now() s.mu.Lock() c := s.c s.mu.Unlock() + began := c.now() + ctx, cancel := context.WithTimeout(ctx, candidateWithin) + defer cancel() + run := &candidateRun{} + done := make(chan delivery.ComposeCandidateAnswer, 1) + go func() { done <- s.composeCandidate(ctx, c, ask, began, run) }() + var a delivery.ComposeCandidateAnswer + select { + case a = <-done: + case <-ctx.Done(): + _, on := run.said(c.now()) + a = delivery.ComposeCandidateAnswer{Node: c.env.Node, Candidate: ask.Candidate, Verdict: delivery.ComposeCandidateUnready, + Refused: fmt.Sprintf("the node did not compose the candidate within %s: it waits on %s", candidateWithin, on), + Took: c.now().Sub(began).Milliseconds()} + } + waits, _ := run.said(c.now()) + words := "" + if a.Refused != "" { + words = ": " + a.Refused + } + c.env.Say(fmt.Sprintf("compose-candidate %s answered %s in %s (%s)%s", ask.Candidate, a.Verdict, + (time.Duration(a.Took) * time.Millisecond).String(), waits, words)) + return a +} + +// composeCandidate composes ask on scratch copies of c, each added to run as it starts. +func (s *Shadow) composeCandidate(ctx context.Context, c *Composer, ask delivery.ComposeCandidateAsk, began time.Time, run *candidateRun) delivery.ComposeCandidateAnswer { node := c.env.Node a := delivery.ComposeCandidateAnswer{Node: node, Candidate: ask.Candidate} refuse := func(why string) delivery.ComposeCandidateAnswer { a.Verdict, a.Refused, a.Modules, a.Own = delivery.ComposeCandidateRefused, why, nil, delivery.ModuleComposed{} - a.Took = time.Since(began).Milliseconds() + a.Took = c.now().Sub(began).Milliseconds() return a } // A node that cannot compose now (its shadow not ready, a read the bus did not answer, the bound passed) answers @@ -58,12 +141,10 @@ func (s *Shadow) ComposeCandidate(ctx context.Context, ask delivery.ComposeCandi if err != nil { return refuse(err.Error()) } - ctx, cancel := context.WithTimeout(ctx, delivery.ComposeAnswerBound) - defer cancel() if !s.ready.Load() { return unready(errNotReady.Error()) } - base := c.scratch() + base := run.add(c.scratch()) raw, err := base.get(ctx, delivery.CandidatesBucket, ckey) if err != nil { return unready(fmt.Sprintf("the indexer's candidate %s cannot be read: %v", ask.Candidate, err)) @@ -80,17 +161,21 @@ func (s *Shadow) ComposeCandidate(ctx context.Context, ask delivery.ComposeCandi // not asked about. No answer (ADR 0593 §9), never a verdict on the wrong heads. return unready(fmt.Sprintf("the indexer's candidate of the group %s is at heads %s, not %s: the check asked is replaced", group, cand.HeadsHash, heads)) } - laid := c.scratch() - touched, err := laid.layCandidate(ctx, cand) - if err != nil { - return unready(err.Error()) - } + // Every module's manifest is read before either composition, several at once, into the shadow's own: a composition + // reads every manifest in the mesh one by one, which off the control-node took about 35 s each (issue 1126). + base.warm(ctx, c, cand) var running []delivery.Composed if c.env.Running != nil { running = c.env.Running() } baseComps, baseHeld, baseErr := base.composeShadow(ctx, running, nil, nil) + // The candidate laid over a copy taken after the composition without it, so what that read is not read again. + laid := run.add(c.scratch()) + touched, err := laid.layCandidate(ctx, cand) + if err != nil { + return unready(err.Error()) + } laidComps, laidHeld, laidErr := laid.composeShadow(ctx, running, touched, func(scope frombus.Scope) { if !ask.Input { return @@ -109,7 +194,8 @@ func (s *Shadow) ComposeCandidate(ctx context.Context, ask delivery.ComposeCandi } }) if ctx.Err() != nil { - return unready(fmt.Sprintf("the bound of %s passed before the node composed the candidate", delivery.ComposeAnswerBound)) + _, on := run.said(c.now()) + return unready(fmt.Sprintf("the node did not compose the candidate within %s: it waits on %s", candidateWithin, on)) } switch { case laidErr != nil && BusFailed(laidErr): @@ -118,7 +204,7 @@ func (s *Shadow) ComposeCandidate(ctx context.Context, ask delivery.ComposeCandi // The node composes none of its own without the candidate either: the candidate changes nothing of that. a.Verdict, a.Modules = delivery.ComposeCandidateComposed, []delivery.ModuleComposed{} a.Own = delivery.ModuleComposed{Module: delivery.HaveNodeWord, State: delivery.ModuleHeldState, Words: laidErr.Error()} - a.Took = time.Since(began).Milliseconds() + a.Took = c.now().Sub(began).Milliseconds() return a case laidErr != nil: return refuse(laidErr.Error()) @@ -193,7 +279,7 @@ func (s *Shadow) ComposeCandidate(ctx context.Context, ask delivery.ComposeCandi if refused { a.Verdict = delivery.ComposeCandidateRefused } - a.Took = time.Since(began).Milliseconds() + a.Took = c.now().Sub(began).Milliseconds() return a } @@ -214,9 +300,63 @@ func (c *Composer) scratch() *Composer { out.ownHanded = maps.Clone(c.ownHanded) out.certified = c.certified out.placementKeys = c.placementKeys + out.origin = c return out } +// warm reads, several at once, each manifest the indexer's modules and the candidate name that the shadow (origin) does +// not hold yet, keeping each in origin and in c; one not read is left to the composition, which reads it and says why. +// Its reads are not noted as the bus failing: the composition that reads again notes its own. +func (c *Composer) warm(ctx context.Context, origin *Composer, cand delivery.Candidate) { + origin.mu.Lock() + want := map[string]bool{} + for _, m := range origin.modules { + if _, ok := origin.manifests[m.Manifest]; m.Manifest != "" && !ok { + want[m.Manifest] = true + } + } + for _, pull := range cand.Pulls { + for _, cm := range pull.Fps { + if _, ok := origin.manifests[cm.Manifest]; cm.Manifest != "" && !ok { + want[cm.Manifest] = true + } + } + } + origin.mu.Unlock() + if len(want) == 0 { + return + } + defer c.waiting(fmt.Sprintf("%d of the indexer's manifests (%s)", len(want), delivery.ManifestsBucket))() + slots := make(chan struct{}, warmAtOnce) + var wg sync.WaitGroup + for digest := range want { + key, err := delivery.ManifestsKey(digest) + if err != nil { + continue + } + wg.Add(1) + go func() { + defer wg.Done() + select { + case slots <- struct{}{}: + case <-ctx.Done(): + return + } + defer func() { <-slots }() + value, err := c.env.Get(ctx, delivery.ManifestsBucket, key) + if err != nil || value == nil { + return + } + m, err := delivery.DecodeManifest(value) + if err != nil { + return + } + c.keepRead(func(k *Composer) { k.manifests[digest] = []byte(m.JSON) }) + }() + } + wg.Wait() +} + // layCandidate lays the candidate's modules over the indexer's: each at its fingerprint, with its manifest's digest and // the indexer's verdict on it (read from its verdicts, none read taken as accepted); a module the candidate removes goes. // It answers the modules laid. diff --git a/internal/selfcompose/candidate_test.go b/internal/selfcompose/candidate_test.go index e935430..ad303cd 100644 --- a/internal/selfcompose/candidate_test.go +++ b/internal/selfcompose/candidate_test.go @@ -133,3 +133,121 @@ func TestTheNodeComposesACandidateOnAsk(t *testing.T) { t.Errorf("composing candidates wrote %v, marked %d have(s), handed %d answer(s); want nothing", state.written(), applied.Load(), handed.Load()) } } + +// Issue 1126, 2026-11-03: off the control-node an ask of compose-candidate was not answered within a minute, and said +// nothing of why. Each of its two compositions read every manifest in the mesh one by one, on copies of the shadow +// that kept nothing, so every ask read them all twice again. Each manifest is now read once, before either +// composition, into the shadow, and a later ask reads none; an ask whose read does not answer is answered unready at +// its bound, naming what the node waits on; and every answer is said in one line with what it waited on. +func TestComposeCandidateReadsOnceAndAnswersWithinItsBound(t *testing.T) { + fp := delivery.SourcePrefix2 + strings.Repeat("a", 64) + fpNew := delivery.SourcePrefix2 + strings.Repeat("b", 64) + lemurs2 := strings.Replace(lemurs, `"version":"1"`, `"version":"2"`, 1) + other := strings.NewReplacer(`"module":"lemurs"`, `"module":"other"`, "lemurs.service", "other.service").Replace(lemurs) + digest, digest2, digestOther := delivery.ManifestDigest([]byte(lemurs)), delivery.ManifestDigest([]byte(lemurs2)), + delivery.ManifestDigest([]byte(other)) + otherKey, _ := delivery.ManifestsKey(digestOther) + + // shadow is a ready shadow of n1 over b: lemurs placed on it, other placed nowhere (its manifest read for the mesh's + // catalogue alone), and a candidate laying lemurs at a new build; its clock moves a second at each reading. + shadow := func(b *fakeBus) (*Shadow, string) { + for d, body := range map[string]string{digest: lemurs, digest2: lemurs2, digestOther: other} { + man, _ := delivery.EncodeManifest(delivery.Manifest{Module: "x", JSON: body}) + key, _ := delivery.ManifestsKey(d) + b.kv[delivery.ManifestsBucket+"/"+key] = man + } + head := delivery.Head{Repository: "novox/x", Number: 7, Head: "c0ffee"} + heads, _ := delivery.HeadsHash([]delivery.Head{head}) + pulls := []delivery.CandidatePull{{Head: head, Modules: []string{"lemurs"}, + Fps: map[string]delivery.CandidateModule{"lemurs": {FP2: fpNew, Manifest: digest2}}}} + raw, _ := delivery.EncodeCandidate(delivery.Candidate{Group: "fix/1126", HeadsHash: heads, Pulls: pulls, + FPSet: delivery.FingerprintSet(pulls)}) + ckey, _ := delivery.CandidatesKey("fix/1126") + b.kv[delivery.CandidatesBucket+"/"+ckey] = raw + env := b.env() + var tick atomic.Int64 + env.Now = func() time.Time { return time.Unix(0, 0).Add(time.Duration(tick.Add(1)) * time.Second) } + s := NewShadow(env, nil) + s.c.placements["n1"] = delivery.Placement{Node: "n1", Decided: delivery.NodeDecided{Hub: true, Address: "10.77.0.1"}, + Modules: []delivery.PlacedModule{{Module: "lemurs"}}} + s.c.records["n1"] = delivery.NodeRecord{Node: "n1", TunnelKey: "k", SealingKey: "sk", Capabilities: []string{"systemd"}} + s.c.modules["lemurs"] = delivery.Module{FP2: fp, Manifest: digest, Repository: "novox/x", Commit: "c"} + s.c.modules["other"] = delivery.Module{FP2: fp, Manifest: digestOther, Repository: "novox/x", Commit: "c"} + s.ready.Store(true) + key, _ := delivery.CompositionKey("fix/1126", heads) + return s, key + } + readsOf := func(b *fakeBus, key string) (n int) { + b.mu.Lock() + defer b.mu.Unlock() + for _, r := range b.reads { + if r == [2]string{delivery.ManifestsBucket, key} { + n++ + } + } + return n + } + saidLast := func(b *fakeBus) string { + b.mu.Lock() + defer b.mu.Unlock() + if len(b.said) == 0 { + return "" + } + return b.said[len(b.said)-1] + } + + for _, tc := range []struct { + name string + // stuck: the read of other's manifest does not answer until the ask's bound ends. + stuck bool + asks int + verdict string + reads int // of other's manifest, over every ask + words string // in the answer's words + said string // in the line said of the last answer + }{ + {name: "one ask reads each manifest once", asks: 1, verdict: delivery.ComposeCandidateComposed, reads: 1, + said: "compose-candidate fix/1126."}, + {name: "a later ask reads none again", asks: 2, verdict: delivery.ComposeCandidateComposed, reads: 1, + said: "read(s) waited on"}, + {name: "a read that does not answer is named at the bound", stuck: true, asks: 1, verdict: delivery.ComposeCandidateUnready, + words: "waits on", said: "answered unready"}, + } { + t.Run(tc.name, func(t *testing.T) { + b := newFakeBus() + s, key := shadow(b) + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + if tc.stuck { + get := s.c.env.Get + s.c.env.Get = func(rctx context.Context, bucket, k string) ([]byte, error) { + if bucket == delivery.ManifestsBucket && k == otherKey { + b.mu.Lock() + b.reads = append(b.reads, [2]string{bucket, k}) + b.mu.Unlock() + cancel() // the ask's bound ends while the read waits + <-rctx.Done() + return nil, rctx.Err() + } + return get(rctx, bucket, k) + } + } + var a delivery.ComposeCandidateAnswer + for range tc.asks { + a = s.ComposeCandidate(ctx, delivery.ComposeCandidateAsk{Candidate: key}) + } + if a.Verdict != tc.verdict || !strings.Contains(a.Refused, tc.words) { + t.Errorf("answered %s %q; want %s with %q", a.Verdict, a.Refused, tc.verdict, tc.words) + } + if tc.stuck && !strings.Contains(a.Refused, "manifest") { + t.Errorf("answered %q; want the manifest it waits on named", a.Refused) + } + if got := readsOf(b, otherKey); tc.reads > 0 && got != tc.reads { + t.Errorf("other's manifest was read %d time(s); want %d", got, tc.reads) + } + if line := saidLast(b); !strings.Contains(line, tc.said) { + t.Errorf("said %q; want a line with %q", line, tc.said) + } + }) + } +} diff --git a/internal/selfcompose/selfcompose.go b/internal/selfcompose/selfcompose.go index 41c4203..3019186 100644 --- a/internal/selfcompose/selfcompose.go +++ b/internal/selfcompose/selfcompose.go @@ -97,6 +97,8 @@ type Env struct { // ComposedState is this node's composition state `composed-` (novox/hq ADR 0593 §6), where every composition // a pass makes is published for its readers (publishComposed). Nil keeps none. ComposedState ComposedStore + // Now is the clock what the composer waits on is timed by; nil is time.Now. + Now func() time.Time } // VaultSecretChanged is the vault's event that a secret changed: a name and its generation, never a value. @@ -141,10 +143,16 @@ type Composer struct { held []string // doing is what the composer waits on now (waiting), for a running answer to say (issue 1126, T2); its own lock, so // it is read while c.mu is held. - doingMu sync.Mutex - doing string - caught bool - rev uint64 + doingMu sync.Mutex + doing string + doingSince time.Time + // waits is what the composer waited on, under doingMu: for compose-candidate's line (issue 1126). + waits waitLog + // origin is the composer a scratch copy was taken of (scratch): what is read once by its digest or key and never + // changes (a manifest, a templates archive, a done build) is kept there too, so the next copy reads it no more. + origin *Composer + caught bool + rev uint64 // missed counts the reads the bus did not answer (BusFailed), for a pass or an answer to tell whether it met one: // a read that failed on the bus is tried again after a bound, never kept as an answer (issue 1126, 2026-10-28). missed atomic.Uint64 @@ -1060,19 +1068,56 @@ func (c *Composer) keepRunning(comp delivery.Composed, running []delivery.Compos return delivery.KeepSeals(comp, kept, c.sameValue) } -// waiting notes what the composer waits on until the returned func is called, which restores what it waited on before. +// waitLog is what a composer waited on: how many waits ended, the longest and what it was, and the last. +type waitLog struct { + n int + longest time.Duration + longestOn string + lastOn string +} + +// now is the composer's clock (Env.Now). +func (c *Composer) now() time.Time { + if c.env.Now != nil { + return c.env.Now() + } + return time.Now() +} + +// waiting notes what the composer waits on until the returned func is called, which restores what it waited on before +// and counts the wait, timed, in waits. func (c *Composer) waiting(what string) func() { + began := c.now() c.doingMu.Lock() - before := c.doing - c.doing = what + before, beforeSince := c.doing, c.doingSince + c.doing, c.doingSince = what, began c.doingMu.Unlock() return func() { + took := c.now().Sub(began) c.doingMu.Lock() - c.doing = before + c.doing, c.doingSince = before, beforeSince + c.waits.n++ + c.waits.lastOn = what + if took > c.waits.longest || c.waits.longestOn == "" { + c.waits.longest, c.waits.longestOn = took, what + } c.doingMu.Unlock() } } +// keepRead keeps, in c and in the composer c is a scratch copy of, what set writes: a read that never changes for its +// digest or key. Each under its own lock, one after the other. +func (c *Composer) keepRead(set func(*Composer)) { + c.mu.Lock() + set(c) + c.mu.Unlock() + if o := c.origin; o != nil { + o.mu.Lock() + set(o) + o.mu.Unlock() + } +} + // waitingOn is what the composer waits on now, in words. func (c *Composer) waitingOn() string { c.doingMu.Lock() @@ -1303,9 +1348,7 @@ func (r reader) Manifest(ctx context.Context, digest string) ([]byte, error) { if err != nil { return nil, err } - r.c.mu.Lock() - r.c.manifests[digest] = []byte(m.JSON) - r.c.mu.Unlock() + r.c.keepRead(func(k *Composer) { k.manifests[digest] = []byte(m.JSON) }) return []byte(m.JSON), nil } @@ -1330,9 +1373,7 @@ func (r reader) Build(ctx context.Context, module, fp string) (*delivery.Builder return nil, fmt.Errorf("the builder's %s: %w", key, err) } if b.State == delivery.BuildDone { - r.c.mu.Lock() - r.c.builds[key] = b - r.c.mu.Unlock() + r.c.keepRead(func(k *Composer) { k.builds[key] = b }) } return &b, nil } @@ -1363,9 +1404,7 @@ func (r reader) Archive(ctx context.Context, url, digest string) ([]byte, error) if got := "sha256:" + hex.EncodeToString(sum[:]); got != digest { return nil, fmt.Errorf("%s was recorded as %s and what arrived is %s", url, digest, got) } - r.c.mu.Lock() - r.c.archives[digest] = body - r.c.mu.Unlock() + r.c.keepRead(func(k *Composer) { k.archives[digest] = body }) return body, nil }