testing/slogtest: support sub-tests #61758

pohly · 2023-08-04T13:21:45Z

Proposal

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

The text was updated successfully, but these errors were encountered:

pohly · 2023-08-04T13:53:22Z

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 · 2023-08-04T13:59:19Z

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 · 2023-08-04T15:53:23Z

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 · 2023-08-04T17:43:04Z

CC @jba

jba · 2023-08-04T18:04:36Z

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

jba · 2023-08-04T18:31:51Z

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 · 2023-08-04T18:33:08Z

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

gopherbot · 2023-08-04T18:42:24Z

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

jba · 2023-08-04T18:43:27Z

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

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

pohly · 2023-08-07T06:24:23Z

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?

jba · 2023-08-07T16:23:37Z

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.

That seems reasonable. I especially like that newHandler can call t.Skip, so skipping can be done in code instead of only on the command line.

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?

I hope we don't have to get that fancy. Anyway, the name will be unique, so someone who wants to skip a subset of cases can always categorize that subset by name. That might be a bit fragile but again, the code only changes once per release.

Updates #61758. Change-Id: I4ce0359f676b6832e40203e1034ba1c4f6d2b2ed Reviewed-on: https://go-review.googlesource.com/c/go/+/516155 Run-TryBot: Jonathan Amsterdam <jba@google.com> Reviewed-by: Patrick Ohly <patrick.ohly@googlemail.com> TryBot-Result: Gopher Robot <gobot@golang.org> Reviewed-by: Alan Donovan <adonovan@google.com>

rsc · 2023-08-09T21:42:07Z

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

jba · 2023-08-11T14:19:09Z

@pohly I updated my proposal to add testing.T arguments to the callbacks.

Could you edit your top post to link to the proposal, so we know exactly what this issue is proposing?

pohly · 2023-08-11T15:33:12Z

Done.

In the proposal you might add:

If the cases were sub-tests, go test -skip could be used to skip the problematic ones. Alternatively, the callback itself could check t.Name() and skip known unsupported test cases with t.Skip.

jba · 2023-08-11T17:49:00Z

@pohly Done.

rsc · 2023-08-16T17:59:01Z

Have all remaining concerns about #61758 (comment) been addressed?

pohly · 2023-08-17T06:03:56Z

Yes, looks good to me.

rsc · 2023-08-30T18:19:19Z

Based on the discussion above, this proposal seems like a likely accept.
— rsc for the proposal review group

Updates golang#61758. Change-Id: I4ce0359f676b6832e40203e1034ba1c4f6d2b2ed Reviewed-on: https://go-review.googlesource.com/c/go/+/516155 Run-TryBot: Jonathan Amsterdam <jba@google.com> Reviewed-by: Patrick Ohly <patrick.ohly@googlemail.com> TryBot-Result: Gopher Robot <gobot@golang.org> Reviewed-by: Alan Donovan <adonovan@google.com>

rsc · 2023-09-07T13:53:11Z

No change in consensus, so accepted. 🎉
This issue now tracks the work of implementing the proposal.
— rsc for the proposal review group

pohly added the Proposal label Aug 4, 2023

gopherbot added this to the Proposal milestone Aug 4, 2023

pohly mentioned this issue Aug 4, 2023

WIP: add slogr go-logr/logr#195

Closed

rsc added the Proposal-FinalCommentPeriod label Aug 30, 2023

rsc changed the title ~~proposal: testing/slogtest: support sub-tests~~ testing/slogtest: support sub-tests Sep 7, 2023

rsc modified the milestones: Proposal, Backlog Sep 7, 2023

rsc added the Proposal-Accepted label Sep 7, 2023

rsc removed the Proposal-FinalCommentPeriod label Sep 7, 2023

gopherbot closed this as completed in a742ae4 Sep 8, 2023

mknyszek mentioned this issue Nov 22, 2023

api: audit for Go 1.22 #64343

Closed

arukiidou mentioned this issue Jan 31, 2024

proposal: testing/slogtest: Add RunWithSkip func #65400

Closed

pohly mentioned this issue Mar 22, 2024

funcr: Handle nested empty groups properly go-logr/logr#274

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

testing/slogtest: support sub-tests #61758

testing/slogtest: support sub-tests #61758

pohly commented Aug 4, 2023 •

edited

pohly commented Aug 4, 2023

pohly commented Aug 4, 2023

pohly commented Aug 4, 2023

ianlancetaylor commented Aug 4, 2023

jba commented Aug 4, 2023

jba commented Aug 4, 2023 •

edited

gopherbot commented Aug 4, 2023

gopherbot commented Aug 4, 2023

jba commented Aug 4, 2023

pohly commented Aug 7, 2023

jba commented Aug 7, 2023

rsc commented Aug 9, 2023

jba commented Aug 11, 2023

pohly commented Aug 11, 2023

jba commented Aug 11, 2023

rsc commented Aug 16, 2023

pohly commented Aug 17, 2023

rsc commented Aug 30, 2023

rsc commented Sep 7, 2023

testing/slogtest: support sub-tests #61758

testing/slogtest: support sub-tests #61758

Comments

pohly commented Aug 4, 2023 • edited

Proposal

Original problem statement

pohly commented Aug 4, 2023

pohly commented Aug 4, 2023

pohly commented Aug 4, 2023

ianlancetaylor commented Aug 4, 2023

jba commented Aug 4, 2023

jba commented Aug 4, 2023 • edited

Add a Run function to testing/slogtest

Rationale

gopherbot commented Aug 4, 2023

gopherbot commented Aug 4, 2023

jba commented Aug 4, 2023

pohly commented Aug 7, 2023

jba commented Aug 7, 2023

rsc commented Aug 9, 2023

jba commented Aug 11, 2023

pohly commented Aug 11, 2023

jba commented Aug 11, 2023

rsc commented Aug 16, 2023

pohly commented Aug 17, 2023

rsc commented Aug 30, 2023

rsc commented Sep 7, 2023

pohly commented Aug 4, 2023 •

edited

jba commented Aug 4, 2023 •

edited