Skip to content

Commit

Permalink
slogr: add SlogSink
Browse files Browse the repository at this point in the history
A LogSink may implement this additional interface if it wants to support
logging through slog better. Doing so addresses several issues:

- stack unwinding gets avoided in favor of logging the pre-recorded PC
- proper grouping of key/value pairs via WithGroup
- verbosity levels > slog.LevelInfo can be recorded
- less overhead

A LogSink implementation which wants to provide a `New*Handler() slog.Handler`
function can either implement a second type (required because the prototype of
the Enabled method conflicts) or use `logr.NewSlogHandler`. The latter is
better because then conversion back-and-forth works. The overhead for the
additional wrapper should be minimal.
  • Loading branch information
pohly authored and thockin committed Aug 27, 2023
1 parent 358130c commit 7bf6c82
Show file tree
Hide file tree
Showing 3 changed files with 138 additions and 39 deletions.
36 changes: 29 additions & 7 deletions slogr/sloghandler.go
Original file line number Diff line number Diff line change
Expand Up @@ -27,7 +27,10 @@ import (
)

type slogHandler struct {
// May be nil, in which case all logs get discarded.
sink logr.LogSink
// Non-nil if sink is non-nil and implements SlogSink.
slogSink SlogSink

// groupPrefix collects values from WithGroup calls. It gets added as
// prefix to value keys when handling a log record.
Expand Down Expand Up @@ -56,6 +59,14 @@ func (l *slogHandler) Enabled(ctx context.Context, level slog.Level) bool {
}

func (l *slogHandler) Handle(ctx context.Context, record slog.Record) error {
if l.slogSink != nil {
// Only adjust verbosity level of log entries < slog.LevelError.
if record.Level < slog.LevelError {
record.Level -= l.levelBias
}
return l.slogSink.Handle(ctx, record)
}

// No need to check for nil sink here because Handle will only be called
// when Enabled returned true.

Expand Down Expand Up @@ -97,14 +108,20 @@ func (l *slogHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
if l.sink == nil || len(attrs) == 0 {
return l
}
kvList := make([]any, 0, 2*len(attrs))
for _, attr := range attrs {
if attr.Key != "" {
kvList = append(kvList, l.addGroupPrefix(attr.Key), attr.Value.Resolve().Any())

copy := *l
if l.slogSink != nil {
copy.slogSink = l.slogSink.WithAttrs(attrs)
copy.sink = copy.slogSink
} else {
kvList := make([]any, 0, 2*len(attrs))
for _, attr := range attrs {
if attr.Key != "" {
kvList = append(kvList, l.addGroupPrefix(attr.Key), attr.Value.Resolve().Any())
}
}
copy.sink = l.sink.WithValues(kvList...)
}
copy := *l
copy.sink = l.sink.WithValues(kvList...)
return &copy
}

Expand All @@ -113,7 +130,12 @@ func (l *slogHandler) WithGroup(name string) slog.Handler {
return l
}
copy := *l
copy.groupPrefix = copy.addGroupPrefix(name)
if l.slogSink != nil {
copy.slogSink = l.slogSink.WithGroup(name)
copy.sink = l.slogSink
} else {
copy.groupPrefix = copy.addGroupPrefix(name)
}
return &copy
}

Expand Down
38 changes: 37 additions & 1 deletion slogr/slogr.go
Original file line number Diff line number Diff line change
Expand Up @@ -25,6 +25,7 @@ limitations under the License.
package slogr

import (
"context"
"log/slog"

"github.com/go-logr/logr"
Expand Down Expand Up @@ -67,5 +68,40 @@ func NewSlogHandler(logger logr.Logger) slog.Handler {
return sink.handler
}

return &slogHandler{sink: logger.GetSink(), levelBias: slog.Level(logger.GetV())}
handler := &slogHandler{sink: logger.GetSink(), levelBias: slog.Level(logger.GetV())}
if slogSink, ok := handler.sink.(SlogSink); ok {
handler.slogSink = slogSink
}
return handler
}

// SlogSink is an optional interface that a LogSink can implement to support
// logging through the slog.Logger or slog.Handler APIs better. It then should
// also support special slog values like slog.Group. When used as a
// slog.Handler, the advantages are:
//
// - stack unwinding gets avoided in favor of logging the pre-recorded PC,
// as intended by slog
// - proper grouping of key/value pairs via WithGroup
// - verbosity levels > slog.LevelInfo can be recorded
// - less overhead
//
// Both APIs (logr.Logger and slog.Logger/Handler) then are supported equally
// well. Developers can pick whatever API suits them better and/or mix
// packages which use either API in the same binary with a common logging
// implementation.
//
// This interface is necessary because the type implementing the LogSink
// interface cannot also implement the slog.Handler interface due to the
// different prototype of the common Enabled method.
//
// An implementation could support both interfaces in two different types, but then
// additional interfaces would be needed to convert between those types in NewLogr
// and NewSlogHandler.
type SlogSink interface {
logr.LogSink

Handle(ctx context.Context, record slog.Record) error
WithAttrs(attrs []slog.Attr) SlogSink
WithGroup(name string) SlogSink
}
103 changes: 72 additions & 31 deletions slogr/slogr_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -21,6 +21,7 @@ package slogr_test

import (
"bytes"
"context"
"encoding/json"
"errors"
"fmt"
Expand Down Expand Up @@ -106,30 +107,78 @@ func logHelper(logger logr.Logger) {
logger.WithCallDepth(1).Info("hello")
}

func TestSlogHandler(t *testing.T) {
var buffer bytes.Buffer
funcrLogger := funcr.NewJSON(func(obj string) {
fmt.Fprintln(&buffer, obj)
}, funcr.Options{
LogTimestamp: true,
Verbosity: 10,
RenderBuiltinsHook: func(kvList []any) []any {
mappedKVList := make([]any, len(kvList))
for i := 0; i < len(kvList); i += 2 {
key := kvList[i]
switch key {
case "ts":
mappedKVList[i] = "time"
default:
mappedKVList[i] = key
}
mappedKVList[i+1] = kvList[i+1]
}
return mappedKVList
},
func TestJSONHandler(t *testing.T) {
testSlog(t, func(buffer *bytes.Buffer) logr.Logger {
handler := slog.NewJSONHandler(buffer, nil)
sink := testSlogSink{handler: handler}
return logr.New(sink)
})
handler := slogr.NewSlogHandler(funcrLogger)
}

var _ logr.LogSink = testSlogSink{}
var _ slogr.SlogSink = testSlogSink{}

// testSlogSink is only used through slog and thus doesn't need to implement the
// normal LogSink methods.
type testSlogSink struct {
handler slog.Handler
}

func (s testSlogSink) Init(logr.RuntimeInfo) {}
func (s testSlogSink) Enabled(int) bool { return true }
func (s testSlogSink) Error(error, string, ...interface{}) {}
func (s testSlogSink) Info(int, string, ...interface{}) {}
func (s testSlogSink) WithName(string) logr.LogSink { return s }
func (s testSlogSink) WithValues(...interface{}) logr.LogSink { return s }

func (s testSlogSink) Handle(ctx context.Context, record slog.Record) error {
return s.handler.Handle(ctx, record)
}
func (s testSlogSink) WithAttrs(attrs []slog.Attr) slogr.SlogSink {
return testSlogSink{handler: s.handler.WithAttrs(attrs)}
}
func (s testSlogSink) WithGroup(name string) slogr.SlogSink {
return testSlogSink{handler: s.handler.WithGroup(name)}
}

func TestFuncrHandler(t *testing.T) {
testSlog(t, func(buffer *bytes.Buffer) logr.Logger {
logger := funcr.NewJSON(func(obj string) {
fmt.Fprintln(buffer, obj)
}, funcr.Options{
LogTimestamp: true,
Verbosity: 10,
RenderBuiltinsHook: func(kvList []any) []any {
mappedKVList := make([]any, len(kvList))
for i := 0; i < len(kvList); i += 2 {
key := kvList[i]
switch key {
case "ts":
mappedKVList[i] = "time"
default:
mappedKVList[i] = key
}
mappedKVList[i+1] = kvList[i+1]
}
return mappedKVList
},
})
return logger
},
"a Handler should ignore a zero Record.Time", // Time is generated by sink.
"a Handler should handle Group attributes", // funcr doesn't.
"a Handler should inline the Attrs of a group with an empty key", // funcr doesn't know about groups.
"a Handler should not output groups for an empty Record", // Relies on WithGroup. Text may change, see https://go.dev/cl/516155
"a Handler should handle the WithGroup method", // logHandler does by prefixing keys, which is not what the test expects.
"a Handler should handle multiple WithGroup and WithAttr calls", // Same.
"a Handler should call Resolve on attribute values in groups", // funcr doesn't do that and slogHandler can't do it for it.
)
}

func testSlog(t *testing.T, createLogger func(buffer *bytes.Buffer) logr.Logger, exceptions ...string) {
var buffer bytes.Buffer
logger := createLogger(&buffer)
handler := slogr.NewSlogHandler(logger)
err := slogtest.TestHandler(handler, func() []map[string]any {
var ms []map[string]any
for _, line := range bytes.Split(buffer.Bytes(), []byte{'\n'}) {
Expand All @@ -153,15 +202,7 @@ func TestSlogHandler(t *testing.T) {
Unwrap() []error
}); ok {
for _, err := range err.Unwrap() {
if !containsOne(err.Error(),
"a Handler should ignore a zero Record.Time", // Time is generated by sink.
"a Handler should handle Group attributes", // funcr doesn't.
"a Handler should inline the Attrs of a group with an empty key", // funcr doesn't know about groups.
"a Handler should not output groups for an empty Record", // Relies on WithGroup. Text may change, see https://go.dev/cl/516155
"a Handler should handle the WithGroup method", // logHandler does by prefixing keys, which is not what the test expects.
"a Handler should handle multiple WithGroup and WithAttr calls", // Same.
"a Handler should call Resolve on attribute values in groups", // funcr doesn't do that and slogHandler can't do it for it.
) {
if !containsOne(err.Error(), exceptions...) {
t.Errorf("Unexpected error: %v", err)
}
}
Expand Down

0 comments on commit 7bf6c82

Please sign in to comment.