Merge pull request #357 from dnephin/test-timeout-junitxml

Include test.timeout stack trace in the junit.xml

cmd/handler_test.go

@@ -2,15 +2,17 @@ package cmd
 
 import (
 	"bytes"
-	"io/ioutil"
+	"io"
 	"os"
 	"path/filepath"
 	"strings"
 	"testing"
 
+	"gotest.tools/gotestsum/internal/junitxml"
 	"gotest.tools/gotestsum/internal/text"
 	"gotest.tools/gotestsum/testjson"
 	"gotest.tools/v3/assert"
+	"gotest.tools/v3/assert/cmp"
 	"gotest.tools/v3/env"
 	"gotest.tools/v3/fs"
 	"gotest.tools/v3/golden"
@@ -88,7 +90,7 @@ func TestEventHandler_Event_WithMissingActionFail(t *testing.T) {
 }
 
 func TestEventHandler_Event_MaxFails(t *testing.T) {
-	format := testjson.NewEventFormatter(ioutil.Discard, "testname", testjson.FormatOptions{})
+	format := testjson.NewEventFormatter(io.Discard, "testname", testjson.FormatOptions{})
 
 	source := golden.Get(t, "../../testjson/testdata/input/go-test-json.out")
 	cfg := testjson.ScanConfig{
@@ -132,3 +134,40 @@ func TestWriteJunitFile_CreatesDirectory(t *testing.T) {
 	_, err = os.Stat(junitFile)
 	assert.NilError(t, err)
 }
+
+func TestScanTestOutput_TestTimeoutPanicRace(t *testing.T) {
+	run := func(t *testing.T, name string) {
+		format := testjson.NewEventFormatter(io.Discard, "testname", testjson.FormatOptions{})
+
+		source := golden.Get(t, "input/go-test-json-"+name+".out")
+		cfg := testjson.ScanConfig{
+			Stdout:  bytes.NewReader(source),
+			Handler: &eventHandler{formatter: format},
+		}
+		exec, err := testjson.ScanTestOutput(cfg)
+		assert.NilError(t, err)
+
+		out := new(bytes.Buffer)
+		testjson.PrintSummary(out, exec, testjson.SummarizeAll)
+
+		actual := text.ProcessLines(t, out, text.OpRemoveSummaryLineElapsedTime)
+		golden.Assert(t, actual, "expected/"+name+"-summary")
+
+		var buf bytes.Buffer
+		err = junitxml.Write(&buf, exec, junitxml.Config{})
+		assert.NilError(t, err)
+
+		assert.Assert(t, cmp.Contains(buf.String(), "panic: test timed out"))
+	}
+
+	testCases := []string{
+		"panic-race-1",
+		"panic-race-2",
+	}
+
+	for _, tc := range testCases {
+		t.Run(tc, func(t *testing.T) {
+			run(t, tc)
+		})
+	}
+}

cmd/main.go

@@ -74,7 +74,7 @@ func setupFlags(name string) (*pflag.FlagSet, *options) {
 	flags.StringVar(&opts.jsonFileTimingEvents, "jsonfile-timing-events",
 		lookEnvWithDefault("GOTESTSUM_JSONFILE_TIMING_EVENTS", ""),
 		"write only the pass, skip, and fail TestEvents to the file")
-	flags.BoolVar(&opts.noColor, "no-color", defaultNoColor, "disable color output")
+	flags.BoolVar(&opts.noColor, "no-color", defaultNoColor(), "disable color output")
 
 	flags.Var(opts.hideSummary, "no-summary",
 		"do not print summary of: "+testjson.SummarizeAll.String())
@@ -200,7 +200,7 @@ func (o options) Validate() error {
 	return nil
 }
 
-var defaultNoColor = func() bool {
+func defaultNoColor() bool {
 	// fatih/color will only output color when stdout is a terminal which is not
 	// true for many CI environments which support color output. So instead, we
 	// try to detect these CI environments via their environment variables.
@@ -229,7 +229,7 @@ var defaultNoColor = func() bool {
 		return false
 	}
 	return color.NoColor
-}()
+}
 
 func setupLogging(opts *options) {
 	if opts.debug {

cmd/main_e2e_test.go

@@ -43,7 +43,7 @@ func TestE2E_RerunFails(t *testing.T) {
 
 		envVars := osEnviron()
 		envVars["TEST_SEEDFILE"] = tmpFile.Path()
-		defer env.PatchAll(t, envVars)()
+		env.PatchAll(t, envVars)
 
 		flags, opts := setupFlags("gotestsum")
 		assert.NilError(t, flags.Parse(tc.args))
@@ -218,7 +218,7 @@ func TestE2E_MaxFails_EndTestRun(t *testing.T) {
 
 	envVars := osEnviron()
 	envVars["TEST_SEEDFILE"] = tmpFile.Path()
-	defer env.PatchAll(t, envVars)()
+	env.PatchAll(t, envVars)
 
 	flags, opts := setupFlags("gotestsum")
 	args := []string{"--max-fails=2", "--packages=./testdata/e2e/flaky/", "--", "-tags=testdata"}

cmd/main_test.go

@@ -10,6 +10,7 @@ import (
 	"strings"
 	"testing"
 
+	"github.com/fatih/color"
 	"gotest.tools/gotestsum/testjson"
 	"gotest.tools/v3/assert"
 	"gotest.tools/v3/assert/cmp"
@@ -19,7 +20,8 @@ import (
 )
 
 func TestUsage_WithFlagsFromSetupFlags(t *testing.T) {
-	defer env.PatchAll(t, nil)()
+	env.PatchAll(t, nil)
+	patchNoColor(t, false)
 
 	name := "gotestsum"
 	flags, _ := setupFlags(name)
@@ -29,6 +31,14 @@ func TestUsage_WithFlagsFromSetupFlags(t *testing.T) {
 	golden.Assert(t, buf.String(), "gotestsum-help-text")
 }
 
+func patchNoColor(t *testing.T, value bool) {
+	orig := color.NoColor
+	color.NoColor = value
+	t.Cleanup(func() {
+		color.NoColor = orig
+	})
+}
+
 func TestOptions_Validate_FromFlags(t *testing.T) {
 	type testCase struct {
 		name     string
@@ -97,7 +107,7 @@ func TestGoTestCmdArgs(t *testing.T) {
 	run := func(t *testing.T, name string, tc testCase) {
 		t.Helper()
 		runCase(t, name, func(t *testing.T) {
-			defer env.PatchAll(t, env.ToMap(tc.env))()
+			env.PatchAll(t, env.ToMap(tc.env))
 			actual := goTestCmdArgs(tc.opts, tc.rerunOpts)
 			assert.DeepEqual(t, actual, tc.expected)
 		})

cmd/testdata/expected/panic-race-2-summary

@@ -0,0 +1,41 @@
+
+=== Failed
+=== FAIL: example  (0.00s)
+panic: test timed out after 2s
+running tests:
+	TestSleepsTooLong (2s)
+
+goroutine 17 [running]:
+testing.(*M).startAlarm.func1()
+	/usr/lib/go/src/testing/testing.go:2241 +0x3c5
+created by time.goFunc
+	/usr/lib/go/src/time/sleep.go:176 +0x32
+
+goroutine 1 [chan receive]:
+testing.(*T).Run(0xc0000076c0, {0x52afd7?, 0x4baa25?}, 0x533d98)
+	/usr/lib/go/src/testing/testing.go:1630 +0x405
+testing.runTests.func1(0x6102c0?)
+	/usr/lib/go/src/testing/testing.go:2036 +0x45
+testing.tRunner(0xc0000076c0, 0xc000096c88)
+	/usr/lib/go/src/testing/testing.go:1576 +0x10b
+testing.runTests(0xc000026140?, {0x606c80, 0x1, 0x1}, {0x0?, 0x100c0000a6598?, 0x60fae0?})
+	/usr/lib/go/src/testing/testing.go:2034 +0x489
+testing.(*M).Run(0xc000026140)
+	/usr/lib/go/src/testing/testing.go:1906 +0x63a
+main.main()
+	_testmain.go:47 +0x1aa
+
+goroutine 6 [sleep]:
+time.Sleep(0x4a817c800)
+	/usr/lib/go/src/runtime/time.go:195 +0x135
+gotest.tools/gotestsum/example.TestSleepsTooLong(0x0?)
+	/home/daniel/pers/code/gotestsum/example/testing_test.go:9 +0x25
+testing.tRunner(0xc000007860, 0x533d98)
+	/usr/lib/go/src/testing/testing.go:1576 +0x10b
+created by testing.(*T).Run
+	/usr/lib/go/src/testing/testing.go:1629 +0x3ea
+FAIL	gotest.tools/gotestsum/example	2.003s
+
+=== FAIL: example TestSleepsTooLong (unknown)
+
+DONE 1 tests, 2 failures

cmd/testdata/input/go-test-json-panic-race-2.out

@@ -0,0 +1,38 @@
+{"Time":"2023-08-12T12:54:44.132409933-04:00","Action":"start","Package":"gotest.tools/gotestsum/example"}
+{"Time":"2023-08-12T12:54:44.133131471-04:00","Action":"run","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong"}
+{"Time":"2023-08-12T12:54:44.133140584-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"=== RUN   TestSleepsTooLong\n"}
+{"Time":"2023-08-12T12:54:46.135570065-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"panic: test timed out after 2s\n"}
+{"Time":"2023-08-12T12:54:46.135604434-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"running tests:\n"}
+{"Time":"2023-08-12T12:54:46.135608775-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"\tTestSleepsTooLong (2s)\n"}
+{"Time":"2023-08-12T12:54:46.135611536-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"\n"}
+{"Time":"2023-08-12T12:54:46.135614121-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"goroutine 17 [running]:\n"}
+{"Time":"2023-08-12T12:54:46.135643208-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"testing.(*M).startAlarm.func1()\n"}
+{"Time":"2023-08-12T12:54:46.135647115-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"\t/usr/lib/go/src/testing/testing.go:2241 +0x3c5\n"}
+{"Time":"2023-08-12T12:54:46.135652292-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"created by time.goFunc\n"}
+{"Time":"2023-08-12T12:54:46.135655313-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"\t/usr/lib/go/src/time/sleep.go:176 +0x32\n"}
+{"Time":"2023-08-12T12:54:46.135657739-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"\n"}
+{"Time":"2023-08-12T12:54:46.135660238-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"goroutine 1 [chan receive]:\n"}
+{"Time":"2023-08-12T12:54:46.135662906-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"testing.(*T).Run(0xc0000076c0, {0x52afd7?, 0x4baa25?}, 0x533d98)\n"}
+{"Time":"2023-08-12T12:54:46.135666381-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"\t/usr/lib/go/src/testing/testing.go:1630 +0x405\n"}
+{"Time":"2023-08-12T12:54:46.135668821-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"testing.runTests.func1(0x6102c0?)\n"}
+{"Time":"2023-08-12T12:54:46.135671151-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"\t/usr/lib/go/src/testing/testing.go:2036 +0x45\n"}
+{"Time":"2023-08-12T12:54:46.135673732-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"testing.tRunner(0xc0000076c0, 0xc000096c88)\n"}
+{"Time":"2023-08-12T12:54:46.135676164-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"\t/usr/lib/go/src/testing/testing.go:1576 +0x10b\n"}
+{"Time":"2023-08-12T12:54:46.135678759-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"testing.runTests(0xc000026140?, {0x606c80, 0x1, 0x1}, {0x0?, 0x100c0000a6598?, 0x60fae0?})\n"}
+{"Time":"2023-08-12T12:54:46.135684642-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"\t/usr/lib/go/src/testing/testing.go:2034 +0x489\n"}
+{"Time":"2023-08-12T12:54:46.135687261-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"testing.(*M).Run(0xc000026140)\n"}
+{"Time":"2023-08-12T12:54:46.135715549-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"\t/usr/lib/go/src/testing/testing.go:1906 +0x63a\n"}
+{"Time":"2023-08-12T12:54:46.135718294-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"main.main()\n"}
+{"Time":"2023-08-12T12:54:46.135726996-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"\t_testmain.go:47 +0x1aa\n"}
+{"Time":"2023-08-12T12:54:46.135729722-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"\n"}
+{"Time":"2023-08-12T12:54:46.135732073-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"goroutine 6 [sleep]:\n"}
+{"Time":"2023-08-12T12:54:46.135734314-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"time.Sleep(0x4a817c800)\n"}
+{"Time":"2023-08-12T12:54:46.13573659-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"\t/usr/lib/go/src/runtime/time.go:195 +0x135\n"}
+{"Time":"2023-08-12T12:54:46.135739011-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"gotest.tools/gotestsum/example.TestSleepsTooLong(0x0?)\n"}
+{"Time":"2023-08-12T12:54:46.135760842-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"\t/home/daniel/pers/code/gotestsum/example/testing_test.go:9 +0x25\n"}
+{"Time":"2023-08-12T12:54:46.135763588-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"testing.tRunner(0xc000007860, 0x533d98)\n"}
+{"Time":"2023-08-12T12:54:46.135766232-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"\t/usr/lib/go/src/testing/testing.go:1576 +0x10b\n"}
+{"Time":"2023-08-12T12:54:46.135768744-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"created by testing.(*T).Run\n"}
+{"Time":"2023-08-12T12:54:46.135771535-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Test":"TestSleepsTooLong","Output":"\t/usr/lib/go/src/testing/testing.go:1629 +0x3ea\n"}
+{"Time":"2023-08-12T12:54:46.135869063-04:00","Action":"output","Package":"gotest.tools/gotestsum/example","Output":"FAIL\tgotest.tools/gotestsum/example\t2.003s\n"}
+{"Time":"2023-08-12T12:54:46.135881864-04:00","Action":"fail","Package":"gotest.tools/gotestsum/example","Elapsed":2.003}

cmd/tool/slowest/slowest_test.go

@@ -9,7 +9,7 @@ import (
 )
 
 func TestUsage_WithFlagsFromSetupFlags(t *testing.T) {
-	defer env.PatchAll(t, nil)()
+	env.PatchAll(t, nil)
 
 	name := "gotestsum tool slowest"
 	flags, _ := setupFlags(name)

testjson/execution.go

@@ -250,9 +250,14 @@ func tcIDSet(skipped []TestCase) map[int]struct{} {
 	return result
 }
 
-// TestMainFailed returns true if the package failed, but there were no tests.
-// This may occur if the package init() or TestMain exited non-zero.
+// TestMainFailed returns true if the package has output related to a failure. This
+// may happen if a TestMain or init function panic, or if test timeout
+// is reached and output is associated with the package instead of the running
+// test.
 func (p *Package) TestMainFailed() bool {
+	if p.testTimeoutPanicInTest != "" {
+		return true
+	}
 	return p.action == ActionFail && len(p.Failed) == 0
 }
 
@@ -538,7 +543,7 @@ func (e *Execution) Failed() []TestCase {
 		// 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 != "" {
+		if pkg.TestMainFailed() {
 			failed = append(failed, TestCase{Package: name})
 		}
 		failed = append(failed, pkg.Failed...)

testjson/execution_test.go

@@ -157,7 +157,7 @@ func pkgOutput(id int, line string) map[int][]string {
 	return map[int][]string{id: {line}}
 }
 
-func TestScanOutput_WithMissingEvents(t *testing.T) {
+func TestScanTestOutput_WithMissingEvents(t *testing.T) {
 	source := golden.Get(t, "go-test-json-missing-test-events.out")
 	handler := &captureHandler{}
 	cfg := ScanConfig{
@@ -190,7 +190,7 @@ func TestScanOutput_WithMissingEvents(t *testing.T) {
 	assert.DeepEqual(t, expected, handler.events[start:], cmpTestEventShallow)
 }
 
-func TestScanOutput_WithNonJSONLines(t *testing.T) {
+func TestScanTestOutput_WithNonJSONLines(t *testing.T) {
 	source := golden.Get(t, "go-test-json-with-nonjson-stdout.out")
 	nonJSONLine := "|||This line is not valid test2json output.|||"
 
@@ -218,7 +218,7 @@ func TestScanOutput_WithNonJSONLines(t *testing.T) {
 	}
 }
 
-func TestScanOutput_WithGODEBUG(t *testing.T) {
+func TestScanTestOutput_WithGODEBUG(t *testing.T) {
 	goDebugSource := `HASH[moduleIndex]
 HASH[moduleIndex]: "go1.20.4"
 HASH /usr/lib/go/src/runtime/debuglog_off.go: d6f147198

testjson/summary_test.go

@@ -7,7 +7,6 @@ import (
 	"testing"
 	"time"
 
-	"gotest.tools/gotestsum/internal/text"
 	"gotest.tools/v3/assert"
 	"gotest.tools/v3/golden"
 )
@@ -320,19 +319,3 @@ 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")
-}