proposal: testing: expose test location information indirectly from t.Context()

[apparentlymart]

Proposal Details

I originally presented this idea in a comment of #59928, but was correctly advised that it was a separate proposal.

This proposal makes use of several recently-accepted proposals, combining them to solve a new problem:

• testing: add T.Context() accessor #16221
• testing: Add T.Output() etc #59928

This also has some similarities to #70480, but is focused on a different problem.

---

#59928 has added a new, lower-level way for tests to generate output using an implementation of io.Writer. The main motivation for that proposal was to be able to direct output from log or slog into the test log stream instead of stdout/stderr, but the current form of the proposal does not include a convenient for such an integration to achieve an effect similar to t.Log's prefix indicating which source line the log was emitted from.

I'd like to address that with some additions to package testing, including one new function and an extension of the behavior of the existing t.Context method.

First, the new function:

package testing

// SourceLocation returns a concise string representation of a source
// location in a test or benchmark associated with the given context, or
// an empty string if the context is not related to a test or benchmark.
//
// Use [T.Context] to create a context associated with a test. The
// reported location is the source line where T.Context was called.
// The returned string is guaranteed to match the location that
// would be used in the prefix generated by by [T.Log] if called at
// the same source location. Any child context of such a context is
// also associated with the same source line.
func SourceLocation(ctx context.Context) string

As the doc comment implies, the second change is to extend T.Context (from #16221) so that the context it returns responds to Context.Value using a key that's of an unexported type in package testing, returning the information that SourceLocation would need to perform its documented behavior. The source location captured by T.Context should be exactly the same that would be included in a log line generated by T.Log if called at the same source location, taking into account any stack frames where t.Helper was called in the same way that T.Log does.

A non-empty string returned by SourceLocation is in the same format that t.Log would use as a prefix of the line it writes, without the trailing colon and space. For example, it might return "foo_test.go:143". Returning a string, rather than something more explicitly-structured, avoids constraining the future evolution of package testing's representation of source locations any further than it's already constrained by the established t.Log behavior.

The primary intention is to allow a downstream logging implementation to produce a similar presentation as t.Log would produce, but to write it through the writer returned by t.Output instead. For example, in a (minimal, somewhat-contrived) test-oriented implementation of slog.Handler:

type TestLogHandler struct {
    w io.Writer
}

func (h *TestLogHandler) Handle(ctx context.Context, record slog.Record) error {
    var prefix string
    testLoc := testing.SourceLocation(ctx)
    if testLoc != "" {
        prefix = testLog + ": "
    }

    return fmt.Fprintln(prefix + record.Message)
}

The above assumes that the test would arrange for this handler to be active while the test is running -- for example, by calling slog.SetDefault in TestMain -- and that it passes t.Context() to any context.Context arguments of the code under test. The author can decide which log level produces an appropriate level of verbosity for useful test failure output, and might select a different log level if testing.Verbose returns true, but that's a policy decision made by the test author and not a direct part of this proposal.

Although much of the above refers to testing.T in particular for explanation purposes, I propose that this also work for testing.B.

---

The maintainers of logging libraries, or third-parties providing reusable utilities for those logging libraries, might choose to offer a ready-to-use implementation of whatever is their closest equivalent of slog.Handler designed for convenient use in test code.

Because slog is one such logging library built in to Go's standard library, someone might propose to add such a thing for that package eventually, but I'm not proposing any such thing here because I want to focus for now only on the core behavior in package testing that other libraries can build on. Replicating package testing's special handling of stack frames with t.Helper outside of the standard library doesn't seem practical, but a hypothetical slog.Handler making use of this new API could be written a third-party module just as easily as it could be written in the standard library.

---

I note that t.Context currently returns the same context.Context value on each call within a particular test function. The proposed behavior implies that the function would change to instead produce a new derived context on each call, doing something like this:

func (c *common) Context() context.Context {
	c.checkFuzzFn("Context")
	return context.WithValue(c.ctx, sourceLockKey, c.sourceLoc())
}

...where of course sourceLockKey and common.sourceLoc are just placeholders for the unexported key and the function responsible for generating its value.

I note that this does mean that repeated calls to t.Context will presumably now generate some garbage, which might be annoying in benchmarks.

Edit: in the first draft of this I grabbed the wrong link for t.Context from my notes. It now links to the proposal that was accepted, as I had original intended.

[seankhliao]

Overloading Context in this way seems quite wrong, I expect most tests to only call Context once at the top, and wrap / pass it down as necessary.

I feel this has heavy overlap with #52751

[apparentlymart]

I don't use t.Context in that way, but fair enough.

Admittedly, part of the reason I don't use it that way is specifically because the method currently returns the same context every time and so also assigning it to a local variable seems pointless, and this proposal changes that to return a separate context each time, but it does that in a way I'd find useful. 🤷🏻‍♂️

Edit: I reflected a little on why I have ended up using t.Context in this apparently-unconventional way, and I think it's because in test code the testing.T object effectively takes the place of a context.Context as the first argument to any test helper function, and so it seems silly to redundantly also pass the t.Context() result as a separate argument. And so I use the t right up until I'm calling into non-test code and use t.Context to pivot from the test-flavored "context" into the general-purpose context. I honestly hadn't even questioned it because it until now because it seemed intuitive to me given the very similar pattern of both testing.T and context.Context representing a bag of useful cross-cutting junk passed wholesale between functions as a standard first argument. 🤷🏻‍♂️

[apparentlymart]

Thanks for the link to #52751.

I agree that it seems related. In principle it would be possible to place a result from the function in that proposal into a context as a value and then pull it out again inside the log handler to get the same effect as this proposal outside of package testing:

func locationContext(t *testing T) context.Context {
    t.Helper()
    return context.WithValue(t.Context(), someKey, t.Name("whatever"))
}

It isn't clear to me whether that proposal actually allows extracting the string representation of the location from the NameFileLine value as currently proposed, but it would presumably be possible to do so if there were a good reason to expose that, and the use-case that motivated what I proposed here could be such a reason.

It not having a standard API in package testing makes it more likely that each codebase wanting this would invent its own separate convention for annotating the context and therefore need its own special log handler to work with that, but while that's less convenient it's not technically problematic because it only requires the tests in one package to agree with the log handler set up in that same package, so there's no cross-package wiring to deal with.

[apparentlymart]

Reflecting on this a while later, I think I may have "jumped the gun" in opening this proposal.

I think it would make sense to leave this on hold until an implementation of #59928 has been released and folks have had some chance to try using it for logging in practice.

Hopefully that will mean there are some examples of testing-specific log handler setup we can refer to, and use that to think about what (if anything) is missing to help connect the log output with the test code that caused it to be emitted.