testing: summary and test output interleaved

[mattmoor]

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

>> go version
go version go1.14.6 linux/amd64

Does this issue reproduce with the latest release?

We haven't yet picked up 1.15, which cut like yesterday and it's an intermittent flake for us.

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

go env Output

>> go version
go version go1.14.6 linux/amd64

What did you do?

We are running our e2e tests with t.Parallel() and -v thru gotestsum.

What did you expect to see?

gotestsum uses test2json to parse the build log output, and I expect to see passing test results for all of the tests run.

What did you see instead?

Action: pass events are missing for typically 2 of the tests.

We were originally chasing this here (has links to richer logs): gotestyourself/gotestsum#141

To include some relevant context here, we see several test summaries that are interleaved with other output, which seems to trip up test2json. Here are three from a single run (3 diff API versions):

Normal (what you'd normally see):

--- PASS: TestContainerExitingMsg (0.01s)
    --- PASS: TestContainerExitingMsg/tcp (27.63s)
    --- PASS: TestContainerExitingMsg/http (160.37s)

Weird (interleaved, but surfaces events properly):

--- PASS: TestContainerExitingMsg (0.00s)
        + 				Message:            "Waiting for Envoys to receive Endpoints data.",
    --- PASS: TestContainerExitingMsg/http (179.23s)
          			},
          		},
          		Annotations: nil,
    --- PASS: TestContainerExitingMsg/tcp (194.07s)

Broken (interleaved with another test context switch, breaks things):

--- PASS: TestContainerExitingMsg (0.00s)
=== CONT  TestBlueGreenRoute
    kubelogs.go:201: I 01:01:58.381 webhook-98759d99-pfkgh [conversion/conversion.go:133] [serving-tests/blue-green-route-atsgeusz-q56cd] Converting [kind=Revision group=serving.knative.dev version=v1] to version serving.knative.dev/v1beta1
    --- PASS: TestContainerExitingMsg/http (49.33s)
    --- PASS: TestContainerExitingMsg/tcp (165.25s)

If I change the ordering of lines in this last section, I get the appropriate set of events.

[andybons]

@bcmills @matloob @jayconrod

[dnephin]

The test2json bug can be seen in these logs:

{"Time":"2020-08-11T01:03:41.641590332Z","Action":"output","Package":"knative.dev/serving/test/conformance/api/v1","Test":"TestContainerExitingMsg","Output":"--- PASS: TestContainerExitingMsg (0.00s)\n"}
{"Time":"2020-08-11T01:03:41.641597357Z","Action":"pass","Package":"knative.dev/serving/test/conformance/api/v1","Test":"TestContainerExitingMsg","Elapsed":0}
{"Time":"2020-08-11T01:03:41.641625254Z","Action":"output","Package":"knative.dev/serving/test/conformance/api/v1","Test":"TestBlueGreenRoute","Output":"    --- PASS: TestContainerExitingMsg/http (49.33s)\n"}
{"Time":"2020-08-11T01:03:41.641632549Z","Action":"output","Package":"knative.dev/serving/test/conformance/api/v1","Test":"TestBlueGreenRoute","Output":"    --- PASS: TestContainerExitingMsg/tcp (165.25s)\n"}

The --- PASS TestContainerExitingMsg output is attributed to TestBlueGreenRoute, and test2json does to create Action: pass events for those 2 subtests.

[mattmoor]

I actually suspect that the testing package has races related to the === markers.

Here's another strange interleaving I see, which ultimately leaves certain log lines under the incorrect heading:

=== CONT  TestSecretVolume             <-- Nothing logged wtf?
=== CONT  TestRevisionTimeout
    kubelogs.go:201: I 01:00:41.328 autoscaler-86d4bd9bcb-hvnt8 [kpa-class-podautoscaler-controller] [serving-tests/revision-timeout-when-b67b736422814c3736c90c658f29bd58-zwcnw8nw] Sleeping additionally for 57.671904984s before can scale to 0
    # These log lines actually belong to the first empty heading!
    kubelogs.go:201: I 01:00:49.594 webhook-98759d99-pfkgh [conversion/conversion.go:133] [serving-tests/secret-volume-dsivzkqq] Converting [kind=Route group=serving.knative.dev version=v1] to version serving.knative.dev/v1alpha1
    kubelogs.go:201: I 01:00:52.333 contour-ingress-controller-5dc846564f-jtmpz [controller/controller.go:520] [serving-tests/projected-secret-volume-erpaxwuw] Reconcile succeeded. Time taken: 31.082µs

Is there a way to disable the streaming interleaved output? If so, then we can probably mitigate many of this issues by simply throwing that in our CI setup.

[bcmills]

This is probably related to the fix for #39308, and thus also to #40657. (CC @jadekler)

[bcmills]

@mattmoor, the output in that last snippet does not look like a call to t.Logf. Was it written directly to os.Stdout or os.Stderr? (If so, the answer is “don't write to os.Stdout or os.Stderr in a parallel test if you want the output to associate correctly”.)

[mattmoor]

Should all be t.Logf: https://github.com/knative/pkg/blob/c9f9284521f197a17fcdbaf5c4360bef8ef8570d/test/logstream/kubelogs.go#L222

@bcmills @dnephin Is there any way to mitigate this?

Ideally we'd want the -v behavior prior to streaming, but I'd also consider/propose dropping -v in CI if that's the only way until this is fixed.

[mattmoor]

You may be looking at this formatting, but that's going through the logf: https://github.com/knative/pkg/blob/c9f9284521f197a17fcdbaf5c4360bef8ef8570d/test/logstream/kubelogs.go#L185

[mattmoor]

Switching to gotestsum's equivalent of "no -v" doesn't help, I suspect that's because -json is purely output based? 😞

[bcmills]

@mattmoor, are these t.Logf calls occurring after the test has already completed? (Is the --- PASS line actually chronologically misplaced, or is this more just a matter of missing === CONT headers?)

[mattmoor]

No, we stop calling t.Logf for a particular test when the cancel function is called, which is registered via t.Cleanup