Skip to content

Commit

Permalink
zapslog: fix all with slogtest, support inline group, ignore empty gr…
Browse files Browse the repository at this point in the history
…oup. (#1408)

This change adds a test based on testing/slogtest
that verifies compliance with the slog handler contract
(a draft of this was available in #1335),
and fixes all resulting issues.

The two remaining issues were:

- `Group("", attrs)` should inline the new fields
  instead of creating a group with an empty name.
  This was fixed with the use of `zap.Inline`.
- Groups without any attributes should not be created.
  That is, `logger.WithGroup("foo").Info("bar")` should not
  create an empty "foo" namespace (`"foo": {}`).
  This was fixed by keeping track of unapplied groups
  and applying them the first time a field is serialized.

Following this change, slogtest passes as expected.

Refs #1333
Resolves #1334, #1401, #1402
Supersedes #1263, #1335

### TESTS

- passed. arukiidou#1
- This also works in Go 1.22

---------

Signed-off-by: junya koyama <[email protected]>
Co-authored-by: Abhinav Gupta <[email protected]>
  • Loading branch information
arukiidou and abhinav authored Feb 5, 2024
1 parent 27b96e3 commit 35ded09
Show file tree
Hide file tree
Showing 2 changed files with 281 additions and 11 deletions.
62 changes: 52 additions & 10 deletions exp/zapslog/handler.go
Original file line number Diff line number Diff line change
Expand Up @@ -39,6 +39,13 @@ type Handler struct {
addCaller bool
addStackAt slog.Level
callerSkip int

// List of unapplied groups.
//
// These are applied only if we encounter a real field
// to avoid creating empty namespaces -- which is disallowed by slog's
// usage contract.
groups []string
}

// NewHandler builds a [Handler] that writes to the supplied [zapcore.Core]
Expand Down Expand Up @@ -88,6 +95,10 @@ func convertAttrToField(attr slog.Attr) zapcore.Field {
case slog.KindUint64:
return zap.Uint64(attr.Key, attr.Value.Uint64())
case slog.KindGroup:
if attr.Key == "" {
// Inlines recursively.
return zap.Inline(groupObject(attr.Value.Group()))
}
return zap.Object(attr.Key, groupObject(attr.Value.Group()))
case slog.KindLogValuer:
return convertAttrToField(slog.Attr{
Expand Down Expand Up @@ -157,34 +168,65 @@ func (h *Handler) Handle(ctx context.Context, record slog.Record) error {
ce.Stack = stacktrace.Take(3 + h.callerSkip)
}

fields := make([]zapcore.Field, 0, record.NumAttrs())
fields := make([]zapcore.Field, 0, record.NumAttrs()+len(h.groups))

var addedNamespace bool
record.Attrs(func(attr slog.Attr) bool {
fields = append(fields, convertAttrToField(attr))
f := convertAttrToField(attr)
if !addedNamespace && len(h.groups) > 0 && f != zap.Skip() {
// Namespaces are added only if at least one field is present
// to avoid creating empty groups.
fields = h.appendGroups(fields)
addedNamespace = true
}
fields = append(fields, f)
return true
})

ce.Write(fields...)
return nil
}

func (h *Handler) appendGroups(fields []zapcore.Field) []zapcore.Field {
for _, g := range h.groups {
fields = append(fields, zap.Namespace(g))
}
return fields
}

// WithAttrs returns a new Handler whose attributes consist of
// both the receiver's attributes and the arguments.
func (h *Handler) WithAttrs(attrs []slog.Attr) slog.Handler {
fields := make([]zapcore.Field, 0, len(attrs))
fields := make([]zapcore.Field, 0, len(attrs)+len(h.groups))
var addedNamespace bool
for _, attr := range attrs {
fields = append(fields, convertAttrToField(attr))
f := convertAttrToField(attr)
if !addedNamespace && len(h.groups) > 0 && f != zap.Skip() {
// Namespaces are added only if at least one field is present
// to avoid creating empty groups.
fields = h.appendGroups(fields)
addedNamespace = true
}
fields = append(fields, f)
}

cloned := *h
cloned.core = h.core.With(fields)
if addedNamespace {
// These groups have been applied so we can clear them.
cloned.groups = nil
}
return h.withFields(fields...)
return &cloned
}

// WithGroup returns a new Handler with the given group appended to
// the receiver's existing groups.
func (h *Handler) WithGroup(group string) slog.Handler {
return h.withFields(zap.Namespace(group))
}
newGroups := make([]string, len(h.groups)+1)
copy(newGroups, h.groups)
newGroups[len(h.groups)] = group

// withFields returns a cloned Handler with the given fields.
func (h *Handler) withFields(fields ...zapcore.Field) *Handler {
cloned := *h
cloned.core = h.core.With(fields)
cloned.groups = newGroups
return &cloned
}
230 changes: 229 additions & 1 deletion exp/zapslog/handler_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -23,13 +23,18 @@
package zapslog

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

"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
"go.uber.org/zap/zapcore"
"go.uber.org/zap/zaptest"
"go.uber.org/zap/zaptest/observer"
)

Expand Down Expand Up @@ -128,8 +133,8 @@ func TestEmptyAttr(t *testing.T) {
}

func TestWithName(t *testing.T) {
t.Parallel()
fac, observedLogs := observer.New(zapcore.DebugLevel)

t.Run("default", func(t *testing.T) {
sl := slog.New(NewHandler(fac))
sl.Info("msg")
Expand All @@ -150,6 +155,191 @@ func TestWithName(t *testing.T) {
})
}

func TestInlineGroup(t *testing.T) {
fac, observedLogs := observer.New(zapcore.DebugLevel)

t.Run("simple", func(t *testing.T) {
sl := slog.New(NewHandler(fac))
sl.Info("msg", "a", "b", slog.Group("", slog.String("c", "d")), "e", "f")

logs := observedLogs.TakeAll()
require.Len(t, logs, 1, "Expected exactly one entry to be logged")
assert.Equal(t, map[string]any{
"a": "b",
"c": "d",
"e": "f",
}, logs[0].ContextMap(), "Unexpected context")
})

t.Run("recursive", func(t *testing.T) {
sl := slog.New(NewHandler(fac))
sl.Info("msg", "a", "b", slog.Group("", slog.Group("", slog.Group("", slog.String("c", "d"))), slog.Group("", "e", "f")))

logs := observedLogs.TakeAll()
require.Len(t, logs, 1, "Expected exactly one entry to be logged")
assert.Equal(t, map[string]any{
"a": "b",
"c": "d",
"e": "f",
}, logs[0].ContextMap(), "Unexpected context")
})
}

func TestWithGroup(t *testing.T) {
fac, observedLogs := observer.New(zapcore.DebugLevel)

// Groups can be nested inside each other.
t.Run("nested", func(t *testing.T) {
sl := slog.New(NewHandler(fac))
sl.With("a", "b").WithGroup("G").WithGroup("in").Info("msg", "c", "d")

logs := observedLogs.TakeAll()
require.Len(t, logs, 1, "Expected exactly one entry to be logged")
assert.Equal(t, map[string]any{
"G": map[string]any{
"in": map[string]any{
"c": "d",
},
},
"a": "b",
}, logs[0].ContextMap(), "Unexpected context")
})

t.Run("nested empty", func(t *testing.T) {
sl := slog.New(NewHandler(fac))
sl.With("a", "b").WithGroup("G").WithGroup("in").Info("msg")

logs := observedLogs.TakeAll()
require.Len(t, logs, 1, "Expected exactly one entry to be logged")
assert.Equal(t, map[string]any{
"a": "b",
}, logs[0].ContextMap(), "Unexpected context")
})

t.Run("empty group", func(t *testing.T) {
sl := slog.New(NewHandler(fac))
sl.With("a", "b").WithGroup("G").With("c", "d").WithGroup("H").Info("msg")

logs := observedLogs.TakeAll()
require.Len(t, logs, 1, "Expected exactly one entry to be logged")
assert.Equal(t, map[string]any{
"G": map[string]any{
"c": "d",
},
"a": "b",
}, logs[0].ContextMap(), "Unexpected context")
})

t.Run("skipped field", func(t *testing.T) {
sl := slog.New(NewHandler(fac))
sl.WithGroup("H").With(slog.Attr{}).Info("msg")

logs := observedLogs.TakeAll()
require.Len(t, logs, 1, "Expected exactly one entry to be logged")
assert.Equal(t, map[string]any{}, logs[0].ContextMap(), "Unexpected context")
})

t.Run("reuse", func(t *testing.T) {
sl := slog.New(NewHandler(fac)).WithGroup("G")

sl.With("a", "b").Info("msg1", "c", "d")
sl.With("e", "f").Info("msg2", "g", "h")

logs := observedLogs.TakeAll()
require.Len(t, logs, 2, "Expected exactly two entries to be logged")

assert.Equal(t, map[string]any{
"G": map[string]any{
"a": "b",
"c": "d",
},
}, logs[0].ContextMap(), "Unexpected context")
assert.Equal(t, "msg1", logs[0].Message, "Unexpected message")

assert.Equal(t, map[string]any{
"G": map[string]any{
"e": "f",
"g": "h",
},
}, logs[1].ContextMap(), "Unexpected context")
assert.Equal(t, "msg2", logs[1].Message, "Unexpected message")
})
}

// Run a few different loggers with concurrent logs
// in an attempt to trip up 'go test -race' and discover any data races.
func TestConcurrentLogs(t *testing.T) {
t.Parallel()

const (
NumWorkers = 10
NumLogs = 100
)

tests := []struct {
name string
buildHandler func(zapcore.Core) slog.Handler
}{
{
name: "default",
buildHandler: func(core zapcore.Core) slog.Handler {
return NewHandler(core)
},
},
{
name: "grouped",
buildHandler: func(core zapcore.Core) slog.Handler {
return NewHandler(core).WithGroup("G")
},
},
{
name: "named",
buildHandler: func(core zapcore.Core) slog.Handler {
return NewHandler(core, WithName("test-name"))
},
},
}

for _, tt := range tests {
tt := tt
t.Run(tt.name, func(t *testing.T) {
t.Parallel()

fac, observedLogs := observer.New(zapcore.DebugLevel)
sl := slog.New(tt.buildHandler(fac))

// Use two wait groups to coordinate the workers:
//
// - ready: indicates when all workers should start logging.
// - done: indicates when all workers have finished logging.
var ready, done sync.WaitGroup
ready.Add(NumWorkers)
done.Add(NumWorkers)

for i := 0; i < NumWorkers; i++ {
i := i
go func() {
defer done.Done()

ready.Done() // I'm ready.
ready.Wait() // Are others?

for j := 0; j < NumLogs; j++ {
sl.Info("msg", "worker", i, "log", j)
}
}()
}

done.Wait()

// Ensure that all logs were recorded.
logs := observedLogs.TakeAll()
assert.Len(t, logs, NumWorkers*NumLogs,
"Wrong number of logs recorded")
})
}
}

type Token string

func (Token) LogValue() slog.Value {
Expand Down Expand Up @@ -189,3 +379,41 @@ func TestAttrKinds(t *testing.T) {
},
entry.ContextMap())
}

func TestSlogtest(t *testing.T) {
var buff bytes.Buffer
core := zapcore.NewCore(
zapcore.NewJSONEncoder(zapcore.EncoderConfig{
TimeKey: slog.TimeKey,
MessageKey: slog.MessageKey,
LevelKey: slog.LevelKey,
EncodeLevel: zapcore.CapitalLevelEncoder,
EncodeTime: zapcore.RFC3339TimeEncoder,
}),
zapcore.AddSync(&buff),
zapcore.DebugLevel,
)

// zaptest doesn't expose the underlying core,
// so we'll extract it from the logger.
testCore := zaptest.NewLogger(t).Core()

handler := NewHandler(zapcore.NewTee(core, testCore))
err := slogtest.TestHandler(
handler,
func() []map[string]any {
// Parse the newline-delimted JSON in buff.
var entries []map[string]any

dec := json.NewDecoder(bytes.NewReader(buff.Bytes()))
for dec.More() {
var ent map[string]any
require.NoError(t, dec.Decode(&ent), "Error decoding log message")
entries = append(entries, ent)
}

return entries
},
)
require.NoError(t, err, "Unexpected error from slogtest.TestHandler")
}

0 comments on commit 35ded09

Please sign in to comment.