cmd/go: go test -v -run TestFoo ./... does not stream test output when multiple packages present but test regex only matches tests from a single package

[MadLittleMods]

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

$ go version
go version go1.16.6 darwin/amd64

Does this issue reproduce with the latest release?

Untested but the relevant code still looks the same

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

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/eric/Library/Caches/go-build"
GOENV="/Users/eric/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/eric/.gvm/pkgsets/go1.16.6/global/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/eric/.gvm/pkgsets/go1.16.6/global"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/Users/eric/.gvm/gos/go1.16.6"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/Users/eric/.gvm/gos/go1.16.6/pkg/tool/darwin_amd64"
GOVCS=""
GOVERSION="go1.16.6"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/eric/Documents/github/go/src/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/5r/34hr5d_x7995nj8wk77dj_n40000gn/T/go-build3417095465=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

Run go test -v -run TestFoo ./... in a Go module that has multiple packages present. Where TestFoo only matches tests in a single package.

What did you expect to see?

I expected to see the logs streamed as the tests run.

I especially expected this to work since all of the tests matching the regex( -run TestFoo) are from a single package which is already supported to stream and only stopped working once an unrelated package was added to the tests directory.

What did you see instead?

All test output is buffered and only printed when the tests completely finish.

Potential solutions

This is highly related to #46959 and #27826 but I didn't want to muddy up those issues aiming to solve a slightly different use case even though a solution there would probably also solve my use case.

Do any of these seem viable for a PR/CL?

1. Stream logs from all packages (magic)
   • There are some concerns about legibility mentioned in the other issue.
   • This is what cmd/go: go test -v does not stream logs when testing multiple packages #46959 and testing: testing a list of packages blocks the real-time output #27826 are wanting.
2. Always stream the first package and printed rest of the buffered output afterwards
   • This seems like an interesting compromise! But adds a bit more magic to the stream vs buffered behavior.
3. Since streaming is already supported when a single package is present, detect when -run only matches tests from a single package and stream.
   • Normally the test regex matching is done within the test binary but we do have access to the list of tests that will be run before we pass it off to the test binary so we could probably also run the matching on the outside.
4. Add new command-line option to override the buffer/stream behavior
   • Easy to implement a new option to override the other logic and simple to reason about.
   • There is some discussion for and against an extra option in testing: stream t.Log output as it happens #24929 (comment)

Relevant Go source code

Here is the code on how Go decides to stream or buffer the output from the test binaries of multiple packages:

go/src/cmd/go/internal/test/test.go

Lines 1196 to 1224 in 259735f

	var buf bytes.Buffer
	if len(pkgArgs) == 0 || testBench != "" || testFuzz != "" {
	// Stream test output (no buffering) when no package has
	// been given on the command line (implicit current directory)
	// or when benchmarking or fuzzing.
	// No change to stdout.
	} else {
	// If we're only running a single package under test or if parallelism is
	// set to 1, and if we're displaying all output (testShowPass), we can
	// hurry the output along, echoing it as soon as it comes in.
	// We still have to copy to &buf for caching the result. This special
	// case was introduced in Go 1.5 and is intentionally undocumented:
	// the exact details of output buffering are up to the go command and
	// subject to change. It would be nice to remove this special case
	// entirely, but it is surely very helpful to see progress being made
	// when tests are run on slow single-CPU ARM systems.
	//
	// If we're showing JSON output, then display output as soon as
	// possible even when multiple tests are being run: the JSON output
	// events are attributed to specific package tests, so interlacing them
	// is OK.
	if testShowPass() && (len(pkgs) == 1 || cfg.BuildP == 1) || testJSON {
	// Write both to stdout and buf, for possible saving
	// to cache, and for looking for the "no tests to run" message.
	stdout = io.MultiWriter(stdout, &buf)
	} else {
	stdout = &buf
	}
	}

Here is where it loops over the packages and runs a test binary for each (a test binary is run/created for each package found/specified),

go/src/cmd/go/internal/test/test.go

Lines 843 to 850 in 259735f

	// Prepare build + run + print actions for all packages being tested.
	for _, p := range pkgs {
	// sync/atomic import is inserted by the cover tool. See #18486
	if testCover && testCoverMode == "atomic" {
	ensureImport(p, "sync/atomic")
	}
	buildTest, runTest, printTest, err := builderTest(&b, ctx, pkgOpts, p)

Checking the -v verbose flag and creating a chattyPrinter,

go/src/testing/testing.go

Lines 1804 to 1806 in c0ac39c

	if Verbose() {
	t.chatty = newChattyPrinter(t.w)
	}

---

Tracking this internally at matrix-org/complement#215

Keywords: print, stream, log

[seankhliao]

cc @bcmills @matloob

[bcmills]

I agree that it's a bit annoying to have to specify the package you want to test explicitly, but it seems rare enough to know that the test case isn't duplicated across any other packages that I don't think this is worth the complexity to fix.

[bcmills]

Closing as not viable to fix. (Specifically, the streaming vs. non-streaming behavior would be too difficult for users to predict — in this case, the extra work of naming a specific package provides an extra invariant that the package matching the test pattern is necessarily unique.)

[MadLittleMods]

Thanks for the thoughts @bcmills 🙂 - This issue is spawning from wishing streaming would work out of the box somehow and for others not have to understand the nuance. Was also hoping for some possible better ideas 😁

the extra work of naming a specific package provides an extra invariant that the package matching the test pattern necessarily unique.

Interesting note here 👍

the streaming vs. non-streaming behavior would be too difficult for users to predict

A "new command-line option to override the buffer/stream behavior" seems like the easiest to predict. But I understand that this isn't necessarily that different from specifying a package (both end-up require changing your command to get streaming). Although specifying a package is very indirect to understand.

---

As a note, the current behavior is hard to understand and I had to do some Googling why it wasn't streaming anymore. First stumbled on https://dave.cheney.net/2020/03/10/go-test-v-streaming-output from Googling go testing change output and saw I was already using -v and then had to Google "go test -v" no longer streaming output to find #46959 and noticed that someone did recently add a new package to the tests directory to cause the problem. Looking forward to the doc updates that might come out of that.