testing: add t.Helper to make file:line results more useful

[eaigner]

Currently the caller level of T's decorate function is fixed

    _, file, line, ok := runtime.Caller(3) // decorate + log + public function.

When wrapping common assertions in a code block, it would be useful to be able to modify
the caller level for correct log output.

[bradfitz]

Comment 1:

Rob and I were discussing possibilities, like:
t.Frames(5).Errorf("...")
But probably after Go1.1.

Labels changed: added priority-later, removed priority-triage, go1.1maybe.

[rsc]

Comment 2:

[The time for maybe has passed.]

[mxk]

Comment 3:

This is a hack, but it works (except when it doesn't, which is in deferred function
calls):
package demo_test
import (
    "fmt"
    "runtime"
    "testing"
)
func up(frame int, s string) string {
    _, origFile, origLine, _ := runtime.Caller(1)
    _, frameFile, frameLine, _ := runtime.Caller(frame + 1)
    if origFile != frameFile {
        return s // Deferred call after a panic or runtime.Goexit()
    }
    erase := []byte("\b\b\b")
    for ; origLine > 9; origLine /= 10 {
        erase = append(erase, '\b')
    }
    return fmt.Sprintf("%s%d: %s", erase, frameLine, s)
}
func assert(t *testing.T) {
    t.Logf("wrong line number")
    t.Logf(up(1, "right line number"))
}
func TestDemo(t *testing.T) {
    assert(t)
}

[ianlancetaylor]

Comment 4:

Labels changed: added go1.2maybe.

[rsc]

Comment 5:

Status changed to Accepted.

[remyoudompheng]

Comment 6:

Issue #6024 has been merged into this issue.

[davecheney]

Comment 7:

I made a start on this, https://golang.org/cl/12405043/. It is not ready for
submission, but certainly ready for feedback.

Owner changed to @davecheney.

Status changed to Started.

[mxk]

Comment 8:

What about a simpler solution that prints out all line numbers within the same _test.go
file? I found that my hack actually makes it more difficult to figure out the true cause
of the error. In some cases it's better to have the location in the Test function, while
in others you want to know where in the helper function the test failed. Something like
"my_test.go:63:591: a != b" makes it very easy to track down the problem by giving you
all the relevant line numbers without dumping a full stack trace.

[davecheney]

Comment 9:

@max, yes, this is what I am proposing
t.Error("something") // logs the file and line of where t.Error is called
t.Frames(1).Error("something") // logs the file and line of the caller of the function
that called Error.

[mxk]

Comment 10:

Right, but I'm suggesting not having the Frames function. You could change the decorate
function instead to look through all stack frames starting at 3 and concatenate all line
numbers that are in the current _test.go file. If t.Error("something") is called in a
Test function, then the output stays as it is right now. But if it's called from a
helper function, then you get two or more line numbers, starting in the Test function
and working your way through all the helpers.

[davecheney]

Comment 11:

No thank you.
1. how do you defined a helper function ? I can't think of a way short of making them
end with helper or something.
2. this isn't want is spec'd by brad in comment #1
3. That isn't want Erik or I wanted in the original request or issue #6024.

[mxk]

Comment 12:

So for issue #6024, instead of "tt_test.go:8: an error" you would get "tt_test.go:16:8:
an error" without any changes to your code. No special naming is necessary. If chk is in
the current _test.go file, which you can easily figure out in decorate, then append its
line number.
In my experience, having both line numbers is frequently useful in tracking down the
problem, especially if your chk function tests for multiple error conditions. For an
example, take a look at how I use the "cl" function in my SQLite test code:
http://code.google.com/p/go-sqlite/source/browse/go1/sqlite3/sqlite3_test.go

[robpike]

Comment 13:

Still not convinced this is a good idea. Deferring to 1.3.

Labels changed: added go1.3maybe, removed go1.2maybe.

[robpike]

Comment 14:

Labels changed: removed go1.3maybe.

[rsc]

Comment 15:

Labels changed: added go1.3maybe.

[rsc]

Comment 16:

Labels changed: added release-none, removed go1.3maybe.

[rsc]

Comment 17:

Labels changed: added repo-main.

[josharian]

Comment 18:

I'll throw out another approach here. It's not perfect, but maybe it'll inspire a better
idea in someone else.
`go test` knows where the actual test is; let it do the work.
Let testing.T accept a filename and line range. If not present, behavior is unchanged.
If present, t.decorate walks up the stack until it finds a matching frame. (If no such
frame, use current behavior.) In cmd/go, when scanning for Test*/Benchmark* function
declarations, note the filename and corresponding start/end lines, use them to populate
InternalTest, and have InternalTest populate T/B accordingly.
This does make things worse when TestFoo just wraps testFoo with minor variants. (See
e.g. src/pkg/math/all_test.go:TestExp.) Perhaps this could be ameliorated by adding a
method to t to clear the filename and line range, which could be explicitly called in
such tests. Alternatively, the default could be flipped, cmd/go could gather the
filename and line ranges, and let individual tests turn on their usage.
This will also not likely play nicely with -cover, but we could just not generate
filename and line range in cover mode and fall back to the current behavior.
Thoughts?

[josharian]

Comment 19:

Here's a better proposal. (Nothing like writing down a bad idea and then sleeping on it.)
Add t.Helper() and b.Helper(). When called, they mark the calling function as a helper
function; testing looks further up the stack when printing file and line info.
Sample usage in the program from issue #6024: http://play.golang.org/p/_uAL3FGBYq
Whipped up a quick and dirty implementation at https://golang.org/cl/79890043
if anyone wants to give it a whirl to see how it feels. (At the least, it needs tests
and an example to make it complete.)

[gopherbot]

Comment 20 by asokoloski.work:

What I had in mind before stumbling on this thread was something like this:
func Helper(t *testing.T) {
    t.Descend() // or Down
    defer t.Ascend() // or Up
    ...
    t.Error("blah blah")
}
...where the Descend and Ascend methods simply modify a stack frame offset, which is
currently hardcoded.
I see that Rob Pike has mentioned a similar but more stateless version of the same idea
here: https://golang.org/cl/12405043/#msg3
And now I'm curious what he means about testing helpers being "the devil's handiwork" :)

[davecheney]

Comment 21:

Issue #8783 has been merged into this issue.

[cespare]

Comment 22:

#19: I'd really like that feature or something similar. It would be great to have some
alternative to the \r hack that most of the testing libraries out there are using.
Josh, are you interested in submitting a CL later for 1.5? I'm also willing to do the
fleshing out (tests, etc) if that helps.

[josharian]

Comment 23:

Caleb, there are two things preventing me from mailing that CL for 1.5:
1. The API. The proposal in #19 differs from what Brad and Rob had in mind. Before
polishing a CL to send, I'd like to get their input.
2. The implementation. Using runtime.Func's Entry is a bit of a hack, and one that won't
work for closures, I think. (Maybe we don't care?) And I don't see another obvious way.

[cespare]

Proposal over in #18440.

Proposal lives in this thread now.

[gopherbot]

CL https://golang.org/cl/34717 mentions this issue.

[rogpeppe]

As an alternative suggestion, how about changing Error and friends so that they print all the file/line numbers up to the top-level Test function?

The problem with just allowing control over the single file/line number is that it doesn't easily compose. If a given primitive selects a particular frame count, some other code might wrap that primitive and then the frame count is wrong again.

For example, it's common for people to write an "assert" primitive (here's one I came across last week). The proposed Helper method would work well when assert is called directly from a test function, but if someone makes a higher level function that calls assert as part of its implementation, the line number will be wrong again.

[josharian]

how about changing Error and friends so that they print all the file/line numbers up to the top-level Test function?

This seems really noisy to me as a default.

If a given primitive selects a particular frame count, some other code might wrap that primitive and then the frame count is wrong again.

Caleb's proposal handles this case, and the proposal doc discusses it explicitly. Perhaps something in the doc needs clarifying or expanding.

[cespare]

See the Helper proposal here:

https://github.com/golang/proposal/blob/master/design/4899-testing-helper.md

[rogpeppe]

Caleb's proposal handles this case, and the proposal doc discusses it explicitly. Perhaps something in the doc needs clarifying or expanding.

Yes, you're right that it does handle this case, but I still think it's not sufficient.

To go with the "assert" example for a bit, let's say I have some code like this:

func TestFoo(t *testing.T) {
	higherLevelCheck(t, someArgs{something})
	higherLevelCheck(t, someArgs{somethingElse})
}

func higherLevelCheck(t *testing.T, someArgs Args) {
	t.Helper()
	r, err := doSomething(someArgs)
	assert(t, err, nil)
	assert(t, r.Something, expectedValue)
	z, err = somethingElse(someArgs)
	assert(t, err, nil)
	if foo(z) {
		t.Fatalf("higher level check failed")
	}
}

func assert(t *testing.T, got, want interface{}) {
	t.Helper()
	if !reflect.DeepEqual(want, got) {
		t.Fatalf("got = %v, want = %v", got, want)
	}
}

Say the third call to "assert" in higherLevelCheck fails, with the proposal
as is, this will print the line in TestFoo that called the higherLevelCheck
function. That's useful information, but it doesn't tell us which assert
within higherLevelCheck failed, and that's important information.

I've seen this issue multiple times in real test code.

This seems really noisy to me as a default.

I'm not convinced that it would be too noisy - this only happens on test failures.
Perhaps we could look at some sample test failure output with and without
the extra information to get a feel for it?

[josharian]

To go with the "assert" example for a bit, let's say I have some code like this:

In this concrete example, I'd be inclined to use subtests in TestFoo and drop the t.Helper() from higherLevelCheck, and I suspect such a strategy will work well in many such cases. I can see that it won't always work, but I'm not convinced that this example means that t.Helper is not a very useful solution for a different and broad class of problems.

There's a similar problem with table-driven tables. If you don't write good error messages explaining which input failed, the error line number is insufficient by itself, and in a sense, you want the line number of the failing entry in the input table, even though that isn't anywhere in the stack trace at all. The right solution for that case is judicious use of the tools: combine subtests, good error messages, refactoring, and in a pinch, flag protection and/or commenting stuff out. I think something similar applies here.

Also, in some ways, printing all lines and using t.Helper are complementary. For example, you could imagine printing a stack and omitting all frames marked as helpers, and making more sparing use of t.Helper.

Perhaps we could look at some sample test failure output with and without the extra information to get a feel for it?

In a sense, we both have lots of experience with this. When you break a test and it panics instead of failing, you get a stack trace. I prefer the concision of the failures.

I personally would be fine with a flag to go test that switches to printing full stacks, perhaps informed by t.Helper. I just don't want it on all the time.

[alandonovan]

FYI: I filed a related feature request (golang/go issue #18848) to allow tests to report arbitrary file/line information in error messages, not just Go source lines. When input comes from a testdata file, and particularly when the testdata file is in some kind of scripting language, it's the position in the data file that is most relevant to users stepping through test errors in their editor.

[cespare]

Anyone else have thoughts about this? Any more info needed before a decision is made?

[sdboyer]

I'd second @josharian's last couple comments. While the issue raised by @rogpeppe is concerning, I think it's ultimately orthogonal to the addition of TB.Helper(). That is, while I'd value this in some cases:

As an alternative suggestion, how about changing Error and friends so that they print all the file/line numbers up to the top-level Test function?

It does make for a noisy default. And, given that the introduction of this feature will allow testing frameworks to become first-class citizens, I don't really want to be poring through the stack trace guts of a testing framework all the time. Right now, the testing framework is oriented towards letting the developer hone in on a single point to begin their investigations. That's valuable to keeping tests comprehensible, and while it enforces a level of disciplined test design on the user (as @josharian described), I think that's a property worth maintaining.

Most importantly, though, I think the problem is orthogonal to the TB.Helper() proposal. As noted, we could always add an additional flag to go test that would cause it to print the stack trace back up to the top-level test/subtest. The default output would remain trim and focused, but the user could opt-in to additional inspection if needed.

I'd say this should go ahead as-is.

[josharian]

Aha! Looks like this hasn't been reviewed by @golang/proposal-review because it was on hold waiting for @cespare to mail a doc. Doc done been mailed; un-holding.

[rsc]

The design doc looks good. Does anyone want to make a case against adding t.Helper?

[rsc]

Guess not. OK, proposal accepted as in design doc.

[gopherbot]

CL https://golang.org/cl/38796 mentions this issue.