testing: provide additional information when test funcs panic

Flush the output log up to the root when a test panics. Prior to
this change, only the current test's output log was flushed to its
parent, resulting in no output when a subtest panics.

For the following test function:

	func Test(t *testing.T) {
		for i, test := range []int{1, 0, 2} {
			t.Run(fmt.Sprintf("%v/%v", i, test), func(t *testing.T) {
				_ = 1 / test
			})
		}
	}

Output before this change:

	panic: runtime error: integer divide by zero [recovered]
		panic: runtime error: integer divide by zero
	(stack trace follows)

Output after this change:

	--- FAIL: Test (0.00s)
	    --- FAIL: Test/1/0 (0.00s)
	panic: runtime error: integer divide by zero [recovered]
	(stack trace follows)

Fixes #32121

Change-Id: Ifee07ccc005f0493a902190a8be734943123b6b7
Reviewed-on: https://go-review.googlesource.com/c/go/+/179599
Run-TryBot: Damien Neil <dneil@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Ian Lance Taylor <iant@golang.org>

diff --git a/src/cmd/internal/test2json/testdata/panic.json b/src/cmd/internal/test2json/testdata/panic.json
new file mode 100644 (file)
index 0000000..f99679c
--- /dev/null
+++ b/src/cmd/internal/test2json/testdata/panic.json
@@ -0,0 +1,19 @@
+{"Action":"output","Test":"TestPanic","Output":"--- FAIL: TestPanic (0.00s)\n"}
+{"Action":"output","Test":"TestPanic","Output":"panic: oops [recovered]\n"}
+{"Action":"output","Test":"TestPanic","Output":"\tpanic: oops\n"}
+{"Action":"output","Test":"TestPanic","Output":"\n"}
+{"Action":"output","Test":"TestPanic","Output":"goroutine 7 [running]:\n"}
+{"Action":"output","Test":"TestPanic","Output":"testing.tRunner.func1(0xc000092100)\n"}
+{"Action":"output","Test":"TestPanic","Output":"\t/go/src/testing/testing.go:874 +0x3a3\n"}
+{"Action":"output","Test":"TestPanic","Output":"panic(0x1110ea0, 0x116aea0)\n"}
+{"Action":"output","Test":"TestPanic","Output":"\t/go/src/runtime/panic.go:679 +0x1b2\n"}
+{"Action":"output","Test":"TestPanic","Output":"command-line-arguments.TestPanic(0xc000092100)\n"}
+{"Action":"output","Test":"TestPanic","Output":"\ta_test.go:6 +0x39\n"}
+{"Action":"output","Test":"TestPanic","Output":"testing.tRunner(0xc000092100, 0x114f500)\n"}
+{"Action":"output","Test":"TestPanic","Output":"\tgo/src/testing/testing.go:909 +0xc9\n"}
+{"Action":"output","Test":"TestPanic","Output":"created by testing.(*T).Run\n"}
+{"Action":"output","Test":"TestPanic","Output":"\tgo/src/testing/testing.go:960 +0x350\n"}
+{"Action":"output","Test":"TestPanic","Output":"FAIL\tcommand-line-arguments\t0.042s\n"}
+{"Action":"fail","Test":"TestPanic"}
+{"Action":"output","Output":"FAIL\n"}
+{"Action":"fail"}

diff --git a/src/cmd/internal/test2json/testdata/panic.test b/src/cmd/internal/test2json/testdata/panic.test
new file mode 100644 (file)
index 0000000..517ebaf
--- /dev/null
+++ b/src/cmd/internal/test2json/testdata/panic.test
@@ -0,0 +1,17 @@
+--- FAIL: TestPanic (0.00s)
+panic: oops [recovered]
+       panic: oops
+
+goroutine 7 [running]:
+testing.tRunner.func1(0xc000092100)
+       /go/src/testing/testing.go:874 +0x3a3
+panic(0x1110ea0, 0x116aea0)
+       /go/src/runtime/panic.go:679 +0x1b2
+command-line-arguments.TestPanic(0xc000092100)
+       a_test.go:6 +0x39
+testing.tRunner(0xc000092100, 0x114f500)
+       go/src/testing/testing.go:909 +0xc9
+created by testing.(*T).Run
+       go/src/testing/testing.go:960 +0x350
+FAIL   command-line-arguments  0.042s
+FAIL

