package log
import (
"bytes"
"context"
"encoding/json"
"log/slog"
"strings"
"testing"
"go.opentelemetry.io/otel/trace"
)
func TestNewWithFormatTextAndDefault(t *testing.T) {
for _, format := range []string{"", "text"} {
var buf bytes.Buffer
logger, err := newWithFormatWriter(&buf, "spindle", format)
if err != nil {
t.Fatal(err)
}
logger.Info("hello")
if got := buf.String(); !strings.Contains(got, "spindle") || !strings.Contains(got, "hello") {
t.Errorf("text log = %q", got)
}
}
}
func TestNewWithFormatJSON(t *testing.T) {
var buf bytes.Buffer
logger, err := newWithFormatWriter(&buf, "spindle", "json")
if err != nil {
t.Fatal(err)
}
logger.Info("hello")
var record map[string]any
if err := json.Unmarshal(buf.Bytes(), &record); err != nil {
t.Fatalf("parse json log: %v", err)
}
if record["logger"] != "spindle" || record["msg"] != "hello" {
t.Errorf("json log = %#v", record)
}
}
func TestNewWithFormatRejectsUnknownFormat(t *testing.T) {
if _, err := NewWithFormat("spindle", "unknown"); err == nil {
t.Fatal("unknown format accepted")
}
}
func TestSubLoggerPreservesJSON(t *testing.T) {
var buf bytes.Buffer
base, err := newWithFormatWriter(&buf, "spindle", "json")
if err != nil {
t.Fatal(err)
}
SubLogger(SubLogger(base, "mill"), "session").Info("connected")
var record map[string]any
if err := json.Unmarshal(buf.Bytes(), &record); err != nil {
t.Fatalf("parse json log: %v", err)
}
if record["logger"] != "spindle/mill/session" {
t.Errorf("logger = %q", record["logger"])
}
if strings.Count(buf.String(), `"logger"`) != 1 {
t.Errorf("duplicate logger fields in %s", buf.String())
}
}
func TestSubLoggerPreservesBoundAttributesAndGroups(t *testing.T) {
var buf bytes.Buffer
base, err := newWithFormatWriter(&buf, "spindle", "json")
if err != nil {
t.Fatal(err)
}
bound := base.With("request_id", "req-1").WithGroup("request").With("actor", "did:web:alice")
SubLogger(bound, "xrpc").Info("handled")
var record map[string]any
if err := json.Unmarshal(buf.Bytes(), &record); err != nil {
t.Fatalf("parse json log: %v", err)
}
if record["logger"] != "spindle/xrpc" || record["request_id"] != "req-1" {
t.Errorf("json log = %#v", record)
}
group, ok := record["request"].(map[string]any)
if !ok || group["actor"] != "did:web:alice" {
t.Errorf("request group = %#v", record["request"])
}
}
func TestSubLoggerPreservesUnknownHandler(t *testing.T) {
var buf bytes.Buffer
base := slog.New(slog.NewJSONHandler(&buf, nil))
SubLogger(base, "worker").Info("running")
var record map[string]any
if err := json.Unmarshal(buf.Bytes(), &record); err != nil {
t.Fatalf("parse json log: %v", err)
}
if record["component"] != "worker" {
t.Errorf("component = %q", record["component"])
}
}
func TestTracingInLogHandler(t *testing.T) {
sampledSpanCtx := trace.NewSpanContext(trace.SpanContextConfig{
TraceID: trace.TraceID{1},
SpanID: trace.SpanID{2},
TraceFlags: trace.FlagsSampled,
})
unsampledSpanCtx := trace.NewSpanContext(trace.SpanContextConfig{
TraceID: trace.TraceID{3},
SpanID: trace.SpanID{4},
TraceFlags: 0,
})
t.Run("sampled JSON", func(t *testing.T) {
var buf bytes.Buffer
logger, err := newWithFormatWriter(&buf, "spindle", "json")
if err != nil {
t.Fatal(err)
}
ctx := trace.ContextWithSpanContext(context.Background(), sampledSpanCtx)
logger.InfoContext(ctx, "hello")
var record map[string]any
if err := json.Unmarshal(buf.Bytes(), &record); err != nil {
t.Fatalf("parse json log: %v", err)
}
if record["trace_id"] != sampledSpanCtx.TraceID().String() {
t.Errorf("trace_id = %v, want %v", record["trace_id"], sampledSpanCtx.TraceID().String())
}
if record["span_id"] != sampledSpanCtx.SpanID().String() {
t.Errorf("span_id = %v, want %v", record["span_id"], sampledSpanCtx.SpanID().String())
}
})
t.Run("sampled text", func(t *testing.T) {
var buf bytes.Buffer
logger, err := newWithFormatWriter(&buf, "spindle", "text")
if err != nil {
t.Fatal(err)
}
ctx := trace.ContextWithSpanContext(context.Background(), sampledSpanCtx)
logger.InfoContext(ctx, "hello")
got := buf.String()
if !strings.Contains(got, sampledSpanCtx.TraceID().String()) {
t.Errorf("text log missing trace_id: %q", got)
}
if !strings.Contains(got, sampledSpanCtx.SpanID().String()) {
t.Errorf("text log missing span_id: %q", got)
}
})
t.Run("unsampled JSON", func(t *testing.T) {
var buf bytes.Buffer
logger, err := newWithFormatWriter(&buf, "spindle", "json")
if err != nil {
t.Fatal(err)
}
ctx := trace.ContextWithSpanContext(context.Background(), unsampledSpanCtx)
logger.InfoContext(ctx, "hello")
var record map[string]any
if err := json.Unmarshal(buf.Bytes(), &record); err != nil {
t.Fatalf("parse json log: %v", err)
}
if _, ok := record["trace_id"]; ok {
t.Errorf("unsampled log should not have trace_id")
}
if _, ok := record["span_id"]; ok {
t.Errorf("unsampled log should not have span_id")
}
})
t.Run("no context JSON", func(t *testing.T) {
var buf bytes.Buffer
logger, err := newWithFormatWriter(&buf, "spindle", "json")
if err != nil {
t.Fatal(err)
}
logger.Info("hello")
var record map[string]any
if err := json.Unmarshal(buf.Bytes(), &record); err != nil {
t.Fatalf("parse json log: %v", err)
}
if _, ok := record["trace_id"]; ok {
t.Errorf("no-context log should not have trace_id")
}
if _, ok := record["span_id"]; ok {
t.Errorf("no-context log should not have span_id")
}
})
t.Run("prevent duplicate fields in record attributes", func(t *testing.T) {
var buf bytes.Buffer
logger, err := newWithFormatWriter(&buf, "spindle", "json")
if err != nil {
t.Fatal(err)
}
ctx := trace.ContextWithSpanContext(context.Background(), sampledSpanCtx)
logger.InfoContext(ctx, "hello", "trace_id", "custom-trace-id", "span_id", "custom-span-id")
var record map[string]any
if err := json.Unmarshal(buf.Bytes(), &record); err != nil {
t.Fatalf("parse json log: %v", err)
}
if record["trace_id"] != "custom-trace-id" {
t.Errorf("trace_id = %v, want custom-trace-id", record["trace_id"])
}
if record["span_id"] != "custom-span-id" {
t.Errorf("span_id = %v, want custom-span-id", record["span_id"])
}
})
t.Run("prevent duplicate fields in WithAttrs", func(t *testing.T) {
var buf bytes.Buffer
logger, err := newWithFormatWriter(&buf, "spindle", "json")
if err != nil {
t.Fatal(err)
}
ctx := trace.ContextWithSpanContext(context.Background(), sampledSpanCtx)
logger.With("trace_id", "custom-trace-id", "span_id", "custom-span-id").InfoContext(ctx, "hello")
var record map[string]any
if err := json.Unmarshal(buf.Bytes(), &record); err != nil {
t.Fatalf("parse json log: %v", err)
}
if record["trace_id"] != "custom-trace-id" {
t.Errorf("trace_id = %v, want custom-trace-id", record["trace_id"])
}
if record["span_id"] != "custom-span-id" {
t.Errorf("span_id = %v, want custom-span-id", record["span_id"])
}
})
}
type mockHandler struct {
records []slog.Record
attrs []slog.Attr
groups []string
name string
enabled bool
}
func (m *mockHandler) Enabled(ctx context.Context, level slog.Level) bool {
return m.enabled
}
func (m *mockHandler) Handle(ctx context.Context, r slog.Record) error {
m.records = append(m.records, r)
return nil
}
func (m *mockHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
return &mockHandler{
records: m.records,
attrs: append(m.attrs, attrs...),
groups: m.groups,
name: m.name,
enabled: m.enabled,
}
}
func (m *mockHandler) WithGroup(name string) slog.Handler {
return &mockHandler{
records: m.records,
attrs: m.attrs,
groups: append(m.groups, name),
name: m.name,
enabled: m.enabled,
}
}
func (m *mockHandler) WithName(name string) slog.Handler {
return &mockHandler{
records: m.records,
attrs: m.attrs,
groups: m.groups,
name: name,
enabled: m.enabled,
}
}
func TestFanoutHandlerNoExtra(t *testing.T) {
primary := NewHandler("spindle")
handler := NewFanoutHandler(primary)
if handler != primary {
t.Error("NewFanoutHandler with no extra handlers should return the primary handler directly")
}
}
func TestFanoutHandlerRouting(t *testing.T) {
primaryBuf := new(bytes.Buffer)
primary, err := newWithFormatWriter(primaryBuf, "primary", "json")
if err != nil {
t.Fatal(err)
}
mock1 := &mockHandler{enabled: true}
mock2 := &mockHandler{enabled: false}
fanout := NewFanoutHandler(primary.Handler(), mock1, mock2)
logger := slog.New(fanout)
logger.Info("hello", "foo", "bar")
if len(mock1.records) != 1 {
t.Errorf("mock1 got %d records, want 1", len(mock1.records))
} else {
rec := mock1.records[0]
if rec.Message != "hello" {
t.Errorf("mock1 message = %q, want hello", rec.Message)
}
}
if len(mock2.records) != 0 {
t.Errorf("mock2 got %d records, want 0", len(mock2.records))
}
if !strings.Contains(primaryBuf.String(), `"msg":"hello"`) {
t.Errorf("primaryBuf = %q, missing hello", primaryBuf.String())
}
}
func TestSubLoggerFanoutPropagation(t *testing.T) {
primaryBuf := new(bytes.Buffer)
primary, err := newWithFormatWriter(primaryBuf, "primary", "json")
if err != nil {
t.Fatal(err)
}
mock := &mockHandler{enabled: true}
fanout := NewFanoutHandler(primary.Handler(), mock)
logger := slog.New(fanout)
sub := SubLogger(logger, "sub")
sub.Info("test")
if !strings.Contains(primaryBuf.String(), `"logger":"primary/sub"`) {
t.Errorf("primaryBuf = %q, missing logger primary/sub", primaryBuf.String())
}
if fanoutSub, ok := sub.Handler().(*fanoutHandler); ok {
if m, ok := fanoutSub.others[0].(*mockHandler); ok {
if m.name != "primary/sub" {
t.Errorf("mock name = %q, want primary/sub", m.name)
}
} else {
t.Error("fanoutSub others[0] is not *mockHandler")
}
} else {
t.Error("sub handler is not *fanoutHandler")
}
}
func TestFanoutHandlerWithGroupAndAttrs(t *testing.T) {
primaryBuf := new(bytes.Buffer)
primary, err := newWithFormatWriter(primaryBuf, "primary", "json")
if err != nil {
t.Fatal(err)
}
mock := &mockHandler{enabled: true}
fanout := NewFanoutHandler(primary.Handler(), mock)
logger := slog.New(fanout)
logger.With("a", "b").WithGroup("g").Info("test")
if fanoutSub, ok := logger.With("a", "b").WithGroup("g").Handler().(*fanoutHandler); ok {
if m, ok := fanoutSub.others[0].(*mockHandler); ok {
if len(m.attrs) != 1 || m.attrs[0].Key != "a" || m.attrs[0].Value.String() != "b" {
t.Errorf("mock attrs = %v, want [{a b}]", m.attrs)
}
if len(m.groups) != 1 || m.groups[0] != "g" {
t.Errorf("mock groups = %v, want [g]", m.groups)
}
}
}
}