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}