testing: testing a list of packages blocks the real-time output

[mwf]

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

go version go1.11 darwin/amd64

Does this issue reproduce with the latest release?

Yes, reproduced on tip - go version devel +ce58a39fca Thu Sep 20 22:52:44 2018 +0000 darwin/amd64

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

GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/ikorolev/Library/Caches/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/ikorolev/.gvm/pkgsets/go1.11/global:/Users/ikorolev/dev/go"
GOPROXY=""
GORACE=""
GOROOT="/Users/ikorolev/.gvm/gos/go1.11"
GOTMPDIR=""
GOTOOLDIR="/Users/ikorolev/.gvm/gos/go1.11/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD=""
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 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/_b/d1934m9s587_8t_6ngv3hnc00000gp/T/go-build880489854=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

go test -v -count=1 ./... doesn't print real-time test output if you got subpackages.

cd `mktemp -d`
go mod init example.com/test
cat <<EOD > main_test.go
package main

import (
    "fmt"
    "testing"
    "time"
)

func TestLong(t *testing.T) {
    fmt.Println("running")
    time.Sleep(2 * time.Second)
    fmt.Println("2 second later")
}
EOD
mkdir subpkg
cat <<EOD > subpkg/main_test.go
package subpkg
EOD
go test -v -count=1 ./...

What did you expect to see?

I expect to see the output successively as the test is running. And I will see it if run go test -v -count=1 . instead.

What did you see instead?

Using ./... doesn't produce real-time output. The output is produced only when all the tests are finished.

It's not convenient when you run tests on a CI and see only "go test -v ./..." line for several minutes. You don't have any idea if the tests have stuck somewhere or they are just too slow.

I understand that such behaviour may be connected with running the tests in parallel, but maybe we could do anything about it?

[mwf]

@gopherbot please, add label Testing.

[ianlancetaylor]

Related to #24929.

[paol]

A flag to disable stdout buffering could be helpful. Or, at a minimum, document the effect of the -p (and -count ?) flags on output buffering.

As a note, this bug is not quite a duplicate of #24929, as it affects all of stdout, not just the uses of t.Log (Maybe the underlying mechanism is the same, I don't know.)

We care about stdout too because we're doing heavy initializations in TestMain where t.Log isn't available, and we want to see the progress messages as they happen.