Test output not parsed well in Parallel

[ialcor-zz]

When many tests are launched in parallel the output of the test is lost most of the time. In fact it's assigned to the wrong test.

The parser iterates over every line of the Go test output, matching them against some regex to parse different info. The parsed info is assigned to the current test.

Current test (var cur string) is dynamically changed when lines containing === RUN {testName} or === CONT {testName} are found.

Example:

=== RUN   TestListAccessRight/list_wildcard
--- PASS: TestGetAccessRight (0.02s)
--- PASS: TestDeleteAccessRight (0.02s)
=== RUN   TestListAccessRight/list_wildcard_filter
=== RUN   TestCreateCardKey/update_mask_uid
--- PASS: TestListUser (0.03s)
    TestUpdateUser/update_mask_nil: user_test.go:330:
         got: name:"xxx/yyy/users/hope-clayton" first_name:"Jane" last_name:"Doe" display_name:"Jane Doe" email:"jane.doe@was.found" activate_time:{seconds:1596380613 nanos:316546000} expire_time:{seconds:1596380613 nanos:316546000}
         want: name:"xxx/zzz/users/hope-clayton" first_name:"Jane" last_name:"Doe" display_name:"Jane Doe" email:"jane.doe@was.found" activate_time:{seconds:1596380613 nanos:316546000} expire_time:{seconds:1596380613 nanos:316546000}
=== RUN   TestUpdateUser/update_mask_empty
--- PASS: TestCancelCardKey (0.02s)
=== RUN   TestUpdateCardKey/update_mask_nil
=== RUN   TestCreateCardKey/update_mask_empty
    TestUpdateUser/update_mask_empty: user_test.go:330:
         got: name:"xxx/yyy/users/hope-clayton" first_name:"Jane" last_name:"Doe" display_name:"Jane Doe" email:"jane.doe@was.found" activate_time:{seconds:1596380613 nanos:316546000} expire_time:{seconds:1596380613 nanos:316546000}
         want: name:"xxx/zzz/users/hope-clayton" first_name:"Jane" last_name:"Doe" display_name:"Jane Doe" email:"jane.doe@was.found" activate_time:{seconds:1596380613 nanos:316546000} expire_time:{seconds:1596380613 nanos:316546000}
=== RUN   TestUpdateUser/update_mask_paths_empty
=== RUN   TestUpdateCardKey/update_mask_empty

In the above example, you can see that output from TestUpdateUser/update_mask_nil is just after === RUN TestCreateCardKey/update_mask_empty and thus the output is assigned to that test.

[crockeo]

Hopping on this issue, I was hoping to use this tool at my company but couldn't roll it out because it didn't support parallel output. @jstemmer would you accept a PR for this before a 2.0 release? I'm going through the OSS contribution approval process right now but, assuming it gets approved, I'd love to contribute.

EDIT: My mistake! It looks like our issues may be coming from #123, and not this issue. I'm still happy to provide a PR but it'll be for #123 and not this.

[jstemmer]

There seem to have been some changes in the go test output since this bug was created, since I haven't been able to reproduce the behaviour where errors/logs are not preceded by the correct test name.

I believe version 2.0.0-beta1 should be able to properly handle parallel test output, give it a try. I'm closing this bug, but feel free to reopen if you think it's not behaving correctly.