[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

@@ -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
+	output  map[testKey][]string
-	dropped   map[testKey]int
+	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
+	// panics holds the head of a panic per package. Package streams interleave
-	panicking bool
+	// 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,
+		out:       out,
-		output:  make(map[testKey][]string),
+		output:    make(map[testKey][]string),
-		dropped: make(map[testKey]int),
+		dropped:   make(map[testKey]int),
-		stores:  make(map[testKey]storeStats),
+		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 {
+	if head, ok := s.panics[key.pkg]; ok {
-		// The goroutine dump that follows a panic is kept in panicHead only;
+		// 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 {
+		if len(head) < panicHeadLines {
-			s.panicHead = append(s.panicHead, line)
+			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(s.output[key]) >= bufferedOutputLines {
-	if len(buf) >= bufferedOutputLines {
-		buf = buf[1:]
 		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 {
+	delete(s.pkgOutput, ev.Package)
-		fmt.Fprintf(s.out, "\n==== panic in %s (first %d lines) ====\n", shortPkg(ev.Package), len(s.panicHead))
+	delete(s.panics, ev.Package)
-		for _, l := range s.panicHead {
+}
-			fmt.Fprintln(s.out, l)
+
-		}
+// printPackageOutput shows what a failed package printed outside its tests,
-		fmt.Fprintln(s.out, "==== end of panic head ====")
+// such as the compiler errors of a build failure.
-		fmt.Fprintln(s.out)
+func (s *summarizer) printPackageOutput(pkg string) {
-		s.panicHead = nil
+	lines := s.pkgOutput[pkg]
-		s.panicking = false
+	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

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