testing/slogtest: support sub-tests

[pohly]

Proposal

See #61758 (comment)

Original problem statement

I'm in the early stages of adding slog support to zapr. I know that I am not handling all corner cases yet and started using testing/slogtest to see whether that finds the known (and perhaps some unknown) gaps.

Here's what my test currently looks like:

package zapr_test

import (
	"bytes"
	"encoding/json"
	"log/slog"
	"testing"
	"testing/slogtest"

	"github.com/go-logr/logr"
	"github.com/go-logr/zapr"
	"go.uber.org/zap"
	"go.uber.org/zap/zapcore"
)

func TestSlogHandler(t *testing.T) {
	var buffer bytes.Buffer
	encoder := zapcore.NewJSONEncoder(zapcore.EncoderConfig{
		MessageKey: slog.MessageKey,
		TimeKey:    slog.TimeKey,
		LevelKey:   slog.LevelKey,
		EncodeLevel: func(level zapcore.Level, encoder zapcore.PrimitiveArrayEncoder) {
			encoder.AppendInt(int(level))
		},
	})
	core := zapcore.NewCore(encoder, zapcore.AddSync(&buffer), zapcore.Level(0))
	zl := zap.New(core)
	logger := zapr.NewLogger(zl)
	handler := logr.ToSlogHandler(logger)

	err := slogtest.TestHandler(handler, func() []map[string]any {
		zl.Sync()
		return parseOutput(t, buffer.Bytes())
	})
	t.Logf("Log output:\n%s\nAs JSON:\n%v\n", buffer.String(), parseOutput(t, buffer.Bytes()))
	if err != nil {
		t.Errorf("Error report from testing/slogtest.TestHandler:\n%s", err.Error())
	}
}

func parseOutput(t *testing.T, output []byte) []map[string]any {
	var result []map[string]any
	// The last slice entry will be empty, ignore it.
	lines := bytes.Split(output, []byte("\n"))
	for i := 0; i < len(lines)-1; i++ {
		line := lines[i]
		var entry map[string]any
		if err := json.Unmarshal(line, &entry); err != nil {
			t.Fatalf("JSON decoding error: %v", err)
		}
		result = append(result, entry)
	}
	return result
}

Here's how it fails:

--- FAIL: TestSlogHandler (0.00s)
    slog_test.go:54: Log output:
        {"level":0,"time":1691154817356555161,"msg":"message"}
        {"level":0,"time":1691154817356574869,"msg":"message","k":"v"}
        {"level":0,"time":1691154817356582056,"msg":"msg","a":"b","":null,"c":"d"}
        {"level":0,"time":-6795364578871345152,"msg":"msg","k":"v"}
        {"level":0,"time":1691154817356635297,"msg":"msg","a":"b","k":"v"}
        {"level":0,"time":1691154817356645449,"msg":"msg","a":"b","G":{"c":"d"},"e":"f"}
        {"level":0,"time":1691154817356651881,"msg":"msg","a":"b","e":"f"}
        {"level":0,"time":1691154817356657033,"msg":"msg","a":"b","c":"d","e":"f"}
        {"level":0,"time":1691154817356663905,"msg":"msg","G":{"a":"b"}}
        {"level":0,"time":1691154817356685178,"msg":"msg","a":"b","G":{"c":"d","H":{"e":"f"}}}
        {"level":0,"time":1691154817356704244,"msg":"msg","a":"b","G":{"c":"d","H":{}}}
        {"level":0,"time":1691154817356711037,"msg":"msg","k":"replaced"}
        {"level":0,"time":1691154817356726582,"msg":"msg","G":{"a":"v1","b":"v2"}}
        {"level":0,"time":1691154817356734813,"msg":"msg","k":"replaced"}
        {"level":0,"time":1691154817356745464,"msg":"msg","G":{"a":"v1","b":"v2"}}
        
        As JSON:
        [map[level:0 msg:message time:1.6911548173565553e+18] map[k:v level:0 msg:message time:1.691154817356575e+18] map[:<nil> a:b c:d level:0 msg:msg time:1.6911548173565821e+18] map[k:v level:0 msg:msg time:-6.795364578871345e+18] map[a:b k:v level:0 msg:msg time:1.6911548173566354e+18] map[G:map[c:d] a:b e:f level:0 msg:msg time:1.6911548173566454e+18] map[a:b e:f level:0 msg:msg time:1.6911548173566518e+18] map[a:b c:d e:f level:0 msg:msg time:1.6911548173566572e+18] map[G:map[a:b] level:0 msg:msg time:1.6911548173566638e+18] map[G:map[H:map[e:f] c:d] a:b level:0 msg:msg time:1.691154817356685e+18] map[G:map[H:map[] c:d] a:b level:0 msg:msg time:1.6911548173567043e+18] map[k:replaced level:0 msg:msg time:1.691154817356711e+18] map[G:map[a:v1 b:v2] level:0 msg:msg time:1.6911548173567265e+18] map[k:replaced level:0 msg:msg time:1.6911548173567347e+18] map[G:map[a:v1 b:v2] level:0 msg:msg time:1.6911548173567455e+18]]
    slog_test.go:56: Error report from testing/slogtest.TestHandler:
        unexpected key "": a Handler should ignore an empty Attr (/nvme/gopath/go-1.21rc4/src/testing/slogtest/slogtest.go:74)
        unexpected key "time": a Handler should ignore a zero Record.Time (/nvme/gopath/go-1.21rc4/src/testing/slogtest/slogtest.go:85)
        unexpected key "H": a Handler should not output groups for an empty Record (/nvme/gopath/go-1.21rc4/src/testing/slogtest/slogtest.go:166)

