Merge pull request #298 from gotestyourself/missing-panic-output

Print the test timeout panic as package output

.project/golangci-lint.yml

@@ -1,6 +1,4 @@
 linters-settings:
-  gocyclo:
-    min-complexity: 12
   goconst:
     min-len: 2
     min-occurrences: 4
@@ -33,7 +31,6 @@ linters:
     - errcheck
     - gocognit
     - goconst
-    - gocyclo
     - gofmt
     - goimports
     - gosimple

testjson/execution.go

@@ -109,6 +109,11 @@ type Package struct {
 	// shuffleSeed is the seed used to shuffle the tests. The value is set when
 	// tests are run with -shuffle
 	shuffleSeed string
+
+	// testTimeoutPanicInTest stores the name of a test that received the panic
+	// output caused by a test timeout. This is necessary to work around a race
+	// condition in test2json. See https://github.com/golang/go/issues/57305.
+	testTimeoutPanicInTest string
 }
 
 // Result returns if the package passed, failed, or was skipped because there
@@ -398,6 +403,14 @@ func (p *Package) addTestEvent(event TestEvent) {
 
 	switch event.Action {
 	case ActionOutput, ActionBench:
+		if strings.HasPrefix(event.Output, "panic: test timed out") {
+			p.testTimeoutPanicInTest = event.Test
+		}
+		if p.testTimeoutPanicInTest == event.Test {
+			p.addOutput(0, event.Output)
+			return
+		}
+
 		tc := p.running[event.Test]
 		p.addOutput(tc.ID, event.Output)
 		return
@@ -491,8 +504,10 @@ func (e *Execution) Failed() []TestCase {
 	for _, name := range sortedKeys(e.packages) {
 		pkg := e.packages[name]
 
-		// Add package-level failure output if there were no failed tests.
-		if pkg.TestMainFailed() {
+		// Add package-level failure output if there were no failed tests, or
+		// if the test timeout was reached (because we now have to store that
+		// output on the package).
+		if pkg.TestMainFailed() || pkg.testTimeoutPanicInTest != "" {
 			failed = append(failed, TestCase{Package: name})
 		}
 		failed = append(failed, pkg.Failed...)

testjson/format.go

@@ -67,7 +67,7 @@ func testNameFormat(event TestEvent, exec *Execution) string {
 		}
 
 		event.Elapsed = 0 // hide elapsed for now, for backwards compat
-		return result + " " + packageLine(event, exec)
+		return result + " " + packageLine(event, exec.Package(event.Package))
 
 	case event.Action == ActionFail:
 		pkg := exec.Package(event.Package)
@@ -152,7 +152,7 @@ func shortFormatPackageEvent(opts FormatOptions, event TestEvent, exec *Executio
 	}
 
 	fmtEvent := func(action string) string {
-		return action + "  " + packageLine(event, exec)
+		return action + "  " + packageLine(event, exec.Package(event.Package))
 	}
 	withColor := colorEvent(event)
 	switch event.Action {
@@ -175,9 +175,7 @@ func shortFormatPackageEvent(opts FormatOptions, event TestEvent, exec *Executio
 	return ""
 }
 
-func packageLine(event TestEvent, exec *Execution) string {
-	pkg := exec.Package(event.Package)
-
+func packageLine(event TestEvent, pkg *Package) string {
 	var buf strings.Builder
 	buf.WriteString(RelativePackagePath(event.Package))
 

testjson/summary_test.go

@@ -7,6 +7,7 @@ import (
 	"testing"
 	"time"
 
+	"gotest.tools/gotestsum/internal/text"
 	"gotest.tools/v3/assert"
 	"gotest.tools/v3/golden"
 )
@@ -319,3 +320,19 @@ func scanConfigFromGolden(filename string) func(t *testing.T) ScanConfig {
 		return ScanConfig{Stdout: bytes.NewReader(golden.Get(t, filename))}
 	}
 }
+
+func TestSummary_TestTimeoutPanicRace(t *testing.T) {
+	source := golden.Get(t, "input/go-test-json-panic-race.out")
+	cfg := ScanConfig{
+		Stdout:  bytes.NewReader(source),
+		Handler: &captureHandler{},
+	}
+	exec, err := ScanTestOutput(cfg)
+	assert.NilError(t, err)
+
+	out := new(bytes.Buffer)
+	PrintSummary(out, exec, SummarizeAll)
+
+	actual := text.ProcessLines(t, out, text.OpRemoveSummaryLineElapsedTime)
+	golden.Assert(t, actual, "summary/test-timeout-panic-race")
+}

testjson/testdata/input/go-test-json-panic-race.out

@@ -0,0 +1,39 @@
+{"Time":"2022-12-14T09:49:01.562401799Z","Action":"start","Package":"github.com/mafredri/test"}
+{"Time":"2022-12-14T09:49:01.569546938Z","Action":"run","Package":"github.com/mafredri/test","Test":"TestHello"}
+{"Time":"2022-12-14T09:49:01.569700427Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"=== RUN   TestHello\n"}
+{"Time":"2022-12-14T09:49:02.569759117Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"    main_test.go:11: Hello\n"}
+{"Time":"2022-12-14T09:49:02.56982657Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"--- PASS: TestHello (1.00s)\n"}
+{"Time":"2022-12-14T09:49:02.572963923Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"panic: test timed out after 1s\n"}
+{"Time":"2022-12-14T09:49:02.572982687Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"running tests:\n"}
+{"Time":"2022-12-14T09:49:02.572992095Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\tTestHello (1s)\n"}
+{"Time":"2022-12-14T09:49:02.573000907Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\n"}
+{"Time":"2022-12-14T09:49:02.573019868Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"goroutine 33 [running]:\n"}
+{"Time":"2022-12-14T09:49:02.573029067Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"testing.(*M).startAlarm.func1()\n"}
+{"Time":"2022-12-14T09:49:02.573038878Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:2240 +0x3b9\n"}
+{"Time":"2022-12-14T09:49:02.573064315Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"created by time.goFunc\n"}
+{"Time":"2022-12-14T09:49:02.573079975Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t/home/mafredri/sdk/go1.20rc1/src/time/sleep.go:176 +0x32\n"}
+{"Time":"2022-12-14T09:49:02.573097493Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\n"}
+{"Time":"2022-12-14T09:49:02.573119064Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"goroutine 1 [runnable]:\n"}
+{"Time":"2022-12-14T09:49:02.573141104Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"testing.(*T).Run(0xc000083040, {0x5be88c?, 0x4ce6c5?}, 0x6072a0)\n"}
+{"Time":"2022-12-14T09:49:02.573162696Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:1629 +0x405\n"}
+{"Time":"2022-12-14T09:49:02.573178743Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"testing.runTests.func1(0x7438e0?)\n"}
+{"Time":"2022-12-14T09:49:02.573203585Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:2035 +0x45\n"}
+{"Time":"2022-12-14T09:49:02.57321895Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"testing.tRunner(0xc000083040, 0xc00025fc88)\n"}
+{"Time":"2022-12-14T09:49:02.573239542Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:1575 +0x10b\n"}
+{"Time":"2022-12-14T09:49:02.573342015Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"testing.runTests(0xc0000c0500?, {0x739320, 0x2, 0x2}, {0x0?, 0x100c0000ab938?, 0x743080?})\n"}
+{"Time":"2022-12-14T09:49:02.573376752Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:2033 +0x489\n"}
+{"Time":"2022-12-14T09:49:02.573403856Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"testing.(*M).Run(0xc0000c0500)\n"}
+{"Time":"2022-12-14T09:49:02.573433691Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:1905 +0x63a\n"}
+{"Time":"2022-12-14T09:49:02.573456763Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"main.main()\n"}
+{"Time":"2022-12-14T09:49:02.573483156Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t_testmain.go:49 +0x1aa\n"}
+{"Time":"2022-12-14T09:49:02.573503088Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\n"}
+{"Time":"2022-12-14T09:49:02.573520911Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"goroutine 20 [runnable]:\n"}
+{"Time":"2022-12-14T09:49:02.573539195Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"runtime.goexit1()\n"}
+{"Time":"2022-12-14T09:49:02.573576101Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t/home/mafredri/sdk/go1.20rc1/src/runtime/proc.go:3616 +0x54\n"}
+{"Time":"2022-12-14T09:49:02.573596375Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"runtime.goexit()\n"}
+{"Time":"2022-12-14T09:49:02.573620424Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t/home/mafredri/sdk/go1.20rc1/src/runtime/asm_amd64.s:1599 +0x6\n"}
+{"Time":"2022-12-14T09:49:02.573637148Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"created by testing.(*T).Run\n"}
+{"Time":"2022-12-14T09:49:02.573690092Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:1628 +0x3ea\n"}
+{"Time":"2022-12-14T09:49:02.574702109Z","Action":"pass","Package":"github.com/mafredri/test","Test":"TestHello","Elapsed":1}
+{"Time":"2022-12-14T09:49:02.57473959Z","Action":"output","Package":"github.com/mafredri/test","Output":"FAIL\tgithub.com/mafredri/test\t1.012s\n"}
+{"Time":"2022-12-14T09:49:02.574754586Z","Action":"fail","Package":"github.com/mafredri/test","Elapsed":1.012}

testjson/testdata/summary/test-timeout-panic-race

@@ -0,0 +1,37 @@
+
+=== Failed
+=== FAIL: github.com/mafredri/test  (0.00s)
+panic: test timed out after 1s
+running tests:
+	TestHello (1s)
+
+goroutine 33 [running]:
+testing.(*M).startAlarm.func1()
+	/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:2240 +0x3b9
+created by time.goFunc
+	/home/mafredri/sdk/go1.20rc1/src/time/sleep.go:176 +0x32
+
+goroutine 1 [runnable]:
+testing.(*T).Run(0xc000083040, {0x5be88c?, 0x4ce6c5?}, 0x6072a0)
+	/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:1629 +0x405
+testing.runTests.func1(0x7438e0?)
+	/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:2035 +0x45
+testing.tRunner(0xc000083040, 0xc00025fc88)
+	/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:1575 +0x10b
+testing.runTests(0xc0000c0500?, {0x739320, 0x2, 0x2}, {0x0?, 0x100c0000ab938?, 0x743080?})
+	/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:2033 +0x489
+testing.(*M).Run(0xc0000c0500)
+	/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:1905 +0x63a
+main.main()
+	_testmain.go:49 +0x1aa
+
+goroutine 20 [runnable]:
+runtime.goexit1()
+	/home/mafredri/sdk/go1.20rc1/src/runtime/proc.go:3616 +0x54
+runtime.goexit()
+	/home/mafredri/sdk/go1.20rc1/src/runtime/asm_amd64.s:1599 +0x6
+created by testing.(*T).Run
+	/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:1628 +0x3ea
+FAIL	github.com/mafredri/test	1.012s
+
+DONE 1 tests, 1 failure