Skip to content

Commit 99abaf9

Browse files
authored
fix!: don't panic, only accept typed log Fields (#222)
* fix: don't panic, only accept typed log Fields * slogtest errors if we fail to stringify a field value
1 parent 40ff199 commit 99abaf9

File tree

5 files changed

+77
-113
lines changed

5 files changed

+77
-113
lines changed

internal/entryhuman/entry.go

Lines changed: 34 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -56,33 +56,34 @@ func reset(w io.Writer, termW io.Writer) {
5656
}
5757
}
5858

59-
func formatValue(v interface{}) string {
59+
func formatValue(v interface{}) (string, error) {
6060
if vr, ok := v.(driver.Valuer); ok {
6161
var err error
6262
v, err = vr.Value()
6363
if err != nil {
64-
return fmt.Sprintf("error calling Value: %v", err)
64+
return "", xerrors.Errorf("error calling Value: %w", err)
6565
}
6666
}
6767
if v == nil {
68-
return "<nil>"
68+
return "<nil>", nil
6969
}
7070
typ := reflect.TypeOf(v)
7171
switch typ.Kind() {
7272
case reflect.Struct, reflect.Map:
7373
byt, err := json.Marshal(v)
7474
if err != nil {
75-
panic(err)
75+
// don't panic
76+
return "", xerrors.Errorf("error marshalling value: %w", err)
7677
}
77-
return string(byt)
78+
return string(byt), nil
7879
case reflect.Slice:
7980
// Byte slices are optimistically readable.
8081
if typ.Elem().Kind() == reflect.Uint8 {
81-
return fmt.Sprintf("%q", v)
82+
return fmt.Sprintf("%q", v), nil
8283
}
8384
fallthrough
8485
default:
85-
return quote(fmt.Sprintf("%+v", v))
86+
return quote(fmt.Sprintf("%+v", v)), nil
8687
}
8788
}
8889

@@ -174,6 +175,10 @@ func writeValueFast(w io.Writer, v interface{}) (bool, error) {
174175
}
175176
}
176177

