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

Author: spikecurtis

internal/entryhuman/entry.go

@@ -56,33 +56,34 @@ func reset(w io.Writer, termW io.Writer) {
 	}
 }
 
-func formatValue(v interface{}) string {
+func formatValue(v interface{}) (string, error) {
 	if vr, ok := v.(driver.Valuer); ok {
 		var err error
 		v, err = vr.Value()
 		if err != nil {
-			return fmt.Sprintf("error calling Value: %v", err)
+			return "", xerrors.Errorf("error calling Value: %w", err)
 		}
 	}
 	if v == nil {
-		return "<nil>"
+		return "<nil>", nil
 	}
 	typ := reflect.TypeOf(v)
 	switch typ.Kind() {
 	case reflect.Struct, reflect.Map:
 		byt, err := json.Marshal(v)
 		if err != nil {
-			panic(err)
+			// don't panic
+			return "", xerrors.Errorf("error marshalling value: %w", err)
 		}
-		return string(byt)
+		return string(byt), nil
 	case reflect.Slice:
 		// Byte slices are optimistically readable.
 		if typ.Elem().Kind() == reflect.Uint8 {
-			return fmt.Sprintf("%q", v)
+			return fmt.Sprintf("%q", v), nil
 		}
 		fallthrough
 	default:
-		return quote(fmt.Sprintf("%+v", v))
+		return quote(fmt.Sprintf("%+v", v)), nil
 	}
 }
 
@@ -174,6 +175,10 @@ func writeValueFast(w io.Writer, v interface{}) (bool, error) {
 	}
 }
 
+type Formatter struct {
+	ErrorCallback func(slog.Field, error)
+}
+
 // Fmt returns a human readable format for ent. Assumes we have a bytes.Buffer
 // which we will more easily be able to assume underlying reallocation of it's size is possible
 // if necessary than for an arbitrary io.Writer/io.StringWriter
