cmd/go: invalidate cached test results if env vars or files change

When we write a cached test result, we now also write a log of the
environment variables and files inspected by the test run,
along with a hash of their content. Before reusing a cached test result,
we recompute the hash of the content specified by the log, and only
use the result if that content has not changed.

This makes test caching behave correctly for tests that consult
environment variables or stat or read files or directories.

Fixes #22593.

Change-Id: I8608798e73c90e0c1911a38bf7e03e1232d784dc
Reviewed-on: https://go-review.googlesource.com/81895
Run-TryBot: Russ Cox <rsc@golang.org>
Reviewed-by: Ian Lance Taylor <iant@golang.org>

src/cmd/go/go_test.go

@@ -2479,7 +2479,7 @@ func TestCoveragePattern(t *testing.T) {
 	// (as opposed to pattern matching on deps)
 	// then it will try to load sleepybad, which does not compile,
 	// and the test command will fail.
-	tg.run("test", "-coverprofile="+filepath.Join(tg.tempdir, "cover.out"), "-coverpkg=sleepy...", "-run=^$", "sleepy1")
+	tg.run("test", "-coverprofile="+tg.path("cover.out"), "-coverpkg=sleepy...", "-run=^$", "sleepy1")
 }
 
 func TestCoverageErrorLine(t *testing.T) {
@@ -2530,7 +2530,7 @@ func TestCoverageFunc(t *testing.T) {
 	tg.setenv("GOPATH", filepath.Join(tg.pwd(), "testdata"))
 
 	tg.run("test", "-outputdir="+tg.tempdir, "-coverprofile=cover.out", "coverasm")
-	tg.run("tool", "cover", "-func="+filepath.Join(tg.tempdir, "cover.out"))
+	tg.run("tool", "cover", "-func="+tg.path("cover.out"))
 	tg.grepStdout(`\tg\t*100.0%`, "did not find g 100% covered")
 	tg.grepStdoutNot(`\tf\t*[0-9]`, "reported coverage for assembly function f")
 }
@@ -4344,7 +4344,7 @@ func main() {
 }
 `)
 	tg.setenv("GOPATH", tg.path("go"))
-	exe := filepath.Join(tg.tempdir, "p.exe")
+	exe := tg.path("p.exe")
 	tg.creatingTemp(exe)
 	tg.run("build", "-o", exe, "p")
 }
@@ -4958,7 +4958,7 @@ func TestCacheCoverage(t *testing.T) {
 	tg.setenv("GOPATH", filepath.Join(tg.pwd(), "testdata"))
 	tg.makeTempdir()
 
-	tg.setenv("GOCACHE", filepath.Join(tg.tempdir, "c1"))
+	tg.setenv("GOCACHE", tg.path("c1"))
 	tg.run("test", "-cover", "strings")
 	tg.run("test", "-cover", "math", "strings")
 }
@@ -4987,12 +4987,12 @@ func TestIssue22531(t *testing.T) {
 	tg.parallel()
 	tg.makeTempdir()
 	tg.setenv("GOPATH", tg.tempdir)
-	tg.setenv("GOCACHE", filepath.Join(tg.tempdir, "cache"))
+	tg.setenv("GOCACHE", tg.path("cache"))
 	tg.tempFile("src/m/main.go", "package main /* c1 */; func main() {}\n")
 	tg.run("install", "-x", "m")
 	tg.run("list", "-f", "{{.Stale}}", "m")
 	tg.grepStdout("false", "reported m as stale after install")
-	tg.run("tool", "buildid", filepath.Join(tg.tempdir, "bin/m"+exeSuffix))
+	tg.run("tool", "buildid", tg.path("bin/m"+exeSuffix))
 
 	// The link action ID did not include the full main build ID,
 	// even though the full main build ID is written into the
@@ -5003,7 +5003,7 @@ func TestIssue22531(t *testing.T) {
 	tg.run("install", "-x", "m")
 	tg.run("list", "-f", "{{.Stale}}", "m")
 	tg.grepStdout("false", "reported m as stale after reinstall")
-	tg.run("tool", "buildid", filepath.Join(tg.tempdir, "bin/m"+exeSuffix))
+	tg.run("tool", "buildid", tg.path("bin/m"+exeSuffix))
 }
 
 func TestIssue22596(t *testing.T) {
@@ -5014,17 +5014,17 @@ func TestIssue22596(t *testing.T) {
 	defer tg.cleanup()
 	tg.parallel()
 	tg.makeTempdir()
-	tg.setenv("GOCACHE", filepath.Join(tg.tempdir, "cache"))
+	tg.setenv("GOCACHE", tg.path("cache"))
 	tg.tempFile("gopath1/src/p/p.go", "package p; func F(){}\n")
 	tg.tempFile("gopath2/src/p/p.go", "package p; func F(){}\n")
 
-	tg.setenv("GOPATH", filepath.Join(tg.tempdir, "gopath1"))
+	tg.setenv("GOPATH", tg.path("gopath1"))
 	tg.run("list", "-f={{.Target}}", "p")
 	target1 := strings.TrimSpace(tg.getStdout())
 	tg.run("install", "p")
 	tg.wantNotStale("p", "", "p stale after install")
 
-	tg.setenv("GOPATH", filepath.Join(tg.tempdir, "gopath2"))
+	tg.setenv("GOPATH", tg.path("gopath2"))
 	tg.run("list", "-f={{.Target}}", "p")
 	target2 := strings.TrimSpace(tg.getStdout())
 	tg.must(os.MkdirAll(filepath.Dir(target2), 0777))
@@ -5043,7 +5043,7 @@ func TestTestCache(t *testing.T) {
 	tg.parallel()
 	tg.makeTempdir()
 	tg.setenv("GOPATH", tg.tempdir)
-	tg.setenv("GOCACHE", filepath.Join(tg.tempdir, "cache"))
+	tg.setenv("GOCACHE", tg.path("cache"))
 
 	// timeout here should not affect result being cached
 	// or being retrieved later.
@@ -5138,6 +5138,95 @@ func TestTestCache(t *testing.T) {
 	tg.grepStdout(`ok  \tt/t4\t\(cached\)`, "did not cache t/t4")
 }
 
+func TestTestCacheInputs(t *testing.T) {
+	if strings.Contains(os.Getenv("GODEBUG"), "gocacheverify") {
+		t.Skip("GODEBUG gocacheverify")
+	}
+	tg := testgo(t)
+	defer tg.cleanup()
+	tg.parallel()
+	tg.makeTempdir()
+	tg.setenv("GOPATH", filepath.Join(tg.pwd(), "testdata"))
+	tg.setenv("GOCACHE", tg.path("cache"))
+
+	defer os.Remove(filepath.Join(tg.pwd(), "testdata/src/testcache/file.txt"))
+	tg.must(ioutil.WriteFile(filepath.Join(tg.pwd(), "testdata/src/testcache/file.txt"), []byte("x"), 0644))
+	old := time.Now().Add(-1 * time.Minute)
+	tg.must(os.Chtimes(filepath.Join(tg.pwd(), "testdata/src/testcache/file.txt"), old, old))
+	info, err := os.Stat(filepath.Join(tg.pwd(), "testdata/src/testcache/file.txt"))
+	if err != nil {
+		t.Fatal(err)
+	}
+	t.Logf("file.txt: old=%v, info.ModTime=%v", old, info.ModTime()) // help debug when Chtimes lies about succeeding
+	tg.setenv("TESTKEY", "x")
+
+	tg.must(ioutil.WriteFile(filepath.Join(tg.pwd(), "testdata/src/testcache/script.sh"), []byte("#!/bin/sh\nexit 0\n"), 0755))
+	tg.must(os.Chtimes(filepath.Join(tg.pwd(), "testdata/src/testcache/script.sh"), old, old))
+
+	tg.run("test", "testcache")
+	tg.run("test", "testcache")
+	tg.grepStdout(`\(cached\)`, "did not cache")
+
+	tg.setenv("TESTKEY", "y")
+	tg.run("test", "testcache")
+	tg.grepStdoutNot(`\(cached\)`, "did not notice env var change")
+	tg.run("test", "testcache")
+	tg.grepStdout(`\(cached\)`, "did not cache")
+
+	tg.run("test", "testcache", "-run=FileSize")
+	tg.run("test", "testcache", "-run=FileSize")
+	tg.grepStdout(`\(cached\)`, "did not cache")
+	tg.must(ioutil.WriteFile(filepath.Join(tg.pwd(), "testdata/src/testcache/file.txt"), []byte("xxx"), 0644))
+	tg.run("test", "testcache", "-run=FileSize")
+	tg.grepStdoutNot(`\(cached\)`, "did not notice file size change")
+	tg.run("test", "testcache", "-run=FileSize")
+	tg.grepStdout(`\(cached\)`, "did not cache")
+
+	tg.run("test", "testcache", "-run=Chdir")
+	tg.run("test", "testcache", "-run=Chdir")
+	tg.grepStdout(`\(cached\)`, "did not cache")
+	tg.must(ioutil.WriteFile(filepath.Join(tg.pwd(), "testdata/src/testcache/file.txt"), []byte("xxxxx"), 0644))
+	tg.run("test", "testcache", "-run=Chdir")
+	tg.grepStdoutNot(`\(cached\)`, "did not notice file size change")
+	tg.run("test", "testcache", "-run=Chdir")
+	tg.grepStdout(`\(cached\)`, "did not cache")
+
+	tg.must(os.Chtimes(filepath.Join(tg.pwd(), "testdata/src/testcache/file.txt"), old, old))
+	tg.run("test", "testcache", "-run=FileContent")
+	tg.run("test", "testcache", "-run=FileContent")
+	tg.grepStdout(`\(cached\)`, "did not cache")
+	tg.must(ioutil.WriteFile(filepath.Join(tg.pwd(), "testdata/src/testcache/file.txt"), []byte("yyy"), 0644))
+	old2 := old.Add(10 * time.Second)
+	tg.must(os.Chtimes(filepath.Join(tg.pwd(), "testdata/src/testcache/file.txt"), old2, old2))
+	tg.run("test", "testcache", "-run=FileContent")
+	tg.grepStdoutNot(`\(cached\)`, "did not notice file content change")
+	tg.run("test", "testcache", "-run=FileContent")
+	tg.grepStdout(`\(cached\)`, "did not cache")
+
+	tg.run("test", "testcache", "-run=DirList")
+	tg.run("test", "testcache", "-run=DirList")
+	tg.grepStdout(`\(cached\)`, "did not cache")
+	tg.must(os.Remove(filepath.Join(tg.pwd(), "testdata/src/testcache/file.txt")))
+	tg.run("test", "testcache", "-run=DirList")
+	tg.grepStdoutNot(`\(cached\)`, "did not notice directory change")
+	tg.run("test", "testcache", "-run=DirList")
+	tg.grepStdout(`\(cached\)`, "did not cache")
+
+	switch runtime.GOOS {
+	case "nacl", "plan9", "windows":
+		// no shell scripts
+	default:
+		tg.run("test", "testcache", "-run=Exec")
+		tg.run("test", "testcache", "-run=Exec")
+		tg.grepStdout(`\(cached\)`, "did not cache")
+		tg.must(os.Chtimes(filepath.Join(tg.pwd(), "testdata/src/testcache/script.sh"), old2, old2))
+		tg.run("test", "testcache", "-run=Exec")
+		tg.grepStdoutNot(`\(cached\)`, "did not notice script change")
+		tg.run("test", "testcache", "-run=Exec")
+		tg.grepStdout(`\(cached\)`, "did not cache")
+	}
+}
+
 func TestTestVet(t *testing.T) {
 	tg := testgo(t)
 	defer tg.cleanup()
@@ -5151,9 +5240,9 @@ func TestTestVet(t *testing.T) {
 		}
 	`)
 
