testing: parallel subtest log output not properly constrained in go1.14rc1

[mdwhatcott]

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

$ go version
go version go1.14rc1 darwin/amd64

Does this issue reproduce with the latest release?

• The bad behavior reported below can be consistently reproduced with go1.14rc1.
• The good behavior reported below can be consistently reproduced with go1.13.8.

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

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/mike/Library/Caches/go-build"
GOENV="/Users/mike/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/mike"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/mike/src/github.com/smartystreets/gunit/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 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/d1/m6l916pn5sn0t3wp5jgy63sr0000gn/T/go-build658210039=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

Consider the following sample program, which runs 10 subtests using t.Parallel():

package example

import (
	"fmt"
	"testing"
)

func Test(t *testing.T) {
	for x := 0; x < 10; x++ {
		t.Run("Hello"+fmt.Sprint(x), func(t *testing.T) {
			t.Parallel()
			t.Log(t.Name())
		})
	}
}

What did you expect to see?

I expected to see the output aligned with the final report for each subtest, which works
in go1.13.8 (just released earlier today).

$ go version && go test -v
go version go1.13.8 darwin/amd64
=== RUN   Test
=== RUN   Test/Hello0
=== PAUSE Test/Hello0
=== RUN   Test/Hello1
=== PAUSE Test/Hello1
=== RUN   Test/Hello2
=== PAUSE Test/Hello2
=== RUN   Test/Hello3
=== PAUSE Test/Hello3
=== RUN   Test/Hello4
=== PAUSE Test/Hello4
=== RUN   Test/Hello5
=== PAUSE Test/Hello5
=== RUN   Test/Hello6
=== PAUSE Test/Hello6
=== RUN   Test/Hello7
=== PAUSE Test/Hello7
=== RUN   Test/Hello8
=== PAUSE Test/Hello8
=== RUN   Test/Hello9
=== PAUSE Test/Hello9
=== CONT  Test/Hello0
=== CONT  Test/Hello5
=== CONT  Test/Hello9
=== CONT  Test/Hello8
=== CONT  Test/Hello4
=== CONT  Test/Hello3
=== CONT  Test/Hello2
=== CONT  Test/Hello1
=== CONT  Test/Hello7
=== CONT  Test/Hello6
--- PASS: Test (0.00s)
    --- PASS: Test/Hello0 (0.00s)
        stuff_test.go:12: Test/Hello0
    --- PASS: Test/Hello5 (0.00s)
        stuff_test.go:12: Test/Hello5
    --- PASS: Test/Hello9 (0.00s)
        stuff_test.go:12: Test/Hello9
    --- PASS: Test/Hello8 (0.00s)
        stuff_test.go:12: Test/Hello8
    --- PASS: Test/Hello4 (0.00s)
        stuff_test.go:12: Test/Hello4
    --- PASS: Test/Hello3 (0.00s)
        stuff_test.go:12: Test/Hello3
    --- PASS: Test/Hello2 (0.00s)
        stuff_test.go:12: Test/Hello2
    --- PASS: Test/Hello1 (0.00s)
        stuff_test.go:12: Test/Hello1
    --- PASS: Test/Hello7 (0.00s)
        stuff_test.go:12: Test/Hello7
    --- PASS: Test/Hello6 (0.00s)
        stuff_test.go:12: Test/Hello6
PASS
ok  	example	0.086s

What did you see instead?

Notice that in go1.14rc1 the test log output appears in unexpected places in the
overall verbose output. This change in behavior makes the output more difficult to decipher for
humans and causes test log output to be lost when scanned by test runners in
editors and IDEs (such as Intellij GoLand).

$ go version && go test -v
go version go1.14rc1 darwin/amd64
=== RUN   Test
=== RUN   Test/Hello0
=== PAUSE Test/Hello0
=== RUN   Test/Hello1
=== PAUSE Test/Hello1
=== RUN   Test/Hello2
=== PAUSE Test/Hello2
=== RUN   Test/Hello3
=== PAUSE Test/Hello3
=== RUN   Test/Hello4
=== PAUSE Test/Hello4
=== RUN   Test/Hello5
=== PAUSE Test/Hello5
=== RUN   Test/Hello6
=== PAUSE Test/Hello6
=== RUN   Test/Hello7
=== PAUSE Test/Hello7
=== RUN   Test/Hello8
=== PAUSE Test/Hello8
=== RUN   Test/Hello9
=== PAUSE Test/Hello9
=== CONT  Test/Hello0
    Test/Hello0: stuff_test.go:12: Test/Hello0
