testing: deferred func runs before parallel subtest

[willfaught]

Also, Run's result was wrong.

What did you do?

I deferred a function in a package-scope test, then ran a parallel subtest that assumed the deferred function would run after it completes, but this wasn't the case, and Run returned true when the subtest failed.

Basically, this:

func TestFoo(t *testing.T) {
    defer bar() // Runs before baz

    var passed = t.Run("subtest", func(t *testing.T) {
        t.Parallel()
        baz() // Runs after bar
        t.Fail()
    } // Passed is true

    // ...
}

It doesn't matter whether the package-scope test is parallel.

A full example: https://play.golang.org/p/pMsKhRvjiW. Note that you'll have to run it locally.

The documentation for testing.T.Run says:

func (t *T) Run(name string, f func(t *T)) bool
    Run runs f as a subtest of t called name. It reports whether f succeeded.
    Run runs f in a separate goroutine and will block until all its parallel
    subtests have completed.

    Run may be called simultaneously from multiple goroutines, but all such
    calls must return before the outer test function for t returns.

This seems to say that Run always returns an accurate status of the subtest, even if it's parallel, which means the subtest must finish before the Run call completes, and thus before the parent test returns, after which its deferred functions run, but I'm seeing such a deferred function run first. The discussion in https://golang.org/pkg/testing/#hdr-Subtests_and_Sub_benchmarks similarly indicates to me this is incorrect behavior, specifically the paragraphs starting with "Subtests can also be used to control parallelism" and "Run does not return until parallel subtests have completed".

The documentation for testing.T.Parallel says:

func (t *T) Parallel()
    Parallel signals that this test is to be run in parallel with (and only
    with) other parallel tests. When a test is run multiple times due to use of
    -test.count or -test.cpu, multiple instances of a single test never run in
    parallel with each other.

This doesn't seem to augment Run's documentation's guarantees, but I'm not sure.

I feel like I must be missing something obvious, but a colleague agreed with my interpretation.

What did you expect to see?

$ go test -v
=== RUN   TestFoo
=== RUN   TestFoo/sub
--- PASS: TestFoo (0.00s)
	t_test.go:34: passed: actual true, expected true
    --- PASS: TestFoo/sub (0.00s)
PASS
ok  	t	0.036s

What did you see instead?

$ go test -v
=== RUN   TestFoo
=== RUN   TestFoo/sub
--- FAIL: TestFoo (0.00s)
	t_test.go:34: passed: actual true, expected true
    --- FAIL: TestFoo/sub (0.10s)
    	t_test.go:24: Get http://127.0.0.1:61311: dial tcp 127.0.0.1:61311: getsockopt: connection refused
    	t_test.go:28: response: actual nil, expected not nil
FAIL
exit status 1
FAIL	t	0.141s

System details

go version go1.9.2 darwin/amd64
GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/willfaught/Developer/go"
GORACE=""
GOROOT="/usr/local/Cellar/go/1.9.2/libexec"
GOTOOLDIR="/usr/local/Cellar/go/1.9.2/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/_1/ggvd2t1x7hz_185crsb36zlr0000gp/T/go-build590837635=/tmp/go-build -gno-record-gcc-switches -fno-common"
CXX="clang++"
CGO_ENABLED="1"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOROOT/bin/go version: go version go1.9.2 darwin/amd64
GOROOT/bin/go tool compile -V: compile version go1.9.2
uname -v: Darwin Kernel Version 17.2.0: Fri Sep 29 18:27:05 PDT 2017; root:xnu-4570.20.62~3/RELEASE_X86_64
ProductName:	Mac OS X
ProductVersion:	10.13.1
BuildVersion:	17B1003
lldb --version: lldb-900.0.57
  Swift-4.0

[willfaught]

https://blog.golang.org/subtests says:

A parallel test never runs concurrently with a sequential test and its execution is suspended until its calling test function, that of the parent test, has returned

which might explain this behavior, but it conflicts with the T documentation in that it breaks T.Run's result.

[willfaught]

Perhaps the core issue is that the T documentation doesn't specify the ordering of a parent test function returning and its parallel subtest goroutine resuming after its T.Parallel call (and also that a T.Run call in a parent test returns true immediately when T.Parallel is called in a subtest, even if that subtest later fails).

[ianlancetaylor]

I think this is an issue to be fixed with better documentation.

CC @mpvl

[gopherbot]

Change https://golang.org/cl/83880 mentions this issue: testing: define Run result a little more clearly