Merge pull request 'Image builds run their RUN steps on pasta, and every build failure keeps its real error (issue 1703)' (#502) from fix/1703-image-error-shown into main

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 `# <package>` 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
 		}
 	}

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 `# <package>` 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)
+		}
+	}
+}

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) {
+	if r.Status != 0 || r.Err != "" {
-		return "", fmt.Errorf("the digest of the image %s could not be read: %s", name, lastLine(r.Err+"\n"+r.Stderr+"\n"+r.Stdout))
+		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 ""
-}

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.
+// 1703c, issue 1703: a failing Dockerfile step fails the step, its reason saying buildah's error from stderr, never the
-func TestBuildFailsWithBuildahsLastLine(t *testing.T) {
+// last STEP line buildah writes on stdout; nothing is pushed.
-	m, f, states := setup(t, same)
+func TestBuildFailsWithBuildahsError(t *testing.T) {
-	f.failBud = "Error: building at STEP \"RUN false\": exit status 1"
+	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"
-	_, st := runBuild(t, m, states, nil)
+	long := strings.Repeat("x", 2*CauseBytes)
-	if st.State != delivery.StepFailed || !strings.Contains(st.Reason, `STEP "RUN false"`) {
+	cases := map[string]struct {
-		t.Errorf("step = %+v", st)
+		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 {
+	for name, c := range cases {
-		t.Error("a failed build pushed")
+		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)
+		}
 	}
 }
 

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"))
+}

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"
+	refuse  int          // the first n pushes answer "connection refused"
-	failBud string
+	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 != "" {
+		if f.failBud.Status != 0 || f.failBud.Err != "" {
-			return forgekey.Ran{Status: 1, Stderr: "STEP 1/2: FROM x\n" + f.failBud + "\n"}
+			return f.failBud
 		}
 	case name == "buildah" && strings.Contains(line, " images "):
 		return forgekey.Ran{Stdout: f.digest + "\n"}

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)
 	}
 }
 

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...)
+		last = m.Run(ctx, m.env(), "buildah", argv...)
-		if r.Status != 0 || r.Err != "" {
+		if last.Status != 0 || last.Err != "" {
-			return errors.New(lastLine(r.Err + "\n" + r.Stderr + "\n" + r.Stdout))
+			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

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))
+		}
+	}
+}

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)
+	why := fmt.Sprintf("status %d %s", r.Status, r.Err)
-	if len(out) > 1500 {
+	if e := strings.TrimSpace(r.Stderr); e != "" {
-		out = out[:1500] + " ..."
+		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