178+
type Formatter struct {
179+
ErrorCallback func(slog.Field, error)
180+
}
181+
177182
// Fmt returns a human readable format for ent. Assumes we have a bytes.Buffer
178183
// which we will more easily be able to assume underlying reallocation of it's size is possible
179184
// if necessary than for an arbitrary io.Writer/io.StringWriter
@@ -187,6 +192,10 @@ func writeValueFast(w io.Writer, v interface{}) (bool, error) {
187192
// for extra lines in a log so if we did it here, the fields would be indented
188193
// twice in test logs. So the Stderr logger indents all the fields itself.
189194
func Fmt(buf *bytes.Buffer, termW io.Writer, ent slog.SinkEntry) {
195+
Formatter{}.Fmt(buf, termW, ent)
196+
}
197+
198+
func (f Formatter) Fmt(buf *bytes.Buffer, termW io.Writer, ent slog.SinkEntry) {
190199
reset(buf, termW)
191200

192201
// Timestamp + space
@@ -238,12 +247,12 @@ func Fmt(buf *bytes.Buffer, termW io.Writer, ent slog.SinkEntry) {
238247

239248
// Find a multiline field without mutating ent.Fields.
240249
multiIdx := -1
241-
for i, f := range ent.Fields {
250+
for i, fld := range ent.Fields {
242251
if multilineVal != "" {
243252
break
244253
}
245254
var s string
246-
switch v := f.Value.(type) {
255+
switch v := fld.Value.(type) {
247256
case string:
248257
s = v
249258
case error, xerrors.Formatter:
@@ -254,27 +263,35 @@ func Fmt(buf *bytes.Buffer, termW io.Writer, ent slog.SinkEntry) {
254263
continue
255264
}
256265
multiIdx = i
257-
multilineKey = f.Name
266+
multilineKey = fld.Name
258267
multilineVal = s
259268
break
260269
}
261270

262271
// Print fields (skip multiline field index).
263-
for i, f := range ent.Fields {
272+
for i, fld := range ent.Fields {
264273
if i == multiIdx {
265274
continue
266275
}
267276
if i < len(ent.Fields) {
268277
buf.WriteString(tab)
269278
}
270279

271-
buf.WriteString(render(termW, keyStyle, quoteKey(f.Name)))
280+
buf.WriteString(render(termW, keyStyle, quoteKey(fld.Name)))
272281
buf.WriteString(render(termW, equalsStyle, "="))
273282

274-
if ok, err := writeValueFast(buf, f.Value); err != nil {
275-
// return err
283+
if ok, err := writeValueFast(buf, fld.Value); err != nil && f.ErrorCallback != nil {
284+
f.ErrorCallback(fld, err)
276285
} else if !ok {
277-
buf.WriteString(formatValue(f.Value))
286+
s, err := formatValue(fld.Value)
287+
if err != nil {
288+
if f.ErrorCallback != nil {
289+
f.ErrorCallback(fld, err)
290+
}
291+
buf.WriteString(err.Error())
292+
continue
293+
}
294+
buf.WriteString(s)
278295
}
279296
}
280297

@@ -334,7 +351,8 @@ func levelStyle(level slog.Level) lipgloss.Style {
334351
case slog.LevelError, slog.LevelFatal, slog.LevelCritical:
335352
return levelErrorStyle
336353
default:
337-
panic("unknown level")
354+
// don't panic
355+
return levelErrorStyle
338356
}
339357
}
340358

slog.go

Lines changed: 7 additions & 59 deletions
Original file line numberDiff line numberDiff line change
@@ -80,67 +80,40 @@ func Make(sinks ...Sink) Logger {
8080
}
8181

8282
// Debug logs the msg and fields at LevelDebug.
83-
// See Info for information on the fields argument.
84-
func (l Logger) Debug(ctx context.Context, msg string, fields ...any) {
83+
func (l Logger) Debug(ctx context.Context, msg string, fields ...Field) {
8584
l.log(ctx, LevelDebug, msg, fields)
8685
}
8786

8887
// Info logs the msg and fields at LevelInfo.
89-
// Fields may contain any combination of key value pairs, Field, and Map.
90-
// For example:
91-
//
92-
// log.Info(ctx, "something happened", "user", "alex", slog.F("age", 20))
93-
//
94-
// is equivalent to:
95-
//
96-
// log.Info(ctx, "something happened", slog.F("user", "alex"), slog.F("age", 20))
97-
//
98-
// is equivalent to:
99-
//
100-
// log.Info(ctx, "something happened", slog.M(
101-
// slog.F("user", "alex"),
102-
// slog.F("age", 20),
103-
// ))
104-
//
105-
// is equivalent to:
106-
//
107-
// log.Info(ctx, "something happened", "user", "alex", "age", 20)
108-
//
109-
// In general, prefer using key value pairs over Field and Map, as that is how
110-
// the standard library's slog package works.
111-
func (l Logger) Info(ctx context.Context, msg string, fields ...any) {
88+
func (l Logger) Info(ctx context.Context, msg string, fields ...Field) {
11289
l.log(ctx, LevelInfo, msg, fields)
11390
}
11491

11592
// Warn logs the msg and fields at LevelWarn.
116-
// See Info() for information on the fields argument.
117-
func (l Logger) Warn(ctx context.Context, msg string, fields ...any) {
93+
func (l Logger) Warn(ctx context.Context, msg string, fields ...Field) {
11894
l.log(ctx, LevelWarn, msg, fields)
11995
}
12096

12197
// Error logs the msg and fields at LevelError.
122-
// See Info() for information on the fields argument.
12398
//
12499
// It will then Sync().
125-
func (l Logger) Error(ctx context.Context, msg string, fields ...any) {
100+
func (l Logger) Error(ctx context.Context, msg string, fields ...Field) {
126101
l.log(ctx, LevelError, msg, fields)
127102
l.Sync()
128103
}
129104

130105
// Critical logs the msg and fields at LevelCritical.
131-
// See Info() for information on the fields argument.
132106
//
133107
// It will then Sync().
134-
func (l Logger) Critical(ctx context.Context, msg string, fields ...any) {
108+
func (l Logger) Critical(ctx context.Context, msg string, fields ...Field) {
135109
l.log(ctx, LevelCritical, msg, fields)
136110
l.Sync()
137111
}
138112

139113
// Fatal logs the msg and fields at LevelFatal.
140-
// See Info() for information on the fields argument.
141114
//
142115
// It will then Sync() and os.Exit(1).
143-
func (l Logger) Fatal(ctx context.Context, msg string, fields ...any) {
116+
func (l Logger) Fatal(ctx context.Context, msg string, fields ...Field) {
144117
l.log(ctx, LevelFatal, msg, fields)
145118
l.Sync()
146119

@@ -182,32 +155,7 @@ func (l Logger) AppendSinks(s ...Sink) Logger {
182155
return l
183156
}
184157

185-
func (l Logger) log(ctx context.Context, level Level, msg string, rawFields []any) {
186-
fields := make(Map, 0, len(rawFields))
187-
var wipField Field
188-
for i, f := range rawFields {
189-
if wipField.Name != "" {
190-
wipField.Value = f
191-
fields = append(fields, wipField)
192-
wipField = Field{}
193-
continue
194-
}
195-
switch f := f.(type) {
196-
case Field:
197-
fields = append(fields, f)
198-
case Map:
199-
fields = append(fields, f...)
200-
case string:
201-
wipField.Name = f
202-
default:
203-
panic(fmt.Sprintf("unexpected field type %T at index %v (does it have a key?)", f, i))
204-
}
205-
}
206-
207-
if wipField.Name != "" {
208-
panic(fmt.Sprintf("field %q has no value", wipField.Name))
209-
}
210-
158+
func (l Logger) log(ctx context.Context, level Level, msg string, fields []Field) {
211159
ent := l.entry(ctx, level, msg, fields)
212160
l.Log(ctx, ent)
213161
}

slog_test.go

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

33
import (
44
"context"
5-
"fmt"
65
"io"
76
"runtime"
87
"testing"
@@ -76,7 +75,7 @@ func TestLogger(t *testing.T) {
7675

7776
File: slogTestFile,
7877
Func: "cdr.dev/slog_test.TestLogger.func2",
79-
Line: 68,
78+
Line: 67,
8079

8180
Fields: slog.M(
8281
slog.F("ctx", 1024),
@@ -113,7 +112,7 @@ func TestLogger(t *testing.T) {
113112

114113
File: slogTestFile,
115114
Func: "cdr.dev/slog_test.TestLogger.func3",
116-
Line: 103,
115+
Line: 102,
117116

118117
SpanContext: span.SpanContext(),
119118

@@ -154,36 +153,6 @@ func TestLogger(t *testing.T) {
154153
assert.Equal(t, "level", slog.LevelFatal, s.entries[5].Level)
155154
assert.Equal(t, "exits", 1, exits)
156155
})
157-
158-
t.Run("kv", func(t *testing.T) {
159-
s := &fakeSink{}
160-
l := slog.Make(s)
161-
162-
// All of these formats should be equivalent.
163-
formats := [][]any{
164-
{"animal", "cat", "weight", 15},
165-
{slog.F("animal", "cat"), "weight", 15},
166-
{slog.M(
167-
slog.F("animal", "cat"),
168-
slog.F("weight", 15),
169-
)},
170-
{slog.F("animal", "cat"), slog.F("weight", 15)},
171-
}
172-
173-
for _, format := range formats {
174-
l.Info(bg, "msg", format...)
175-
}
176-
177-
assert.Len(t, "entries", 4, s.entries)
178-
179-
for i := range s.entries {
180-
assert.Equal(
181-
t, fmt.Sprintf("%v", i),
182-
s.entries[0].Fields,
183-
s.entries[i].Fields,
184-
)
185-
}
186-
})
187156
}
188157

189158
func TestLevel_String(t *testing.T) {

sloggers/slogtest/t.go

Lines changed: 10 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -99,7 +99,12 @@ func (ts *testSink) LogEntry(_ context.Context, ent slog.SinkEntry) {
9999

100100
var sb bytes.Buffer
101101
// The testing package logs to stdout and not stderr.
102-
entryhuman.Fmt(&sb, os.Stdout, ent)
102+
f := entryhuman.Formatter{
103+
ErrorCallback: func(field slog.Field, err error) {
104+
ts.tb.Errorf("failed to log field %q: %v", field.Name, err)
105+
},
106+
}
107+
f.Fmt(&sb, os.Stdout, ent)
103108

104109
switch ent.Level {
105110
case slog.LevelDebug, slog.LevelInfo, slog.LevelWarn:
@@ -146,25 +151,25 @@ func l(t testing.TB) slog.Logger {
146151
}
147152

148153
// Debug logs the given msg and fields to t via t.Log at the debug level.
149-
func Debug(t testing.TB, msg string, fields ...any) {
154+
func Debug(t testing.TB, msg string, fields ...slog.Field) {
150155
slog.Helper()
151156
l(t).Debug(ctx, msg, fields...)
152157
}
153158

154159
// Info logs the given msg and fields to t via t.Log at the info level.
155-
func Info(t testing.TB, msg string, fields ...any) {
160+
func Info(t testing.TB, msg string, fields ...slog.Field) {
156161
slog.Helper()
157162
l(t).Info(ctx, msg, fields...)
158163
}
159164

160165
// Error logs the given msg and fields to t via t.Error at the error level.
161-
func Error(t testing.TB, msg string, fields ...any) {
166+
func Error(t testing.TB, msg string, fields ...slog.Field) {
162167
slog.Helper()
163168
l(t).Error(ctx, msg, fields...)
164169
}
165170

166171
// Fatal logs the given msg and fields to t via t.Fatal at the fatal level.
167-
func Fatal(t testing.TB, msg string, fields ...any) {
172+
func Fatal(t testing.TB, msg string, fields ...slog.Field) {
168173
slog.Helper()
169174
l(t).Fatal(ctx, msg, fields...)
170175
}

sloggers/slogtest/t_test.go

Lines changed: 24 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,7 @@ package slogtest_test
33
import (
44
"context"
55
"fmt"
6+
"strings"
67
"testing"
78

89
"golang.org/x/xerrors"
@@ -175,13 +176,31 @@ func TestSkipCleanup(t *testing.T) {
175176
assert.Len(t, "no cleanups", 0, tb.cleanups)
176177
}
177178

179+
func TestUnmarshalable(t *testing.T) {
180+
t.Parallel()
181+
tb := &fakeTB{}
182+
l := slogtest.Make(tb, &slogtest.Options{})
183+
s := &selfRef{}
184+
s.Ref = s
185+
s2 := selfRef{Ref: s} // unmarshalable because it contains a cyclic ref
186+
l.Info(bg, "hello", slog.F("self", s2))
187+
assert.Equal(t, "errors", 1, tb.errors)
188+
assert.Len(t, "len errorfs", 1, tb.errorfs)
189+
assert.True(t, "errorfs", strings.Contains(tb.errorfs[0], "failed to log field \"self\":"))
190+
}
191+
192+
type selfRef struct {
193+
Ref *selfRef
194+
}
195+
178196
var bg = context.Background()
179197

180198
type fakeTB struct {
181199
testing.TB
182200

183201
logs int
184202
errors int
203+
errorfs []string
185204
fatals int
186205
cleanups []func()
187206
}
@@ -196,6 +215,11 @@ func (tb *fakeTB) Error(v ...interface{}) {
196215
tb.errors++
197216
}
198217

218+
func (tb *fakeTB) Errorf(msg string, v ...interface{}) {
219+
tb.errors++
220+
tb.errorfs = append(tb.errorfs, fmt.Sprintf(msg, v...))
221+
}
222+
199223
func (tb *fakeTB) Fatal(v ...interface{}) {
200224
tb.fatals++
201225
panic("")

0 commit comments

Comments
 (0)