testing: testing Log functions do not capture timestamp

[vimalk78]

What version of Go are you using (go version)?

$ go version
go version go1.13.6 linux/amd64  

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (go env)?

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/vimalkum/.cache/go-build"
GOENV="/home/vimalkum/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/vimalkum/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build339334134=/tmp/go-build -gno-record-gcc-switches"

What did you do?

https://play.golang.org/p/525R1YDp8sB

Write a test case which calls t.Log or t.Logf
The output of these logs is generated when a test fails. If i am using a CI for testing, it makes my job much easier if i can correlate test log timestamps with other logs captured by CI

What did you expect to see?

The t.Log statements should produce timestamps.

What did you see instead?

No timestamps

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

[ianlancetaylor]

I don't think this is what most people want. You can add timestamps yourself to your t.Log calls if you want them.

[TomerYakir]

for what it's worth, I think it'd be a useful feature as well, for the same reason @vimalk78 provided.
It'd be cool if we had a t.SetPrefix function (similarly to how the log package implemented this)

[maansaake]

Agree, have always used timestamps and would rather not have a separate log package/include a TS snippet in each log statement.

[mvdan]

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:

--- FAIL: TestGetValue (1.50s)
    0.30s - main_test.go:9: this is log statement
    0.60s - main_test.go:11: this is error log statement
    0.90s - main_test.go:12: expected 100
FAIL
exit status 1
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):

# Verify that the go.mod files for both modules in the workspace are tidy,
# and add missing go.sum entries as needed. (0.032s)
> cp go.mod go.mod.orig
> go mod tidy
[...]
# Now remove the module dependencies from the module cache.
# Because one module upgrades a transitive dependency needed by another,
# listing the modules in the workspace should error out. (0.005s)
> go clean -modcache
> 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.

[mvdan]

For the record, my current workaround is:

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

The logs with go test -v show up like:

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

[bcmills]

For what it's worth, I added absolute timestamps to cmd/go script tests in CL 405714.

However, I only added a timestamp at the start of the run: the timestamp at the start combined with the running time of the test give a bounded window in which the events of the test occurred, which was all I really cared about for the purpose (diagnosing test failures caused by errors in non-hermetic external services).

[seankhliao]

I think #59928 with the writer passed to a logger would be a better fit