testing: streaming output loses parallel subtest associations
rsc opened this issue · 32 comments
Normal go test prints output like this for parallel subtests:
$ go test -run=Testdata/MIT
--- FAIL: TestTestdata (0.51s)
--- FAIL: TestTestdata/MIT-0.t1 (0.00s)
license_test.go:138: testdata/MIT-0.t1:1,3: diff -want +have:
- 93.5%
+ 97.4%
- MIT-0 100.0% 74,$
+ MIT-0 100.0% 26,$
--- FAIL: TestTestdata/MIT-0.t2 (0.00s)
license_test.go:138: testdata/MIT-0.t2:2,4: diff -want +have:
- 100.0%
+ 0.0%
- MIT-0 100.0% 0,$
--- FAIL: TestTestdata/MIT.t3 (0.00s)
license_test.go:138: testdata/MIT.t3:2,4: diff -want +have:
- 100.0%
+ 0.0%
- MIT 95.8% 0,$
--- FAIL: TestTestdata/MIT-Header.t1 (0.00s)
license_test.go:138: testdata/MIT-Header.t1:1,3: diff -want +have:
- 86.9%
+ 0.0%
- MIT-Header 100.0% 83,$
FAIL
My memory is that we made a change to try to print output earlier for -v, but this is completely breaking the output for parallel subtests. There is no obvious way to tell which test printed:
$ go test -v -run=Testdata/MIT
=== RUN TestTestdata
=== RUN TestTestdata/MIT-0.t1
=== PAUSE TestTestdata/MIT-0.t1
=== RUN TestTestdata/MIT-0.t2
=== PAUSE TestTestdata/MIT-0.t2
=== RUN TestTestdata/MIT-Header.t1
=== PAUSE TestTestdata/MIT-Header.t1
=== RUN TestTestdata/MIT.t1
=== PAUSE TestTestdata/MIT.t1
=== RUN TestTestdata/MIT.t2
=== PAUSE TestTestdata/MIT.t2
=== RUN TestTestdata/MIT.t3
=== PAUSE TestTestdata/MIT.t3
=== CONT TestTestdata/MIT-0.t1
=== CONT TestTestdata/MIT.t1
=== CONT TestTestdata/MIT-0.t2
=== CONT TestTestdata/MIT.t3
=== CONT TestTestdata/MIT.t2
=== CONT TestTestdata/MIT-Header.t1
TestTestdata/MIT-0.t1: license_test.go:138: testdata/MIT-0.t1:1,3: diff -want +have:
- 93.5%
+ 97.4%
- MIT-0 100.0% 74,$
+ MIT-0 100.0% 26,$
TestTestdata/MIT-0.t2: license_test.go:138: testdata/MIT-0.t2:2,4: diff -want +have:
- 100.0%
+ 0.0%
- MIT-0 100.0% 0,$
TestTestdata/MIT.t3: license_test.go:138: testdata/MIT.t3:2,4: diff -want +have:
- 100.0%
+ 0.0%
- MIT 95.8% 0,$
TestTestdata/MIT-Header.t1: license_test.go:138: testdata/MIT-Header.t1:1,3: diff -want +have:
- 86.9%
+ 0.0%
- MIT-Header 100.0% 83,$
--- FAIL: TestTestdata (0.52s)
--- FAIL: TestTestdata/MIT-0.t1 (0.00s)
--- FAIL: TestTestdata/MIT-0.t2 (0.00s)
--- PASS: TestTestdata/MIT.t1 (0.00s)
--- PASS: TestTestdata/MIT.t2 (0.00s)
--- FAIL: TestTestdata/MIT.t3 (0.00s)
--- FAIL: TestTestdata/MIT-Header.t1 (0.00s)
FAIL
In this case, the subtest name happens to be echoed in the message, but that's because of a print in the test; the testing framework has failed at its job and omitted the information.
In contrast, here is Go 1.12:
$ go1.12 test -run=Testdata/MIT -v
=== RUN TestTestdata
=== RUN TestTestdata/MIT-0.t1
=== PAUSE TestTestdata/MIT-0.t1
=== RUN TestTestdata/MIT-0.t2
=== PAUSE TestTestdata/MIT-0.t2
=== RUN TestTestdata/MIT-Header.t1
=== PAUSE TestTestdata/MIT-Header.t1
=== RUN TestTestdata/MIT.t1
=== PAUSE TestTestdata/MIT.t1
=== RUN TestTestdata/MIT.t2
=== PAUSE TestTestdata/MIT.t2
=== RUN TestTestdata/MIT.t3
=== PAUSE TestTestdata/MIT.t3
=== CONT TestTestdata/MIT-0.t1
=== CONT TestTestdata/MIT.t1
=== CONT TestTestdata/MIT.t2
=== CONT TestTestdata/MIT-Header.t1
=== CONT TestTestdata/MIT-0.t2
=== CONT TestTestdata/MIT.t3
--- FAIL: TestTestdata (0.57s)
--- PASS: TestTestdata/MIT.t1 (0.00s)
--- FAIL: TestTestdata/MIT-0.t1 (0.00s)
license_test.go:138: testdata/MIT-0.t1:1,3: diff -want +have:
- 93.5%
+ 97.4%
- MIT-0 100.0% 74,$
+ MIT-0 100.0% 26,$
--- PASS: TestTestdata/MIT.t2 (0.00s)
--- FAIL: TestTestdata/MIT-Header.t1 (0.00s)
license_test.go:138: testdata/MIT-Header.t1:1,3: diff -want +have:
- 86.9%
+ 0.0%
- MIT-Header 100.0% 83,$
--- FAIL: TestTestdata/MIT.t3 (0.00s)
license_test.go:138: testdata/MIT.t3:2,4: diff -want +have:
- 100.0%
+ 0.0%
- MIT 95.8% 0,$
--- FAIL: TestTestdata/MIT-0.t2 (0.00s)
license_test.go:138: testdata/MIT-0.t2:2,4: diff -want +have:
- 100.0%
+ 0.0%
- MIT-0 100.0% 0,$
FAIL
exit status 1
FAIL github.com/google/licensecheck 0.882s
$
And here is current go with the t.Parallel call commented out:
$ go test -run=Testdata/MIT -v
=== RUN TestTestdata
=== RUN TestTestdata/MIT-0.t1
TestTestdata/MIT-0.t1: license_test.go:138: testdata/MIT-0.t1:1,3: diff -want +have:
- 93.5%
+ 97.4%
- MIT-0 100.0% 74,$
+ MIT-0 100.0% 26,$
=== RUN TestTestdata/MIT-0.t2
TestTestdata/MIT-0.t2: license_test.go:138: testdata/MIT-0.t2:2,4: diff -want +have:
- 100.0%
+ 0.0%
- MIT-0 100.0% 0,$
=== RUN TestTestdata/MIT-Header.t1
TestTestdata/MIT-Header.t1: license_test.go:138: testdata/MIT-Header.t1:1,3: diff -want +have:
- 86.9%
+ 0.0%
- MIT-Header 100.0% 83,$
=== RUN TestTestdata/MIT.t1
=== RUN TestTestdata/MIT.t2
=== RUN TestTestdata/MIT.t3
TestTestdata/MIT.t3: license_test.go:138: testdata/MIT.t3:2,4: diff -want +have:
- 100.0%
+ 0.0%
- MIT 95.8% 0,$
--- FAIL: TestTestdata (0.54s)
--- FAIL: TestTestdata/MIT-0.t1 (0.00s)
--- FAIL: TestTestdata/MIT-0.t2 (0.00s)
--- FAIL: TestTestdata/MIT-Header.t1 (0.00s)
--- PASS: TestTestdata/MIT.t1 (0.00s)
--- PASS: TestTestdata/MIT.t2 (0.00s)
--- FAIL: TestTestdata/MIT.t3 (0.00s)
FAIL
$
Rolling back the change for parallel subtests would be unfortunate, since it would make the output placement dependent on use of t.Parallel. (It's already unfortunate that the output placement is dependent on -v but that ship has sailed.)
Perhaps the best fix would be to print a new === CONT line each time the test generating output changes (before the output).
Isn't the TestTestdata/MIT-0.t1: prefix in the parallel output the full subtest path?
TestTestdata/MIT-0.t1: license_test.go:138: testdata/MIT-0.t1:1,3: ↑ subtest name ↑ source location ↑ start of user-generated message
I didn't notice the prefix. Having that prefix on every line is pretty noisy. It's turned the output into something that requires a machine to read. I think we should change this output again. I know we just did in Go 1.14, but the current output is simply not human-friendly. The prefix is stuttering, and "file:line:" should always be at the start of a line.
$ cat x_test.go
package main
import "testing"
func Test(t *testing.T) {
for i := 0; i < 10; i++ {
t.Log(i, "->\n", i)
}
}
$ go test -v x_test.go
=== RUN Test
Test: x_test.go:7: 0 ->
0
Test: x_test.go:7: 1 ->
1
Test: x_test.go:7: 2 ->
2
Test: x_test.go:7: 3 ->
3
Test: x_test.go:7: 4 ->
4
Test: x_test.go:7: 5 ->
5
Test: x_test.go:7: 6 ->
6
Test: x_test.go:7: 7 ->
7
Test: x_test.go:7: 8 ->
8
Test: x_test.go:7: 9 ->
9
--- PASS: Test (0.00s)
PASS
ok command-line-arguments 0.075s
$ go1.12 test -v x_test.go
=== RUN Test
--- PASS: Test (0.00s)
x_test.go:7: 0 ->
0
x_test.go:7: 1 ->
1
x_test.go:7: 2 ->
2
x_test.go:7: 3 ->
3
x_test.go:7: 4 ->
4
x_test.go:7: 5 ->
5
x_test.go:7: 6 ->
6
x_test.go:7: 7 ->
7
x_test.go:7: 8 ->
8
x_test.go:7: 9 ->
9
PASS
ok command-line-arguments (cached)
$
Let's replace the prefix with tracking what test name has been printed in an === line most recently, and print a new === line if needed to change the "currently printing" test.
This will change the work done for #24929
CC @jadekler @randall77
One consequence of #24929 (streaming t.Log output) is that test2json wasn't updated with any understanding of streaming output and how it would affect parallel subtests. FWIW, PR #38189 (for issue #38050) attempts to correct that oversight. This comment is a friendly reminder to include the test2json utility in whatever changes result from this issue.
Change https://golang.org/cl/229085 mentions this issue: testing: print === lines when subtests change output in parallel mode
I spent time looking into this today, and am working on a cl that implements @rsc's suggestion: https://go-review.googlesource.com/c/go/+/229085. Russ, your solution seems reasonable. Here's what that looks like:
Before
$ go test . -v
=== RUN TestFoo
=== RUN TestFoo/SubTest-2
TestFoo/SubTest-2: foo_test.go:23: This is a t.Log from sub-2 (message-0)
TestFoo/SubTest-2: foo_test.go:23: This is a t.Log from sub-2 (message-1)
=== RUN TestFoo/SubTest-0
TestFoo/SubTest-0: foo_test.go:23: This is a t.Log from sub-0 (message-0)
=== RUN TestFoo/SubTest-1
TestFoo/SubTest-1: foo_test.go:23: This is a t.Log from sub-1 (message-0)
TestFoo/SubTest-2: foo_test.go:23: This is a t.Log from sub-2 (message-2)
TestFoo/SubTest-0: foo_test.go:23: This is a t.Log from sub-0 (message-1)
TestFoo/SubTest-2: foo_test.go:23: This is a t.Log from sub-2 (message-3)
TestFoo/SubTest-0: foo_test.go:23: This is a t.Log from sub-0 (message-2)
TestFoo/SubTest-1: foo_test.go:23: This is a t.Log from sub-1 (message-1)
TestFoo/SubTest-2: foo_test.go:23: This is a t.Log from sub-2 (message-4)
TestFoo/SubTest-1: foo_test.go:23: This is a t.Log from sub-1 (message-2)
TestFoo/SubTest-1: foo_test.go:23: This is a t.Log from sub-1 (message-3)
TestFoo/SubTest-0: foo_test.go:23: This is a t.Log from sub-0 (message-3)
TestFoo/SubTest-1: foo_test.go:23: This is a t.Log from sub-1 (message-4)
TestFoo/SubTest-0: foo_test.go:23: This is a t.Log from sub-0 (message-4)
--- PASS: TestFoo (0.00s)
--- PASS: TestFoo/SubTest-2 (0.00s)
--- PASS: TestFoo/SubTest-1 (0.00s)
--- PASS: TestFoo/SubTest-0 (0.00s)
After
=== RUN TestName
=== RUN TestName/SubTest-2
sub_test.go:571: This is a t.Log from sub-2 (message-0)
sub_test.go:571: This is a t.Log from sub-2 (message-1)
=== RUN TestName/SubTest-0
=== RUN TestName/SubTest-1
=== TestName/SubTest-0
sub_test.go:571: This is a t.Log from sub-0 (message-0)
=== TestName/SubTest-1
sub_test.go:571: This is a t.Log from sub-1 (message-0)
=== TestName/SubTest-2
sub_test.go:571: This is a t.Log from sub-2 (message-2)
=== TestName/SubTest-0
sub_test.go:571: This is a t.Log from sub-0 (message-1)
sub_test.go:571: This is a t.Log from sub-0 (message-2)
=== TestName/SubTest-1
sub_test.go:571: This is a t.Log from sub-1 (message-1)
=== TestName/SubTest-0
sub_test.go:571: This is a t.Log from sub-0 (message-3)
=== TestName/SubTest-2
sub_test.go:571: This is a t.Log from sub-2 (message-3)
=== TestName/SubTest-1
sub_test.go:571: This is a t.Log from sub-1 (message-2)
sub_test.go:571: This is a t.Log from sub-1 (message-3)
sub_test.go:571: This is a t.Log from sub-1 (message-4)
=== TestName/SubTest-2
sub_test.go:571: This is a t.Log from sub-2 (message-4)
=== TestName/SubTest-0
sub_test.go:571: This is a t.Log from sub-0 (message-4)
--- PASS: TestName (0.00s)
--- PASS: TestName/SubTest-1 (0.00s)
--- PASS: TestName/SubTest-2 (0.00s)
Does this look right? As you can see, it's quite a bit more chatty when there's a high degree of interleaving, which could be a bummer. On the other hand, it does separate subtests better.
If so, happy to continue on that CL and figure out a real way to implement this, instead of my hacky way. 🙂 (I also figured out a better way to capture and test subtest output, so minimally I'd like to get that into the testsuite)
The indented === lines look wrong. They have no verb and they are indented.
Also, how is it even possible to be running multiple tests without a === PAUSE line?
OK, I looked at the CL test. Starting a subtest inside a kicked-off goroutine is non-standard to say the least. The important part is that the output should not require any changes to test2json. Test2json expects === lines to be unindented and contain a verb. The obvious verb here is "CONT" for continue, so that no new verb is needed either.
Instead of introducing the output redirect in package testing, I'd rather see a test script in cmd/go, testing both go test -v and go test -json. Then the diff should be very small.
That is, I think the output should be:
=== RUN TestName
=== RUN TestName/SubTest-2
sub_test.go:571: This is a t.Log from sub-2 (message-0)
sub_test.go:571: This is a t.Log from sub-2 (message-1)
=== RUN TestName/SubTest-0
=== RUN TestName/SubTest-1
=== CONT TestName/SubTest-0
sub_test.go:571: This is a t.Log from sub-0 (message-0)
=== CONT TestName/SubTest-1
sub_test.go:571: This is a t.Log from sub-1 (message-0)
=== CONT TestName/SubTest-2
sub_test.go:571: This is a t.Log from sub-2 (message-2)
=== CONT TestName/SubTest-0
sub_test.go:571: This is a t.Log from sub-0 (message-1)
sub_test.go:571: This is a t.Log from sub-0 (message-2)
=== CONT TestName/SubTest-1
sub_test.go:571: This is a t.Log from sub-1 (message-1)
=== CONT TestName/SubTest-0
sub_test.go:571: This is a t.Log from sub-0 (message-3)
=== CONT TestName/SubTest-2
sub_test.go:571: This is a t.Log from sub-2 (message-3)
=== CONT TestName/SubTest-1
sub_test.go:571: This is a t.Log from sub-1 (message-2)
sub_test.go:571: This is a t.Log from sub-1 (message-3)
sub_test.go:571: This is a t.Log from sub-1 (message-4)
=== CONT TestName/SubTest-2
sub_test.go:571: This is a t.Log from sub-2 (message-4)
=== CONT TestName/SubTest-0
sub_test.go:571: This is a t.Log from sub-0 (message-4)
--- PASS: TestName (0.00s)
--- PASS: TestName/SubTest-1 (0.00s)
--- PASS: TestName/SubTest-2 (0.00s)
Starting a subtest inside a kicked-off goroutine is non-standard to say the least.
t.Parallel was blocking for some reason, so after some investigation I threw my hands up and went with the easy out to get at what I wanted. And, it was a prototype CL, so wasn't too concerned. But good to know that's unexpected for future tests!
Instead of introducing the output redirect in package testing, I'd rather see a test script in cmd/go, testing both go test -v and go test -json. Then the diff should be very small.
SG, thanks for the direction! That helps me orient.
That is, I think the output should be:
SG, thanks for the output. I'll work on updating the CL. 👍
I've updated https://go-review.googlesource.com/c/go/+/229085:
- I've put the test in cmd/go/testdata/script. (still need a benchmark test, and a -json test)
- I've updated the implementation to work correctly when FAIL and PASS occurs.
- I've removed some of the old prototype stuff.
I'm not in love with the solution, though. It seems not-great to lock, record, and unlock everywhere we print. That seems like something that's easy to forget to do in the future. I explored adding a writer that keeps track of the test name on all outgoing writes, but quickly realized it would have to interpolate each outgoing line to figure out test name (no way to pass test name through io.Writer.Write AFAICT), which doesn't seem great.
Would love thoughts if there's a better approach. (also on anything else, but particularly that)
I explored adding a writer that keeps track of the test name on all outgoing writes, but quickly realized it would have to interpolate each outgoing line to figure out test name (no way to pass test name through io.Writer.Write AFAICT), which doesn't seem great.
Don't do it as a generic Writer. Could you implement it as a method that takes a prefix, name, suffix format, and suffix args?
Don't do it as a generic Writer
Done. I've created a non-io.Writer writer (called testPrinter).
that takes a prefix
What would a prefix look like? Something like mytest.go:17?
name
Done.
suffix format, and suffix args
I've just used fmt.Sprintf at the call site. Is that bad? Should I have Fprintf and Printf methods?
Change https://golang.org/cl/232157 mentions this issue: testing: reformat test chatty output
Change https://golang.org/cl/232157 mentions this issue:
testing: reformat test chatty output
Ignore this, bad mail :)
I’ll add the release blocker label for Go1.15.
@jadekler (and anyone else): Checking in on the status of this as an issue blocking the Go 1.15 beta.
@toothrot AFAICT this is ready, just waiting for a +2. I have a +1 from bcmills already.
@gopherbot, please backport to Go 1.14: the 1.14 output format breaks go test -json for parallel subtests, and backporting the fix to the output format is likely to be more maintainable than a one-off test2json fix that is only used for the 1.14 branch.
Backport issue(s) opened: #39308 (for 1.14).
Remember to create the cherry-pick CL(s) as soon as the patch is submitted to master, according to https://golang.org/wiki/MinorReleases.
@jadekler, I noticed some awkwardness remaining with this fix using gotip. The --- PASS lines for one test may interrupt the output lines of another, without emitting another === CONT line, and then as a reader it's a bit difficult to figure out which test emitted the line immediately after the --- PASS.
Ack - sounds like some test cases missing. Could you show some output? Bonus: if you have a test on hand that demonstrates this, that'd be nice too. :)
@jadekler, I'm not sure how to do it without a time.Sleep, but https://play.golang.org/p/1zo6hpethfQ reproduces it reliably for me.
$ go version
go version devel +8f4151ea Thu May 28 22:48:53 2020 +0000 linux/amd64
$ go test -v ./main_test.go
=== RUN TestFast
=== PAUSE TestFast
=== RUN TestSlow
=== PAUSE TestSlow
=== CONT TestFast
=== CONT TestSlow
main_test.go:26: Once begun...
--- PASS: TestFast (0.00s)
main_test.go:31: ...is half done.
--- PASS: TestSlow (0.10s)
PASS
ok command-line-arguments 0.116s
Change https://golang.org/cl/241660 mentions this issue: doc/go1.15: add line for testing streaming change
Change https://golang.org/cl/242058 mentions this issue: [release-branch.go1.14] testing: capture testname on --- PASS and --- FAIL lines
Change https://golang.org/cl/242057 mentions this issue: [release-branch.go1.14] testing: reformat test chatty output
Change https://golang.org/cl/242059 mentions this issue: [release-branch.go1.14] cmd/go: fix parallel chatty tests on solaris-amd64 builder
Change https://golang.org/cl/249026 mentions this issue: testing: flush test summaries to stdout atomically when streaming output
Change https://golang.org/cl/252637 mentions this issue: [release-branch.go1.15] testing: flush test summaries to stdout atomically when streaming output
Change https://golang.org/cl/252638 mentions this issue: [release-branch.go1.14] testing: flush test summaries to stdout atomically when streaming output