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 e60665ac..9e57505c 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 @@ -527,7 +527,7 @@ func TestAFailedKeyIsBuiltAgainAsANewRevisionFromANewModulesValueWithTheSameFing 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"}) + b.start(t, "n1", map[string]string{"MESH_BUILDER_RETAKE_BACKOFF": "1s"}) if v := b.await(t, "ca-trust", isState(delivery.BuildFailed)); !delivery.Retakeable(v.Error) { t.Fatalf("build = %+v, want failed retakeable", v) } diff --git a/modules/mesh-delivery-builder/internal/build/claim.go b/modules/mesh-delivery-builder/internal/build/claim.go index 748fffad..4e1cf7a9 100644 --- a/modules/mesh-delivery-builder/internal/build/claim.go +++ b/modules/mesh-delivery-builder/internal/build/claim.go @@ -66,6 +66,10 @@ type ClaimOptions struct { // done: the store's nightly collector deletes a blob nothing holds, and a key the controller never took in holds // nothing, so a key whose blob is gone is claimed building as a new revision and built again. Nil asks nothing. Stored func(ctx context.Context, references []string) (gone []string, err error) + // Retaking is this claim being the builder's backoff taking a retakeable failed key again (Builder.armRetake, issue + // 1748): only it adds to BuilderBuild.Retakes, so the cap of delivery.MaxRetakes counts the backoff's own retakes and + // not a look another event makes while the backoff waits. + Retaking bool } // StoredReferences are the references of a done build's bundles and archives that name a blob in the artifact store @@ -153,8 +157,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 (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 +// which wait for another fingerprint (a retakeable failure, delivery.Retakeable, is taken again too; the new +// revision keeps Retakes, and counts one more only when it is the backoff's claim, ClaimOptions.Retaking), 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; @@ -213,8 +217,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) + building.Retakes = cur.Retakes // the count rides on the key's value, so it survives a restart (issue 1748) + if opt.Retaking && delivery.Retakeable(cur.Error) { + building.Retakes++ } 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 != "": diff --git a/modules/mesh-delivery-builder/internal/build/retake_test.go b/modules/mesh-delivery-builder/internal/build/retake_test.go index 08c12b89..b260ef28 100644 --- a/modules/mesh-delivery-builder/internal/build/retake_test.go +++ b/modules/mesh-delivery-builder/internal/build/retake_test.go @@ -46,102 +46,134 @@ func retakeRig(t *testing.T) (*rig, *clock) { 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++ { +// 1748: a key failed retakeable is taken again by the builder's backoff, and only by it counts toward the cap. +func TestTheBuilderRetakesARetakeableFailure(t *testing.T) { + // AC3: claimed again as a new revision after the 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. + t.Run("after its backoff, at most three times", func(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 || c.waits[1] != 20*time.Second || c.waits[2] != 40*time.Second { + t.Fatalf("after %d retakes: %d pending, backoffs %v; want none pending and 10s, 20s, 40s", delivery.MaxRetakes, len(c.pending), c.waits) + } + if n := len(r.bm.callsOf("build_go_build")); n != 1+delivery.MaxRetakes { + t.Errorf("%d builds, want the first and %d retakes", n, delivery.MaxRetakes) + } + // A builder that starts again reads the count from the key: at the cap it arms nothing, below it the next wait. + restarted := func(retakes int) *clock { + rr, cc := retakeRig(t) + rr.st, rr.b.Claimer.Store = r.st, 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) + } + }) + // AC4: a failure of the source (a compile error, FailedUntilChanged) is never taken again by the backoff. + t.Run("a failure of the source is never taken again", func(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) + } + } + }) + // Only the backoff's claim counts: a look another event makes while the backoff waits (a toolchain change, a new modules + // value) takes the key again and leaves the count as it was, so those looks cannot spend the retakes inside the pause. + t.Run("another event's look leaves the count", func(t *testing.T) { + r, c := retakeRig(t) + r.bm.fails["ace/build_go_build"] = lookupFailure + r.consider(t, "modules/m") + for i := 0; i < 2*delivery.MaxRetakes; i++ { + r.b.Reconsider(context.Background()) + r.b.Wait() + } + if v := valueOf(t, r.st, r.key); v.Retakes != 0 || v.State != delivery.BuildFailed { + t.Fatalf("after Reconsider looks the key = %+v, want failed with Retakes 0", v) + } if c.fire() != 1 { - t.Fatalf("retake %d: no timer was set", retake) + t.Fatal("the backoff's own wait was not armed once") } 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) + if v := valueOf(t, r.st, r.key); v.Retakes != 1 { + t.Errorf("after the backoff's claim the key = %+v, want Retakes 1", v) } - 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"} { + }) + // The journal says each retake with its count and the log's entry of the build's end names it. + t.Run("the journal and the log say the count", func(t *testing.T) { 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) + var said []string + r.b.Logf = func(f string, a ...any) { said = append(said, strings.TrimSpace(fmt.Sprintf(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) + } } - if len(c.waits) != 0 || c.fire() != 0 { - t.Errorf("%q: the backoff was armed: %v", reason, c.waits) + 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) } - } + if joined := strings.Join(said, "\n"); !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) + } + }) + // The key's error opens with the retake prefix only when every failing lane failed retakeable. + t.Run("the key error opens with the prefix only when every lane is retakeable", func(t *testing.T) { + for _, c := range []struct { + name string + errs []string + prefix bool + }{ + {"one retakeable lane", []string{"mesh-build-go on ace: the step failed: " + lookupFailure}, true}, + {"two retakeable lanes", []string{"a: " + lookupFailure, "b: " + lookupFailure}, true}, + {"a retakeable and a compile error", []string{"a: " + lookupFailure, "b: go build of tool: undefined: x"}, false}, + {"a compile error", []string{"b: go build of tool: undefined: x"}, false}, + } { + got := keyError(c.errs) + if has := strings.HasPrefix(got, delivery.Retake); has != c.prefix || delivery.Retakeable(got) != c.prefix { + t.Errorf("%s: keyError = %q, want prefix %v", c.name, got, c.prefix) + } + } + }) } - -// 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 df7c49b0..eb2f0a83 100644 --- a/modules/mesh-delivery-builder/internal/build/run.go +++ b/modules/mesh-delivery-builder/internal/build/run.go @@ -108,12 +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 + // armed are the keys with a retake wait running, by build key; retaking are the keys whose backoff has passed and whose + // next claim is the backoff's own (ClaimOptions.Retaking). + armed, retaking map[string]bool } // DefaultRetakeBackoff is the first wait before a retakeable failure is taken again; each retake doubles it. -const DefaultRetakeBackoff = 30 * time.Second +const DefaultRetakeBackoff = 60 * time.Second type planned struct { plan Plan @@ -131,7 +132,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{} + b.armed, b.retaking = map[string]bool{}, map[string]bool{} }) } @@ -449,9 +450,11 @@ func (b *Builder) try(ctx context.Context, module string, m delivery.Module) { trunk := b.trunkFP[key] first := !b.tried[key] b.tried[key] = true + retaking := b.retaking[key] + delete(b.retaking, key) b.mu.Unlock() cl, err := b.Claimer.Claim(ctx, module, m.FP2, m.Manifest, ClaimOptions{TakeOver: first, ImageBuilder: imageSeat, Trunk: trunk, Published: b.isPublished, - Stored: b.storedOnce(key)}) + Stored: b.storedOnce(key), Retaking: retaking}) if err != nil { b.logf("%s: %v", module, err) return @@ -568,6 +571,9 @@ func (b *Builder) armRetake(ctx context.Context, key, module, fp string, v deliv 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.mu.Lock() + b.retaking[key] = true + b.mu.Unlock() b.consider(ctx, module, m) }) } @@ -776,7 +782,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, delivery.Retake} +var keyPrefixes = []string{delivery.NotPinned, delivery.VersionTaken, delivery.RefusedKind, delivery.NotStored} // 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 @@ -793,6 +799,19 @@ func keyError(errs []string) string { } } } + // A retakeable failure opens the key's error only when every failing lane is one (issue 1748): a lane that failed on its + // source would be built again for nothing. + all := len(errs) > 0 + for _, e := range errs { + all = all && strings.Contains(e, delivery.Retake) + } + if all { + stripped := make([]string, len(errs)) + for i, e := range errs { + stripped[i] = strings.Replace(e, delivery.Retake, "", 1) + } + return delivery.Retake + strings.Join(stripped, "; ") + } return strings.Join(errs, "; ") } diff --git a/modules/mesh-delivery-builder/manifest_test.go b/modules/mesh-delivery-builder/manifest_test.go index f94b1720..d30abd40 100644 --- a/modules/mesh-delivery-builder/manifest_test.go +++ b/modules/mesh-delivery-builder/manifest_test.go @@ -212,4 +212,25 @@ func TestServesNoRequestSubjectAndHoldsNoTicker(t *testing.T) { // 1607/AC6 (ADR if files < 1 { t.Fatalf("read %d source files, want the program's", files) } + // The one bounded wait the builder holds for its own sake is the retake backoff (issue 1748): a goroutine that waits a + // context's deadline and then acts. It lives in Builder.armRetake only; any other source holding that idiom is refused. + const idiom = "context.DeadlineExceeded" + var holders []string + for _, root := range []string{"cmd", "internal"} { + filepath.WalkDir(root, func(path string, d fs.DirEntry, err error) error { + if err != nil || d.IsDir() || !strings.HasSuffix(path, ".go") || strings.HasSuffix(path, "_test.go") { + return err + } + src, _ := os.ReadFile(path) + for _, fn := range strings.Split(string(src), "\nfunc ") { + if strings.Contains(fn, idiom) && !strings.HasPrefix(fn, "(b *Builder) armRetake(") { + holders = append(holders, path) + } + } + return nil + }) + } + if len(holders) != 0 { + t.Errorf("%v waits for a context's deadline and acts: the retake backoff in Builder.armRetake is the one allowed bounded wait (issue 1748); any other wait is a timer", holders) + } }