funcr: slog output omits intermediate groups

[avorima]

I'm working on implementing a SlogSink for another logger and looked to funcr for guidance on how to handle certain cases with groups but found that it behaves unexpectedly.

I added the following lines to ExampleToSlogHandler:

slogLogger.WithGroup("a").Info("single empty group")
slogLogger.WithGroup("a").WithGroup("b").Info("chained empty groups")
slogLogger.WithGroup("a").WithGroup("b").With("str", "abc").Info("first group empty")
slogLogger.WithGroup("a").With("str", "abc").WithGroup("b").Info("last group empty")
slogLogger.WithGroup("a").With("str", "abc").WithGroup("b").WithGroup("c").With("x", 1).Info("middle group empty")

The output I got was:

"level"=0 "msg"="single empty group"
"level"=0 "msg"="chained empty groups"}
"level"=0 "msg"="first group empty" "b"={"str"="abc"}}
"level"=0 "msg"="last group empty" "a"={"str"="abc"}
"level"=0 "msg"="middle group empty" "a"={"str"="abc" "c"={"x"=1}}}

Apart from the trailing curly brackets I expected funcr to behave like a slog.TextHandler, so something like:

"level"=0 "msg"="single empty group"
"level"=0 "msg"="chained empty groups"
"level"=0 "msg"="first group empty" "a"={"b"={"str"="abc"}}
"level"=0 "msg"="last group empty" "a"={"str"="abc"}
"level"=0 "msg"="middle group empty" "a"={"str"="abc" "b"={"c"={"x"=1}}}

I'm assuming the omission of the intermediate group is causing the trailing } problem.

[thockin]

What I see is:

$ cat repro/repro.go 
package main

import (
	"fmt"
	"log/slog"

	"github.com/go-logr/logr"
	"github.com/go-logr/logr/funcr"
)

func main() {
	logger := funcr.NewJSON(
		func(arg string) { fmt.Println(arg) },
		funcr.Options{})
	slogger := slog.New(logr.ToSlogHandler(logger))

	slogger.WithGroup("a").Info("single empty group")
	slogger.WithGroup("a").WithGroup("b").Info("chained empty groups")
	slogger.WithGroup("a").WithGroup("b").With("str", "abc").Info("first group empty")
	slogger.WithGroup("a").With("str", "abc").WithGroup("b").Info("last group empty")
	slogger.WithGroup("a").With("str", "abc").WithGroup("b").WithGroup("c").With("x", 1).Info("middle group empty")
}

$ go run ./repro/
{"logger":"","level":0,"msg":"single empty group"}
{"logger":"","level":0,"msg":"chained empty groups"}}
{"logger":"","level":0,"msg":"first group empty","b":{"str":"abc"}}}
{"logger":"","level":0,"msg":"last group empty","a":{"str":"abc"}}
{"logger":"","level":0,"msg":"middle group empty","a":{"str":"abc","c":{"x":1}}}}

Oh, looking closely I do see this. huh. I think you punched a hole in my pre-render-everything approach. To my own defense, we pass slogtest.TestHandler - you should file a bug against Go to cover this case! :)

I will have to think about how to solve this.

[thockin]

I figured it out:

$ cat repro/repro.go 
package main

import (
	"fmt"
	"log/slog"

	"github.com/go-logr/logr"
	"github.com/go-logr/logr/funcr"
)

func main() {
	logger := funcr.NewJSON(
		func(arg string) { fmt.Println(arg) },
		funcr.Options{})
	slogger := slog.New(logr.ToSlogHandler(logger))

	slogger.WithGroup("a").Info("single empty group")
	slogger.WithGroup("a").WithGroup("b").Info("chained empty groups")
	slogger.WithGroup("a").WithGroup("b").With("str", "abc").Info("first group empty")
	slogger.WithGroup("a").With("str", "abc").WithGroup("b").Info("last group empty")
	slogger.WithGroup("a").With("str", "abc").WithGroup("b").WithGroup("c").With("x", 1).Info("middle group empty")

	slogger.
		With("x", 1).
		WithGroup("g1").
		With("g1x", 2).
		WithGroup("g2").
		WithGroup("g3").
		With("g3x", 1).
		WithGroup("g4").
		WithGroup("g5").
		Info("kitchen sink")
}

$ go run ./repro/
{"logger":"","level":0,"msg":"single empty group"}
{"logger":"","level":0,"msg":"chained empty groups"}
{"logger":"","level":0,"msg":"first group empty","a":{"b":{"str":"abc"}}}
{"logger":"","level":0,"msg":"last group empty","a":{"str":"abc"}}
{"logger":"","level":0,"msg":"middle group empty","a":{"str":"abc","b":{"c":{"x":1}}}}
{"logger":"","level":0,"msg":"kitchen sink","x":1,"g1":{"g1x":2,"g2":{"g3":{"g3x":1}}}}

I will have to craft a test to cover this, which I can try to do tomorrow.

[thockin]

master...thockin:logr:master

[avorima]

I looked into creating a golang issue and noticed that TestRunSlogTestsOnSlogHandlerLogSink fails on go 1.22. Both on master and your PR @thockin.

slog.go:62: Unexpected error: missing group "G": a Handler should not output groups if there are no attributes 

Which is this test case: https://github.com/golang/go/blob/go1.22.0/src/testing/slogtest/slogtest.go#L161

[thockin]

Weird, when I run 1.22 I see the test fail, but when I look at the output generated I see `{"logger":"slog","ts":"2024-03-01 08:27:53.763813","caller":{"file":"main_slog.go","line":42},"level":0,"msg":"msg","mode":"slog","a":"b","G":{"c":"d"}}`

…

On Fri, Mar 1, 2024 at 3:00 AM Mario Valderrama ***@***.***> wrote: I looked into creating a golang issue and noticed that TestRunSlogTestsOnSlogHandlerLogSink fails on go 1.22. Both on master and your PR @thockin <https://github.com/thockin>. slog.go:62: Unexpected error: missing group "G": a Handler should not output groups if there are no attributes Which is this test case: https://github.com/golang/go/blob/go1.22.0/src/testing/slogtest/slogtest.go#L161 — Reply to this email directly, view it on GitHub <#273 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ABKWAVBTXXJLDR56IBABLY3YWBNTVAVCNFSM6AAAAABD6MZKQWVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTSNZSHE3TQMJTGY> . You are receiving this because you were mentioned.Message ID: ***@***.***>

[thockin]

Yeah, the tescase seems broken - I have the right output. Will investigate later.

[thockin]

OK. The test fail on 1.22 is because they added a new testcase that our slog handler adapter doesn't cover.

Go should add a testcase for nested groups and trailing "empty" groups, I think. funcr itself passes slogtest right now, but it should not.