mesh-build-go: a failed test keeps its last lines and its error line, not its first fifteen (issue 1901)

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

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.
+// outputBytes is the most a failure keeps of its output, and outputLineBytes the most of one line. **A failure keeps its
-const outputLines = 15
+// 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 {
+	size, from := 0, len(lines)
-		lines = append(lines[:outputLines:outputLines], fmt.Sprintf("... (%d more lines)", len(lines)-outputLines))
+	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

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}