runtime.Caller gives different results under go test vs bazel test

[cstrahan]

What version of rules_go are you using?

v0.40.1

What version of gazelle are you using?

v0.30.0

What version of Bazel are you using?

$ bazel version                                                                                                        
Bazelisk version: v1.15.0
Build label: 6.3.2
Build target: bazel-out/darwin_arm64-opt/bin/src/main/java/com/google/devtools/build/lib/bazel/BazelServer_deploy.jar
Build time: Tue Aug 8 15:51:44 2023 (1691509904)
Build timestamp: 1691509904
Build timestamp as int: 1691509904

Does this issue reproduce with the latest releases of all the above?

Yes

What operating system and processor architecture are you using?

macOS, arm64

$ uname -a
Darwin charles 22.6.0 Darwin Kernel Version 22.6.0: Wed Jul  5 22:22:05 PDT 2023; root:xnu-8796.141.3~6/RELEASE_ARM64_T6000 arm64

Any other potentially useful information about your toolchain?

Nothing novel.

What did you do?

Minimal reproducer here: https://github.com/cstrahan/assert_bazel_repro

What did you expect to see?

Expected that runtime.Caller when tests are run under bazel to behave the same as when run through go test.

More specifically, I would expect testing libraries which make use of runtime.Caller to be able to open/read the caller's source file, for things like printing the assertion's expression. An example would be this library (which I use in my minimal reproducer): https://github.com/gotestyourself/gotest.tools

package assert_repro_test

import (
	"fmt"
	"log"
	"os"
	"syscall"
	"testing"

	"gotest.tools/v3/assert"
)

func TestAssertShouldWorkUnderBazel(t *testing.T) {
	// to prevent std{out,err} being out of order
	syscall.Dup2(1, 2)

	cwd, _ := os.Getwd()
	fmt.Println("===> CWD: ", cwd)

	fmt.Println("===> BEGIN FILES")
	entries, err := os.ReadDir("./")
	if err != nil {
		log.Fatal(err)
	}
	for _, e := range entries {
		fmt.Println(e.Name())
	}
	fmt.Println("===> END FILES")

	a := 1
	b := 2
	assert.Assert(t, a == b, "a should equal b")
}

For comparison, here's what we see with go test:

$ GOTESTTOOLS_DEBUG=1 go test ./some_package
===> CWD:  /Users/charles/src/assert_bazel_repro/some_package
===> BEGIN FILES
BUILD.bazel
repro_test.go
===> END FILES
DEBUG: call stack position: /Users/charles/src/assert_bazel_repro/some_package/repro_test.go:32
DEBUG: found node: (*ast.ExprStmt) assert.Assert(t, a == b, "a should equal b")
DEBUG: visit: (*ast.ExprStmt) assert.Assert(t, a == b, "a should equal b")
DEBUG: visit: (*ast.CallExpr) assert.Assert(t, a == b, "a should equal b")
DEBUG: callExpr: (*ast.CallExpr) assert.Assert(t, a == b, "a should equal b")
--- FAIL: TestAssertShouldWorkUnderBazel (0.00s)
    repro_test.go:32: assertion failed: a is not b: a should equal b
FAIL
FAIL    github.com/cstrahan/assert_bazel_repro/some_package     0.242s
FAIL

The important line is here:

DEBUG: call stack position: /Users/charles/src/assert_bazel_repro/some_package/repro_test.go:32

Note that this is an absolute path.

Also, we see that the testing library manages to successfully read the source file and print a helpful assertion message:

    repro_test.go:32: assertion failed: a is not b: a should equal b

What did you see instead?

When I run bazel test:

$ bazel test  --test_env=GOTESTTOOLS_DEBUG=1 --test_output=all --cache_test_results=no //some_package:some_package_test
INFO: Analyzed target //some_package:some_package_test (1 packages loaded, 2 targets configured).
INFO: Found 1 test target...
FAIL: //some_package:some_package_test (see /private/var/tmp/_bazel_charles/99cf13450b07a7c7594bbbe785fbd4ef/execroot/__main__/bazel-out/darwin_arm64-fastbuild/testlogs/some_package/some_package_test/test.log)
INFO: From Testing //some_package:some_package_test:
==================== Test output for //some_package:some_package_test:
===> CWD:  /private/var/tmp/_bazel_charles/99cf13450b07a7c7594bbbe785fbd4ef/sandbox/darwin-sandbox/177/execroot/__main__/bazel-out/darwin_arm64-fastbuild/bin/some_package/some_package_test_/some_package_test.runfiles/__main__/some_package
===> BEGIN FILES
repro_test.go
some_package_test_
===> END FILES
DEBUG: call stack position: some_package/repro_test.go:32
--- FAIL: TestAssertShouldWorkUnderBazel (0.00s)
    repro_test.go:32: failed to parse source file some_package/repro_test.go: open some_package/repro_test.go: no such file or directory
