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

[pete-woods]

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

$ go version
go version go1.14.1 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
GO111MODULE="on"
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/pete/Library/Caches/go-build"
GOENV="/Users/pete/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=" -mod="
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GONOPROXY="github.com/circleci"
GONOSUMDB="github.com/circleci"
GOOS="darwin"
GOPATH="/Users/pete/Source/go"
GOPRIVATE="github.com/circleci"
GOPROXY="direct"
GOROOT="/usr/local/Cellar/go/1.14.1/libexec"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/Cellar/go/1.14.1/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="<>/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/lh/8qc651cn25n1knh824hcyd0r0000gn/T/go-build757047380=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

package testissue

import (
	"fmt"
	"testing"
)

func TestBad(t *testing.T) {
	// No newline below
	fmt.Print("bad output")
}

func TestGood(t *testing.T) {
	// Print a newline below
	fmt.Println("good output")
}

then run:

go test -json ./testissue

What is the issue?

The JSON output seems corrupted for the "bad" test. You can see that it is missing a "pass" action.

The issue appears to be in the conversion the test2json command is doing from stdout of the test runner into JSON. https://github.com/golang/go/blob/master/src/cmd/internal/test2json/test2json.go

{"Time":"2020-03-25T10:07:16.831092Z","Action":"run","Package":"github.com/circleci/distributor/testissue","Test":"TestBad"}
{"Time":"2020-03-25T10:07:16.83137Z","Action":"output","Package":"github.com/circleci/distributor/testissue","Test":"TestBad","Output":"=== RUN   TestBad\n"}
{"Time":"2020-03-25T10:07:16.831384Z","Action":"output","Package":"github.com/circleci/distributor/testissue","Test":"TestBad","Output":"bad output--- PASS: TestBad (0.00s)\n"}
{"Time":"2020-03-25T10:07:16.831401Z","Action":"run","Package":"github.com/circleci/distributor/testissue","Test":"TestGood"}
{"Time":"2020-03-25T10:07:16.831405Z","Action":"output","Package":"github.com/circleci/distributor/testissue","Test":"TestGood","Output":"=== RUN   TestGood\n"}
{"Time":"2020-03-25T10:07:16.831414Z","Action":"output","Package":"github.com/circleci/distributor/testissue","Test":"TestGood","Output":"good output\n"}
{"Time":"2020-03-25T10:07:16.831423Z","Action":"output","Package":"github.com/circleci/distributor/testissue","Test":"TestGood","Output":"--- PASS: TestGood (0.00s)\n"}
{"Time":"2020-03-25T10:07:16.831426Z","Action":"pass","Package":"github.com/circleci/distributor/testissue","Test":"TestGood","Elapsed":0}
{"Time":"2020-03-25T10:07:16.831443Z","Action":"output","Package":"github.com/circleci/distributor/testissue","Output":"PASS\n"}
{"Time":"2020-03-25T10:07:16.831486Z","Action":"output","Package":"github.com/circleci/distributor/testissue","Output":"ok  \tgithub.com/circleci/distributor/testissue\t0.149s\n"}
{"Time":"2020-03-25T10:07:16.833206Z","Action":"pass","Package":"github.com/circleci/distributor/testissue","Elapsed":0.151}

[andybons]

@matloob @bcmills @jayconrod

[bcmills]

This has basically nothing to do with test2json — it is more-or-less correctly parsing the bad output. The problem is that the output is missing a newline, and the testing wrapper doesn't inject one:

example.com$ go version
go version devel +6b6414ca Wed Mar 25 04:06:34 2020 +0000 linux/amd64

example.com$ go mod init example.com
go: creating new go.mod: module example.com

example.com$ cat > testissue_test.go
package testissue

import (
        "fmt"
        "testing"
)

func TestBad(t *testing.T) {
        // No newline below
        fmt.Print("bad output")
}

func TestGood(t *testing.T) {
        // Print a newline below
        fmt.Println("good output")
}

example.com$ go test -v .
=== RUN   TestBad
bad output--- PASS: TestBad (0.00s)
=== RUN   TestGood
good output
--- PASS: TestGood (0.00s)
PASS
ok      example.com     0.021s

[bcmills]

This problem appears to have existed for a long time:

example.com$ go1.13.9 test -v .
=== RUN   TestBad
bad output--- PASS: TestBad (0.00s)
=== RUN   TestGood
good output
--- PASS: TestGood (0.00s)
PASS
ok      example.com     (cached)

example.com$ go1.12.17 test -v .
=== RUN   TestBad
bad output--- PASS: TestBad (0.00s)
=== RUN   TestGood
good output
--- PASS: TestGood (0.00s)
PASS
ok      example.com     (cached)

[bcmills]

CC @mpvl @changkun

[changkun]

Can we really do anything about this? I could not imagine a way to determine the last character from flushed outputs... In the log package, it is pretty straightforward, because it has an internal buffer, and the check can be done by checking its buffer, but in the testing package, the output is directly executed from the userland.

Unless we print a \n before the --- PASS or PASS anyway.

[jayconrod]

Related to #27764 #35180 #33419 at least.

[jayconrod]

Can we really do anything about this? I could not imagine a way to determine the last character from flushed outputs...

Maybe. Test binaries write messages to the go test driver on stdout. Tests may also write to stdout, so the output gets mixed together. Test binaries could write messages on some other channel (pipe, socket, whatever) to avoid this problem.