Take a build's outcome on the event loop without waiting for the plans, and leave it to the build records with a look asked, so a holder sending for minutes no longer stops the controller listening (issue 1708)

2026-10-21 14:33:09 +02:00
parent f10fbda1f6
commit c24139a0fd
3 changed files with 183 additions and 7 deletions
@@ -0,0 +1,106 @@
+package main
+
+import (
+	"context"
+	"testing"
+	"time"
+
+	"github.com/novox/mesh-controller/internal/inventory"
+)
+
+// heldElsewhere is the plans held by another act for longer than any test runs: waiting for them ends only with the
+// context, and a look that does not wait is told at once that they are busy.
+func heldElsewhere(ctx context.Context, wait bool) (func(), error) {
+	if !wait {
+		return nil, inventory.ErrPlansBusy
+	}
+	<-ctx.Done()
+	return nil, inventory.ErrPlansBusy
+}
+
+// 1708/AC1: given the plans held by another act, when the event loop takes a build's outcome, then it returns at
+// once, without waiting the plans' two minutes (on 2026-10-21 at 14:20:45 nodered's outcome held the loop until
+// 14:22:45, and the operator was told the controller stopped listening).
+func TestAnOutcomeDoesNotWaitForThePlansAnotherActHolds(t *testing.T) {
+	ctx, cancel := context.WithTimeout(t.Context(), 3*time.Second)
+	defer cancel()
+	start := time.Now()
+	release, err := holdPlansForOutcome(ctx, heldElsewhere)
+	if took := time.Since(start); took > time.Second {
+		t.Fatalf("taking an outcome waited %s for plans another act holds; the event loop takes nothing meanwhile", took)
+	}
+	if err == nil || release != nil {
+		t.Fatalf("plans another act holds were said to be held: release %v, err %v", release != nil, err)
+	}
+}
+
+// 1708/AC4: given the plans free, when the event loop takes a build's outcome, then it holds them and marks the plan
+// from the outcome directly, as before.
+func TestAnOutcomeHoldsThePlansWhenTheyAreFree(t *testing.T) {
+	let := false
+	release, err := holdPlansForOutcome(t.Context(), func(context.Context, bool) (func(), error) {
+		return func() { let = true }, nil
+	})
+	if err != nil || release == nil {
+		t.Fatalf("free plans were not held: %v", err)
+	}
+	release()
+	if !let {
+		t.Fatal("the hold given was not the one taken")
+	}
+}
+
+// withLooker installs a looker that is never run, and answers it, so a test can read whether a look was asked.
+func withLooker(t *testing.T) *looker {
+	t.Helper()
+	l := newLooker(func(context.Context) bool { return false })
+	lookerMu.Lock()
+	before := theLooker
+	theLooker = l
+	lookerMu.Unlock()
+	t.Cleanup(func() {
+		lookerMu.Lock()
+		theLooker = before
+		lookerMu.Unlock()
+	})
+	return l
+}
+
+// 1708/AC2: given an outcome left to the build records because the plans were held, when it is left, then the look
+// at the plans is asked for, so the records settle it once the holder lets go rather than at the next event.
+func TestAnOutcomeLeftToTheRecordsAsksForTheLook(t *testing.T) {
+	l := withLooker(t)
+	leaveToRecords("nodered", "build-1708-ac2", "", inventory.ErrPlansBusy)
+	select {
+	case <-l.signal:
+	default:
+		t.Fatal("an outcome left to the build records asked for no look: the plan waits for whatever event comes next")
+	}
+}
+
+// 1708/AC3: given an outcome left to the records that said what the build did (ADR 0350 §4), when the look settles
+// the plan from the build records by that build's id, then the module keeps those words, once.
+func TestTheRecordsSettleAnOutcomeWithWhatTheBuildDid(t *testing.T) {
+	withLooker(t)
+	asked := time.Date(2026, 10, 21, 12, 15, 0, 0, time.UTC)
+	plan := func() inventory.Plan {
+		return inventory.Plan{ID: "plan-1708", Tiers: [][]string{{"nodered"}},
+			Modules: map[string]*inventory.PlanModule{"nodered": {State: "asked", AskedAt: &asked, Build: "build-1708-ac3"}}}
+	}
+	byID := map[string]inventory.Build{"build-1708-ac3": {ID: "build-1708-ac3", Module: "nodered", Commit: "4efac366",
+		At: asked.Add(5 * time.Minute)}}
+	leaveToRecords("nodered", "build-1708-ac3", "reused from build-1708-check", inventory.ErrPlansBusy)
+
+	p := plan()
+	if !settleFromRecords(&p, p.Tiers[0], nil, byID) || p.Modules["nodered"].State != "built" {
+		t.Fatalf("the records did not settle the outcome: %+v", p.Modules["nodered"])
+	}
+	if got := p.Modules["nodered"].Made; got != "reused from build-1708-check" {
+		t.Fatalf("settled from the records, the module says %q of what its build did, not the outcome's words", got)
+	}
+	again := plan()
+	settleFromRecords(&again, again.Tiers[0], nil, byID)
+	if got := again.Modules["nodered"].Made; got != "" {
+		t.Fatalf("an outcome's words were kept for a second settle: %q", got)
+	}
+}
@@ -625,16 +625,81 @@ func planBuilt(ctx context.Context, open *stores, module, commit, failed string,
 	planBuiltSaying(ctx, open, module, commit, failed, asked, id, "")
 }

