proposal: testing: Add T.Output() etc

[earthboundkid]

In a test, you often want to mock out the logger. It would be nice to be able to call t.Slog() and get a log/slog logger that send output to t.Log() with the correct caller information.

See https://github.com/neilotoole/slogt for an example of a third party library providing this functionality, but note that it cannot provide correct caller information:

Alas, given the available functionality on testing.T (i.e. the Helper method), and how slog is implemented, there's no way to have the correct callsite printed.

It seems like this needs to be done on the Go side to fix the callsite.

[earthboundkid]

Expanding on this little, there are two cases of logging during testing:

1. Sometimes you want to examine the log and ensure that some info is in the log.
2. Sometimes you just want to provide debug information.

This is just about case 2. For that reason, I thinking testing.Slog() should return a slog.Handler that is essentially a slog.TextHandler, except it always logs to the testing.Log stream.

For case 1, people can just log to a bytes.Buffer and poke around as usual, or maybe there can be a log/slog/testslog that has a handler that just appends slog.Records to a big slice you can look at after the test.

[seankhliao]

See also previous discussion

#56345 (comment)
#56345 (comment)

[AndrewHarrisSPU]

Sometimes you just want to provide debug information.

Yeah, I agree having something like "if this test fails, show me some logs" is a productive idea and different from testing against the contents of logged output.

The twist seems like - the way that testing observes stack metadata reports lines related to the structure and control flow of running tests. The way that slog observes stack metadata reports where code has decided to emit a slog.Record. We might want both kinds of observations, for example we might have a discrete chunk of test logic where the code under test emits a number of slog.Records worth looking at - we'd want a line annotation for the test logic, and one for each Record.

