mitigate test2json bug causing missing test output

internal/junitxml/report.go

@@ -155,14 +155,16 @@ func packageTestCases(pkg *testjson.Package, formatClassname FormatFunc) []JUnit
 		jtc := newJUnitTestCase(tc, formatClassname)
 		jtc.Failure = &JUnitFailure{
 			Message:  "Failed",
-			Contents: pkg.Output(tc.Test),
+			Contents: strings.Join(pkg.OutputLines(tc), ""),
 		}
 		cases = append(cases, jtc)
 	}
 
 	for _, tc := range pkg.Skipped {
 		jtc := newJUnitTestCase(tc, formatClassname)
-		jtc.SkipMessage = &JUnitSkipMessage{Message: pkg.Output(tc.Test)}
+		jtc.SkipMessage = &JUnitSkipMessage{
+			Message: strings.Join(pkg.OutputLines(tc), ""),
+		}
 		cases = append(cases, jtc)
 	}
 

testjson/execution.go

@@ -69,7 +69,11 @@ type Package struct {
 	Failed  []TestCase
 	Skipped []TestCase
 	Passed  []TestCase
-	output  map[string][]string
+	// output printed by test cases. Output is stored first by root TestCase
+	// name, then by subtest name to mitigate github.com/golang/go/issues/29755.
+	// In the future when that bug is fixed this can be reverted to store all
+	// output by full test name.
+	output map[string]map[string][]string
 	// coverage stores the code coverage output for the package without the
 	// trailing newline (ex: coverage: 91.1% of statements).
 	coverage string
@@ -105,8 +109,68 @@ func (p Package) TestCases() []TestCase {
 }
 
 // Output returns the full test output for a test.
+//
+// Unlike OutputLines() it does not return any extra lines in some cases.
 func (p Package) Output(test string) string {
-	return strings.Join(p.output[test], "")
+	root, sub := splitTestName(test)
+	return strings.Join(p.output[root][sub], "")
+}
+
+// OutputLines returns the full test output for a test as a slice of strings.
+//
+// As a workaround for test output being attributed to the wrong subtest, if:
+//   - the requested test output only contains framing lines (ex: --- FAIL: ), and
+//   - the TestCase is a root TestCase (not a subtest), and
+//   - the TestCase has no subtest failures;
+// then all output for every subtest under the root test is returned.
+// See https://github.com/golang/go/issues/29755.
+func (p Package) OutputLines(tc TestCase) []string {
+	root, sub := splitTestName(tc.Test)
+	lines := p.output[root][sub]
+	// every test will have 2 framing lines, === RUN, and --- {PASS,FAIL}
+	if len(lines) > 2 {
+		return lines
+	}
+
+	// If this is a subtest, or a root test case with subtest failures the
+	// subtest failure output should contain the relevant lines, so we don't need
+	// extra lines.
+	if sub != "" || tc.subTestFailed {
+		return lines
+	}
+	//
+	result := make([]string, 0, len(p.output[root])*2)
+	for _, sub := range testNamesSorted(p.output[root]) {
+		result = append(result, p.output[root][sub]...)
+	}
+	return result
+}
+
+func testNamesSorted(subs map[string][]string) []string {
+	names := make([]string, 0, len(subs))
+	for name := range subs {
+		names = append(names, name)
+	}
+	sort.Strings(names)
+	return names
+}
+
+func (p Package) addOutput(test string, output string) {
+	root, sub := splitTestName(test)
+	if p.output[root] == nil {
+		p.output[root] = make(map[string][]string)
+	}
+	// TODO: limit size of buffered test output
+	p.output[root][sub] = append(p.output[root][sub], output)
+}
+
+// splitTestName into root test name and any subtest names.
+func splitTestName(name string) (root, sub string) {
+	parts := strings.SplitN(name, "/", 2)
+	if len(parts) < 2 {
+		return name, ""
+	}
+	return parts[0], parts[1]
 }
 
 // TestMainFailed returns true if the package failed, but there were no tests.
@@ -130,11 +194,14 @@ type TestCase struct {
 	Package string
 	Test    string
 	Elapsed time.Duration
+	// subTestFailed is true when a subtest of this TestCase has failed. It is
+	// used to find root TestCases which have no failing subtests.
+	subTestFailed bool
 }
 
 func newPackage() *Package {
 	return &Package{
-		output:  make(map[string][]string),
+		output:  make(map[string]map[string][]string),
 		running: make(map[string]TestCase),
 	}
 }
@@ -171,7 +238,7 @@ func (e *Execution) addPackageEvent(pkg *Package, event TestEvent) {
 		if isCachedOutput(event.Output) {
 			pkg.cached = true
 		}
-		pkg.output[""] = append(pkg.output[""], event.Output)
+		pkg.addOutput("", event.Output)
 	}
 }
 