=== CONT  Test/Hello5
=== CONT  Test/Hello4
    Test/Hello4: stuff_test.go:12: Test/Hello4
=== CONT  Test/Hello3
    Test/Hello5: stuff_test.go:12: Test/Hello5
    Test/Hello3: stuff_test.go:12: Test/Hello3
=== CONT  Test/Hello8
    Test/Hello8: stuff_test.go:12: Test/Hello8
=== CONT  Test/Hello2
    Test/Hello2: stuff_test.go:12: Test/Hello2
=== CONT  Test/Hello7
=== CONT  Test/Hello1
    Test/Hello7: stuff_test.go:12: Test/Hello7
    Test/Hello1: stuff_test.go:12: Test/Hello1
=== CONT  Test/Hello6
    Test/Hello6: stuff_test.go:12: Test/Hello6
=== CONT  Test/Hello9
    Test/Hello9: stuff_test.go:12: Test/Hello9
--- PASS: Test (0.00s)
    --- PASS: Test/Hello0 (0.00s)
    --- PASS: Test/Hello4 (0.00s)
    --- PASS: Test/Hello5 (0.00s)
    --- PASS: Test/Hello3 (0.00s)
    --- PASS: Test/Hello8 (0.00s)
    --- PASS: Test/Hello2 (0.00s)
    --- PASS: Test/Hello7 (0.00s)
    --- PASS: Test/Hello1 (0.00s)
    --- PASS: Test/Hello6 (0.00s)
    --- PASS: Test/Hello9 (0.00s)
PASS
ok  	example	0.915s

This feels very much like a newly-introduced bug.

[networkimprov]

@dmitshur possible release-blocker?

[dmitshur]

Can you take a look at #24929 (comment). Is this issue different from that or the same?

/cc @jadekler @ianlancetaylor

[jeanbza]

Not trying to be antagonistic, but why is this unexpected behavior? These are tests running in parallel, and their output is arriving as it happens rather than buffered and presented in-order at the end. That seems to be WAI.

(I may be missing something - typing from the car :) )

[ianlancetaylor]

This is due to https://golang.org/cl/127120, for issue #24929.

[ianlancetaylor]

This is documented in the release notes: search for "Testing" under https://tip.golang.org/doc/go1.14#tools.

The right thing happens with go test -json, which is the intended mechanism for programs that parse test output.

So this change is intentional. The question is: should we roll it back? What are the bad effects of this change on your system? Can they be ameliorated by using go test -json instead?

CC @rsc @mpvl

[mdwhatcott]

Thanks everyone for chiming in.

@dmitshur - I've reviewed #24929 and can confirm that my issue is a direct result of that issue having been implemented. I understand what that issue is trying to accomplish and see the need for it.

@ianlancetaylor - Thank you for pointing out the explanation in the release notes. I missed that the first time through. Be aware that the "testing" package documentation for the T interface contradicts what's on the release notes:

T is a type passed to Test functions to manage test state and support formatted test logs. Logs are accumulated during execution and dumped to standard output when done.

I agree in principle with the idea that -v output is for humans and -json output is for tools like IDEs. Currently, my IDE of choice (Jetbrains Goland) makes use of the -json flag in some scenarios, but probably just needs some work to make sure each JSON object is correctly organized and displayed with its proper test in the final report. I'll probably have to take this up as a separate issue on the Jetbrains issue tracker (@zolotov ).

---

Crazy idea: could we emit log output immediately to stdout AND buffer it for a more tidy presentation at the end (like we've always had)?

[gopherbot]

Change https://golang.org/cl/219540 mentions this issue: testing: remove obsolete comment in testing.(*T) docs

[mdwhatcott]

@ianlancetaylor

The right thing happens with go test -json, which is the intended mechanism for programs that parse test output.

The real reason I filed this issue was because the GoLand test runner wasn't able to handle the new style of output (#24929). I've since learned that it's the output of go test -json and go tool test2json are no longer correct in all cases in Go 1.14 and I've filed a subsequent issue: #38050

[odeke-em]

@mdwhatcott thank you for filing this issue, thank you Ian, Liam, Jean and Dmitri for the responses! @mdwhatcott I believe that your last statements were acknowledgements of the change that we intentionally made and you filed a subsequent follow-up for the new output being incorrect, on behalf of what you saw in GoLand. Can we close this issue then? Thank you.