Go 1.18并行测试模式下JSON输出用例归属错误问题咨询

复现环境与现象 #

• Go版本：1.18.1
  编写测试文件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)
        }
    })
}

执行测试命令go test parallel_test.go -v -json后，输出存在归属错误，截取异常片段如下：

{"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"}

其中最后一行存在明确错误：内容a 0本是TestP/a的打印输出，却被错误标记为TestP/b的输出。这类问题会导致测试报告工具生成错误的统计结果，IDE也无法正确归类并行测试的输出内容。此前官方问题追踪记录曾标注该问题在Go 1.14.6版本修复，但Go 1.18版本下仍可复现。

问题成因 #

该问题的本质是测试框架输出拦截逻辑的竞态缺陷：

1. Go 1.14.6版本的修复仅覆盖了测试框架内置的t.Log/t.Logf打印接口，这类接口输出时会绑定当前调用的测试实例对象，不会出现归属错误。
2. 对于代码直接调用fmt.Println等方法写入进程标准输出的内容，测试框架是通过替换stdout文件描述符、统一读取管道内容的方式做JSON包装的。在1.19版本之前，框架读取到管道内容后，是通过全局变量记录的“当前正在运行的测试”来标记输出归属的，这个全局变量没有做协程隔离，多个并行测试同时运行时，协程调度顺序和全局变量更新时机存在竞态，就会出现把A测试的输出挂到B测试名下的问题。

解决办法 #

• 规范测试日志写法：测试代码里的日志打印统一使用t.Log/t.Logf接口，不要直接调用fmt包往标准输出写日志。这类接口输出和测试实例强绑定，不存在串流问题，同时默认仅在测试失败或加-v参数时展示，更符合测试日志的使用习惯。
• 升级Go版本：升级到Go 1.19及以上版本，新版本给每个并行测试单独分配了独立的输出拦截管道，从根源上解决了标准输出串流标记错误的问题。
• 临时规避：如果暂时无法升级Go版本、也不方便改造现有测试代码，可以在执行测试时加-parallel 1参数关闭测试并行执行能力，串行执行时不会出现全局测试标记的竞态切换，输出归属完全准确，缺点是会拉长整体测试执行时间。

内容的提问来源于stack exchange，提问作者Rainy Chan