testing: writing to os.Stderr pollutes test names in go test -json output

[liggitt]

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

$ go version
go version go1.12.4 darwin/amd64

Does this issue reproduce with the latest release?

Yes

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

go env Output

$ go env
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/liggitt/Library/Caches/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/liggitt/go"
GOPROXY=""
GORACE=""
GOROOT="/Users/liggitt/.gvm/gos/go1.12.4"
GOTMPDIR=""
GOTOOLDIR="/Users/liggitt/.gvm/gos/go1.12.4/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/h8/3dzrjpfj76d93vbhc5f2r8tw00kjgb/T/go-build854512890=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

We have go tests that start a server goroutine running in the background, then run subtests against that server. The server goroutine can log to stdout/stderr.

To obtain structured test output, we run go tests with -json to cleanly separate test names, status, and output.

The following example reproduces the issue:

stdout_test.go:

package main

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

func TestStdoutJSON(t *testing.T) {
	go func() {
		for {
			os.Stderr.Write([]byte("os.Stderr message\n"))
			os.Stdout.Write([]byte("os.Stdout message\n"))
			time.Sleep(time.Millisecond)
		}
	}()

	for i := 0; i < 10; i++ {
		t.Run(fmt.Sprintf("subtest %d", i), func(t *testing.T) {
			for i := 0; i < 10; i++ {
				t.Run(fmt.Sprintf("subtest %d", i), func(t *testing.T) {
					for i := 0; i < 10; i++ {
						t.Run(fmt.Sprintf("subtest %d", i), func(t *testing.T) {
							t.Log("testlog")
						})
					}
				})
			}
		})
	}
}

$ go test -count=100 -json -v stdout_test.go | jq 'select(.Test//"" | contains("os"))' 

{
  "Time": "2019-08-01T16:06:56.384955-04:00",
  "Action": "output",
  "Package": "command-line-arguments",
  "Test": "Tos.Stderr message",
  "Output": "            --- PASS: Tos.Stderr message\n"
}
{
  "Time": "2019-08-01T16:06:56.384968-04:00",
  "Action": "output",
  "Package": "command-line-arguments",
  "Test": "Tos.Stderr message",
  "Output": "estStdoutJSON/subtest_4/subtest_6/subtest_6 (0.00s)\n"
}
...

What did you expect to see?

Correct test name and status in go test -json output

What did you see instead?

Stderr output from the server goroutine interleaved with test names inside the structured json data.

Observations:

• This has only been seen in tests that make use of subtests
• Stdout from the background goroutine is not observed to interleave, only Stderr

go test -json not outputting test names with fidelity messes up systems that transform that output to junit format or ingest it into tools like testgrid that show history of a particular test

[bcmills]

See also #27764, #29811, and #25241.

[ianlancetaylor]

It's not clear to me that there is anything we can do about this.

[liggitt]

I had a pretty hard time following the -json handling at https://github.com/golang/go/blob/master/src/cmd/go/internal/test/test.go#L1042-L1146, so it's possible I misunderstood, but does the -json option only affect processing of output at the package level?

If so, I expected the json output option to be passed down to test/subtests processes, and for them to output json the package-level would aggregate (and maybe supplement with package-level info), rather than invoke them normally and try to untangle their output.

[ianlancetaylor]

I'm not sure what you mean by "the package level."

go test -json works by building the test binary as usual, running the test binary as usual, and piping the output of the test binary to the test2json program. The fact that the user has requested JSON output is not reported to the test binary, which simply doesn't need to know. Using a separate process like this means that we can get good JSON output even if the test binary itself crashes in some way. But it does only work if the test is reasonably disciplined about its output.

[liggitt]

running the test binary as usual, and piping the output of the test binary to the test2json program

I thought the invocations of the test binary were once per tested package, but I may have misread the test runner.

The fact that the user has requested JSON output is not reported to the test binary, which simply doesn't need to know

If the output could be reliably parsed by test2json, I'd agree, but in practice, it cannot. Maybe it doesn't need to know it is outputting to be parsed by test2json, but if it is treating stderr as a structured communication channel, it needs to take measures to prevent interleaving.

But it does only work if the test is reasonably disciplined about its output.