+// holdPlansForOutcome is how an outcome taken on the event loop holds the plans: **without waiting for them**
+// (novox/hq issue 1708). The loop takes one message at a time, and the plans' holder may keep them for minutes while
+// it sends machines their declarations; an outcome that waited its turn (up to inventory.HoldWaitFor, two minutes)
+// held every report, build and merge behind it for as long, and the watchdog said the controller stopped listening
+// (2026-10-21 14:20:45 to 14:22:45). Busy, the outcome is left to the build records, where it already is, and the
+// look settles the plan from them (leaveToRecords).
+func holdPlansForOutcome(ctx context.Context, hold func(context.Context, bool) (func(), error)) (func(), error) {
+	return hold(ctx, false)
+}
+
+// leaveToRecords says an outcome was not taken into the plans, which settle it from the build records (novox/hq issue
+// 214). When another act holds the plans it asks for the look, which waits for them off the event loop and settles
+// the plan from the records once they are let go (issue 1708); what the build did is kept for that settle by the
+// build's id, so the walk's module says it as it would have (ADR 0350 §4).
+func leaveToRecords(module, id, made string, err error) {
+	fmt.Printf("plans: %s's outcome is left to the build records: %v\n", module, err)
+	if !errors.Is(err, inventory.ErrPlansBusy) {
+		return
+	}
+	keepMadeFor(id, made, time.Now())
+	askToLook()
+}
+
+// madeLeft is what each build left to the records did, by the build's id, until a settle takes it: kept in the
+// process, so a controller replaced before the settle loses only these words, never the outcome.
+var (
+	madeLeftMu sync.Mutex
+	madeLeft   = map[string]madeKept{}
+)
+
+type madeKept struct {
+	made string
+	at   time.Time
+}
+
+// madeLeftFor is how long words nobody settled are kept: a plan that ended or moved on never asks for them.
+const madeLeftFor = time.Hour
+
+// keepMadeFor keeps what a build left to the records did for the settle that takes it, forgetting words older than
+// madeLeftFor.
+func keepMadeFor(id, made string, now time.Time) {
+	if id == "" || made == "" {
+		return
+	}
+	madeLeftMu.Lock()
+	defer madeLeftMu.Unlock()
+	for k, v := range madeLeft {
+		if now.Sub(v.at) > madeLeftFor {
+			delete(madeLeft, k)
+		}
+	}
+	madeLeft[id] = madeKept{made: made, at: now}
+}
+
+// takeMadeOf is what the build of this id did, if its outcome was left to the records with words; taken once.
+func takeMadeOf(id string) string {
+	madeLeftMu.Lock()
+	defer madeLeftMu.Unlock()
+	k, ok := madeLeft[id]
+	if !ok {
+		return ""
+	}
+	delete(madeLeft, id)
+	return k.made
+}
+
 // planBuiltSaying is planBuilt keeping what the build did — "reused from <check build>" or "built: <why>" (novox/hq
 // ADR 0350 §4) — on the module of the walk it answers.
 func planBuiltSaying(ctx context.Context, open *stores, module, commit, failed string, asked time.Time, id, made string) {
 	inv := open.inventory
-	// One controller works the plans at a time (novox/hq issue 213); an outcome waits its turn rather
-	// than write over what the holder is about to save. Not taken, it is still in the build records,
-	// which the holder settles the plan from (issue 214).
-	release, err := inv.HoldPlans(ctx, true)
+	// One controller works the plans at a time (novox/hq issue 213). Not taken, the outcome is still in the build
+	// records, which the holder settles the plan from (issue 214).
+	release, err := holdPlansForOutcome(ctx, inv.HoldPlans)
 	if err != nil {
-		fmt.Printf("plans: %s's outcome is left to the build records: %v\n", module, err)
+		leaveToRecords(module, id, made, err)
 		return
 	}
 	defer release()
@@ -2531,6 +2596,10 @@ func settleFromRecords(p *inventory.Plan, tier []string, recorded map[string][]i
 			s.State = "built"
 			s.BuiltAt = &at
 			s.Commit = outcome.Commit
+			// What the build did, when its outcome was left to the records with words (issue 1708).
+			if made := takeMadeOf(outcome.ID); made != "" {
+				s.Made = made
+			}
 		} else {
 			s.State = "failed"
 			s.Why = outcome.Failed