testing: go test JSON output reports failure if stdout redirected

james-johnston-thumbtack commented 4 years ago

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

$ go version
go version go1.13.4 darwin/amd64

Does this issue reproduce with the latest release?

It should; I don't see why it wouldn't as the code I highlighted below is in the master branch.

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

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/jamesjohnston/Library/Caches/go-build"
GOENV="/Users/jamesjohnston/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/jamesjohnston/Thumbtack/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/Cellar/go/1.13.4/libexec"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/Cellar/go/1.13.4/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS="-I/usr/local/include"
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-L/usr/local/lib"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/4_/s_mp89t54_b8xbgwclmf2scw0000gp/T/go-build586602208=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

Create a test that overwrites os.Stdout, and then run it using go test -json.

https://play.golang.org/p/zeonvI5FdUJ

func TestWithOverride(t *testing.T) {
    _, stdOutPipe, _ := os.Pipe()
    os.Stdout = stdOutPipe
}

Then run the test using go test -json.

What did you expect to see?

The test should succeed: both the exit code should be 0, and the JSON output should indicate a successful test.

What did you see instead?

The JSON output indicates the test failed, yet the exit code is still 0, indicating success:

jamesjohnston-mac:testcase jamesjohnston$ go test -json
{"Time":"2020-02-19T15:27:30.928348-08:00","Action":"run","Package":"github.com/thumbtack/go/testcase","Test":"TestWithOverride"}
{"Time":"2020-02-19T15:27:30.928623-08:00","Action":"output","Package":"github.com/thumbtack/go/testcase","Test":"TestWithOverride","Output":"=== RUN   TestWithOverride\n"}
{"Time":"2020-02-19T15:27:30.928661-08:00","Action":"output","Package":"github.com/thumbtack/go/testcase","Test":"TestWithOverride","Output":"--- PASS: TestWithOverride (0.00s)\n"}
{"Time":"2020-02-19T15:27:30.92872-08:00","Action":"output","Package":"github.com/thumbtack/go/testcase","Test":"TestWithOverride","Output":"ok  \tgithub.com/thumbtack/go/testcase\t0.006s\n"}
{"Time":"2020-02-19T15:27:30.928732-08:00","Action":"fail","Package":"github.com/thumbtack/go/testcase","Test":"TestWithOverride","Elapsed":0.007}
jamesjohnston-mac:testcase jamesjohnston$ echo $?
0

Notice the failure that is reported in the JSON: "Action":"fail". This is all very ambiguous: did the test pass or fail? The exit code says one thing, but the JSON output says another.

Further investigation

Notice if we run the above play link, we get this output:

=== RUN   TestWithOverride
--- PASS: TestWithOverride (0.00s)

All tests passed.

However, if we write a "normal" test that does not tamper with Stdout, we get additional output: a final "PASS": https://play.golang.org/p/3Z8hY3rAfhj

package main

import (
    "testing"
)

func TestWithoutOverride(t *testing.T) {
    // do nothing
}

Output:

=== RUN   TestWithoutOverride
--- PASS: TestWithoutOverride (0.00s)
PASS

All tests passed.

It would appear that test2json is interpreting the lack of a final "PASS" as being a failure when converting it to JSON. However, the main "go test" command does not do similarly, and thus exits with a "successful" exit code. Therefore, we end up with a test that is both "passing" and "failing" simultaneously.

The issue appears to be that the testing.go file is completely written under the assumption that the end-user will never write to any of the os.StdXYZ variables. For example: https://github.com/golang/go/blob/c4c73ce0e3a7b5c3a61678325c61b09783f76220/src/testing/testing.go#L1211

    fmt.Println("PASS")

is the code that writes the final "PASS" note.

A couple possible fixes might be:

Update testing.go so that it reads the os.StdXYZ variables at the start of testing, and then never reads from them again. So e.g. the above code would be updated to fmt.Fprintln(originalStdOut, "PASS"). This protects the code from tests that tamper with the standard files.
Update go test and/or test2json so that if a test binary outputs a truncated output due to this issue (or any other), it consistently either passes or fails the test and does not leave disagreement between JSON and exit code.

Interestingly, the issue is limited only to -json flag. If we run go test without that flag, the test will pass and no indication of anything going wrong will be given.

Justification / backstory

This test case was derived from a test somebody wrote at my employer that was testing a command-line tool of some sort. It was temporarily replacing Stdout so that output could be captured and compared against expected output. The issue is that for one test, this person forgot to restore the original Stdout, and this was not noticed until I started working on introducing tools that work with the JSON output, like using gotestsum to convert JSON to JUnit XML and then passing that to Jenkins JUnit plug-in.... Jenkins was (surprisingly) reporting failed tests despite the test suite "passing."

While replacing os.Stdout might arguably not the best approach to testing a command-line tool, somebody did write a test that way, and in such a scenario, I feel that the test runner should exhibit predictable behavior when presented with "interesting" tests like this one.

toothrot commented 4 years ago

/cc @mpvl @josharian

mvdan commented 4 years ago

While replacing os.Stdout might arguably not the best approach to testing a command-line tool, somebody did write a test that way, and in such a scenario, I feel that the test runner should exhibit predictable behavior when presented with "interesting" tests like this one.

I definitely agree that you shouldn't be replacing os.Stdout like that. A similar issue is how calling os.Exit(0) can make an entire package pass its tests when it definitely shouldn't.

I don't know what we can do here, but I don't think adapting go test -json to such tests is a good idea.

bcmills commented 4 years ago

The testing package itself could save os.Stdout and os.Stderr and restore them at the end of each test.

Any parallel test that attempts to reassign those would be reported as a race, but that seems like a good thing to report anyway.

golang / go