novox/mesh-catalog
18
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Build modules: a failed command's reason says its error, not its last progress line (issue 1703)

Browse Source 
buildah writes STEP lines on stdout and its error on stderr, so the last line of both hid every image build's cause.
mesh-build-image's reason is now stderr's last lines (600 bytes) with the exit status, and the journal gets both tails;
mesh-build-node keeps stderr's end and stdout's start apart; mesh-build-go's cause skips go build's '# package' line.
This commit is contained in:
jschoubben
2026-10-26 15:21:01 +01:00
parent 9a8e54d988
commit 98c66fb1e4
9 changed files with 222 additions and 37 deletions
Download Patch File Download Diff File Expand all files Collapse all files
modules/mesh-build-go/cmd/mesh-build-go/fetch.go
+3 -2
View File
@@ -331,10 +331,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
+13
View File
@@ -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
+8 -15
View File
@@ -162,7 +162,8 @@ func (m *Module) build(ctx context.Context, args map[string]any) (any, error) {
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 +205,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 +220,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
+44 -9
View File
@@ -2,6 +2,7 @@ package main
import (
"encoding/json"
"git.novox.be/novox/mesh-sdk/go/forgekey"
"os"
"path/filepath"
"strings"
@@ -117,16 +118,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)
}
}
}
modules/mesh-build-image/cmd/mesh-build-image/cause.go
+90
View File
@@ -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
+3 -3
View File
@@ -71,7 +71,7 @@ type fake struct {
digest string // what `buildah images` prints
pushes int
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 != "" {
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"}
modules/mesh-build-image/cmd/mesh-build-image/push.go
+7 -3
View File
@@ -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
modules/mesh-build-node/cmd/mesh-build-node/build_test.go
+35
View File
@@ -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
+19 -5
View File
@@ -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