-	tg.runFail("test", filepath.Join(tg.tempdir, "p1_test.go"))
+	tg.runFail("test", tg.path("p1_test.go"))
 	tg.grepStderr(`Logf format %d`, "did not diagnose bad Logf")
-	tg.run("test", "-vet=off", filepath.Join(tg.tempdir, "p1_test.go"))
+	tg.run("test", "-vet=off", tg.path("p1_test.go"))
 	tg.grepStdout(`^ok`, "did not print test summary")
 
 	tg.tempFile("p1.go", `
@@ -5163,12 +5252,12 @@ func TestTestVet(t *testing.T) {
 			fmt.Printf("%d") // oops
 		}
 	`)
-	tg.runFail("test", filepath.Join(tg.tempdir, "p1.go"))
+	tg.runFail("test", tg.path("p1.go"))
 	tg.grepStderr(`Printf format %d`, "did not diagnose bad Printf")
-	tg.run("test", "-x", "-vet=shift", filepath.Join(tg.tempdir, "p1.go"))
+	tg.run("test", "-x", "-vet=shift", tg.path("p1.go"))
 	tg.grepStderr(`[\\/]vet.*-shift`, "did not run vet with -shift")
 	tg.grepStdout(`\[no test files\]`, "did not print test summary")
-	tg.run("test", "-vet=off", filepath.Join(tg.tempdir, "p1.go"))
+	tg.run("test", "-vet=off", tg.path("p1.go"))
 	tg.grepStdout(`\[no test files\]`, "did not print test summary")
 
 	tg.setenv("GOPATH", filepath.Join(tg.pwd(), "testdata"))
