testing: mark when parallel test begins running in output

[mvdan]

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

go version devel +d9270ecb3a Fri Feb 24 19:09:41 2017 +0000 linux/amd64

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

linux/amd64, doesn't matter really

What did you do?

Write a bunch of parallel subtests. Run them with different values of -parallel N.

package foo

import "testing"

func TestFoo(t *testing.T) {
        for _, s := range []string{
                "sub1", "sub2", "sub3", "sub4",
        } {
                t.Run(s, func(t *testing.T) {
                        t.Parallel()
                        println("output")
                })
        }
}

What did you expect to see?

$ go test -v
=== RUN   TestFoo
=== RUN   TestFoo/sub1
=== RUN   TestFoo/sub2
=== RUN   TestFoo/sub3
=== RUN   TestFoo/sub4
output
output
output
output
[...]
$ go test -v -parallel 1
=== RUN   TestFoo
=== RUN   TestFoo/sub1
output
=== RUN   TestFoo/sub2
output
=== RUN   TestFoo/sub3
output
=== RUN   TestFoo/sub4
output
[...]

What did you see instead?

Second command does not separate subtest outputs:

$ go test -v -parallel 1
=== RUN   TestFoo
=== RUN   TestFoo/sub1
=== RUN   TestFoo/sub2
=== RUN   TestFoo/sub3
=== RUN   TestFoo/sub4
output
output
output
output
[...]

I realise this example is very stupid, but the current behavior is confusing. -parallel does take effect, but go test prints all the === RUN lines at once regardless. It's hard to tell when each subtest actually starts executing.

And, for my particular problem, I can't tell what output is from what subtest with -parallel 1 since the outputs aren't delimited by each of their === RUN lines.

[josharian]

cc @mpvl

[mvdan]

Bump @mpvl? Happy to work on a patch, but first want to know if the current behaviour is on purpose - i.e. whether a patch would be welcome or not.

[magiconair]

This gets more confusing if your tests have sleeps:

package main

import (
	"log"
	"testing"
	"time"
)

func TestA(t *testing.T) {
	t.Parallel()
	for i := 0; i < 3; i++ {
		log.Println("A")
		time.Sleep(25 * time.Millisecond)
	}
}

func TestB(t *testing.T) {
	t.Parallel()
	for i := 0; i < 3; i++ {
		log.Println("B")
		time.Sleep(25 * time.Millisecond)
	}
}

Output:

$ go test -v -parallel 1
=== RUN   TestA
=== RUN   TestB
2017/04/27 13:17:21 A
2017/04/27 13:17:21 A
2017/04/27 13:17:21 A
2017/04/27 13:17:21 B <--- ???
--- PASS: TestA (0.09s)
2017/04/27 13:17:21 B
2017/04/27 13:17:21 B
--- PASS: TestB (0.08s)
PASS

[mpvl]

In order to see logging interleaved in a more structured way with test output, one would use t.Log, not println, log, or fmt.

If you don't use the logging facilities of the testing package, there is no guarantees and what you see is in the realm of the possible. If you increase the number of subtasks you'll see more interleaving of printing and RUN lines.

If you use t.Log, the logs will be grouped with the respective tests. In this case, tests collect the logs for this test and flush it to the parent on completion. Top-level tests flush to stdout.

That said. The particular order in which things are run is very finicky, but if you find an easy way to make this more like you expect you're welcome to try.

[magiconair]

@mpvl you are missing the point. The log output in the example does not come from the test but from the code that is tested. I've added it to demonstrate that tests which use t.Parallel() behave differently from tests that don't when used with -parallel 1 which I find surprising. When run with -parallel 1 the tests should behave the same way as when t.Parallel() wasn't there at all. Otherwise, tracing down test errors that stem from running tests in parallel require to comment out the t.Parallel() instead of just disabling it.

In my case, the example was that the last log line of an integration test was attributed to a different test which confused me because it didn't make sense. After commenting out t.Parallel() I noticed that I was chasing a ghost.

[mvdan]

My example above was perhaps misleading. My output came from the tested code too.

[mpvl]

Fair enough, I'll look into the issue. May take a bit, as I'm attending a summit at the moment.

[magiconair]

@mpvl Thank you.

[mpvl]

This is actually working as intended and an unfortunate consequence of the way t.Parallel works.

Firstly, note that the reported behavior is identical to the case if t.Parallel is called on a bunch of top-level tests.
In general:

• parallel tests are not run until the calling parent is run to completion (for top-level tests the parent is a hidden overarching main test).
• In this specific case it would even be illegal to run the parallel children before the parent has completed, because the parent is sequential.
• RUN is printed before the user-given test function is called.
• RUN cannot be printed after resuming from a call to Parallel, as 1) there may be output before such a call, and 2) it is not known if Parallel is known at all.

In other words, no matter what the parallelism is, or whether we are talking about top-level or subtests, it is pretty much guaranteed all RUNs are run before the parent test completes and that anything after t.Parallel in a subtest will be run after the parent completes.

Ideally, there would be no t.Parallel and we would use something like t.Go() instead. That way we could print RUN really when the user-given function is called.

So we can't fix RUN. What we could do, though, is to have another header that is printed after a test that was suspended by a call to Parallel is resumed. Something like:

=== RUN TestFoo
=== RUN TestFoo/sub1
=== RUN TestFoo/sub2
=== RUN TestFoo/sub3
=== RUN TestFoo/sub4
=== RESUME TestFoo/sub1
output
=== RESUME TestFoo/sub3
output
=== RESUME TestFoo/sub2
output
=== RESUME TestFoo/sub4
output
--- PASS: TestFoo (0.00s)
--- PASS: TestFoo/sub1 (0.00s)
--- PASS: TestFoo/sub3 (0.00s)
--- PASS: TestFoo/sub2 (0.00s)
--- PASS: TestFoo/sub4 (0.00s)
PASS
ok golang.org/x/text/foo 0.015s

The output would be the same regardless of whether -parallel=1 is passed or not.

Input welcome.

[magiconair]

I think what you are describing is a leaking implementation detail. When -parallel 1 is used the call to t.Parallel() should be ignored as if it isn't there at all. After that the two cases behave the same.