@@ -187,6 +192,10 @@ func writeValueFast(w io.Writer, v interface{}) (bool, error) {
 // for extra lines in a log so if we did it here, the fields would be indented
 // twice in test logs. So the Stderr logger indents all the fields itself.
 func Fmt(buf *bytes.Buffer, termW io.Writer, ent slog.SinkEntry) {
+	Formatter{}.Fmt(buf, termW, ent)
+}
+
+func (f Formatter) Fmt(buf *bytes.Buffer, termW io.Writer, ent slog.SinkEntry) {
 	reset(buf, termW)
 
 	// Timestamp + space
@@ -238,12 +247,12 @@ func Fmt(buf *bytes.Buffer, termW io.Writer, ent slog.SinkEntry) {
 
 	// Find a multiline field without mutating ent.Fields.
 	multiIdx := -1
-	for i, f := range ent.Fields {
+	for i, fld := range ent.Fields {
 		if multilineVal != "" {
 			break
 		}
 		var s string
-		switch v := f.Value.(type) {
+		switch v := fld.Value.(type) {
 		case string:
 			s = v
 		case error, xerrors.Formatter:
@@ -254,27 +263,35 @@ func Fmt(buf *bytes.Buffer, termW io.Writer, ent slog.SinkEntry) {
 			continue
 		}
 		multiIdx = i
-		multilineKey = f.Name
+		multilineKey = fld.Name
 		multilineVal = s
 		break
 	}
 
 	// Print fields (skip multiline field index).
-	for i, f := range ent.Fields {
+	for i, fld := range ent.Fields {
 		if i == multiIdx {
 			continue
 		}
 		if i < len(ent.Fields) {
 			buf.WriteString(tab)
 		}
 
-		buf.WriteString(render(termW, keyStyle, quoteKey(f.Name)))
+		buf.WriteString(render(termW, keyStyle, quoteKey(fld.Name)))
 		buf.WriteString(render(termW, equalsStyle, "="))
 
-		if ok, err := writeValueFast(buf, f.Value); err != nil {
-			// return err
+		if ok, err := writeValueFast(buf, fld.Value); err != nil && f.ErrorCallback != nil {
+			f.ErrorCallback(fld, err)
 		} else if !ok {
-			buf.WriteString(formatValue(f.Value))
+			s, err := formatValue(fld.Value)
+			if err != nil {
+				if f.ErrorCallback != nil {
+					f.ErrorCallback(fld, err)
+				}
+				buf.WriteString(err.Error())
+				continue
+			}
+			buf.WriteString(s)
 		}
 	}
 
@@ -334,7 +351,8 @@ func levelStyle(level slog.Level) lipgloss.Style {
 	case slog.LevelError, slog.LevelFatal, slog.LevelCritical:
 		return levelErrorStyle
 	default:
-		panic("unknown level")
+		// don't panic
+		return levelErrorStyle
 	}
 }
 

slog.go

@@ -80,67 +80,40 @@ func Make(sinks ...Sink) Logger {
 }
 
 // Debug logs the msg and fields at LevelDebug.
-// See Info for information on the fields argument.
-func (l Logger) Debug(ctx context.Context, msg string, fields ...any) {
+func (l Logger) Debug(ctx context.Context, msg string, fields ...Field) {
 	l.log(ctx, LevelDebug, msg, fields)
 }
 
 // Info logs the msg and fields at LevelInfo.
-// Fields may contain any combination of key value pairs, Field, and Map.
-// For example:
-//
-//	log.Info(ctx, "something happened", "user", "alex", slog.F("age", 20))
-//
-// is equivalent to:
-//
-//	log.Info(ctx, "something happened", slog.F("user", "alex"), slog.F("age", 20))
-//
-// is equivalent to:
-//
-//	log.Info(ctx, "something happened", slog.M(
-//		slog.F("user", "alex"),
-//		slog.F("age", 20),
-//	))
-//
-// is equivalent to:
-//
-//	log.Info(ctx, "something happened", "user", "alex", "age", 20)
-//
-// In general, prefer using key value pairs over Field and Map, as that is how
-// the standard library's slog package works.
-func (l Logger) Info(ctx context.Context, msg string, fields ...any) {
+func (l Logger) Info(ctx context.Context, msg string, fields ...Field) {
 	l.log(ctx, LevelInfo, msg, fields)
 }
 
 // Warn logs the msg and fields at LevelWarn.
-// See Info() for information on the fields argument.
-func (l Logger) Warn(ctx context.Context, msg string, fields ...any) {
+func (l Logger) Warn(ctx context.Context, msg string, fields ...Field) {
 	l.log(ctx, LevelWarn, msg, fields)
 }
 
 // Error logs the msg and fields at LevelError.
-// See Info() for information on the fields argument.
 //
 // It will then Sync().
-func (l Logger) Error(ctx context.Context, msg string, fields ...any) {
+func (l Logger) Error(ctx context.Context, msg string, fields ...Field) {
 	l.log(ctx, LevelError, msg, fields)
 	l.Sync()
 }
 
 // Critical logs the msg and fields at LevelCritical.
-// See Info() for information on the fields argument.
 //
 // It will then Sync().
-func (l Logger) Critical(ctx context.Context, msg string, fields ...any) {
+func (l Logger) Critical(ctx context.Context, msg string, fields ...Field) {
 	l.log(ctx, LevelCritical, msg, fields)
 	l.Sync()
 }
 
 // Fatal logs the msg and fields at LevelFatal.
-// See Info() for information on the fields argument.
 //
 // It will then Sync() and os.Exit(1).
-func (l Logger) Fatal(ctx context.Context, msg string, fields ...any) {
+func (l Logger) Fatal(ctx context.Context, msg string, fields ...Field) {
 	l.log(ctx, LevelFatal, msg, fields)
 	l.Sync()
 
@@ -182,32 +155,7 @@ func (l Logger) AppendSinks(s ...Sink) Logger {
 	return l
 }
 
-func (l Logger) log(ctx context.Context, level Level, msg string, rawFields []any) {
-	fields := make(Map, 0, len(rawFields))
-	var wipField Field
-	for i, f := range rawFields {
-		if wipField.Name != "" {
-			wipField.Value = f
-			fields = append(fields, wipField)
-			wipField = Field{}
-			continue
-		}
-		switch f := f.(type) {
-		case Field:
-			fields = append(fields, f)
-		case Map:
-			fields = append(fields, f...)
-		case string:
-			wipField.Name = f
-		default:
-			panic(fmt.Sprintf("unexpected field type %T at index %v (does it have a key?)", f, i))
-		}
-	}
-
-	if wipField.Name != "" {
-		panic(fmt.Sprintf("field %q has no value", wipField.Name))
-	}
-
+func (l Logger) log(ctx context.Context, level Level, msg string, fields []Field) {
 	ent := l.entry(ctx, level, msg, fields)
 	l.Log(ctx, ent)
 }

slog_test.go

@@ -2,7 +2,6 @@ package slog_test
 
 import (
 	"context"
-	"fmt"
 	"io"
 	"runtime"
 	"testing"
@@ -76,7 +75,7 @@ func TestLogger(t *testing.T) {
 
 			File: slogTestFile,
 			Func: "cdr.dev/slog_test.TestLogger.func2",
-			Line: 68,
+			Line: 67,
 
 			Fields: slog.M(
 				slog.F("ctx", 1024),
@@ -113,7 +112,7 @@ func TestLogger(t *testing.T) {
 
 			File: slogTestFile,
 			Func: "cdr.dev/slog_test.TestLogger.func3",
-			Line: 103,
+			Line: 102,
 
 			SpanContext: span.SpanContext(),
 
@@ -154,36 +153,6 @@ func TestLogger(t *testing.T) {
 		assert.Equal(t, "level", slog.LevelFatal, s.entries[5].Level)
 		assert.Equal(t, "exits", 1, exits)
 	})
-
-	t.Run("kv", func(t *testing.T) {
-		s := &fakeSink{}
-		l := slog.Make(s)
-
-		// All of these formats should be equivalent.
-		formats := [][]any{
-			{"animal", "cat", "weight", 15},
-			{slog.F("animal", "cat"), "weight", 15},
-			{slog.M(
-				slog.F("animal", "cat"),
-				slog.F("weight", 15),
-			)},
-			{slog.F("animal", "cat"), slog.F("weight", 15)},
-		}
-
-		for _, format := range formats {
-			l.Info(bg, "msg", format...)
-		}
-
-		assert.Len(t, "entries", 4, s.entries)
-
-		for i := range s.entries {
-			assert.Equal(
-				t, fmt.Sprintf("%v", i),
-				s.entries[0].Fields,
-				s.entries[i].Fields,
-			)
-		}
-	})
 }
 
 func TestLevel_String(t *testing.T) {

sloggers/slogtest/t.go

@@ -99,7 +99,12 @@ func (ts *testSink) LogEntry(_ context.Context, ent slog.SinkEntry) {
 
 	var sb bytes.Buffer
 	// The testing package logs to stdout and not stderr.
-	entryhuman.Fmt(&sb, os.Stdout, ent)
+	f := entryhuman.Formatter{
+		ErrorCallback: func(field slog.Field, err error) {
+			ts.tb.Errorf("failed to log field %q: %v", field.Name, err)
+		},
+	}
+	f.Fmt(&sb, os.Stdout, ent)
 
 	switch ent.Level {
 	case slog.LevelDebug, slog.LevelInfo, slog.LevelWarn:
@@ -146,25 +151,25 @@ func l(t testing.TB) slog.Logger {
 }
 
 // Debug logs the given msg and fields to t via t.Log at the debug level.
-func Debug(t testing.TB, msg string, fields ...any) {
+func Debug(t testing.TB, msg string, fields ...slog.Field) {
 	slog.Helper()
 	l(t).Debug(ctx, msg, fields...)
 }
 
 // Info logs the given msg and fields to t via t.Log at the info level.
-func Info(t testing.TB, msg string, fields ...any) {
+func Info(t testing.TB, msg string, fields ...slog.Field) {
 	slog.Helper()
 	l(t).Info(ctx, msg, fields...)
 }
 
 // Error logs the given msg and fields to t via t.Error at the error level.
-func Error(t testing.TB, msg string, fields ...any) {
+func Error(t testing.TB, msg string, fields ...slog.Field) {
 	slog.Helper()
 	l(t).Error(ctx, msg, fields...)
 }
 
 // Fatal logs the given msg and fields to t via t.Fatal at the fatal level.
-func Fatal(t testing.TB, msg string, fields ...any) {
+func Fatal(t testing.TB, msg string, fields ...slog.Field) {
 	slog.Helper()
 	l(t).Fatal(ctx, msg, fields...)
 }

sloggers/slogtest/t_test.go

@@ -3,6 +3,7 @@ package slogtest_test
 import (
 	"context"
 	"fmt"
+	"strings"
 	"testing"
 
 	"golang.org/x/xerrors"
@@ -175,13 +176,31 @@ func TestSkipCleanup(t *testing.T) {
 	assert.Len(t, "no cleanups", 0, tb.cleanups)
 }
 
+func TestUnmarshalable(t *testing.T) {
+	t.Parallel()
+	tb := &fakeTB{}
+	l := slogtest.Make(tb, &slogtest.Options{})
+	s := &selfRef{}
+	s.Ref = s
+	s2 := selfRef{Ref: s} // unmarshalable because it contains a cyclic ref
+	l.Info(bg, "hello", slog.F("self", s2))
+	assert.Equal(t, "errors", 1, tb.errors)
+	assert.Len(t, "len errorfs", 1, tb.errorfs)
+	assert.True(t, "errorfs", strings.Contains(tb.errorfs[0], "failed to log field \"self\":"))
+}
+
+type selfRef struct {
+	Ref *selfRef
+}
+
 var bg = context.Background()
 
 type fakeTB struct {
 	testing.TB
 
 	logs     int
 	errors   int
+	errorfs  []string
 	fatals   int
 	cleanups []func()
 }
@@ -196,6 +215,11 @@ func (tb *fakeTB) Error(v ...interface{}) {
 	tb.errors++
 }
 
+func (tb *fakeTB) Errorf(msg string, v ...interface{}) {
+	tb.errors++
+	tb.errorfs = append(tb.errorfs, fmt.Sprintf(msg, v...))
+}
+
 func (tb *fakeTB) Fatal(v ...interface{}) {
 	tb.fatals++
 	panic("")