I had some results decorating a testing.TB with Handler methods and a buffer that would replay slog.Logger calls when t.Error was hit, this kind of thing (https://go.dev/play/p/mPkMxYq2CK__z?v=gotip) ... this approach dictates a particular way of collating slog output via testing.TB hooks, which doesn't feel quite right, however.

I do think other approaches might need a way to access the result of testing.common.frameSkip.

[rsc]

This proposal has been added to the active column of the proposals project
and will now be reviewed at the weekly proposal review meetings.
— rsc for the proposal review group

[dnephin]

Does the file:line annotation from t.Log help in debugging the test failure? The file:line of the caller should already be available by setting slog.HandlerOptions.AddSource=true.

In my experience adding the file:line annotation from t.Log to log output generally makes the test harder to debug because log output and the failure messages from t.Error/t.Fatal look identical. This is particularly problematic when logs come from a background goroutine and the failure message appears in the middle of the logging output.

If the goal is to only display log lines when a test fails, I've seen this approach (https://go.dev/play/p/WXHWdRW8s4Z) in a few places:

func testLogger(t *testing.T) *slog.Logger {
	t.Helper()
	buf := new(bytes.Buffer)
	opts := &slog.HandlerOptions{AddSource: true}
	log := slog.New(slog.NewTextHandler(buf, opts))

	t.Cleanup(func() {
		if !t.Failed() {
			return
		}
		t.Helper()
		t.Log("log output\n", buf.String())
	})
	return log
}

This approach makes the failure message and log lines much more distinct. It also addresses some of the challenges in test2json when tests use t.Parallel. The obvious disadvantage is that log output is no longer streamed.

Maybe t.Slog() could omit the leading file:line annotation? Or alternatively a t.Output() that returns an io.Writer that prints without the file:line annotation could be passed to a slog.Logger?

[Merovius]

@dnephin

In my experience adding the file:line annotation from t.Log to log output generally makes the test harder to debug because log output and the failure messages from t.Error/t.Fatal look identical.

I'd be totally happy if the output would made to be look different. But I don't think that is possible with the current API. If you log to stdout/stderr, the output looks different, but is then also not correlated with the actual test and interleaved with its t.Error calls. So you end up with a slodge of logging output, then a list of tests runs and failures.

If the goal is to only display log lines when a test fails

Even if you only get the output of failed tests, that still means if you have more than one of those you have no idea what log output belongs where. And even if you only have one failing test (e.g. by re-running it with -run), you have no idea what log output happens before and which happens after the failure.

So, no. The goal is not only to limit log output to failures - it's also to correctly correlate and interleave it with other test output.

Maybe t.Slog() could omit the leading file:line annotation? Or alternatively a t.Output() that returns an io.Writer that prints without the file:line annotation could be passed to a slog.Logger?

I think both of these would work for me.

[AndrewHarrisSPU]

#52751 (comment) would make more third-party (or similarly, deliberately decoupled) solutions possible, as the top post here discusses.

[dnephin]

if you only get the output of failed tests, that still means if you have more than one of those you have no idea what log output belongs where

Looking at the output of https://go.dev/play/p/8s2T3VcEi7C, go test, go test -v, and go test -json all make it clear where the output comes from, for both stdout and t.Log. Stdout interleaved with t.Log is difficult to read, but having worked on projects that use t.Log for logger output, I would argue the file:line annotation from t.Log only makes the cause of the failure harder to find.

Looking at that ouptut I realize that stdout is also hidden by go test when the test passes, so that also can't be the goal of this proposal.

The goal is ... also to correctly correlate and interleave it with other test output.

That is already possible today, so that must not be the goal of this proposal.

[Merovius]

@dnephin

For me at least, not when I run it locally.

[dnephin]

#52751 (comment) would make more third-party solutions possible, as the top post here discusses.

What does #52751 provide that isn't already possible with slog.HandlerOptions.AddSource=true ?

A library like https://github.com/neilotoole/slogt could implement a handler that:

• formats the source attr without the directory (see this example).
• formats the record as ex: main.go:102: time=2023-06-30T00:12:06.256-04:00 level=INFO log output
• print it with t.Log

This would match exactly the output proposed in #52751.

The problem faced by https://github.com/neilotoole/slogt must not be retrieving the line that called log.Info, that's already available from slog.HandlerOptions.AddSource=true.

In #52751 (comment) I suggested what was missing was a way to print test output that was indented and displayed in the same place as t.Log output, but without the standard file:line annotation. I believe at that time (go1.18) the stdout from tests behaved differently (was not hidden when the test passed, and was grouped separately from t.Log output).

Looking at the output today (https://go.dev/play/p/ES9_Y5BC5kj), it seems those problems are fixed. It should already be possible to implement a logger that has the behaviour described in https://github.com/neilotoole/slogt#deficiency by writing the log output with:

fmt.Printf("    %v: %v\n", filepath.Base(source),  logMsg)

I believe the formatting of test output has changed a few times. It seems possible it could change again in the future. A t.Print or t.Output returning io.Writer might be more reliable.

[dnephin]

@Merovius what version of Go? Is that from go1.18? The output you shared is what I remember as well, but I can no longer reproduce with the two latest versions of Go.

[Merovius]

go version go1.21rc2 linux/amd64. It's been like this ~forever, for me.

[Merovius]

TBF, with -v it interleaves the output correctly. I don't think it used to (again, for me, as far as I remember, all that jazz). So maybe that makes me happy enough.

[AndrewHarrisSPU]

What does #52751 provide that isn't already possible with slog.HandlerOptions.AddSource=true ?

While AddSource captures file:line data wherever code under test has chosen to log, #52751 would offer a way to get the file:line of test inputs or other arbitrary points of interest that occur in the testing suite. This information could then be slog.Attr-ized and emitted in slog records (or even baked into handlers).

I think using hooks in testing to trigger emitting logs from code under test is usually plausible, but there are some limitations to this approach. First, the output is no longer consistently structured. Second, it doesn't cover some testing arrangements. For example, if I have routines for test setup and teardown, there might be interesting activity captured in logs but this doesn't neatly line up with the hooks testing provides. It's not that #52751 solves these issues exactly, but more flexibility in obtaining accurate file:line information from the testing suite would be useful; the information would be conspicuously missing otherwise.

[jba]

Let me try to summarize.

The request seems to be for a slog.Logger whose output behaves like that of t.Log: it is interleaved properly with the other output from the testing package, and without -v it appears only for failed tests.

The request isn't merely for structured logging that behaves like t.Log, like you could get with something like t.Info(msg, "k1", v1, "k2", v2). I take it no one wants that. For one thing, I don't see why anyone would prefer structured logs to formatted logs for test output, which should be designed for maximum human readability. For another thing, you could get that output with t.Logf("msg=%q k1=%v k2=%v", msg, v1, v2) if you really wanted it. The solution must actually expose a slog.Logger, so it can be injected into the code under test.

The discussion about source locations (file:line information) doesn't seem relevant to this proposal. We already have an accepted proposal, #52751, that adds general source location marking to testing. The slog package already allows you to include, exclude or reformat the source line of the logging call.

So if a slog.Logger with interleaved output is what's wanted, then something like https://go.dev/play/p/nnu-8RLql0X, written without any new API, should almost do it. It will produce interleaved and indented output when run with -v on the current (1.21 prerelease) version of the testing package:

=== RUN   TestTestLogger
    level=INFO msg="info 1"
    t1_test.go:48: t.log
    level=INFO msg="info 2"
    t1_test.go:50: t.log
    level=INFO msg="info 3"
    ...

The -json flag also results in properly interleaved output. Without any flags, the output isn't interleaved, and all of it appears, for passing tests as well as failing ones.

So does that make everyone, as @Merovius says, "happy enough"?

[rsc]

Writing to os.Stdout does not play well with (the lack of) -v, nor does it play well with parallel tests. That said, I think instead it would be fine to use something like

type testWriter struct {
   t *testing.T
}
func (w *testWriter) Write(b []byte) (int, error) {
    t.Logf("%s", b)
    return len(b), nil
}

and then use slog.NewTextHandler(&testWriter{t}, nil)

Perhaps all that is needed is some kind of t.LogWriter() io.Writer method, which could be used with log.New, slog.NewTextHandler, and slog.NewJSONHandler.

[jba]

t.LogWriter() was suggested upthread as t.Output(). That does seem the simplest and most general idea. Is there a good reason to put Log in the name?

[rsc]

If it's a general writer we should probably line-buffer up to some max like 4k to handle Write callers that - unlike the log packages - do not guarantee one line per write.

[jba]

Name bikeshed: t.Output or t.Writer?

[rsc]

t.Output sounds fine to me.

[jba]

Here's a problem: When you use t.Logf or fmt.Fprintf(t.Output(), ...), you'll always get the right output for the test you're in. But if you write

func Test(t *testing.T) {
    logger := slog.New(slog.NewTextHandler(t.Output(), nil))
    ...
}

then all uses of logger, even in subtests, will write to the output for whatever t was when the logger was constructed. Even without -v, you'll see the output for all subtests, both succeeding and failing ones, grouped with the parent test.

I don't know how annoying or error-prone that's going to be.

[rsc]

I agree that if you write code to send the log messages to the wrong test, they show up in the wrong test. We can't fix every possible mistake.

Writing to os.Stdout definitely does the wrong thing with parallel subtests though, and we can fix that.

[AndrewHarrisSPU]

all uses of logger, even in subtests, will write to the output for whatever t was when the logger was constructed.

Seems like it's a moving target - while this is probably the wrong thing for tables of unit tests, this seems like the right thing for wider integration tests.

So does that make everyone, as @Merovius says, "happy enough"?

FWIW, I'd mention Kubernetes' ktesting as another interesting exploration of how to integrate testing and logging (pre-slog). I think the approach of testing.T.Output as well as #52751 is enough to make some third-party extension like this a lot more reasonable, so of course everyone's happy :)

[jba]

The current proposal is to add the methods

package testing
func (*T) Output() io.Writer
func (*B) Output() io.Writer
func (*F) Output() io.Writer

Writes to tbf.Output() will behave like tbf.Log:

• They will appear along with other output for tbf's test/benchmark/fuzz.
• Lines will be indented.
• They will be displayed only for failing tests, unless the -v or -json flags are provided, in which case they will always be displayed.

@carlmjohnson, this is your issue. If you're okay with this change, could you modify the issue title, and edit your top post to include the above or link to this comment?

[jba]

The suggestion is that t.Slog returns a logger with a special slog.Handler that behaves like t.Log. That raises some questions.

• What is the minimum level of the handler? The default handlers use Info, but we are logging failed tests, so perhaps Debug makes more sense. But then logs at lower levels wouldn't appear, and they might be helpful.

• One aspect of slog's flexibility is that an application can provide a handler that processes some values specially. For example, an application might log values of type func() T, and its handler might call those functions just before it outputs the log event. That sort of lazy evaluation is not part of slog, so special functionality like this wouldn't be available to the testing handler.

One advantage of t.Output is that it's just an io.Writer, so the application could use its own handler with it. But that has its problems too. Perhaps the application handler doesn't take an io.Writer, or maybe it outputs a binary format.

I don't think there's a perfect answer, but if we go with t.Slog then the user can always wrap the testing handler with their own:

type myTestingHandler struct {
   h slog.Handler
}

func newTestingLogger(t *testing.T) *slog.Logger {
    return slog.New(&myTestingHandler{h: t.Slog.Handler()})
}

// Enabled enforces a minimum level of Debug-10. It does not call h.h.Enabled,
// so whatever minimum level the testing handler uses is ignored.
func (h *myTestingHandler) Enabled(ctx context.Context, level slog.Level) bool {...}

// Handle replaces attribute values of type `func() T`  with the result of invoking the function,
// then calls h.h.Handle.
func (h *myTestingHandler) Handle(ctx context.Context, r slog.Record) error {...}

Another possibility is that t.Slog could take a slog.HandlerOptions, which would make it easy to set a minimum level and perform some special actions, including the lazy evaluation I described above.

[jba]

@dnephin, if I understand you right, you are criticizing Russ's claim that people can write t.Output themselves. We agree they cannot because of the source location.

But do you have a problem with Russ's actual suggestion, which aligns with the top post, to have a t.Slog method that behaves like t.Log in the relevant ways (no output for passing tests, etc.)?

I don't think it's critical that the -json flag results in JSON output, but it could make life easier for the consumer of the output. Instead of a line like

{"Time":"...","Action":"slog","Package":"p","Test":"t","Output":"msg=hello k1=1 k2=2"}

where you'd have to parse the output string to recover the key-value pairs, there would be

{"Time":"...","Action":"slog","Package":"p","Test":"t","Output":{"msg":"hello","k1":1,"k2":2}}

which is JSON all the way down.

[AndrewHarrisSPU]

Another possibility is that t.Slog could take a slog.HandlerOptions, which would make it easy to set a minimum level and perform some special actions, including the lazy evaluation I described above.

Is there another possibility, something like passing t.Slog a slog Handler, and generating log lines for significant testing events from the t (or derived t, etc.)?

Currently testing.TB implementations are a bit privileged - source location in relation to testing.TB.Helper is the obvious one. Resolving this would require greater access to some the internal implementation, or testing.TB implementations could learn to generate slog logging lines. The latter seems messy but finite - I think the destination would be another testing type along the lines of T or B that also knows how to slog.

[dnephin]

@jba to be honest, I'm a bit confused about why we went back to talking about t.Slog. I reread this entire comment history in an attempt to understand. In June through August it seems like everyone was happy with testing.T.Output() io.Writer. What changed?

But do you have a problem with Russ's actual suggestion, which aligns with the top post, to have a t.Slog method that behaves like t.Log in the relevant ways (no output for passing tests, etc.)?

First I'd like to challenge the idea that this aligns with the top post. To summarize, the top 2 posts said this about using a logger in tests:

1. Sometimes you want to examine the log and ensure that some info is in the log.

I believe everyone agrees that this case is already handled by bytes.Buffer. I think this is relevant to the proposal because some tests should explicitly not use an API like t.Slog, and should always use something like:

buf := new(bytes.Buffer)
logger := slog.New(slog.NewJSONHandler(buf, nil)) // or maybe a custom handler to capture the attributes

I think the existence of a t.Slog would make this pattern (using a bytes.Buffer) more difficult to discover.

2. Sometimes you just want to provide debug information. This [proposal] is just about [this case].

The original problem was the lack of relevant file:line information, but I think I showed in #59928 (comment) that the problem isn't a lack of file:line info (that's already available from slog.HandlerOptions.AddSource=true). The problem is actually that t.Log adds an unnecessary and misleading file:line for an irrelevant source location.

testing.T.Output() io.Writer seems like the obvious solution to not only this problem, but a number of other problems I've had in the past when trying to output more detailed failure messages. I believe that was confirmed in #59928 (comment) - "I think as long as Output doesn't add line numbers, it's good."

Perhaps the application handler doesn't take an io.Writer, or maybe it outputs a binary format.

It seems like it should always be possible to accept an io.Writer. If the application accepts a higher level interface like slog.Handler or slog.Logger you can easily construct those from an io.Writer. I don't understand why someone would print a binary format to the test output. I'd expect that to go to a bytes.Buffer, or to a file.

I think you've already found many of the problems with func (*T) Slog() *slog.Logger. A func (*T) Slog() *slog.Handler was proposed in the second post. I think that's slightly better, but I don't understand why that would be preferred over t.Output given that both would require a line of code to construct the actual logger. I'd like to explore that a bit more, but first a response to another point.

---

I don't think it's critical that the -json flag results in JSON output, but it could make life easier for the consumer of the output.

{"Time":"...","Action":"slog","Package":"p","Test":"t","Output":{"msg":"hello","k1":1,"k2":2}}

I didn't realize this originally, but I think this has the same problem as I described in #59928 (comment).

Many of the tools that use the -json output today (IDEs, CI systems, etc) use the run/pass/fail actions to learn about the tests, but will generally print the TestEvent.Output field of action=output events directly to the user.

Structured JSON output in the Output field breaks the most common use case for test2json output. Any tools reading this now have to convert the JSON back into the text format (whatever was parsed by test2json).

In other words, I don't think the logger should write JSON in the Output field, as #59928 (comment) says, whatever is reading the Output can handle decoding the log. That shouldn't be a problem.

go test and go test -v should output a text format, so either way something needs to convert the text format into JSON, but I don't think we have seen any use cases for JSON in the Output field.

[dnephin]

If I understand correctly there are a few options for something like t.Slog:

Option 1

func (*T) Slog() *slog.Logger

(Ignoring the part about "When used with go test -json, any log messages are printed in JSON form.", since I've made an argument against that in the second part of #59928 (comment)).

I think #59928 (comment) already calls out the problems with this approach.

I'll add that In general I'd probably want to hide the timestamp from this output, so I'd want something like

ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr {
	// Remove time from the output for predictable test output.
	if a.Key == slog.TimeKey {
		return slog.Attr{}
	}
...

But that may not be appropriate in all cases. The lack of extensibility makes this not a good option.

A variation on this option from the second post:

func (*T) SlogHandler() *slog.Handler

I think this has the same problems.

Option 2

To address those problems the methods could accept handler options.

func (*T) Slog(handlerOpts slog.HandlerOptions) *slog.Logger
...
func (*T) SlogHandler(handlerOpts slog.HandlerOptions) *slog.Handler

What does the go test and go test -v output look like for this logger? Is is equivalent to:

opts := &slog.HandlerOptions{AddSource: true, Level: slog.LevelDebug}
logger := slog.New(slog.NewTextHandler(t.Output(), opts))

If that's the output format it doesn't seem like these new methods on T add much.

Or would it be more like this?

source.go:512: level=INFO msg="something happened" key=value

I mentioned in #59928 (comment), in my experience this makes test failures more difficult to debug because the log output looks too similar to the failure message. This problem is considerably worse when logs are output from a background goroutine, because the failure is not at the end of the output, but somewhere in the middle of many log lines, and they all have a similar prefix.

#62728 helps address that problem for test2json output, but I think the problem remains for the standard text format.

Option 3

My proposal is this:

// Output returns a writter that writes to the test case output, like t.Log does, without any leading
// file:line annotations.
func (*T) Output() *io.Writer

// SlogHandlerOptions returns options appropriate for constructing an slog.Handler. The default
// level is set to slog.LevelDebug, AddSource = true, and slog.TimeKey will be omitted from the
// attributes.
func SlogHandlerOptions() *slog.HandlerOptions

This approach makes the common case fairly easy:

logger := slog.New(slog.NewTextHandler(t.Output(), testing.SlogHandlerOptions()))

while still making it possible to customize the logger:

opts := testing.SlogHandlerOptions()
opts.Level  = slog.LevelTrace
logger := slog.New(slog.NewTextHandler(t.Output(), opts))

and allowing the "capture logs for comparison" case to look similar:

buf := new(bytes.Buffer)
logger := slog.New(slog.NewJSONHandler(buf, testing.SlogHandlerOptions()))

SlogHandlerOptions does not really need to be in the testing package. It could be copied around initially. It should be under 10 lines.

[earthboundkid]

I agree with @dnephin. The only thing I’ll add is that besides bytes.Buffer it might be nice to have a slice of slog records to use for test log verification, but that should be a separate proposal. I think t.Output solves this case and leaves things open for whatever future log stuff comes up.

[stevenh]

t.Output gives much more flexibility for other use cases.

[aclements]

Thanks for the summary, @dnephin.

TB.Output() io.Writer definitely seems like the most flexible option here. This would return a Writer that writes to the same stream as T.Log, but would exclude the source position information that T.Log adds. Ideally it would also do line buffering. In -json output, output written to this Writer would appear as "output" events just like output from T.Log, so it wouldn't present any compatibility issues from new event types. While @rsc claimed you could easily write this yourself, I think he overlooked the problem with extraneous source position information.

With TB.Output as a primitive, a test can always wrap a slog.Logger around the returned io.Writer. Unlike trying to build a slog.Handler that defers to T.Log, a slog.Logger built using T.Output would print correct source information, with the exception of not knowing about T.Helper. The logger doesn't necessarily even need testing-specific configuration. The reverse is not true: if we expose T.Slog() *slog.Logger, there's no good way to build something like T.Output().

I can see a few advantages to built-in support of slog. One is that it could theoretically account for source position information the same way that T.Log does by skipping helper frames. I'm not sure that's actually possible to implement in slog, but I may be mistaken. Another is that it could have special integration with test2json, such as emitting JSON for direct embedding in some new action type. It's not clear to me that's actually desirable or necessary: new action types can cause compatibility issues, and it's not hard for tools that are already parsing the test2json JSON to parse double-escaped JSON.

The Writer returned by T.Output would also be valuable for passing to other things that can only take a Writer, for example a subprocess created by the test, or other logger systems not built on slog.

[jba]

One is that [slog] could theoretically account for source position information the same way that T.Log does by skipping helper frames.

That would require somehow exposing testing.common.frameSkip to slog. But whether or not it's technically feasible, I don't think it's relevant. The main reason to use T.Output with slog is to display the log lines from the system under test. None of the log-generating calls (slog.Info, etc.) in the system under test are in helper functions. I don't think it's as important to provide structured logging to the tests themselves; there, T.Log(f) suffices.

[apparentlymart]

I do hesitate to add this since I note that this proposal already has at least a couple counterproposals in the comments, but getting log output integrated nicely with tests has been a pain point for me for a long time and so I'm pretty invested in something happening here.

I'd personally find it useful to be able to attribute a log line to some specific part of a test, since in the system I maintain in my day job our tests often call a variety of functions that all generate quite a large amount of log information. Therefore while I do like the t.Output compromise, I'd prefer a solution that is able to include at least some source location information from the test code in the captured logs.

When considering the discussion above, I had the following idea...

---

The log/slog API already offers the possibility of logging with a context.Context, which gets passed through to the handler when deciding whether a particular log level is enabled and when asking the handler to handle a log record.

I imagine a new method on testing.T that takes a context.Context and returns a new one that's annotated with a value that represents the same source location that a t.Log call would've used if called from the same callsite, but does not immediately contribute anything new to the log.

A new package-level function in testing could then allow downstream code to retrieve that information given a context.

package testing

func (c *T) LocationContext(ctx context.Context) context.Context
func (c *B) LocationContext(ctx context.Context) context.Context

func LocationFromContext(ctx context.Context) (TestLocation, bool)

type TestLocation struct {
    Filename string
    Line     int
}

func (l TestLocation) String() string {
    // (returns the same filename:line format that t.Log would normally use as a prefix)
}

When a test calls a function that takes a context.Context and that indirectly interacts with slog, the test code would construct a location-annotated context directly in the call, thus capturing the relevant source location:

func TestExample(t *testing.T) {
    ctx := context.Background()
    // ...
    got, err := ThingBeingTested(t.LocationContext(ctx))
    // ...
}

A hypothetical slog.Handler that interacts with the proposed t.Output could then call testing.LocationFromContext on the context it receives, and then generate its own annotation of what the test source location was, potentially mimicking the output format of t.Log with the source location shown as a prefix.

This exploits the ability for a context.Context to ferry cross-cutting concerns across API boundaries to let the test code communicate its source location information indirectly to the test-specific slog handler, without modifying any intermediate code¹ and without introducing slog-specific knowledge into testing or testing-specific knowledge into slog. In particular, any third-party logging system that deals in context.Context could use testing.LocationFromContext directly itself, so this design is still potentially useful for those who decide not to use slog.

Whether the standard library should then provide this hypothetical slog.Handler that writes to t.Output is a question. It seems to me like it wouldn't be a lot of code to write, but also that there's really only one "obvious" way to implement it and so little reason to have every codebase duplicate essentially that same code. I think it would need live in a separate package slogtest, since it isn't possible to implement slog.Handler without importing slog but it also wouldn't be possible to write this specific implementation without importing testing to get testing.LocationFromContext, and so trying to place it in either one would cause cyclic package dependencies.

Footnotes

1. (as long as all of the intermediate calls actually pass on the context.Context, that is...) ↩

[jba]

I'd prefer a solution that is able to include at least some source location information from the test code in the captured logs.

@apparentlymart, I think your LocationContext method qualifies as a separate proposal.

You could get very close to what you want today, by writing a slog.Handler that walks up the stack looking for the first frame from a *_test.go file, or it could include all frames from there to the top. You wouldn't quite match what t.Helper provides, but it would probably be good enough.

[apparentlymart]

Fair enough! I'd considered what I proposed as filling the gap left by the t.Output design (that it would then not be able to include test source location information in the output without some sort of further integration with package testing), but I can also see that several folks in this thread are not actually concerned by the lack of source location information and so I can see the perspective that it's something separate.

Since this issue presumably already has an audience of people who are invested in some sort of integration between testing and slog I will sit on this for now and see if there are any other reactions to it (emoji-based reactions to my comment would do, if you don't want to make comment notification noise) to judge whether it seems like there's any appetite for something like that before I write it up as a separate proposal issue.

[seankhliao]

@apparentlymart see #52751

---

If I understand correctly, the current proposal includes indenting the output, but what are the indentation rules?
That is, if I do:

fmt.Fprint(t.Output(), "foo")
t.Log("bar")

is the output

    foo
    main_test.go:123 bar

or

    foomain_test.go:123 bar

---

I recently had another use for t.Output: I wanted to run x/tools/go/analysis passes over the module's source code, and report the lines of the analysis result, not the testing setup (related #71478)

[jba]

@seankhliao I would have t.Output be to t.Log as os.Stdout is to log.Print.

That is, t.Output is an io.Writer that does not add any bytes to what you give it, whereas t.Log adds a final newline for convenience.

So the output would be

foomain_test.go:123 bar

However, t.Output should buffer a line before emitting it.

[apparentlymart]

I like that general idea of t.Output acting like a regular writer and not adding anything new itself, but given that all of these functions are presumably all cooperating to share a line buffer anyway I'd consider a tweak where the t.Log family of functions would check if there is already a partial line buffered and flush that line separately first before emitting their own full log line.

That seems more aligned with likely author intent -- at least for me, I always intend for a test log item to stand alone relative to anything else I might be emitting -- and would encourage the system to produce more intelligible output even if, for example, a quirk of the test code or the code under test causes there to be an incomplete line left in the buffer just before a t.Errorf. I would not want that error message (or any other such line-oriented output with a source location prefix) to get visually "lost" by appearing only at the end of a line of otherwise-unrelated content.

I can't personally think of any strong justification for starting a line with a write to t.Output and then completing it using t.Log -- I'd expect anyone working with partial lines to use t.Output consistently -- but perhaps I don't have sufficient imagination. 😀

[jba]

@apparentlymart That works for me. It's not that t.Output is adding a newline, it's that t.Log starts with (a hypothetical function) flushLine.

[seankhliao]

I assume use of t.Output after the test completes will panic similar to what t.Log does now?

[jba]

Yes, it should.

[gopherbot]

Change https://go.dev/cl/646956 mentions this issue: testing: add a new output writer and use it in t.Log