The builder takes a retakeable failure again after a backoff, at most three times, the count kept on the key (issue 1748)

A name lookup that timed out passes by itself, but nothing fired for the key after its failure, so it stayed failed until a person built it again. Claude-Session: https://claude.ai/code/session_01JG73KJNrH5EgFXMKKYSrig
2026-11-04 22:30:22 +01:00
parent ae31b66a9e
commit d134b8dfec
5 changed files with 253 additions and 3 deletions
@@ -62,6 +62,8 @@ type fakeBuildModules struct {
 	js        jetstream.JetStream
 	ctx       context.Context
 	failBuild atomic.Bool
+	// failRetakeable makes every build fail as a lookup that timed out (delivery.Retake), which passes by itself.
+	failRetakeable atomic.Bool
 	// refusePush makes every bundle and archive build fail as a push the artifact store refused (ADR 0498 clause 2).
 	refusePush atomic.Bool
 	mu         sync.Mutex
@@ -117,6 +119,8 @@ func (f *fakeBuildModules) step(module, name string, args map[string]any) (any,
 			merge = `,"merge":"` + strings.Repeat("9", 40) + `"`
 		}
 		return json.RawMessage(`{"workspace":"w` + buildstep.NewID() + `","commit":"` + commit + `"` + merge + `}`), nil
+	case f.failRetakeable.Load() && tool != "build_image_copy":
+		return nil, fmt.Errorf("%slookup git.novox.be on 10.10.0.3:53: i/o timeout", delivery.Retake)
 	case f.failBuild.Load() && tool != "build_image_copy": // the build fails wherever it runs
 		return nil, fmt.Errorf("go build of %v: boom", args["artifact"])
 	case tool == "build_image_copy": // the upstream copy answers the digest and the registry's reference (ADR 0498 clause 4)
@@ -517,6 +521,23 @@ func TestAFailedKeyIsBuiltAgainAsANewRevisionFromANewModulesValueWithTheSameFing
 	}
 }

+// 1748/AC6: a build failed retakeable is built again after its backoff, with no new modules value or other event, and ends
+// done; the key says it was retaken once.
+func TestARetakeableFailureIsBuiltAgainAfterItsBackoffAndEndsDone(t *testing.T) {
+	b := startBed(t)
+	b.fake.failRetakeable.Store(true)
+	b.archive(t, "ca-trust", "modules/ca-trust", commit)
+	b.start(t, "n1", map[string]string{"MESH_BUILDER_RETAKE_BACKOFF": "300ms"})
+	if v := b.await(t, "ca-trust", func(v delivery.BuilderBuild) bool { return v.State == delivery.BuildFailed }); !delivery.Retakeable(v.Error) {
+		t.Fatalf("build = %+v, want failed retakeable", v)
+	}
+	b.fake.failRetakeable.Store(false) // the lookup passes
+	v := b.await(t, "ca-trust", isState(delivery.BuildDone))
+	if v.Retakes < 1 {
+		t.Errorf("done key = %+v, want its retake counted", v)
+	}
+}
+
 // TestAToolchainChangeDoesNotBuildTheOldFingerprint: the fingerprint names go1.27.1, the nodes then agree on go1.27.2 (a
 // report of both nodes), and the builder writes no key for the old fingerprint although it was woken by the report; a
 // module value naming go1.27.2 (the new fingerprint, computed by the indexer) is built.
@@ -77,6 +77,12 @@ func run(ctx context.Context, getenv func(string) string, logOut io.Writer) erro
 			return fmt.Errorf("MESH_BUILDER_STEP_BOUND: %w", err)
 		}
 	}
+	var retakeBackoff time.Duration // 0 is build.DefaultRetakeBackoff
+	if v := strings.TrimSpace(getenv("MESH_BUILDER_RETAKE_BACKOFF")); v != "" {
+		if retakeBackoff, err = time.ParseDuration(v); err != nil {
+			return fmt.Errorf("MESH_BUILDER_RETAKE_BACKOFF: %w", err)
+		}
+	}
 	tools := &buildrun.ToolchainSet{}
 	// Each build module's part of a build is an ask on its build seat's stream, pulled by a build node with a free slot
 	// (novox/hq ADR 0525): the builder chooses no node, so it reads neither presence nor have and holds no capacity.
