Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

testing: Parallel subtests killed on panic #38749

Closed
tommyknows opened this issue Apr 29, 2020 · 3 comments
Closed

testing: Parallel subtests killed on panic #38749

tommyknows opened this issue Apr 29, 2020 · 3 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Unplanned

Comments

@tommyknows
Copy link

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 andybons added GoCommand cmd/go NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Apr 29, 2020
@andybons andybons added this to the Unplanned milestone Apr 29, 2020
@andybons
Copy link
Member

@bcmills @jayconrod @matloob

@bcmills
Copy link
Contributor

bcmills commented Apr 29, 2020 •
edited

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.

@bcmills bcmills removed the GoCommand cmd/go label Apr 29, 2020
@tommyknows
Copy link
Author

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

Thank you for the explanation.

@golang golang locked and limited conversation to collaborators Apr 29, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Milestone
Unplanned
Development

No branches or pull requests
4 participants
@andybons @bcmills @gopherbot @tommyknows