Repository: go
Issue: cmd/go: -json test report ordering
Labels: NeedsInvestigation

<!-- Please answer these questions before submitting your issue. Thanks! -->

### What version of Go are you using (`go version`)?

<pre>
$ go version
go version go1.11.2 darwin/amd64
</pre>

### Does this issue reproduce with the latest release?

Yes


### What operating system and processor architecture are you using (`go env`)?

<details><summary><code>go env</code> Output</summary><br><pre>
$ go env
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/me/Library/Caches/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/me/.go:/Users/mark/Projects/go"
GOPROXY=""
GORACE=""
GOROOT="/Users/me/.goenv/versions/1.11.2"
GOTMPDIR=""
GOTOOLDIR="/Users/me/.goenv/versions/1.11.2/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/mark/Projects/mine/my_pkg/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/vy/hzm88gt90292ztr9f3qg9zhr0000gn/T/go-build057809249=/tmp/go-build -gno-record-gcc-switches -fno-common"
</pre></details>

### What did you do?

I ran tests for a module using the following commands:

```bash
$ go test -v ./...
$ go test -v -json ./...
$ go test -v ./... | go tool test2json
```

Repository: https://github.com/reproduce/golant-test-ordering-issue


### What did you expect to see?

I expected to see the test events to be in the exact same order in each case



### What did you see instead?

<details><summary><code>go test -v ./...</code> Output</summary><br><pre>
$ go test -v ./...
=== RUN   TestSuccess
--- PASS: TestSuccess (0.00s)
=== RUN   TestSkip
--- SKIP: TestSkip (0.00s)
    test_test.go:10: skipping test
=== RUN   TestFail
--- FAIL: TestFail (0.00s)
    test_test.go:14: failed test
=== RUN   TestMain
=== RUN   TestMain/success
=== RUN   TestMain/skip
=== RUN   TestMain/fail
--- FAIL: TestMain (0.00s)
    --- PASS: TestMain/success (0.00s)
    --- SKIP: TestMain/skip (0.00s)
        test_test.go:23: skipping test
    --- FAIL: TestMain/fail (0.00s)
        test_test.go:27: failed test
FAIL
FAIL	my_pkg	0.005s
?   	my_pkg/pkg/no_tests	[no test files]
testing: warning: no tests to run
PASS
ok  	my_pkg/pkg/subpkg	0.005s [no tests to run]
</pre></details>

