The builder narrates every step, and every command it runs

A build was silent from clone to publish, so a build in progress, one that failed
quietly, and a request that never arrived all looked identical — which cost a long
diagnosis against a running mesh chasing "the handler never fired".

Now: the handler announces a request the instant it lands. Build logs each phase
— clone, commit, manifest, bases, each artifact starting and finishing with what
it produced, resolve, done — through a Log callback that is nil-safe, so the tests
that pass none still build. And the Command runner echoes every command before it
runs, with where and how long it took, because on a hang the last line is exactly
the command it is stuck inside: "git clone waiting on a network that will not
answer" rather than "the builder did nothing".

The unreadable-request path prints to stdout now too, not stderr, so it shows in
docker logs without splitting streams — the split is what hid it.

Claude-Session: https://claude.ai/code/session_01D6qtiYU3P9jk3pnAXyAFyx

cmd/mesh-builder/main.go

@@ -160,12 +160,18 @@ func run() error {
 func answer(ctx context.Context, channel *amqp.Channel, publisher builder.Publisher,
 	on, workspace string, delivery amqp.Delivery) {
 
+	// **First thing, and to stdout.** A build request that arrives and produces no visible line
+	// until it either finishes or fails is indistinguishable from one that never arrived — which
+	// cost a long diagnosis against a running mesh, chasing "the handler never fired" when the
+	// truth was only that the handler said nothing until the end.
+	fmt.Printf("a build request arrived (%d bytes)\n", len(delivery.Body))
+
 	var request link.BuildRequest
 	if err := json.Unmarshal(delivery.Body, &request); err != nil {
 		// Unreadable. Acknowledged and dropped rather than requeued: a message this builder
 		// cannot parse will not become parseable by being delivered again, and requeueing it
 		// would put it in front of every real request for ever.
-		fmt.Fprintf(os.Stderr, "a request could not be read and was dropped: %v\n", err)
+		fmt.Printf("a request could not be read and was dropped: %v\n", err)
 		_ = delivery.Ack(false)
 		return
 	}
@@ -184,7 +190,10 @@ func answer(ctx context.Context, channel *amqp.Channel, publisher builder.Publis
 	fmt.Println()
 
 	built, err := builder.Build(ctx, builder.Command, publisher,
-		request.Repository, request.Path, request.Ref, workspace, request.Held)
+		request.Repository, request.Path, request.Ref, workspace, request.Held,
+		func(step, message string) {
+			fmt.Printf("  [%s] %s\n", step, message)
+		})
 	if err != nil {
 		// A failure is a result. A build that fails and says nothing is indistinguishable from a
 		// builder that is not running, and those want completely different responses.

cmd/mesh-builder/once.go

@@ -84,7 +84,8 @@ func buildOnce(ctx context.Context, args []string) error {
 	}
 	fmt.Fprintln(os.Stderr)
 
-	built, buildErr := builder.Build(ctx, builder.Command, publisher, repository, *path, *ref, where, bases)
+	built, buildErr := builder.Build(ctx, builder.Command, publisher, repository, *path, *ref, where, bases,
+		func(step, message string) { fmt.Printf("  [%s] %s\n", step, message) })
 	if buildErr != nil {
 		return buildErr
 	}

internal/builder/builder.go

@@ -14,6 +14,7 @@ import (
 	"regexp"
 	"sort"
 	"strings"
+	"time"
 
 	"github.com/novox/mesh-control/internal/catalogue"
 )
@@ -67,7 +68,10 @@ type Result struct {
 // archive failed would otherwise leave half of itself in the store under a digest the mesh never
 // records — reachable, unreferenced, and indistinguishable from something in use.
 func Build(ctx context.Context, run Runner, publish Publisher,
-	repository, path, ref, workspace string, held map[string]string) (Result, error) {
+	repository, path, ref, workspace string, held map[string]string, log Log) (Result, error) {
+
+	say := logging(log)
+	say("clone", "%s%s at %s", repository, describePath(path), refOrHead(ref))
 
 	// Made rather than required. A builder that fails because the directory it was told to work
 	// in does not exist is a builder that needs a setup step nobody documented.
@@ -82,8 +86,10 @@ func Build(ctx context.Context, run Runner, publish Publisher,
 	// that reuses a working tree can succeed because of something a previous build left behind,
 	// and that is a build nobody can reproduce.
 	if _, err := run(ctx, workspace, "git", "clone", "--quiet", repository, tree); err != nil {
+		say("clone", "FAILED: %v", err)
 		return Result{}, fmt.Errorf("cannot clone %s: %w", repository, err)
 	}
+	say("clone", "done")
 	if ref != "" {
 		if _, err := run(ctx, tree, "git", "checkout", "--quiet", ref); err != nil {
 			return Result{}, fmt.Errorf("%s has no %s: %w", repository, ref, err)
@@ -94,6 +100,7 @@ func Build(ctx context.Context, run Runner, publish Publisher,
 		return Result{}, err
 	}
 	commit = strings.TrimSpace(commit)
+	say("commit", "%s", short(commit))
 
 	// A module is a repository and a path within it (novox/hq ADR 0069). The ordinary case is an
 	// empty path, meaning the repository's root; a repository holding several modules names each
@@ -112,8 +119,10 @@ func Build(ctx context.Context, run Runner, publish Publisher,
 	}
 	manifest, err := catalogue.ParseManifest(raw)
 	if err != nil {
+		say("manifest", "INVALID: %v", err)
 		return Result{}, err
 	}
+	say("manifest", "%s v%s — %d artifact(s)", manifest.Module, manifest.Version, artifactCount(manifest))
 
 	var built []catalogue.Built
 	if manifest.Build != nil {
@@ -122,29 +131,86 @@ func Build(ctx context.Context, run Runner, publish Publisher,
 		// fix it rather than inside a build that stops on its own first line.
 		args, err := standingOn(manifest, held)
 		if err != nil {
+			say("bases", "UNMET: %v", err)
 			return Result{}, err
 		}
+		if len(args) > 0 {
+			say("bases", "%d resolved from what the mesh holds", len(args)/2)
+		}
 		artifacts := append([]catalogue.Artifact{}, manifest.Build.Artifacts...)
 		// Ordered, so two builds of one commit do the same work in the same sequence and their
 		// logs can be compared.
 		sort.Slice(artifacts, func(i, j int) bool { return artifacts[i].Name < artifacts[j].Name })
 		for _, a := range artifacts {
-			made, err := one(ctx, run, publish, manifest.Module, within, commit, a, args, held)
+			say("artifact", "%s (%s%s) — starting", a.Name, a.Kind, langSuffix(a))
+			made, err := one(ctx, run, publish, manifest.Module, within, commit, a, args, held, say)
 			if err != nil {
+				say("artifact", "%s FAILED: %v", a.Name, err)
 				return Result{}, err
 			}
+			say("artifact", "%s done — %s", a.Name, describeMade(made))
 			built = append(built, made)
 		}
 	}
 
 	resolved, err := manifest.Resolve(built)
 	if err != nil {
+		say("resolve", "FAILED: %v", err)
 		return Result{}, err
 	}
+	say("done", "%s at %s — %d artifact(s) pinned", manifest.Module, short(commit), len(built))
 	return Result{Manifest: resolved, Commit: commit, Built: built,
 		Against: against(within, manifest)}, nil
 }
 
+// Log is where a build says what it is doing, step by step. Nil is silent — the tests pass none,
+// and a build with nowhere to speak must still build.
+type Log func(step, message string)
+
+func logging(log Log) func(step, format string, args ...any) {
+	if log == nil {
+		return func(string, string, ...any) {}
+	}
+	return func(step, format string, args ...any) {
+		log(step, fmt.Sprintf(format, args...))
+	}
+}
+
+func describePath(path string) string {
+	if path == "" {
+		return ""
+	}
+	return " at " + path
+}
+
+func refOrHead(ref string) string {
+	if ref == "" {
+		return "HEAD"
+	}
+	return ref
+}
+
+func artifactCount(m catalogue.Manifest) int {
+	if m.Build == nil {
+		return 0
+	}
+	return len(m.Build.Artifacts)
+}
+
+func langSuffix(a catalogue.Artifact) string {
+	if a.Language != "" {
+		return ", " + a.Language
+	}
+	return ""
+}
+
+func describeMade(made catalogue.Built) string {
+	if made.Digest != "" {
+		return made.Kind + " " + short(strings.TrimPrefix(made.Digest, "sha256:"))
+	}
+	return made.Kind + " " + made.Reference
+}
+
 // inside resolves a module's path within a clone, and refuses one that leaves it.
 //
 // **A build reads only its own tree.** A path of `../../etc` would otherwise make a build read —
@@ -216,16 +282,18 @@ const ManifestName = "module.json"
 
 func one(ctx context.Context, run Runner, publish Publisher,
 	module, tree, commit string, a catalogue.Artifact, args []string,
-	held map[string]string) (catalogue.Built, error) {
+	held map[string]string, say func(step, format string, args ...any)) (catalogue.Built, error) {
 
 	switch a.Kind {
 	case catalogue.ArtifactUpstream:
 		// Mirrored, not built. Pulled by the reference the module names and pushed under a name
 		// of the mesh's own, so what a machine fetches is pinned by a digest this registry
 		// assigned rather than by a tag somebody else can move.
+		say("mirror", "pulling %s", a.From)
 		if _, err := run(ctx, tree, "docker", "pull", a.From); err != nil {
 			return catalogue.Built{}, fmt.Errorf("%s: cannot fetch %s: %w", module, a.From, err)
 		}
+		say("mirror", "publishing under the mesh's own name")
 		reference, err := publish.PublishImage(ctx, a.From, module+"/"+a.Name)
 		if err != nil {
 			return catalogue.Built{}, err
@@ -244,9 +312,11 @@ func one(ctx context.Context, run Runner, publish Publisher,
 			invocation = append(invocation, "--target", a.Target)
 		}
 		invocation = append(invocation, ".")
+		say("image", "docker build -f %s", a.From)
 		if _, err := run(ctx, tree, "docker", invocation...); err != nil {
 			return catalogue.Built{}, fmt.Errorf("%s: building %s failed: %w", module, a.Name, err)
 		}
+		say("image", "built, publishing")
 		reference, err := publish.PublishImage(ctx, local, module+"/"+a.Name)
 		if err != nil {
 			return catalogue.Built{}, err
@@ -277,10 +347,12 @@ func one(ctx context.Context, run Runner, publish Publisher,
 					"holds no copy of it. Build %s first",
 				module, a.Name, chain.Language, chain.Base, chain.Artifact, chain.Base)
 		}
+		say("bundle", "compiling %s in %s's toolchain", a.Language, chain.Base)
 		compiled, err := compile(ctx, run, tree, chain, base, a)
 		if err != nil {
 			return catalogue.Built{}, fmt.Errorf("%s: compiling %s failed: %w", module, a.Name, err)
 		}
+		say("bundle", "compiled, packing")
 		body, err := pack(compiled)
 		if err != nil {
 			return catalogue.Built{}, fmt.Errorf("%s: packing %s failed: %w", module, a.Name, err)
@@ -401,16 +473,31 @@ func short(commit string) string {
 
 // Command is a Runner that actually runs things.
 func Command(ctx context.Context, dir, name string, args ...string) (string, error) {
+	// **Every command is echoed before it runs**, with where. On a build that hangs, the last line
+	// is exactly the command it is inside — which is the difference between "the builder did
+	// nothing" and "git clone is waiting on a network that will not answer". Silent on success is
+	// what made an empty workspace unreadable.
+	started := timeNow()
+	fmt.Printf("  $ (%s) %s %s\n", short(filepath.Base(dir)), name, strings.Join(args, " "))
 	cmd := exec.CommandContext(ctx, name, args...)
 	cmd.Dir = dir
 	out, err := cmd.CombinedOutput()
 	if err != nil {
+		fmt.Printf("  ! %s %s failed after %s\n", name, args[0], since(started))
 		return string(out), fmt.Errorf("%s %s: %w\n%s",
 			name, strings.Join(args, " "), err, strings.TrimSpace(string(out)))
 	}
+	fmt.Printf("  ✓ %s %s (%s)\n", name, firstArg(args), since(started))
 	return string(out), nil
 }
 
+func firstArg(args []string) string {
+	if len(args) == 0 {
+		return ""
+	}
+	return args[0]
+}
+
 var _ io.Writer = (*stringWriter)(nil)
 
 // standingOn turns the bases a module named into build arguments for what this mesh holds.
@@ -504,3 +591,6 @@ func sourcesFor(entrypoints []string, out string) []string {
 	}
 	return sources
 }
+
+func timeNow() time.Time       { return time.Now() }
+func since(t time.Time) string { return time.Since(t).Round(time.Millisecond).String() }

internal/builder/builder_test.go

@@ -108,7 +108,7 @@ func TestABuildProducesAManifestThePinsAreIn(t *testing.T) {
 	r, workspace := aRepository(t, withBoth, map[string]string{
 		"Dockerfile": "FROM scratch", "files/theme.conf": "dark",
 	})
-	got, err := Build(context.Background(), r.run, r, "https://forge.invalid/meshboard.git", "", "", workspace, nil)
+	got, err := Build(context.Background(), r.run, r, "https://forge.invalid/meshboard.git", "", "", workspace, nil, nil)
 	if err != nil {
 		t.Fatal(err)
 	}
@@ -134,7 +134,7 @@ func TestTwoBuildsOfOneCommitProduceOneDigest(t *testing.T) {
 		})
 		// A year apart, so a packer carrying timestamps cannot accidentally agree.
 		r.stamped = time.Date(2020+i, time.March, 3, 4, 5, 6, 0, time.UTC)
-		got, err := Build(context.Background(), r.run, r, "https://forge.invalid/x.git", "", "", workspace, nil)
+		got, err := Build(context.Background(), r.run, r, "https://forge.invalid/x.git", "", "", workspace, nil, nil)
 		if err != nil {
 			t.Fatal(err)
 		}
@@ -154,7 +154,7 @@ func TestNothingIsPublishedUntilEverythingIsBuilt(t *testing.T) {
 	// unreferenced, and indistinguishable from something in use.
 	r, workspace := aRepository(t, withBoth, map[string]string{"Dockerfile": "FROM scratch"})
 	// `files` is missing, so packing the archive fails — after the image would have been pushed.
-	_, err := Build(context.Background(), r.run, r, "https://forge.invalid/x.git", "", "", workspace, nil)
+	_, err := Build(context.Background(), r.run, r, "https://forge.invalid/x.git", "", "", workspace, nil, nil)
 	if err == nil {
 		t.Fatal("a build with a missing input succeeded")
 	}
@@ -166,7 +166,7 @@ func TestNothingIsPublishedUntilEverythingIsBuilt(t *testing.T) {
 func TestARepositoryWithNoManifestSaysSo(t *testing.T) {
 	workspace := t.TempDir()
 	r := &recorded{contents: map[string]string{"README.md": "nothing to see"}}
-	_, err := Build(context.Background(), r.run, r, "https://forge.invalid/x.git", "", "", workspace, nil)
+	_, err := Build(context.Background(), r.run, r, "https://forge.invalid/x.git", "", "", workspace, nil, nil)
 	if err == nil {
 		t.Fatal("a repository with nothing saying what it is was built")
 	}
@@ -179,7 +179,7 @@ func TestAModuleThatBuildsNothingStillProducesAManifest(t *testing.T) {
 	// Most of what a person installs is configuration.
 	r, workspace := aRepository(t, `{"module":"shell","version":"1","resources":[
 		{"id":"rc","type":"file","path":"/etc/zsh/zshrc","content":"setopt"}]}`, nil)
-	got, err := Build(context.Background(), r.run, r, "https://forge.invalid/shell.git", "", "", workspace, nil)
+	got, err := Build(context.Background(), r.run, r, "https://forge.invalid/shell.git", "", "", workspace, nil, nil)
 	if err != nil {
 		t.Fatal(err)
 	}
@@ -209,7 +209,7 @@ func TestTheTreeIsFreshEveryTime(t *testing.T) {
 	if err := os.WriteFile(leftover, []byte("stale"), 0o644); err != nil {
 		t.Fatal(err)
 	}
-	if _, err := Build(context.Background(), r.run, r, "https://forge.invalid/x.git", "", "", workspace, nil); err != nil {
+	if _, err := Build(context.Background(), r.run, r, "https://forge.invalid/x.git", "", "", workspace, nil, nil); err != nil {
 		t.Fatal(err)
 	}
 	if _, err := os.Stat(leftover); err == nil {
@@ -222,7 +222,7 @@ func TestABuildThatCannotPushFails(t *testing.T) {
 		"Dockerfile": "FROM scratch", "files/a": "b",
 	})
 	r.failPush = true
-	if _, err := Build(context.Background(), r.run, r, "https://forge.invalid/x.git", "", "", workspace, nil); err == nil {
+	if _, err := Build(context.Background(), r.run, r, "https://forge.invalid/x.git", "", "", workspace, nil, nil); err == nil {
 		t.Fatal("a build that could publish nothing reported success")
 	}
 }
@@ -236,7 +236,7 @@ func TestAnUpstreamImageIsMirroredRatherThanBuilt(t *testing.T) {
 	  "resources":[{"id":"db","type":"container","name":"mesh-postgres","artifact":"store"}]}`
 
 	r, workspace := aRepository(t, mirrors, nil)
-	got, err := Build(context.Background(), r.run, r, "https://forge.invalid/postgres.git", "", "", workspace, nil)
+	got, err := Build(context.Background(), r.run, r, "https://forge.invalid/postgres.git", "", "", workspace, nil, nil)
 	if err != nil {
 		t.Fatal(err)
 	}
@@ -302,7 +302,7 @@ func TestAModuleIsBuiltFromItsPathWithinTheRepository(t *testing.T) {
 		"modules/other/" + ManifestName: `{"module":"other","version":"1"}`,
 	}}
 	got, err := Build(context.Background(), r.run, r,
-		"https://forge.invalid/catalogue.git", "modules/shell", "", t.TempDir(), nil)
+		"https://forge.invalid/catalogue.git", "modules/shell", "", t.TempDir(), nil, nil)
 	if err != nil {
 		t.Fatal(err)
 	}
@@ -321,7 +321,7 @@ func TestAPathThatLeavesTheRepositoryIsRefused(t *testing.T) {
 	for _, escaping := range []string{"../../etc", "/etc"} {
 		r := &recorded{contents: map[string]string{ManifestName: withBoth}}
 		_, err := Build(context.Background(), r.run, r,
-			"https://forge.invalid/x.git", escaping, "", t.TempDir(), nil)
+			"https://forge.invalid/x.git", escaping, "", t.TempDir(), nil, nil)
 		if err == nil {
 			t.Fatalf("%q was accepted as a module's path", escaping)
 		}

internal/builder/bundle_test.go

@@ -54,7 +54,7 @@ func TestABundleIsCompiledAndPackedWithNoDockerfile(t *testing.T) {
 	held := map[string]string{"mesh-tools/build": "registry.invalid/mesh-tools/build@sha256:" + strings.Repeat("b", 64)}
 
 	got, err := Build(context.Background(), compiling{r}.run, r,
-		"https://forge.invalid/greeter.git", "", "", workspace, held)
+		"https://forge.invalid/greeter.git", "", "", workspace, held, nil)
 	if err != nil {
 		t.Fatalf("a module with a language and no Dockerfile did not build: %v", err)
 	}
@@ -91,7 +91,7 @@ func TestABundleWhoseToolchainIsNotHeldIsRefusedFirst(t *testing.T) {
 	r, workspace := aRepository(t, aBundle, map[string]string{"index.ts": "console.log(1)"})
 
 	_, err := Build(context.Background(), compiling{r}.run, r,
-		"https://forge.invalid/greeter.git", "", "", workspace, nil)
+		"https://forge.invalid/greeter.git", "", "", workspace, nil, nil)
 	if err == nil {
 		t.Fatal("a bundle was built with no toolchain to compile it in")
 	}
@@ -112,7 +112,7 @@ func TestABundleInAnUnknownLanguageIsRefused(t *testing.T) {
 
 	_, err := Build(context.Background(), compiling{r}.run, r,
 		"https://forge.invalid/greeter.git", "", "", workspace,
-		map[string]string{"mesh-tools/build": "registry.invalid/x@sha256:" + strings.Repeat("c", 64)})
+		map[string]string{"mesh-tools/build": "registry.invalid/x@sha256:" + strings.Repeat("c", 64)}, nil)
 	if err == nil {
 		t.Fatal("a language nothing can compile was accepted")
 	}
@@ -140,7 +140,7 @@ func TestTwoBundlesInOneModuleArePackedSeparately(t *testing.T) {
 	held := map[string]string{"mesh-tools/build": "registry.invalid/mesh-tools/build@sha256:" + strings.Repeat("b", 64)}
 
 	got, err := Build(context.Background(), compiling{r}.run, r,
-		"https://forge.invalid/greeter.git", "", "", workspace, held)
+		"https://forge.invalid/greeter.git", "", "", workspace, held, nil)
 	if err != nil {
 		t.Fatalf("a module with two bundles did not build: %v", err)
 	}