@@ -121,6 +127,8 @@ func run(ctx context.Context, getenv func(string) string, logOut io.Writer) erro
 		Logf:       logger.Printf,
 		Stored:     storedVia(calls.Call),
 		Node:       cred.Node,
+		// A key failed retakeable (delivery.Retake) is taken again by itself after this wait, at most delivery.MaxRetakes times (issue 1748).
+		RetakeBackoff: retakeBackoff,
 	}
 	// A candidate's preview is merged onto the trunk head the indexer previewed it onto: source.main at the candidate's base
 	// revision (the gate's source state). The source's revisions are watched with their history (a direct get of one revision
@@ -153,7 +153,8 @@ func Unreferenced(b delivery.BuilderBuild) bool {
 //   - a failed key is taken again as a new revision of the same key (ADR 0429 clause 18), except one failed for a kind no
 //     builder builds, for an upstream pinned by no digest or a package version taken (delivery.FailedUntilChanged: ADR 0478
 //     clause 2, ADR 0498 clauses 4 and 5) or for digests that differ (buildrun.DigestsDifferPrefix, clause 4),
-//     which wait for another fingerprint, and one failed for want of an image builder (NoImageBuilderPrefix), which waits for
+//     which wait for another fingerprint (a retakeable failure, delivery.Retakeable, is taken again too, and the new
+//     revision counts it in Retakes, which the builder's backoff reads: Builder.armRetake), and one failed for want of an image builder (NoImageBuilderPrefix), which waits for
 //     another fingerprint or a node that runs the image build module (ClaimOptions.ImageBuilder);
 //   - a key queued waiting for a package version (Waits) is claimed building as a new revision once that version is
 //     published (ClaimOptions.Published, ADR 0500 clause 6), and not before;
@@ -212,6 +213,9 @@ func (c Claimer) Claim(ctx context.Context, module, fingerprint, manifest string
 	case cur.State == delivery.BuildFailed && strings.HasPrefix(cur.Error, NoImageBuilderPrefix) && (opt.ImageBuilder == nil || !opt.ImageBuilder()):
 		return nil, nil
 	case cur.State == delivery.BuildFailed:
+		if delivery.Retakeable(cur.Error) {
+			building.Retakes = cur.Retakes + 1 // the count rides on the key's value, so it survives a restart (issue 1748)
+		}
 		return c.write(ctx, key, building, func(data []byte) (uint64, error) { return c.Store.Update(ctx, key, data, rev) })
 	case cur.State == delivery.BuildQueued && cur.Waits != "":
 		if opt.Published == nil || !opt.Published(cur.Waits) {
@@ -0,0 +1,147 @@
+package build
+
+import (
+	"context"
+	"fmt"
+	"strings"
+	"sync"
+	"testing"
+	"time"
+
+	"git.novox.be/novox/mesh-sdk/go/delivery"
+)
+
+// clock is the builder's fake clock for the retake backoff (issue 1748): After records what is asked and fire runs it.
+type clock struct {
+	mu      sync.Mutex
+	waits   []time.Duration
+	pending []func()
+}
+
+func (c *clock) after(d time.Duration, f func()) func() {
+	c.mu.Lock()
+	defer c.mu.Unlock()
+	c.waits, c.pending = append(c.waits, d), append(c.pending, f)
+	return func() {}
+}
+
+// fire runs every timer set so far, once, and answers how many there were.
+func (c *clock) fire() int {
+	c.mu.Lock()
+	fs := c.pending
+	c.pending = nil
+	c.mu.Unlock()
+	for _, f := range fs {
+		f()
+	}
+	return len(fs)
+}
+
+func retakeRig(t *testing.T) (*rig, *clock) {
+	r := newRig(t, goBundle)
+	c := &clock{}
+	r.b.RetakeBackoff, r.b.After = 10*time.Second, c.after
+	return r, c
+}
+
+const lookupFailure = delivery.Retake + "go mod download: lookup git.novox.be on 10.10.0.3:53: i/o timeout"
+
+// 1748/AC3: a key failed retakeable is claimed again as a new revision after its backoff, with no other event; the count
+// kept on the key stops it after delivery.MaxRetakes, and a builder that starts again reads the count.
+func TestARetakeableFailureIsTakenAgainAfterItsBackoffAtMostThreeTimes(t *testing.T) {
+	r, c := retakeRig(t)
+	r.bm.fails["ace/build_go_build"] = lookupFailure
+	v := r.consider(t, "modules/m")
+	if v.State != delivery.BuildFailed || !delivery.Retakeable(v.Error) || v.Retakes != 0 {
+		t.Fatalf("build = %+v, want failed retakeable with no retake yet", v)
+	}
+	if len(c.waits) != 1 || c.waits[0] != 10*time.Second {
+		t.Fatalf("backoffs = %v, want one of 10s", c.waits)
+	}
+	rev := r.st.revs[r.key]
+	for retake := 1; retake <= delivery.MaxRetakes; retake++ {
+		if c.fire() != 1 {
+			t.Fatalf("retake %d: no timer was set", retake)
+		}
+		r.b.Wait()
+		v = valueOf(t, r.st, r.key)
+		if v.Retakes != retake || r.st.revs[r.key] <= rev {
+			t.Fatalf("retake %d: key = %+v at revision %d (was %d)", retake, v, r.st.revs[r.key], rev)
+		}
+		rev = r.st.revs[r.key]
+	}
+	if len(c.pending) != 0 || len(c.waits) != delivery.MaxRetakes {
+		t.Fatalf("after %d retakes: %d timers pending, backoffs %v; want none pending and %d set", delivery.MaxRetakes, len(c.pending), c.waits, delivery.MaxRetakes)
+	}
+	if c.waits[1] != 20*time.Second || c.waits[2] != 40*time.Second {
+		t.Errorf("backoffs = %v, want each doubled", c.waits)
+	}
+	if len(r.bm.callsOf("build_go_build")) != 1+delivery.MaxRetakes {
+		t.Errorf("%d builds, want the first and %d retakes", len(r.bm.callsOf("build_go_build")), delivery.MaxRetakes)
+	}
+
+	// A builder that starts again reads the count from the key: at the cap it arms nothing, below it it arms the next wait.
+	restarted := func(retakes int) *clock {
+		rr, cc := retakeRig(t)
+		rr.st = r.st
+		rr.b.Claimer.Store = r.st
+		data, err := delivery.EncodeBuilderBuild(delivery.BuilderBuild{State: delivery.BuildFailed, Error: lookupFailure, Retakes: retakes})
+		if err != nil {
+			t.Fatal(err)
+		}
+		r.st.vals[r.key] = data
+		rr.b.init()
+		rr.b.known["m"] = delivery.Module{FP2: fp1, Manifest: mdigest('a')}
+		if err := rr.b.Sweep(context.Background()); err != nil {
+			t.Fatal(err)
+		}
+		return cc
+	}
+	if cc := restarted(delivery.MaxRetakes); len(cc.waits) != 0 {
+		t.Errorf("a key retaken %d times was armed again: %v", delivery.MaxRetakes, cc.waits)
+	}
+	if cc := restarted(1); len(cc.waits) != 1 || cc.waits[0] != 20*time.Second {
+		t.Errorf("a key retaken once was armed with %v, want one wait of 20s", cc.waits)
+	}
+}
+
+// 1748/AC4: a failure of the source (a compile error, FailedUntilChanged) is never taken again by the backoff.
+func TestAFailureOfTheSourceIsNeverTakenAgainByTheBackoff(t *testing.T) {
+	for _, reason := range []string{"go build of tool: undefined: x", delivery.NotPinned + "up: names no digest", delivery.VersionTaken + "@x/y@1 holds another file"} {
+		r, c := retakeRig(t)
+		r.bm.fails["ace/build_go_build"] = reason
+		v := r.consider(t, "modules/m")
+		if v.State != delivery.BuildFailed || delivery.Retakeable(v.Error) {
+			t.Fatalf("%q: build = %+v, want failed and not retakeable", reason, v)
+		}
+		if len(c.waits) != 0 || c.fire() != 0 {
+			t.Errorf("%q: the backoff was armed: %v", reason, c.waits)
+		}
+	}
+}
+
+// A retake is said in the builder's journal with its count, and the log's entry of the build's end names it.
+func TestARetakeIsSaidWithItsCountAndReachesTheLog(t *testing.T) {
+	r, c := retakeRig(t)
+	var said []string
+	r.b.Logf = func(f string, a ...any) { said = append(said, strings.TrimSpace(sprint(f, a...))) }
+	var ended []delivery.BuildLogEntry
+	r.b.Node, r.b.Log = "novox", func(e delivery.BuildLogEntry) {
+		if e.Event == delivery.BuildEndedEvent {
+			ended = append(ended, e)
+		}
+	}
+	r.bm.fails["ace/build_go_build"] = lookupFailure
+	r.consider(t, "modules/m")
+	c.fire()
+	r.b.Wait()
+	if len(ended) != 2 || ended[0].Retakes != 0 || ended[1].Retakes != 1 {
+		t.Fatalf("ended entries = %+v, want retakes 0 then 1; journal: %v", ended, said)
+	}
+	joined := strings.Join(said, "\n")
+	if !strings.Contains(joined, "taken again after its backoff (retake 1 of 3)") {
+		t.Errorf("the journal says %q, want the retake with its count", joined)
+	}
+}
+
+func sprint(f string, a ...any) string { return fmt.Sprintf(f, a...) }
@@ -79,6 +79,12 @@ type Builder struct {
 	// time.Now. Node is the node the builder runs on, which asked the build.
 	Now  func() time.Time
 	Node string
+	// RetakeBackoff is the wait before the builder takes a key that failed retakeable (delivery.Retakeable) again by itself,
+	// doubled with each retake (issue 1748): DefaultRetakeBackoff when 0. After runs f once d has passed and returns a
+	// stop; nil waits a context's bound (ADR 0437 §8: the builder holds no timer). The wait is re-armed from the key's value at
+	// start (Sweep): a build's work is not a message of the builder's own on a stream, so there is no delivery delay to ride.
+	RetakeBackoff time.Duration
+	After         func(d time.Duration, f func()) (stop func())

 	once     sync.Once
 	sem      chan struct{}
@@ -102,8 +108,13 @@ type Builder struct {
 	waiting map[string]map[string]chan string
 	// hands are the requests to build a key again by hand that wait for the claim and its asks (BuildAgain), by build key.
 	hands map[string]*handWatch
+	// armed are the keys with a retake timer running, by build key.
+	armed map[string]bool
 }

+// DefaultRetakeBackoff is the first wait before a retakeable failure is taken again; each retake doubles it.
+const DefaultRetakeBackoff = 30 * time.Second
+
 type planned struct {
 	plan Plan
 	err  error
@@ -120,6 +131,7 @@ func (b *Builder) init() {
 		b.known, b.inflight, b.again, b.plans, b.tried = map[string]delivery.Module{}, map[string]bool{}, map[string]delivery.Module{}, map[string]planned{}, map[string]bool{}
 		b.published, b.held, b.waiting = map[string]bool{}, map[string]bool{}, map[string]map[string]chan string{}
 		b.hands = map[string]*handWatch{}
+		b.armed = map[string]bool{}
 	})
 }

@@ -187,6 +199,14 @@ func (b *Builder) Sweep(ctx context.Context) error {
 			continue
 		}
 		newly = b.notePublished(cur) || newly
+		if current[key] && cur.State == delivery.BuildFailed {
+			if module, _, err := delivery.ParseBuilderBuildKey(key); err == nil {
+				b.mu.Lock()
+				fp := b.known[module].FP2
+				b.mu.Unlock()
+				b.armRetake(ctx, key, module, fp, cur) // a restarted builder reads the count and goes on
+			}
+		}
 		if current[key] || cur.State != delivery.BuildBuilding {
 			continue
 		}
@@ -477,7 +497,7 @@ func (b *Builder) try(ctx context.Context, module string, m delivery.Module) {
 		b.logf("%s: left building, the toolchains moved under it", cl.Key)
 		return
 	}
-	result.By, result.Manifest = b.Claimer.By, m.Manifest
+	result.By, result.Manifest, result.Retakes = b.Claimer.By, m.Manifest, cl.Build.Retakes
 	if len(cl.Gone) > 0 && result.State == delivery.BuildDone {
 		result.Step += " (built again: the artifact store no longer held " + strings.Join(cl.Gone, ", ") + ")"
 	}
@@ -493,6 +513,7 @@ func (b *Builder) try(ctx context.Context, module string, m delivery.Module) {
 	b.logBuild(LogEnded(module, m, b.refOf(module, m.FP2), b.Node, b.now(), result))
 	if result.State == delivery.BuildFailed {
 		b.logf("%s: failed: %s", cl.Key, result.Error)
+		b.armRetake(ctx, cl.Key, module, m.FP2, result)
 	}
 	if result.State == delivery.BuildQueued {
 		b.logf("%s: waits for the package %s to be published", cl.Key, result.Waits)
@@ -503,6 +524,54 @@ func (b *Builder) try(ctx context.Context, module string, m delivery.Module) {
 	}
 }

+// armRetake takes a key that failed retakeable again by itself once its backoff has passed, as a new revision (issue 1748):
+// only an error that opens with delivery.Retake, and at most delivery.MaxRetakes times, counted on the key's value. A key
+// failed for its source (a compile error, FailedUntilChanged) is never armed.
+func (b *Builder) armRetake(ctx context.Context, key, module, fp string, v delivery.BuilderBuild) {
+	if v.State != delivery.BuildFailed || !delivery.Retakeable(v.Error) || v.Retakes >= delivery.MaxRetakes || ctx.Err() != nil {
+		return
+	}
+	b.mu.Lock()
+	if b.armed[key] {
+		b.mu.Unlock()
+		return
+	}
+	b.armed[key] = true
+	b.mu.Unlock()
+	wait := b.RetakeBackoff
+	if wait <= 0 {
+		wait = DefaultRetakeBackoff
+	}
+	wait <<= v.Retakes
+	b.logf("%s: failed retakeable; taken again in %s (retake %d of %d)", key, wait, v.Retakes+1, delivery.MaxRetakes)
+	after := b.After
+	if after == nil {
+		// The builder holds no timer (ADR 0437 §8: a wait is a context's bound): the wait is the bound of a context, which
+		// the builder's own context ends early.
+		after = func(d time.Duration, f func()) func() {
+			wait, stop := context.WithTimeout(ctx, d)
+			go func() {
+				<-wait.Done()
+				if errors.Is(wait.Err(), context.DeadlineExceeded) && ctx.Err() == nil {
+					f()
+				}
+			}()
+			return stop
+		}
+	}
+	after(wait, func() {
+		b.mu.Lock()
+		delete(b.armed, key)
+		m, known := b.known[module]
+		b.mu.Unlock()
+		if ctx.Err() != nil || !known || m.FP2 != fp {
+			return // a newer fingerprint supersedes it: that one is built by its own event
+		}
+		b.logf("%s: taken again after its backoff (retake %d of %d)", key, v.Retakes+1, delivery.MaxRetakes)
+		b.consider(ctx, module, m)
+	})
+}
+
 // stale is why the module's fingerprint is not built now, or empty when it is: the toolchain each language of the plan
 // has agreed (novox/hq ADR 0465) must be the one the fingerprint was computed with (Module.Toolchains).
 func (b *Builder) stale(m delivery.Module, plan Plan) string {
@@ -707,7 +776,7 @@ func waitsOf(errs []string) string {

 // keyPrefixes are the errors a build module's step may open its reason with that the key's error must open with too, so
 // the claim reads them (delivery.FailedUntilChanged), first the ones not built again.
-var keyPrefixes = []string{delivery.NotPinned, delivery.VersionTaken, delivery.RefusedKind, delivery.NotStored}
+var keyPrefixes = []string{delivery.NotPinned, delivery.VersionTaken, delivery.RefusedKind, delivery.NotStored, delivery.Retake}

 // keyError is the error of a key from its lanes' errors: when one names a prefix of keyPrefixes inside the step's words
 // (`<tool> on <node>: the step <key> failed: not stored: ...`), the key's error opens with that prefix, so a reader of the
@@ -955,6 +1024,7 @@ func LogEnded(module string, m delivery.Module, ref, by string, at time.Time, re
 		e.Against = append([]string(nil), m.Inputs2.Bases...)
 	}
 	e.Made = append([]delivery.BuiltArtifact(nil), result.Artifacts...)
+	e.Retakes = result.Retakes
 	e.Imports = append([]string(nil), result.Imports...) // the indexer keeps them on the module (novox/hq ADR 0593 §2)
 	return e
 }