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.

What makes you believe the output should have a certain order given your prints are totally unsynchronised? — Volker, Jun 10 '22 at 21:26
the conclusion is, since logger / printer in inner labs are not awared from testing.T context, and we cannot calculate a goroutine's parent goroutine number, so it's impossible to hack / monkey patch the output of other libraries. the only way is passing testing.T context explicitally but not always possible in real projects — Rainy Chan, Jun 25 '22 at 00:38

score 1 · Accepted Answer · answered Jun 10 '22 at 20:00

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)

answered Jun 10 '22 at 20:00

Dmitry Harnitski

5,838
1
28
43

the problem is that some infra modules which log the output was shared by non-test packages, which cannot pass `testing.T` into their functions... – Rainy Chan Jun 11 '22 at 08:36
1

Tests should perform validation using assertions. CI should rely on test names and tests execution status. Logs are not a right way to communicate tests status. At most, they can be used for tests debugging. I suggest you to rewrite tests instead of fighting with logs parsing. – Dmitry Harnitski Jun 11 '22 at 13:46
1

nice, we are using go-test for automatic tests (system test). the background is we are writing a framework / tool to generate reports from CI tests. We do know accurate results of CI tests and assertions, but if there is a way to handle output / log better, the report will provide more useful info for troubleshooting. Currently we passed context to help a little, but in some integrations we cannot pass it deep inside SDK provided by other teams (in fact teamwork & management problem) – Rainy Chan Jun 11 '22 at 18:02

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

1 Answers1