testing: data race between parallel panicking and normal subtest

[changkun]

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

$ go version
go version go1.14 darwin/amd64

Does this issue reproduce with the latest release?

Yes

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

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/changkun/Library/Caches/go-build"
GOENV="/Users/changkun/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/changkun/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/Cellar/go/1.14/libexec"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/Cellar/go/1.14/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/j_/h4j7spgj3znbfxcbbph5fp4w0000gn/T/go-build613651133=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

package main_test

import "testing"

func TestA(t *testing.T) {
	t.Run("1", func(t *testing.T) {
		t.Run("1", func(t *testing.T) {
			t.Parallel()
			panic("A1/1 panics")
		})
		t.Run("2", func(t *testing.T) {
			t.Parallel()
			println("A/1/2 is ok")
		})
	})
}

$ go test -v -race -count=1 .

What did you expect to see?

=== RUN   TestA
=== RUN   TestA/1
=== RUN   TestA/1/1
=== PAUSE TestA/1/1
=== RUN   TestA/1/2
=== PAUSE TestA/1/2
=== CONT  TestA/1/1
=== CONT  TestA/1/2
A/1/2 is ok
--- FAIL: TestA (0.00s)
    --- FAIL: TestA/1 (0.00s)
        --- PASS: TestA/1/2 (0.00s)
        --- FAIL: TestA/1/1 (0.00s)
panic: A1/1 panics [recovered]
        panic: A1/1 panics

goroutine 20 [running]:
testing.tRunner.func1.1(0x1110560, 0x1168870)
        /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:941 +0x3d0
testing.tRunner.func1(0xc0000cc360)
        /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:944 +0x3f9
panic(0x1110560, 0x1168870)
        /usr/local/Cellar/go/1.14/libexec/src/runtime/panic.go:967 +0x15d
_/Users/changkun/Desktop/testing/parallel_test.TestA.func1.1(0xc0000cc360)
        /Users/changkun/Desktop/testing/parallel/main_test.go:13 +0x47
testing.tRunner(0xc0000cc360, 0x114a410)
        /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:992 +0xdc
created by testing.(*T).Run
        /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:1043 +0x357
FAIL    _/Users/changkun/Desktop/testing/parallel       0.144s
FAIL

What did you see instead?

Data race appears in Go 1.14 and not in Go 1.13.8:

=== RUN   TestA
=== RUN   TestA/1
=== RUN   TestA/1/1
=== PAUSE TestA/1/1
=== RUN   TestA/1/2
=== PAUSE TestA/1/2
=== CONT  TestA/1/2
A/1/2 is ok
=== CONT  TestA/1/1
==================
WARNING: DATA RACE
Read at 0x00c000156258 by goroutine 9:
  testing.indenter.Write()
      /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:533 +0xd9
  fmt.Fprintf()
      /usr/local/Cellar/go/1.14/libexec/src/fmt/print.go:205 +0xcc
  testing.tRunner.func1.1()
      /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:934 +0x3a8
  testing.tRunner.func1()
      /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:944 +0x5ff
  runtime.call32()
      /usr/local/Cellar/go/1.14/libexec/src/runtime/asm_amd64.s:539 +0x3a
  testing.tRunner()
      /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:992 +0x1eb

Previous write at 0x00c000156258 by goroutine 10:
  testing.indenter.Write()
      /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:533 +0x17b
  fmt.Fprintf()
      /usr/local/Cellar/go/1.14/libexec/src/fmt/print.go:205 +0xcc
  testing.(*common).flushToParent()
      /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:509 +0x137
  testing.(*T).report()
      /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:1227 +0x3b6
  testing.tRunner.func1()
      /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:974 +0x452
  testing.tRunner()
      /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:996 +0x20d

Goroutine 9 (running) created at:
  testing.(*T).Run()
      /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:1043 +0x660
  _/Users/changkun/Desktop/testing/parallel_test.TestA.func1()
      /Users/changkun/Desktop/testing/parallel/main_test.go:11 +0x5d
  testing.tRunner()
      /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:992 +0x1eb

