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

liggitt · 2019-08-01T20:08:27Z

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

The text was updated successfully, but these errors were encountered:

bcmills · 2019-08-01T20:32:17Z

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

ianlancetaylor · 2019-08-01T20:39:13Z

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

liggitt · 2019-08-01T20:49:04Z

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 · 2019-08-01T22:23:17Z

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 · 2019-08-01T22:54:06Z

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 · 2019-08-02T00:36:30Z

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 · 2019-08-02T00:43:03Z

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 · 2019-08-02T18:25:50Z

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 · 2019-09-03T14:13:38Z

I think this is related to #23036.

ianlancetaylor · 2019-09-03T14:25:44Z

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 · 2020-05-28T01:49:42Z

@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 · 2020-12-08T13:09:49Z

Related to #26325

gopherbot · 2022-10-18T14:39:07Z

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

Test2json is parsing the output stream from the test, which includes package testing's own framing lines intermingled with other output, in particular any output printed via fmt.Printf, println, and so on. We have had recurring problems with unexpected partial output lines causing a framing line to be missed. A recent talk at GopherCon gave an example of an integration test involving Docker that happened to print \r-terminated lines instead of \n-terminated lines in some configurations, which in turn broke test2json badly. (https://www.gophercon.com/agenda/session/944259) There are also a variety of open reported issues with similar problems, which this CL also addresses. The general approach is to add a new testing flag -test.v=json that means to print additional output to help test2json. And then test2json takes advantage of that output. Among the fixes: - Identify testing framing more reliably, using ^V (golang#23036, golang#26325, golang#43683, GopherCon talk) - Test that output with \r\n endings is handled correctly (golang#43683, golang#34286) - Use === RUN in fuzz tests (golang#52636, golang#48132) - Add === RUN lines to note benchmark starts (golang#27764, golang#49505) - Print subtest --- PASS/FAIL lines as they happen (golang#29811) - Add === NAME lines to emit more test change events, such as when a subtest stops and the parent continues running. - Fix event shown in overall test failure (golang#27568) - Avoid interleaving of writes to os.Stdout and os.Stderr (golang#33419) Fixes golang#23036. Fixes golang#26325. Fixes golang#27568. Fixes golang#27764. Fixes golang#29811. Fixes golang#33419. Fixes golang#34286. Fixes golang#43683. Fixes golang#49505. Fixes golang#52636. Change-Id: Id4207b746a20693f92e52d68c6e4a7f8c41cc7c6 Reviewed-on: https://go-review.googlesource.com/c/go/+/443596 Auto-Submit: Russ Cox <rsc@golang.org> Run-TryBot: Russ Cox <rsc@golang.org> Reviewed-by: Bryan Mills <bcmills@google.com> TryBot-Result: Gopher Robot <gobot@golang.org>

katiehockman added the NeedsDecision Feedback is required from experts, contributors, and/or the community before a change can be made. label Aug 5, 2019

katiehockman added this to the Go1.14 milestone Aug 5, 2019

ianlancetaylor added NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. help wanted and removed NeedsDecision Feedback is required from experts, contributors, and/or the community before a change can be made. labels Sep 3, 2019

rsc modified the milestones: Go1.14, Backlog Oct 9, 2019

bcmills mentioned this issue Dec 5, 2019

cmd/go: go test -json has package output incorrectly attributed to the last test when a test panics #35180

Closed

tehsphinx mentioned this issue Jan 15, 2020

stdout messes up go test --json #36576

Closed

Gregory-Ledray mentioned this issue Feb 25, 2020

fix: handle wasm module loading failure and improve logging and perfo… agnivade/wasmbrowsertest#13

Closed

jayconrod mentioned this issue Mar 25, 2020

testing: bad output formatting when test stdout ends in an incomplete line #38063

Closed

liggitt mentioned this issue May 2, 2020

Switch core master base images (kube-apiserver, kube-scheduler) from debian to distroless kubernetes/kubernetes#90674

Merged

This was referenced Jun 1, 2020

Parallel test output is sometimes assigned to the wrong test in JSON kubernetes/minikube#8349

Closed

suggestion: use Triage-Party for engaging community for github issues #39412

Closed

medyagh mentioned this issue Jun 16, 2020

testing: streaming output loses parallel subtest associations [1.14 backport] #39308

Closed

bcmills mentioned this issue Feb 15, 2022

cmd/go: spurious linefeed + backspace (\r\u0008) characters in go test -json output on Windows #51207

Closed

gopherbot closed this as completed in 1c72ee7 Oct 26, 2022

dmitshur added NeedsFix The path to resolution is known, but the work has not been done. and removed NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Nov 18, 2022

dmitshur modified the milestones: Backlog, Go1.20 Nov 18, 2022

golang locked and limited conversation to collaborators Nov 18, 2023

gopherbot added the FrozenDueToAge label Nov 18, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

liggitt commented Aug 1, 2019 •

edited

bcmills commented Aug 1, 2019

ianlancetaylor commented Aug 1, 2019

liggitt commented Aug 1, 2019

ianlancetaylor commented Aug 1, 2019

liggitt commented Aug 1, 2019

ianlancetaylor commented Aug 2, 2019

liggitt commented Aug 2, 2019 •

edited

liggitt commented Aug 2, 2019

ianlancetaylor commented Sep 3, 2019

ianlancetaylor commented Sep 3, 2019

medyagh commented May 28, 2020 •

edited

skipor commented Dec 8, 2020

gopherbot commented Oct 18, 2022

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

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

Comments

liggitt commented Aug 1, 2019 • edited

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

Does this issue reproduce with the latest release?

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

What did you do?

What did you expect to see?

What did you see instead?

bcmills commented Aug 1, 2019

ianlancetaylor commented Aug 1, 2019

liggitt commented Aug 1, 2019

ianlancetaylor commented Aug 1, 2019

liggitt commented Aug 1, 2019

ianlancetaylor commented Aug 2, 2019

liggitt commented Aug 2, 2019 • edited

liggitt commented Aug 2, 2019

ianlancetaylor commented Sep 3, 2019

ianlancetaylor commented Sep 3, 2019

medyagh commented May 28, 2020 • edited

background:

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

Log files:

Footnote1:

skipor commented Dec 8, 2020

gopherbot commented Oct 18, 2022

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

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

liggitt commented Aug 1, 2019 •

edited

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

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

liggitt commented Aug 2, 2019 •

edited

medyagh commented May 28, 2020 •

edited