Skip to content

Commit 284c50f

Browse files
dannykoppingclaude
andauthored
fix: render error types as strings in human log sink (#224)
`formatValue` checked `reflect.Struct` before checking the `error` interface, so struct-typed errors like `context.DeadlineExceeded` were serialized via `json.Marshal` as `{}` instead of their error string. Co-authored-by: Claude Opus 4.6 <noreply@anthropic.com>
1 parent 348ac12 commit 284c50f

File tree

4 files changed

+115
-4
lines changed

4 files changed

+115
-4
lines changed

internal/entryhuman/entry.go

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -67,6 +67,10 @@ func formatValue(v interface{}) (string, error) {
6767
if v == nil {
6868
return "<nil>", nil
6969
}
70+
switch v.(type) {
71+
case error, fmt.Stringer:
72+
return quote(fmt.Sprintf("%+v", v)), nil
73+
}
7074
typ := reflect.TypeOf(v)
7175
switch typ.Kind() {
7276
case reflect.Struct, reflect.Map:

internal/entryhuman/entry_test.go

Lines changed: 48 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -2,12 +2,14 @@ package entryhuman_test
22

33
import (
44
"bytes"
5+
"context"
56
"database/sql"
67
"flag"
78
"fmt"
89
"io"
910
"math"
1011
"os"
12+
"strings"
1113
"testing"
1214
"time"
1315

@@ -284,6 +286,52 @@ func TestEntry(t *testing.T) {
284286
})
285287
}
286288

289+
func TestContextErrorFormatting(t *testing.T) {
290+
t.Parallel()
291+
292+
tests := []struct {
293+
name string
294+
err error
295+
expected string
296+
}{
297+
{
298+
name: "DeadlineExceeded",
299+
err: context.DeadlineExceeded,
300+
expected: "context deadline exceeded",
301+
},
302+
{
303+
name: "Canceled",
304+
err: context.Canceled,
305+
expected: "context canceled",
306+
},
307+
{
308+
name: "WrappedDeadlineExceeded",
309+
err: fmt.Errorf("request failed: %w", context.DeadlineExceeded),
310+
expected: "request failed: context deadline exceeded",
311+
},
312+
}
313+
314+
for _, tc := range tests {
315+
tc := tc
316+
t.Run(tc.name, func(t *testing.T) {
317+
t.Parallel()
318+
319+
var buf bytes.Buffer
320+
entryhuman.Fmt(&buf, io.Discard, slog.SinkEntry{
321+
Level: slog.LevelError,
322+
Message: "something failed",
323+
Fields: slog.M(
324+
slog.Error(tc.err),
325+
),
326+
})
327+
328+
got := buf.String()
329+
assert.False(t, "error not empty object", strings.Contains(got, "error={}"))
330+
assert.True(t, "error contains expected string", strings.Contains(got, tc.expected))
331+
})
332+
}
333+
}
334+
287335
func BenchmarkFmt(b *testing.B) {
288336
bench := func(b *testing.B, color bool) {
289337
nfs := []int{1, 4, 16}

map_test.go

Lines changed: 23 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,7 @@ package slog_test
22

33
import (
44
"bytes"
5+
"context"
56
"encoding/json"
67
"io"
78
"runtime"
@@ -62,12 +63,12 @@ func TestMap(t *testing.T) {
6263
{
6364
"msg": "wrap1",
6465
"fun": "cdr.dev/slog/v3_test.TestMap.func2",
65-
"loc": "`+mapTestFile+`:41"
66+
"loc": "`+mapTestFile+`:42"
6667
},
6768
{
6869
"msg": "wrap2",
6970
"fun": "cdr.dev/slog/v3_test.TestMap.func2",
70-
"loc": "`+mapTestFile+`:42"
71+
"loc": "`+mapTestFile+`:43"
7172
},
7273
"EOF"
7374
],
@@ -220,6 +221,26 @@ func TestMap(t *testing.T) {
220221
"val": "{meow:hi bar:23 far:600}"
221222
}`)
222223
})
224+
225+
t.Run("contextDeadlineExceeded", func(t *testing.T) {
226+
t.Parallel()
227+
228+
test(t, slog.M(
229+
slog.Error(context.DeadlineExceeded),
230+
), `{
231+
"error": "context deadline exceeded"
232+
}`)
233+
})
234+
235+
t.Run("contextCanceled", func(t *testing.T) {
236+
t.Parallel()
237+
238+
test(t, slog.M(
239+
slog.Error(context.Canceled),
240+
), `{
241+
"error": "context canceled"
242+
}`)
243+
})
223244
}
224245

225246
func indentJSON(t *testing.T, j string) string {

sloggers/slogjson/slogjson_test.go

Lines changed: 40 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,7 @@ import (
66
"database/sql"
77
"fmt"
88
"runtime"
9+
"strings"
910
"testing"
1011

1112
sdktrace "go.opentelemetry.io/otel/sdk/trace"
@@ -34,7 +35,7 @@ func TestMake(t *testing.T) {
3435
l.Error(ctx, "line1\n\nline2", slog.F("wowow", "me\nyou"))
3536

3637
j := entryjson.Filter(b.String(), "ts")
37-
exp := fmt.Sprintf(`{"level":"ERROR","msg":"line1\n\nline2","caller":"%v:34","func":"cdr.dev/slog/v3/sloggers/slogjson_test.TestMake","logger_names":["named"],"trace":"%v","span":"%v","fields":{"wowow":"me\nyou"}}
38+
exp := fmt.Sprintf(`{"level":"ERROR","msg":"line1\n\nline2","caller":"%v:35","func":"cdr.dev/slog/v3/sloggers/slogjson_test.TestMake","logger_names":["named"],"trace":"%v","span":"%v","fields":{"wowow":"me\nyou"}}
3839
`, slogjsonTestFile, span.SpanContext().TraceID().String(), span.SpanContext().SpanID().String())
3940
assert.Equal(t, "entry", exp, j)
4041
}
@@ -60,7 +61,44 @@ func TestNoDriverValue(t *testing.T) {
6061
l.Error(bg, "error!", slog.F("inval", invalidField), slog.F("val", validField), slog.F("int", validInt))
6162

6263
j := entryjson.Filter(b.String(), "ts")
63-
exp := fmt.Sprintf(`{"level":"ERROR","msg":"error!","caller":"%v:60","func":"cdr.dev/slog/v3/sloggers/slogjson_test.TestNoDriverValue","logger_names":["named"],"fields":{"inval":null,"val":"cat","int":42}}
64+
exp := fmt.Sprintf(`{"level":"ERROR","msg":"error!","caller":"%v:61","func":"cdr.dev/slog/v3/sloggers/slogjson_test.TestNoDriverValue","logger_names":["named"],"fields":{"inval":null,"val":"cat","int":42}}
6465
`, slogjsonTestFile)
6566
assert.Equal(t, "entry", exp, j)
6667
}
68+
69+
func TestContextErrors(t *testing.T) {
70+
t.Parallel()
71+
72+
t.Run("DeadlineExceeded", func(t *testing.T) {
73+
t.Parallel()
74+
75+
b := &bytes.Buffer{}
76+
l := slog.Make(slogjson.Sink(b))
77+
l.Error(bg, "request failed", slog.Error(context.DeadlineExceeded))
78+
79+
j := entryjson.Filter(b.String(), "ts")
80+
assert.True(t, "error contains deadline exceeded", strings.Contains(j, `"error":"context deadline exceeded"`))
81+
})
82+
83+
t.Run("Canceled", func(t *testing.T) {
84+
t.Parallel()
85+
86+
b := &bytes.Buffer{}
87+
l := slog.Make(slogjson.Sink(b))
88+
l.Error(bg, "request failed", slog.Error(context.Canceled))
89+
90+
j := entryjson.Filter(b.String(), "ts")
91+
assert.True(t, "error contains context canceled", strings.Contains(j, `"error":"context canceled"`))
92+
})
93+
94+
t.Run("WrappedDeadlineExceeded", func(t *testing.T) {
95+
t.Parallel()
96+
97+
b := &bytes.Buffer{}
98+
l := slog.Make(slogjson.Sink(b))
99+
l.Error(bg, "request failed", slog.Error(fmt.Errorf("dial: %w", context.DeadlineExceeded)))
100+
101+
j := entryjson.Filter(b.String(), "ts")
102+
assert.True(t, "error contains dial: context deadline exceeded", strings.Contains(j, `"error":"dial: context deadline exceeded"`))
103+
})
104+
}

0 commit comments

Comments
 (0)