cmd/test2json: bogus Elapsed field computed when test times out

[andreimatei]

If you run go tool test2json with the -t flag, it produces some timing info in its structured output. Among them, an Elapsed field defined vaguely in the docs as

The Elapsed field is set for "pass" and "fail" events. It gives the time elapsed for the specific test or the overall package test that passed or failed.

So, the field is produced for either test or package-level pass/fail events. When referring to a single test, the Elapsed field generally measures how long that one test took (which is good).
However, when the test binary times out (through the -test.timeout flag), the last entry produced by the test2json seems non-sensical: it claims that the test running when the timeout occurred took as long as the whole test binary took to run. In other words, all the tests' durations are accounted towards the one test that was running when the timeout occurs.
For example, with a test binary, say kv.test, if one does:

./kv.test -test.v -test.timeout=5s  2>&1 | go tool test2json -t > /tmp/out-streamed-timeout.json

The last line of the tools output reads like:

{"Time":"2018-09-08T11:00:49.477928549-04:00","Action":"fail","Test":"TestTxnDBReadSkewAnomaly","Elapsed":5.049}

So, it claims that TestTxnDBReadSkewAnomaly ran for 5s. That's not true, as can be seen from the first line of tool output for that test:

{"Time":"2018-09-08T11:00:48.676274586-04:00","Action":"run","Test":"TestTxnDBReadSkewAnomaly"}

The test in fact ran for less than one second.
A good guess is that the tool got confused about what context its in when printing the last line, and looked at the whole test binary duration - which is around 5s as can be see by looking at the first line of output:

{"Time":"2018-09-08T11:00:44.462501938-04:00","Action":"run","Test":"TestBatchPrevNext"}

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

go version go1.10 darwin/amd64

Does this issue reproduce with the latest release?

Yes, reproduced with go1.11 too

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

Reproduced on both OSX and Linux.

[andreimatei]

I should add a guess about something potentially related: in the timeout case, there's no "--- PASS" or "--- FAIL" log line with timing info preceding the pass/fail event. I'm guessing the tool uses those when they're present (since I've noticed that it produces Elapsed calculations even when the input is not streamed into it, but comes from a file instead).

[andybons]

@rsc

[gopherbot]

Change https://go.dev/cl/443596 mentions this issue: testing: fix many test2json inaccuracies