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 1e8664c9..845dfe30 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 @@ -541,7 +541,15 @@ func TestBuilderMakesADoneKeyWithTheDigests(t *testing.T) { // 1607/AC7 } // 1955/L7 (ADR 0571 §1): the build's start and end are in the module log build-log under the module's key, read as a // reader with the log's read reads them, the end naming the manifest and what was made. - ended := b.logged(t, "netcheck") + // DLV-B10: between them the build log holds the build's narrations (build.said), each version numbered, and why. + var ended []delivery.BuildLogEntry + for _, e := range b.logged(t, "netcheck") { + if e.Event != delivery.BuildSaidEvent { + ended = append(ended, e) + } else if e.Why != versions.SaidNumbered || !strings.Contains(e.Line, "numbered 0.1.5") || e.FP != fp { + t.Errorf("said = %+v, want netcheck's versions numbered", e) + } + } if len(ended) != 2 || ended[0].Event != delivery.BuildStartedEvent || ended[1].Event != delivery.BuildEndedEvent || ended[1].Manifest != digest || len(ended[1].Made) != 2 || ended[1].Node != "n1" { t.Errorf("logged = %+v, want the start and the end of netcheck's build", ended) @@ -555,6 +563,13 @@ func TestBuilderMakesADoneKeyWithTheDigests(t *testing.T) { // 1607/AC7 if !strings.Contains(said, "the check's build of abc is not claimed yet") { t.Errorf("the narration = %q, want what the ask waits on", said) } + // And in the build log, under the builder's own key (the ruling of 13:17: build.said). + if !slices.ContainsFunc(b.logged(t, delivery.BuilderModule), func(e delivery.BuildLogEntry) bool { + return e.Event == delivery.BuildSaidEvent && e.Why == versions.SaidUnanswered && e.FP == key && e.Commit == "abc" && + strings.Contains(e.Line, "the check's build of abc is not claimed yet") + }) { + t.Errorf("the build log of %s = %+v, want the unanswered tag ask said", delivery.BuilderModule, b.logged(t, delivery.BuilderModule)) + } if e, err := b.tagAsks.Get(b.ctx, key); err != nil { t.Fatal(err) } else if a, _ := versions.DecodeTagAsk(e.Value()); a.Answered.IsZero() || !a.Unanswered() { @@ -601,6 +616,11 @@ func TestBuilderMakesADoneKeyWithTheDigests(t *testing.T) { // 1607/AC7 b.moduleFP(t, "netcheck", netcheck, "modules/netcheck", bothToolchains, commit, third, 3) // the indexer writes it again b.awaitFP(t, "netcheck", third, isState(delivery.BuildDone)) b.awaitSaid(t, "kept: fingerprint "+third+" is numbered under it") + if !slices.ContainsFunc(b.logged(t, "netcheck"), func(e delivery.BuildLogEntry) bool { + return e.Event == delivery.BuildSaidEvent && e.Why == versions.SaidKept && e.FP == third && strings.Contains(e.Line, "kept: fingerprint "+third) + }) { + t.Errorf("the build log of netcheck says no version kept at %s", third) + } reg.awaitFinding(t, failed, false) // DLV-B4: the seats' refused and removed, heard on the builder's durable consumer, move a numbered version: a retention // removal turns the entry removed with its reason, a refusal refused with the holder's reason and the bytes it refused. 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 98f84aa4..d2d3a8f5 100644 --- a/modules/mesh-delivery-builder/cmd/mesh-delivery-builder/main.go +++ b/modules/mesh-delivery-builder/cmd/mesh-delivery-builder/main.go @@ -155,7 +155,8 @@ func run(ctx context.Context, getenv func(string) string, logOut io.Writer) erro b.Numbers = build.VersionNumbers{N: numberer, TagNumbered: tagNumbered(tagAsksKV.KV, logger.Printf, time.Now)} // An ask not answered within five minutes is narrated with what it waits on: its bound's end on the bus says when. boundsKV := process.AwaitBucket(ctx, js, conn, versions.TagAskBoundsBucket, "an unanswered tag ask is not narrated", logger.Printf) - bounds := &tagBounds{asks: tagAsksKV.KV, bounds: boundsKV.KV, bound: tagAskBound, waits: floorWaits.Waiting, logf: logger.Printf, now: time.Now} + bounds := &tagBounds{asks: tagAsksKV.KV, bounds: boundsKV.KV, bound: tagAskBound, waits: floorWaits.Waiting, logf: logger.Printf, now: time.Now, + log: func(e delivery.BuildLogEntry) { b.Log(e) }} // A state bound later numbers the builds looked at without it. versionsKV.Ready(func(jetstream.KeyValue) { b.Reconsider(ctx) }) // The versions' hand acts (builder_publish_again, builder_floor_again) come through reasks, as builder_build_again. @@ -185,6 +186,9 @@ func run(ctx context.Context, getenv func(string) string, logOut io.Writer) erro // The builder's log (ADR 0571 §1): each build's start and end in its module log `build-log`, read by the view, the // indexer and the assigner through their reads, and by the operator's command nox builds through the tool builder_builds_since. b.Log = func(e delivery.BuildLogEntry) { + if e.Node == "" { // a narration of no one build (a tag ask, the old form's window) is this instance's + e.Node = cred.Node + } if err := appendLog(context.WithoutCancel(ctx), js, cred, e); err != nil { logger.Printf("%v", err) } @@ -225,7 +229,7 @@ func run(ctx context.Context, getenv func(string) string, logOut io.Writer) erro // The old reference form's window over them (DLV-B9), kept in the state old-form once it is bound; builder_old_form // reads it and drops a retired node by hand. reads.ctx = context.WithoutCancel(ctx) - reads.window = &oldForm{forms: forms.Current, findings: found, logf: logger.Printf, now: time.Now, + reads.window = &oldForm{forms: forms.Current, findings: found, logf: logger.Printf, now: time.Now, log: func(e delivery.BuildLogEntry) { b.Log(e) }, said: func(body versions.OldFormClosedBody) { if err := emitEvent(context.WithoutCancel(ctx), js, cred, versions.OldFormClosedEvent, "old-form-closed-"+body.At.Format(time.RFC3339Nano), body); err != nil { logger.Printf("saying %s: %v", versions.OldFormClosedEvent, err) diff --git a/modules/mesh-delivery-builder/cmd/mesh-delivery-builder/oldform.go b/modules/mesh-delivery-builder/cmd/mesh-delivery-builder/oldform.go index 63fa95d2..ee93522e 100644 --- a/modules/mesh-delivery-builder/cmd/mesh-delivery-builder/oldform.go +++ b/modules/mesh-delivery-builder/cmd/mesh-delivery-builder/oldform.go @@ -12,6 +12,7 @@ import ( "github.com/nats-io/nats.go/jetstream" + "git.novox.be/novox/mesh-sdk/go/delivery" "git.novox.be/novox/mesh-sdk/go/health" "git.novox.be/novox/mesh-delivery/sdk/forms" @@ -28,6 +29,8 @@ type oldForm struct { findings *findings // said emits version.old-form-closed. said func(versions.OldFormClosedBody) + // log writes the close into the builder's build log (build.said); nil writes none. + log func(delivery.BuildLogEntry) logf func(string, ...any) now func() time.Time @@ -103,8 +106,15 @@ func (o *oldForm) step(ctx context.Context, counted map[string][]string) { o.overdue = overdue if closed { body := next.Closing() - o.logf("the old reference form's window closed at %s: no counted node-engine reads only an older form (last held by %s; dropped by hand: %d); new build keys leave it out", + line := fmt.Sprintf("the old reference form's window closed at %s: no counted node-engine reads only an older form (last held by %s; dropped by hand: %d); new build keys leave it out", body.At.Format(time.RFC3339), strings.Join(body.LastHolding, ", "), len(body.Dropped)) + o.logf("%s", line) + // In the build log too (design 51 *The node-engine's own build*), under the builder's own key, the window's key + // standing for the fingerprint: the close is no one build's. + if o.log != nil { + o.log(delivery.BuildLogEntry{Event: delivery.BuildSaidEvent, Module: delivery.BuilderModule, FP: versions.OldFormKey, + At: body.At.UTC(), Line: line, Why: versions.SaidOldFormClosed}) + } if o.said != nil { o.said(body) } diff --git a/modules/mesh-delivery-builder/cmd/mesh-delivery-builder/refused_test.go b/modules/mesh-delivery-builder/cmd/mesh-delivery-builder/refused_test.go index 225474da..e98037ab 100644 --- a/modules/mesh-delivery-builder/cmd/mesh-delivery-builder/refused_test.go +++ b/modules/mesh-delivery-builder/cmd/mesh-delivery-builder/refused_test.go @@ -344,8 +344,10 @@ func aFailedTrunkBuildIsAFinding(t *testing.T) { now := time.Unix(0, 0) fs := forms.ArtifactForms{{Name: "registry", First: true, Kinds: []string{"image"}}, {Name: "oci", Kinds: []string{"image"}}} var closings []versions.OldFormClosedBody + var logged []delivery.BuildLogEntry window := &oldForm{forms: fs, findings: f, logf: t.Logf, now: func() time.Time { return now }, - said: func(b versions.OldFormClosedBody) { closings = append(closings, b) }} + said: func(b versions.OldFormClosedBody) { closings = append(closings, b) }, + log: func(e delivery.BuildLogEntry) { logged = append(logged, e) }} reads := &engineReads{keeper: &enginereads.Keeper{}, window: window, counted: []string{"a", "b"}} newest := []string{forms.FormNeed("oci")} counted := map[string][]string{"a": newest, "b": nil} @@ -365,6 +367,12 @@ func aFailedTrunkBuildIsAFinding(t *testing.T) { if window.w.Open || len(closings) != 1 || !slices.Equal(closings[0].LastHolding, []string{"b"}) || st.vals[heldKey] != nil { t.Errorf("the node back with the newest form: %+v, closings %+v, finding left %v", window.w, closings, st.vals[heldKey] != nil) } + if len(logged) != 1 || logged[0].Event != delivery.BuildSaidEvent || logged[0].Why != versions.SaidOldFormClosed || + !strings.Contains(logged[0].Line, "last held by b") { + t.Errorf("the build log = %+v, want the close said once (build.said)", logged) + } else if _, err := delivery.EncodeBuildLogEntry(logged[0]); err != nil { + t.Errorf("the close is no entry the build log takes: %v", err) + } if _, err := window.drop(context.Background(), "b", "op@shanks", "retired", now); err != nil { t.Fatal(err) } diff --git a/modules/mesh-delivery-builder/cmd/mesh-delivery-builder/tagbounds.go b/modules/mesh-delivery-builder/cmd/mesh-delivery-builder/tagbounds.go index 500320bc..8a2454b4 100644 --- a/modules/mesh-delivery-builder/cmd/mesh-delivery-builder/tagbounds.go +++ b/modules/mesh-delivery-builder/cmd/mesh-delivery-builder/tagbounds.go @@ -8,6 +8,8 @@ import ( "github.com/nats-io/nats.go/jetstream" + "git.novox.be/novox/mesh-sdk/go/delivery" + "mesh-delivery-builder/internal/versions" ) @@ -19,8 +21,10 @@ type tagBounds struct { bounds func() jetstream.KeyValue waits func() []versions.FloorWait logf func(string, ...any) - now func() time.Time - bound time.Duration + // log writes a narration into the builder's build log (build.said); nil writes none. + log func(delivery.BuildLogEntry) + now func() time.Time + bound time.Duration } // arm writes key's bound when none stands: a Create, so a standing bound keeps its time and a restart arms each @@ -73,7 +77,14 @@ func (tb *tagBounds) ended(ctx context.Context, e jetstream.KeyValueEntry) { if tb.waits != nil { waits = tb.waits() } - tb.logf("%s", versions.NarrateUnanswered(t, waits, tb.now())) + line := versions.NarrateUnanswered(t, waits, tb.now()) + tb.logf("%s", line) + // In the build log too (design 51 *Tagged versions*): under the builder's own key, no build being claimed yet, the + // ask's key standing for the fingerprint. + if tb.log != nil { + tb.log(delivery.BuildLogEntry{Event: delivery.BuildSaidEvent, Module: delivery.BuilderModule, FP: e.Key(), Commit: t.Head, + At: tb.now().UTC(), Line: line, Why: versions.SaidUnanswered}) + } tb.arm(ctx, e.Key()) } diff --git a/modules/mesh-delivery-builder/internal/build/numbers.go b/modules/mesh-delivery-builder/internal/build/numbers.go index aefab4e7..06d019cf 100644 --- a/modules/mesh-delivery-builder/internal/build/numbers.go +++ b/modules/mesh-delivery-builder/internal/build/numbers.go @@ -4,6 +4,7 @@ import ( "context" "fmt" "strconv" + "time" "git.novox.be/novox/mesh-sdk/go/delivery" @@ -74,7 +75,12 @@ func (b *Builder) number(ctx context.Context, module string, m delivery.Module, } got, err := b.Numbers.Number(ctx, module, m, plan, tag) for _, s := range got.Said { - b.logf("%s at %s: %s", module, m.FP2, s) + b.logf("%s at %s: %s", module, m.FP2, s.Line) + // And in the build log (design 51 *The versions*: it says a version was kept, and why), between the build's start and end. + if b.Log != nil { + b.Log(delivery.BuildLogEntry{Event: delivery.BuildSaidEvent, Module: module, FP: m.FP2, Commit: m.Commit, Node: b.Node, + At: time.Now().UTC(), Line: s.Line, Why: s.Why}) + } } if err != nil { // Said, and built as before: an unnumbered build is published by its digest (ADR 0617 §1), numbered at its next look. diff --git a/modules/mesh-delivery-builder/internal/versions/claim.go b/modules/mesh-delivery-builder/internal/versions/claim.go index e758d927..08f0791a 100644 --- a/modules/mesh-delivery-builder/internal/versions/claim.go +++ b/modules/mesh-delivery-builder/internal/versions/claim.go @@ -74,8 +74,36 @@ type Numbering struct { Unnumbered []string // Wait is why the build waits: a package whose floor is not known (design 51 *The floor*). Nothing is claimed. Wait string - // Said are the builder's narrations of each decision, for its log. - Said []string + // Said are the builder's narrations of each decision, for its process log and its build log (build.said). + Said []Narration +} + +// Narration is one line the builder says in its build log (design 51: the build log says a version was kept, and +// why), and what it narrates. +type Narration struct{ Line, Why string } + +// What a narration of the build log narrates (the build.said entry's why). +const ( + SaidNumbered = "numbered" + SaidKept = "kept" + SaidWaiting = "waiting" + SaidUnnumbered = "unnumbered" + SaidUnanswered = "tag ask unanswered" + SaidOldFormClosed = "old-form-closed" +) + +// narrationOf is a decision's narration. +func narrationOf(name string, d Decision) Narration { + why := SaidNumbered + switch { + case d.Keep: + why = SaidKept + case d.Wait: + why = SaidWaiting + case d.Unnumbered: + why = SaidUnnumbered + } + return Narration{Line: name + ": " + d.Why, Why: why} } // Numberer numbers trunk builds at their claim (design 51 *The versions*, DLV-B2, B3): it asks a name's floor only @@ -118,7 +146,7 @@ func (n *Numberer) Number(ctx context.Context, c BuildClaim) (Numbering, error) if err != nil { return out, err } - out.Said = append(out.Said, name+": "+d.Why) + out.Said = append(out.Said, narrationOf(name, d)) switch { case d.Wait: n.wait(name, seat, floor, why)