Navigation Menu

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,runtime: calling t.Helper() in a goroutine logs asm file names, not the one from the call site #58545

Open
pmalek opened this issue Feb 15, 2023 · 3 comments
Open

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

pmalek opened this issue Feb 15, 2023 · 3 comments
Labels
compiler/runtime Issues related to the Go compiler and/or runtime. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Unplanned

Comments

@pmalek
Copy link

pmalek commented Feb 15, 2023

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 bcmills changed the title Calling t.Helper() in a goroutine logs asm file names not the one from the call site testing,runtime: calling t.Helper() in a goroutine logs asm file names, not the one from the call site Feb 15, 2023
@gopherbot gopherbot added the compiler/runtime Issues related to the Go compiler and/or runtime. label Feb 15, 2023
@bcmills
Copy link
Contributor

bcmills commented Feb 15, 2023

#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.

@bcmills bcmills added this to the Unplanned milestone Feb 15, 2023
@bcmills bcmills added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Feb 15, 2023
@kevherro
Copy link
Contributor

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
Copy link

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
compiler/runtime Issues related to the Go compiler and/or runtime. 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
@pmalek @bcmills @gopherbot @kevherro