From 683af3b6cbf57c38c5ebf52d3e60e106bacf4e85 Mon Sep 17 00:00:00 2001 From: mlsmaycon Date: Sat, 12 Sep 2026 12:17:37 +0000 Subject: [PATCH] [misc] Track panics and package output per package in gotestsummary go test -json interleaves the streams of packages that run in parallel, so a single panic flag let one package's goroutine dump swallow the output of every other package until its own fail event. Keep the panic head per package and clear it with that package's result. A test that hangs before printing anything is now registered on its run event, so the unfinished list names it. Output a package prints outside any test, which is where compiler diagnostics of a failed build land, was dropped; it is buffered and printed when the package fails, including the build-fail event newer Go versions emit. --- tools/gotestsummary/main.go | 113 +++++++++++++++++++++++-------- tools/gotestsummary/main_test.go | 112 ++++++++++++++++++++++++++++++ 2 files changed, 196 insertions(+), 29 deletions(-) create mode 100644 tools/gotestsummary/main_test.go diff --git a/tools/gotestsummary/main.go b/tools/gotestsummary/main.go index cff975e29..5870ecd78 100644 --- a/tools/gotestsummary/main.go +++ b/tools/gotestsummary/main.go @@ -48,6 +48,9 @@ type event struct { Test string `json:"Test"` Output string `json:"Output"` Elapsed float64 `json:"Elapsed"` + // ImportPath is set instead of Package on build events; it carries a + // " [pkg.test]" suffix for a test binary. + ImportPath string `json:"ImportPath"` } type testKey struct { @@ -71,13 +74,18 @@ type packageResult struct { type summarizer struct { out io.Writer - output map[testKey][]string - dropped map[testKey]int + output map[testKey][]string + dropped map[testKey]int + // pkgOutput keeps what a package printed outside any test, which is where + // compiler diagnostics of a failed build end up. + pkgOutput map[string][]string stores map[testKey]storeStats tests []testResult packages []packageResult - panicHead []string - panicking bool + // panics holds the head of a panic per package. Package streams interleave + // in a go test -json run, so one package's dump must not swallow another's + // output. + panics map[string][]string } type storeStats struct { @@ -87,10 +95,12 @@ type storeStats struct { func newSummarizer(out io.Writer) *summarizer { return &summarizer{ - out: out, - output: make(map[testKey][]string), - dropped: make(map[testKey]int), - stores: make(map[testKey]storeStats), + out: out, + output: make(map[testKey][]string), + dropped: make(map[testKey]int), + pkgOutput: make(map[string][]string), + stores: make(map[testKey]storeStats), + panics: make(map[string][]string), } } @@ -140,10 +150,23 @@ func (s *summarizer) consume(r io.Reader) error { } func (s *summarizer) handle(ev event) { + if ev.Package == "" && ev.ImportPath != "" { + ev.Package, _, _ = strings.Cut(ev.ImportPath, " [") + } key := testKey{pkg: ev.Package, name: ev.Test} switch ev.Action { - case "output": + case "run": + // Register the test even before it prints anything, so a test that + // hangs silently still shows up as unfinished. + if ev.Test != "" { + if _, ok := s.output[key]; !ok { + s.output[key] = []string{} + } + } + case "output", "build-output": s.handleOutput(key, strings.TrimRight(ev.Output, "\n")) + case "build-fail": + s.handlePackageResult(ev) case "pass", "fail", "skip": if ev.Test == "" { s.handlePackageResult(ev) @@ -155,13 +178,15 @@ func (s *summarizer) handle(ev event) { func (s *summarizer) handleOutput(key testKey, line string) { if strings.HasPrefix(line, "panic: ") || strings.HasPrefix(line, "fatal error: ") { - s.panicking = true + if _, ok := s.panics[key.pkg]; !ok { + s.panics[key.pkg] = []string{} + } } - if s.panicking { - // The goroutine dump that follows a panic is kept in panicHead only; + if head, ok := s.panics[key.pkg]; ok { + // The goroutine dump that follows a panic is kept in the panic head only; // letting it flood the per-test buffers would hide the test's own output. - if len(s.panicHead) < panicHeadLines { - s.panicHead = append(s.panicHead, line) + if len(head) < panicHeadLines { + s.panics[key.pkg] = append(head, line) } return } @@ -176,14 +201,21 @@ func (s *summarizer) handleOutput(key testKey, line string) { } if key.name == "" { + s.pkgOutput[key.pkg] = appendBounded(s.pkgOutput[key.pkg], line) return } - buf := s.output[key] - if len(buf) >= bufferedOutputLines { - buf = buf[1:] + if len(s.output[key]) >= bufferedOutputLines { s.dropped[key]++ } - s.output[key] = append(buf, line) + s.output[key] = appendBounded(s.output[key], line) +} + +// appendBounded keeps the most recent bufferedOutputLines lines. +func appendBounded(buf []string, line string) []string { + if len(buf) >= bufferedOutputLines { + buf = buf[1:] + } + return append(buf, line) } func (s *summarizer) handleTestResult(key testKey, ev event) { @@ -232,26 +264,49 @@ func (s *summarizer) handlePackageResult(ev event) { label := "ok " switch ev.Action { - case "fail": + case "fail", "build-fail": label = "FAIL" case "skip": label = "skip" } fmt.Fprintf(s.out, "%s %s %s\n", label, shortPkg(ev.Package), elapsed.Round(time.Millisecond)) - if ev.Action == "fail" { + if label == "FAIL" { + s.printPackageOutput(ev.Package) s.printUnfinished(ev.Package) + s.printPanicHead(ev.Package) } - if ev.Action == "fail" && len(s.panicHead) > 0 { - fmt.Fprintf(s.out, "\n==== panic in %s (first %d lines) ====\n", shortPkg(ev.Package), len(s.panicHead)) - for _, l := range s.panicHead { - fmt.Fprintln(s.out, l) - } - fmt.Fprintln(s.out, "==== end of panic head ====") - fmt.Fprintln(s.out) - s.panicHead = nil - s.panicking = false + delete(s.pkgOutput, ev.Package) + delete(s.panics, ev.Package) +} + +// printPackageOutput shows what a failed package printed outside its tests, +// such as the compiler errors of a build failure. +func (s *summarizer) printPackageOutput(pkg string) { + lines := s.pkgOutput[pkg] + if len(lines) == 0 { + return } + if len(lines) > failedTestOutputLines { + lines = lines[len(lines)-failedTestOutputLines:] + } + fmt.Fprintf(s.out, "\n==== output of %s outside tests ====\n", shortPkg(pkg)) + for _, l := range lines { + fmt.Fprintf(s.out, " %s\n", l) + } +} + +func (s *summarizer) printPanicHead(pkg string) { + head := s.panics[pkg] + if len(head) == 0 { + return + } + fmt.Fprintf(s.out, "\n==== panic in %s (first %d lines) ====\n", shortPkg(pkg), len(head)) + for _, l := range head { + fmt.Fprintln(s.out, l) + } + fmt.Fprintln(s.out, "==== end of panic head ====") + fmt.Fprintln(s.out) } // printUnfinished names the tests of a failed package that never reported a diff --git a/tools/gotestsummary/main_test.go b/tools/gotestsummary/main_test.go new file mode 100644 index 000000000..202fff2f6 --- /dev/null +++ b/tools/gotestsummary/main_test.go @@ -0,0 +1,112 @@ +package main + +import ( + "bytes" + "strings" + "testing" +) + +func feed(t *testing.T, events string) string { + t.Helper() + var out bytes.Buffer + s := newSummarizer(&out) + if err := s.consume(strings.NewReader(events)); err != nil { + t.Fatalf("consume: %v", err) + } + s.printSummary(10) + return out.String() +} + +func TestTimeoutReportsUnfinishedTestsAndPanicHead(t *testing.T) { + events := ` +{"Action":"run","Package":"a","Test":"TestHang"} +{"Action":"output","Package":"a","Test":"TestHang","Output":"=== RUN TestHang\n"} +{"Action":"run","Package":"a","Test":"TestSilent"} +{"Action":"output","Package":"a","Test":"TestHang","Output":"panic: test timed out after 1s\n"} +{"Action":"output","Package":"a","Test":"TestHang","Output":"\trunning tests:\n"} +{"Action":"output","Package":"a","Test":"TestHang","Output":"\t\tTestHang (1s)\n"} +{"Action":"output","Package":"a","Test":"TestHang","Output":"goroutine 7 [running]:\n"} +{"Action":"fail","Package":"a","Elapsed":1.0} +` + got := feed(t, events) + for _, want := range []string{ + "--- UNFINISHED: a.TestHang", + "--- UNFINISHED: a.TestSilent", + "==== panic in a (first 4 lines) ====", + "\t\tTestHang (1s)", + " === RUN TestHang", + } { + if !strings.Contains(got, want) { + t.Errorf("output lacks %q:\n%s", want, got) + } + } + if strings.Contains(got, " goroutine 7 [running]:") { + t.Errorf("goroutine dump leaked into the test's own output:\n%s", got) + } +} + +func TestPanicInOnePackageKeepsOtherPackageOutput(t *testing.T) { + events := ` +{"Action":"run","Package":"a","Test":"TestHang"} +{"Action":"output","Package":"a","Test":"TestHang","Output":"panic: test timed out after 1s\n"} +{"Action":"run","Package":"b","Test":"TestOther"} +{"Action":"output","Package":"b","Test":"TestOther","Output":" other_test.go:9: expected 1, got 2\n"} +{"Action":"output","Package":"a","Test":"TestHang","Output":"goroutine 7 [running]:\n"} +{"Action":"fail","Package":"b","Test":"TestOther","Elapsed":0.01} +{"Action":"fail","Package":"b","Elapsed":0.02} +{"Action":"fail","Package":"a","Elapsed":1.0} +` + got := feed(t, events) + if !strings.Contains(got, " other_test.go:9: expected 1, got 2") { + t.Errorf("other package's output was swallowed by the panic head:\n%s", got) + } + if strings.Contains(got, "panic in b") { + t.Errorf("panic head attributed to the wrong package:\n%s", got) + } + if !strings.Contains(got, "==== panic in a (first 2 lines) ====") { + t.Errorf("panic head missing for package a:\n%s", got) + } +} + +func TestStoreSetupTimeIsAttributedToTheTest(t *testing.T) { + events := ` +{"Action":"run","Package":"a","Test":"TestStore"} +{"Action":"output","Package":"a","Test":"TestStore","Output":"level=info msg=\"test store created: engine=mysql total=1.5s sqlite=100ms engine_setup=1.4s\"\n"} +{"Action":"output","Package":"a","Test":"TestStore","Output":"level=info msg=\"test store created: engine=mysql total=500ms sqlite=100ms engine_setup=400ms\"\n"} +{"Action":"pass","Package":"a","Test":"TestStore","Elapsed":2.5} +{"Action":"pass","Package":"a","Elapsed":2.6} +` + got := feed(t, events) + if !strings.Contains(got, "a.TestStore [stores: 2, 2s]") { + t.Errorf("store setup not aggregated:\n%s", got) + } +} + +func TestBuildFailureShowsCompilerOutput(t *testing.T) { + events := ` +{"Action":"build-output","ImportPath":"a [a.test]","Output":"# a [a.test]\n"} +{"Action":"build-output","ImportPath":"a [a.test]","Output":"a_test.go:7:2: undefined: nope\n"} +{"Action":"build-fail","ImportPath":"a [a.test]"} +` + got := feed(t, events) + for _, want := range []string{ + "FAIL a 0s", + "==== output of a outside tests ====", + " a_test.go:7:2: undefined: nope", + } { + if !strings.Contains(got, want) { + t.Errorf("output lacks %q:\n%s", want, got) + } + } +} + +func TestPassingPackageOutputIsNotPrinted(t *testing.T) { + events := ` +{"Action":"output","Package":"a","Output":"level=info msg=\"noise between tests\"\n"} +{"Action":"pass","Package":"a","Elapsed":0.5} +` + got := feed(t, events) + if strings.Contains(got, "noise between tests") { + t.Errorf("package output of a passing package should stay quiet:\n%s", got) + } +}