testing: data race is attributed to wrong test in -json formatting

[vearutop]

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

Reproducible with these versions:

$ go version
go version go1.19.6 darwin/amd64

$ go1.20.1 version
go version go1.20.1 darwin/amd64

$ go1.13 version
go version go1.13 darwin/amd64

$ gotip version
go version devel go1.21-99bc53f5e8 Mon Feb 20 02:28:50 2023 +0000 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="on"

GOARCH="amd64"

GOBIN=""

GOCACHE="/Users/vearutop/Library/Caches/go-build"

GOENV="/Users/vearutop/Library/Application Support/go/env"

GOEXE=""

GOEXPERIMENT=""

GOFLAGS=""

GOHOSTARCH="amd64"

GOHOSTOS="darwin"

GOINSECURE=""

GOMODCACHE="/Users/vearutop/go/pkg/mod"

GONOPROXY="github.com/adjust,github.com/vearutop,github.com/Unbotify"

GONOSUMDB="github.com/adjust,github.com/vearutop,github.com/Unbotify"

GOOS="darwin"

GOPATH="/Users/vearutop/go"

GOPRIVATE="github.com/adjust,github.com/vearutop,github.com/Unbotify"

GOPROXY="https://proxy.golang.org,direct"

GOROOT="/usr/local/opt/go/libexec"

GOSUMDB="sum.golang.org"

GOTMPDIR=""

GOTOOLDIR="/usr/local/opt/go/libexec/pkg/tool/darwin_amd64"

GOVCS=""

GOVERSION="go1.19.6"

GCCGO="gccgo"

GOAMD64="v1"

AR="ar"

CC="clang"

CXX="clang++"

CGO_ENABLED="1"

GOMOD="/Users/vearutop/dev/teststat/go.mod"

GOWORK=""

CGO_CFLAGS="-g -O2"

CGO_CPPFLAGS=""

CGO_CXXFLAGS="-g -O2"

CGO_FFLAGS="-g -O2"

CGO_LDFLAGS="-g -O2"

PKG_CONFIG="pkg-config"

GOGCCFLAGS="-fPIC -arch x86_64 -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/n7/jv2b0zv57jzc8y6zhmfzbn7c0000gn/T/go-build1651747709=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

I'm running racy tests with -race -json.

The reproducing tests are available here https://github.com/vearutop/teststat/tree/faulty-tests.

go test -race -json -count 5 ./... > run.jsonl

imperfect_test.go

package main_test

import (
	"math/rand"
	"testing"
	"time"
)

func TestThatIsRacy(t *testing.T) {
	t.Parallel()

	a := 1

	for i := 0; i < 1000; i++ {
		go func() { a++ }()
	}

	time.Sleep(10 * time.Millisecond)
	a++
}

func TestThatFlakes(t *testing.T) {
	t.Parallel()

	if rand.Int()%3 == 0 { //nolint
		return
	}

	t.Fatal("oh, I'm so flaky")
}

func TestThatFlakesToo(t *testing.T) {
	t.Parallel()

	if rand.Int()%5 == 0 { //nolint
		return
	}

	t.Fatal("oh, I'm even more flaky")
}

func TestThatIsSometimesSlow(t *testing.T) {
	t.Parallel()

	if rand.Int()%3 == 0 { //nolint
		time.Sleep(1 * time.Second)
	}
}

func TestThatIsAlwaysSlow(t *testing.T) {
	t.Parallel()
	time.Sleep(1 * time.Second)
}

What did you expect to see?

Data race has reference to TestThatIsRacy.

...
{"Time":"2023-02-22T11:17:42.83469+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatIsRacy","Output":"WARNING: DATA RACE\n"}
...

What did you see instead?

Data race has reference to another test (TestThatFlakesToo).

Part of run.jsonl:

