Builds have a history, and failures are rows like any other

A build result was answered to whoever asked and kept nowhere. So "when
did this last build", "why did it fail" and "which machine built what is
running" had no answer, and a build nobody was waiting for was reported
into the void — which is the same as not reporting it.

Failures are recorded too, and that is the point rather than a detail: a
failed build that leaves no trace is indistinguishable from one nobody
asked for, and the difference is the whole of whether somebody should be
looking at something. A build that never learned what it was building
keeps the repository, because that is what a person goes and looks at.

Recording is idempotent on the correlation id, because a result can
arrive twice — as the answer to whoever asked, and on the exchange when
nobody was. Two rows would show one build as two, and which is real is
not answerable afterwards.

The serving control plane now binds `built` as well, so results from
builds it did not ask for are kept. It refuses them loudly when it has
nowhere to put them rather than dropping them, so the broker's own
counters show something arriving that nothing handles.

`builds [<module>]` reads it: what happened lately across the mesh, or
what has happened to one module — the first asked after something goes
wrong, the second when deciding whether to trust something.

What was published is kept with the build, so a digest traces back to
what made it without holding the manifest twice in a place that can
disagree with the first.

cmd/mesh-control/main.go

@@ -65,6 +65,8 @@ func run() error {
 	switch args[0] {
 	case "build":
 		return buildCommand(ctx, args[1:])
+	case "builds":
+		return buildsCommand(ctx, args[1:])
 	case "pin":
 		return pinCommand(ctx, args[1:], true)
 	case "unpin":
@@ -134,6 +136,7 @@ func usage() {
   settings set <module> <file> --node <n>   ...or for one machine
   settings clear <module> [--node <n>]      take a layer away
   build <repository> [--ref R]   have a build machine build it, and record what came out
+  builds [<module>]              what has been built lately, and what came of it
   pin <node> <provision> <from>  which node this one gets a provision from
   unpin <node> <provision>       put that question back
   plan <node> [--files|--json]     what that node would run, and why
@@ -490,6 +493,9 @@ func serve(ctx context.Context) error {
 		return err
 	}
 	defer server.Close()
+	// And build results nobody was waiting for. A build triggered any other way than `build`
+	// would otherwise be reported into the void, which is the same as not reporting it.
+	server.Records(builds{inv})
 
 	return server.Serve(ctx)
 }
@@ -1711,6 +1717,19 @@ func buildCommand(ctx context.Context, args []string) error {
 	if err != nil {
 		return err
 	}
+
+	// Kept before it is judged. A failed build that leaves no trace is indistinguishable from one
+	// nobody asked for, and the difference is the whole of whether somebody should be looking at
+	// something.
+	inv, err := openInventory(ctx)
+	if err != nil {
+		return err
+	}
+	defer inv.Close()
+	if err := inv.RecordBuild(ctx, buildFrom(result)); err != nil {
+		return err
+	}
+
 	if result.Failed != "" {
 		// The builder's own words. Wrapping them in something about the control plane would put
 		// two explanations between a person and a build log.
@@ -1738,12 +1757,6 @@ func buildCommand(ctx context.Context, args []string) error {
 		return nil
 	}
 
-	inv, err := openInventory(ctx)
-	if err != nil {
-		return err
-	}
-	defer inv.Close()
-
 	// Recorded with where it came from, so "is this current?" is answerable without building it
 	// again (novox/hq ADR 0009).
 	if err := inv.RegisterModule(ctx, manifest, inventory.Source{
@@ -1757,3 +1770,108 @@ func buildCommand(ctx context.Context, args []string) error {
 	fmt.Printf("  run `assign <node> %s` to put it somewhere\n", manifest.Module)
 	return nil
 }
+
+// buildFrom turns what a builder said into what the mesh keeps.
+func buildFrom(result link.BuildResult) inventory.Build {
+	kept := inventory.Build{
+		ID: result.ID, Repository: result.Repository, Ref: result.Ref,
+		Commit: result.Commit, On: result.On, Failed: result.Failed,
+	}
+	for _, made := range result.Made {
+		kept.Made = append(kept.Made, inventory.Artifact{
+			Name: made.Name, Kind: made.Kind, Reference: made.Reference,
+		})
+	}
+	// The module name comes from the manifest, which only exists when the build got that far.
+	if len(result.Manifest) > 0 {
+		if m, err := catalogue.ParseManifest(result.Manifest); err == nil {
+			kept.Module = m.Module
+		}
+	}
+	return kept
+}
+
+// buildsCommand says what has been built lately.
+func buildsCommand(ctx context.Context, args []string) error {
+	set := flag.NewFlagSet("builds", flag.ContinueOnError)
+	limit := set.Int("n", 20, "how many to show")
+	positionals, err := parseAround(set, args)
+	if err != nil {
+		return err
+	}
+	module := ""
+	if len(positionals) == 1 {
+		module = positionals[0]
+	} else if len(positionals) > 1 {
+		return errors.New("builds [<module>] [-n N]")
+	}
+
+	inv, err := openInventory(ctx)
+	if err != nil {
+		return err
+	}
+	defer inv.Close()
+
+	builds, err := inv.Builds(ctx, module, *limit)
+	if err != nil {
+		return err
+	}
+	if len(builds) == 0 {
+		// Said rather than printed as nothing: an empty list and a failed read must never look
+		// the same, and getting here means the store answered.
+		if module != "" {
+			fmt.Printf("nothing has been built for %s\n", module)
+			return nil
+		}
+		fmt.Println("nothing has been built yet")
+		return nil
+	}
+
+	for _, b := range builds {
+		what := b.Module
+		if what == "" {
+			// It failed before knowing what it was building, which is most of the interesting
+			// failures. The repository is what a person has to go and look at.
+			what = "?"
+		}
+		outcome := "built " + short(b.Commit)
+		if !b.Worked() {
+			outcome = "failed"
+		}
+		fmt.Printf("%-18s %-14s %-10s %s\n",
+			what, outcome, b.On, b.At.Local().Format("2006-01-02 15:04"))
+		fmt.Printf("    %s", b.Repository)
+		if b.Ref != "" {
+			fmt.Printf(" at %s", b.Ref)
+		}
+		fmt.Println()
+		for _, made := range b.Made {
+			fmt.Printf("    %-10s %s\n", made.Kind, made.Reference)
+		}
+		if !b.Worked() {
+			// The builder's own first line. The whole failure is often a build log, and printing
+			// it here would bury every other row.
+			fmt.Printf("    %s\n", firstLine(b.Failed))
+		}
+	}
+	return nil
+}
+
+// firstLine is as much of a failure as belongs in a list.
+func firstLine(s string) string {
+	if cut := strings.IndexByte(s, '\n'); cut >= 0 {
+		return strings.TrimSpace(s[:cut])
+	}
+	return strings.TrimSpace(s)
+}
+
+// builds keeps what a builder said, for the serving control plane.
+//
+// A type of its own rather than a method on the enrolment, because they are unrelated things
+// arriving on one queue and an implementation of one should not have to say anything about the
+// other.
+type builds struct{ inv *inventory.Inventory }
+
+func (b builds) Built(ctx context.Context, result link.BuildResult) error {
+	return b.inv.RecordBuild(ctx, buildFrom(result))
+}

internal/inventory/builds.go

@@ -0,0 +1,102 @@
+package inventory
+
+import (
+	"context"
+	"encoding/json"
+	"time"
+)
+
+// What has been built.
+//
+// A build result was answered to whoever asked and kept nowhere, so "when did this last build",
+// "why did it fail" and "which machine built what is running" had no answer. Failures are recorded
+// too: one that leaves no trace is indistinguishable from a build nobody asked for, and the
+// difference is the whole of whether somebody should be looking at something.
+
+// Build is one attempt, whichever way it went.
+type Build struct {
+	ID         string
+	Repository string
+	Ref        string
+	// Module is empty for a build that failed before it knew what it was building.
+	Module string
+	Commit string
+	// On is the machine that did it.
+	On string
+	// Failed is the builder's own words, empty when it worked.
+	Failed string
+	Made   []Artifact
+	At     time.Time
+}
+
+// Artifact is one thing a build published.
+type Artifact struct {
+	Name      string `json:"name"`
+	Kind      string `json:"kind"`
+	Reference string `json:"reference"`
+}
+
+// Worked reports whether this build produced something.
+func (b Build) Worked() bool { return b.Failed == "" }
+
+// RecordBuild keeps what a builder said.
+//
+// Idempotent on the correlation id, because a result can arrive twice: once as the answer to
+// whoever asked and once on the exchange when nobody was. Recording both would show one build as
+// two, and which of the two is real is not a question anybody could answer afterwards.
+func (i *Inventory) RecordBuild(ctx context.Context, b Build) error {
+	made, err := json.Marshal(b.Made)
+	if err != nil {
+		return err
+	}
+	var module *string
+	if b.Module != "" {
+		module = &b.Module
+	}
+	_, err = i.store.Pool().Exec(ctx,
+		`insert into build (id, repository, ref, module, commit_hash, built_on, failed, made)
+		 values ($1, $2, $3, $4, $5, $6, $7, $8)
+		 on conflict (id) do nothing`,
+		b.ID, b.Repository, b.Ref, module, b.Commit, b.On, b.Failed, made)
+	return err
+}
+
+// Builds is what has happened lately, newest first.
+//
+// For one module when named, or across the mesh when not. Both are asked: *what happened just
+// now* after something goes wrong, and *what has happened to this* when deciding whether to
+// trust it.
+func (i *Inventory) Builds(ctx context.Context, module string, limit int) ([]Build, error) {
+	if limit <= 0 {
+		limit = 20
+	}
+	query := `select id, repository, ref, coalesce(module,''), commit_hash, built_on, failed, made, at
+	          from build order by at desc limit $1`
+	args := []any{limit}
+	if module != "" {
+		query = `select id, repository, ref, coalesce(module,''), commit_hash, built_on, failed, made, at
+		         from build where module = $2 order by at desc limit $1`
+		args = append(args, module)
+	}
+
+	rows, err := i.store.Pool().Query(ctx, query, args...)
+	if err != nil {
+		return nil, err
+	}
+	defer rows.Close()
+
+	var out []Build
+	for rows.Next() {
+		var b Build
+		var made []byte
+		if err := rows.Scan(&b.ID, &b.Repository, &b.Ref, &b.Module, &b.Commit,
+			&b.On, &b.Failed, &made, &b.At); err != nil {
+			return nil, err
+		}
+		if err := json.Unmarshal(made, &b.Made); err != nil {
+			return nil, err
+		}
+		out = append(out, b)
+	}
+	return out, rows.Err()
+}

internal/inventory/builds_test.go

@@ -0,0 +1,138 @@
+package inventory
+
+import (
+	"context"
+	"strings"
+	"testing"
+)
+
+// A build result was answered to whoever asked and kept nowhere, so "when did this last build",
+// "why did it fail" and "which machine built what is running" had no answer at all.
+
+func aBuild(id, module, failed string) Build {
+	b := Build{
+		ID: id, Repository: "https://forge.invalid/" + strings.TrimSuffix(module, "?") + ".git",
+		Module: module, On: "a-build-machine", Failed: failed,
+	}
+	if failed == "" {
+		b.Commit = "c0ffee" + id
+		b.Made = []Artifact{{Name: "config", Kind: "archive", Reference: "…/blobs/sha256:…"}}
+	}
+	return b
+}
+
+func TestAFailedBuildIsARowLikeAnyOther(t *testing.T) {
+	// One that leaves no trace is indistinguishable from a build nobody asked for, and the
+	// difference is the whole of whether somebody should be looking at something.
+	inv := fresh(t)
+	ctx := context.Background()
+	if err := inv.RecordBuild(ctx, aBuild("1", "", "cannot clone: no such repository")); err != nil {
+		t.Fatal(err)
+	}
+	got, err := inv.Builds(ctx, "", 10)
+	if err != nil {
+		t.Fatal(err)
+	}
+	if len(got) != 1 {
+		t.Fatalf("got %d builds", len(got))
+	}
+	if got[0].Worked() {
+		t.Fatal("a failure was recorded as a success")
+	}
+	if !strings.Contains(got[0].Failed, "no such repository") {
+		t.Fatalf("the builder's own words were not kept: %q", got[0].Failed)
+	}
+	// And it kept what was asked for, which is the only thing a person can go and look at when
+	// the build never learned what it was building.
+	if got[0].Module != "" || got[0].Repository == "" {
+		t.Fatalf("got %+v", got[0])
+	}
+}
+
+func TestOneResultRecordedTwiceIsOneBuild(t *testing.T) {
+	// A result can arrive twice: as the answer to whoever asked, and on the exchange when nobody
+	// was. Two rows would show one build as two, and which is real is not answerable afterwards.
+	inv := fresh(t)
+	ctx := context.Background()
+	for i := 0; i < 2; i++ {
+		if err := inv.RecordBuild(ctx, aBuild("same", "shell", "")); err != nil {
+			t.Fatal(err)
+		}
+	}
+	got, err := inv.Builds(ctx, "", 10)
+	if err != nil {
+		t.Fatal(err)
+	}
+	if len(got) != 1 {
+		t.Fatalf("one build was recorded %d times", len(got))
+	}
+}
+
+func TestBuildsComeBackNewestFirstAndCanBeAskedPerModule(t *testing.T) {
+	inv := fresh(t)
+	ctx := context.Background()
+	for _, b := range []Build{
+		aBuild("1", "shell", ""),
+		aBuild("2", "meshboard", ""),
+		aBuild("3", "shell", "the tests failed"),
+	} {
+		if err := inv.RecordBuild(ctx, b); err != nil {
+			t.Fatal(err)
+		}
+	}
+
+	all, err := inv.Builds(ctx, "", 10)
+	if err != nil {
+		t.Fatal(err)
+	}
+	if len(all) != 3 || all[0].ID != "3" {
+		t.Fatalf("newest is not first: %v", ids(all))
+	}
+
+	// Per module, because "what has happened to this" is asked when deciding whether to trust it.
+	shell, err := inv.Builds(ctx, "shell", 10)
+	if err != nil {
+		t.Fatal(err)
+	}
+	if len(shell) != 2 {
+		t.Fatalf("shell has %d builds: %v", len(shell), ids(shell))
+	}
+	for _, b := range shell {
+		if b.Module != "shell" {
+			t.Fatalf("asked for shell and got %q", b.Module)
+		}
+	}
+}
+
+func TestWhatWasPublishedIsKeptWithTheBuild(t *testing.T) {
+	// So a digest can be traced back to the build that made it, without keeping the manifest a
+	// second time in a place that can disagree with the first.
+	inv := fresh(t)
+	ctx := context.Background()
+	if err := inv.RecordBuild(ctx, aBuild("1", "shell", "")); err != nil {
+		t.Fatal(err)
+	}
+	got, _ := inv.Builds(ctx, "", 10)
+	if len(got[0].Made) != 1 || got[0].Made[0].Kind != "archive" {
+		t.Fatalf("what was published was not kept: %+v", got[0].Made)
+	}
+}
+
+func TestAskingForMoreThanThereIsIsNotAnError(t *testing.T) {
+	inv := fresh(t)
+	got, err := inv.Builds(context.Background(), "", 100)
+	if err != nil {
+		t.Fatal(err)
+	}
+	if len(got) != 0 {
+		t.Fatalf("got %d", len(got))
+	}
+}
+
+func ids(builds []Build) []string {
+	var out []string
+	for _, b := range builds {
+		out = append(out, b.ID)
+	}
+	return out
+}

internal/inventory/migrations/0010-builds.sql

@@ -0,0 +1,44 @@
+-- What has been built, and what came of it.
+--
+-- A build result is answered to whoever asked and, until this, kept nowhere. So "when did this
+-- module last build", "why did it fail", and "which machine built what is running" had no answer
+-- at all -- and a build nobody was waiting for was reported into the void.
+--
+-- **Failures are rows too.** A failed build that leaves no trace is indistinguishable from one
+-- nobody asked for, and the difference is the whole of whether somebody should be looking at
+-- something. This is the same rule the host follows about a service that does not exist.
+
+create table build (
+    -- The correlation the control plane made when it asked. Not the module name: two builds of
+    -- one module can be in flight, and one is not the other.
+    id          text        primary key,
+
+    -- What was asked for. Kept even when the build failed before knowing what the module is
+    -- called, which is most of the interesting failures.
+    repository  text        not null,
+    ref         text        not null default '',
+
+    -- What came of it. `module` and `commit` are empty for a build that never got that far.
+    module      text,
+    commit_hash text        not null default '',
+
+    -- The machine that did it, so a failure about one machine can be told from one about the
+    -- source. Not a foreign key to node: a build machine need not be a node the mesh manages,
+    -- and a record that vanished when it stopped being one would lose the history.
+    built_on    text        not null default '',
+
+    -- Empty when it worked. The builder's own words, because anything this end wrote instead
+    -- would put a second explanation between a person and a build log.
+    failed      text        not null default '',
+
+    -- What was published, as [{name, kind, reference}]. Kept so a digest can be traced back to
+    -- the build that made it without keeping the manifest twice.
+    made        jsonb       not null default '[]',
+
+    at          timestamptz not null default now()
+);
+
+-- The two questions asked of this table: what happened lately, and what has happened to this
+-- module. Neither is answerable quickly by scanning once there is a year of them.
+create index build_lately on build (at desc);
+create index build_by_module on build (module, at desc) where module is not null;

internal/link/serve.go

@@ -33,14 +33,32 @@ type Listener interface {
 	Heard(ctx context.Context, report Report) error
 }
 
+// Recorder keeps what builders say.
+//
+// Separate from Listener because they are different things arriving: a report is a node saying
+// what it did with a declaration, and a build result is a machine saying what came of some work.
+// One interface carrying both would mean an implementation of one having to say something about
+// the other.
+type Recorder interface {
+	Built(ctx context.Context, result BuildResult) error
+}
+
 type Server struct {
 	conn     *amqp.Connection
 	channel  *amqp.Channel
 	enroller Enroller
 	listener Listener
+	recorder Recorder
 	log      *log.Logger
 }
 
+// Records tells the server where to keep build results.
+//
+// Set after Connect rather than passed to it, because a control plane that only publishes — the
+// `build` command, which waits for its own answer — needs a connection and no recorder, and
+// making it supply one would have it construct something it never uses.
+func (s *Server) Records(r Recorder) { s.recorder = r }
+
 // Connect opens the control plane's own connection to the broker.
 func Connect(enroller Enroller, listener Listener) (*Server, error) {
 	url := strings.TrimSpace(os.Getenv(AMQPVar))
@@ -78,7 +96,7 @@ func Connect(enroller Enroller, listener Listener) (*Server, error) {
 	// accepts, finds no queue for, and drops — the publisher sees success and the consumer sees
 	// nothing. That is exactly what happened to reports: `report` was left unbound while `enrol`
 	// worked, so nodes announced what they had applied into a void for an afternoon.
-	for _, key := range []string{KeyEnrol, KeyReport, KeyAlive} {
+	for _, key := range []string{KeyEnrol, KeyReport, KeyAlive, KeyBuilt} {
 		if err := channel.QueueBind(ControlQueue, key, Exchange, false, nil); err != nil {
 			conn.Close()
 			return nil, fmt.Errorf("cannot bind %s to %s/%s: %w", ControlQueue, Exchange, key, err)
@@ -121,7 +139,8 @@ func (s *Server) Serve(ctx context.Context) error {
 	}
 
 	closed := s.conn.NotifyClose(make(chan *amqp.Error, 1))
-	s.log.Printf("consuming %s, bound to %s/{%s,%s,%s}", ControlQueue, Exchange, KeyEnrol, KeyReport, KeyAlive)
+	s.log.Printf("consuming %s, bound to %s/{%s,%s,%s,%s}",
+		ControlQueue, Exchange, KeyEnrol, KeyReport, KeyAlive, KeyBuilt)
 
 	for {
 		select {
@@ -149,6 +168,8 @@ func (s *Server) handle(ctx context.Context, delivery amqp.Delivery) {
 		s.handleReport(delivery)
 	case KeyAlive:
 		s.handleAlive(delivery)
+	case KeyBuilt:
+		s.handleBuilt(ctx, delivery)
 	default:
 		// Rejected without requeue: a message nothing understands will not be understood on the
 		// next attempt either, and requeuing it would spin.
@@ -255,3 +276,36 @@ func (s *Server) reply(ctx context.Context, delivery amqp.Delivery, reply EnrolR
 		s.log.Printf("cannot reply to %s: %v", delivery.ReplyTo, err)
 	}
 }
+
+// handleBuilt keeps what a builder said, whichever way it went.
+//
+// This is for results nobody was waiting for. A build asked for with `build` is answered directly
+// to the asker; one triggered any other way is published here, and without this it would be
+// reported into the void — which is the same as not reporting it.
+func (s *Server) handleBuilt(ctx context.Context, delivery amqp.Delivery) {
+	var result BuildResult
+	if err := json.Unmarshal(delivery.Body, &result); err != nil {
+		s.log.Printf("a build result could not be read: %v", err)
+		_ = delivery.Reject(false)
+		return
+	}
+	if s.recorder == nil {
+		// Nothing to keep it in. Rejected rather than dropped silently, so the broker's own
+		// counters show something arriving that nothing handles.
+		s.log.Printf("a build result arrived and this control plane keeps none")
+		_ = delivery.Reject(false)
+		return
+	}
+	if err := s.recorder.Built(ctx, result); err != nil {
+		s.log.Printf("cannot keep a build result from %s: %v", result.On, err)
+		_ = delivery.Reject(false)
+		return
+	}
+	switch {
+	case result.Failed != "":
+		s.log.Printf("%s could not build %s", result.On, result.Repository)
+	default:
+		s.log.Printf("%s built %s from %s", result.On, result.Repository, result.Commit)
+	}
+	_ = delivery.Ack(false)
+}