diff --git a/modules/mesh-delivery-builder/cmd/mesh-delivery-builder/integration_test.go b/modules/mesh-delivery-builder/cmd/mesh-delivery-builder/integration_test.go index 96c9d54d..8eccbd80 100644 --- a/modules/mesh-delivery-builder/cmd/mesh-delivery-builder/integration_test.go +++ b/modules/mesh-delivery-builder/cmd/mesh-delivery-builder/integration_test.go @@ -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. diff --git a/modules/mesh-delivery-builder/cmd/mesh-delivery-builder/main.go b/modules/mesh-delivery-builder/cmd/mesh-delivery-builder/main.go index bdfdb4a3..63f1915c 100644 --- a/modules/mesh-delivery-builder/cmd/mesh-delivery-builder/main.go +++ b/modules/mesh-delivery-builder/cmd/mesh-delivery-builder/main.go @@ -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 diff --git a/modules/mesh-delivery-builder/internal/build/claim.go b/modules/mesh-delivery-builder/internal/build/claim.go index 50b933a9..748fffad 100644 --- a/modules/mesh-delivery-builder/internal/build/claim.go +++ b/modules/mesh-delivery-builder/internal/build/claim.go @@ -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) { diff --git a/modules/mesh-delivery-builder/internal/build/retake_test.go b/modules/mesh-delivery-builder/internal/build/retake_test.go new file mode 100644 index 00000000..08c12b89 --- /dev/null +++ b/modules/mesh-delivery-builder/internal/build/retake_test.go @@ -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...) } diff --git a/modules/mesh-delivery-builder/internal/build/run.go b/modules/mesh-delivery-builder/internal/build/run.go index 106916cf..df7c49b0 100644 --- a/modules/mesh-delivery-builder/internal/build/run.go +++ b/modules/mesh-delivery-builder/internal/build/run.go @@ -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 // (` on : the step 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 }