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.

Comment From: gabyhelp

Related Issues and Documentation

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

Comment From: dr2chase

@adonovan , @neild , @rsc

Comment From: rittneje

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

Comment From: 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.

Comment From: 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

Comment From: 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.

Comment From: 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

Comment From: seankhliao

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

Comment From: 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

Comment From: rittneje

@adonovan , @neild , @rsc

Comment From: adonovan

@matloob @samthanawalla

Comment From: matloob

We need to investigate this more thoroughly but it seems like somehow a cached file that is needed to build test2 is being trimmed by the go run. We should be marking a file as 'used' and updating its modification time so it's not obvious to me why this is happening.