testing,runtime: calling t.Helper() in a goroutine logs asm file names, not the one from the call site

[pmalek]

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

$ go version
go version go1.20.1 darwin/arm64

Does this issue reproduce with the latest release?

1.20.1 is the latest release at the moment.

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

go env Output

$ go env
GO111MODULE=""
GOARCH="arm64"
GOBIN=""
GOCACHE="/Users/USER/Library/Caches/go-build"
GOENV="/Users/USER/Library/Application Support/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="arm64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/USER/.gvm/pkgsets/go1.20.1/global/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/USER/.gvm/pkgsets/go1.20.1/global"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/Users/USER/.gvm/gos/go1.20.1"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/Users/USER/.gvm/gos/go1.20.1/pkg/tool/darwin_arm64"
GOVCS=""
GOVERSION="go1.20.1"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/dev/null"
GOWORK=""
CGO_CFLAGS="-O2 -g"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-O2 -g"
CGO_FFLAGS="-O2 -g"
CGO_LDFLAGS="-O2 -g"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/0m/_63w01516tgf3cftmp9h7ylm0000gn/T/go-build1387756731=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

Calling t.Helper() in helper that spawns a goroutine that calls t.Log() in that goroutine doesn't account for the t.Helper() call - that is expected, not the same func.

Calling t.Helper() and t.Log() inside the goroutine spawned in a function logs asm related file name - unexpected.

package thelper

import (
	"sync"
	"testing"
)

func Test(t *testing.T) {
	t.Log("calling helper")
	helper(t)
}

func helper(t *testing.T) {
	t.Helper()
	t.Log("in helper")

	var wg sync.WaitGroup
	wg.Add(1)
	go func(t *testing.T) {
		defer wg.Done()
		t.Helper()
		t.Log("in helper's goroutine")
	}(t)
	wg.Wait()
}

What did you expect to see?

=== RUN   Test
    main_test.go:9: calling helper
    main_test.go:10: in helper
    main_test.go:10: in helper's goroutine
--- PASS: Test (0.00s)
PASS
ok      thelper 0.004s

What did you see instead?

=== RUN   Test
    main_test.go:9: calling helper
    main_test.go:10: in helper
    asm_arm64.s:1172: in helper's goroutine
--- PASS: Test (0.00s)
PASS
ok      thelper 0.004s

[bcmills]

#38651 is somewhat related. This is a hard problem to solve — in the general case, by the time the call to t.Helper occurs in the child goroutine the parent may have already returned.

[kevherro]

I noticed that the following change to parallelTestHelper(t *T) causes TestTBHelperParallel(t *T) to fail with a similar result:

diff --git a/src/testing/helperfuncs_test.go b/src/testing/helperfuncs_test.go
index b63bc91ac2..5e90ce7fe7 100644
--- a/src/testing/helperfuncs_test.go
+++ b/src/testing/helperfuncs_test.go
@@ -90,7 +90,8 @@ func parallelTestHelper(t *T) {
 	for i := 0; i < 5; i++ {
 		wg.Add(1)
 		go func() {
-			notHelperCallingHelper(t, "parallel")
+			t.Helper()
+			t.Error("parallel")
 			wg.Done()
 		}()
 	}

$ godevel test -v -test.run TestTBHelperParallel
=== RUN   TestTBHelperParallel
    helper_test.go:74: got output line "asm_arm64.s:1172: parallel"; want "helperfuncs_test.go:21: parallel"
--- FAIL: TestTBHelperParallel (0.00s)
FAIL
exit status 1
FAIL	testing	0.317s

Is this failure unexpected, too?

go env Output

$ godevel env
GO111MODULE=""
GOARCH="arm64"
GOBIN=""
GOCACHE="/Users/kevherro/Library/Caches/go-build"
GOENV="/Users/kevherro/Library/Application Support/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="arm64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/kevherro/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/kevherro/go"
GOPRIVATE=""
GOPROXY="https://goproxy.io,direct"
GOROOT="/Users/kevherro/golang.org"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/Users/kevherro/golang.org/pkg/tool/darwin_arm64"
GOVCS=""
GOVERSION="devel go1.21-99bc53f5e8 Mon Feb 20 02:28:50 2023 +0000"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/kevherro/golang.org/src/go.mod"
GOWORK=""
CGO_CFLAGS="-O2 -g"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-O2 -g"
CGO_FFLAGS="-O2 -g"
CGO_LDFLAGS="-O2 -g"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/ck/5sb0xvts6kg81fwzdbtrd2cc0000gr/T/go-build1818295499=/tmp/go-build -gno-record-gcc-switches -fno-common"

[gopherbot]

Change https://go.dev/cl/477495 mentions this issue: testing: log the call site file name of t.Helper() when called in a goroutine