I think the failure is accurate. But initially I had problems understanding the error string:

• It was not clear that a Handler should ignore an empty Attr is a test case instead of additional explanation and that slogtest.go:74 is where I can find out what exactly that test case covers. Example output in https://pkg.go.dev/testing/slogtest with explanations would help.
• There's no information about which specific line in the log output corresponds to that test case. Perhaps include it in the error or use the explanation as message to simplify correlating? If there is an unexpected key, it's value might shed some light on why it is present, but that's not easy to see right now.

That could be done without changing the API. But what I'd really love to have instead is an API which allows me to iterate over each test case and run each one as a sub-test. That would enable me to do dlv test . -- -test.run=TestSlogHandler/ignore.an.empty.Attr and deal with just that one failure. It'll be immediately obvious what the log output for that test case is because there will only be one line. Parsing that line will also be simpler.

cc @jba

[pohly]

Using sub-tests would also help with another problem: I cannot configure zap to skip the zero time. That's just how it is and https://pkg.go.dev/log/slog#Handler allows it ("should observe", not "must observe"). But in order to pass TestHandler, a handler "must" skip it, which is stronger than required.

If it was a sub-test with a known name, then I could skip that one test case.

[pohly]

Same with "a Handler should not output groups for an empty Record": I'm mapping slog.Handler.WithGroup to zap.Logger.Namespace and that adds the group even when its empty.

BTW, "for an empty Record" seems a bit misleading. Perhaps replace with "if they are empty"?

[pohly]

It was not clear that a Handler should ignore an empty Attr is a test case instead of additional explanation

For example, consider this error that occurs when the handler doesn't use the right field name for "time":

    slog_test.go:56: Error report from testing/slogtest.TestHandler:
        missing key "time": this test expects slog.TimeKey, slog.LevelKey and slog.MessageKey (/nvme/gopath/go-1.21rc4/src/testing/slogtest/slogtest.go:54)
        missing key "time": a Handler should handle the WithGroup method (/nvme/gopath/go-1.21rc4/src/testing/slogtest/slogtest.go:139)
...

The first error looks okay, but the second doesn't.

Another simple fix would be to swap the strings:

    slog_test.go:56: Error report from testing/slogtest.TestHandler:
        this test expects slog.TimeKey, slog.LevelKey and slog.MessageKey (/nvme/gopath/go-1.21rc4/src/testing/slogtest/slogtest.go:54): missing key "time"
        a Handler should handle the WithGroup method (/nvme/gopath/go-1.21rc4/src/testing/slogtest/slogtest.go:139): missing key "time"
...

[ianlancetaylor]

CC @jba

[jba]

See also #61706, which would benefit from skipping the ignore-zero-time test case.

[jba]

Edited: added a *testing.T arg to the callbacks.

---

OK, here's a concrete proposal. Let me know what you think.

Add a Run function to testing/slogtest

We would like to add the following function:

func Run(t *testing.T, newHandler func(*testing.T) slog.Handler, result func(*testing.T) map[string]any)

Unlike the TestHandler function, Run runs each test case in a sub-test of t. For each case, it first calls newHandler to get an instance of the handler under test, then runs the test case, then calls result to get the result. Instead of returning errors, it calls t.Error.

Rationale

Running all test cases on a handler in bulk has a couple of problems:

• When a test case fails, it can be hard to determine why. It would be helpful to be able to run just that case. If the case is a sub-test, go test -run can isolate it.

• Some handlers may choose not to implement part of the Handler contract. For example, a handler may reasonably want to omit the time entirely. It would be too bad if the handler couldn't be exercised on the other test cases because of that deviation (which is not a hard requirement on handlers). If the cases were sub-tests, go test -skip could be used to skip the problematic ones, or the newHandler callback could call t.Skip based on the value of t.Name().

[gopherbot]

Change https://go.dev/cl/516076 mentions this issue: testing/slogtest: add Run to run cases as subtests

[gopherbot]

Change https://go.dev/cl/516155 mentions this issue: testing/slogtest: reword a confusing explanation

[jba]

"for an empty Record" seems a bit misleading. Perhaps replace with "if they are empty"?

See https://go.dev/cl/516155.

[pohly]

func Run(t *testing.T, newHandler func() slog.Handler, result func() map[string]any)

Can we pass t to the callbacks? Then they can report errors and log messages properly for each test case instead of having to use the outer testing.T instance.

I'm also wondering about future extensions. We discussed skipping specific test cases. With t passed into newHandler, skipping can be done based on the current test name. That's okay. But perhaps at some point we want to add options that describe capabilities of the handler to select test cases accordingly or some other optional parameter?

Should that be considered by the API already now or is it okay to add RunWithOptions when the need arises?