diff --git a/modules/mesh-build-go/cmd/mesh-build-go/fetch.go b/modules/mesh-build-go/cmd/mesh-build-go/fetch.go index 2b166c9e..f612dbb5 100644 --- a/modules/mesh-build-go/cmd/mesh-build-go/fetch.go +++ b/modules/mesh-build-go/cmd/mesh-build-go/fetch.go @@ -332,10 +332,11 @@ func (m *Module) clock() time.Time { func (m *Module) now() time.Time { return m.clock() } // causeLine is the first line of a go command's output that says something other than Go's own progress: `go: -// downloading ...` comes first when Go fetches a module, and the cause of a failure on a later line. +// downloading ...` comes first when Go fetches a module, and `# ` heads a compile error of go build or go vet +// (issue 1703: the reason said only the package), and the cause of a failure on a later line. func causeLine(s string) string { for _, l := range strings.Split(s, "\n") { - if l = strings.TrimSpace(l); l != "" && !strings.HasPrefix(l, "go: downloading ") { + if l = strings.TrimSpace(l); l != "" && !strings.HasPrefix(l, "go: downloading ") && !strings.HasPrefix(l, "# ") { return l } } diff --git a/modules/mesh-build-go/cmd/mesh-build-go/fetch_test.go b/modules/mesh-build-go/cmd/mesh-build-go/fetch_test.go index 04874659..6c248513 100644 --- a/modules/mesh-build-go/cmd/mesh-build-go/fetch_test.go +++ b/modules/mesh-build-go/cmd/mesh-build-go/fetch_test.go @@ -302,3 +302,16 @@ func TestWorkAndCacheAreTheDirectoriesTheManifestPlacesOutsideTheHome(t *testing } } } + +// issue 1703: a go command's reason is its cause, not Go's progress nor go build's `# ` heading. +func TestCauseLineSkipsProgressAndThePackageHeading(t *testing.T) { + for in, want := range map[string]string{ + "go: downloading x v1\n# git.example/m/cmd\n./main.go:3:2: undefined: y\n": "./main.go:3:2: undefined: y", + "\ngo: example.com/x@v1: reading: 404\n": "go: example.com/x@v1: reading: 404", + "go: downloading x v1\n": "go: downloading x v1", + } { + if got := causeLine(in); got != want { + t.Errorf("causeLine(%q) = %q, want %q", in, got, want) + } + } +} diff --git a/modules/mesh-build-image/cmd/mesh-build-image/build.go b/modules/mesh-build-image/cmd/mesh-build-image/build.go index e138fd75..c3e1d0e4 100644 --- a/modules/mesh-build-image/cmd/mesh-build-image/build.go +++ b/modules/mesh-build-image/cmd/mesh-build-image/build.go @@ -155,14 +155,18 @@ func (m *Module) build(ctx context.Context, args map[string]any) (any, error) { } local := localName(workspace, manifest.Module, art.Name) - argv := append(m.storeFlags(), "bud", "--isolation", "oci", "--tag", local, "--file", dockerfile) + // --network pasta: a RUN step's network is pasta's, in user space. buildah's default for a rootless RUN is a + // netavark bridge whose nftables rules cannot be applied for an account without a user session, so every RUN + // failed before it started ("setup network: netavark: nftables error"; issue 1703, reproduced with buildah 1.45.2). + argv := append(m.storeFlags(), "bud", "--isolation", "oci", "--network", "pasta", "--tag", local, "--file", dockerfile) if art.Target != "" { argv = append(argv, "--target", art.Target) } argv = append(argv, imageArgs(manifest)...) argv = append(argv, contextDir) if r := m.Run(ctx, m.env(), "buildah", argv...); r.Status != 0 || r.Err != "" { - return nil, fmt.Errorf("buildah bud of %s: %s", art.Name, lastLine(r.Err+"\n"+r.Stderr+"\n"+r.Stdout)) + m.sayFailure("buildah bud of "+art.Name+" of "+manifest.Module, r) + return nil, fmt.Errorf("buildah bud of %s: %s", art.Name, cause(r)) } defer m.remove(local) digest, err := m.localDigest(ctx, local) @@ -204,8 +208,11 @@ func localName(workspace, module, artifact string) string { func (m *Module) localDigest(ctx context.Context, name string) (string, error) { r := m.Run(ctx, m.env(), "buildah", append(m.storeFlags(), "images", "--no-trunc", "--format", "{{.Digest}}", name)...) digest := strings.TrimSpace(r.Stdout) - if r.Status != 0 || r.Err != "" || !digestOK.MatchString(digest) { - return "", fmt.Errorf("the digest of the image %s could not be read: %s", name, lastLine(r.Err+"\n"+r.Stderr+"\n"+r.Stdout)) + if r.Status != 0 || r.Err != "" { + return "", fmt.Errorf("the digest of the image %s could not be read: %s", name, cause(r)) + } + if !digestOK.MatchString(digest) { + return "", fmt.Errorf("the digest of the image %s could not be read: buildah images answered %q, not a digest", name, cutFront(digest, CauseBytes)) } return digest, nil } @@ -216,17 +223,6 @@ var digestOK = regexp.MustCompile(`^sha256:[0-9a-f]{64}$`) func (m *Module) remove(name string) { r := m.Run(m.Ctx, m.env(), "buildah", append(m.storeFlags(), "rmi", "--force", name)...) if (r.Status != 0 || r.Err != "") && m.Say != nil { - m.Say("the image %s could not be removed from the store: %s", name, lastLine(r.Err+"\n"+r.Stderr)) + m.Say("the image %s could not be removed from the store: %s", name, cause(r)) } } - -// lastLine is the last line of a command's output that says something: buildah's error is its last line. -func lastLine(s string) string { - lines := strings.Split(s, "\n") - for i := len(lines) - 1; i >= 0; i-- { - if l := strings.TrimSpace(lines[i]); l != "" { - return l - } - } - return "" -} diff --git a/modules/mesh-build-image/cmd/mesh-build-image/build_test.go b/modules/mesh-build-image/cmd/mesh-build-image/build_test.go index 04fad85a..3bb92b3a 100644 --- a/modules/mesh-build-image/cmd/mesh-build-image/build_test.go +++ b/modules/mesh-build-image/cmd/mesh-build-image/build_test.go @@ -2,6 +2,7 @@ package main import ( "encoding/json" + "git.novox.be/novox/mesh-sdk/go/forgekey" "os" "path/filepath" "strings" @@ -84,7 +85,7 @@ func TestBuildRunsBuildahRootlessAndAnswersTheDigest(t *testing.T) { } dir := filepath.Join(m.Work, "ws1", "tree", "modules", "demo") for _, want := range []string{ - "--root " + m.Store + "/root", "--runroot " + m.Store + "/run", "--isolation oci", + "--root " + m.Store + "/root", "--runroot " + m.Store + "/run", "--isolation oci", "--network pasta", "--file " + dir + "/Dockerfile", "--target final", "--build-arg DEMO_BASE=docker.io/library/busybox@sha256:0000000000000000000000000000000000000000000000000000000000000001", } { @@ -121,16 +122,50 @@ func TestBuildRunsBuildahRootlessAndAnswersTheDigest(t *testing.T) { } } -// 1703c: a failing Dockerfile step fails the step, saying buildah's last line. -func TestBuildFailsWithBuildahsLastLine(t *testing.T) { - m, f, states := setup(t, same) - f.failBud = "Error: building at STEP \"RUN false\": exit status 1" - _, st := runBuild(t, m, states, nil) - if st.State != delivery.StepFailed || !strings.Contains(st.Reason, `STEP "RUN false"`) { - t.Errorf("step = %+v", st) +// 1703c, issue 1703: a failing Dockerfile step fails the step, its reason saying buildah's error from stderr, never the +// last STEP line buildah writes on stdout; nothing is pushed. +func TestBuildFailsWithBuildahsError(t *testing.T) { + steps := "STEP 1/3: FROM docker.io/library/alpine\nSTEP 2/3: RUN apk add --no-cache ca-certificates\nfetch https://dl-cdn.alpinelinux.org/x\n" + long := strings.Repeat("x", 2*CauseBytes) + cases := map[string]struct { + ran forgekey.Ran + want []string + wantNot []string + }{ + "buildah's RUN failure": {forgekey.Ran{Status: 1, Stdout: steps + "STEP 3/3: COPY . /app\n", + Stderr: "error running container: from /usr/bin/crun creating container for [/bin/sh -c apk add]: sd-bus call: Interactive authentication required.\nError: building at STEP \"RUN apk add --no-cache ca-certificates\": while running runtime: exit status 1\n"}, + []string{"exit status 1", "Interactive authentication required", `building at STEP "RUN apk add`}, []string{"STEP 3/3", "COPY"}}, + "a failed RUN": {forgekey.Ran{Status: 1, Stdout: steps, Stderr: "Error: building at STEP \"RUN false\": exit status 1\n"}, + []string{`STEP "RUN false"`}, []string{"dl-cdn"}}, + "a long stderr is bounded, its end kept": {forgekey.Ran{Status: 125, Stdout: steps, Stderr: "early noise\n" + long + "\nError: the end\n"}, + []string{"Error: the end"}, []string{"early noise", long}}, + "nothing on stderr": {forgekey.Ran{Status: 2, Stdout: steps}, []string{"exit status 2", "nothing on stderr", "dl-cdn"}, nil}, + "never ran": {forgekey.Ran{Err: "ENOENT"}, []string{"ENOENT", "wrote nothing"}, nil}, } - if len(f.called("push")) != 0 { - t.Error("a failed build pushed") + for name, c := range cases { + m, f, states := setup(t, same) + f.failBud = c.ran + _, st := runBuild(t, m, states, nil) + if st.State != delivery.StepFailed { + t.Errorf("%s: step = %+v, want failed", name, st) + continue + } + for _, w := range c.want { + if !strings.Contains(st.Reason, w) { + t.Errorf("%s: the reason %q lacks %q", name, st.Reason, w) + } + } + for _, w := range c.wantNot { + if strings.Contains(st.Reason, w) { + t.Errorf("%s: the reason %q carries %q", name, st.Reason, w) + } + } + if len(st.Reason) > CauseBytes+200 { + t.Errorf("%s: the reason is %d bytes, more than its bound", name, len(st.Reason)) + } + if len(f.called("push")) != 0 { + t.Errorf("%s: a failed build pushed", name) + } } } diff --git a/modules/mesh-build-image/cmd/mesh-build-image/cause.go b/modules/mesh-build-image/cmd/mesh-build-image/cause.go new file mode 100644 index 00000000..f0368b76 --- /dev/null +++ b/modules/mesh-build-image/cmd/mesh-build-image/cause.go @@ -0,0 +1,90 @@ +package main + +// Why a command failed, as the command said it (issue 1703). buildah writes its progress (STEP n/m, the RUN's own +// output) on stdout and its error on stderr, so the last line of both together is a STEP line and hides the error: +// a failure's reason is stderr's last lines, never stdout's, and the whole tail of stderr is said in the journal. + +import ( + "fmt" + "strings" + "unicode/utf8" + + "git.novox.be/novox/mesh-sdk/go/forgekey" +) + +// CauseBytes bounds what a failure's reason carries of the command's output; TailBytes bounds what the journal gets. +const ( + CauseBytes = 600 + TailBytes = 4096 +) + +// cause says why a command failed: its exit status (or why it never ran to one) and the last lines it wrote on stderr, +// at most CauseBytes of them, joined with " | ". Only when stderr is empty does stdout's tail stand in, said as such. +func cause(r forgekey.Ran) string { + head := exitOf(r) + if said := tailLines(r.Stderr, CauseBytes, " | "); said != "" { + return head + ": " + said + } + if said := tailLines(r.Stdout, CauseBytes, " | "); said != "" { + return head + ", nothing on stderr; stdout ends: " + said + } + return head + ", and it wrote nothing" +} + +// exitOf is how a command ended: why it never ran to an exit status, or the status. +func exitOf(r forgekey.Ran) string { + if r.Err != "" { + return r.Err + } + return fmt.Sprintf("exit status %d", r.Status) +} + +// tailLines is the last non-empty lines of s, trimmed, joined with sep, at most max bytes: the lines are taken whole +// from the end while they fit, and when even the last one does not, its end is kept behind "…". +func tailLines(s string, max int, sep string) string { + var lines []string + for _, l := range strings.Split(s, "\n") { + if l = strings.TrimSpace(l); l != "" { + lines = append(lines, l) + } + } + var keep []string + n := 0 + for i := len(lines) - 1; i >= 0; i-- { + add := len(lines[i]) + if len(keep) > 0 { + add += len(sep) + } + if n+add > max { + if len(keep) == 0 { + keep = append(keep, "…"+cutFront(lines[i], max-len("…"))) + } + break + } + keep = append([]string{lines[i]}, keep...) + n += add + } + return strings.Join(keep, sep) +} + +// cutFront is the last at most max bytes of s, starting on a whole character. +func cutFront(s string, max int) string { + if max <= 0 { + return "" + } + if len(s) <= max { + return s + } + s = s[len(s)-max:] + for len(s) > 0 && !utf8.RuneStart(s[0]) { + s = s[1:] + } + return s +} + +// sayFailure writes the tail of a failed command's stderr (and of its stdout, where buildah's RUN output goes) to the +// journal, so what the reason had to leave out can still be read there. +func (m *Module) sayFailure(what string, r forgekey.Ran) { + m.say("%s failed (%s); stderr ends:\n%s\nstdout ends:\n%s", what, exitOf(r), + tailLines(r.Stderr, TailBytes, "\n"), tailLines(r.Stdout, TailBytes, "\n")) +} diff --git a/modules/mesh-build-image/cmd/mesh-build-image/helpers_test.go b/modules/mesh-build-image/cmd/mesh-build-image/helpers_test.go index 876c6685..ecaefd90 100644 --- a/modules/mesh-build-image/cmd/mesh-build-image/helpers_test.go +++ b/modules/mesh-build-image/cmd/mesh-build-image/helpers_test.go @@ -70,8 +70,8 @@ type fake struct { calls []cmdRecord digest string // what `buildah images` prints pushes int - refuse int // the first n pushes answer "connection refused" - failBud string + refuse int // the first n pushes answer "connection refused" + failBud forgekey.Ran // what a failing buildah bud answers; a zero Status is a passing bud // digestFile: "" writes the digest, "none" writes no file, "empty" writes an empty one. digestFile string // registry: repository:tag -> digest @@ -116,8 +116,8 @@ func (f *fake) run(ctx context.Context, env []string, name string, args ...strin case name == "buildah" && strings.Contains(line, "--version"): return forgekey.Ran{Stdout: "buildah version 1.45.1 (image-spec 1.1.0, runtime-spec 1.1.0)\n"} case name == "buildah" && strings.Contains(line, " bud "): - if f.failBud != "" { - return forgekey.Ran{Status: 1, Stderr: "STEP 1/2: FROM x\n" + f.failBud + "\n"} + if f.failBud.Status != 0 || f.failBud.Err != "" { + return f.failBud } case name == "buildah" && strings.Contains(line, " images "): return forgekey.Ran{Stdout: f.digest + "\n"} diff --git a/modules/mesh-build-image/cmd/mesh-build-image/integration_test.go b/modules/mesh-build-image/cmd/mesh-build-image/integration_test.go index 6b6d13c3..a34cc083 100644 --- a/modules/mesh-build-image/cmd/mesh-build-image/integration_test.go +++ b/modules/mesh-build-image/cmd/mesh-build-image/integration_test.go @@ -203,6 +203,8 @@ func TestARealBuildIsRootlessWithNoSocketAndNoWayOut(t *testing.T) { imageModule(t, m, "FROM "+base+"\nRUN echo b > /proc/sysrq-trigger\n", nil) if _, st := buildReal(t, m, states); st.State != delivery.StepFailed { t.Errorf("a write to the host's /proc/sysrq-trigger passed: %+v", st) + } else if strings.Contains(st.Reason, "setup network") { + t.Errorf("the RUN never started, so the write was not what failed (issue 1703): %s", st.Reason) } } diff --git a/modules/mesh-build-image/cmd/mesh-build-image/push.go b/modules/mesh-build-image/cmd/mesh-build-image/push.go index a78ed0ce..75c22c50 100644 --- a/modules/mesh-build-image/cmd/mesh-build-image/push.go +++ b/modules/mesh-build-image/cmd/mesh-build-image/push.go @@ -15,6 +15,8 @@ import ( "strings" "syscall" "time" + + "git.novox.be/novox/mesh-sdk/go/forgekey" ) // RegistryWait is how long a call waits for a registry that refuses connections, longer than the nightly collection @@ -47,13 +49,15 @@ func (m *Module) push(ctx context.Context, workspace, module, local string, res dest := addr + "/" + repository + ":" + tag digestFile := filepath.Join(m.Work, workspace, "pushed."+tag) argv := append(m.storeFlags(), "push", "--tls-verify=false", "--digestfile", digestFile, local, "docker://"+dest) + var last forgekey.Ran if err := m.waitForRegistry(ctx, addr, "buildah push "+dest, func() error { - r := m.Run(ctx, m.env(), "buildah", argv...) - if r.Status != 0 || r.Err != "" { - return errors.New(lastLine(r.Err + "\n" + r.Stderr + "\n" + r.Stdout)) + last = m.Run(ctx, m.env(), "buildah", argv...) + if last.Status != 0 || last.Err != "" { + return errors.New(cause(last)) } return nil }); err != nil { + m.sayFailure("buildah push "+dest, last) return nil, fmt.Errorf("pushing %s: %w", dest, err) } var served string diff --git a/modules/mesh-build-node/cmd/mesh-build-node/build_test.go b/modules/mesh-build-node/cmd/mesh-build-node/build_test.go index 0165c9bd..8ae6ed75 100644 --- a/modules/mesh-build-node/cmd/mesh-build-node/build_test.go +++ b/modules/mesh-build-node/cmd/mesh-build-node/build_test.go @@ -267,3 +267,38 @@ func TestTheLaunchersAreTheSDKsRule(t *testing.T) { t.Errorf("launchers %v, mesh-sdk's rule %v", got, want) } } + +// issue 1703: a failed command's reason keeps stderr's end and stdout's start, each bounded, so a long stdout (npm's +// progress) never pushes npm's error out, and tsc's first error on stdout stays in. +func TestRanFailedKeepsTheError(t *testing.T) { + noise := strings.Repeat("npm progress line\n", 200) + cases := map[string]struct { + ran forgekey.Ran + want []string + wantNot []string + }{ + "passed": {forgekey.Ran{Stdout: "ok"}, nil, nil}, + "npm, long stdout": {forgekey.Ran{Status: 1, Stdout: noise, Stderr: "npm ERR! early\n" + noise + "npm ERR! code E404\n"}, []string{"status 1", "npm ERR! code E404"}, []string{"npm ERR! early"}}, + "tsc on stdout": {forgekey.Ran{Status: 2, Stdout: "src/a.ts(1,7): error TS2322: wrong\n" + noise}, []string{"error TS2322"}, nil}, + "never ran": {forgekey.Ran{Err: "ENOENT"}, []string{"ENOENT"}, nil}, + } + for name, c := range cases { + got := ranFailed(c.ran) + if c.want == nil && got != "" { + t.Errorf("%s: %q, want none", name, got) + } + for _, w := range c.want { + if !strings.Contains(got, w) { + t.Errorf("%s: %q lacks %q", name, got, w) + } + } + for _, w := range c.wantNot { + if strings.Contains(got, w) { + t.Errorf("%s: %q carries %q", name, got, w) + } + } + if len(got) > failedBytes+100 { + t.Errorf("%s: %d bytes, past its bound", name, len(got)) + } + } +} diff --git a/modules/mesh-build-node/cmd/mesh-build-node/workspace.go b/modules/mesh-build-node/cmd/mesh-build-node/workspace.go index c49f6cc7..845bf4ce 100644 --- a/modules/mesh-build-node/cmd/mesh-build-node/workspace.go +++ b/modules/mesh-build-node/cmd/mesh-build-node/workspace.go @@ -180,14 +180,28 @@ func (m *Module) runIn(ctx context.Context, root string, write bool, dir string, return run(ctx, extra, "env", append([]string{"-C", dir, name}, args...)...) } -// ranFailed says why a command did not pass, or "" when it did. +// ranFailed says why a command did not pass, or "" when it did (issue 1703): its exit status, the end of what it wrote +// on stderr (npm's error is its last lines) and the start of what it wrote on stdout (tsc writes its errors there, +// first first), each bounded, so a long stdout never pushes stderr's error out of the reason. func ranFailed(r forgekey.Ran) string { if r.Status == 0 && r.Err == "" { return "" } - out := strings.TrimSpace(r.Stdout + "\n" + r.Stderr) - if len(out) > 1500 { - out = out[:1500] + " ..." + why := fmt.Sprintf("status %d %s", r.Status, r.Err) + if e := strings.TrimSpace(r.Stderr); e != "" { + if len(e) > failedBytes/2 { + e = "... " + e[len(e)-failedBytes/2:] + } + why += ": stderr: " + e } - return fmt.Sprintf("status %d %s: %s", r.Status, r.Err, out) + if o := strings.TrimSpace(r.Stdout); o != "" { + if len(o) > failedBytes/2 { + o = o[:failedBytes/2] + " ..." + } + why += ": stdout: " + o + } + return why } + +// failedBytes bounds what ranFailed carries of a command's output, stderr and stdout half each. +const failedBytes = 1500