cmd/go: go test -v does not stream logs when testing multiple packages

[leighmcculloch]

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

$ go version
go version go1.16.5 linux/amd64

Does this issue reproduce with the latest release?

Yes, this reproduces on Go 1.16.5.

This also reproduces on Go 1.14, the version that introduced test log streaming.

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

go env Output

$ go env
GO111MODULE="auto"
GOARCH="amd64"
GOBIN="/home/vscode/.local/bin"
GOCACHE="/home/vscode/.cache/go-build"
GOENV="/home/vscode/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/home/vscode/.local/bin/go/1.16.5"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/vscode/.local/bin/go/1.16.5/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.16.5"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="0"
GOMOD="/workspaces/stellar--experimental-payment-channels/sdk/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 -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build112618337=/tmp/go-build -gno-record-gcc-switches"

What did you do?

I ran go test -v ./... in a Go module that has multiple packages, each with tests.

What did you expect to see?

I expected to see the logs stream for the test(s) currently running.

According to the Go 1.14 release notes:

go test -v now streams t.Log output as it happens, rather than at the end of all tests.

Ref: https://golang.org/doc/go1.14

What did you see instead?

The logs did not stream to stdout, but were batched until each test completed.

When I run the tests for a single package (go test -v ./pkg1), or if I run the tests without package parallelism (go test -p 1 -v ./...), the logs do stream.

It looks to me like this is probably behaving as intended, especially since Go 1.14 had this same behavior, but the release notes are misleading since they simply state that logs stream but not that they only stream under specific conditions.

I haven't found documentation about the interactions between log streaming and test package parallelism. I haven't found any documentation about test package parallelism either, and the help pages inside the go tool itself about the -p flag are difficult to find. To find a definition of it, one has to follow two references, so the path to discovering it is go help test, then go help testflags, then go help build.

Possibly this is an opportunity for improved docs, but it's unclear to me where that would need to go.

[mvdan]

go help test does have a section related to this:

Go test runs in two different modes:

It talks about the difference between running go test without and with package arguments. Initially, I was going to reply to this issue saying that only in the mode without arguments you were meant to get streaming output, but that's clearly wrong - like you say, go test -v ./pkg streams output too.

Implementing output streaming for multiple packages is harder, for what it's worth. Like others mentioned in the original thread, output from testing multiple packages is buffered, and legibility could suffer from streaming. So my guess is that not including support for multiple packages was on purpose.

All that said, I agree this should be better documented. I'd perhaps put a short paragraph in go help test.

[bboreham]

Similar to #27826 ?

[MadLittleMods]

It would be nice to override this behavior or detect that I'm only running tests from a single package and stream. In my use cases, I'm only running some specific tests via go test -v -run TestImportHistoricalMessages ./tests/... which are all in a single file (let alone the same package) but the directory,./tests/..., happens to include multiple packages.

For the curious, here are the actual tests

For the curious, here are the actual tests: https://github.com/matrix-org/complement/tree/050afc551c2695e8e055903f8e8ad6f3ecce17a0/tests (tests and csapi package)

As a workaround, I can get the log streaming behavior I want by being very selective about the files to run: go test -v -run TestImportHistoricalMessages ./tests/main_test.go ./tests/msc2716_test.go but this is manual process adjusting our generic test runner every time.

Created #49195 to track a solution for this similar use case.

[Olshansk]

I summarised my learnings in this StackOverflow answer in case someone else comes by this thread.

[brusdev]

A simple workaround is to loop through packages, i.e.

for PACKAGE in $(go list ./...); do go test -v ${PACKAGE}; done;

[bboreham]

@brusdev that seems equivalent to the workaround already mentioned – go test -p 1 – with the same downside of no parallelism.

[steeling]

One thought that might be a good middleground: we don't have to necessarily stream logs, but we don't need to wait for every package to be completed before dumping all the logs either.

As each package completes its tests it could output logs through a global lock. Just a thought