proposal: testing: report failing test after panic

[neild]

When a test panics in a table-driven test, it is difficult to tell which case caused the failure. For example:

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

panic: runtime error: integer divide by zero [recovered]
        panic: runtime error: integer divide by zero

goroutine 8 [running]:
testing.tRunner.func1(0xc0000ac400)
        /usr/lib/google-golang/src/testing/testing.go:830 +0x388
panic(0x511aa0, 0x623f00)
        /usr/lib/google-golang/src/runtime/panic.go:522 +0x1b5
_/usr/local/google/home/dneil/src/testpanic_test.Test.func1(0xc0000ac400)
        /usr/local/google/home/dneil/src/testpanic/panic_test.go:11 +0x24
testing.tRunner(0xc0000ac400, 0xc00005c490)
        /usr/lib/google-golang/src/testing/testing.go:865 +0xc0
created by testing.(*T).Run
        /usr/lib/google-golang/src/testing/testing.go:916 +0x357
FAIL    _/usr/local/google/home/dneil/src/testpanic     0.018s

We know that testpanic_test.Test panicked, but we don't know which test case is to blame. You can get a much more useful error by manually recovering the panic and converting it to a t.Fatal:

func Test(t *testing.T) {
        for _, test := range []int{1, 2, 0, 3} {
                t.Run(fmt.Sprintf("%v", test), func(t *testing.T) {
                        defer func() {
                                if err := recover(); err != nil {
                                        t.Error(string(debug.Stack()))
                                        t.Fatal(err)
                                }
                        }()
                        _ = 1 / test
                })
        }
}

--- FAIL: Test (0.00s)
    --- FAIL: Test/0 (0.00s)
        panic_test.go:14: runtime error: integer divide by zero
            
            goroutine 8 [running]:
            runtime/debug.Stack(0xc000046670, 0x512aa0, 0x625f00)
                /usr/lib/google-golang/src/runtime/debug/stack.go:24 +0x9d
            _/usr/local/google/home/dneil/src/testpanic_test.Test.func1.1(0xc0000ac400)
                /usr/local/google/home/dneil/src/testpanic/panic_test.go:14 +0x57
            panic(0x512aa0, 0x625f00)
                /usr/lib/google-golang/src/runtime/panic.go:522 +0x1b5
            _/usr/local/google/home/dneil/src/testpanic_test.Test.func1(0xc0000ac400)
                /usr/local/google/home/dneil/src/testpanic/panic_test.go:17 +0x7c
            testing.tRunner(0xc0000ac400, 0xc00005c490)
                /usr/lib/google-golang/src/testing/testing.go:865 +0xc0
            created by testing.(*T).Run
                /usr/lib/google-golang/src/testing/testing.go:916 +0x35a
FAIL
FAIL    _/usr/local/google/home/dneil/src/testpanic     0.016s

I propose that the testing package do something like that automatically. Perhaps rather than converting the panic to a t.Fatal it should print the failing test name and continue panicking; the important point is to provide information about which test case triggered the panic.

This doesn't help with panics in goroutines started by a test, of course.

[rsc]

It doesn't seem like we can recover during panic, but printing more information as the panic passes by seems like something we should investigate. At the least, we should print the name of the (sub)test that panicked, but we should probably also flush the current test output log, which would mean formatting a failure as well.

Does anyone want to sketch out details for this?

[neild]

I can try prototyping something if we're okay with the idea in principle.

[gopherbot]

Change https://golang.org/cl/179599 mentions this issue: testing: provide additional information when test funcs panic

[neild]

Turns out we already flush the test output log on panic, but we don't recursively flush it up to the root so subtest output gets lost. https://golang.org/cl/179599 flushes output to the root, and adds an explicit ==== PANIC (test name) message at the end just to make it clear.

Example output with this change:

--- FAIL: Test
    --- FAIL: Test/1/0
=== PANIC  Test/1/0
panic: runtime error: integer divide by zero [recovered]
	panic: runtime error: integer divide by zero

goroutine 36 [running]:
testing.tRunner.func1(0xc0000c4300)
	/Users/dneil/src/go/src/testing/testing.go:882 +0x5ff
panic(0x111bfa0, 0x1230f50)
	/Users/dneil/src/go/src/runtime/panic.go:619 +0x1b2
foo.Test.func1(0xc0000c4300)
	/Users/dneil/src/testpanic/panic_test.go:11 +0x24
testing.tRunner(0xc0000c4300, 0xc00008e310)
	/Users/dneil/src/go/src/testing/testing.go:917 +0xbf
created by testing.(*T).Run
	/Users/dneil/src/go/src/testing/testing.go:968 +0x350
FAIL	foo	0.077s

[rsc]

This looks fantastic. I could have used this over the weekend.

[rsc]

Let's get this in early in Go 1.14, just because I kind of remember a previous attempt failing badly.

[neild]

Two minor design questions from the CL:

• Should this print === PANIC (test name) at the end on panic?
• Should the stack trace be printed by the default panic handler, or should it be attached to the failing test?

e.g., this could instead be:

--- FAIL: Test
    --- FAIL: Test/1/0
        panic: runtime error: integer divide by zero [recovered]
         panic: runtime error: integer divide by zero

        goroutine 36 [running]:
        testing.tRunner.func1(0xc0000c4300)
         /Users/dneil/src/go/src/testing/testing.go:882 +0x5ff
        panic(0x111bfa0, 0x1230f50)
         /Users/dneil/src/go/src/runtime/panic.go:619 +0x1b2
        foo.Test.func1(0xc0000c4300)
         /Users/dneil/src/testpanic/panic_test.go:11 +0x24
        testing.tRunner(0xc0000c4300, 0xc00008e310)
         /Users/dneil/src/go/src/testing/testing.go:917 +0xbf
        created by testing.(*T).Run
         /Users/dneil/src/go/src/testing/testing.go:968 +0x350
FAIL foo 0.077s

[neild]

FWIW, some version of #32333 (fatal panic handler) would let us also produce similar improvements in test output when a panic occurs in a goroutine not started by a Test function.