cmd/go: unexpected test cache hit of "PASS" when test should "FAIL" #30313

myitcv · 2019-02-19T14:47:26Z

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

$ go version
go version go1.12rc1 linux/amd64

Does this issue reproduce with the latest release?

Testing with the 1.12rc1 ahead of the release

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

go env Output

$ go env
GOARCH="amd64"
GOBIN=""
GOCACHE="/tmp/tmp.J3hpB7VPny"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/tmp/tmp.HS8GyDw25c"
GOPROXY=""
GORACE=""
GOROOT="/home/myitcv/gos"
GOTMPDIR=""
GOTOOLDIR="/home/myitcv/gos/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/tmp/tmp.HS8GyDw25c/src/example.com/consttofile/go.mod"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build403487949=/tmp/go-build -gno-record-gcc-switches"

What did you do?

> cd $(mktemp -d)
> git clone https://github.com/myitcv/cacherepro src/example.com/consttofile
Cloning into 'src/example.com/consttofile'...
remote: Enumerating objects: 13, done.
remote: Counting objects: 100% (13/13), done.
remote: Compressing objects: 100% (12/12), done.
remote: Total 13 (delta 1), reused 13 (delta 1), pack-reused 0
Unpacking objects: 100% (13/13), done.
> cd src/example.com/consttofile
> go mod download
go: finding github.com/rogpeppe/go-internal v1.2.1
go: finding golang.org/x/tools v0.0.0-20190125232054-d66bd3c5d5a6
go: finding gopkg.in/errgo.v2 v2.1.0
go: finding github.com/kr/pretty v0.1.0
go: finding gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127
go: finding github.com/kr/text v0.1.0
go: finding github.com/kr/pty v1.1.1

The first run of go test . does not result in a cache hit, as expected:

> go test .
ok      example.com/consttofile 0.666s

The second run does; not clear whether this is expected or not given the code in question:

> go test .
ok      example.com/consttofile (cached)

Now let's remove the flag -silent which should cause the testscript test in testdata/missing.txt to fail:

> cp main.go.bad main.go

Re-run the tests:

> go test .
ok      example.com/consttofile (cached)

This cache hit is definitely unexpected and not only that it's wrong:

> go test
--- FAIL: TestScripts (0.65s)
    --- FAIL: TestScripts/testscript (0.00s)
        --- FAIL: TestScripts/testscript/missing (0.08s)
            <autogenerated>:1:
                > ! go generate -tags noflag
                [stderr]
                failed to find const myfile_txt

                noflag.go:5: running "consttofile": exit status 1

                [exit status 1]
                > cmp stderr fail.txt
                > go generate -tags flag
                [stderr]
                flag provided but not defined: -silent
                consttofile expands a package-level string constant to a file.

                consttofile is best used via go generate directives in a main package:

                  //go:generate consttofile myconst_txt

                Running go generate (or any other program that understands go:generate
                directives) will result in a single file, gen_myconst_consttofile.txt, that
                contains the value of the string constant myconst_txt.
                flag provided but not defined: -silent
                flag.go:5: running "consttofile": exit status 1

                [exit status 1]
                FAIL: testdata/missing.txt:4: unexpected go command failure

FAIL

Re-running go test . we still get an incorrect cache hit:

> go test .
ok      example.com/consttofile (cached)

But if we:

> touch testdata/missing.txt

then:

> go test .
--- FAIL: TestScripts (0.62s)
    --- FAIL: TestScripts/testscript (0.00s)
        --- FAIL: TestScripts/testscript/missing (0.08s)
            <autogenerated>:1:
                > ! go generate -tags noflag
                [stderr]
                failed to find const myfile_txt

                noflag.go:5: running "consttofile": exit status 1

                [exit status 1]
                > cmp stderr fail.txt
                > go generate -tags flag
                [stderr]
                flag provided but not defined: -silent
                consttofile expands a package-level string constant to a file.

                consttofile is best used via go generate directives in a main package:

                  //go:generate consttofile myconst_txt

                Running go generate (or any other program that understands go:generate
                directives) will result in a single file, gen_myconst_consttofile.txt, that
                contains the value of the string constant myconst_txt.
                flag provided but not defined: -silent
                flag.go:5: running "consttofile": exit status 1

                [exit status 1]
                FAIL: testdata/missing.txt:4: unexpected go command failure

FAIL

What did you expect to see?

For go test . not to report a "cached" result of success when in fact go test results in a failure.

Also to note, if the above steps are repeated outside of GOPATH then the test results are never cached:

cd $(mktemp -d)
git clone https://github.com/myitcv/cacherepro .
go test .
go test .

gives:

> go test .
ok      example.com/consttofile 0.674s
> go test .
ok      example.com/consttofile 0.675s