diff --git a/src/testing/panic_test.go b/src/testing/panic_test.go
new file mode 100644 (file)
index 0000000..3491510
--- /dev/null
+++ b/src/testing/panic_test.go
@@ -0,0 +1,83 @@
+// Copyright 2019 The Go Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package testing_test
+
+import (
+       "flag"
+       "fmt"
+       "internal/testenv"
+       "os"
+       "os/exec"
+       "regexp"
+       "strings"
+       "testing"
+)
+
+var testPanicTest = flag.String("test_panic_test", "", "TestPanic: indicates which test should panic")
+
+func TestPanic(t *testing.T) {
+       testenv.MustHaveExec(t)
+
+       testCases := []struct {
+               desc  string
+               flags []string
+               want  string
+       }{{
+               desc:  "root test panics",
+               flags: []string{"-test_panic_test=TestPanicHelper"},
+               want: `
+--- FAIL: TestPanicHelper (N.NNs)
+    panic_test.go:NNN: TestPanicHelper
+`,
+       }, {
+               desc:  "subtest panics",
+               flags: []string{"-test_panic_test=TestPanicHelper/1"},
+               want: `
+--- FAIL: TestPanicHelper (N.NNs)
+    panic_test.go:NNN: TestPanicHelper
+    --- FAIL: TestPanicHelper/1 (N.NNs)
+        panic_test.go:NNN: TestPanicHelper/1
+`,
+       }}
+       for _, tc := range testCases {
+               t.Run(tc.desc, func(t *testing.T) {
+                       cmd := exec.Command(os.Args[0], "-test.run=TestPanicHelper")
+                       cmd.Args = append(cmd.Args, tc.flags...)
+                       cmd.Env = append(os.Environ(), "GO_WANT_HELPER_PROCESS=1")
+                       b, _ := cmd.CombinedOutput()
+                       got := string(b)
+                       want := strings.TrimSpace(tc.want)
+                       re := makeRegexp(want)
+                       if ok, err := regexp.MatchString(re, got); !ok || err != nil {
+                               t.Errorf("output:\ngot:\n%s\nwant:\n%s", got, want)
+                       }
+               })
+       }
+}
+
+func makeRegexp(s string) string {
+       s = regexp.QuoteMeta(s)
+       s = strings.ReplaceAll(s, ":NNN:", `:\d+:`)
+       s = strings.ReplaceAll(s, "N\\.NNs", `\d*\.\d*s`)
+       return s
+}
+
+func TestPanicHelper(t *testing.T) {
+       if os.Getenv("GO_WANT_HELPER_PROCESS") != "1" {
+               return
+       }
+       t.Log(t.Name())
+       if t.Name() == *testPanicTest {
+               panic("panic")
+       }
+       for i := 0; i < 3; i++ {
+               t.Run(fmt.Sprintf("%v", i), func(t *testing.T) {
+                       t.Log(t.Name())
+                       if t.Name() == *testPanicTest {
+                               panic("panic")
+                       }
+               })
+       }
+}

diff --git a/src/testing/testing.go b/src/testing/testing.go
index bbb10263c39aacba9d367fdbc0ecd8950ba25587..b9d4f2b5a564846b18b939cd74351aa0be753784 100644 (file)
--- a/src/testing/testing.go
+++ b/src/testing/testing.go
@@ -860,7 +860,6 @@ func tRunner(t *T, fn func(t *T)) {
                        t.Errorf("race detected during execution of test")
                }
 
-               t.duration += time.Since(t.start)
                // If the test panicked, print any test output before dying.
                err := recover()
                signal := true
@@ -877,10 +876,20 @@ func tRunner(t *T, fn func(t *T)) {
                }
                if err != nil {
                        t.Fail()
-                       t.report()
+                       // Flush the output log up to the root before dying.
+                       t.mu.Lock()
+                       root := &t.common
+                       for ; root.parent != nil; root = root.parent {
+                               root.duration += time.Since(root.start)
+                               fmt.Fprintf(root.parent.w, "--- FAIL: %s (%s)\n", root.name, fmtDuration(root.duration))
+                               root.parent.mu.Lock()
+                               io.Copy(root.parent.w, bytes.NewReader(root.output))
+                       }
                        panic(err)
                }
 
+               t.duration += time.Since(t.start)
+
                if len(t.sub) > 0 {
                        // Run parallel subtests.
                        // Decrease the running count for this test.