cmd/test2json: streamed log output not correctly associated with parallel tests #38050

mdwhatcott · 2020-03-24T18:25:51Z

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=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/mike/Library/Caches/go-build"
GOENV="/Users/mike/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/mike"
GOPRIVATE=""
GOPROXY="direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/mike/src/github.com/mdwhatcott/parallel/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/mv/rt57xj7n1xl1wvqn5h0y2x4m0000gp/T/go-build151690166=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

Working sample code: https://github.com/mdwhatcott/parallel

The sample code referenced above runs tests in parallel. I use parallel tests quite often to prove that test cases are isolated and that there are no unintended temporal couplings in the code. The purpose of this code is to illustrate a bug in the output of go test -json (as well as go tool test2json).

After upgrading to Go 1.14 I noticed that output associated with failing tests wasn't always correctly associated with the failing test. I suppose this is a consequence of the change to test output introduced in Go 1.14 which causes all output to be immediately streamed to the output rather than buffered for each test. (See the original issue (#24929) and the Go 1.14 release notes (https://golang.org/doc/go1.14#go-test).)

The repository referenced above (https://github.com/mdwhatcott/parallel) includes working tests and reference output for both Go 1.14.1 (problematic) and Go 1.13.1 (working fine).

What did you expect to see?

I expect that the output of go test -json correctly associate output of failing tests with the test that failed, not other tests (that might even have passed).

What did you see instead?

The problem is that output associated with failing tests is sometimes associated with passing tests, probably because it (the failure output) is emitted proximate to output for the passing test. This is very problematic for test runner tools found in many text editors and IDEs (issue on JetBrains GoLand issue tracker: https://youtrack.jetbrains.com/issue/GO-8985).

Here's what the errant lines look like from executing go test -json:

{"Time":"2020-03-24T12:13:53.358545-06:00","Action":"output","Package":"parallel","Test":"Test1/this_passes","Output":"        got:  [THIS WILL FAIL]\n"}
{"Time":"2020-03-24T12:13:53.358549-06:00","Action":"output","Package":"parallel","Test":"Test1/this_passes","Output":"        want: [because this is wrong]\n"}

Notice that the failure output is associated with "Test1/this_passes", which was a passing test with no output.

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

andybons · 2020-03-25T16:08:55Z

@rsc @mpvl

vvakame · 2020-03-26T04:34:09Z

sorry for my unclear information.
We have a similar like problems on Circle CI.
We are using t.Parallel. When test was failed, We can't see --- FAIL (and --- PASS) log about specific test case. Its vanished.
We got only FAIL log at last.
We are using golang:1.14-buster docker image on CI.
and, We can't reproduce with small sample code...

HACK to accommodate for #28 Also see: golang/go#38050

mdwhatcott · 2020-03-31T18:59:36Z

I have a fix almost ready to submit as a PR. The gist of the change is that the test2json converter needs to keep track of all test names in a map[string]struct{} so that when decorated test log output is emitted (at any point, thanks to #24929) it can be associated back to the originating test. Here's how I'm planning to implement the logic that is needed (at line 214):

if !ok {
    // Not a special test output line, but it may be the beginning
    // of decorated test log output and should be associated with its originating test.
    line := string(origLine)
    dedent := strings.TrimLeftFunc(line, unicode.IsSpace)
    end := strings.Index(dedent, ":")
    if end >= len("Test") {
        name := dedent[:end]
        _, found := c.testNames[name]
        if found {
            c.testName = name
        }
    }
    c.output.write(origLine)
    return
}

Here's the test case I plan on adding (straight from the sample code referenced in the description of this issue):

=== RUN   Test1
=== PAUSE Test1
=== RUN   Test2
=== PAUSE Test2
=== CONT  Test1
=== CONT  Test2
=== RUN   Test1/this_passes
=== PAUSE Test1/this_passes
=== RUN   Test1/this_will_fail
=== RUN   Test2/this_passes
=== PAUSE Test1/this_will_fail
=== CONT  Test1/this_passes
=== PAUSE Test2/this_passes
=== CONT  Test1/this_will_fail
=== RUN   Test2/this_will_fail
=== PAUSE Test2/this_will_fail
=== CONT  Test2/this_passes
    Test1/this_will_fail: parallel_test.go:40:
        got:  [THIS WILL FAIL]
        want: [because this is wrong]
=== CONT  Test2/this_will_fail
--- FAIL: Test1 (0.00s)
    --- PASS: Test1/this_passes (0.00s)
    --- FAIL: Test1/this_will_fail (0.00s)
    Test2/this_will_fail: parallel_test.go:40:
        got:  [THIS WILL FAIL]
        want: [because this is wrong]
--- FAIL: Test2 (0.00s)
    --- PASS: Test2/this_passes (0.00s)
    --- FAIL: Test2/this_will_fail (0.00s)
FAIL

And here's the expected output (made possible by the code above):

{"Action":"run","Test":"Test1"}
{"Action":"output","Test":"Test1","Output":"=== RUN   Test1\n"}
{"Action":"output","Test":"Test1","Output":"=== PAUSE Test1\n"}
{"Action":"pause","Test":"Test1"}
{"Action":"run","Test":"Test2"}
{"Action":"output","Test":"Test2","Output":"=== RUN   Test2\n"}
{"Action":"output","Test":"Test2","Output":"=== PAUSE Test2\n"}
{"Action":"pause","Test":"Test2"}
{"Action":"cont","Test":"Test1"}
{"Action":"output","Test":"Test1","Output":"=== CONT  Test1\n"}
{"Action":"cont","Test":"Test2"}
{"Action":"output","Test":"Test2","Output":"=== CONT  Test2\n"}
{"Action":"run","Test":"Test1/this_passes"}
{"Action":"output","Test":"Test1/this_passes","Output":"=== RUN   Test1/this_passes\n"}
{"Action":"output","Test":"Test1/this_passes","Output":"=== PAUSE Test1/this_passes\n"}
{"Action":"pause","Test":"Test1/this_passes"}
{"Action":"run","Test":"Test1/this_will_fail"}
{"Action":"output","Test":"Test1/this_will_fail","Output":"=== RUN   Test1/this_will_fail\n"}
{"Action":"run","Test":"Test2/this_passes"}
{"Action":"output","Test":"Test2/this_passes","Output":"=== RUN   Test2/this_passes\n"}
{"Action":"output","Test":"Test1/this_will_fail","Output":"=== PAUSE Test1/this_will_fail\n"}
{"Action":"pause","Test":"Test1/this_will_fail"}
{"Action":"cont","Test":"Test1/this_passes"}
{"Action":"output","Test":"Test1/this_passes","Output":"=== CONT  Test1/this_passes\n"}
{"Action":"output","Test":"Test2/this_passes","Output":"=== PAUSE Test2/this_passes\n"}
{"Action":"pause","Test":"Test2/this_passes"}
{"Action":"cont","Test":"Test1/this_will_fail"}
{"Action":"output","Test":"Test1/this_will_fail","Output":"=== CONT  Test1/this_will_fail\n"}
{"Action":"run","Test":"Test2/this_will_fail"}
{"Action":"output","Test":"Test2/this_will_fail","Output":"=== RUN   Test2/this_will_fail\n"}
{"Action":"output","Test":"Test2/this_will_fail","Output":"=== PAUSE Test2/this_will_fail\n"}
{"Action":"pause","Test":"Test2/this_will_fail"}
{"Action":"cont","Test":"Test2/this_passes"}
{"Action":"output","Test":"Test2/this_passes","Output":"=== CONT  Test2/this_passes\n"}
{"Action":"output","Test":"Test1/this_will_fail","Output":"    Test1/this_will_fail: parallel_test.go:40:\n"}
{"Action":"output","Test":"Test1/this_will_fail","Output":"        got:  [THIS WILL FAIL]\n"}
{"Action":"output","Test":"Test1/this_will_fail","Output":"        want: [because this is wrong]\n"}
{"Action":"cont","Test":"Test2/this_will_fail"}
{"Action":"output","Test":"Test2/this_will_fail","Output":"=== CONT  Test2/this_will_fail\n"}
{"Action":"output","Test":"Test1","Output":"--- FAIL: Test1 (0.00s)\n"}
{"Action":"output","Test":"Test1/this_passes","Output":"    --- PASS: Test1/this_passes (0.00s)\n"}
{"Action":"pass","Test":"Test1/this_passes"}
{"Action":"output","Test":"Test1/this_will_fail","Output":"    --- FAIL: Test1/this_will_fail (0.00s)\n"}
{"Action":"output","Test":"Test2/this_will_fail","Output":"    Test2/this_will_fail: parallel_test.go:40:\n"}
{"Action":"output","Test":"Test2/this_will_fail","Output":"        got:  [THIS WILL FAIL]\n"}
{"Action":"output","Test":"Test2/this_will_fail","Output":"        want: [because this is wrong]\n"}
{"Action":"fail","Test":"Test1/this_will_fail"}
{"Action":"fail","Test":"Test1"}
{"Action":"output","Test":"Test2","Output":"--- FAIL: Test2 (0.00s)\n"}
{"Action":"output","Test":"Test2/this_passes","Output":"    --- PASS: Test2/this_passes (0.00s)\n"}
{"Action":"pass","Test":"Test2/this_passes"}
{"Action":"output","Test":"Test2/this_will_fail","Output":"    --- FAIL: Test2/this_will_fail (0.00s)\n"}
{"Action":"fail","Test":"Test2/this_will_fail"}
{"Action":"fail","Test":"Test2"}
{"Action":"output","Output":"FAIL\n"}
{"Action":"fail"}

gopherbot · 2020-03-31T23:14:39Z

Change https://golang.org/cl/226757 mentions this issue: test2json: associate streaming log output with the originating test

mdwhatcott · 2020-04-10T14:28:28Z

@andybons - Just curious, how shall I know when/whether the associated PR has been seen or reviewed, or what the next step is?

#38189

andybons · 2020-04-10T22:18:46Z

@bcmills mind taking a look?

mdwhatcott · 2020-04-15T17:30:22Z

@andybons @bcmills - Had a chance to look over the PR? #38189

mdwhatcott · 2020-04-15T20:15:41Z

@bcmills - Thanks for the review. Stay tuned for additional commits.

mdwhatcott · 2020-04-15T22:07:52Z

@bcmills - Ok, I've incorporated your suggestions, including the addition of an integration test/script.

andybons · 2020-04-16T05:15:05Z

@mdwhatcott please use the Gerrit UI — https://go-review.googlesource.com/c/go/+/226757 and mark comments you’ve addressed as “resolved” rather than commenting here. Thanks.

mdwhatcott · 2020-04-16T05:36:05Z

@andybons - Well, I definitely am new here ;)

Thanks

mdwhatcott · 2020-04-17T13:52:57Z

@andybons @bcmills - ok, I think I've marked all comments as resolved, so it's back in your court now.

bcmills · 2020-04-18T02:55:52Z

Thanks. There is some discussion of rolling back the output-format change (#38458), so this may only need to happen on the 1.14 branch.

mdwhatcott · 2020-05-08T01:55:53Z

@bcmills @andybons - any chance of movement on this?

dlsniper · 2020-05-28T13:57:49Z

I'm going to ping this one as well :)

bcmills · 2020-05-28T21:26:17Z

I believe that #39308 will be the fix for this in 1.14. (We'll fix the output format rather than the test2json tool.)

mdwhatcott · 2020-07-17T15:01:45Z

Resolved in Go1.14.6. Thanks everyone!

mdwhatcott mentioned this issue Mar 24, 2020

testing: parallel subtest log output not properly constrained in go1.14rc1 #37203

Closed

andybons added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Mar 25, 2020

andybons added this to the Unplanned milestone Mar 25, 2020

mdwhatcott mentioned this issue Mar 30, 2020

gunit.RunSequential currently required when running Go 1.14 smarty/gunit#28

Closed

mdwhatcott added a commit to smarty/gunit that referenced this issue Mar 30, 2020

Disable parallel execution of tests until test2json is patched.

98db72e

HACK to accommodate for #28 Also see: golang/go#38050

mdwhatcott changed the title ~~testing: -json output is often incorrect (mixed up) for parallel tests~~ cmd/test2json: decorated log output not correctly associated with parallel tests Mar 31, 2020

mdwhatcott mentioned this issue Mar 31, 2020

test2json: associate streaming log output with the originating test #38189

Closed

mdwhatcott changed the title ~~cmd/test2json: decorated log output not correctly associated with parallel tests~~ cmd/test2json: streamed log output not correctly associated with parallel tests Mar 31, 2020

mdwhatcott mentioned this issue Apr 18, 2020

testing: streaming output loses parallel subtest associations #38458

Closed

mdwhatcott closed this as completed Jul 17, 2020

aaronlehmann mentioned this issue Apr 1, 2021

Handle missing "pass" event for subtests gotestyourself/gotestsum#188

Closed

golang locked and limited conversation to collaborators Jul 17, 2021

gopherbot added the FrozenDueToAge label Jul 17, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

cmd/test2json: streamed log output not correctly associated with parallel tests #38050

cmd/test2json: streamed log output not correctly associated with parallel tests #38050

mdwhatcott commented Mar 24, 2020

andybons commented Mar 25, 2020

vvakame commented Mar 26, 2020

mdwhatcott commented Mar 31, 2020 •

edited

gopherbot commented Mar 31, 2020

mdwhatcott commented Apr 10, 2020

andybons commented Apr 10, 2020

mdwhatcott commented Apr 15, 2020

mdwhatcott commented Apr 15, 2020

mdwhatcott commented Apr 15, 2020

andybons commented Apr 16, 2020

mdwhatcott commented Apr 16, 2020

mdwhatcott commented Apr 17, 2020

bcmills commented Apr 18, 2020

mdwhatcott commented May 8, 2020

dlsniper commented May 28, 2020

bcmills commented May 28, 2020

mdwhatcott commented Jul 17, 2020 •

edited

cmd/test2json: streamed log output not correctly associated with parallel tests #38050

cmd/test2json: streamed log output not correctly associated with parallel tests #38050

Comments

mdwhatcott commented Mar 24, 2020

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?

andybons commented Mar 25, 2020

vvakame commented Mar 26, 2020

mdwhatcott commented Mar 31, 2020 • edited

gopherbot commented Mar 31, 2020

mdwhatcott commented Apr 10, 2020

andybons commented Apr 10, 2020

mdwhatcott commented Apr 15, 2020

mdwhatcott commented Apr 15, 2020

mdwhatcott commented Apr 15, 2020

andybons commented Apr 16, 2020

mdwhatcott commented Apr 16, 2020

mdwhatcott commented Apr 17, 2020

bcmills commented Apr 18, 2020

mdwhatcott commented May 8, 2020

dlsniper commented May 28, 2020

bcmills commented May 28, 2020

mdwhatcott commented Jul 17, 2020 • edited

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

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

mdwhatcott commented Mar 31, 2020 •

edited

mdwhatcott commented Jul 17, 2020 •

edited