go 测试: 测试日志功能无法捕获时间戳

fcy6dtqo  于 9个月前  发布在  Go
关注(0)|答案(6)|浏览(148)

你正在使用的Go版本是什么( go version )?

  1. $ go version
  2. go version go1.13.6 linux/amd64

这个问题在最新版本中是否重现?

是的

你正在使用什么操作系统和处理器架构( go env )?

go env 输出

  1. $ go env
  2. GO111MODULE=""
  3. GOARCH="amd64"
  4. GOBIN=""
  5. GOCACHE="/home/vimalkum/.cache/go-build"
  6. GOENV="/home/vimalkum/.config/go/env"
  7. GOEXE=""
  8. GOFLAGS=""
  9. GOHOSTARCH="amd64"
  10. GOHOSTOS="linux"
  11. GONOPROXY=""
  12. GONOSUMDB=""
  13. GOOS="linux"
  14. GOPATH="/home/vimalkum/go"
  15. GOPRIVATE=""
  16. GOPROXY="https://proxy.golang.org,direct"
  17. GOROOT="/usr/local/go"
  18. GOSUMDB="sum.golang.org"
  19. GOTMPDIR=""
  20. GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
  21. GCCGO="gccgo"
  22. AR="ar"
  23. CC="gcc"
  24. CXX="g++"
  25. CGO_ENABLED="1"
  26. GOMOD=""
  27. CGO_CFLAGS="-g -O2"
  28. CGO_CPPFLAGS=""
  29. CGO_CXXFLAGS="-g -O2"
  30. CGO_FFLAGS="-g -O2"
  31. CGO_LDFLAGS="-g -O2"
  32. PKG_CONFIG="pkg-config"
  33. GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build339334134=/tmp/go-build -gno-record-gcc-switches"

你做了什么?

https://play.golang.org/p/525R1YDp8sB
编写一个调用 t.Logt.Logf 的测试用例。当测试失败时,这些日志的输出会生成。如果我正在使用CI进行测试,如果能够将测试日志时间戳与其他由CI捕获的日志相关联,那么我的工作会容易得多。

你期望看到什么?

t.Log语句应该产生时间戳。

你看到了什么?

没有时间戳

  1. 2020/01/20 21:15:05 GetValue called
  2. --- FAIL: TestGetValue (0.00s)
  3. main_test.go:9: this is log statement
  4. main_test.go:11: this is error log statement
  5. main_test.go:12: expected 100
  6. FAIL
  7. exit status 1
  8. FAIL github.com/vimalk78/test-testing 0.001s
7y4bm7vi

7y4bm7vi1#

我认为这不是大多数人想要的。如果你需要,你可以自己在你的t.Log通话中添加时间戳。

2nbm6dog

2nbm6dog2#

就其价值而言,我认为这也是一个有用的功能,原因与@vimalk78提供的原因相同。如果我们有一个t.SetPrefix函数(类似于log包实现的方式),那将很酷。

pb3skfrl

pb3skfrl3#

同意,一直使用时间戳,并宁愿不要单独的日志包/在每个日志语句中包含一个TS片段。

vojdkbi0

vojdkbi04#

I personally think this would be nice by default; most of the output from go test already includes relative timestamps, like how long a test ran for, or how long the entire package took to test. Here's an example of how relative timestamps on logs could look like:

  1. --- FAIL: TestGetValue (1.50s)
  2. 0.30s - main_test.go:9: this is log statement
  3. 0.60s - main_test.go:11: this is error log statement
  4. 0.90s - main_test.go:12: expected 100
  5. FAIL
  6. exit status 1
  7. FAIL github.com/vimalk78/test-testing 1.600s

cmd/go's TestScript does something similar; each section of a test script has a comment, and the output includes how long that section took to run (cc @bcmills):

  1. # Verify that the go.mod files for both modules in the workspace are tidy,
  2. # and add missing go.sum entries as needed. (0.032s)
  3. > cp go.mod go.mod.orig
  4. > go mod tidy
  5. [...]
  6. # Now remove the module dependencies from the module cache.
  7. # Because one module upgrades a transitive dependency needed by another,
  8. # listing the modules in the workspace should error out. (0.005s)
  9. > go clean -modcache
  10. > env GOPROXY=off

When I write long tests in Go, such as integration tests, I often want similar timestamps or durations to be able to tell what's taking most of the time. It's also useful with go test -v -run OneTest , so that the logs being streamed out can give a better idea of how the time is being spent.
Like @ianlancetaylor says, I can always add timestamps or elapsed durations to log calls myself, though at this point I've done that in a handful of different places, and I don't see a reason why we shouldn't do it by default :) I reckon I would generally find this useful for any test which takes more than a tens of milliseconds and prints a few logs.
Worth noting that, with go test -json , log lines get printed as "output" actions with a timestamp, but that's not very friendly for humans.

展开查看全部
kgqe7b3p

kgqe7b3p5#

为了记录,我目前的解决方法是:

  1. func TestFoo(t *testing.T) {
  2. start := time.Now()
  3. logf := func(format string, args ...any) {
  4. t.Logf("%.2fs: "+format, append([]any{time.Since(start).Seconds()}, args...)...)
  5. }
  6. [...]
  7. logf("cloning %s", ghSourceRepo)

带有 go test -v 的日志显示如下:

  1. === RUN TestFoo
  2. foo_test.go:34: 0.00s: cloning mvdan/test-repo
  3. foo_test.go:34: 0.86s: committing a new file
  4. foo_test.go:34: 0.86s: pushing to mvdan/test-repo
wfauudbj

wfauudbj6#

就其价值而言,我在CL 405714中的cmd/go脚本测试中添加了绝对时间戳。然而,我只在运行开始时添加了一个时间戳:开始时的时间戳与测试的运行时间相结合,给出了一个有界的窗口,其中测试的事件发生,这是我真正关心的目的(诊断由非一致外部服务中的错误引起的测试失败)。

相关问题