测试:在测试完成后,丢失了在一个goroutine中创建的日志消息,

avwztpqn  于 3个月前  发布在  Go
关注(0)|答案(2)|浏览(24)

测试包在测试完成后静默丢弃由goroutine生成的t.Log消息。例如,以下测试通过且不记录任何日志。
这个问题应该通过扩展1.12版本中如果goroutine在测试完成后记录日志会引发panic的代码来修复,而不是静默丢弃日志消息。当前代码中出现静默丢弃是因为每个测试都在父上下文中运行,而父上下文累积的输出被丢弃了。

vaj7vani

vaj7vani1#

嘿,
我尝试调查并编写了一个测试,并在我的分支中修改了testing.go的各个地方,如loglogDepth函数,并添加了调试语句(fmt.Fprintf(os.Stdout, "%s", string(s)))。但是日志从未运行过。
我可能在这里犯了一个错误,但我猜想在TestLateLog函数退出后,t.outputt.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的情况下检测到这是一个测试?

6ju8rftf

6ju8rftf2#

问题:Go中的测试包在测试完成后会静默丢弃由goroutine生成的"t.Log"消息。

我们为什么要担心这个问题:这种行为有时会导致遗漏重要的日志消息,使调试变得更加困难。

原因:这个问题出现是因为测试运行的父上下文会丢弃所有累积的输出。

解决方案:
有两种方法可以解决这个问题:

  1. 为了捕获并显示测试完成后来自goroutine的日志消息,你可以创建一个自定义的日志记录器,并手动收集日志消息。
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
  1. 另一种方法是创建一个临时文件来捕获日志消息。
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

现在有了这两种方法,即使测试已经完成,我们也可以显示日志!

相关问题