Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
andreimatei opened this issue Sep 8, 2018 · 3 comments
Closed

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

andreimatei opened this issue Sep 8, 2018 · 3 comments
Labels
FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Milestone
Go1.20

Comments

@andreimatei
Copy link
Contributor

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
Copy link
Contributor Author

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 andybons added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Sep 26, 2018
@andybons andybons added this to the Unplanned milestone Sep 26, 2018
@andybons
Copy link
Member

@rsc

@gopherbot
Copy link

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

romaindoumenc pushed a commit to TroutSoftware/go that referenced this issue Nov 3, 2022
@rsc @romaindoumenc
testing: fix many test2json inaccuracies
2955168 
Test2json is parsing the output stream from the test, which includes
package testing's own framing lines intermingled with other output,
in particular any output printed via fmt.Printf, println, and so on.
We have had recurring problems with unexpected partial output lines
causing a framing line to be missed.

A recent talk at GopherCon gave an example of an integration test
involving Docker that happened to print \r-terminated lines instead
of \n-terminated lines in some configurations, which in turn broke
test2json badly. (https://www.gophercon.com/agenda/session/944259)

There are also a variety of open reported issues with similar problems,
which this CL also addresses. The general approach is to add a new
testing flag -test.v=json that means to print additional output to help
test2json. And then test2json takes advantage of that output.

Among the fixes:

 - Identify testing framing more reliably, using ^V
   (golang#23036, golang#26325, golang#43683, GopherCon talk)
 - Test that output with \r\n endings is handled correctly
   (golang#43683, golang#34286)
 - Use === RUN in fuzz tests (golang#52636, golang#48132)
 - Add === RUN lines to note benchmark starts (golang#27764, golang#49505)
 - Print subtest --- PASS/FAIL lines as they happen (golang#29811)
 - Add === NAME lines to emit more test change events,
   such as when a subtest stops and the parent continues running.
 - Fix event shown in overall test failure (golang#27568)
 - Avoid interleaving of writes to os.Stdout and os.Stderr (golang#33419)

Fixes golang#23036.
Fixes golang#26325.
Fixes golang#27568.
Fixes golang#27764.
Fixes golang#29811.
Fixes golang#33419.
Fixes golang#34286.
Fixes golang#43683.
Fixes golang#49505.
Fixes golang#52636.

Change-Id: Id4207b746a20693f92e52d68c6e4a7f8c41cc7c6
Reviewed-on: https://go-review.googlesource.com/c/go/+/443596
Auto-Submit: Russ Cox <rsc@golang.org>
Run-TryBot: Russ Cox <rsc@golang.org>
Reviewed-by: Bryan Mills <bcmills@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
@dmitshur dmitshur modified the milestones: Unplanned, Go1.20 Nov 18, 2022
@dmitshur dmitshur added NeedsFix The path to resolution is known, but the work has not been done. and removed NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Nov 18, 2022
@golang golang locked and limited conversation to collaborators Nov 18, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Projects
None yet
Milestone
Go1.20
Development

No branches or pull requests
4 participants
@andybons @andreimatei @dmitshur @gopherbot