go testing outputs wrong case names in json format under parallel mode

Question

go version: 1.18.1

suppose i wrote this test file parallel_test.go

package parallel_json_output

import (
    "fmt"
    "testing"
    "time"
)

func TestP(t *testing.T) {
    t.Run("a", func(t *testing.T) {
        t.Parallel()
        for i := 0; i < 5; i++ {
            time.Sleep(time.Second)
            fmt.Println("a", i)
        }
    })
    t.Run("b", func(t *testing.T) {
        t.Parallel()
        for i := 0; i < 5; i++ {
            time.Sleep(time.Second)
            fmt.Println("b", i)
        }
    })
}

after running go test parallel_test.go -v -json, i got

{"Time":"2022-06-11T02:48:10.3262833+08:00","Action":"run","Package":"command-line-arguments","Test":"TestP"}
{"Time":"2022-06-11T02:48:10.3672856+08:00","Action":"output","Package":"command-line-arguments","Test":"TestP","Output":"=== RUN   TestP\n"}
{"Time":"2022-06-11T02:48:10.3682857+08:00","Action":"run","Package":"command-line-arguments","Test":"TestP/a"}
{"Time":"2022-06-11T02:48:10.3682857+08:00","Action":"output","Package":"command-line-arguments","Test":"TestP/a","Output":"=== RUN   TestP/a\n"}
{"Time":"2022-06-11T02:48:10.3692857+08:00","Action":"output","Package":"command-line-arguments","Test":"TestP/a","Output":"=== PAUSE TestP/a\n"}
{"Time":"2022-06-11T02:48:10.3702858+08:00","Action":"pause","Package":"command-line-arguments","Test":"TestP/a"}
{"Time":"2022-06-11T02:48:10.3702858+08:00","Action":"run","Package":"command-line-arguments","Test":"TestP/b"}
{"Time":"2022-06-11T02:48:10.3712858+08:00","Action":"output","Package":"command-line-arguments","Test":"TestP/b","Output":"=== RUN   TestP/b\n"}
{"Time":"2022-06-11T02:48:10.3712858+08:00","Action":"output","Package":"command-line-arguments","Test":"TestP/b","Output":"=== PAUSE TestP/b\n"}
{"Time":"2022-06-11T02:48:10.3722859+08:00","Action":"pause","Package":"command-line-arguments","Test":"TestP/b"}
{"Time":"2022-06-11T02:48:10.373286+08:00","Action":"cont","Package":"command-line-arguments","Test":"TestP/a"}
{"Time":"2022-06-11T02:48:10.373286+08:00","Action":"output","Package":"command-line-arguments","Test":"TestP/a","Output":"=== CONT  TestP/a\n"}
{"Time":"2022-06-11T02:48:10.374286+08:00","Action":"cont","Package":"command-line-arguments","Test":"TestP/b"}
{"Time":"2022-06-11T02:48:10.374286+08:00","Action":"output","Package":"command-line-arguments","Test":"TestP/b","Output":"=== CONT  TestP/b\n"}
{"Time":"2022-06-11T02:48:11.3352891+08:00","Action":"output","Package":"command-line-arguments","Test":"TestP/b","Output":"b 0\n"}
{"Time":"2022-06-11T02:48:11.3352891+08:00","Action":"output","Package":"command-line-arguments","Test":"TestP/b","Output":"a 0\n"}
...

look at this line {"Time":"2022-06-11T02:48:11.3352891+08:00","Action":"output","Package":"command-line-arguments","Test":"TestP/b","Output":"a 0\n"}. this output should be printed by case TestP/a instead of b, but the output messed up the case name in parallel tests.

this problem made reporting tool generate wrong HTML report, IDEs (like GoLand) are effected too and cannot sort parallel output correctly.

i found an issue of it in Github here, but this issue seems had been fixed already in go 1.14.6, however, it still appears in go 1.18. i wonder what happend and how to deal with it, many thanks.

Answer 1

It makes sense that generic fmt package has little knowledge about currently executed tests in concurrent environment.

Testing package has its own Log method that correctly renders current test:

t.Log("a", i)