testing: streaming output loses parallel subtest associations

[rsc]

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).

[bcmills]

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

[rsc]

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)
$ 

[rsc]

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.

[ianlancetaylor]

This will change the work done for #24929

CC @jadekler @randall77

[mdwhatcott]

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.

[gopherbot]

Change https://golang.org/cl/229085 mentions this issue: testing: print === lines when subtests change output in parallel mode

[jeanbza]

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)

[rsc]

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?

[rsc]

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)

[jeanbza]

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. 👍