testing/slogtest: unable to get TestHandler suite passing when Handler doesn't emit slog.TimeKey

[matthewmueller]

What version of Go are you using (go version)?

$ go version
go version go1.21rc3 darwin/amd64

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (go env)?

go env Output

$ go env
GO111MODULE=''
GOARCH='amd64'
GOBIN=''
GOCACHE='/Users/m/Library/Caches/go-build'
GOENV='/Users/m/Library/Application Support/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='amd64'
GOHOSTOS='darwin'
GOINSECURE=''
GOMODCACHE='/Users/m/dev/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='darwin'
GOPATH='/Users/m/dev'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/usr/local/go'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/usr/local/go/pkg/tool/darwin_amd64'
GOVCS=''
GOVERSION='go1.21rc3'
GCCGO='gccgo'
GOAMD64='v1'
AR='ar'
CC='clang'
CXX='clang++'
CGO_ENABLED='1'
GOMOD='/Users/m/dev/src/github.com/matthewmueller/willpower/go.mod'
GOWORK=''
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
PKG_CONFIG='pkg-config'
GOGCCFLAGS='-fPIC -arch x86_64 -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -ffile-prefix-map=/var/folders/3p/215s80gx7rx2qs2g9v5r601c0000gp/T/go-build2582099463=/tmp/go-build -gno-record-gcc-switches -fno-common'

What did you do?

I'm creating a new slog.Handler that intentionally doesn't print the time out. I'm trying to use slogtest.TestHandler to test the new handler, but I'm running up against a test that I don't think I can make pass without altering the Handle method to include the time.

What did you expect to see?

I expect there to be some way to get the test suite passing without requiring the handler to print out the time.

What did you see instead?

The problematic test is:

{
	explanation: withSource("a Handler should ignore a zero Record.Time"),
	f: func(l *slog.Logger) {
		l.Info("msg", "k", "v")
	},
	mod: func(r *slog.Record) { r.Time = time.Time{} },
	checks: []check{
		missingKey(slog.TimeKey),
	},
},

In: https://tip.golang.org/src/testing/slogtest/slogtest.go

The documentation (helpfully) says the following:

// If a Handler intentionally drops an attribute that is checked by a test,
// then the results function should check for its absence and add it to the map it returns.

So in my tests I do the following:

record[slog.TimeKey] = nil

Unfortunately, the test case above fails and I can't figure out how I'd unset this key just for this test

err: unexpected key "time": a Handler should ignore a zero Record.Time (/usr/local/go/src/testing/slogtest/slogtest.go:85)

[dr2chase]

@jba

[jba]

It's great that you're using slogtest and I would hate it if you had to stop using it because of this.

We can't change the package until the next release, and I don't see how we would change it for this. Maybe the function needs to take options like "I don't plan on displaying the time, ever." I don't want to do that, because every such option weakens the Handler contract. I'm open to other suggestions.

Anyway, you need a workaround for the next six months. Here are two ideas:

1. (very hacky) You know this is the n th test. That's not changing for at least six months. So you can hard-code your results function to skip the line that assigns to slog.TimeKey just for that test.
2. (less hacky) Add a testMode boolean to your handler, or as a global. When set, the handler follows the rules for time.

[matthewmueller]

Hey @jba, thanks for the ideas on hacky solutions! I think both would work for this case. I was hoping to flag this before the release, but oh well.

For future consideration towards removing this test:

This test feels like an oddball of the current test suite. It's the only test that checks for a missing key on a non-attr property. As a result, the slog.TimeKey is the only key that's required to be rendered in some way by the resulting handler.

Some examples where this assumption breaks down:

• https://github.com/livebud/log: The console handler is the one that prompted this issue
• https://github.com/apex/log: The text and delta handlers show time as the delta from start and time in-between logs. I don't think these log handlers would work either.

[jba]

Thanks @matthewmueller, I'll think on it.

/cc @ianthehat

[gopherbot]

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

[komuw]

Maybe the function needs to take options like "I don't plan on displaying the time, ever." I don't want to do that, because every such option weakens the Handler contract. I'm open to other suggestions.

I do not have suggestions, I just want to note a use case I ran into that proved to be hard to test with slogtest.
I wanted to create a Handler that wraps slog.JSONHandler and only logs errors(slog.LevelError). The actual usecase is a bit more involved but the minimized description and repro is enough to show the issue.
Link to playground; https://go.dev/play/p/OUVqbIUeKc4

// errHandler wraps [slog.JSONHandler] to only log errors.
type errHandler struct {
	*slog.JSONHandler
}

func (h errHandler) Enabled(_ context.Context, l slog.Level) bool {
	if l >= slog.LevelError {
		return true
	}
	return false
}

Testing this with slogtest fails with got 6 results, want 15
But if I fork slogtest and replace every call of l.Info() (like this one https://github.com/golang/go/blob/go1.21.0/src/testing/slogtest/slogtest.go#L56) with l.Error() then it works.

I would love an option to tell slogtest.TestHandler() that the output method to use is Logger.Error

[jba]

@komuw Your handler seems to be a specialization of this example.

I think wrapping handlers like those that don't actually affect the format don't need testing/slogtest. You can just write tests for the particular changes to behavior that they implement, and trust that the handler they wrap has passed slogtest.