testing: unexpected top level test output belonging to a subtest

[mfridman]

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

go version devel +76e8ca4 Tue Jan 15 18:14:54 2019 +0000 darwin/amd64

Does this issue reproduce with the latest release?

N/A, working with master.

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

GOARCH="amd64"
GOOS="darwin"

What did you do?

Run code from this playground example

go test debug/golang/subtest -run ^TestThis$ -v -race

What did you expect to see?

Expected to see the test output

some_test.go:14: woah, something went wrong

belong to the top level test and not the inner subtest. E.g., when running the above with -json I'd expect this output:

{"Time":"2019-01-15T13:40:03.616451-05:00","Action":"output","Package":"debug/golang/subtest","Test":"TestThis/topLevelTest","Output":"        some_test.go:14: woah, something went wrong\n"}

note the test name in the json output is expected to beTestThis/topLevelTest

What did you see instead?

Instead the output and -json output makes it seem as if it belongs to the inner subtest, i.e., test name TestThis/topLevelTest/subA

This may be a misuse of the API, but I couldn't find any docs that mention there shouldn't be anything in between subtests.

=== RUN   TestThis
=== RUN   TestThis/topLevelTest
=== RUN   TestThis/topLevelTest/subA
--- FAIL: TestThis (0.00s)
    --- FAIL: TestThis/topLevelTest (0.00s)
        --- PASS: TestThis/topLevelTest/subA (0.00s)
            some_test.go:11: subA passing
        some_test.go:14: woah, something went wrong
FAIL
FAIL	debug/go-trun	0.026s

The -json output was:

{"Time":"2019-01-15T13:40:03.616451-05:00","Action":"output","Package":"debug/golang/subtest","Test":"TestThis/topLevelTest/subA","Output":"        some_test.go:14: woah, something went wrong\n"}

This might be an issue with test2json.

[bcmills]

CC @mpvl @josharian

As far as I can tell the indentation looks right. I suspect a test2json bug.

[dnephin]

I ran into this bug as well. I started reading test2json for the first time.

From my not-yet-informed first read, it seems like the bug may be that converter.testName is used as event.Test. That value is a single field, not a stack, so when indentation drops back down the testName isn't being reset. converter.report seems to be a stack of event, which has a Name field.

Maybe testName could be removed and the value could be ready from report[-1]? (or we could add a new stack for testName if that won't work for some reason).

Anyone familiar with this code that might be able to confirm?

I can work on contributing a fix.

[gopherbot]

Change https://golang.org/cl/196617 mentions this issue: cmd/test2json: attribute output to the correct test