What did you see instead?

When within GOPATH, go test . incorrectly reports a cached result of "success" when go test results in a fail.

cc @bcmills

The text was updated successfully, but these errors were encountered:

myitcv · 2019-02-19T14:50:28Z

At least based on my understanding, this issue does not appear to be exactly the same as either #26790 or #29111

jayconrod · 2019-02-20T01:23:02Z

I tried to reproduce this, but I actually didn't see go test . hit the cache on the second run. Which is not what I expected. I'm also running Go 1.12rc1.

As far as I understand, go test keeps a record of all the files that were accessed through common I/O functions, and incorporates hashes of those files into the cache key for the test result. go test won't know if you access a file through some other mechanism. Since this test is accessing files through a subcommand, go test may not know that the cached test result should be invalidated.

I'll take a closer look tomorrow. There may not be an easy solution though.

myitcv · 2019-02-20T09:34:33Z

Thanks @jayconrod

The following testscript script should repro the issue:

env GO111MODULE=on
env GOPATH=$WORK/gopath
mkdir gopath
exec git clone https://github.com/myitcv/cacherepro gopath/src/example.com/consttofile
cd gopath/src/example.com/consttofile
go mod download
go test .
go test .
cp main.go.bad main.go
! go test .

This fails with:

> go test .
[stdout]
ok      example.com/consttofile 0.722s

> go test .
[stdout]
ok      example.com/consttofile (cached)

> cp main.go.bad main.go
> ! go test .
[stdout]
ok      example.com/consttofile (cached)

FAIL: /tmp/testscript635956775/0/script.txt:10: unexpected go command success

jayconrod · 2019-02-20T23:40:32Z

I think I understand this now.

The difference between main.go.bad and main.go.good is only in body of the mainerr function, which is only reachable from the main function. When the test binary is created, the linker eliminates mainerr, since it's dead code within the test binary. It doesn't show up in the output of go tool nm. More importantly, the sha256 of the test binary is identical when you zero out the build id, which is how we compute the content id.

So as far as the cache is concerned, after the source file change, the test binary is identical. A hash of the test binary is used to derive a cache key, which is used to look up a list of files the test accessed previously. None of the known input files have changed, so the cache test result is used.

Of course, the code in the "dead" function actually matters for this test, since it runs go install ., then runs that binary. We don't know (and can't know) the files that go install . and other subcommands access, and the content of those files don't affect the cache key.

I'm going to close this issue because the cache is working as designed here. I'm not sure the details of this are documented anywhere. #22593 seems to be where this was originally discussed. #23799 would probably be the right fix for this: this test would need to identify itself as uncacheable if there were a way to do so.

myitcv · 2019-02-21T11:55:49Z

@jayconrod - that makes total sense, thanks.

Apologies, in this situation it's definitely a case of my error, so thank you for taking the time to look into this.

The usual pattern I follow for testing programs has a reference from main_test.go to main1, e.g.:

func TestMain(m *testing.M) {
	os.Exit(testscript.RunMain(m, map[string]func() int{
		"testscript": main1,
	}))
}

(taken from testscript)

In this case, because the program I'm testing is a go generate code generator, I need the program to be available in the PATH of the testscript script. Hence the go install followed by the augmentation of the PATH environment variable available to the script.

The problem I'm seeing is easily solved by keeping such a reference form main_test.go to main1, even if that shorthand command definition never gets used.

myitcv added the GoCommand cmd/go label Feb 19, 2019

jayconrod added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Feb 20, 2019

jayconrod self-assigned this Feb 20, 2019

jayconrod closed this as completed Feb 20, 2019

golang locked and limited conversation to collaborators Feb 21, 2020

gopherbot added the FrozenDueToAge label Feb 21, 2020

rsc unassigned jayconrod Jun 23, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

cmd/go: unexpected test cache hit of "PASS" when test should "FAIL" #30313

cmd/go: unexpected test cache hit of "PASS" when test should "FAIL" #30313

myitcv commented Feb 19, 2019

myitcv commented Feb 19, 2019

jayconrod commented Feb 20, 2019

myitcv commented Feb 20, 2019

jayconrod commented Feb 20, 2019

myitcv commented Feb 21, 2019

cmd/go: unexpected test cache hit of "PASS" when test should "FAIL" #30313

cmd/go: unexpected test cache hit of "PASS" when test should "FAIL" #30313

Comments

myitcv commented Feb 19, 2019

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

Does this issue reproduce with the latest release?

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

What did you do?

What did you expect to see?

What did you see instead?

myitcv commented Feb 19, 2019

jayconrod commented Feb 20, 2019

myitcv commented Feb 20, 2019

jayconrod commented Feb 20, 2019

myitcv commented Feb 21, 2019

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

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