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.

[bitfield]

In a test, you often want to mock out the logger

Speak for yourself...

[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.