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: wrong line number from t.Log when using "log := t.Log" #14415

Closed
asadovsky opened this issue Feb 19, 2016 · 2 comments
Closed

testing: wrong line number from t.Log when using "log := t.Log" #14415

asadovsky opened this issue Feb 19, 2016 · 2 comments
Labels
FrozenDueToAge help wanted NeedsFix The path to resolution is known, but the work has not been done.
Milestone

Comments

@asadovsky
Copy link

Consider the following test program:

package my_test

import "testing"

func TestLineNumber(t *testing.T) {
    log := t.Log
    log("test")
}

When run with go test -v, the output is:

=== RUN   TestLineNumber
--- PASS: TestLineNumber (0.00s)
    my_test.go:6: test
PASS

The line number is wrong - it should be 7, not 6.

The testing package internally uses runtime.Caller(3) to identify the user code calling the testing.T logging function. It appears that the log := t.Log line is implicitly creating a closure, i.e. adding to the depth of the call stack, resulting in an incorrect line number.

@ianlancetaylor ianlancetaylor added this to the Unplanned milestone Feb 19, 2016
@ALTree ALTree added NeedsFix The path to resolution is known, but the work has not been done. help wanted labels Jul 18, 2017
@agnivade
Copy link
Contributor

I looked into this. There doesn't seem to be an easy fix from inside the "testing" package. A look inside the call stack reveals -

testing.(*common).decorate /home/agniva/play/gosource/go/src/testing/testing.go 362
testing.(*common).log /home/agniva/play/gosource/go/src/testing/testing.go 559
testing.(*common).Log /home/agniva/play/gosource/go/src/testing/testing.go 566
testing.(*common).Log-fm /home/agniva/play/gosource/go/src/encoding/hex/hex_test.go 29
encoding/hex.TestLineNumber /home/agniva/play/gosource/go/src/encoding/hex/hex_test.go 44
testing.tRunner /home/agniva/play/gosource/go/src/testing/testing.go 755
runtime.goexit /home/agniva/play/gosource/go/src/runtime/asm_amd64.s 2320

(I have put the test code inside hex_test.go. Let's ignore that)

The testing.(*common).Log-fm indicates that a closure is being created the moment something like fn := t.Log is done.

And what is more interesting is it persists across function calls. Notice that the Log-fm line is at 29 and the actual call is at 44. That is because it is happening in another Test function altogether.

As a stripped down version, I have something like

func TestEncode(t *testing.T) {
	_ = t.Log  -> L29
        ...
        ...
}


func TestLineNumber(t *testing.T) {
	log := t.Log
	log("test") -> L44
}

So, even if I execute only the TestLineNumber function, the stack shows that the closure is being created at L29.

@ianlancetaylor
Copy link
Contributor

As of 1.9 this should now be possible, at the cost of being slightly more awkward, by writing

    log := func(args ...interface{}) {
        t.Helper()
        t.Log(args...)
    }

Closing because this is kind of special purpose and there is (now) a workaround.

@golang golang locked and limited conversation to collaborators Aug 21, 2018
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge help wanted NeedsFix The path to resolution is known, but the work has not been done.
Projects
None yet
Development

No branches or pull requests

5 participants