package simplelog import ( "bytes" "context" "encoding/json" "errors" "io" "log/slog" "net/http" "net/http/httptest" "os" "reflect" "strings" "testing" "time" ) // These tests assert on the bytes the handlers actually emit, because that is // where the defect lives: the handlers accept attributes and then throw them // away, so nothing short of reading the output proves they survived. // captureStdout redirects os.Stdout for the duration of fn and returns what was // written to it. Both the console and the JSON handler write to os.Stdout, so // this is the only way to see their real output. func captureStdout(t *testing.T, fn func()) string { t.Helper() r, w, err := os.Pipe() if err != nil { t.Fatalf("os.Pipe: %v", err) } original := os.Stdout os.Stdout = w collected := make(chan string, 1) go func() { var buf bytes.Buffer _, _ = io.Copy(&buf, r) collected <- buf.String() }() defer func() { os.Stdout = original _ = r.Close() }() fn() os.Stdout = original if err := w.Close(); err != nil { t.Fatalf("close pipe writer: %v", err) } return <-collected } // testRecord builds an INFO record carrying the given attributes. func testRecord(message string, attrs ...slog.Attr) slog.Record { record := slog.NewRecord(time.Now(), slog.LevelInfo, message, 0) record.AddAttrs(attrs...) return record } // decodeLine parses a single line of JSON handler output. func decodeLine(t *testing.T, output string) map[string]any { t.Helper() line := strings.TrimSpace(output) if line == "" { t.Fatal("handler emitted no output") } var decoded map[string]any if err := json.Unmarshal([]byte(line), &decoded); err != nil { t.Fatalf("output is not valid JSON: %v\noutput: %s", err, line) } return decoded } // wantField asserts that a decoded JSON object has key with the given value. func wantField(t *testing.T, decoded map[string]any, key string, want any) { t.Helper() got, ok := decoded[key] if !ok { t.Fatalf("field %q missing from output: %v", key, decoded) } if got != want { t.Fatalf("field %q = %v, want %v", key, got, want) } } // wantGroup asserts that a decoded JSON object has key holding a nested object. func wantGroup(t *testing.T, decoded map[string]any, key string) map[string]any { t.Helper() got, ok := decoded[key] if !ok { t.Fatalf("group %q missing from output: %v", key, decoded) } group, ok := got.(map[string]any) if !ok { t.Fatalf("field %q = %v, want a nested object", key, got) } return group } // wantNoField asserts that a decoded JSON object does not carry key. func wantNoField(t *testing.T, decoded map[string]any, key string) { t.Helper() if got, present := decoded[key]; present { t.Fatalf("field %q unexpectedly present as %v: %v", key, got, decoded) } } // wantUnchanged asserts that a value the caller still owns was not written to // by the handler. Logging must read what it is handed, never modify it. func wantUnchanged(t *testing.T, what string, got, want any) { t.Helper() if !reflect.DeepEqual(got, want) { t.Fatalf("handler mutated the caller's %s: got %v, want %v", what, got, want) } } // wantContains asserts that console output contains a fragment. func wantContains(t *testing.T, output, fragment string) { t.Helper() if !strings.Contains(output, fragment) { t.Fatalf("output does not contain %q\noutput: %s", fragment, output) } } // wantNotContains asserts that console output does not contain a fragment. func wantNotContains(t *testing.T, output, fragment string) { t.Helper() if strings.Contains(output, fragment) { t.Fatalf("output unexpectedly contains %q\noutput: %s", fragment, output) } } // castTarget is a slog.LogValuer: the handler must resolve it rather than // serialising the struct itself. type castTarget struct { id string } func (c castTarget) LogValue() slog.Value { return slog.StringValue(c.id) } var _ slog.LogValuer = castTarget{} func TestJSONHandlerEmitsRecordAttrs(t *testing.T) { output := captureStdout(t, func() { handler := NewJSONHandler() record := testRecord( "casting", slog.String("device", "livingroom"), slog.String("file", "movie.mp4"), slog.Int("attempt", 3), ) if err := handler.Handle(context.Background(), record); err != nil { t.Fatalf("Handle: %v", err) } }) decoded := decodeLine(t, output) wantField(t, decoded, "Message", "casting") wantField(t, decoded, "device", "livingroom") wantField(t, decoded, "file", "movie.mp4") wantField(t, decoded, "attempt", float64(3)) } func TestJSONHandlerWithAttrsAccumulates(t *testing.T) { output := captureStdout(t, func() { handler := NewJSONHandler(). WithAttrs([]slog.Attr{slog.String("service", "cattbox")}). WithAttrs([]slog.Attr{slog.String("component", "caster")}) record := testRecord("casting", slog.String("device", "livingroom")) if err := handler.Handle(context.Background(), record); err != nil { t.Fatalf("Handle: %v", err) } }) decoded := decodeLine(t, output) wantField(t, decoded, "service", "cattbox") wantField(t, decoded, "component", "caster") wantField(t, decoded, "device", "livingroom") } func TestJSONHandlerWithAttrsDoesNotMutateReceiver(t *testing.T) { parent := NewJSONHandler() first := parent.WithAttrs([]slog.Attr{slog.String("worker", "first")}) second := parent.WithAttrs([]slog.Attr{slog.String("worker", "second")}) firstOutput := captureStdout(t, func() { if err := first.Handle(context.Background(), testRecord("work")); err != nil { t.Fatalf("Handle: %v", err) } }) secondOutput := captureStdout(t, func() { if err := second.Handle(context.Background(), testRecord("work")); err != nil { t.Fatalf("Handle: %v", err) } }) parentOutput := captureStdout(t, func() { if err := parent.Handle(context.Background(), testRecord("work")); err != nil { t.Fatalf("Handle: %v", err) } }) wantField(t, decodeLine(t, firstOutput), "worker", "first") wantField(t, decodeLine(t, secondOutput), "worker", "second") if _, present := decodeLine(t, parentOutput)["worker"]; present { t.Fatalf("parent handler leaked an attribute from a derived handler: %s", parentOutput) } } func TestJSONHandlerWithGroupNestsAttrs(t *testing.T) { output := captureStdout(t, func() { handler := NewJSONHandler(). WithGroup("cast"). WithAttrs([]slog.Attr{slog.String("device", "livingroom")}) record := testRecord("casting", slog.String("file", "movie.mp4")) if err := handler.Handle(context.Background(), record); err != nil { t.Fatalf("Handle: %v", err) } }) decoded := decodeLine(t, output) wantField(t, decoded, "Message", "casting") group := wantGroup(t, decoded, "cast") wantField(t, group, "device", "livingroom") wantField(t, group, "file", "movie.mp4") } func TestJSONHandlerResolvesValues(t *testing.T) { output := captureStdout(t, func() { handler := NewJSONHandler() record := testRecord( "cast failed", slog.Group("request", slog.Int("status", 502), slog.String("method", "POST")), slog.Any("target", castTarget{id: "chromecast-7"}), slog.Any("error", errors.New("connection refused")), ) if err := handler.Handle(context.Background(), record); err != nil { t.Fatalf("Handle: %v", err) } }) decoded := decodeLine(t, output) wantField(t, decoded, "target", "chromecast-7") wantField(t, decoded, "error", "connection refused") group := wantGroup(t, decoded, "request") wantField(t, group, "status", float64(502)) wantField(t, group, "method", "POST") } func TestConsoleHandlerEmitsRecordAttrs(t *testing.T) { output := captureStdout(t, func() { handler := NewConsoleHandler() record := testRecord( "casting", slog.String("device", "livingroom"), slog.String("file", "movie.mp4"), slog.Int("attempt", 3), ) if err := handler.Handle(context.Background(), record); err != nil { t.Fatalf("Handle: %v", err) } }) wantContains(t, output, "casting") wantContains(t, output, "device=livingroom") wantContains(t, output, "file=movie.mp4") wantContains(t, output, "attempt=3") } func TestConsoleHandlerQuotesValuesNeedingIt(t *testing.T) { output := captureStdout(t, func() { handler := NewConsoleHandler() record := testRecord("casting", slog.String("file", "The Movie.mp4")) if err := handler.Handle(context.Background(), record); err != nil { t.Fatalf("Handle: %v", err) } }) wantContains(t, output, `file="The Movie.mp4"`) } func TestConsoleHandlerWithAttrsAccumulates(t *testing.T) { output := captureStdout(t, func() { handler := NewConsoleHandler(). WithAttrs([]slog.Attr{slog.String("service", "cattbox")}). WithAttrs([]slog.Attr{slog.String("component", "caster")}) record := testRecord("casting", slog.String("device", "livingroom")) if err := handler.Handle(context.Background(), record); err != nil { t.Fatalf("Handle: %v", err) } }) wantContains(t, output, "service=cattbox") wantContains(t, output, "component=caster") wantContains(t, output, "device=livingroom") } func TestConsoleHandlerWithAttrsDoesNotMutateReceiver(t *testing.T) { parent := NewConsoleHandler() first := parent.WithAttrs([]slog.Attr{slog.String("worker", "first")}) second := parent.WithAttrs([]slog.Attr{slog.String("worker", "second")}) firstOutput := captureStdout(t, func() { if err := first.Handle(context.Background(), testRecord("work")); err != nil { t.Fatalf("Handle: %v", err) } }) secondOutput := captureStdout(t, func() { if err := second.Handle(context.Background(), testRecord("work")); err != nil { t.Fatalf("Handle: %v", err) } }) parentOutput := captureStdout(t, func() { if err := parent.Handle(context.Background(), testRecord("work")); err != nil { t.Fatalf("Handle: %v", err) } }) wantContains(t, firstOutput, "worker=first") wantNotContains(t, firstOutput, "worker=second") wantContains(t, secondOutput, "worker=second") wantNotContains(t, secondOutput, "worker=first") wantNotContains(t, parentOutput, "worker=") } func TestConsoleHandlerWithGroupQualifiesAttrs(t *testing.T) { output := captureStdout(t, func() { handler := NewConsoleHandler(). WithGroup("cast"). WithAttrs([]slog.Attr{slog.String("device", "livingroom")}) record := testRecord("casting", slog.String("file", "movie.mp4")) if err := handler.Handle(context.Background(), record); err != nil { t.Fatalf("Handle: %v", err) } }) wantContains(t, output, "cast.device=livingroom") wantContains(t, output, "cast.file=movie.mp4") } func TestConsoleHandlerResolvesValues(t *testing.T) { output := captureStdout(t, func() { handler := NewConsoleHandler() record := testRecord( "cast failed", slog.Group("request", slog.Int("status", 502)), slog.Any("target", castTarget{id: "chromecast-7"}), slog.Any("error", errors.New("connection refused")), ) if err := handler.Handle(context.Background(), record); err != nil { t.Fatalf("Handle: %v", err) } }) wantContains(t, output, "request.status=502") wantContains(t, output, "target=chromecast-7") wantContains(t, output, `error="connection refused"`) } func TestWebhookHandlerEmitsAttrs(t *testing.T) { bodies := make(chan []byte, 1) server := httptest.NewServer(http.HandlerFunc( func(w http.ResponseWriter, r *http.Request) { body, err := io.ReadAll(r.Body) if err != nil { t.Errorf("read webhook body: %v", err) } bodies <- body w.WriteHeader(http.StatusOK) }, )) defer server.Close() handler, err := NewWebhookHandler(server.URL) if err != nil { t.Fatalf("NewWebhookHandler: %v", err) } withAttrs := handler.WithAttrs([]slog.Attr{slog.String("service", "cattbox")}) record := testRecord("casting", slog.String("device", "livingroom")) if err := withAttrs.Handle(context.Background(), record); err != nil { t.Fatalf("Handle: %v", err) } var body []byte select { case body = <-bodies: case <-time.After(5 * time.Second): t.Fatal("webhook handler posted nothing") } decoded := decodeLine(t, string(body)) wantField(t, decoded, "service", "cattbox") wantField(t, decoded, "device", "livingroom") } // TestMultiplexHandlerPassesAttrsThrough guards the composite handler that // package init installs: attributes must survive the multiplex too. func TestMultiplexHandlerPassesAttrsThrough(t *testing.T) { output := captureStdout(t, func() { handler := (&MultiplexHandler{handlers: []ExtendedHandler{NewJSONHandler()}}). WithAttrs([]slog.Attr{slog.String("service", "cattbox")}) record := testRecord("casting", slog.String("device", "livingroom")) if err := handler.Handle(context.Background(), record); err != nil { t.Fatalf("Handle: %v", err) } }) decoded := decodeLine(t, output) wantField(t, decoded, "service", "cattbox") wantField(t, decoded, "device", "livingroom") } // A logging library must read the values it is handed and never write to them. // The dangerous shape is a group that shares a key with something the caller // logged by reference: merging the group's members into whatever already sits // at that key would reach straight back into the caller's own data structure. // The next four tests hold every handler to that, through both the record path // and the derived-logger path. func TestJSONHandlerDoesNotMutateCallerMap(t *testing.T) { caller := map[string]any{"mine": "untouched"} output := captureStdout(t, func() { handler := NewJSONHandler() record := testRecord( "casting", slog.Any("g", caller), slog.Group("g", slog.Int("injected", 1)), ) if err := handler.Handle(context.Background(), record); err != nil { t.Fatalf("Handle: %v", err) } }) wantUnchanged(t, "map", caller, map[string]any{"mine": "untouched"}) // The later attribute wins the key outright, as any repeated key does. group := wantGroup(t, decodeLine(t, output), "g") wantField(t, group, "injected", float64(1)) wantNoField(t, group, "mine") } func TestJSONHandlerDoesNotMutateCallerMapThroughWithAttrs(t *testing.T) { caller := map[string]any{"id": "req-1"} output := captureStdout(t, func() { handler := NewJSONHandler(). WithAttrs([]slog.Attr{slog.Any("req", caller)}). WithGroup("req") record := testRecord("cast failed", slog.Int("status", 502)) if err := handler.Handle(context.Background(), record); err != nil { t.Fatalf("Handle: %v", err) } }) wantUnchanged(t, "map", caller, map[string]any{"id": "req-1"}) group := wantGroup(t, decodeLine(t, output), "req") wantField(t, group, "status", float64(502)) wantNoField(t, group, "id") } // TestJSONHandlerDoesNotMutateCallerSlice is the slice form of the same // hazard: a caller's slice is also handed over by reference, and appending // into its spare capacity would be just as visible to the caller as writing // into its map. The slice is built with room to spare so that an append within // capacity cannot hide behind an unchanged length. func TestJSONHandlerDoesNotMutateCallerSlice(t *testing.T) { caller := make([]any, 2, 4) caller[0] = "first" caller[1] = "second" output := captureStdout(t, func() { handler := NewJSONHandler() record := testRecord( "casting", slog.Any("s", caller), slog.Group("s", slog.Int("injected", 1)), ) if err := handler.Handle(context.Background(), record); err != nil { t.Fatalf("Handle: %v", err) } }) wantUnchanged(t, "slice", caller, []any{"first", "second"}) wantUnchanged( t, "slice backing array", caller[:cap(caller)], []any{"first", "second", nil, nil}, ) group := wantGroup(t, decodeLine(t, output), "s") wantField(t, group, "injected", float64(1)) } func TestConsoleHandlerDoesNotMutateCallerMap(t *testing.T) { caller := map[string]any{"mine": "untouched"} output := captureStdout(t, func() { handler := NewConsoleHandler() record := testRecord( "casting", slog.Any("g", caller), slog.Group("g", slog.Int("injected", 1)), ) if err := handler.Handle(context.Background(), record); err != nil { t.Fatalf("Handle: %v", err) } }) wantUnchanged(t, "map", caller, map[string]any{"mine": "untouched"}) wantContains(t, output, "g.injected=1") } func TestWebhookHandlerDoesNotMutateCallerMap(t *testing.T) { caller := map[string]any{"id": "req-1"} bodies := make(chan []byte, 1) server := httptest.NewServer(http.HandlerFunc( func(w http.ResponseWriter, r *http.Request) { body, err := io.ReadAll(r.Body) if err != nil { t.Errorf("read webhook body: %v", err) } bodies <- body w.WriteHeader(http.StatusOK) }, )) defer server.Close() handler, err := NewWebhookHandler(server.URL) if err != nil { t.Fatalf("NewWebhookHandler: %v", err) } derived := handler. WithAttrs([]slog.Attr{slog.Any("req", caller)}). WithGroup("req") record := testRecord("cast failed", slog.Int("status", 502)) if err := derived.Handle(context.Background(), record); err != nil { t.Fatalf("Handle: %v", err) } var body []byte select { case body = <-bodies: case <-time.After(5 * time.Second): t.Fatal("webhook handler posted nothing") } wantUnchanged(t, "map", caller, map[string]any{"id": "req-1"}) group := wantGroup(t, decodeLine(t, string(body)), "req") wantField(t, group, "status", float64(502)) } // TestJSONHandlerRendersDurationAsNanoseconds pins the json rendering of a // duration to a number of nanoseconds, which is what slog.NewJSONHandler // emits. A consumer that sums or compares the field needs a number; the "3s" // form would silently arrive as a string. func TestJSONHandlerRendersDurationAsNanoseconds(t *testing.T) { output := captureStdout(t, func() { handler := NewJSONHandler() record := testRecord("casting", slog.Duration("elapsed", 3*time.Second)) if err := handler.Handle(context.Background(), record); err != nil { t.Fatalf("Handle: %v", err) } }) decoded := decodeLine(t, output) if _, isNumber := decoded["elapsed"].(float64); !isNumber { t.Fatalf("field \"elapsed\" = %#v, want a json number", decoded["elapsed"]) } wantField(t, decoded, "elapsed", float64((3 * time.Second).Nanoseconds())) } // TestConsoleHandlerRendersDurationReadably is the other half of that choice: // the console line is read by a person, so it carries the same human-readable // form slog.NewTextHandler uses. func TestConsoleHandlerRendersDurationReadably(t *testing.T) { output := captureStdout(t, func() { handler := NewConsoleHandler() record := testRecord("casting", slog.Duration("elapsed", 3*time.Second)) if err := handler.Handle(context.Background(), record); err != nil { t.Fatalf("Handle: %v", err) } }) wantContains(t, output, "elapsed=3s") } // TestJSONHandlerContractEdgeCases pins the slog.Handler contract's four // edge cases. Every case carries a control attribute as well, so a handler // that emitted no attributes at all would fail rather than pass by omission. // // The empty group is attached through WithAttrs rather than to the record, // because slog.Record.AddAttrs elides empty groups itself: routed through the // record, the case would never reach the handler at all. func TestJSONHandlerContractEdgeCases(t *testing.T) { tests := []struct { name string build func() slog.Handler attrs []slog.Attr verify func(t *testing.T, decoded map[string]any) }{ { name: "empty attr is ignored", build: func() slog.Handler { return NewJSONHandler() }, attrs: []slog.Attr{{}, slog.String("kept", "yes")}, verify: func(t *testing.T, decoded map[string]any) { wantField(t, decoded, "kept", "yes") wantNoField(t, decoded, "") }, }, { name: "empty group is elided along with its key", build: func() slog.Handler { return NewJSONHandler(). WithAttrs([]slog.Attr{slog.Group("empty")}) }, attrs: []slog.Attr{slog.String("kept", "yes")}, verify: func(t *testing.T, decoded map[string]any) { wantField(t, decoded, "kept", "yes") wantNoField(t, decoded, "empty") }, }, { name: "group with an empty key is inlined", build: func() slog.Handler { return NewJSONHandler() }, attrs: []slog.Attr{ slog.Group("", slog.String("inner", "yes")), }, verify: func(t *testing.T, decoded map[string]any) { wantField(t, decoded, "inner", "yes") wantNoField(t, decoded, "") }, }, { name: "WithGroup with an empty name is a no-op", build: func() slog.Handler { return NewJSONHandler().WithGroup("") }, attrs: []slog.Attr{slog.String("kept", "yes")}, verify: func(t *testing.T, decoded map[string]any) { wantField(t, decoded, "kept", "yes") wantNoField(t, decoded, "") }, }, } for _, test := range tests { t.Run(test.name, func(t *testing.T) { output := captureStdout(t, func() { handler := test.build() record := testRecord("casting", test.attrs...) if err := handler.Handle(context.Background(), record); err != nil { t.Fatalf("Handle: %v", err) } }) test.verify(t, decodeLine(t, output)) }) } } // TestConsoleHandlerContractEdgeCases holds the console handler to the same // four rules, since it renders attributes through its own code path. func TestConsoleHandlerContractEdgeCases(t *testing.T) { tests := []struct { name string build func() slog.Handler attrs []slog.Attr want string notWant string }{ { name: "empty attr is ignored", build: func() slog.Handler { return NewConsoleHandler() }, attrs: []slog.Attr{{}, slog.String("kept", "yes")}, want: "kept=yes", notWant: " =", }, { name: "empty group is elided along with its key", build: func() slog.Handler { return NewConsoleHandler(). WithAttrs([]slog.Attr{slog.Group("empty")}) }, attrs: []slog.Attr{slog.String("kept", "yes")}, want: "kept=yes", notWant: "empty=", }, { name: "group with an empty key is inlined", build: func() slog.Handler { return NewConsoleHandler() }, attrs: []slog.Attr{ slog.Group("", slog.String("inner", "yes")), }, want: " inner=yes", notWant: ".inner=", }, { name: "WithGroup with an empty name is a no-op", build: func() slog.Handler { return NewConsoleHandler().WithGroup("") }, attrs: []slog.Attr{slog.String("kept", "yes")}, want: " kept=yes", notWant: ".kept=", }, } for _, test := range tests { t.Run(test.name, func(t *testing.T) { output := captureStdout(t, func() { handler := test.build() record := testRecord("casting", test.attrs...) if err := handler.Handle(context.Background(), record); err != nil { t.Fatalf("Handle: %v", err) } }) wantContains(t, output, test.want) wantNotContains(t, output, test.notWant) }) } } // TestJSONHandlerRecordFieldsWinKeyCollision pins a caller-visible surprise: // the json payload is an object, so the record's own fields own their names // and an attribute keyed after one of them is dropped rather than emitted. func TestJSONHandlerRecordFieldsWinKeyCollision(t *testing.T) { output := captureStdout(t, func() { handler := NewJSONHandler() record := testRecord( "the real message", slog.String("Time", "hijacked"), slog.String("Level", "hijacked"), slog.String("Message", "hijacked"), slog.String("PC", "hijacked"), slog.String("kept", "yes"), ) if err := handler.Handle(context.Background(), record); err != nil { t.Fatalf("Handle: %v", err) } }) decoded := decodeLine(t, output) wantField(t, decoded, "kept", "yes") wantField(t, decoded, "Message", "the real message") wantField(t, decoded, "Level", "INFO") for _, reserved := range []string{"Time", "PC"} { if decoded[reserved] == "hijacked" { t.Fatalf("attribute overwrote the record's own %q field: %v", reserved, decoded) } } } // TestJSONHandlerDuplicateKeysKeepLast pins the other consequence of the // payload being an object: a key logged twice collapses to its last value. func TestJSONHandlerDuplicateKeysKeepLast(t *testing.T) { output := captureStdout(t, func() { handler := NewJSONHandler() record := testRecord( "casting", slog.String("device", "kitchen"), slog.String("device", "livingroom"), ) if err := handler.Handle(context.Background(), record); err != nil { t.Fatalf("Handle: %v", err) } }) wantField(t, decodeLine(t, output), "device", "livingroom") } // TestConsoleHandlerKeepsDuplicateKeys is the console counterpart: a line of // text is not an object, so both pairs survive there. func TestConsoleHandlerKeepsDuplicateKeys(t *testing.T) { output := captureStdout(t, func() { handler := NewConsoleHandler() record := testRecord( "casting", slog.String("device", "kitchen"), slog.String("device", "livingroom"), ) if err := handler.Handle(context.Background(), record); err != nil { t.Fatalf("Handle: %v", err) } }) wantContains(t, output, "device=kitchen") wantContains(t, output, "device=livingroom") }