proposal: testing: Add T.Output() etc

[carlmjohnson]

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.

[carlmjohnson]

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.

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

[ChrisHines]

Will you also add a new method to the testing.TB interface?

[carlmjohnson]

I think as long as Output doesn't add line numbers, it's good.

[jba]

@ChrisHines I don't see how we could add a method to TB without breaking backwards compatibility.

[ChrisHines]

@jba The authors of testing.TB carved it out of the backwards compatibility contract, see: https://cs.opensource.google/go/go/+/refs/tags/go1.20.6:src/testing/testing.go;drc=38cfb3be9d486833456276777155980d1ec0823e;l=880

	// A private method to prevent users implementing the
	// interface and so future additions to it will not
	// violate Go 1 compatibility.
	private()

As far as I know the only way to implement testing.TB outside of the testing package is to embed it in another type, but in that scenario adding a new method to TB also adds the method to any type that embeds it. :)

[ChrisHines]

To answer the unasked question "why should we add Output" to testing.TB? ...

The practice of writing a logger adapter to forward messages to t.Log is pretty common (I think). It's certainly not new, I've been doing it for years. Our internal logging package (which is basically a blending of uber/zap and go-kit/log) provides just such a wrapper that looks essentially like:

func TestLogger(t testing.TB) Logger {
    f := func(p []byte) (int, error) {
        t.Logf("%s", p)
        return len(p), nil
    }
    testLogger := NewLogger(writerfunc(f))
    return DuplicateKeyDetector(testLogger, t)
}

type writerfunc func([]byte) (int, error)

func (f writerfunc) Write(p []byte) (n int, err error) { return f(p) }

func DuplicateKeyDetector(next Logger, t testing.TB) Logger { ... }

With the current proposal we could delete the local f function and writerFunc type and just pass t.Output directly to NewLogger. If the method is added to testing.TB this would not require a local interface declaration and type assertion.

Also of note: DuplicateKeyDetector fails any test for code that tries to log a record with conflicting log keys. The test code for DuplicateKeyDetector mocks testing.TB as seen below. This code would not be broken by adding a new method to testing.TB.

type mockTBInterface struct {
	ErrorStrings []string
	testing.TB
}

func (m *mockTBInterface) Errorf(format string, args ...any) {
	m.ErrorStrings = append(m.ErrorStrings, fmt.Sprintf(format, args...))
}

[riannucci]

This may be a similar/overlapping proposal with #43936 where slog output on testing was suggested as a possible way to accomplish test metadata output.

[jba]

@ChrisHines I did not know about the exception for testing.TB. I guess we would add TB.Output then.

[rsc]

#43936 asks for the ability to add new JSON directly to the test2json output.
Instead of new API in testing it seems like some connection to slog would make more sense.
But that connection would look differently from just using TB.Output, so maybe we should rethink this part.

[carlmjohnson]

I'm not sure it needs to look different than TB.Output. A JSON log analyze ought to be able to read JSON nested inside of JSON.

[carlmjohnson]

Maybe to help the log analyzers, add a new action for TB.Output. Something like

{
  "Time":"2023-07-25T16:54:03.554841-04:00",
  "Action":"log",
  "Package":"example.com/foo",
  "Output":"{\"nested\": true}"
}

Instead of "Action": "output".

[jba]

Here's an alternative design that aims to satisfy #43936 as well as this issue.

If t is a testing.T (or B or F), then t.Slog() returns a *slog.Logger. The logger's handler cannot be modified. Its output is coordinated with the rest of the test output. It has no minimum level—all log events are output. It uses the TextHandler format normally, or JSON if the -json flag is present, in which case it appears like

{"action": "log", "record": {"message": "debugging  info", "level":"INFO", "requestID": 123}}

It is now easy to annotate tests with metadata as #43936 asks for, with code like

t.Slog().Info("debugging info",  "requestID", 123)

To satisfy the needs of this proposal, the logger returned by t.Slog() can be passed directly to the code under test. Or the handler can be wrapped to set a minimum level, modify the record, or whatever else is desired, by writing

logger := slog.New(newWrappingHandler(t.Slog().Handler()))

[dnephin]

Trying to satisfy both cases likely makes it not ideal for either.

As noted in #43936 (comment) the testing package doesn't emit JSON directly, so t.Slog() would not be able to emit JSON. It would have to emit some logging format that can be parsed by cmd/test2json. Can the TextHandler output be easily and unambiguously parsed into JSON? How would these lines be distinguished from the existing text output that uses === RUN, etc for framing of events?

A tool attempting to use this new action=log output for metadata would need to be concerned about every possible attribute used by any library that emits logs to slog.Logger. At the very least anyone trying to use it for metadata would have to construct long unique keys to ensure that some library doesn't use the same attribute key. A t.Metadata wouldn't have these problems because only the test cases and maybe a few testing helpers would have access to t.Metadata.
Edit: I guess this is already true for any library using slog, and a convention of a test.metadata prefix for keys would be easy enough.

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. Today logs from a test run would be included in action=output events. When a user switches to t.Slog() the logs will be output from an action=log event. At the very least the TestEvent.Output field of these events should contain the text output of the log. Even then, if the tool that's consuming these events is strict about the actions, there's a reasonable chance it will discard these new events with action=log instead of treating them like action=output. That seems like it could be considered a breaking change. An action=metadata doesn't have this problem because test metadata isn't an important part of the test output. A system reading the test2json output only needs to be concerned about the metadata it knows how to consume, it wouldn't need to be updated to maintain correct behaviour.

Using t.Slog to emit metadata is not different from what is possible today. A test author can already emit JSON and the system that wants to read that metadata can decode the JSON from the Output field.

Both #43936 and this proposal are similar in that they deal with structured data, but otherwise the use cases are quite different.

[riannucci]

So perhaps the dichotomy could be summarized as:

1. There is a need to be able to associate Stdout (and Stderr) of the code under test with the test case itself... short of backwards incompatible changes to how os.Stdout/Stderr work, the next best thing would be to expose output object(s) directly on testing.TB which can be passed to the code under test. The intent would be to allow this output from the code under test to display with the actual test output, ideally without breaking existing tools reading this via test2json (and also having a chance to work correctly with parallel tests!)
2. There is a need to be able to have tests emit Metadata to a compatible reader; ideally this has a different "channel" than raw output to allow out of band communication between the test and some test observer.

Slog was mentioned in both places... but I think that @dnephin is right here - fundamentally the requirements are different. The intent is to have separate channels for these different types of data. And it's not clear that code under test should have the ability to emit Metadata for the test incidentally by using slog (I would argue that it should not; test Metadata should require using the testing.TB directly because the code should be aware its talking to a test observer... though I'm willing to be wrong here!). So consider my earlier comment a (likely) red herring :)

Edit: typo

[AndrewHarrisSPU]

I'm more optimistic about t.Slog when thinking about a tool like jq reprocessing output. I also wonder if the TestEvent struct defined in cmd/internal/test2json is like helper-aware file:line stuff - is it unwise to expose these details? TestEvent could be in testing, along with a way to define a callback for when a TestEvent is generated.

[carlmjohnson]

2. There is a need to be able to have tests emit Metadata to a compatible reader; ideally this has a different "channel" than raw output to allow out of band communication between the test and some test observer.

That suggests calling it TB.StdOut() and TB.StdErr().

[rsc]

If we add these it should definitely not be spelled with different casing than the top-level os variables (Stdout and Stderr).