Skip to content

Commit 1ad9952

Browse files
maargentonmaargenton
authored
Add slogtest package for recording structured log output during tests (#28)
- Add `slogtest.Recorder` as a recording implementation of `slog.Handler`. - Add helper functions to extract all attributes from `slog.Record`. - Add helper function to install temporary recorder as default slog logger.
1 parent da3d445 commit 1ad9952

File tree

3 files changed

+322
-0
lines changed

3 files changed

+322
-0
lines changed

‎.vscode/settings.json‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,7 @@
44
"errorf",
55
"keypath",
66
"niladic",
7+
"slogtest",
78
"struct",
89
"subexpr",
910
"testpredicate"

‎pkg/slogtest/recorder.go‎

Lines changed: 177 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,177 @@
1+
//go:build go1.21
2+
3+
// Package slogtest provides support for recording structured log slog messages
4+
// during tests and verifying that the expected messages have been emitted.
5+
//
6+
// `slogtest.Recorder` is a full-featured `slog.Handler` that records every
7+
// structured log message and supports both shared attributes with `With()` and
8+
// nested groups with `WithGroup()`.
9+
//
10+
// `slogtest.GetAllAttrs` and `slogtest.GetFlattenAttrs` are helper functions to
11+
// retrieve all the attributes of a record as a map, with fully resolved values.
12+
//
13+
// `slogtest.WithSlogRecorder()` evaluate a function with a temporary
14+
// `slogtest.Recorder` installed as the default logger of the slog packages.
15+
package slogtest
16+
17+
import (
18+
"context"
19+
"log"
20+
"log/slog"
21+
"os"
22+
"sync"
23+
)
24+
25+
// Recorder is an implementation of slog.Handler that records each log entry for
26+
// later verification during unit tests.
27+
type Recorder struct {
28+
records []slog.Record
29+
mu sync.Mutex
30+
}
31+
32+
var _ slog.Handler = (*Recorder)(nil)
33+
34+
func (h *Recorder) Enabled(context.Context, slog.Level) bool { return true }
35+
func (h *Recorder) WithAttrs(attrs []slog.Attr) slog.Handler {
36+
return &nestedRecorder{parent: h, attrs: attrs}
37+
}
38+
39+
func (h *Recorder) WithGroup(name string) slog.Handler {
40+
return &nestedRecorder{parent: h, group: name}
41+
}
42+
43+
func (h *Recorder) Handle(ctx context.Context, r slog.Record) error {
44+
h.mu.Lock()
45+
defer h.mu.Unlock()
46+
47+
h.records = append(h.records, r)
48+
return nil
49+
}
50+
51+
func (h *Recorder) GetRecords() []slog.Record {
52+
h.mu.Lock()
53+
defer h.mu.Unlock()
54+
return h.records
55+
}
56+
57+
// GetFlattenAttrs returns all the attributes of a record as a single-level map,
58+
// where keys of nested groups are expanded to a dot-separated syntax, and all
59+
// the values are fully resolved.
60+
func GetFlattenAttrs(r slog.Record) map[string]any {
61+
var attrs = make(map[string]any)
62+
var attrList []slog.Attr
63+
64+
r.Attrs(func(attr slog.Attr) bool {
65+
attrList = append(attrList, attr)
66+
return true
67+
})
68+
flattenAttrs(attrs, "", attrList)
69+
return attrs
70+
}
71+
72+
func flattenAttrs(attrs map[string]any, prefix string, group []slog.Attr) {
73+
for _, attr := range group {
74+
var key = prefix + attr.Key
75+
if attr.Value.Kind() == slog.KindGroup {
76+
flattenAttrs(attrs, key+".", attr.Value.Group())
77+
} else {
78+
attrs[key] = attr.Value.Resolve().Any()
79+
}
80+
}
81+
}
82+
83+
// GetAllAttrs returns all the attributes of a record as a map, preserving the
84+
// hierarchy of groups, with fully resolved values.
85+
func GetAllAttrs(r slog.Record) map[string]any {
86+
var attrs = make(map[string]any)
87+
r.Attrs(func(attr slog.Attr) bool {
88+
attrs[attr.Key] = expandAttrValue(attr.Value)
89+
return true
90+
})
91+
return attrs
92+
}
93+
94+
func expandAttrValue(v slog.Value) any {
95+
if v.Kind() == slog.KindGroup {
96+
var attrs = make(map[string]any)
97+
for _, attr := range v.Group() {
98+
attrs[attr.Key] = expandAttrValue(attr.Value)
99+
}
100+
return attrs
101+
} else {
102+
return v.Resolve().Any()
103+
}
104+
}
105+
106+
// WithSlogRecorder creates and install a new log recorder as the global
107+
// slog.Default(), and passes the recorder to the nested function. Upon return,
108+
// it restores the prior slog.Default() and attempts to restore the state of the
109+
// log package as well -- if a log.SetOutput() was installed after a call to
110+
// slog.SetDefault(), the output will not be restored. Note that this function
111+
// has global side-effects and may not behave as expected with concurrently
112+
// executing tests.
113+
func WithSlogRecorder(f func(logs *Recorder)) {
114+
var r = &Recorder{}
115+
var defaultLogger = slog.Default()
116+
var defaultLogFlags = log.Flags()
117+
118+
slog.SetDefault(slog.New(r))
119+
defer func() {
120+
// Restore log output to os.Stderr before restoring prior slog; this is
121+
// intended to cover 2 cases:
122+
//
123+
// - the restored slog is the default logger in which case the log
124+
// package is not updated but should be restored to operating
125+
// independently and log to stderr by default.
126+
// - the restored slog is a custom logger, in which case slog
127+
// reconfigure the log package logger to use the custom logger as
128+
// output.
129+
log.SetFlags(defaultLogFlags)
130+
log.SetOutput(os.Stderr)
131+
slog.SetDefault(defaultLogger)
132+
}()
133+
134+
f(r)
135+
}
136+
137+
type nestedRecorder struct {
138+
parent slog.Handler
139+
attrs []slog.Attr
140+
group string
141+
}
142+
143+
var _ slog.Handler = (*nestedRecorder)(nil)
144+
145+
func (h *nestedRecorder) Enabled(ctx context.Context, l slog.Level) bool {
146+
return h.parent.Enabled(ctx, l)
147+
}
148+
149+
func (h *nestedRecorder) WithAttrs(attrs []slog.Attr) slog.Handler {
150+
return &nestedRecorder{parent: h, attrs: attrs}
151+
}
152+
153+
func (h *nestedRecorder) WithGroup(name string) slog.Handler {
154+
return &nestedRecorder{parent: h, group: name}
155+
}
156+
157+
func (h *nestedRecorder) Handle(ctx context.Context, r slog.Record) error {
158+
if h.group != "" || len(h.attrs) > 0 {
159+
var rr = slog.NewRecord(r.Time, r.Level, r.Message, r.PC)
160+
if len(h.attrs) > 0 {
161+
rr.AddAttrs(h.attrs...)
162+
r.Attrs(func(a slog.Attr) bool {
163+
rr.AddAttrs(a)
164+
return true
165+
})
166+
} else if h.group != "" {
167+
var attrs []any
168+
r.Attrs(func(a slog.Attr) bool {
169+
attrs = append(attrs, a)
170+
return true
171+
})
172+
rr.AddAttrs(slog.Group(h.group, attrs...))
173+
}
174+
r = rr
175+
}
176+
return h.parent.Handle(ctx, r)
177+
}

‎pkg/slogtest/recorder_test.go‎

Lines changed: 144 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,144 @@
1+
//go:build go1.21
2+
3+
package slogtest_test
4+
5+
import (
6+
"log"
7+
"log/slog"
8+
"testing"
9+
"time"
10+
11+
"github.com/maargenton/go-testpredicate/pkg/bdd"
12+
"github.com/maargenton/go-testpredicate/pkg/require"
13+
"github.com/maargenton/go-testpredicate/pkg/verify"
14+
15+
"github.com/maargenton/go-testpredicate/pkg/slogtest"
16+
)
17+
18+
func TestGetFlattenAttrs(t *testing.T) {
19+
bdd.Given(t, "a slog.Record", func(t *bdd.T) {
20+
var r = slog.NewRecord(time.Now(), slog.LevelInfo, "message", 0)
21+
r.Add("foo", 123, "bar", slog.GroupValue(slog.String("baz", "baz-value")))
22+
t.When("calling GetFlattenAttrs", func(t *bdd.T) {
23+
t.Then("group attributes are expanded to dot-separated keys", func(t *bdd.T) {
24+
var attrs = slogtest.GetFlattenAttrs(r)
25+
require.That(t, attrs).MapKeys().IsEqualSet([]string{
26+
"foo", "bar.baz",
27+
})
28+
})
29+
t.Then("values are fully resolved, preserving type", func(t *bdd.T) {
30+
var attrs = slogtest.GetFlattenAttrs(r)
31+
require.That(t, attrs).Field("foo").Eq(123)
32+
require.That(t, attrs).Field("bar.baz").Eq("baz-value")
33+
})
34+
})
35+
})
36+
}
37+
38+
func TestGetAllAttrs(t *testing.T) {
39+
bdd.Given(t, "a slog.Record", func(t *bdd.T) {
40+
var r = slog.NewRecord(time.Now(), slog.LevelInfo, "message", 0)
41+
r.Add("foo", 123, "bar", slog.GroupValue(slog.String("baz", "baz-value")))
42+
t.When("calling GetAllAttrs", func(t *bdd.T) {
43+
t.Then("all attributes are stored in resulting map", func(t *bdd.T) {
44+
var attrs = slogtest.GetAllAttrs(r)
45+
require.That(t, attrs).MapKeys().IsEqualSet([]string{
46+
"foo", "bar",
47+
})
48+
})
49+
t.Then("gropup values are stored in nested maps, fully resolved, preserving type", func(t *bdd.T) {
50+
var attrs = slogtest.GetAllAttrs(r)
51+
require.That(t, attrs).Field("foo").Eq(123)
52+
require.That(t, attrs).Field("bar.baz").Eq("baz-value")
53+
})
54+
})
55+
})
56+
}
57+
58+
func TestRecorder(t *testing.T) {
59+
bdd.Given(t, "a recorder", func(t *bdd.T) {
60+
var r = &slogtest.Recorder{}
61+
var l = slog.New(r)
62+
63+
t.When("calling log.Info()", func(t *bdd.T) {
64+
l.Info("message", "key", "value")
65+
66+
t.Then("log is recorded as info, with message and attribute", func(t *bdd.T) {
67+
var rr = r.GetRecords()
68+
require.That(t, rr).Length().Eq(1)
69+
70+
var record = rr[0]
71+
verify.That(t, record.Level).Eq(slog.LevelInfo)
72+
verify.That(t, record.Message).Eq("message")
73+
74+
var attrs = slogtest.GetFlattenAttrs(record)
75+
verify.That(t, attrs).Field("key").Eq("value")
76+
})
77+
})
78+
t.When("calling log.Info() indirectly from With()", func(t *bdd.T) {
79+
l.With("kk", "vv").Info("message", "key", "value")
80+
81+
t.Then("log record include share attributes", func(t *bdd.T) {
82+
var rr = r.GetRecords()
83+
require.That(t, rr).Length().Eq(1)
84+
85+
var attrs = slogtest.GetFlattenAttrs(rr[0])
86+
verify.That(t, attrs).MapKeys().IsEqualSet([]string{"key", "kk"})
87+
verify.That(t, attrs).Field("key").Eq("value")
88+
verify.That(t, attrs).Field("kk").Eq("vv")
89+
})
90+
})
91+
92+
t.When("calling log.Info() indirectly from WithGroup()", func(t *bdd.T) {
93+
l.WithGroup("group").Info("message", "key", "value")
94+
95+
t.Then("log record include attributes prefixed by group name", func(t *bdd.T) {
96+
var rr = r.GetRecords()
97+
require.That(t, rr).Length().Eq(1)
98+
99+
var attrs = slogtest.GetFlattenAttrs(rr[0])
100+
verify.That(t, attrs).MapKeys().IsEqualSet([]string{"group.key"})
101+
verify.That(t, attrs).Field("group.key").Eq("value")
102+
})
103+
})
104+
105+
t.When("calling log.Info() indirectly from mix of With and WithGroup()", func(t *bdd.T) {
106+
l.With("kk", "vv").WithGroup("group").With("gkk", "gvv").Info("message", "key", "value")
107+
108+
t.Then("log record include attributes prefixed by group name", func(t *bdd.T) {
109+
var rr = r.GetRecords()
110+
require.That(t, rr).Length().Eq(1)
111+
112+
var attrs = slogtest.GetFlattenAttrs(rr[0])
113+
verify.That(t, attrs).MapKeys().IsEqualSet([]string{
114+
"group.key", "group.gkk", "kk",
115+
})
116+
verify.That(t, attrs).Field("group.key").Eq("value")
117+
verify.That(t, attrs).Field("group.gkk").Eq("gvv")
118+
verify.That(t, attrs).Field("kk").Eq("vv")
119+
})
120+
})
121+
})
122+
}
123+
124+
func TestWithDefaultRecorder(t *testing.T) {
125+
bdd.Given(t, "something", func(t *bdd.T) {
126+
log.Printf("before log test1")
127+
slog.Info("before slog test2")
128+
129+
var r *slogtest.Recorder
130+
slogtest.WithSlogRecorder(func(logs *slogtest.Recorder) {
131+
log.Printf("captured log test3")
132+
slog.Info("captured slog test4")
133+
r = logs
134+
})
135+
log.Printf("after log test5")
136+
slog.Info("after sog test6")
137+
138+
t.When("doing something", func(t *bdd.T) {
139+
t.Then("something happens", func(t *bdd.T) {
140+
require.That(t, r.GetRecords()).Length().Eq(2)
141+
})
142+
})
143+
})
144+
}

0 commit comments

Comments
 (0)