@@ -5293,8 +5382,8 @@ func TestGoTestJSON(t *testing.T) {
 	tg.grepStdout(`"Package":"errors"`, "did not see JSON output")
 	tg.grepStdout(`"Action":"run"`, "did not see JSON output")
 
-	tg.run("test", "-o", filepath.Join(tg.tempdir, "errors.test.exe"), "-c", "errors")
-	tg.run("tool", "test2json", "-p", "errors", filepath.Join(tg.tempdir, "errors.test.exe"), "-test.v", "-test.short")
+	tg.run("test", "-o", tg.path("errors.test.exe"), "-c", "errors")
+	tg.run("tool", "test2json", "-p", "errors", tg.path("errors.test.exe"), "-test.v", "-test.short")
 	tg.grepStdout(`"Package":"errors"`, "did not see JSON output")
 	tg.grepStdout(`"Action":"run"`, "did not see JSON output")
 	tg.grepStdout(`\{"Action":"pass","Package":"errors"\}`, "did not see final pass")

src/cmd/go/internal/cache/cache.go

@@ -97,6 +97,9 @@ const (
 // GODEBUG=gocacheverify=1.
 var verify = false
 
+// DebugTest is set when GODEBUG=gocachetest=1 is in the environment.
+var DebugTest = false
+
 func init() { initEnv() }
 
 func initEnv() {
@@ -110,6 +113,9 @@ func initEnv() {
 		if f == "gocachehash=1" {
 			debugHash = true
 		}
+		if f == "gocachetest=1" {
+			DebugTest = true
+		}
 	}
 }
 

src/cmd/go/testdata/src/testcache/testcache_test.go

+// Copyright 2017 The Go Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package testcache
+
+import (
+	"io/ioutil"
+	"os"
+	"runtime"
+	"testing"
+)
+
+func TestChdir(t *testing.T) {
+	os.Chdir("..")
+	defer os.Chdir("testcache")
+	info, err := os.Stat("testcache/file.txt")
+	if err != nil {
+		t.Fatal(err)
+	}
+	if info.Size()%2 != 1 {
+		t.Fatal("even file")
+	}
+}
+
+func TestOddFileContent(t *testing.T) {
+	f, err := os.Open("file.txt")
+	if err != nil {
+		t.Fatal(err)
+	}
+	data, err := ioutil.ReadAll(f)
+	f.Close()
+	if err != nil {
+		t.Fatal(err)
+	}
+	if len(data)%2 != 1 {
+		t.Fatal("even file")
+	}
+}
+
+func TestOddFileSize(t *testing.T) {
+	info, err := os.Stat("file.txt")
+	if err != nil {
+		t.Fatal(err)
+	}
+	if info.Size()%2 != 1 {
+		t.Fatal("even file")
+	}
+}
+
+func TestOddGetenv(t *testing.T) {
+	val := os.Getenv("TESTKEY")
+	if len(val)%2 != 1 {
+		t.Fatal("even env value")
+	}
+}
+
+func TestLookupEnv(t *testing.T) {
+	_, ok := os.LookupEnv("TESTKEY")
+	if !ok {
+		t.Fatal("env missing")
+	}
+}
+
+func TestDirList(t *testing.T) {
+	f, err := os.Open(".")
+	if err != nil {
+		t.Fatal(err)
+	}
+	f.Readdirnames(-1)
+	f.Close()
+}
+
+func TestExec(t *testing.T) {
+	if runtime.GOOS == "plan9" || runtime.GOOS == "windows" || runtime.GOOS == "nacl" {
+		t.Skip("non-unix")
+	}
+
+	// Note: not using os/exec to make sure there is no unexpected stat.
+	p, err := os.StartProcess("./script.sh", []string{"script"}, new(os.ProcAttr))
+	if err != nil {
+		t.Fatal(err)
+	}
+	ps, err := p.Wait()
+	if err != nil {
+		t.Fatal(err)
+	}
+	if !ps.Success() {
+		t.Fatalf("script failed: %v", err)
+	}
+}

src/go/build/deps_test.go

@@ -155,7 +155,8 @@ var pkgDeps = map[string][]string{
 	},
 
 	"internal/poll":    {"L0", "internal/race", "syscall", "time", "unicode/utf16", "unicode/utf8", "internal/syscall/windows"},
-	"os":            {"L1", "os", "syscall", "time", "internal/poll", "internal/syscall/windows"},
+	"internal/testlog": {"L0"},
+	"os":               {"L1", "os", "syscall", "time", "internal/poll", "internal/syscall/windows", "internal/testlog"},
 	"path/filepath":    {"L2", "os", "syscall", "internal/syscall/windows"},
 	"io/ioutil":        {"L2", "os", "path/filepath", "time"},
 	"os/exec":          {"L2", "os", "context", "path/filepath", "syscall"},
@@ -270,7 +271,7 @@ var pkgDeps = map[string][]string{
 	"net/url":                  {"L4"},
 	"plugin":                   {"L0", "OS", "CGO"},
 	"runtime/pprof/internal/profile": {"L4", "OS", "compress/gzip", "regexp"},
-	"testing/internal/testdeps":      {"L4", "runtime/pprof", "regexp"},
+	"testing/internal/testdeps":      {"L4", "internal/testlog", "runtime/pprof", "regexp"},
 	"text/scanner":                   {"L4", "OS"},
 	"text/template/parse":            {"L4"},
 

src/internal/testlog/log.go

+// Copyright 2017 The Go Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+// Package testlog provides a back-channel communication path
+// between tests and package os, so that cmd/go can see which
+// environment variables and files a test consults.
+package testlog
+
+import "sync/atomic"
+
+// Interface is the interface required of test loggers.
+// The os package will invoke the interface's methods to indicate that
+// it is inspecting the given environment variables or files.
+// Multiple goroutines may call these methods simultaneously.
+type Interface interface {
+	Getenv(key string)
+	Stat(file string)
+	Open(file string)
+	Chdir(dir string)
+}
+
+// logger is the current logger Interface.
+// We use an atomic.Value in case test startup
+// is racing with goroutines started during init.
+// That must not cause a race detector failure,
+// although it will still result in limited visibility
+// into exactly what those goroutines do.
+var logger atomic.Value
+
+// SetLogger sets the test logger implementation for the current process.
+// It must be called only once, at process startup.
+func SetLogger(impl Interface) {
+	if logger.Load() != nil {
+		panic("testlog: SetLogger must be called only once")
+	}
+	logger.Store(&impl)
+}
+
+// Logger returns the current test logger implementation.
+// It returns nil if there is no logger.
+func Logger() Interface {
+	impl := logger.Load()
+	if impl == nil {
+		return nil
+	}
+	return *impl.(*Interface)
+}
+
+// Getenv calls Logger().Getenv, if a logger has been set.
+func Getenv(name string) {
+	if log := Logger(); log != nil {
+		log.Getenv(name)
+	}
+}
+
+// Open calls Logger().Open, if a logger has been set.
+func Open(name string) {
+	if log := Logger(); log != nil {
+		log.Open(name)
+	}
+}
+
+// Stat calls Logger().Stat, if a logger has been set.
+func Stat(name string) {
+	if log := Logger(); log != nil {
+		log.Stat(name)
+	}
+}

src/os/env.go

@@ -6,7 +6,10 @@
 
 package os
 
-import "syscall"
+import (
+	"internal/testlog"
+	"syscall"
+)
 
 // Expand replaces ${var} or $var in the string based on the mapping function.
 // For example, os.ExpandEnv(s) is equivalent to os.Expand(s, os.Getenv).
@@ -78,6 +81,7 @@ func getShellName(s string) (string, int) {
 // It returns the value, which will be empty if the variable is not present.
 // To distinguish between an empty value and an unset value, use LookupEnv.
 func Getenv(key string) string {
+	testlog.Getenv(key)
 	v, _ := syscall.Getenv(key)
 	return v
 }
@@ -88,6 +92,7 @@ func Getenv(key string) string {
 // Otherwise the returned value will be empty and the boolean will
 // be false.
 func LookupEnv(key string) (string, bool) {
+	testlog.Getenv(key)
 	return syscall.Getenv(key)
 }
 

src/os/exec.go

@@ -5,6 +5,7 @@
 package os
 
 import (
+	"internal/testlog"
 	"runtime"
 	"sync"
 	"sync/atomic"
@@ -91,6 +92,7 @@ func FindProcess(pid int) (*Process, error) {
 //
 // If there is an error, it will be of type *PathError.
 func StartProcess(name string, argv []string, attr *ProcAttr) (*Process, error) {
+	testlog.Open(name)
 	return startProcess(name, argv, attr)
 }
 

src/os/exec/exec_test.go

@@ -401,9 +401,15 @@ var testedAlreadyLeaked = false
 
 // basefds returns the number of expected file descriptors
 // to be present in a process at start.
-// stdin, stdout, stderr, epoll/kqueue
+// stdin, stdout, stderr, epoll/kqueue, maybe testlog
 func basefds() uintptr {
-	return os.Stderr.Fd() + 1
+	n := os.Stderr.Fd() + 1
+	for _, arg := range os.Args {
+		if strings.HasPrefix(arg, "-test.testlogfile=") {
+			n++
+		}
+	}
+	return n
 }
 
 func closeUnexpectedFds(t *testing.T, m string) {

src/os/file.go

@@ -39,6 +39,7 @@ package os
 import (
 	"errors"
 	"internal/poll"
+	"internal/testlog"
 	"io"
 	"syscall"
 	"time"
@@ -228,8 +229,15 @@ func Mkdir(name string, perm FileMode) error {
 // If there is an error, it will be of type *PathError.
 func Chdir(dir string) error {
 	if e := syscall.Chdir(dir); e != nil {
+		testlog.Open(dir) // observe likely non-existent directory
 		return &PathError{"chdir", dir, e}
 	}
+	if log := testlog.Logger(); log != nil {
+		wd, err := Getwd()
+		if err == nil {
+			log.Chdir(wd)
+		}
+	}
 	return nil
 }
 

src/os/file_plan9.go

@@ -6,6 +6,7 @@ package os
 
 import (
 	"internal/poll"
+	"internal/testlog"
 	"io"
 	"runtime"
 	"syscall"
@@ -85,6 +86,8 @@ func syscallMode(i FileMode) (o uint32) {
 // methods on the returned File can be used for I/O.
 // If there is an error, it will be of type *PathError.
 func OpenFile(name string, flag int, perm FileMode) (*File, error) {
+	testlog.Open(name)
+
 	var (
 		fd     int
 		e      error

src/os/file_unix.go

@@ -8,6 +8,7 @@ package os
 
 import (
 	"internal/poll"
+	"internal/testlog"
 	"runtime"
 	"syscall"
 )
@@ -159,6 +160,8 @@ const DevNull = "/dev/null"
 // methods on the returned File can be used for I/O.
 // If there is an error, it will be of type *PathError.
 func OpenFile(name string, flag int, perm FileMode) (*File, error) {
+	testlog.Open(name)
+
 	chmod := false
 	if !supportsCreateWithStickyBit && flag&O_CREATE != 0 && perm&ModeSticky != 0 {
 		if _, err := Stat(name); IsNotExist(err) {

src/os/file_windows.go

@@ -7,6 +7,7 @@ package os
 import (
 	"internal/poll"
 	"internal/syscall/windows"
+	"internal/testlog"
 	"runtime"
 	"syscall"
 	"unicode/utf16"
@@ -154,6 +155,8 @@ func openDir(name string) (file *File, err error) {
 // methods on the returned File can be used for I/O.
 // If there is an error, it will be of type *PathError.
 func OpenFile(name string, flag int, perm FileMode) (*File, error) {
+	testlog.Open(name)
+
 	if name == "" {
 		return nil, &PathError{"open", name, syscall.ENOENT}
 	}

src/os/stat_plan9.go

@@ -5,6 +5,7 @@
 package os
 
 import (
+	"internal/testlog"
 	"syscall"
 	"time"
 )
@@ -89,6 +90,7 @@ func dirstat(arg interface{}) (*syscall.Dir, error) {
 // Stat returns a FileInfo describing the named file.
 // If there is an error, it will be of type *PathError.
 func Stat(name string) (FileInfo, error) {
+	testlog.Stat(name)
 	d, err := dirstat(name)
 	if err != nil {
 		return nil, err

src/os/stat_unix.go

@@ -7,6 +7,7 @@
 package os
 
 import (
+	"internal/testlog"
 	"syscall"
 )
 
@@ -28,6 +29,7 @@ func (f *File) Stat() (FileInfo, error) {
 // Stat returns a FileInfo describing the named file.
 // If there is an error, it will be of type *PathError.
 func Stat(name string) (FileInfo, error) {
+	testlog.Stat(name)
 	var fs fileStat
 	err := syscall.Stat(name, &fs.sys)
 	if err != nil {
@@ -42,6 +44,7 @@ func Stat(name string) (FileInfo, error) {
 // describes the symbolic link. Lstat makes no attempt to follow the link.
 // If there is an error, it will be of type *PathError.
 func Lstat(name string) (FileInfo, error) {
+	testlog.Stat(name)
 	var fs fileStat
 	err := syscall.Lstat(name, &fs.sys)
 	if err != nil {

src/os/stat_windows.go

@@ -6,6 +6,7 @@ package os
 
 import (
 	"internal/syscall/windows"
+	"internal/testlog"
 	"syscall"
 	"unsafe"
 )
@@ -59,6 +60,7 @@ func (file *File) Stat() (FileInfo, error) {
 // Stat returns a FileInfo structure describing the named file.
 // If there is an error, it will be of type *PathError.
 func Stat(name string) (FileInfo, error) {
+	testlog.Stat(name)
 	if len(name) == 0 {
 		return nil, &PathError{"Stat", name, syscall.Errno(syscall.ERROR_PATH_NOT_FOUND)}
 	}
@@ -161,6 +163,7 @@ func statWithFindFirstFile(name string, namep *uint16) (FileInfo, error) {
 // describes the symbolic link. Lstat makes no attempt to follow the link.
 // If there is an error, it will be of type *PathError.
 func Lstat(name string) (FileInfo, error) {
+	testlog.Stat(name)
 	if len(name) == 0 {
 		return nil, &PathError{"Lstat", name, syscall.Errno(syscall.ERROR_PATH_NOT_FOUND)}
 	}

src/testing/internal/testdeps/deps.go

@@ -11,9 +11,13 @@
 package testdeps
 
 import (
+	"bufio"
+	"internal/testlog"
 	"io"
 	"regexp"
 	"runtime/pprof"
+	"strings"
+	"sync"
 )
 
 // TestDeps is an implementation of the testing.testDeps interface,
@@ -56,3 +60,61 @@ var ImportPath string
 func (TestDeps) ImportPath() string {
 	return ImportPath
 }
+
+// testLog implements testlog.Interface, logging actions by package os.
+type testLog struct {
+	mu sync.Mutex
+	w  *bufio.Writer
+}
+
+func (l *testLog) Getenv(key string) {
+	l.add("getenv", key)
+}
+
+func (l *testLog) Open(name string) {
+	l.add("open", name)
+}
+
+func (l *testLog) Stat(name string) {
+	l.add("stat", name)
+}
+
+func (l *testLog) Chdir(name string) {
+	l.add("chdir", name)
+}
+
+// add adds the (op, name) pair to the test log.
+func (l *testLog) add(op, name string) {
+	if strings.Contains(name, "\n") || name == "" {
+		return
+	}
+
+	l.mu.Lock()
+	defer l.mu.Unlock()
+	if l.w == nil {
+		return
+	}
+	l.w.WriteString(op)
+	l.w.WriteByte(' ')
+	l.w.WriteString(name)
+	l.w.WriteByte('\n')
+}
+
+var log testLog
+
+func (TestDeps) StartTestLog(w io.Writer) {
+	log.mu.Lock()
+	log.w = bufio.NewWriter(w)
+	log.w.WriteString("# test log\n") // known to cmd/go/internal/test/test.go
+	log.mu.Unlock()
+
+	testlog.SetLogger(&log)
+}
+
+func (TestDeps) StopTestLog() error {
+	log.mu.Lock()
+	defer log.mu.Unlock()
+	err := log.w.Flush()
+	log.w = nil
+	return err
+}

src/testing/testing.go

@@ -268,10 +268,12 @@ var (
 	timeout              = flag.Duration("test.timeout", 0, "panic test binary after duration `d` (default 0, timeout disabled)")
 	cpuListStr           = flag.String("test.cpu", "", "comma-separated `list` of cpu counts to run each test with")
 	parallel             = flag.Int("test.parallel", runtime.GOMAXPROCS(0), "run at most `n` tests in parallel")
+	testlog              = flag.String("test.testlogfile", "", "write test action log to `file` (for use only by cmd/go)")
 
 	haveExamples bool // are there examples?
 
 	cpuList     []int
+	testlogFile *os.File
 
 	numFailed uint32 // number of test failures
 )
@@ -889,6 +891,8 @@ func (f matchStringOnly) StopCPUProfile()                             {}
 func (f matchStringOnly) WriteHeapProfile(w io.Writer) error          { return errMain }
 func (f matchStringOnly) WriteProfileTo(string, io.Writer, int) error { return errMain }
 func (f matchStringOnly) ImportPath() string                          { return "" }
+func (f matchStringOnly) StartTestLog(io.Writer)                      {}
+func (f matchStringOnly) StopTestLog() error                          { return errMain }
 
 // Main is an internal function, part of the implementation of the "go test" command.
 // It was exported because it is cross-package and predates "internal" packages.
@@ -916,12 +920,14 @@ type M struct {
 // The canonical implementation of this interface is
 // testing/internal/testdeps's TestDeps.
 type testDeps interface {
+	ImportPath() string
 	MatchString(pat, str string) (bool, error)
 	StartCPUProfile(io.Writer) error
 	StopCPUProfile()
+	StartTestLog(io.Writer)
+	StopTestLog() error
 	WriteHeapProfile(io.Writer) error
 	WriteProfileTo(string, io.Writer, int) error
-	ImportPath() string
 }
 
 // MainStart is meant for use by tests generated by 'go test'.
@@ -1100,6 +1106,17 @@ func (m *M) before() {
 		fmt.Fprintf(os.Stderr, "testing: cannot use -test.coverprofile because test binary was not built with coverage enabled\n")
 		os.Exit(2)
 	}
+	if *testlog != "" {
+		// Note: Not using toOutputDir.
+		// This file is for use by cmd/go, not users.
+		f, err := os.Create(*testlog)
+		if err != nil {
+			fmt.Fprintf(os.Stderr, "testing: %s\n", err)
+			os.Exit(2)
+		}
+		m.deps.StartTestLog(f)
+		testlogFile = f
+	}
 }
 
 // after runs after all testing.
@@ -1110,6 +1127,16 @@ func (m *M) after() {
 }
 
 func (m *M) writeProfiles() {
+	if *testlog != "" {
+		if err := m.deps.StopTestLog(); err != nil {
+			fmt.Fprintf(os.Stderr, "testing: can't write %s: %s\n", *testlog, err)
+			os.Exit(2)
+		}
+		if err := testlogFile.Close(); err != nil {
+			fmt.Fprintf(os.Stderr, "testing: can't write %s: %s\n", *testlog, err)
+			os.Exit(2)
+		}
+	}
 	if *cpuProfile != "" {
 		m.deps.StopCPUProfile() // flushes profile to disk
 	}