testing, cmd/go: dependencies in init functions are not recorded in the 'go test' cache key

[aronatkins]

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

$ go version
go version go1.16 darwin/amd64

Does this issue reproduce with the latest release?

Yes

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

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/aron/Library/Caches/go-build"
GOENV="/Users/aron/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/aron/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/aron/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64"
GOVCS=""
GOVERSION="go1.16"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/aron/go/src/foo/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 -arch x86_64 -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/h8/bl1lkr792xz68jzf9s70jzwm0000gn/T/go-build2392571666=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

This is a three-package layout with foo, foo/a and foo/b. Both sub-packages have identical non-test code, but slightly different test code. The foo package uses code from a and b in identical ways. The foo package only has test code (to simplify the example; the real situation has code in all three packages).

• foo - uses values initialized from environment variables in foo/a and foo/b
• foo/a - uses value initialized from environment variable; test code contains additional environment variable read
• foo/b - uses value initialized from environment variable

Code to exercise issue

// file: foo_test.go
package foo

import (
	"testing"

	"foo/a"
	"foo/b"
)

func TestA(t *testing.T) {
	cur := a.IsConfigured()
	if cur != a.Configured {
		t.Errorf("Configured = %v; want %v", cur, a.Configured)
	}
}

func TestB(t *testing.T) {
	cur := b.IsConfigured()
	if cur != b.Configured {
		t.Errorf("Configured = %v; want %v", cur, b.Configured)
	}
}

// file: foo/a.go
package a

import "os"

var Configured bool

func init() {
	Configured = os.Getenv("SETTING") == "ok"
}

func IsConfigured() bool {
	return Configured
}

// file: foo/a_test.go
package a

import "os"
import "testing"

func TestConfigured(t *testing.T) {
	raw := os.Getenv("SETTING")
	cur := IsConfigured()
	if cur != Configured {
		t.Errorf("Configured = %v; want %v; raw %v", cur, Configured, raw)
	}
}

// file: foo/b.go
package b

import "os"

var Configured bool

func init() {
	Configured = os.Getenv("SETTING") == "ok"
}

func IsConfigured() bool {
	return Configured
}

// file: b_test.go
package b

import "testing"

func TestConfigured(t *testing.T) {
	cur := IsConfigured()
	if cur != Configured {
		t.Errorf("Configured = %v; want %v", cur, Configured)
	}
}

Testing these packages with and without the SETTING environment variable uses a cached result for the foo and foo/b packages. The foo/a package, in contrast, runs each time SETTING is changed.

$ go clean -testcache
$ go test foo/...
ok  	foo	0.062s
ok  	foo/a	0.105s
ok  	foo/b	0.149s
$ SETTING=ok go test foo/...
ok  	foo	(cached)
ok  	foo/a	0.059s
ok  	foo/b	(cached)
$ SETTING=not-ok go test foo/...
ok  	foo	(cached)
ok  	foo/a	0.057s
ok  	foo/b	(cached)

What did you expect to see?

All packages that use SETTING, either directly or indirectly, should be run for each change to the SETTING value.

What did you see instead?

Only foo/a, with a read of SETTING from test code, is run each time SETTING is changed. The other packages are skipped with cached results.

[bcmills]

This is an unfortunate interaction between go test and the testing package.

The testing package reroutes the os package to write to a log file, which cmd/go then reads to determine when to invalidate the cache. Unfortunately, the logging hook is not initialized until the tests actually start running, so data dependencies that occur before then (such as in init functions) are missed.

I'm not entirely sure how we can fix this.

The hook is currently installed in (*testing.M).before:

go/src/testing/testing.go

Line 1584 in 27684ea

m.deps.StartTestLog(f)

CC @jayconrod @matloob @ianlancetaylor

[jayconrod]

In Bazel go_test, we run some code in the init function of a synthetic package imported by the test main package. It's mainly used to switch to the package directory (Bazel runs tests from the workspace root).

Not sure if that would be useful here or even a good idea. At minimum, it relies on packages being initialized in the order they're imported; the order is not defined in the spec.

[ianlancetaylor]

I don't know if we can do a perfect fix, but one thing we could do is have cmd/go set a known environment variable when invoking the test binary. Then we could add an init function in the os package that checks for the environment variable, and, if found, calls the internal/testlog functions with some flag to tells them to cache the data if there is no testlog.logger. Then when testlog.SetLogger is called it can play the cached data into the log. Or something like that. But I'm not sure how to avoid caching unbounded amounts of data if nothing ever calls testlog.SetLogger.

[bcmills]

I'm not sure how to avoid caching unbounded amounts of data if nothing ever calls testlog.SetLogger.

Could we fix this at link time, perhaps?

I'm thinking something like:

• When linking the test, poke in some (unexported or internal) variable that causes os to record accesses in an in-memory log.
• In the generated main function, right before we invoke TestMain, call a method to indicate that package-init is complete and no further accesses should be recorded.
• If / when testlog.SetLogger is called, dump the in-memory log to the logger.

That reduces the set of unrecorded races to only what happens within separate goroutines that are started during package-init, which should be quite rare. It does introduce a memory cost for test processes that are hijacked from within TestMain, but those should also be pretty rare and at least no further memory is leaked after the TestMain invocation.

[dvyukov]

I am hitting this issue with an Appengine app tests. The app uses html/template.Must(Glob("*.html")) in initialization of a global var. I think it's pretty common pattern(?). Then changing (breaking) any html files is not caught by testing.
I am also thinking along the lines of starting logging as early as possible and caching the log in memory. We don't even need to write it to file until all tests succeed (failures/crashes are not cached, right?).

[dvyukov]

I tentatively removed the Unfortunate label. The behavior is definitely unfortunate, but not in the sense that we can't fix it, right?