<details><summary><code>go test -v -json ./...</code> Output</summary><br><pre>
$ go test -v -json ./...
{"Time":"2018-11-26T15:03:16.782812+01:00","Action":"output","Package":"my_pkg/pkg/subpkg","Output":"testing: warning: no tests to run\n"}
{"Time":"2018-11-26T15:03:16.783598+01:00","Action":"output","Package":"my_pkg/pkg/subpkg","Output":"PASS\n"}
{"Time":"2018-11-26T15:03:16.783605+01:00","Action":"output","Package":"my_pkg/pkg/subpkg","Output":"ok  \tmy_pkg/pkg/subpkg\t(cached) [no tests to run]\n"}
{"Time":"2018-11-26T15:03:16.783614+01:00","Action":"pass","Package":"my_pkg/pkg/subpkg","Elapsed":0.001}
{"Time":"2018-11-26T15:03:17.015719+01:00","Action":"run","Package":"my_pkg","Test":"TestSuccess"}
{"Time":"2018-11-26T15:03:17.015757+01:00","Action":"output","Package":"my_pkg","Test":"TestSuccess","Output":"=== RUN   TestSuccess\n"}
{"Time":"2018-11-26T15:03:17.015786+01:00","Action":"output","Package":"my_pkg","Test":"TestSuccess","Output":"--- PASS: TestSuccess (0.00s)\n"}
{"Time":"2018-11-26T15:03:17.015797+01:00","Action":"pass","Package":"my_pkg","Test":"TestSuccess","Elapsed":0}
{"Time":"2018-11-26T15:03:17.015804+01:00","Action":"run","Package":"my_pkg","Test":"TestSkip"}
{"Time":"2018-11-26T15:03:17.015816+01:00","Action":"output","Package":"my_pkg","Test":"TestSkip","Output":"=== RUN   TestSkip\n"}
{"Time":"2018-11-26T15:03:17.01583+01:00","Action":"output","Package":"my_pkg","Test":"TestSkip","Output":"--- SKIP: TestSkip (0.00s)\n"}
{"Time":"2018-11-26T15:03:17.015837+01:00","Action":"output","Package":"my_pkg","Test":"TestSkip","Output":"    test_test.go:10: skipping test\n"}
{"Time":"2018-11-26T15:03:17.015848+01:00","Action":"skip","Package":"my_pkg","Test":"TestSkip","Elapsed":0}
{"Time":"2018-11-26T15:03:17.015854+01:00","Action":"run","Package":"my_pkg","Test":"TestFail"}
{"Time":"2018-11-26T15:03:17.015859+01:00","Action":"output","Package":"my_pkg","Test":"TestFail","Output":"=== RUN   TestFail\n"}
{"Time":"2018-11-26T15:03:17.015864+01:00","Action":"output","Package":"my_pkg","Test":"TestFail","Output":"--- FAIL: TestFail (0.00s)\n"}
{"Time":"2018-11-26T15:03:17.01587+01:00","Action":"output","Package":"my_pkg","Test":"TestFail","Output":"    test_test.go:14: failed test\n"}
{"Time":"2018-11-26T15:03:17.015883+01:00","Action":"fail","Package":"my_pkg","Test":"TestFail","Elapsed":0}
{"Time":"2018-11-26T15:03:17.015888+01:00","Action":"run","Package":"my_pkg","Test":"TestMain"}
{"Time":"2018-11-26T15:03:17.015942+01:00","Action":"output","Package":"my_pkg","Test":"TestMain","Output":"=== RUN   TestMain\n"}
{"Time":"2018-11-26T15:03:17.015956+01:00","Action":"run","Package":"my_pkg","Test":"TestMain/success"}
{"Time":"2018-11-26T15:03:17.015963+01:00","Action":"output","Package":"my_pkg","Test":"TestMain/success","Output":"=== RUN   TestMain/success\n"}
{"Time":"2018-11-26T15:03:17.015969+01:00","Action":"run","Package":"my_pkg","Test":"TestMain/skip"}
{"Time":"2018-11-26T15:03:17.015974+01:00","Action":"output","Package":"my_pkg","Test":"TestMain/skip","Output":"=== RUN   TestMain/skip\n"}
{"Time":"2018-11-26T15:03:17.015984+01:00","Action":"run","Package":"my_pkg","Test":"TestMain/fail"}
{"Time":"2018-11-26T15:03:17.01599+01:00","Action":"output","Package":"my_pkg","Test":"TestMain/fail","Output":"=== RUN   TestMain/fail\n"}
{"Time":"2018-11-26T15:03:17.015996+01:00","Action":"output","Package":"my_pkg","Test":"TestMain","Output":"--- FAIL: TestMain (0.00s)\n"}
{"Time":"2018-11-26T15:03:17.016019+01:00","Action":"output","Package":"my_pkg","Test":"TestMain/success","Output":"    --- PASS: TestMain/success (0.00s)\n"}
{"Time":"2018-11-26T15:03:17.016026+01:00","Action":"pass","Package":"my_pkg","Test":"TestMain/success","Elapsed":0}
{"Time":"2018-11-26T15:03:17.016037+01:00","Action":"output","Package":"my_pkg","Test":"TestMain/skip","Output":"    --- SKIP: TestMain/skip (0.00s)\n"}
{"Time":"2018-11-26T15:03:17.016042+01:00","Action":"output","Package":"my_pkg","Test":"TestMain/skip","Output":"        test_test.go:23: skipping test\n"}
{"Time":"2018-11-26T15:03:17.016049+01:00","Action":"skip","Package":"my_pkg","Test":"TestMain/skip","Elapsed":0}
{"Time":"2018-11-26T15:03:17.016054+01:00","Action":"output","Package":"my_pkg","Test":"TestMain/fail","Output":"    --- FAIL: TestMain/fail (0.00s)\n"}
{"Time":"2018-11-26T15:03:17.01606+01:00","Action":"output","Package":"my_pkg","Test":"TestMain/fail","Output":"        test_test.go:27: failed test\n"}
{"Time":"2018-11-26T15:03:17.016088+01:00","Action":"fail","Package":"my_pkg","Test":"TestMain/fail","Elapsed":0}
{"Time":"2018-11-26T15:03:17.016094+01:00","Action":"fail","Package":"my_pkg","Test":"TestMain","Elapsed":0}
{"Time":"2018-11-26T15:03:17.016099+01:00","Action":"output","Package":"my_pkg","Output":"FAIL\n"}
{"Time":"2018-11-26T15:03:17.016309+01:00","Action":"output","Package":"my_pkg","Output":"FAIL\tmy_pkg\t0.005s\n"}
{"Time":"2018-11-26T15:03:17.016339+01:00","Action":"fail","Package":"my_pkg","Elapsed":0.006}
{"Time":"2018-11-26T15:03:17.017209+01:00","Action":"output","Package":"my_pkg/pkg/no_tests","Output":"?   \tmy_pkg/pkg/no_tests\t[no test files]\n"}
{"Time":"2018-11-26T15:03:17.017238+01:00","Action":"skip","Package":"my_pkg/pkg/no_tests","Elapsed":0}
</pre></details>

