Builder: write each build's start and end to its own log on the bus, and ask the seat artifact-store's held and hear its artifacts-gone, the controller's only until the lease write, so build history and the store's sweep leave the controller (issue 1955, ADR 0571 §1, §2)

Pins mesh-sdk f9a496d.

modules/mesh-delivery-builder/internal/build/run.go

@@ -7,6 +7,7 @@ import (
 	"fmt"
 	"maps"
 	"sort"
+	"strconv"
 	"strings"
 	"sync"
 	"time"
@@ -68,6 +69,11 @@ type Builder struct {
 	Askings int
 	// Said is told each ask asked again (the builder's event build.asked-again). Nil tells nobody.
 	Said func(AskedAgain)
+	// Log is told each build's start and end, the entries of the builder's log (novox/hq ADR 0571 §1). Nil tells nobody.
+	Log func(delivery.BuildLogEntry)
+	// Now is the clock of the log; nil is time.Now. Node is the node the builder runs on, which asked the build.
+	Now  func() time.Time
+	Node string
 
 	once     sync.Once
 	sem      chan struct{}
@@ -429,6 +435,7 @@ func (b *Builder) try(ctx context.Context, module string, m delivery.Module) {
 		return
 	}
 	b.handClaimed(key, cl.Rev)
+	b.logBuild(LogStarted(module, m, b.Node, b.now()))
 	if cl.Unasked != nil {
 		b.logf("%v", cl.Unasked)
 	}
@@ -478,6 +485,7 @@ func (b *Builder) try(ctx context.Context, module string, m delivery.Module) {
 		b.logf("%s: the build could not be written: %v", cl.Key, err)
 		return
 	}
+	b.logBuild(LogEnded(module, m, b.Node, b.now(), result))
 	if result.State == delivery.BuildFailed {
 		b.logf("%s: failed: %s", cl.Key, result.Error)
 	}
@@ -872,3 +880,43 @@ func needsFetch(tasks []Task) bool {
 	}
 	return false
 }
+
+func (b *Builder) now() time.Time {
+	if b.Now != nil {
+		return b.Now()
+	}
+	return time.Now()
+}
+
+// logBuild tells the log an entry, said in the journal when it cannot be one.
+func (b *Builder) logBuild(e delivery.BuildLogEntry) {
+	if b.Log == nil {
+		return
+	}
+	if _, err := delivery.EncodeBuildLogEntry(e); err != nil {
+		b.logf("%s at %s: no log entry: %v", e.Module, e.FP, err)
+		return
+	}
+	b.Log(e)
+}
+
+// LogStarted is the log's entry of a build of module's fingerprint starting (ADR 0571 §1): the module, the fingerprint, the
+// source revision, where it is built from (repository, directory, commit), the node of the builder that asked it and the time.
+func LogStarted(module string, m delivery.Module, by string, at time.Time) delivery.BuildLogEntry {
+	dir := m.Path
+	if dir == "" {
+		dir = "."
+	}
+	return delivery.BuildLogEntry{Event: delivery.BuildStartedEvent, Module: module, FP: m.FP2, Source: strconv.FormatUint(m.Src, 10),
+		Repository: m.Repository, Directory: dir, Commit: m.Commit, Node: by, At: at.UTC()}
+}
+
+// LogEnded is the log's entry of that build ending: the outcome (done, failed or queued) and each artifact's digest.
+func LogEnded(module string, m delivery.Module, by string, at time.Time, result delivery.BuilderBuild) delivery.BuildLogEntry {
+	e := LogStarted(module, m, by, at)
+	e.Event, e.Outcome = delivery.BuildEndedEvent, result.State
+	for _, a := range result.Artifacts {
+		e.Artifacts = append(e.Artifacts, delivery.BuiltDigest{Name: a.Name, Digest: a.Digest})
+	}
+	return e
+}

modules/mesh-delivery-builder/internal/build/run_test.go

@@ -221,7 +221,26 @@ var (
 
 func TestABundleAndAnArchiveAreBuiltOnOneNodeAndDone(t *testing.T) { // 1607/AC7, ADR 0478 clauses 1, 4
 	r := newRig(t, goBundle, archiveA, tsBundle)
+	var logged []delivery.BuildLogEntry
+	var lmu sync.Mutex
+	r.b.Node, r.b.Log = "novox", func(e delivery.BuildLogEntry) { lmu.Lock(); logged = append(logged, e); lmu.Unlock() }
 	v := r.consider(t, "modules/m")
+	// 1955/L7 (ADR 0571 §1): the build is one start and one end in the builder's log, every field named, its duration read
+	// from the two.
+	if len(logged) != 2 || logged[0].Event != delivery.BuildStartedEvent || logged[1].Event != delivery.BuildEndedEvent ||
+		logged[1].Outcome != delivery.BuildDone || len(logged[1].Artifacts) != 3 || logged[0].Repository != "novox/mesh-catalog" ||
+		logged[0].Directory != "modules/m" || logged[0].Commit != "7a74cee83f88e6585a5511c3cc53bdf0f5303d20" || logged[0].Node != "novox" ||
+		logged[0].FP != fp1 || logged[0].Module != "m" {
+		t.Fatalf("logged = %+v", logged)
+	}
+	for _, e := range logged {
+		if _, err := delivery.EncodeBuildLogEntry(e); err != nil {
+			t.Errorf("an entry the log refuses: %v", err)
+		}
+	}
+	if _, ok := delivery.BuildDuration(logged[0], logged[1]); !ok {
+		t.Error("no duration from the two entries")
+	}
 	if v.State != delivery.BuildDone || v.By != "novox.builder" || v.Manifest != manifestD || len(v.Artifacts) != 3 {
 		t.Fatalf("build = %+v, want done by novox.builder with three artifacts", v)
 	}