no goroutine with a lifetime spanning tests or subtests being able to use os.Stderr is a pretty surprising requirement for go test -json to work reliably

[ianlancetaylor]

You are correct: a separate test binary is built for each package.

no goroutine with a lifetime spanning tests or subtests being able to use os.Stderr is a pretty surprising requirement for go test -json to work reliably

Well, I'm certainly not opposed to fixing it if we can.

That said, I actually can't recreate the problem. When I run go test -json x_test.go all the "Test" entries look correct to me. I'm running on GNU/Linux, not Darwin, but I don't know why that would make a difference here.

[liggitt]

That said, I actually can't recreate the problem. When I run go test -json x_test.go all the "Test" entries look correct to me.

It's racy, and maybe load dependent? I usually had to run with -count greater than 1 to capture it.

I'm running on GNU/Linux, not Darwin, but I don't know why that would make a difference here.

Yeah, that doesn't matter. We encounter it regularly in CI on Linux -

https://testgrid.k8s.io/presubmits-kubernetes-blocking#pull-kubernetes-integration&sort-by-flakiness=&include-filter-by-regex=Shutting&show-stale-tests=

[liggitt]

Interestingly, for normal use of stderr that writes complete lines, forcing test output to only go to stdout resolves the issue (os.Stderr = os.Stdout in the package's TestMain(m *testing.M))

Letting the package test executable write independent stdout/stderr streams, then joining them without regard for linebreaks (which is what it looks like the exec package does when the same writer is assigned to cmd.Stdout and cmd.Stderr) is what is turning well-behaved independent stderr and stdout writes by the test executable into a single interleaved stream.

[ianlancetaylor]

I think this is related to #23036.

[ianlancetaylor]

I think you're right that we could fix that if cmd/go did not merge stdout and stderr together. We should probably handle test stderr output by arranging for it to flow directly into the test2json Output field. Somehow.

[medyagh]

@liggitt
I dont know if this is related or if I need to create a new issue.

background:

In minikube we use 'go tool test2json' to procude json output and then use a tool called gopopgh to convert it to human-friendly HTML.

in running minikube's e2e in powershell we have noticed that the tests talk over each other.
for example here is the output of the json that I produced using this command:

here we see that inside "TestFunctional/parallel/PersistentVolumeClaim" there is logs from TestFunctional/parallel/MountCmd

{"Time":"2020-05-28T00:12:16.1892262Z","Action":"output","Test":"TestFunctional/parallel/PersistentVolumeClaim","Output":"        ** /stderr **\r\n"}
{"Time":"2020-05-28T00:12:16.1892262Z","Action":"output","Test":"TestFunctional/parallel/PersistentVolumeClaim","Output":"    TestFunctional/parallel/MountCmd: fn_mount_cmd.go:120: /mount-9p did not appear within 19.5329253s: exit status 1\r\n"}
{"Time":"2020-05-28T00:12:16.1892262Z","Action":"output","Test":"TestFunctional/parallel/PersistentVolumeClaim","Output":"    TestFunctional/parallel/MountCmd: fn_mount_cmd.go:75: \"TestFunctional/parallel/MountCmd\" failed, getting debug info...\r\n"}

The exact command to produce the json passed to golang's test binary as see here

./e2e-windows-amd64.exe --minikube-start-args="--driver=docker" --test.timeout=13m --test.v --test.run=TestFunctional --binary="./minikube-windows-amd64.exe" | Out-File -FilePath .\report\testout.txt -Encoding ASCII

and here is the exact command that we use to convert the .txt file to json in powershel

Get-Content .\report\testout.txt | go tool test2json -t | Out-File -FilePath .\report\testout.json -Encoding ASCII

Log files:

here I paste the full .txt an and .json files in a gist https://gist.github.com/medyagh/2d681788e5e6491b8fc735b2ed0454dc

Footnote1:

I had to add -Encoding ASCII in powershell because without it it was producing \r\t which which was not parsable json anymore.

do you think this is related to this bug or or is it more related to this #29811 ?

[skipor]

Related to #26325

[gopherbot]

Change https://go.dev/cl/443596 mentions this issue: testing: fix many test2json inaccuracies