...
{"Time":"2023-02-22T11:17:42.833996+01:00","Action":"cont","Package":"github.com/vearutop/teststat","Test":"TestThatFlakesToo"}
{"Time":"2023-02-22T11:17:42.834018+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatFlakesToo","Output":"=== CONT  TestThatFlakesToo\n"}
{"Time":"2023-02-22T11:17:42.834246+01:00","Action":"cont","Package":"github.com/vearutop/teststat","Test":"TestThatFlakes"}
{"Time":"2023-02-22T11:17:42.834271+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatFlakes","Output":"=== CONT  TestThatFlakes\n"}
{"Time":"2023-02-22T11:17:42.83467+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatFlakes","Output":"==================\n"}
{"Time":"2023-02-22T11:17:42.83469+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatFlakes","Output":"WARNING: DATA RACE\n"}
{"Time":"2023-02-22T11:17:42.834716+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatFlakes","Output":"Read at 0x00c00011ad18 by goroutine 15:\n"}
{"Time":"2023-02-22T11:17:42.834739+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatFlakes","Output":"  github.com/vearutop/teststat_test.TestThatIsRacy.func1()\n"}
{"Time":"2023-02-22T11:17:42.834748+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatFlakes","Output":"      /Users/vearutop/dev/teststat/imperfect_test.go:15 +0x30\n"}
{"Time":"2023-02-22T11:17:42.83478+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatFlakes","Output":"\n"}
{"Time":"2023-02-22T11:17:42.834797+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatFlakes","Output":"Previous write at 0x00c00011ad18 by goroutine 17:\n"}
{"Time":"2023-02-22T11:17:42.834811+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatFlakes","Output":"  github.com/vearutop/teststat_test.TestThatIsRacy.func1()\n"}
{"Time":"2023-02-22T11:17:42.834819+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatFlakes","Output":"      /Users/vearutop/dev/teststat/imperfect_test.go:15 +0x44\n"}
{"Time":"2023-02-22T11:17:42.834825+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatFlakes","Output":"\n"}
{"Time":"2023-02-22T11:17:42.834831+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatFlakes","Output":"Goroutine 15 (running) created at:\n"}
{"Time":"2023-02-22T11:17:42.834837+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatFlakes","Output":"  github.com/vearutop/teststat_test.TestThatIsRacy()\n"}
{"Time":"2023-02-22T11:17:42.834861+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatFlakes","Output":"      /Users/vearutop/dev/teststat/imperfect_test.go:15 +0x5b\n"}
{"Time":"2023-02-22T11:17:42.834868+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatFlakes","Output":"  testing.tRunner()\n"}
{"Time":"2023-02-22T11:17:42.834874+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatFlakes","Output":"      /Users/vearutop/sdk/go1.20.1/src/testing/testing.go:1576 +0x216\n"}
{"Time":"2023-02-22T11:17:42.83488+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatFlakes","Output":"  testing.(*T).Run.func1()\n"}
{"Time":"2023-02-22T11:17:42.834886+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatFlakes","Output":"      /Users/vearutop/sdk/go1.20.1/src/testing/testing.go:1629 +0x47\n"}
{"Time":"2023-02-22T11:17:42.834912+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatFlakes","Output":"\n"}
{"Time":"2023-02-22T11:17:42.834922+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatFlakes","Output":"Goroutine 17 (finished) created at:\n"}
{"Time":"2023-02-22T11:17:42.83493+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatFlakes","Output":"  github.com/vearutop/teststat_test.TestThatIsRacy()\n"}
{"Time":"2023-02-22T11:17:42.834939+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatFlakes","Output":"      /Users/vearutop/dev/teststat/imperfect_test.go:15 +0x5b\n"}
{"Time":"2023-02-22T11:17:42.834948+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatFlakes","Output":"  testing.tRunner()\n"}
{"Time":"2023-02-22T11:17:42.834955+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatFlakes","Output":"      /Users/vearutop/sdk/go1.20.1/src/testing/testing.go:1576 +0x216\n"}
{"Time":"2023-02-22T11:17:42.834962+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatFlakes","Output":"  testing.(*T).Run.func1()\n"}
{"Time":"2023-02-22T11:17:42.834969+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatFlakes","Output":"      /Users/vearutop/sdk/go1.20.1/src/testing/testing.go:1629 +0x47\n"}
{"Time":"2023-02-22T11:17:42.834975+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatFlakes","Output":"==================\n"}
{"Time":"2023-02-22T11:17:42.834984+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatFlakes","Output":"    imperfect_test.go:29: oh, I'm so flaky\n"}
{"Time":"2023-02-22T11:17:42.834992+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatFlakesToo","Output":"    imperfect_test.go:39: oh, I'm even more flaky\n"}
{"Time":"2023-02-22T11:17:42.835022+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatFlakes","Output":"--- FAIL: TestThatFlakes (0.00s)\n"}
{"Time":"2023-02-22T11:17:42.835056+01:00","Action":"fail","Package":"github.com/vearutop/teststat","Test":"TestThatFlakes","Elapsed":0}
{"Time":"2023-02-22T11:17:42.835066+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatFlakesToo","Output":"--- FAIL: TestThatFlakesToo (0.00s)\n"}
{"Time":"2023-02-22T11:17:42.848652+01:00","Action":"fail","Package":"github.com/vearutop/teststat","Test":"TestThatFlakesToo","Elapsed":0}
{"Time":"2023-02-22T11:17:42.84873+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatIsRacy","Output":"    testing.go:1446: race detected during execution of test\n"}
{"Time":"2023-02-22T11:17:42.848836+01:00","Action":"output","Package":"github.com/vearutop/teststat","Test":"TestThatIsRacy","Output":"--- FAIL: TestThatIsRacy (0.02s)\n"}
{"Time":"2023-02-22T11:17:43.621831+01:00","Action":"fail","Package":"github.com/vearutop/teststat/foo","Test":"TestThatIsRacy","Elapsed":0.02}
{"Time":"2023-02-22T11:17:43.621899+01:00","Action":"output","Package":"github.com/vearutop/teststat/foo","Test":"TestThatIsAlwaysSlow","Output":"    testing.go:1446: race detected during execution of test\n"}
...

[thanm]

@bcmills per owners.

Possibly relaed to #57305?

[vearutop]

Perhaps this is an "original" behavior from long ago, as it is reproducible with go1.13 (the least version I've tried) too.