novox/mesh-controller
18
0
Fork 0
Code Issues Pull Requests 4 Releases Wiki Activity

Merge pull request 'Keep a build's outcome off the controller's event loop when the plans are busy, so a slow send no longer leaves the controller deaf (issue 1708)' (#421) from fix/1708-listening into main

Browse Source
This commit was merged in pull request #421.
This commit is contained in:
mesh-tools
2026-10-21 13:33:59 +00:00
parent f10fbda1f6 0e0c775bfa
commit 98ffcb667f
8 changed files with 497 additions and 8 deletions
Download Patch File Download Diff File Expand all files Collapse all files
cmd/mesh-controller/outcome_off_the_loop_test.go
+198
View File
@@ -0,0 +1,198 @@
package main
import (
"context"
"strings"
"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)
}
}
// 1708/AC5: given a serving controller (its look at the plans running), when an outcome was taken into the plans,
// then moving them (a release's sends, which may retry for minutes) is left to the look, off the event loop
// (2026-10-21 14:28:40 to 14:32:10: the loop sent okioki's release to g14 after mesh-delivery-builder's outcome).
func TestAnOutcomeLeavesMovingThePlansToTheLook(t *testing.T) {
l := withLooker(t)
moved := false
advanceAfterOutcome(func() { moved = true })
if moved {
t.Fatal("the plans were moved on the event loop after an outcome, where a send that retries holds every message")
}
select {
case <-l.signal:
default:
t.Fatal("the look was not asked to move the plans after an outcome")
}
}
// 1708/AC5: given no look running (a command, which has no event loop), when an outcome was taken, then the plans are
// moved at once, as before.
func TestAnOutcomeMovesThePlansWhereNoLookRuns(t *testing.T) {
lookerMu.Lock()
before := theLooker
theLooker = nil
lookerMu.Unlock()
t.Cleanup(func() {
lookerMu.Lock()
theLooker = before
lookerMu.Unlock()
})
moved := false
advanceAfterOutcome(func() { moved = true })
if !moved {
t.Fatal("with no look running, an outcome left the plans unmoved")
}
}
// 1708/AC6: given a registration the mesh refused (its build recorded as worked, the outcome failed), left to the
// records because the plans were held, when the look settles the plan from the records, then the module and the plan
// are failed, never built: settled as built, the tier would be sent the version from before (reviewer-1708@shanks).
func TestARefusedRegistrationLeftToTheRecordsFailsThePlan(t *testing.T) {
withLooker(t)
asked := time.Date(2026, 10, 21, 12, 15, 0, 0, time.UTC)
p := inventory.Plan{ID: "plan-1708-ac6", State: inventory.PlanBuilding, Tiers: [][]string{{"nodered"}},
Modules: map[string]*inventory.PlanModule{"nodered": {State: "asked", AskedAt: &asked, Build: "build-1708-ac6"}}}
byID := map[string]inventory.Build{"build-1708-ac6": {ID: "build-1708-ac6", Module: "nodered", Commit: "4efac366",
At: asked.Add(5 * time.Minute)}}
leaveToRecords("nodered", "build-1708-ac6", "", "the mesh does not register it: a port is taken", inventory.ErrPlansBusy)
overlayRefusals(nil, byID, refusalsKeptFor([]string{"build-1708-ac6"}))
settleFromRecords(&p, p.Tiers[0], nil, byID)
if s := p.Modules["nodered"]; s.State != "failed" || p.State != inventory.PlanFailed {
t.Fatalf("a refused registration left to the records settled as %q, the plan %q", s.State, p.State)
}
if !strings.Contains(p.Modules["nodered"].Why, "a port is taken") {
t.Fatalf("the refusal's words were lost: %q", p.Modules["nodered"].Why)
}
}
// 1708/AC6: a refusal kept in the store (a controller replaced before the settle) fails the record as one kept in
// the process does.
func TestARefusalFromTheStoreFailsTheRecord(t *testing.T) {
recorded := map[string][]inventory.Build{"nodered": {{ID: "b-store", Module: "nodered"}, {ID: "b-other", Module: "nodered"}}}
byID := map[string]inventory.Build{"b-store": {ID: "b-store", Module: "nodered"}}
overlayRefusals(recorded, byID, map[string]string{"b-store": "not registered"})
if recorded["nodered"][0].Worked() || byID["b-store"].Worked() {
t.Fatal("a build whose registration was refused still reads as worked")
}
if !recorded["nodered"][1].Worked() {
t.Fatal("a build nobody refused was failed")
}
}
// 1708/AC7: given the records settle a module as deleted at its source, or fail the plan, when the look settles, then
// it does what taking the outcome directly does: the deleted module is named to be forgotten, and the plan's failure
// is said (reviewer-1708@shanks).
func TestSettlingFromTheRecordsDoesWhatTakingTheOutcomeDoes(t *testing.T) {
p := inventory.Plan{State: inventory.PlanFailed, Modules: map[string]*inventory.PlanModule{
"gone": {State: planDeleted}, "x": {State: "failed"}, "y": {State: "built"}}}
before := map[string]string{"gone": "asked", "x": "asked", "y": "built"}
deleted, failed := settledEffects(before, &p, inventory.PlanBuilding)
if len(deleted) != 1 || deleted[0] != "gone" {
t.Fatalf("the module the records found deleted is not forgotten: %v", deleted)
}
if !failed {
t.Fatal("the plan the records failed is not said as failed")
}
if d, f := settledEffects(map[string]string{"gone": planDeleted}, &p, inventory.PlanFailed); len(d) != 0 || f {
t.Fatalf("what was deleted or failed before the settle is acted on again: %v %v", d, f)
}
}
cmd/mesh-controller/plan_looks.go
+12
View File
@@ -136,6 +136,18 @@ func askToLook() {
}
}
// askedToLook asks the serving controller's look at the plans, and says whether there was one to ask.
func askedToLook() bool {
lookerMu.RLock()
l := theLooker
lookerMu.RUnlock()
if l == nil {
return false
}
l.ask()
return true
}
// startPlanLooks starts the look at the open plans, and asks for the first: the controller took the lease, and a
// plan left by a replaced controller resumes from there (ADR 0406 §6). It replaces the rollout's 30 second ticker.
// It answers a channel that is closed once the look has returned after the context ended, for a test that restores what
cmd/mesh-controller/release_plan.go
+212 -6
View File
@@ -625,16 +625,124 @@ 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, failed 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())
// A refused outcome (failed, its build recorded as worked) is kept as refused, or the records settle it built.
keepRefusalFor(id, failed, time.Now())
askToLook()
}
// refusalsKeptFor is the refusals kept in this process for these builds (keepRefusalFor), by id.
func refusalsKeptFor(ids []string) map[string]string {
out := map[string]string{}
refusedLeftMu.Lock()
defer refusedLeftMu.Unlock()
for _, id := range ids {
if k, ok := refusedLeft[id]; ok {
out[id] = k.made
}
}
return out
}
// refusedLeft is why each outcome left to the records was refused, by the build's id: kept in the process beside the
// store's record (RecordRefused), so a store that did not take it still fails the plan while this controller serves.
var (
refusedLeftMu sync.Mutex
refusedLeft = map[string]madeKept{}
)
// keepRefusalFor keeps why an outcome left to the records was refused, forgetting refusals older than madeLeftFor.
func keepRefusalFor(id, why string, now time.Time) {
if id == "" || why == "" {
return
}
refusedLeftMu.Lock()
defer refusedLeftMu.Unlock()
for k, v := range refusedLeft {
if now.Sub(v.at) > madeLeftFor {
delete(refusedLeft, k)
}
}
refusedLeft[id] = madeKept{made: why, at: now}
}
// 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)
if failed != "" && id != "" && errors.Is(err, inventory.ErrPlansBusy) {
// In the store too, so a controller replaced before the look settles still fails the plan (issue 1708).
if err := inv.RecordRefused(ctx, id, module, failed); err != nil {
fmt.Printf("plans: %s's refusal could not be kept in the store, only in this controller: %v\n", module, err)
}
}
leaveToRecords(module, id, made, failed, err)
return
}
defer release()
@@ -696,7 +804,19 @@ func planBuiltSaying(ctx context.Context, open *stores, module, commit, failed s
fmt.Printf("%s: %s; the tiers after it are not asked\n", p.ID, p.Note)
}
}
advanceHeld(ctx, open)
advanceAfterOutcome(func() { advanceHeld(ctx, open) })
}
// advanceAfterOutcome moves the plans after an outcome was taken into them: **in the serving controller, by asking
// the look** (novox/hq issue 1708). The outcome is taken on the event loop, and moving the plans may send machines
// their declarations, a release's send retried for minutes among them; done here it held every report, build and
// merge behind it (2026-10-21 14:28:40 to 14:32:10). The look runs off the loop, holding the plans itself. Where no
// look runs (a command, which has no event loop) the plans are moved at once, as before.
func advanceAfterOutcome(advance func()) {
if askedToLook() {
return
}
advance()
}
// startedBeside is the id of a started walk open beside this one that it is related to — a merge's walk past
@@ -921,7 +1041,17 @@ func advanceOnce(ctx context.Context, open *stores, p *inventory.Plan,
if err != nil {
return false, err
}
before, was := statesOf(p), p.State
if settleFromRecords(p, tier, recorded, byID) {
// As taking the outcome directly does (planBuiltSaying): a module deleted at its source is forgotten, and a
// failed plan says what it built and never sent (issue 1708).
deleted, failed := settledEffects(before, p, was)
for _, m := range deleted {
forgetDeleted(ctx, inv, m, p)
}
if failed {
sayUnsent(p, rollsOut)
}
return true, nil
}
// Asked: wait for every build.
@@ -2479,9 +2609,81 @@ func recordsOfAsked(ctx context.Context, inv *inventory.Inventory, p *inventory.
}
}
}
refused, err := refusalsOf(ctx, inv, recorded, byID)
if err != nil {
return nil, nil, err
}
overlayRefusals(recorded, byID, refused)
return recorded, byID, nil
}
// overlayRefusals marks failed every build record whose registration the mesh refused (novox/hq issue 1708): the record
// keeps the builder's words, which worked, and settled from it as it is the refused build would be built and sent.
func overlayRefusals(recorded map[string][]inventory.Build, byID map[string]inventory.Build, refused map[string]string) {
if len(refused) == 0 {
return
}
fail := func(b *inventory.Build) {
if why, ok := refused[b.ID]; ok && b.Worked() {
b.Failed = why
}
}
for m := range recorded {
for i := range recorded[m] {
fail(&recorded[m][i])
}
}
for id, b := range byID {
fail(&b)
byID[id] = b
}
}
// refusalsOf is every refusal kept for the builds these records name, in the store and in this process.
func refusalsOf(ctx context.Context, inv *inventory.Inventory, recorded map[string][]inventory.Build,
byID map[string]inventory.Build) (map[string]string, error) {
var ids []string
for _, bs := range recorded {
for _, b := range bs {
ids = append(ids, b.ID)
}
}
for id := range byID {
ids = append(ids, id)
}
refused, err := inv.RefusedOf(ctx, ids)
if err != nil {
return nil, fmt.Errorf("the refused registrations cannot be read: %w", err)
}
for id, why := range refusalsKeptFor(ids) {
refused[id] = why
}
return refused, nil
}
// settledEffects is what settling from the records did that needs more than the plan: the modules it found deleted
// at their source, and whether it failed the plan.
func settledEffects(before map[string]string, p *inventory.Plan, was string) (deleted []string, failed bool) {
for m, s := range p.Modules {
if s != nil && s.State == planDeleted && before[m] != planDeleted {
deleted = append(deleted, m)
}
}
sort.Strings(deleted)
return deleted, p.State == inventory.PlanFailed && was != inventory.PlanFailed
}
// statesOf is each module's state in a plan, for settledEffects.
func statesOf(p *inventory.Plan) map[string]string {
out := map[string]string{}
for m, s := range p.Modules {
if s != nil {
out[m] = s.State
}
}
return out
}
// settleFromRecords marks every module of the tier still `asked` built — or failed — from a build
// recorded after it was asked, and says whether it changed anything (novox/hq 04-ISSUES/214).
// Newest first, as Builds answers: the first record after the ask is the outcome of that ask.
@@ -2531,6 +2733,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
internal/inventory/hold.go
+3 -2
View File
@@ -100,8 +100,9 @@ var ErrPlansBusy = errors.New("another controller is working the plans")
// returned function and by the session ending, so a controller that dies holding it holds nothing.
//
// wait false gives ErrPlansBusy at once when another holds them — the timer's way: the holder is
// moving the plans already. wait true looks again every HoldPoll for up to HoldWaitFor — an
// outcome's or a merge's way, which must be written.
// moving the plans already; and a build outcome's on the event loop, which the build records keep
// for the look to settle (novox/hq issue 1708). wait true looks again every HoldPoll for up to
// HoldWaitFor — a merge's way, which must be written.
func (i *Inventory) HoldPlans(ctx context.Context, wait bool) (func(), error) {
deadline := time.Now().Add(HoldWaitFor)
for {
internal/inventory/migrations/0107-a-refused-registration-is-kept.sql
+10
View File
@@ -0,0 +1,10 @@
-- A build's outcome whose registration the mesh refused, by the build's id (novox/hq issue 1708). The build record says
-- what the builder said, which worked; an outcome the event loop could not take into the plans (another act held them)
-- is settled from the records by the look, and without this it would read the refused build as built. Kept in the
-- store so a controller replaced before the settle still fails the plan.
create table build_refused (
id text primary key,
module text not null,
why text not null,
at timestamptz not null default now()
);
internal/inventory/refused.go
+33
View File
@@ -0,0 +1,33 @@
package inventory
import "context"
// RecordRefused keeps that the mesh refused to register a build's outcome, and why (novox/hq issue 1708): the build
// record says the builder's words, which worked, and the look that settles a plan from the records reads this to fail
// it instead. The first refusal of an id stands.
func (i *Inventory) RecordRefused(ctx context.Context, id, module, why string) error {
_, err := i.store.Pool().Exec(ctx,
`insert into build_refused (id, module, why) values ($1, $2, $3) on conflict (id) do nothing`, id, module, why)
return err
}
// RefusedOf is why each of these builds' registration was refused, by id; a build not refused is absent.
func (i *Inventory) RefusedOf(ctx context.Context, ids []string) (map[string]string, error) {
out := map[string]string{}
if len(ids) == 0 {
return out, nil
}
rows, err := i.store.Pool().Query(ctx, `select id, why from build_refused where id = any($1)`, ids)
if err != nil {
return nil, err
}
defer rows.Close()
for rows.Next() {
var id, why string
if err := rows.Scan(&id, &why); err != nil {
return nil, err
}
out[id] = why
}
return out, rows.Err()
}
internal/inventory/refused_test.go
+28
View File
@@ -0,0 +1,28 @@
//go:build integration
package inventory
import "testing"
// novox/hq issue 1708 (1708/AC6): a refused registration is kept by its build's id, the first refusal standing, and
// read back for the builds asked about only.
func TestARefusedRegistrationIsKeptByItsBuild(t *testing.T) {
inv := ForTest(t)
ctx := t.Context()
if err := inv.RecordRefused(ctx, "build-1708-a", "nodered", "a port is taken"); err != nil {
t.Fatal(err)
}
if err := inv.RecordRefused(ctx, "build-1708-a", "nodered", "said again"); err != nil {
t.Fatalf("a refusal said twice was refused: %v", err)
}
got, err := inv.RefusedOf(ctx, []string{"build-1708-a", "build-1708-b"})
if err != nil {
t.Fatal(err)
}
if len(got) != 1 || got["build-1708-a"] != "a port is taken" {
t.Fatalf("the refusals read back are %v", got)
}
if none, err := inv.RefusedOf(ctx, nil); err != nil || len(none) != 0 {
t.Fatalf("no builds asked about answered %v %v", none, err)
}
}
testdata/store-tests
Vendored
+1
View File
@@ -167,3 +167,4 @@
./cmd/mesh-controller TestAMergeOnTheApproveIntoANewRepositoryAsksTheFirstBuildAndItsOutcomeRegistersTheModule
./cmd/mesh-controller TestTheApprovedFirstBuildPassesTheGuardOfAVerbAndIsQueued
./cmd/mesh-controller TestAPlanGoesOnWithoutAMachineAwayWhenItsTierIsSent
./internal/inventory TestARefusedRegistrationIsKeptByItsBuild