chore: extract testutil.FakeSink for slog test assertions (#23208)

Follow-up to [review comment on
#23025](https://github.com/coder/coder/pull/23025#discussion_r2930309487)
from @mafredri.

Extracts the repeated `logSink` / `fakeSink` test pattern into a shared
`testutil.FakeSink` and migrates all existing call sites.

> 🤖 This PR was created with the help of Coder Agents, and will be
reviewed by my human. 🧑‍💻

---------

Co-authored-by: Copilot Autofix powered by AI <175728472+Copilot@users.noreply.github.com>
This commit is contained in:
Cian Johnston
2026-03-18 17:02:38 +00:00
committed by GitHub
parent 2577d16af2
commit 65b7658568
6 changed files with 314 additions and 137 deletions
+6 -27
View File
@@ -6,7 +6,6 @@ import (
"context"
"net"
"path/filepath"
"sync"
"testing"
"github.com/google/uuid"
@@ -23,26 +22,6 @@ import (
"github.com/coder/coder/v2/testutil"
)
// logSink captures structured log entries for testing.
type logSink struct {
mu sync.Mutex
entries []slog.SinkEntry
}
func (s *logSink) LogEntry(_ context.Context, e slog.SinkEntry) {
s.mu.Lock()
defer s.mu.Unlock()
s.entries = append(s.entries, e)
}
func (*logSink) Sync() {}
func (s *logSink) getEntries() []slog.SinkEntry {
s.mu.Lock()
defer s.mu.Unlock()
return append([]slog.SinkEntry{}, s.entries...)
}
// getField returns the value of a field by name from a slog.Map.
func getField(fields slog.Map, name string) interface{} {
for _, f := range fields {
@@ -76,8 +55,8 @@ func TestBoundaryLogs_EndToEnd(t *testing.T) {
require.NoError(t, err)
t.Cleanup(func() { require.NoError(t, srv.Close()) })
sink := &logSink{}
logger := slog.Make(sink)
sink := testutil.NewFakeSink(t)
logger := sink.Logger(slog.LevelInfo)
workspaceID := uuid.New()
templateID := uuid.New()
templateVersionID := uuid.New()
@@ -118,10 +97,10 @@ func TestBoundaryLogs_EndToEnd(t *testing.T) {
sendBoundaryLogsRequest(t, conn, req)
require.Eventually(t, func() bool {
return len(sink.getEntries()) >= 1
return len(sink.Entries()) >= 1
}, testutil.WaitShort, testutil.IntervalFast)
entries := sink.getEntries()
entries := sink.Entries()
require.Len(t, entries, 1)
entry := entries[0]
require.Equal(t, slog.LevelInfo, entry.Level)
@@ -152,10 +131,10 @@ func TestBoundaryLogs_EndToEnd(t *testing.T) {
sendBoundaryLogsRequest(t, conn, req2)
require.Eventually(t, func() bool {
return len(sink.getEntries()) >= 2
return len(sink.Entries()) >= 2
}, testutil.WaitShort, testutil.IntervalFast)
entries = sink.getEntries()
entries = sink.Entries()
entry = entries[1]
require.Len(t, entries, 2)
require.Equal(t, slog.LevelInfo, entry.Level)
+11 -38
View File
@@ -4,7 +4,6 @@ import (
"context"
"net/http"
"net/http/httptest"
"sync"
"testing"
"time"
@@ -17,32 +16,6 @@ import (
"github.com/coder/websocket"
)
// logSink captures log entries so tests can assert on log levels.
type logSink struct {
mu sync.Mutex
entries []slog.SinkEntry
}
func (s *logSink) LogEntry(_ context.Context, e slog.SinkEntry) {
s.mu.Lock()
defer s.mu.Unlock()
s.entries = append(s.entries, e)
}
func (*logSink) Sync() {}
func (s *logSink) entriesAtLevel(level slog.Level) []slog.SinkEntry {
s.mu.Lock()
defer s.mu.Unlock()
var result []slog.SinkEntry
for _, e := range s.entries {
if e.Level == level {
result = append(result, e)
}
}
return result
}
// websocketPair sets up an httptest server with a websocket endpoint and
// returns the server-side conn. The server handler stays alive until ctx
// is done.
@@ -85,8 +58,8 @@ func TestHeartbeatClose(t *testing.T) {
t.Parallel()
ctx := testutil.Context(t, testutil.WaitShort)
sink := &logSink{}
logger := slog.Make(sink).Leveled(slog.LevelDebug)
sink := testutil.NewFakeSink(t)
logger := sink.Logger()
mClock := quartz.NewMock(t)
// Trap ticker creation so we can synchronize startup.
@@ -119,10 +92,10 @@ func TestHeartbeatClose(t *testing.T) {
// A closed connection is a normal shutdown condition. The
// error should be logged at Debug, not Error.
errorEntries := sink.entriesAtLevel(slog.LevelError)
errorEntries := sink.Entries(func(e slog.SinkEntry) bool { return e.Level == slog.LevelError })
assert.Empty(t, errorEntries,
"closed connection should not produce error-level logs, got: %+v", errorEntries)
debugEntries := sink.entriesAtLevel(slog.LevelDebug)
debugEntries := sink.Entries(func(e slog.SinkEntry) bool { return e.Level == slog.LevelDebug })
assert.NotEmpty(t, debugEntries,
"expected a debug-level log entry for the closed connection")
})
@@ -131,8 +104,8 @@ func TestHeartbeatClose(t *testing.T) {
t.Parallel()
ctx := testutil.Context(t, testutil.WaitShort)
sink := &logSink{}
logger := slog.Make(sink).Leveled(slog.LevelDebug)
sink := testutil.NewFakeSink(t)
logger := sink.Logger()
mClock := quartz.NewMock(t)
trap := mClock.Trap().NewTicker("HeartbeatClose")
@@ -161,7 +134,7 @@ func TestHeartbeatClose(t *testing.T) {
t.Fatal("timed out waiting for heartbeatClose to return")
}
errorEntries := sink.entriesAtLevel(slog.LevelError)
errorEntries := sink.Entries(func(e slog.SinkEntry) bool { return e.Level == slog.LevelError })
assert.Empty(t, errorEntries,
"context cancellation should not produce error-level logs, got: %+v", errorEntries)
})
@@ -170,8 +143,8 @@ func TestHeartbeatClose(t *testing.T) {
t.Parallel()
ctx := testutil.Context(t, testutil.WaitShort)
sink := &logSink{}
logger := slog.Make(sink).Leveled(slog.LevelDebug)
sink := testutil.NewFakeSink(t)
logger := sink.Logger()
mClock := quartz.NewMock(t)
trap := mClock.Trap().NewTicker("HeartbeatClose")
@@ -200,10 +173,10 @@ func TestHeartbeatClose(t *testing.T) {
}
// No logs should be emitted during normal operation.
errorEntries := sink.entriesAtLevel(slog.LevelError)
errorEntries := sink.Entries(func(e slog.SinkEntry) bool { return e.Level == slog.LevelError })
assert.Empty(t, errorEntries,
"successful pings should not produce error-level logs, got: %+v", errorEntries)
debugEntries := sink.entriesAtLevel(slog.LevelDebug)
debugEntries := sink.Entries(func(e slog.SinkEntry) bool { return e.Level == slog.LevelDebug })
assert.Empty(t, debugEntries,
"successful pings should not produce debug-level logs, got: %+v", debugEntries)
})
+44 -57
View File
@@ -26,9 +26,8 @@ func TestRequestLogger_WriteLog(t *testing.T) {
t.Parallel()
ctx := context.Background()
sink := &fakeSink{}
logger := slog.Make(sink)
logger = logger.Leveled(slog.LevelDebug)
sink := testutil.NewFakeSink(t)
logger := sink.Logger()
logCtx := NewRequestLogger(logger, "GET", time.Now())
// Add custom fields
@@ -39,24 +38,25 @@ func TestRequestLogger_WriteLog(t *testing.T) {
// Write log for 200 status
logCtx.WriteLog(ctx, http.StatusOK)
require.Len(t, sink.entries, 1, "log was written twice")
entries := sink.Entries()
require.Len(t, entries, 1, "log was written twice")
require.Equal(t, sink.entries[0].Message, "GET")
require.Equal(t, entries[0].Message, "GET")
require.Equal(t, sink.entries[0].Fields[0].Value, "custom_value")
require.Equal(t, entries[0].Fields[0].Value, "custom_value")
// Attempt to write again (should be skipped).
logCtx.WriteLog(ctx, http.StatusInternalServerError)
require.Len(t, sink.entries, 1, "log was written twice")
entries = sink.Entries()
require.Len(t, entries, 1, "log was written twice")
}
func TestLoggerMiddleware_SingleRequest(t *testing.T) {
t.Parallel()
sink := &fakeSink{}
logger := slog.Make(sink)
logger = logger.Leveled(slog.LevelDebug)
sink := testutil.NewFakeSink(t)
logger := sink.Logger()
ctx, cancel := context.WithTimeout(context.Background(), testutil.WaitShort)
defer cancel()
@@ -80,12 +80,13 @@ func TestLoggerMiddleware_SingleRequest(t *testing.T) {
// Serve the request
wrappedHandler.ServeHTTP(sw, req)
require.Len(t, sink.entries, 1, "log was written twice")
entries := sink.Entries()
require.Len(t, entries, 1, "log was written twice")
require.Equal(t, sink.entries[0].Message, "GET")
require.Equal(t, entries[0].Message, "GET")
fieldsMap := make(map[string]any)
for _, field := range sink.entries[0].Fields {
for _, field := range entries[0].Fields {
fieldsMap[field.Name] = field.Value
}
@@ -96,7 +97,7 @@ func TestLoggerMiddleware_SingleRequest(t *testing.T) {
require.True(t, exists, "field %q is missing in log fields", field)
}
require.Len(t, sink.entries[0].Fields, len(requiredFields), "log should contain only the required fields")
require.Len(t, entries[0].Fields, len(requiredFields), "log should contain only the required fields")
// Check value of the status code
require.Equal(t, fieldsMap["status_code"], http.StatusOK)
@@ -107,12 +108,10 @@ func TestLoggerMiddleware_WebSocket(t *testing.T) {
ctx, cancel := context.WithTimeout(context.Background(), testutil.WaitShort)
defer cancel()
sink := &fakeSink{
newEntries: make(chan slog.SinkEntry, 2),
}
logger := slog.Make(sink)
logger = logger.Leveled(slog.LevelDebug)
sink := testutil.NewFakeSink(t)
logger := sink.Logger()
done := make(chan struct{})
logged := make(chan struct{})
wg := sync.WaitGroup{}
// Create a test handler to simulate a WebSocket connection
testHandler := http.HandlerFunc(func(rw http.ResponseWriter, r *http.Request) {
@@ -124,6 +123,7 @@ func TestLoggerMiddleware_WebSocket(t *testing.T) {
requestLgr := RequestLoggerFromContext(r.Context())
requestLgr.WriteLog(r.Context(), http.StatusSwitchingProtocols)
close(logged)
// Block so we can be sure the end of the middleware isn't being called.
wg.Wait()
})
@@ -147,9 +147,11 @@ func TestLoggerMiddleware_WebSocket(t *testing.T) {
require.NoError(t, err, "failed to dial WebSocket")
defer conn.Close(websocket.StatusNormalClosure, "")
// Wait for the log from within the handler
newEntry := testutil.TryReceive(ctx, t, sink.newEntries)
require.Equal(t, newEntry.Message, "GET")
// Wait for the log from within the handler.
_ = testutil.TryReceive(ctx, t, logged)
entries := sink.Entries()
require.Len(t, entries, 1, "expected exactly one log entry after WriteLog")
require.Equal(t, entries[0].Message, "GET")
// Signal the websocket handler to return (and read to handle the close frame)
wg.Done()
@@ -158,15 +160,15 @@ func TestLoggerMiddleware_WebSocket(t *testing.T) {
// Wait for the request to finish completely and verify we only logged once
_ = testutil.TryReceive(ctx, t, done)
require.Len(t, sink.entries, 1, "log was written twice")
entries = sink.Entries()
require.Len(t, entries, 1, "log was written twice")
}
func TestRequestLogger_HTTPRouteParams(t *testing.T) {
t.Parallel()
sink := &fakeSink{}
logger := slog.Make(sink)
logger = logger.Leveled(slog.LevelDebug)
sink := testutil.NewFakeSink(t)
logger := sink.Logger()
ctx, cancel := context.WithTimeout(context.Background(), testutil.WaitShort)
defer cancel()
@@ -196,8 +198,10 @@ func TestRequestLogger_HTTPRouteParams(t *testing.T) {
// Serve the request
wrappedHandler.ServeHTTP(sw, req)
entries := sink.Entries()
require.Len(t, entries, 1, "expected exactly one log entry")
fieldsMap := make(map[string]any)
for _, field := range sink.entries[0].Fields {
for _, field := range entries[0].Fields {
fieldsMap[field.Name] = field.Value
}
@@ -252,9 +256,8 @@ func TestRequestLogger_RouteParamsLogging(t *testing.T) {
t.Run(tt.name, func(t *testing.T) {
t.Parallel()
sink := &fakeSink{}
logger := slog.Make(sink)
logger = logger.Leveled(slog.LevelDebug)
sink := testutil.NewFakeSink(t)
logger := sink.Logger()
// Create a route context with the test parameters
chiCtx := chi.NewRouteContext()
@@ -268,11 +271,12 @@ func TestRequestLogger_RouteParamsLogging(t *testing.T) {
// Write the log
logCtx.WriteLog(ctx, http.StatusOK)
require.Len(t, sink.entries, 1, "expected exactly one log entry")
entries := sink.Entries()
require.Len(t, entries, 1, "expected exactly one log entry")
// Convert fields to map for easier checking
fieldsMap := make(map[string]any)
for _, field := range sink.entries[0].Fields {
for _, field := range entries[0].Fields {
fieldsMap[field.Name] = field.Value
}
@@ -368,9 +372,8 @@ func TestRequestLogger_AuthContext(t *testing.T) {
t.Parallel()
ctx := context.Background()
sink := &fakeSink{}
logger := slog.Make(sink)
logger = logger.Leveled(slog.LevelDebug)
sink := testutil.NewFakeSink(t)
logger := sink.Logger()
logCtx := NewRequestLogger(logger, "GET", time.Now())
logCtx.WithAuthContext(rbac.Subject{
@@ -382,26 +385,10 @@ func TestRequestLogger_AuthContext(t *testing.T) {
logCtx.WriteLog(ctx, http.StatusOK)
require.Len(t, sink.entries, 1, "log was written twice")
require.Equal(t, sink.entries[0].Message, "GET")
require.Equal(t, sink.entries[0].Fields[0].Value, "test-user-id")
require.Equal(t, sink.entries[0].Fields[1].Value, "test name")
require.Equal(t, sink.entries[0].Fields[2].Value, "test@coder.com")
entries := sink.Entries()
require.Len(t, entries, 1, "log was written twice")
require.Equal(t, entries[0].Message, "GET")
require.Equal(t, entries[0].Fields[0].Value, "test-user-id")
require.Equal(t, entries[0].Fields[1].Value, "test name")
require.Equal(t, entries[0].Fields[2].Value, "test@coder.com")
}
type fakeSink struct {
entries []slog.SinkEntry
newEntries chan slog.SinkEntry
}
func (s *fakeSink) LogEntry(_ context.Context, e slog.SinkEntry) {
s.entries = append(s.entries, e)
if s.newEntries != nil {
select {
case s.newEntries <- e:
default:
}
}
}
func (*fakeSink) Sync() {}
+7 -15
View File
@@ -22,6 +22,7 @@ import (
"github.com/coder/coder/v2/enterprise/audit"
"github.com/coder/coder/v2/enterprise/audit/audittest"
"github.com/coder/coder/v2/enterprise/audit/backends"
"github.com/coder/coder/v2/testutil"
)
func TestSlogExporter(t *testing.T) {
@@ -32,8 +33,8 @@ func TestSlogExporter(t *testing.T) {
var (
ctx, cancel = context.WithCancel(context.Background())
sink = &fakeSink{}
logger = slog.Make(sink)
sink = testutil.NewFakeSink(t)
logger = sink.Logger(slog.LevelInfo)
exporter = backends.NewSlogExporter(logger)
alog = audittest.RandomLog()
@@ -42,9 +43,10 @@ func TestSlogExporter(t *testing.T) {
err := exporter.ExportStruct(ctx, alog, "audit_log")
require.NoError(t, err)
require.Len(t, sink.entries, 1)
require.Equal(t, sink.entries[0].Message, "audit_log")
require.Len(t, sink.entries[0].Fields, len(structs.Fields(alog)))
entries := sink.Entries()
require.Len(t, entries, 1)
require.Equal(t, entries[0].Message, "audit_log")
require.Len(t, entries[0].Fields, len(structs.Fields(alog)))
})
t.Run("FormatsCorrectly", func(t *testing.T) {
t.Parallel()
@@ -98,13 +100,3 @@ func TestSlogExporter(t *testing.T) {
assert.Equal(t, expected, string(s.Fields))
})
}
type fakeSink struct {
entries []slog.SinkEntry
}
func (s *fakeSink) LogEntry(_ context.Context, e slog.SinkEntry) {
s.entries = append(s.entries, e)
}
func (*fakeSink) Sync() {}
+76
View File
@@ -0,0 +1,76 @@
package testutil
import (
"context"
"sync"
"testing"
"cdr.dev/slog/v3"
)
// FakeSink is a thread-safe slog.Sink that captures log entries so
// tests can assert on what was logged. It requires a testing.TB
// as it is only meant for use in tests.
type FakeSink struct {
mu sync.RWMutex
entries []slog.SinkEntry
}
// NewFakeSink returns a FakeSink ready for use.
func NewFakeSink(_ testing.TB) *FakeSink {
return &FakeSink{}
}
// LogEntry implements slog.Sink. It appends the entry to the
// internal slice.
func (s *FakeSink) LogEntry(_ context.Context, e slog.SinkEntry) {
s.mu.Lock()
defer s.mu.Unlock()
s.entries = append(s.entries, e)
}
// Sync implements slog.Sink.
func (*FakeSink) Sync() {}
// Entries returns a copy of the captured entries. If filters are
// provided, only entries matching ALL filters are returned. This
// lets callers compose simple predicates instead of needing
// dedicated methods for each field.
func (s *FakeSink) Entries(filters ...func(slog.SinkEntry) bool) []slog.SinkEntry {
s.mu.RLock()
cpy := make([]slog.SinkEntry, len(s.entries))
copy(cpy, s.entries)
s.mu.RUnlock()
filtered := make([]slog.SinkEntry, 0)
for _, e := range cpy {
if !matchAll(e, filters) {
continue
}
filtered = append(filtered, e)
}
return filtered
}
// Logger returns a slog.Logger backed by this sink at the given
// level. If no level is provided it defaults to LevelDebug, which
// captures everything. If more than one level is provided, the
// first one wins.
func (s *FakeSink) Logger(level ...slog.Level) slog.Logger {
l := slog.LevelDebug
if len(level) > 0 {
l = level[0]
}
return slog.Make(s).Leveled(l)
}
func matchAll(e slog.SinkEntry, filters []func(slog.SinkEntry) bool) bool {
for _, f := range filters {
if f == nil {
continue
}
if !f(e) {
return false
}
}
return true
}
+170
View File
@@ -0,0 +1,170 @@
package testutil_test
import (
"strings"
"sync"
"testing"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
"cdr.dev/slog/v3"
"github.com/coder/coder/v2/testutil"
)
func TestFakeSink(t *testing.T) {
t.Parallel()
t.Run("BasicCapture", func(t *testing.T) {
t.Parallel()
ctx := testutil.Context(t, testutil.WaitShort)
sink := testutil.NewFakeSink(t)
logger := sink.Logger()
logger.Debug(ctx, "first test message")
logger.Debug(ctx, "second test message")
logger.Debug(ctx, "third test message")
entries := sink.Entries()
require.Len(t, entries, 3)
})
t.Run("FilterByLevel", func(t *testing.T) {
t.Parallel()
ctx := testutil.Context(t, testutil.WaitShort)
sink := testutil.NewFakeSink(t)
logger := sink.Logger()
logger.Debug(ctx, "debug level message")
logger.Info(ctx, "info level message")
logger.Error(ctx, "error level message")
errorOnly := sink.Entries(func(e slog.SinkEntry) bool {
return e.Level == slog.LevelError
})
require.Len(t, errorOnly, 1)
assert.Equal(t, "error level message", errorOnly[0].Message)
})
t.Run("MultipleFiltersAND", func(t *testing.T) {
t.Parallel()
ctx := testutil.Context(t, testutil.WaitShort)
sink := testutil.NewFakeSink(t)
logger := sink.Logger()
logger.Info(ctx, "hello world filter test")
logger.Info(ctx, "goodbye world filter")
logger.Error(ctx, "hello error filter test")
byLevel := func(e slog.SinkEntry) bool {
return e.Level == slog.LevelInfo
}
byMessage := func(e slog.SinkEntry) bool {
return strings.Contains(e.Message, "hello")
}
matched := sink.Entries(byLevel, byMessage)
require.Len(t, matched, 1)
assert.Equal(t, "hello world filter test", matched[0].Message)
})
t.Run("NilFilterSkipped", func(t *testing.T) {
t.Parallel()
ctx := testutil.Context(t, testutil.WaitShort)
sink := testutil.NewFakeSink(t)
logger := sink.Logger()
logger.Info(ctx, "nil filter test msg")
// A nil filter should be harmlessly skipped.
entries := sink.Entries(nil)
require.Len(t, entries, 1)
})
t.Run("NoFilters", func(t *testing.T) {
t.Parallel()
ctx := testutil.Context(t, testutil.WaitShort)
sink := testutil.NewFakeSink(t)
logger := sink.Logger()
logger.Debug(ctx, "no filter debug msg")
logger.Info(ctx, "no filter info msg")
entries := sink.Entries()
require.Len(t, entries, 2)
})
t.Run("EmptySink", func(t *testing.T) {
t.Parallel()
sink := testutil.NewFakeSink(t)
entries := sink.Entries()
assert.Empty(t, entries)
})
t.Run("ThreadSafety", func(t *testing.T) {
t.Parallel()
ctx := testutil.Context(t, testutil.WaitShort)
sink := testutil.NewFakeSink(t)
logger := sink.Logger()
const goroutines = 10
const entriesPerGoroutine = 100
var wg sync.WaitGroup
wg.Add(goroutines)
for range goroutines {
go func() {
defer wg.Done()
for range entriesPerGoroutine {
logger.Debug(ctx, "concurrent log entry")
}
}()
}
wg.Wait()
entries := sink.Entries()
require.Len(t, entries, goroutines*entriesPerGoroutine)
})
t.Run("LoggerConvenience", func(t *testing.T) {
t.Parallel()
t.Run("DefaultDebug", func(t *testing.T) {
t.Parallel()
ctx := testutil.Context(t, testutil.WaitShort)
sink := testutil.NewFakeSink(t)
logger := sink.Logger()
logger.Debug(ctx, "captured at debug level")
entries := sink.Entries()
require.Len(t, entries, 1)
assert.Equal(t, slog.LevelDebug, entries[0].Level)
})
t.Run("RespectsLevel", func(t *testing.T) {
t.Parallel()
ctx := testutil.Context(t, testutil.WaitShort)
sink := testutil.NewFakeSink(t)
logger := sink.Logger(slog.LevelInfo)
// Debug should be filtered out by the logger
// because the level is set to Info.
logger.Debug(ctx, "filtered out by level")
logger.Info(ctx, "kept by info level")
entries := sink.Entries()
require.Len(t, entries, 1)
assert.Equal(t, slog.LevelInfo, entries[0].Level)
})
})
}