测试包在测试完成后静默丢弃由goroutine生成的t.Log消息。例如,以下测试通过且不记录任何日志。这个问题应该通过扩展1.12版本中如果goroutine在测试完成后记录日志会引发panic的代码来修复,而不是静默丢弃日志消息。当前代码中出现静默丢弃是因为每个测试都在父上下文中运行,而父上下文累积的输出被丢弃了。
t.Log
vaj7vani1#
嘿,我尝试调查并编写了一个测试,并在我的分支中修改了testing.go的各个地方,如log和logDepth函数,并添加了调试语句(fmt.Fprintf(os.Stdout, "%s", string(s)))。但是日志从未运行过。我可能在这里犯了一个错误,但我猜想在TestLateLog函数退出后,t.output或t.parent的输出永远不会改变,刷新输出也从未有过要打印的内容。
testing.go
log
logDepth
fmt.Fprintf(os.Stdout, "%s", string(s))
TestLateLog
t.output
t.parent
func TestLateLogWrapper(t *testing.T) { testenv.MustHaveGoBuild(t) tempDir, err := ioutil.TempDir("", "issue-30389") if err != nil { t.Fatalf("Failed to create temp directory: %v", err) } defer os.RemoveAll(tempDir) code := ` package main import ( "testing" "time" "fmt" ) func TestLateLog(t *testing.T) { c := make(chan bool) go func(t *testing.T) { <-c time.Sleep(10*time.Millisecond) fmt.Printf("-> %v\n", t) t.Log("log after test") }(t) close(c) } ` destFile := filepath.Join(tempDir, "issue30389_test.go") if err := ioutil.WriteFile(destFile, []byte(code), 0644); err != nil { t.Fatalf("Failed to save test code: %v", err) } got, err := exec.Command(testenv.GoToolPath(t), "test", destFile).CombinedOutput() if err == nil { t.Fatal("The command unexpectedly passed") } want := []byte(`xxx`) if !bytes.HasPrefix(got, want) { t.Errorf("Did not print previous output\nGot:\n%s\n\nWant prefix:\n%s", got, want) } }
另一个让我感到疑惑的是,如果我们在以下内容之前添加一个panic,以通知用户这些信息将丢失(甚至用于调试特定情况下),parent.output = append(parent.output, parent.decorate(s, depth+1)...)是否有办法在没有tRunner的情况下检测到这是一个测试?
parent.output = append(parent.output, parent.decorate(s, depth+1)...)
tRunner
6ju8rftf2#
问题:Go中的测试包在测试完成后会静默丢弃由goroutine生成的"t.Log"消息。
我们为什么要担心这个问题:这种行为有时会导致遗漏重要的日志消息,使调试变得更加困难。
原因:这个问题出现是因为测试运行的父上下文会丢弃所有累积的输出。
解决方案:有两种方法可以解决这个问题:
package main import ( "bytes" "log" "testing" "time" ) func TestLateLog(t *testing.T) { c := make(chan bool) logOutput := bytes.Buffer{} logger := log.New(&logOutput, "", 0) // Create custom logger go func() { <-c time.Sleep(time.Millisecond) logger.Println("log after test") }() close(c) time.Sleep(10 * time.Millisecond) t.Log(logOutput.String()) }
来自goroutine的日志消息使用自定义的日志记录器(logger.Println)进行写入。在goroutine完成后,我们可以使用logOutput.String()从bytes.Buffer(logOutput)中访问收集到的日志消息,并使用t.Log显示它们。现在测试后的输出是:
=== RUN TestLateLog main_test.go:21: log after test --- PASS: TestLateLog (0.03s) PASS
package main import ( "io/ioutil" "log" "os" "testing" "time" ) func TestLateLog(t *testing.T) { c := make(chan bool) logFile, err := ioutil.TempFile("", "testlog-") // Temporary file if err != nil { t.Fatal(err) } defer func(name string) { err := os.Remove(name) if err != nil { } }(logFile.Name()) log.SetOutput(logFile) go func() { <-c time.Sleep(time.Millisecond) log.Println("log after test") }() close(c) time.Sleep(10 * time.Millisecond) logFile.Seek(0, 0) logData, _ := ioutil.ReadAll(logFile) t.Log(string(logData)) }
在goroutine完成后,我们使用seek将临时文件的指针移动到文件开头,然后读取所有的日志并使用t.log!第二种方法更快,但占用的内存比第一种方法多。如你所见,完成测试所需的时间比以前少:
=== RUN TestLateLog main_test.go:33: 2023/06/26 19:21:48 log after test --- PASS: TestLateLog (0.02s) PASS
现在有了这两种方法,即使测试已经完成,我们也可以显示日志!
2条答案
按热度按时间vaj7vani1#
嘿,
我尝试调查并编写了一个测试,并在我的分支中修改了
testing.go
的各个地方,如log
和logDepth
函数,并添加了调试语句(fmt.Fprintf(os.Stdout, "%s", string(s))
)。但是日志从未运行过。我可能在这里犯了一个错误,但我猜想在
TestLateLog
函数退出后,t.output
或t.parent
的输出永远不会改变,刷新输出也从未有过要打印的内容。另一个让我感到疑惑的是,如果我们在以下内容之前添加一个panic,以通知用户这些信息将丢失(甚至用于调试特定情况下),
parent.output = append(parent.output, parent.decorate(s, depth+1)...)
是否有办法在没有
tRunner
的情况下检测到这是一个测试?6ju8rftf2#
问题:Go中的测试包在测试完成后会静默丢弃由goroutine生成的"t.Log"消息。
我们为什么要担心这个问题:这种行为有时会导致遗漏重要的日志消息,使调试变得更加困难。
原因:这个问题出现是因为测试运行的父上下文会丢弃所有累积的输出。
解决方案:
有两种方法可以解决这个问题:
来自goroutine的日志消息使用自定义的日志记录器(logger.Println)进行写入。在goroutine完成后,我们可以使用logOutput.String()从bytes.Buffer(logOutput)中访问收集到的日志消息,并使用t.Log显示它们。
现在测试后的输出是:
在goroutine完成后,我们使用seek将临时文件的指针移动到文件开头,然后读取所有的日志并使用t.log!第二种方法更快,但占用的内存比第一种方法多。如你所见,完成测试所需的时间比以前少:
现在有了这两种方法,即使测试已经完成,我们也可以显示日志!