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

[asadovsky]

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.

[agnivade]

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]

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.