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