FAIL
================================================================================
Target //some_package:some_package_test up-to-date:
  bazel-bin/some_package/some_package_test_/some_package_test
INFO: Elapsed time: 1.417s, Critical Path: 1.18s
INFO: 7 processes: 1 internal, 6 darwin-sandbox.
INFO: Build completed, 1 test FAILED, 7 total actions
//some_package:some_package_test                                         FAILED in 0.3s
  /private/var/tmp/_bazel_charles/99cf13450b07a7c7594bbbe785fbd4ef/execroot/__main__/bazel-out/darwin_arm64-fastbuild/testlogs/some_package/some_package_test/test.log

Executed 1 out of 1 test: 1 fails locally.

Note:

DEBUG: call stack position: some_package/repro_test.go:32

The path here is relative. As a result, the testing library will fail to open and read the repro_test.go file, because it will effectively try to open:

/private/var/tmp/_bazel_charles/99cf13450b07a7c7594bbbe785fbd4ef/sandbox/darwin-sandbox/177/execroot/__main__/bazel-out/darwin_arm64-fastbuild/bin/some_package/some_package_test_/some_package_test.runfiles/__main__/some_package/some_package/repro_test.go

When it really needs to open this:

/private/var/tmp/_bazel_charles/99cf13450b07a7c7594bbbe785fbd4ef/sandbox/darwin-sandbox/177/execroot/__main__/bazel-out/darwin_arm64-fastbuild/bin/some_package/some_package_test_/some_package_test.runfiles/__main__/some_package/repro_test.go

Consequently, the testing library explodes when it tries to formulate that nice assertion message:

    repro_test.go:32: failed to parse source file some_package/repro_test.go: open some_package/repro_test.go: no such file or directory

(I've opened an issue with them to see if we can at least more gracefully handle this error, choosing to at least print the user provided assertion message when the file can't be opened/read: gotestyourself/gotest.tools#274)

Can the go test binaries be compiled in such a manner so that runtime.Caller would give the full, absolute path?

[fmeum]

If we compile absolute paths into files, we lose most of the qualities that motivate using Bazel in the first place: caching and reproducibility. Furthermore, sandboxed execution won't see the source files in the first place as they aren't inputs of the test action.

We could probably get this work with bazel run, which is designed to be non-hermetic and contains the prefix for all the paths in the BUILD_WORKSPACE_DIRECTORY environment variable. Could you see that being good enough?

[cstrahan]

If we compile absolute paths into files, we lose most of the qualities that motivate using Bazel in the first place: caching and reproducibility. Furthermore, sandboxed execution won't see the source files in the first place as they aren't inputs of the test action.

Ah, that makes sense. Too much time spent away from Bazel and in Nix instead, where store model and sandboxing approach would "just work". Thanks for pointing that out.

We could probably get this work with bazel run, which is designed to be non-hermetic and contains the prefix for all the paths in the BUILD_WORKSPACE_DIRECTORY environment variable. Could you see that being good enough?

After dumping the env vars, and double checking https://bazel.build/reference/test-encyclopedia, it looks like gotest.tools can probably do what it needs to do by checking if we're running under Bazel ($BAZEL_TEST) and join the source paths to $TEST_SRCDIR.

There may be utility in implementing what you describe, but I don't think we'll have an immediate need for it -- though I would definitely circle back if we do!

Thanks for the help! 🙏

[fmeum]

Sounds good! I will close for now, but feel free to post again if rules_go must do anything to improve interoperability with gotest.

[cstrahan]

Quick update: I've opened a PR here: gotestyourself/gotest.tools#276

To recover the absolute path to the target source file, it joins $TEST_SRCDIR, $TEST_WORKSPACE and the relative path from runtime.Caller.