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.

Sign up for GitHub

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/go: go test -json does not print subtest results as they become available #29811

Closed
rogpeppe opened this issue Jan 18, 2019 · 4 comments
Closed

cmd/go: go test -json does not print subtest results as they become available #29811

rogpeppe opened this issue Jan 18, 2019 · 4 comments
Labels
FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done. ToolSpeed
Milestone
Go1.20

Comments

@rogpeppe
Copy link
Contributor

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

$ go version
go version devel +4b3f04c63b Thu Jan 10 18:15:48 2019 +0000 linux/amd64

When I run go test -json, it prints results for top level tests when those tests complete.
But for subtests, all the results are printed only when the last sibling subtest completes.

For example, consider the following program:

package test

import (
	"fmt"
	"testing"
	"time"
)

func Test1(t *testing.T) {
	t.Parallel()
	for i := 0; i < 3; i++ {
		i := i
		t.Run(fmt.Sprintf("testx%d", i), func(t *testing.T) {
			t.Parallel()
			time.Sleep(time.Duration(3-i) * time.Second)
		})
	}
}

func Test2(t *testing.T) {
	t.Parallel()
}

this produces the following result (each line preceded by the time that line was printed):

Output of go test -json
0:00.117 {"Time":"2019-01-18T17:55:44.379734271Z","Action":"run","Package":"command-line-arguments","Test":"Test1"}
0:00.117 {"Time":"2019-01-18T17:55:44.380063958Z","Action":"output","Package":"command-line-arguments","Test":"Test1","Output":"=== RUN   Test1\n"}
0:00.117 {"Time":"2019-01-18T17:55:44.380075747Z","Action":"output","Package":"command-line-arguments","Test":"Test1","Output":"=== PAUSE Test1\n"}
0:00.117 {"Time":"2019-01-18T17:55:44.380080971Z","Action":"pause","Package":"command-line-arguments","Test":"Test1"}
0:00.117 {"Time":"2019-01-18T17:55:44.380086613Z","Action":"run","Package":"command-line-arguments","Test":"Test2"}
0:00.117 {"Time":"2019-01-18T17:55:44.380102357Z","Action":"output","Package":"command-line-arguments","Test":"Test2","Output":"=== RUN   Test2\n"}
0:00.117 {"Time":"2019-01-18T17:55:44.380108309Z","Action":"output","Package":"command-line-arguments","Test":"Test2","Output":"=== PAUSE Test2\n"}
0:00.117 {"Time":"2019-01-18T17:55:44.380112668Z","Action":"pause","Package":"command-line-arguments","Test":"Test2"}
0:00.117 {"Time":"2019-01-18T17:55:44.380118025Z","Action":"cont","Package":"command-line-arguments","Test":"Test1"}
0:00.117 {"Time":"2019-01-18T17:55:44.380123202Z","Action":"output","Package":"command-line-arguments","Test":"Test1","Output":"=== CONT  Test1\n"}
0:00.117 {"Time":"2019-01-18T17:55:44.380128593Z","Action":"run","Package":"command-line-arguments","Test":"Test1/testx0"}
0:00.117 {"Time":"2019-01-18T17:55:44.380139573Z","Action":"output","Package":"command-line-arguments","Test":"Test1/testx0","Output":"=== RUN   Test1/testx0\n"}
0:00.117 {"Time":"2019-01-18T17:55:44.380146043Z","Action":"output","Package":"command-line-arguments","Test":"Test1/testx0","Output":"=== PAUSE Test1/testx0\n"}
0:00.117 {"Time":"2019-01-18T17:55:44.380150741Z","Action":"pause","Package":"command-line-arguments","Test":"Test1/testx0"}
0:00.117 {"Time":"2019-01-18T17:55:44.38015585Z","Action":"run","Package":"command-line-arguments","Test":"Test1/testx1"}
0:00.117 {"Time":"2019-01-18T17:55:44.380161348Z","Action":"output","Package":"command-line-arguments","Test":"Test1/testx1","Output":"=== RUN   Test1/testx1\n"}
0:00.117 {"Time":"2019-01-18T17:55:44.380169686Z","Action":"output","Package":"command-line-arguments","Test":"Test1/testx1","Output":"=== PAUSE Test1/testx1\n"}
0:00.117 {"Time":"2019-01-18T17:55:44.380174408Z","Action":"pause","Package":"command-line-arguments","Test":"Test1/testx1"}
0:00.117 {"Time":"2019-01-18T17:55:44.380184963Z","Action":"run","Package":"command-line-arguments","Test":"Test1/testx2"}
0:00.117 {"Time":"2019-01-18T17:55:44.380189673Z","Action":"output","Package":"command-line-arguments","Test":"Test1/testx2","Output":"=== RUN   Test1/testx2\n"}
0:00.117 {"Time":"2019-01-18T17:55:44.380195511Z","Action":"output","Package":"command-line-arguments","Test":"Test1/testx2","Output":"=== PAUSE Test1/testx2\n"}
0:00.117 {"Time":"2019-01-18T17:55:44.380200093Z","Action":"pause","Package":"command-line-arguments","Test":"Test1/testx2"}
0:00.117 {"Time":"2019-01-18T17:55:44.380205261Z","Action":"cont","Package":"command-line-arguments","Test":"Test1/testx0"}
0:00.117 {"Time":"2019-01-18T17:55:44.380209759Z","Action":"output","Package":"command-line-arguments","Test":"Test1/testx0","Output":"=== CONT  Test1/testx0\n"}
0:00.117 {"Time":"2019-01-18T17:55:44.380215129Z","Action":"cont","Package":"command-line-arguments","Test":"Test2"}
0:00.117 {"Time":"2019-01-18T17:55:44.380225339Z","Action":"output","Package":"command-line-arguments","Test":"Test2","Output":"=== CONT  Test2\n"}
0:00.117 {"Time":"2019-01-18T17:55:44.380233839Z","Action":"output","Package":"command-line-arguments","Test":"Test2","Output":"--- PASS: Test2 (0.00s)\n"}
0:00.117 {"Time":"2019-01-18T17:55:44.38023952Z","Action":"pass","Package":"command-line-arguments","Test":"Test2","Elapsed":0}
0:00.117 {"Time":"2019-01-18T17:55:44.380245912Z","Action":"cont","Package":"command-line-arguments","Test":"Test1/testx1"}
0:00.117 {"Time":"2019-01-18T17:55:44.380250653Z","Action":"output","Package":"command-line-arguments","Test":"Test1/testx1","Output":"=== CONT  Test1/testx1\n"}
0:00.117 {"Time":"2019-01-18T17:55:44.380256148Z","Action":"cont","Package":"command-line-arguments","Test":"Test1/testx2"}
0:00.117 {"Time":"2019-01-18T17:55:44.380266852Z","Action":"output","Package":"command-line-arguments","Test":"Test1/testx2","Output":"=== CONT  Test1/testx2\n"}
0:00.117 {"Time":"2019-01-18T17:55:44.380273841Z","Action":"output","Package":"command-line-arguments","Test":"Test1","Output":"--- PASS: Test1 (0.00s)\n"}
0:00.117 {"Time":"2019-01-18T17:55:44.380281107Z","Action":"output","Package":"command-line-arguments","Test":"Test1/testx2","Output":"    --- PASS: Test1/testx2 (1.00s)\n"}
0:00.117 {"Time":"2019-01-18T17:55:44.380287211Z","Action":"pass","Package":"command-line-arguments","Test":"Test1/testx2","Elapsed":1}
0:00.117 {"Time":"2019-01-18T17:55:44.380292824Z","Action":"output","Package":"command-line-arguments","Test":"Test1/testx1","Output":"    --- PASS: Test1/testx1 (2.00s)\n"}
0:00.117 {"Time":"2019-01-18T17:55:44.380298591Z","Action":"pass","Package":"command-line-arguments","Test":"Test1/testx1","Elapsed":2}
0:00.117 {"Time":"2019-01-18T17:55:44.380303308Z","Action":"output","Package":"command-line-arguments","Test":"Test1/testx0","Output":"    --- PASS: Test1/testx0 (3.00s)\n"}
0:00.118 {"Time":"2019-01-18T17:55:44.380313673Z","Action":"pass","Package":"command-line-arguments","Test":"Test1/testx0","Elapsed":3}
0:00.118 {"Time":"2019-01-18T17:55:44.380318335Z","Action":"pass","Package":"command-line-arguments","Test":"Test1","Elapsed":0}
0:00.118 {"Time":"2019-01-18T17:55:44.380323168Z","Action":"output","Package":"command-line-arguments","Output":"PASS\n"}
0:00.118 {"Time":"2019-01-18T17:55:44.380328619Z","Action":"output","Package":"command-line-arguments","Output":"ok  \tcommand-line-arguments\t(cached)\n"}
0:00.118 {"Time":"2019-01-18T17:55:44.380336036Z","Action":"pass","Package":"command-line-arguments","Elapsed":0.001}

