cmd/go: invoking go run from go test can corrupt build cache

[rittneje]

Go version

go version go1.22.7 linux/amd64

Output of go env in your module/workspace:

GO111MODULE=''
GOARCH='amd64'
GOBIN=''
GOCACHE='/tmp/.gocache'
GOENV='/root/.config/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='amd64'
GOHOSTOS='linux'
GOINSECURE=''
GOMODCACHE='/go/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='linux'
GOPATH='/go'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/usr/local/go'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='local'
GOTOOLDIR='/usr/local/go/pkg/tool/linux_amd64'
GOVCS=''
GOVERSION='go1.22.7'
GCCGO='gccgo'
GOAMD64='v1'
AR='ar'
CC='gcc'
CXX='g++'
CGO_ENABLED='1'
GOMOD='/Users/rittneje/go-test-bug/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 -m64 -pthread -Wl,--no-gc-sections -fmessage-length=0 -ffile-prefix-map=/tmp/go-build1468831127=/tmp/go-build -gno-record-gcc-switches'

What did you do?

I have the following files:

go.mod

module gotestbug

go 1.22

pkg1/foo_test.go

package pkg1

import (
	"bytes"
	"os/exec"
	"path/filepath"
	"testing"
)

func TestFoo(t *testing.T) {
	cmd := exec.Command("go", "run", filepath.Join("testdata", "main.go"))
	output := new(bytes.Buffer)
	cmd.Stdout = output
	cmd.Stderr = output

	t.Logf("+ %s", cmd)
	if err := cmd.Run(); err != nil {
		t.Fatal(err, output)
	}
}

pkg1/testdata/main.go

package main

func main() {
}

pkg2/bar_test.go

package pkg2

import (
	"testing"
)

func TestBar(t *testing.T) {
	t.Log("hello")
}

I then ran the following commands as root to prime the build cache. (I intentionally set the mtimes and trim.txt file to the past in order to reproduce the bug.)

go clean -cache
go build std
chmod -R a+rwX "${GOCACHE}"
find "${GOCACHE}" -type f -exec touch '{}' -d '2024-07-01 00:00:00' \;
printf '1719792000' > "${GOCACHE}/trim.txt"

Finally I ran go test as a non-root user. (I passed -p=1 to force it to run one package at a time in order to make the bug happen deterministically.)

go test -v -count=1 -p=1 ./...

What did you see happen?

As described in #69565, since the build cache was crafted to look old, go run decided to trim it. This somehow causes go test to break.

=== RUN   TestFoo
    foo_test.go:16: + /usr/local/go/bin/go run testdata/main.go
--- PASS: TestFoo (0.15s)
PASS
ok      gotestbug/pkg1  0.148s
# gotestbug/pkg2 [gotestbug/pkg2.test]
pkg2/bar_test.go:4:2: could not import testing (open /tmp/.gocache/26/26737db8c74b26401dc8828801cc3793a888d7c29c40b7500b7e9e5f96deec19-d: no such file or directory)
FAIL    gotestbug/pkg2 [build failed]
FAIL

It should be noted that this issue does not happen if I run go test as root.

What did you expect to see?

The test should pass without any compilation issues.

[gabyhelp]

Related Issues and Documentation

• cmd/go: go build errors that don't correspond to source file until build cache is cleared #69179
• build: run.bash: make test configuration independent of the user's GOENV file #54084 (closed)
• cmd/go: error if GOCACHE is set but is not an absolute path #30447 (closed)
• cmd/go: tests fail when GOROOT is stale #48698 (closed)
• cmd/go: test reported as cached, but not actually cached #41593
• cmd/go clean -testcache does not clean test cache #29757 (closed)
• go/build: tests use a non-hermetic "go" binary #39198 (closed)
• cmd/go: cache not invalidated if testdata files are changed while the test is running #26790
• x/tools/gopls/test/debug: test fails when run in the module cache #59841 (closed)
• cmd/go: 'go test' fails to cache test result due to modified `.git` directory #52573 (closed)

_{(Emoji vote if this was helpful or unhelpful; more detailed feedback welcome in this discussion.)}

[dr2chase]

@adonovan , @neild , @rsc

[rittneje]

@adonovan , @neild , @rsc following up on this

[seankhliao]

I think this is missing information to be reproducible. It doesn't fail on my system (native linux), nor does it fail in a docker container.

[rittneje]

@seankhliao I just reproduced it again using 1.22.7-alpine container following these steps. Please be sure to follow all the steps carefully, including which ones are run as root vs. non-root, and make sure both users are using the same $GOCACHE.

First, create the go.mod and go files as described above. Then from a terminal in that directory:

