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

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.

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

internal/selfcompose/selfcompose.go

@@ -97,6 +97,8 @@ type Env struct {
 	// ComposedState is this node's composition state `composed-<node>` (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
 }