From 9070d2502c988677ca1174ac69b750c00daf109e Mon Sep 17 00:00:00 2001 From: jochen Date: Tue, 15 Sep 2026 22:26:35 +0200 Subject: [PATCH] The builder narrates every step, and every command it runs MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 | 13 ++++- cmd/mesh-builder/once.go | 3 +- internal/builder/builder.go | 96 +++++++++++++++++++++++++++++++- internal/builder/builder_test.go | 20 +++---- internal/builder/bundle_test.go | 8 +-- 5 files changed, 120 insertions(+), 20 deletions(-) diff --git a/cmd/mesh-builder/main.go b/cmd/mesh-builder/main.go index 2289726..bb68faa 100644 --- a/cmd/mesh-builder/main.go +++ b/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. diff --git a/cmd/mesh-builder/once.go b/cmd/mesh-builder/once.go index 2be3bdb..953cf47 100644 --- a/cmd/mesh-builder/once.go +++ b/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 } diff --git a/internal/builder/builder.go b/internal/builder/builder.go index c8a16ae..d950905 100644 --- a/internal/builder/builder.go +++ b/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() } diff --git a/internal/builder/builder_test.go b/internal/builder/builder_test.go index 7f1c2c3..a97a93f 100644 --- a/internal/builder/builder_test.go +++ b/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) } diff --git a/internal/builder/bundle_test.go b/internal/builder/bundle_test.go index 0b8115a..ffbce41 100644 --- a/internal/builder/bundle_test.go +++ b/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) }