Note that the Test2 pass result is printed as soon as it passes, but all the other results are printed at the same time.

Although this might be a necessary restriction when running go test -v because of the way test output is indented, there doesn't seem to be a need for this restriction when the output is JSON.
@rogpeppe
Copy link
Contributor Author

Note that this is painful because it's not uncommon to gather many tests under a single umbrella. As one example, cmd/go has 139 script-based subtests under TestScript. Seeing progress when there is progress can be very useful, particularly when there's a danger of a test hanging up indefinitely.

@bcmills
Copy link
Contributor

bcmills commented Jan 22, 2019

This might be fixed by #24929.

I believe that the current implementation of go test -json parses the textual output of go test -v, so while the restriction is not required by the API it will be difficult to remove in practice.

@bcmills bcmills added ToolSpeed NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Jan 22, 2019
@bcmills bcmills added this to the Unplanned milestone Jan 22, 2019
@bcmills
Copy link
Contributor

bcmills commented Jan 22, 2019

Let's revisit this after #24929 lands.

@bcmills bcmills mentioned this issue Aug 1, 2019
Closed
@gopherbot
Copy link
Contributor

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. ToolSpeed
Projects
None yet
Milestone
Go1.20
Development

No branches or pull requests
4 participants
@rogpeppe @dmitshur @bcmills @gopherbot