<details><summary><code>go test -v ./... | go tool test2json</code> Output</summary><br><pre>
$ go test -v ./... | go tool test2json
{"Action":"run","Test":"TestSuccess"}
{"Action":"output","Test":"TestSuccess","Output":"=== RUN   TestSuccess\n"}
{"Action":"output","Test":"TestSuccess","Output":"--- PASS: TestSuccess (0.00s)\n"}
{"Action":"pass","Test":"TestSuccess"}
{"Action":"run","Test":"TestSkip"}
{"Action":"output","Test":"TestSkip","Output":"=== RUN   TestSkip\n"}
{"Action":"output","Test":"TestSkip","Output":"--- SKIP: TestSkip (0.00s)\n"}
{"Action":"output","Test":"TestSkip","Output":"    test_test.go:10: skipping test\n"}
{"Action":"skip","Test":"TestSkip"}
{"Action":"run","Test":"TestFail"}
{"Action":"output","Test":"TestFail","Output":"=== RUN   TestFail\n"}
{"Action":"output","Test":"TestFail","Output":"--- FAIL: TestFail (0.00s)\n"}
{"Action":"output","Test":"TestFail","Output":"    test_test.go:14: failed test\n"}
{"Action":"fail","Test":"TestFail"}
{"Action":"run","Test":"TestMain"}
{"Action":"output","Test":"TestMain","Output":"=== RUN   TestMain\n"}
{"Action":"run","Test":"TestMain/success"}
{"Action":"output","Test":"TestMain/success","Output":"=== RUN   TestMain/success\n"}
{"Action":"run","Test":"TestMain/skip"}
{"Action":"output","Test":"TestMain/skip","Output":"=== RUN   TestMain/skip\n"}
{"Action":"run","Test":"TestMain/fail"}
{"Action":"output","Test":"TestMain/fail","Output":"=== RUN   TestMain/fail\n"}
{"Action":"output","Test":"TestMain","Output":"--- FAIL: TestMain (0.00s)\n"}
{"Action":"output","Test":"TestMain/success","Output":"    --- PASS: TestMain/success (0.00s)\n"}
{"Action":"pass","Test":"TestMain/success"}
{"Action":"output","Test":"TestMain/skip","Output":"    --- SKIP: TestMain/skip (0.00s)\n"}
{"Action":"output","Test":"TestMain/skip","Output":"        test_test.go:23: skipping test\n"}
{"Action":"skip","Test":"TestMain/skip"}
{"Action":"output","Test":"TestMain/fail","Output":"    --- FAIL: TestMain/fail (0.00s)\n"}
{"Action":"output","Test":"TestMain/fail","Output":"        test_test.go:27: failed test\n"}
{"Action":"fail","Test":"TestMain/fail"}
{"Action":"fail","Test":"TestMain"}
{"Action":"output","Output":"FAIL\n"}
{"Action":"output","Output":"FAIL\tmy_pkg\t0.006s\n"}
{"Action":"output","Output":"?   \tmy_pkg/pkg/no_tests\t[no test files]\n"}
{"Action":"output","Output":"testing: warning: no tests to run\n"}
{"Action":"output","Output":"PASS\n"}
{"Action":"output","Output":"ok  \tmy_pkg/pkg/subpkg\t(cached) [no tests to run]\n"}
{"Action":"pass"}
</pre></details>

As per https://golang.org/cmd/test2json I expect to see the events to be in the exact same order:

> With that one exception, the concatenation of the Output fields of all output events is the exact output of the test execution.

But they are not. This causes a problem when one would like to get a json output for some kind of reporting purpose, but still want to display the regular test report to the user.