parse outputs for garbled passes to avoid spurious failures

[MisterSquishy]

Implements this suggestion -- updates the execution to search output events for the PASS output string. It will then count those as pass events (if no true pass event is encountered). As per golang/go#26325, test2json occasionally has issues with interleaving stdout logs and test result logs, leading to output lines like

"Output":"[example.go--- PASS: TestExample (0.08s)\n"

The extra text in the output breaks test2json's ability to detect that this is in fact a pass, and as a result we get neither a pass nor fail event in the output json. With this change, we will still be able to count this as a pass.

[dnephin]

Thank you for the PR, and for your interest in fixing this problem!

I'm hoping this problem is fixed in the stdlib at some point. I think the solution proposed in golang/go#26325 (comment) would work quite well, and would be much easier to implement in test2json. That way the last "end event" will fix any problems with duplicate events.

It's possible that we can work around the problem in gotestsum, although I hope we can do so without a regex. We should be able to use similar logic to what test2json uses without the requirement of a newline. I'd have to look again, but I think it probably looks for the literal string --- PASS: Test, using something like strings.IndexOf, or strings.Cut.

Do you have examples of when you run into this problem? Is it developers forgetting to add a \n to log messages, or does something else cause the problem?

[dnephin]

One way to work around problems like this is to add something like this to any test setup functions:

t.Cleanup(func() {
    t.Log("\n")
})

As long as that is the last cleanup function to run, it should guarantee at least one trailing newline.

[MisterSquishy]

Do you have examples of when you run into this problem? Is it developers forgetting to add a \n to log messages, or does something else cause the problem?

I'm specifically encountering it in tests that have asynchronous processes logging shutdown messages at the same time that the test results are being logged. I've been looking for library-level fixes as opposed to test-level fixes, as the codebase has tens of thousands of tests.

I can take a stab at tackling golang/go#26325 (comment) in test2json instead!

[dnephin]

It sounds like https://go-review.googlesource.com/c/go/+/443596 has probably fixed the issue, and that fix should be in the next go release (go1.20).

Thank you for your work to get this issue fixed! I'm going to close this PR since we have a fix coming in the next Go release.