From b42255a375f67be1a65c1995fc6bcf924890d796 Mon Sep 17 00:00:00 2001 From: Steve Moyer Date: Sat, 21 Mar 2026 07:34:59 -0400 Subject: [PATCH] feat(slog): add a deterministic slog.Record recorder --- ...og_test.go => example_slog_handler_test.go | 2 - example_slog_recorder_test.go | 25 ++++ slog.go | 100 ++++++++++++++- slog_test.go | 116 ++++++++++++++---- 4 files changed, 211 insertions(+), 32 deletions(-) rename example_slog_test.go => example_slog_handler_test.go (91%) create mode 100644 example_slog_recorder_test.go diff --git a/example_slog_test.go b/example_slog_handler_test.go similarity index 91% rename from example_slog_test.go rename to example_slog_handler_test.go index 19e936c..843f08b 100644 --- a/example_slog_test.go +++ b/example_slog_handler_test.go @@ -9,10 +9,8 @@ import ( ) func ExampleNewSlogHandler() { - nowFunc := deterministic.NowFunc() handler := deterministic.NewSlogHandler( slog.NewTextHandler(os.Stdout, nil), - nowFunc, ) logger := slog.New(handler) diff --git a/example_slog_recorder_test.go b/example_slog_recorder_test.go new file mode 100644 index 0000000..1e4e7fe --- /dev/null +++ b/example_slog_recorder_test.go @@ -0,0 +1,25 @@ +package deterministic_test + +import ( + "context" + "fmt" + "log/slog" + + "github.com/selesy/deterministic" +) + +func ExampleNewSlogRecorder() { + recorder := deterministic.NewSlogRecorder() + logger := slog.New(recorder) + + logger.InfoContext(context.Background(), "user logged in", slog.String("user_id", "123")) + logger.WarnContext(context.Background(), "high memory usage", slog.Float64("percent", 85.5)) + + for i := range recorder.Len() { + record, _ := recorder.Get(i) + fmt.Printf("[%s] %s\n", record.Level, record.Message) + } + // Output: + // [INFO] user logged in + // [WARN] high memory usage +} diff --git a/slog.go b/slog.go index 7ef8aab..8831dc6 100644 --- a/slog.go +++ b/slog.go @@ -3,9 +3,103 @@ package deterministic import ( "context" "log/slog" + "slices" + "strings" "time" ) +var _ slog.Handler = (*SlogRecorder)(nil) + +// SlogRecorder is a slog.Handler that records all log records for later retrieval. +type SlogRecorder struct { + records *[]slog.Record + attrs []slog.Attr + groups []string +} + +// NewSlogRecorder creates a new SlogRecorder. +func NewSlogRecorder() *SlogRecorder { + return &SlogRecorder{ + records: &[]slog.Record{}, + } +} + +// Enabled returns true, indicating all log levels are enabled. +func (h *SlogRecorder) Enabled(ctx context.Context, level slog.Level) bool { + return true +} + +// Get retrieves the record at the specified index. +func (h *SlogRecorder) Get(index int) (slog.Record, error) { + return (*h.records)[index], nil +} + +func (h *SlogRecorder) prefixAttrs(attrs []slog.Attr) []slog.Attr { + if len(h.groups) == 0 { + return attrs + } + prefix := strings.Join(h.groups, ".") + "." + + res := make([]slog.Attr, len(attrs)) + for i, a := range attrs { + res[i] = a + res[i].Key = prefix + a.Key + } + return res +} + +// Handle records the log record with all attributes and group prefixes applied. +func (h *SlogRecorder) Handle(ctx context.Context, record slog.Record) error { + newRec := slog.NewRecord(record.Time, record.Level, record.Message, record.PC) + + newRec.AddAttrs(h.attrs...) + + var rAttrs []slog.Attr + record.Attrs(func(a slog.Attr) bool { + rAttrs = append(rAttrs, a) + return true + }) + + newRec.AddAttrs(h.prefixAttrs(rAttrs)...) + + *h.records = append(*h.records, newRec) + + return nil +} + +// Len returns the number of recorded log records. +func (h *SlogRecorder) Len() int { + return len(*h.records) +} + +// WithAttrs returns a new handler with the given attributes added to all records. +func (h *SlogRecorder) WithAttrs(attrs []slog.Attr) slog.Handler { + hand := h.clone() + hand.attrs = append(hand.attrs, hand.prefixAttrs(attrs)...) + + return hand +} + +// WithGroup returns a new handler with the given group name. +func (h *SlogRecorder) WithGroup(name string) slog.Handler { + if name == "" { + return h + } + + hand := h.clone() + hand.groups = append(hand.groups, name) + + return hand +} + +func (h *SlogRecorder) clone() *SlogRecorder { + return &SlogRecorder{ + records: h.records, + attrs: slices.Clone(h.attrs), + groups: slices.Clone(h.groups), + } +} + // SlogHandler wraps a slog.Handler and replaces timestamps with deterministic values // from a NowFunc. type SlogHandler struct { @@ -15,12 +109,12 @@ type SlogHandler struct { var _ slog.Handler = (*SlogHandler)(nil) -// NewSlogHandler creates a new handler that uses the given NowFunc to generate +// NewSlogHandler creates a new handler that uses a default NowFunc to generate // deterministic timestamps for all log records. -func NewSlogHandler(handler slog.Handler, nowFunc func() time.Time) *SlogHandler { +func NewSlogHandler(handler slog.Handler) *SlogHandler { return &SlogHandler{ handler: handler, - nowFunc: nowFunc, + nowFunc: NowFunc(), } } diff --git a/slog_test.go b/slog_test.go index 67d7661..1f75312 100644 --- a/slog_test.go +++ b/slog_test.go @@ -3,21 +3,77 @@ package deterministic_test import ( "bytes" "context" + "fmt" "log/slog" "strings" "testing" + "time" + "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "github.com/selesy/deterministic" ) +func TestSlogRecorder(t *testing.T) { + t.Parallel() + + newLoggerAndContent := func(h slog.Handler) { + logger := slog.New(h) + logger.Info("plain", slog.String("a", "a"), slog.String("b", "b")) + logger = logger.With(slog.String("c", "c"), slog.String("d", "d")) + logger.Info("with attrs", slog.String("e", "e"), slog.String("f", "f")) + logger = logger.WithGroup("1") + logger.Info("group1", slog.String("g", "g"), slog.String("h", "h")) + logger = logger.With(slog.String("i", "i"), slog.String("j", "j")) + logger.Info("group1 with attrs", slog.String("k", "k"), slog.String("l", "l")) + logger = logger.WithGroup("2") + logger.Info("group2", slog.String("m", "m"), slog.String("n", "n")) + logger = logger.With(slog.String("o", "o"), slog.String("p", "p")) + logger.Info("group2 with attrs", slog.String("q", "q"), slog.String("r", "r")) + } + + textBuf := &bytes.Buffer{} + var textHandler slog.Handler + textHandler = slog.NewTextHandler(textBuf, nil) + textHandler = deterministic.NewSlogHandler(textHandler) + newLoggerAndContent(textHandler) + + wrappedRecorder := deterministic.NewSlogRecorder() + var recHandler slog.Handler + recHandler = wrappedRecorder + recHandler = deterministic.NewSlogHandler(recHandler) + newLoggerAndContent(recHandler) + + recBuf := &bytes.Buffer{} + for i := range wrappedRecorder.Len() { + rec, err := wrappedRecorder.Get(i) + require.NoError(t, err) + + ts := rec.Time.Format("2006-01-02T15:04:05.000Z07:00") + + msg := rec.Message + if strings.ContainsAny(msg, " \t\n") { + msg = fmt.Sprintf("%q", msg) + } + fmt.Fprintf(recBuf, "time=%s level=%s msg=%s", ts, rec.Level, msg) + rec.Attrs(func(attr slog.Attr) bool { + fmt.Fprintf(recBuf, " %s=%s", attr.Key, attr.Value) + + return true + }) + + fmt.Fprintln(recBuf) + } + + assert.Equal(t, textBuf.String(), recBuf.String()) +} + func TestNewSlogHandler_ReturnsHandler(t *testing.T) { buf := &bytes.Buffer{} underlying := slog.NewTextHandler(buf, nil) - nf := deterministic.NowFunc() - h := deterministic.NewSlogHandler(underlying, nf) + h := deterministic.NewSlogHandler(underlying) if h == nil { t.Error("NewSlogHandler returned nil") } @@ -26,9 +82,8 @@ func TestNewSlogHandler_ReturnsHandler(t *testing.T) { func TestSlogHandler_IsHandler(t *testing.T) { buf := &bytes.Buffer{} underlying := slog.NewTextHandler(buf, nil) - nf := deterministic.NowFunc() - var _ slog.Handler = deterministic.NewSlogHandler(underlying, nf) + var _ slog.Handler = deterministic.NewSlogHandler(underlying) } func TestSlogHandler_ReplaceTimestamp(t *testing.T) { @@ -36,7 +91,7 @@ func TestSlogHandler_ReplaceTimestamp(t *testing.T) { underlying := slog.NewTextHandler(buf, nil) nf := deterministic.NowFunc() - h := deterministic.NewSlogHandler(underlying, nf) + h := deterministic.NewSlogHandler(underlying) ctx := context.Background() // Create a record with any time @@ -60,11 +115,11 @@ func TestSlogHandler_ReplaceTimestamp(t *testing.T) { func TestSlogHandler_ConsecutiveCallsHaveDifferentTimestamps(t *testing.T) { buf := &bytes.Buffer{} underlying := slog.NewTextHandler(buf, nil) - nf := deterministic.NowFunc() - h := deterministic.NewSlogHandler(underlying, nf) + h := deterministic.NewSlogHandler(underlying) ctx := context.Background() + nf := deterministic.NowFunc() dummyTime := nf() // Get a time but discard for logging r1 := slog.NewRecord(dummyTime, slog.LevelInfo, "first", 0) r2 := slog.NewRecord(dummyTime, slog.LevelInfo, "second", 0) @@ -95,9 +150,8 @@ func TestSlogHandler_ConsecutiveCallsHaveDifferentTimestamps(t *testing.T) { func TestSlogHandler_Enabled(t *testing.T) { buf := &bytes.Buffer{} underlying := slog.NewTextHandler(buf, nil) - nf := deterministic.NowFunc() - h := deterministic.NewSlogHandler(underlying, nf) + h := deterministic.NewSlogHandler(underlying) ctx := context.Background() // Both should return the same result @@ -109,9 +163,8 @@ func TestSlogHandler_Enabled(t *testing.T) { func TestSlogHandler_WithAttrs(t *testing.T) { buf := &bytes.Buffer{} underlying := slog.NewTextHandler(buf, nil) - nf := deterministic.NowFunc() - h := deterministic.NewSlogHandler(underlying, nf) + h := deterministic.NewSlogHandler(underlying) attrs := []slog.Attr{ slog.String("key", "value"), @@ -131,9 +184,8 @@ func TestSlogHandler_WithAttrs(t *testing.T) { func TestSlogHandler_WithGroup(t *testing.T) { buf := &bytes.Buffer{} underlying := slog.NewTextHandler(buf, nil) - nf := deterministic.NowFunc() - h := deterministic.NewSlogHandler(underlying, nf) + h := deterministic.NewSlogHandler(underlying) newH := h.WithGroup("mygroup") if newH == nil { @@ -151,29 +203,39 @@ func TestSlogHandler_DifferentInstances(t *testing.T) { buf2 := &bytes.Buffer{} underlying1 := slog.NewTextHandler(buf1, nil) underlying2 := slog.NewTextHandler(buf2, nil) - nf1 := deterministic.NowFunc() - nf2 := deterministic.NowFunc() - h1 := deterministic.NewSlogHandler(underlying1, nf1) - h2 := deterministic.NewSlogHandler(underlying2, nf2) + h1 := deterministic.NewSlogHandler(underlying1) + h2 := deterministic.NewSlogHandler(underlying2) ctx := context.Background() - dummyTime := nf1() // Advance nf1's internal state - r := slog.NewRecord(dummyTime, slog.LevelInfo, "test", 0) + dummyTime := time.Date(2006, 1, 2, 15, 4, 5, 0, time.UTC) + r := slog.NewRecord(dummyTime, slog.LevelInfo, "test1", 0) + + require.NoError(t, h1.Handle(ctx, r)) + r = slog.NewRecord(dummyTime, slog.LevelInfo, "test2", 0) require.NoError(t, h1.Handle(ctx, r)) - // nf2 is at the same initial state as nf1 started, so its first call gives the same time - r = slog.NewRecord(dummyTime, slog.LevelInfo, "test", 0) + // h2's internal NowFunc should be at the first time since we haven't called it yet + r = slog.NewRecord(dummyTime, slog.LevelInfo, "test3", 0) require.NoError(t, h2.Handle(ctx, r)) - ts1 := extractTime(buf1.String()) - ts2 := extractTime(buf2.String()) + // Get the timestamps from each handler + output1 := buf1.String() + output2 := buf2.String() - // Both handlers should have called their respective NowFunc once, so they get different times - // (h1's second call, h2's first call) - if ts1 == ts2 { - t.Errorf("expected different timestamps for different sequences, but got same: %s", ts1) + // Extract all lines + lines1 := strings.Split(strings.TrimSpace(output1), "\n") + lines2 := strings.Split(strings.TrimSpace(output2), "\n") + + // Get the second timestamp from h1 (which should be one second after the first) + ts1_second := extractTime(lines1[1]) + // Get the first timestamp from h2 (which should be the initial time) + ts2_first := extractTime(lines2[0]) + + // They should be different (h1's second call vs h2's first call) + if ts1_second == ts2_first { + t.Errorf("expected different timestamps for different instances, but got same: %s", ts1_second) } }