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

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

Closed
myitcv opened this issue Feb 19, 2019 · 5 comments

Comments

Projects
None yet
2 participants
@myitcv
Copy link
Member

commented Feb 19, 2019

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

@myitcv

This comment has been minimized.

Copy link
Member Author

commented Feb 19, 2019

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

@myitcv myitcv added the GoCommand label Feb 19, 2019

@jayconrod

This comment has been minimized.

Copy link
Contributor

commented Feb 20, 2019

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.

@jayconrod jayconrod self-assigned this Feb 20, 2019

@myitcv

This comment has been minimized.

Copy link
Member Author

commented Feb 20, 2019

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

This comment has been minimized.

Copy link
Contributor

commented Feb 20, 2019

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.

@jayconrod jayconrod closed this Feb 20, 2019

@myitcv

This comment has been minimized.

Copy link
Member Author

commented Feb 21, 2019

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.