testing: Parallel subtests killed on panic

[tommyknows]

What version of Go are you using (go version)?

Tested on HEAD, go 1.13 and go 1.14

What operating system and processor architecture are you using (go env)?

go env Output

$ go env

What did you do?

Run parallel subtests and have one panic.

package main

import (
        "testing"
        "time"
)

func TestPanic(t *testing.T) {
        t.Cleanup(func() { t.Logf("cleaning up root") })

        t.Run("main", func(t *testing.T) {
                t.Cleanup(func() { t.Logf("cleaning up main") })
                t.Run("subtest-one", func(t *testing.T) {
                        t.Parallel()
                        t.Cleanup(func() { t.Logf("subtest-one") })
                        t.Logf("Panicking now")
                        panic("oh no")
                })
                t.Run("subtest-two", func(t *testing.T) {
                        t.Parallel()
                        // we always want to see this cleanup message
                        t.Cleanup(func() { t.Logf("subtest-two") })
                        time.Sleep(time.Second)
                })
        })
}

go test -v .

Also reproducible in the playground

What did you expect to see?

I expected to see that other, parallel running subtests still complete, or at least that their respective Cleanup-functions would run.

=== RUN   TestPanic
=== RUN   TestPanic/main
=== RUN   TestPanic/main/subtest-one
=== PAUSE TestPanic/main/subtest-one
=== RUN   TestPanic/main/subtest-two
=== PAUSE TestPanic/main/subtest-two
=== CONT  TestPanic/main/subtest-one
    TestPanic/main/subtest-one: test_test.go:16: Panicking now
=== CONT  TestPanic/main/subtest-two
    TestPanic/main/subtest-one: test_test.go:15: subtest-one
    TestPanic/main/subtest-two: test_test.go:15: subtest-two // <- this here
    TestPanic/main: test_test.go:12: cleaning up main
    TestPanic: test_test.go:9: cleaning up root
--- FAIL: TestPanic (0.00s)
    --- FAIL: TestPanic/main (0.00s)
        --- PASS: TestPanic/main/subtest-two (1.00s) // <- and this
        --- FAIL: TestPanic/main/subtest-one (0.00s)
panic: oh no [recovered]
        panic: oh no

goroutine 20 [running]:
testing.tRunner.func1.1(0x1110ae0, 0x11691e0)
        /Users/ramon/Documents/go/go-work/src/testing/testing.go:941 +0x3d0
testing.tRunner.func1(0xc0000cc360)
        /Users/ramon/Documents/go/go-work/src/testing/testing.go:944 +0x3f9
panic(0x1110ae0, 0x11691e0)
        /Users/ramon/Documents/go/go-work/src/runtime/panic.go:967 +0x15d
panic.TestPanic.func2.2(0xc0000cc360)
        /tmp/testpanic/test_test.go:17 +0xdb
testing.tRunner(0xc0000cc360, 0x114ac30)
        /Users/ramon/Documents/go/go-work/src/testing/testing.go:992 +0xdc
created by testing.(*T).Run
        /Users/ramon/Documents/go/go-work/src/testing/testing.go:1043 +0x357
FAIL    panic   1.184s
FAIL

What did you see instead?

One subtest panicking takes down the whole test:

=== RUN   TestPanic
=== RUN   TestPanic/main
=== RUN   TestPanic/main/subtest-one
=== PAUSE TestPanic/main/subtest-one
=== RUN   TestPanic/main/subtest-two
=== PAUSE TestPanic/main/subtest-two
=== CONT  TestPanic/main/subtest-one
    TestPanic/main/subtest-one: test_test.go:16: Panicking now
=== CONT  TestPanic/main/subtest-two
    TestPanic/main/subtest-one: test_test.go:15: subtest-one
    TestPanic/main: test_test.go:12: cleaning up main
    TestPanic: test_test.go:9: cleaning up root
--- FAIL: TestPanic (0.00s)
    --- FAIL: TestPanic/main (0.00s)
        --- FAIL: TestPanic/main/subtest-one (0.00s)
panic: oh no [recovered]
        panic: oh no

goroutine 20 [running]:
testing.tRunner.func1.1(0x1110ae0, 0x11691e0)
        /Users/ramon/Documents/go/go-work/src/testing/testing.go:941 +0x3d0
testing.tRunner.func1(0xc0000cc360)
        /Users/ramon/Documents/go/go-work/src/testing/testing.go:944 +0x3f9
panic(0x1110ae0, 0x11691e0)
        /Users/ramon/Documents/go/go-work/src/runtime/panic.go:967 +0x15d
panic.TestPanic.func2.2(0xc0000cc360)
        /tmp/testpanic/test_test.go:17 +0xdb
testing.tRunner(0xc0000cc360, 0x114ac30)
        /Users/ramon/Documents/go/go-work/src/testing/testing.go:992 +0xdc
created by testing.(*T).Run
        /Users/ramon/Documents/go/go-work/src/testing/testing.go:1043 +0x357
FAIL    panic   0.184s
FAIL

Basically, the premise is that a panic only takes down one goroutine.
As t.Run runs in separate goroutines, I would have expected that subtest-two still runs to completion. However, once subtest-one calls panic, nothing else is ran except the chain of Cleanup-functions from the test that panics to the root-test.

If this is expected behaviour, this should be documented.
If this is unexpected behaviour, this is a bug 🙂

[andybons]

@bcmills @jayconrod @matloob

[bcmills]

This is expected behavior. Tests must not panic.

An unexpected panic leaves the process in an arbitrary state, and can even deadlock the process (for example, if the panic occurred after locking a mutex and before unlocking it, or after receiving on a in input channel and before sending on a corresponding output channel).

It is not, in general, safe to proceed after an unexpected panic has occured, and the test has already produced actionable feedback for the user anyway, so the testing package allows it to terminate the process (just like an unrecovered panic in any other goroutine).

Note that nothing in the testing package documentation mentions panic at all (except that *B.ReportMetric panics for invalid units), so it would be suprising if it did implement any special behavior here.

[tommyknows]

Although it's quite unfortunate for the issues I'm having, I do agree with you 🙂

Thank you for the explanation.