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

aronatkins · 2021-02-26T02:52:02Z

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.

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

bcmills · 2021-02-26T21:17:50Z

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 · 2021-02-26T22:26:56Z

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 · 2021-02-27T03:02:26Z

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 · 2021-03-01T20:28:00Z

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 · 2021-06-17T09:01:09Z

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 · 2021-06-17T09:03:06Z

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

bcmills changed the title ~~cmd/go: tests skipped due to cache even with environment variable changes~~ testing, cmd/go: environment dependencies in init functions are not recorded in the 'go test' cache key Feb 26, 2021

bcmills added NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. Unfortunate labels Feb 26, 2021

bcmills added this to the Backlog milestone Feb 26, 2021

dvyukov removed Unfortunate NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Jun 17, 2021

dvyukov changed the title ~~testing, cmd/go: environment dependencies in init functions are not recorded in the 'go test' cache key~~ testing, cmd/go: dependencies in init functions are not recorded in the 'go test' cache key Jun 17, 2021

dvyukov mentioned this issue Jun 17, 2021

dashboard/app: add last activity info to bug list google/syzkaller#2626

Merged

bcmills added NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. GoCommand cmd/go labels Jun 17, 2021

seankhliao mentioned this issue Jul 20, 2021

go test cache check wrong opened file when testing if user do os.Chdir #47305

Closed

bcmills mentioned this issue Aug 6, 2021

bug: GODEBUG getting cached #47574

Closed

bcmills mentioned this issue Apr 26, 2023

testing: calling os.Getenv in TestMain does not factor into test cache #59849

Closed

findleyr mentioned this issue May 8, 2023

cmd/go,testing: GOWORK value does not invalidate test cache #60052

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

aronatkins commented Feb 26, 2021

bcmills commented Feb 26, 2021

jayconrod commented Feb 26, 2021

ianlancetaylor commented Feb 27, 2021

bcmills commented Mar 1, 2021

dvyukov commented Jun 17, 2021

dvyukov commented Jun 17, 2021

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

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

Comments

aronatkins commented Feb 26, 2021

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?

bcmills commented Feb 26, 2021

jayconrod commented Feb 26, 2021

ianlancetaylor commented Feb 27, 2021

bcmills commented Mar 1, 2021

dvyukov commented Jun 17, 2021

dvyukov commented Jun 17, 2021

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

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