From 2cdb9b8fc42381b6118e36944c89589a0863e7d1 Mon Sep 17 00:00:00 2001 From: jochen Date: Fri, 23 Oct 2026 18:07:23 +0200 Subject: [PATCH 1/3] mesh-build-go: a failed test keeps its last lines and its error line, not its first fifteen (issue 1901) --- .../cmd/mesh-build-go/failure_words_test.go | 48 +++++++++++++++ .../mesh-build-go/cmd/mesh-build-go/levels.go | 60 ++++++++++++++++--- .../go-test-json-log-then-fatal.jsonl | 13 ++++ 3 files changed, 113 insertions(+), 8 deletions(-) create mode 100644 modules/mesh-build-go/cmd/mesh-build-go/failure_words_test.go create mode 100644 modules/mesh-build-go/cmd/mesh-build-go/testdata/captured/go-test-json-log-then-fatal.jsonl diff --git a/modules/mesh-build-go/cmd/mesh-build-go/failure_words_test.go b/modules/mesh-build-go/cmd/mesh-build-go/failure_words_test.go new file mode 100644 index 00000000..fede32e4 --- /dev/null +++ b/modules/mesh-build-go/cmd/mesh-build-go/failure_words_test.go @@ -0,0 +1,48 @@ +package main + +import ( + "os" + "strings" + "testing" +) + +// A failed test keeps the lines that say why it failed, not the lines it logged first (issue 1901). The fixture is +// the real `go test -json` of a test that logs a line and then fails with a multi-line t.Fatalf. +func TestAFailedTestKeepsItsFatalMessageAfterItsLogLines(t *testing.T) { + raw, err := os.ReadFile("testdata/captured/go-test-json-log-then-fatal.jsonl") + if err != nil { + t.Fatal(err) + } + res := &TestResult{} + rd := newReader(res, ".") + rd.read(string(raw)) + rd.finish() + if len(res.Failed) != 1 { + t.Fatalf("failures = %+v, want one", res.Failed) + } + f := res.Failed[0] + for _, want := range []string{"3 subscription(s) derive to a subject no emitter owns:", "a.b.c", "d.e.f", "g.h.i"} { + if !strings.Contains(f.Output, want) { + t.Errorf("1901/AC1: output lacks %q: %q", want, f.Output) + } + } + if want := "3 subscription(s) derive to a subject no emitter owns:"; f.Cause != want && !strings.HasSuffix(f.Cause, want) { + t.Errorf("1901/AC2: cause = %q, want the t.Fatalf line, not the t.Logf line", f.Cause) + } +} + +// A failure longer than the bound keeps its last lines, where the cause is, and says how many earlier lines it dropped. +func TestAFailureLongerThanTheBoundKeepsItsLastLines(t *testing.T) { + var lines []string + for i := 0; i < 400; i++ { + lines = append(lines, " x_test.go:1: log line "+strings.Repeat("y", 40)) + } + lines = append(lines, " x_test.go:9: the real cause", "--- FAIL: TestX (0.00s)") + out := clip(lines) + if len(out) > outputBytes+100 { + t.Errorf("1901/AC1: kept %d bytes, bound is %d", len(out), outputBytes) + } + if !strings.HasSuffix(out, "the real cause\n--- FAIL: TestX (0.00s)") || !strings.HasPrefix(out, "... (") { + t.Errorf("1901/AC1: out = %q...%q", out[:40], out[len(out)-60:]) + } +} diff --git a/modules/mesh-build-go/cmd/mesh-build-go/levels.go b/modules/mesh-build-go/cmd/mesh-build-go/levels.go index 6af18e3f..3d921649 100644 --- a/modules/mesh-build-go/cmd/mesh-build-go/levels.go +++ b/modules/mesh-build-go/cmd/mesh-build-go/levels.go @@ -9,6 +9,7 @@ import ( "bufio" "encoding/json" "fmt" + "regexp" "sort" "strings" "time" @@ -49,11 +50,13 @@ type TestTime struct { } // Failure is a test that failed, or a package that failed with no test to name (a build that failed, a TestMain that -// panicked); Output is the first lines it wrote. +// panicked); Output is the last lines it wrote, up to outputBytes (issue 1901), and Cause the first line of what the +// test reported as its error (t.Error, t.Fatal), without its file and line, when go test said which lines those were. type Failure struct { Package string `json:"package"` Test string `json:"test,omitempty"` Output string `json:"output,omitempty"` + Cause string `json:"cause,omitempty"` } // TestResult is what a test step passes with. @@ -96,13 +99,20 @@ type event struct { Package string Test string Output string + OutputType string // "error" for a t.Error or t.Fatal message, "error-continue" for its further lines (go test -json) ImportPath string FailedBuild string Elapsed float64 } -// outputLines is how many lines of output a failure keeps. -const outputLines = 15 +// outputBytes is the most a failure keeps of its output, and outputLineBytes the most of one line. **A failure keeps its +// last lines** (issue 1901): a test logs before it fails, so the lines that say why are at the end, and the first +// fifteen lines kept before lost them (the verdict of group r4g kept a t.Logf line, not the t.Fatalf after it). Four +// kilobytes holds a long assertion message and stays far under a bus message's or a verdict's bound. +const ( + outputBytes = 4096 + outputLineBytes = 1024 +) // reader collects the events of one go.mod directory's `go test -json` into a result. type reader struct { @@ -113,13 +123,14 @@ type reader struct { builds map[string][]string // build output by import path pkgOut map[string][]string testOut map[string][]string // by package + "\x00" + test + causes map[string]string // the first error line of a test, by the same key times []TestTime failedIn map[string]bool // packages with a failed test } func newReader(res *TestResult, dir string) *reader { return &reader{res: res, dir: dir, pkgs: map[string]*PackageResult{}, builds: map[string][]string{}, - pkgOut: map[string][]string{}, testOut: map[string][]string{}, failedIn: map[string]bool{}} + pkgOut: map[string][]string{}, testOut: map[string][]string{}, causes: map[string]string{}, failedIn: map[string]bool{}} } // read takes go test's output. Lines that are not events are kept for a failure that has nothing else to say. @@ -183,6 +194,9 @@ func (r *reader) event(ev event) { switch ev.Action { case "output": r.testOut[key] = keep(r.testOut[key], ev.Output) + if ev.OutputType == "error" && r.causes[key] == "" { + r.causes[key] = errorWords(ev.Output) + } case "pass", "fail", "skip": p := r.pkg(ev.Package) p.Tests++ @@ -193,17 +207,47 @@ func (r *reader) event(ev event) { r.times = append(r.times, TestTime{Package: ev.Package, Test: ev.Test, Elapsed: ev.Elapsed}) if ev.Action == "fail" { r.failedIn[ev.Package] = true - r.res.Failed = append(r.res.Failed, Failure{Package: ev.Package, Test: ev.Test, Output: clip(r.testOut[key])}) + r.res.Failed = append(r.res.Failed, Failure{Package: ev.Package, Test: ev.Test, Output: clip(r.testOut[key]), Cause: r.causes[key]}) } } } } +// clip joins the last lines of a failure's output that fit outputBytes, each cut to outputLineBytes, and says how many +// earlier lines it left out. func clip(lines []string) string { - if len(lines) > outputLines { - lines = append(lines[:outputLines:outputLines], fmt.Sprintf("... (%d more lines)", len(lines)-outputLines)) + size, from := 0, len(lines) + for from > 0 { + n := len(cutLine(lines[from-1])) + 1 + if size+n > outputBytes && from < len(lines) { + break + } + size += n + from-- } - return strings.Join(lines, "\n") + kept := make([]string, 0, len(lines)-from+1) + if from > 0 { + kept = append(kept, fmt.Sprintf("... (%d earlier lines)", from)) + } + for _, l := range lines[from:] { + kept = append(kept, cutLine(l)) + } + return strings.Join(kept, "\n") +} + +// cutLine cuts a line to outputLineBytes, on a character boundary. +func cutLine(l string) string { + if len(l) <= outputLineBytes { + return l + } + return strings.ToValidUTF8(l[:outputLineBytes], "") + "..." +} + +var fileAndLine = regexp.MustCompile(`^\S+\.go:\d+: `) + +// errorWords is the words of an error line of a test: trimmed, without the file and line go test put before them. +func errorWords(out string) string { + return strings.TrimSpace(fileAndLine.ReplaceAllString(strings.TrimSpace(out), "")) } // finish moves what was read into the result: the packages in order, a failure for each failed package that has no diff --git a/modules/mesh-build-go/cmd/mesh-build-go/testdata/captured/go-test-json-log-then-fatal.jsonl b/modules/mesh-build-go/cmd/mesh-build-go/testdata/captured/go-test-json-log-then-fatal.jsonl new file mode 100644 index 00000000..c59fba2f --- /dev/null +++ b/modules/mesh-build-go/cmd/mesh-build-go/testdata/captured/go-test-json-log-then-fatal.jsonl @@ -0,0 +1,13 @@ +{"Action":"start","Package":"x"} +{"Action":"run","Package":"x","Test":"TestThree"} +{"Action":"output","Package":"x","Test":"TestThree","Output":"=== RUN TestThree\n","OutputType":"frame"} +{"Action":"output","Package":"x","Test":"TestThree","Output":" a_test.go:4: judged against /var/lib/mesh-build-go-work/id/beside/mesh-catalog as cloned\n"} +{"Action":"output","Package":"x","Test":"TestThree","Output":" a_test.go:5: 3 subscription(s) derive to a subject no emitter owns:\n","OutputType":"error"} +{"Action":"output","Package":"x","Test":"TestThree","Output":" a.b.c\n","OutputType":"error-continue"} +{"Action":"output","Package":"x","Test":"TestThree","Output":" d.e.f\n","OutputType":"error-continue"} +{"Action":"output","Package":"x","Test":"TestThree","Output":" g.h.i\n","OutputType":"error-continue"} +{"Action":"output","Package":"x","Test":"TestThree","Output":"--- FAIL: TestThree (0.00s)\n","OutputType":"frame"} +{"Action":"fail","Package":"x","Test":"TestThree","Elapsed":0} +{"Action":"output","Package":"x","Output":"FAIL\n","OutputType":"frame"} +{"Action":"output","Package":"x","Output":"FAIL\tx\t0.002s\n","OutputType":"frame"} +{"Action":"fail","Package":"x","Elapsed":0.002} From 746eb885a3f1fb5cef3f44b61592ec5db7a63819 Mon Sep 17 00:00:00 2001 From: jochen Date: Fri, 23 Oct 2026 22:14:28 +0200 Subject: [PATCH 2/3] Test 1901/AC3: an older pair of build module and checker still agree (issue 1901) --- .../cmd/mesh-build-go/failure_words_test.go | 32 ++++++++++++++++++- 1 file changed, 31 insertions(+), 1 deletion(-) diff --git a/modules/mesh-build-go/cmd/mesh-build-go/failure_words_test.go b/modules/mesh-build-go/cmd/mesh-build-go/failure_words_test.go index fede32e4..7a061993 100644 --- a/modules/mesh-build-go/cmd/mesh-build-go/failure_words_test.go +++ b/modules/mesh-build-go/cmd/mesh-build-go/failure_words_test.go @@ -1,6 +1,7 @@ package main import ( + "encoding/json" "os" "strings" "testing" @@ -27,7 +28,7 @@ func TestAFailedTestKeepsItsFatalMessageAfterItsLogLines(t *testing.T) { } } if want := "3 subscription(s) derive to a subject no emitter owns:"; f.Cause != want && !strings.HasSuffix(f.Cause, want) { - t.Errorf("1901/AC2: cause = %q, want the t.Fatalf line, not the t.Logf line", f.Cause) + t.Errorf("1901/AC1: cause = %q, want the t.Fatalf line, not the t.Logf line", f.Cause) } } @@ -46,3 +47,32 @@ func TestAFailureLongerThanTheBoundKeepsItsLastLines(t *testing.T) { t.Errorf("1901/AC1: out = %q...%q", out[:40], out[len(out)-60:]) } } + +// An older checker, which knows no "cause" field, still reads the new build module's answer, and the output it gets +// holds at least what the older build module kept (its first lines, for an output shorter than the bound). +func TestAnOlderCheckerReadsTheNewFailureAndGetsAtLeastWhatItKept(t *testing.T) { // 1901/AC3 + raw, err := os.ReadFile("testdata/captured/go-test-json-log-then-fatal.jsonl") + if err != nil { + t.Fatal(err) + } + res := &TestResult{} + rd := newReader(res, ".") + rd.read(string(raw)) + rd.finish() + b, err := json.Marshal(res.Failed) + if err != nil { + t.Fatal(err) + } + var old []struct { + Package string `json:"package"` + Test string `json:"test,omitempty"` + Output string `json:"output,omitempty"` + } + if err := json.Unmarshal(b, &old); err != nil || len(old) != 1 { + t.Fatalf("1901/AC3: an older checker refused the answer: %v, %d failures", err, len(old)) + } + first := strings.SplitN(old[0].Output, "\n", 2)[0] + if first == "" || !strings.Contains(old[0].Output, "judged against") || !strings.Contains(old[0].Output, "3 subscription(s)") { + t.Errorf("1901/AC3: older checker's output = %q", old[0].Output) + } +} From dcae699323c8bda7d648a2e1303afaa4f6e19913 Mon Sep 17 00:00:00 2001 From: jochen Date: Fri, 23 Oct 2026 22:26:29 +0200 Subject: [PATCH 3/3] mesh-build-go: a clipped failure starts with its cause, not the marker, for an older checker (issue 1901/AC3) --- .../cmd/mesh-build-go/failure_words_test.go | 38 ++++++++++++++++++- .../mesh-build-go/cmd/mesh-build-go/levels.go | 17 +++++++-- 2 files changed, 49 insertions(+), 6 deletions(-) diff --git a/modules/mesh-build-go/cmd/mesh-build-go/failure_words_test.go b/modules/mesh-build-go/cmd/mesh-build-go/failure_words_test.go index 7a061993..9f82aa72 100644 --- a/modules/mesh-build-go/cmd/mesh-build-go/failure_words_test.go +++ b/modules/mesh-build-go/cmd/mesh-build-go/failure_words_test.go @@ -39,11 +39,11 @@ func TestAFailureLongerThanTheBoundKeepsItsLastLines(t *testing.T) { lines = append(lines, " x_test.go:1: log line "+strings.Repeat("y", 40)) } lines = append(lines, " x_test.go:9: the real cause", "--- FAIL: TestX (0.00s)") - out := clip(lines) + out := clip(lines, "") if len(out) > outputBytes+100 { t.Errorf("1901/AC1: kept %d bytes, bound is %d", len(out), outputBytes) } - if !strings.HasSuffix(out, "the real cause\n--- FAIL: TestX (0.00s)") || !strings.HasPrefix(out, "... (") { + if !strings.HasSuffix(out, "the real cause\n--- FAIL: TestX (0.00s)") || !strings.Contains(out, "\n... (") { t.Errorf("1901/AC1: out = %q...%q", out[:40], out[len(out)-60:]) } } @@ -76,3 +76,37 @@ func TestAnOlderCheckerReadsTheNewFailureAndGetsAtLeastWhatItKept(t *testing.T) t.Errorf("1901/AC3: older checker's output = %q", old[0].Output) } } + +// A long failure, whose earlier lines are left out, still starts with a real line for an older checker, which keeps only the +// first non-empty line of the output cut to 120 characters, and not with the marker. +func TestALongFailureStillStartsWithARealLineForAnOlderChecker(t *testing.T) { // 1901/AC3 + var lines []string + for i := 0; i < 400; i++ { + lines = append(lines, " x_test.go:1: log line "+strings.Repeat("y", 40)) + } + lines = append(lines, " x_test.go:9: the real cause", "--- FAIL: TestX (0.00s)") + oldFirst := func(out string) string { // the older checker's rule (judge.go firstLine) + for _, l := range strings.Split(out, "\n") { + if l = strings.TrimSpace(l); l != "" { + if len(l) > 120 { + l = l[:120] + } + return l + } + } + return "" + } + for _, cause := range []string{"the real cause", ""} { + out := clip(lines, cause) + got := oldFirst(out) + if strings.HasPrefix(got, "... (") || got == "" { + t.Errorf("1901/AC3: cause %q: an older checker would read %q", cause, got) + } + if cause != "" && got != cause { + t.Errorf("1901/AC3: older checker reads %q, want the cause", got) + } + if !strings.HasSuffix(out, "--- FAIL: TestX (0.00s)") { + t.Errorf("1901/AC3: the last lines are lost: %q", out[len(out)-40:]) + } + } +} diff --git a/modules/mesh-build-go/cmd/mesh-build-go/levels.go b/modules/mesh-build-go/cmd/mesh-build-go/levels.go index 3d921649..d247f1a9 100644 --- a/modules/mesh-build-go/cmd/mesh-build-go/levels.go +++ b/modules/mesh-build-go/cmd/mesh-build-go/levels.go @@ -207,15 +207,17 @@ func (r *reader) event(ev event) { r.times = append(r.times, TestTime{Package: ev.Package, Test: ev.Test, Elapsed: ev.Elapsed}) if ev.Action == "fail" { r.failedIn[ev.Package] = true - r.res.Failed = append(r.res.Failed, Failure{Package: ev.Package, Test: ev.Test, Output: clip(r.testOut[key]), Cause: r.causes[key]}) + r.res.Failed = append(r.res.Failed, Failure{Package: ev.Package, Test: ev.Test, Output: clip(r.testOut[key], r.causes[key]), Cause: r.causes[key]}) } } } } // clip joins the last lines of a failure's output that fit outputBytes, each cut to outputLineBytes, and says how many -// earlier lines it left out. -func clip(lines []string) string { +// earlier lines it left out. **When it leaves lines out, its first line is still a real one** (issue 1901/AC3): the failure's +// cause, or failing that the first non-empty line of the output, then the marker. An older checker takes only the first +// non-empty line of the output, and a marker there would be less than the older pair kept. +func clip(lines []string, cause string) string { size, from := 0, len(lines) for from > 0 { n := len(cutLine(lines[from-1])) + 1 @@ -227,6 +229,13 @@ func clip(lines []string) string { } kept := make([]string, 0, len(lines)-from+1) if from > 0 { + head := strings.TrimSpace(cause) + for i := 0; head == "" && i < from; i++ { + head = strings.TrimSpace(lines[i]) + } + if head != "" { + kept = append(kept, cutLine(head)) + } kept = append(kept, fmt.Sprintf("... (%d earlier lines)", from)) } for _, l := range lines[from:] { @@ -256,7 +265,7 @@ func (r *reader) finish() { for _, name := range r.order { p := r.pkgs[name] if !p.Passed && !r.failedIn[name] { - r.res.Failed = append(r.res.Failed, Failure{Package: name, Output: clip(r.pkgOut[name])}) + r.res.Failed = append(r.res.Failed, Failure{Package: name, Output: clip(r.pkgOut[name], "")}) } if !p.NoTests && p.Elapsed > r.res.Elapsed { r.res.Elapsed = p.Elapsed