feat(slog): add a deterministic slog.Record recorder

example_slog_test.go → 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)
 

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
+}

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(),
 	}
 }
 

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,17 +82,16 @@ 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) {
 	buf := &bytes.Buffer{}
 	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)
 	}
 }