Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

testing: testing Log functions do not capture timestamp #36656

Open
vimalk78 opened this issue Jan 20, 2020 · 6 comments
Open

testing: testing Log functions do not capture timestamp #36656

vimalk78 opened this issue Jan 20, 2020 · 6 comments
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone

Comments

@vimalk78
Copy link

vimalk78 commented Jan 20, 2020

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
Copy link
Contributor

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

@toothrot toothrot added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Jan 21, 2020
@toothrot toothrot added this to the Backlog milestone Jan 21, 2020
@TomerYakir
Copy link

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)

@maansthoernvik
Copy link

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

@mvdan
Copy link
Member

mvdan commented Dec 1, 2022

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
Copy link
Member

mvdan commented Dec 1, 2022

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
Copy link
Contributor

bcmills commented Dec 6, 2022

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).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Development

No branches or pull requests

7 participants