$ docker run --rm -it -v $PWD:$PWD:ro -w $PWD --name bug69566 -e GOCACHE=/tmp/.gocache golang:1.22.7-alpine
# go clean -cache
# go build std
# chmod -R a+rwX "${GOCACHE}"
# find "${GOCACHE}" -type f -exec touch '{}' -d '2024-07-01 00:00:00' \;
# printf '1719792000' > "${GOCACHE}/trim.txt"

DON'T exit the container yet.

Second terminal:

$ docker exec --user 1000:1000 -it bug69566 go test -v -count=1 -p=1 ./...
=== RUN   TestFoo
    foo_test.go:16: + /usr/local/go/bin/go run testdata/main.go
--- PASS: TestFoo (0.05s)
PASS
ok      gotestbug/pkg1  0.047s
# gotestbug/pkg2 [gotestbug/pkg2.test]
pkg2/bar_test.go:4:2: could not import testing (open /tmp/.gocache/29/296368aeed90a129a28950e111fd458e601eed33c87eeef072b3b96018f4a860-d: no such file or directory)
FAIL    gotestbug/pkg2 [build failed]
FAIL

[seankhliao]

As far as I can tell, marking the cache entry as used by updating the mtime/atime with os.Chtimes fails with "operation not permitted" during the build of the test
https://go.googlesource.com/go/+/37f27fbecd422da9fefb8ae1cc601bc5b4fec44b/src/cmd/go/internal/cache/cache.go#366

Which results in the cache entry getting trimmed during the go run.

Does it only fail in docker? it may be an issue with overlayfs.
It doesn't fail if I mount a tmpfs for the go cache (--tmpfs /tmp/.gocache).
side note: I'm not sure why exec touch works, but os.Chtimes fails if run during the test.

[rittneje]

@seankhliao I am also able to reproduce this issue on my Linux VM (i.e., without docker).

$ sudo su
# export GOCACHE=/tmp/.gocache
# path/to/go1.22.7/bin/go clean -cache
# path/to/go1.22.7/bin/go build std
# chmod -R a+rwX "${GOCACHE}"
# find "${GOCACHE}" -type f -exec touch '{}' -d '2024-07-01 00:00:00' \;
# printf '1719792000' > "${GOCACHE}/trim.txt"
# exit
$ export GOCACHE=/tmp/.gocache
$ go test -v -count=1 -p=1 ./...
=== RUN   TestFoo
    foo_test.go:16: + /home/rittneje/go1.22.7/bin/go run testdata/main.go
--- PASS: TestFoo (0.08s)
PASS
ok  	gotestbug/pkg1	0.078s
# gotestbug/pkg2 [gotestbug/pkg2.test]
pkg2/bar_test.go:4:2: could not import testing (open /tmp/.gocache/29/296368aeed90a129a28950e111fd458e601eed33c87eeef072b3b96018f4a860-d: no such file or directory)
FAIL	gotestbug/pkg2 [build failed]
FAIL

[seankhliao]

what's the mount type / fs of your tmp?

[rittneje]

In my VM, I get this:

$ df -Th
Filesystem     Type      Size  Used Avail Use% Mounted on
tmpfs          tmpfs     391M  1.5M  389M   1% /run
/dev/sda2      ext4       19G  8.9G  8.9G  51% /
tmpfs          tmpfs     2.0G     0  2.0G   0% /dev/shm
tmpfs          tmpfs     5.0M  8.0K  5.0M   1% /run/lock
efivarfs       efivarfs  256K  3.3K  253K   2% /sys/firmware/efi/efivars
rittneje       vboxsf    927G  264G  663G  29% /media/sf_rittneje
/dev/sda1      vfat      952M  6.4M  945M   1% /boot/efi
tmpfs          tmpfs     391M  120K  390M   1% /run/user/1000

Seems to be ext4.

I also re-ran the test with GOCACHE=/run/user/1000/.gocache (which is tmpfs) and it still failed.

$ go test -v -count=1 -p=1 ./...
=== RUN   TestFoo
    foo_test.go:16: + /home/rittneje/go1.22.7/bin/go run testdata/main.go
--- PASS: TestFoo (0.06s)
PASS
ok  	gotestbug/pkg1	0.063s
# gotestbug/pkg2 [gotestbug/pkg2.test]
pkg2/bar_test.go:4:2: could not import testing (open /run/user/1000/.gocache/29/296368aeed90a129a28950e111fd458e601eed33c87eeef072b3b96018f4a860-d: no such file or directory)
FAIL	gotestbug/pkg2 [build failed]
FAIL

[rittneje]

@adonovan , @neild , @rsc

[adonovan]

@matloob @samthanawalla