@@ -185,8 +252,7 @@ func (e *Execution) addTestEvent(pkg *Package, event TestEvent) {
 		}
 		return
 	case ActionOutput, ActionBench:
-		// TODO: limit size of buffered test output
-		pkg.output[event.Test] = append(pkg.output[event.Test], event.Output)
+		pkg.addOutput(event.Test, event.Output)
 		return
 	case ActionPause, ActionCont:
 		return
@@ -199,6 +265,14 @@ func (e *Execution) addTestEvent(pkg *Package, event TestEvent) {
 	switch event.Action {
 	case ActionFail:
 		pkg.Failed = append(pkg.Failed, tc)
+
+		// If this is a subtest, mark the root test as having subtests.
+		root, subTest := splitTestName(event.Test)
+		if subTest != "" {
+			rootTestCase := pkg.running[root]
+			rootTestCase.subTestFailed = true
+			pkg.running[root] = rootTestCase
+		}
 	case ActionSkip:
 		pkg.Skipped = append(pkg.Skipped, tc)
 	case ActionPass:
@@ -222,14 +296,13 @@ func isCachedOutput(output string) bool {
 	return strings.Contains(output, "\t(cached)")
 }
 
-// Output returns the full test output for a test.
-func (e *Execution) Output(pkg, test string) string {
-	return strings.Join(e.packages[pkg].output[test], "")
-}
-
-// OutputLines returns the full test output for a test as an array of lines.
-func (e *Execution) OutputLines(pkg, test string) []string {
-	return e.packages[pkg].output[test]
+// OutputLines returns the full test output for a test as an slice of lines.
+// This function is a convenient wrapper around Package.OutputLines() to
+// support the hiding of output in the summary.
+//
+// See Package.OutLines() for more details.
+func (e *Execution) OutputLines(tc TestCase) []string {
+	return e.packages[tc.Package].OutputLines(tc)
 }
 
 // Package returns the Package by name.

testjson/execution_test.go

@@ -35,8 +35,10 @@ func TestExecution_Add_PackageCoverage(t *testing.T) {
 	pkg := exec.Package("mytestpkg")
 	expected := &Package{
 		coverage: "coverage: 33.1% of statements",
-		output: map[string][]string{
-			"": {"coverage: 33.1% of statements\n"},
+		output: map[string]map[string][]string{
+			"": {
+				"": {"coverage: 33.1% of statements\n"},
+			},
 		},
 		running: map[string]TestCase{},
 	}

testjson/format.go

@@ -79,7 +79,7 @@ func shortVerboseFormat(event TestEvent, exec *Execution) (string, error) {
 		}
 
 	case event.Action == ActionFail:
-		return exec.Output(event.Package, event.Test) + formatTest(), nil
+		return exec.Package(event.Package).Output(event.Test) + formatTest(), nil
 
 	case event.Action == ActionPass:
 		return formatTest(), nil
@@ -164,7 +164,7 @@ func shortFormatPackageEvent(event TestEvent, exec *Execution) (string, error) {
 func shortWithFailuresFormat(event TestEvent, exec *Execution) (string, error) {
 	if !event.PackageEvent() {
 		if event.Action == ActionFail {
-			return exec.Output(event.Package, event.Test), nil
+			return exec.Package(event.Package).Output(event.Test), nil
 		}
 		return "", nil
 	}

testjson/summary.go

@@ -143,14 +143,14 @@ func countErrors(errors []string) int {
 type executionSummary interface {
 	Failed() []TestCase
 	Skipped() []TestCase
-	OutputLines(pkg, test string) []string
+	OutputLines(TestCase) []string
 }
 
 type noOutputSummary struct {
 	Execution
 }
 
-func (s *noOutputSummary) OutputLines(_, _ string) []string {
+func (s *noOutputSummary) OutputLines(_ TestCase) []string {
 	return nil
 }
 
@@ -173,8 +173,8 @@ func writeTestCaseSummary(out io.Writer, execution executionSummary, conf testCa
 			RelativePackagePath(tc.Package),
 			tc.Test,
 			FormatDurationAsSeconds(tc.Elapsed, 2))
-		for _, line := range execution.OutputLines(tc.Package, tc.Test) {
-			if isRunLine(line) || conf.filter(line) {
+		for _, line := range execution.OutputLines(tc) {
+			if isRunLine(line) || conf.filter(tc.Test, line) {
 				continue
 			}
 			fmt.Fprint(out, line)
@@ -186,7 +186,7 @@ func writeTestCaseSummary(out io.Writer, execution executionSummary, conf testCa
 type testCaseFormatConfig struct {
 	header string
 	prefix string
-	filter func(string) bool
+	filter func(testName string, line string) bool
 	getter func(executionSummary) []TestCase
 }
 
@@ -195,8 +195,8 @@ func formatFailed() testCaseFormatConfig {
 	return testCaseFormatConfig{
 		header: withColor("Failed"),
 		prefix: withColor("FAIL"),
-		filter: func(line string) bool {
-			return strings.HasPrefix(line, "--- FAIL: Test")
+		filter: func(testName string, line string) bool {
+			return strings.HasPrefix(line, "--- FAIL: "+testName+" ")
 		},
 		getter: func(execution executionSummary) []TestCase {
 			return execution.Failed()
@@ -209,8 +209,8 @@ func formatSkipped() testCaseFormatConfig {
 	return testCaseFormatConfig{
 		header: withColor("Skipped"),
 		prefix: withColor("SKIP"),
-		filter: func(line string) bool {
-			return strings.HasPrefix(line, "--- SKIP: Test")
+		filter: func(testName string, line string) bool {
+			return strings.HasPrefix(line, "--- SKIP: "+testName+" ")
 		},
 		getter: func(execution executionSummary) []TestCase {
 			return execution.Skipped()

testjson/summary_test.go

@@ -88,17 +88,17 @@ func TestPrintSummary_WithFailures(t *testing.T) {
 						Elapsed: 12 * time.Millisecond,
 					},
 				},
-				output: map[string][]string{
+				output: map[string]map[string][]string{
 					"TestFileDo": multiLine(`=== RUN   TestFileDo
 Some stdout/stderr here
---- FAIL: TestFailDo (1.41s)
+--- FAIL: TestFileDo (1.41s)
 	do_test.go:33 assertion failed
 `),
 					"TestFileDoError": multiLine(`=== RUN   TestFileDoError
---- FAIL: TestFailDoError (0.01s)
+--- FAIL: TestFileDoError (0.01s)
 	do_test.go:50 assertion failed: expected nil error, got WHAT!
 `),
-					"": {"FAIL\n"},
+					"": multiLine("FAIL\n"),
 				},
 				action: ActionFail,
 			},
@@ -118,7 +118,7 @@ Some stdout/stderr here
 						Elapsed: 0,
 					},
 				},
-				output: map[string][]string{
+				output: map[string]map[string][]string{
 					"TestAlbatross": multiLine(`=== RUN   TestAlbatross
 --- FAIL: TestAlbatross (0.04s)
 `),
@@ -130,8 +130,8 @@ Some stdout/stderr here
 			},
 			"example.com/project/badmain": {
 				action: ActionFail,
-				output: map[string][]string{
-					"": {"sometimes main can exit 2\n"},
+				output: map[string]map[string][]string{
+					"": multiLine("sometimes main can exit 2\n"),
 				},
 			},
 		},
@@ -220,13 +220,16 @@ func patchClock() (clockwork.FakeClock, func()) {
 	return fake, func() { clock = clockwork.NewRealClock() }
 }
 
-func multiLine(s string) []string {
-	return strings.SplitAfter(s, "\n")
+func multiLine(s string) map[string][]string {
+	return map[string][]string{
+		"": strings.SplitAfter(s, "\n"),
+	}
 }
 
 func TestPrintSummary_MissingTestFailEvent(t *testing.T) {
 	_, reset := patchClock()
 	defer reset()
+
 	exec, err := ScanTestOutput(ScanConfig{
 		Stdout:  bytes.NewReader(golden.Get(t, "go-test-json-missing-test-fail.out")),
 		Stderr:  bytes.NewReader(nil),
@@ -248,3 +251,35 @@ func (s noopHandler) Event(TestEvent, *Execution) error {
 func (s noopHandler) Err(string) error {
 	return nil
 }
+
+func TestPrintSummary_WithMisattributedOutput(t *testing.T) {
+	_, reset := patchClock()
+	defer reset()
+
+	exec, err := ScanTestOutput(ScanConfig{
+		Stdout:  bytes.NewReader(golden.Get(t, "go-test-json-misattributed.out")),
+		Stderr:  bytes.NewBuffer(nil),
+		Handler: noopHandler{},
+	})
+	assert.NilError(t, err)
+
+	buf := new(bytes.Buffer)
+	PrintSummary(buf, exec, SummarizeAll)
+	golden.Assert(t, buf.String(), "summary-misattributed-output")
+}
+
+func TestPrintSummary_WithSubtestFailures(t *testing.T) {
+	_, reset := patchClock()
+	defer reset()
+
+	exec, err := ScanTestOutput(ScanConfig{
+		Stdout:  bytes.NewReader(golden.Get(t, "go-test-json.out")),
+		Stderr:  bytes.NewBuffer(nil),
+		Handler: noopHandler{},
+	})
+	assert.NilError(t, err)
+
+	buf := new(bytes.Buffer)
+	PrintSummary(buf, exec, SummarizeAll)
+	golden.Assert(t, buf.String(), "summary-root-test-has-subtest-failures")
+}

testjson/testdata/go-test-json-misattributed.out

@@ -0,0 +1,35 @@
+{"Action":"run","Test":"TestOutputWithSubtest"}
+{"Action":"output","Test":"TestOutputWithSubtest","Output":"=== RUN   TestOutputWithSubtest\n"}
+{"Action":"run","Test":"TestOutputWithSubtest/sub_test"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test","Output":"=== RUN   TestOutputWithSubtest/sub_test\n"}
+{"Action":"run","Test":"TestOutputWithSubtest/sub_test/sub2"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test/sub2","Output":"=== RUN   TestOutputWithSubtest/sub_test/sub2\n"}
+{"Action":"run","Test":"TestOutputWithSubtest/sub_test2"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test2","Output":"=== RUN   TestOutputWithSubtest/sub_test2\n"}
+{"Action":"run","Test":"TestOutputWithSubtest/sub_test2/sub2"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test2/sub2","Output":"=== RUN   TestOutputWithSubtest/sub_test2/sub2\n"}
+{"Action":"output","Test":"TestOutputWithSubtest","Output":"--- FAIL: TestOutputWithSubtest (0.00s)\n"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test","Output":"    --- PASS: TestOutputWithSubtest/sub_test (0.00s)\n"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test","Output":"        foo_test.go:9: output from sub test\n"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test","Output":"        foo_test.go:11: more output from sub test\n"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test","Output":"        foo_test.go:16: more output from sub test\n"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test/sub2","Output":"        --- PASS: TestOutputWithSubtest/sub_test/sub2 (0.00s)\n"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test/sub2","Output":"            foo_test.go:14: output from sub2 test\n"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test/sub2","Output":"    foo_test.go:22: output from root test\n"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test/sub2","Output":"    foo_test.go:27: output from root test\n"}
+{"Action":"pass","Test":"TestOutputWithSubtest/sub_test/sub2"}
+{"Action":"pass","Test":"TestOutputWithSubtest/sub_test"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test2","Output":"    --- PASS: TestOutputWithSubtest/sub_test2 (0.00s)\n"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test2","Output":"        foo_test.go:21: output from sub test2\n"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test2","Output":"        foo_test.go:23: more output from sub test2\n"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test2","Output":"        foo_test.go:28: more output from sub test2\n"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test2/sub2","Output":"        --- PASS: TestOutputWithSubtest/sub_test2/sub2 (0.00s)\n"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test2/sub2","Output":"            foo_test.go:26: output from sub2 test\n"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test2/sub2","Output":"    foo_test.go:32: output after sub test\n"}
+{"Action":"pass","Test":"TestOutputWithSubtest/sub_test2/sub2"}
+{"Action":"pass","Test":"TestOutputWithSubtest/sub_test2"}
+{"Action":"fail","Test":"TestOutputWithSubtest"}
+{"Action":"output","Output":"FAIL\n"}
+{"Action":"output","Output":"FAIL\tgotest.tools/gotestsum/foo\t0.001s\n"}
+{"Action":"output","Output":"FAIL\n"}
+{"Action":"fail"}