Goroutine 10 (running) created at:
  testing.(*T).Run()
      /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:1043 +0x660
  _/Users/changkun/Desktop/testing/parallel_test.TestA.func1()
      /Users/changkun/Desktop/testing/parallel/main_test.go:15 +0x8c
  testing.tRunner()
      /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:992 +0x1eb
==================
==================
WARNING: DATA RACE
Read at 0x00c00015c040 by goroutine 9:
  runtime.growslice()
      /usr/local/Cellar/go/1.14/libexec/src/runtime/slice.go:76 +0x0
  testing.indenter.Write()
      /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:533 +0x341
  fmt.Fprintf()
      /usr/local/Cellar/go/1.14/libexec/src/fmt/print.go:205 +0xcc
  testing.tRunner.func1.1()
      /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:934 +0x3a8
  testing.tRunner.func1()
      /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:944 +0x5ff
  runtime.call32()
      /usr/local/Cellar/go/1.14/libexec/src/runtime/asm_amd64.s:539 +0x3a
  testing.tRunner()
      /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:992 +0x1eb

Previous write at 0x00c00015c044 by goroutine 10:
  runtime.slicecopy()
      /usr/local/Cellar/go/1.14/libexec/src/runtime/slice.go:197 +0x0
  testing.indenter.Write()
      /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:534 +0x252
  fmt.Fprintf()
      /usr/local/Cellar/go/1.14/libexec/src/fmt/print.go:205 +0xcc
  testing.(*common).flushToParent()
      /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:509 +0x137
  testing.(*T).report()
      /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:1227 +0x3b6
  testing.tRunner.func1()
      /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:974 +0x452
  testing.tRunner()
      /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:996 +0x20d

Goroutine 9 (running) created at:
  testing.(*T).Run()
      /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:1043 +0x660
  _/Users/changkun/Desktop/testing/parallel_test.TestA.func1()
      /Users/changkun/Desktop/testing/parallel/main_test.go:11 +0x5d
  testing.tRunner()
      /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:992 +0x1eb

Goroutine 10 (running) created at:
  testing.(*T).Run()
      /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:1043 +0x660
  _/Users/changkun/Desktop/testing/parallel_test.TestA.func1()
      /Users/changkun/Desktop/testing/parallel/main_test.go:15 +0x8c
  testing.tRunner()
      /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:992 +0x1eb
==================
--- FAIL: TestA (0.00s)
    --- FAIL: TestA/1 (0.00s)
        --- PASS: TestA/1/2 (0.00s)
        --- FAIL: TestA/1/1 (0.00s)
panic: A1/1 panics [recovered]
        panic: A1/1 panics

goroutine 21 [running]:
testing.tRunner.func1.1(0x11d6b60, 0x123d440)
        /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:941 +0x5d0
testing.tRunner.func1(0xc000156360)
        /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:944 +0x600
panic(0x11d6b60, 0x123d440)
        /usr/local/Cellar/go/1.14/libexec/src/runtime/panic.go:973 +0x396
_/Users/changkun/Desktop/testing/parallel_test.TestA.func1.1(0xc000156360)
        /Users/changkun/Desktop/testing/parallel/main_test.go:13 +0x55
testing.tRunner(0xc000156360, 0x12175d8)
        /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:992 +0x1ec
created by testing.(*T).Run
        /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:1043 +0x661
FAIL    _/Users/changkun/Desktop/testing/parallel       0.066s
FAIL

[gopherbot]

Change https://golang.org/cl/221322 mentions this issue: testing: fix data race between parallel subtests

[zikaeroh]

Does this need to be backported if it's a race in 1.14?

[ianlancetaylor]

@gopherbot Please backport to 1.14. This is a regression that was newly introduced in 1.14.

[gopherbot]

Backport issue(s) opened: #37959 (for 1.14).

Remember to create the cherry-pick CL(s) as soon as the patch is submitted to master, according to https://golang.org/wiki/MinorReleases.

[gopherbot]

Change https://golang.org/cl/224257 mentions this issue: [release-branch.go1.14] testing: fix data race between parallel subtests