support "structured error"

A "structured error" is an error which implements error and slog.LogValuer.
When encountering such an error, it gets logged normally and then another field
gets added with the result of LogValue().

The name of the extra field is the original field name plus a configurable
suffix, with "Details" as default.

The extra details are logged as if they had been passed as a value to
zapr. slog.Value.Resolve is used to protect against errors and recursion while
calling LogValue, but does not protect against recursion that can occur when
LogValue returns the original error: then zapIt->zapError->zapIt->... repeats
until the program gets killed.

A simple guard against this (not expanding error again while formatting an
error) is too simplistic and would prevent nice rendering of a wrapped error
that might get returned by MarshalLog. zapIt would have to track the exact
error instance and detect when it gets the same value again.

Author: pohly

README.md

@@ -105,3 +105,11 @@ The zapr `logr.LogSink` implementation also implements `logr.SlogHandler`. That
 enables `slogr.NewSlogHandler` to provide a `slog.Handler` which just passes
 parameters through to zapr. zapr handles special slog values (Group,
 LogValuer), regardless of which front-end API is used.
+
+The value logged for errors is the string returned by `error.Error`.
+If the error also implements `slog.LogValuer`, then it is treated as a
+"structured error" and the value returned by `slog.LogValuer.LogValue` is
+logged *in addition* to the error string, using a key that is the original
+key plus a "Details" suffix. For example, `"err", err` will be logged as if
+`"err", err.Error(), "errDetails", err.LogValue()` has been passed. This
+ensures that the "err" key is always associated with a string.

slogzapr.go

@@ -60,7 +60,7 @@ func (zl *zapLogger) Handle(_ context.Context, record slog.Record) error {
 		// Inline all attributes.
 		fields = append(fields, zap.Inline(zapcore.ObjectMarshalerFunc(func(enc zapcore.ObjectEncoder) error {
 			record.Attrs(func(attr slog.Attr) bool {
-				encodeSlog(enc, attr)
+				zl.encodeSlog(enc, attr)
 				return true
 			})
 			return nil
@@ -70,7 +70,7 @@ func (zl *zapLogger) Handle(_ context.Context, record slog.Record) error {
 	return nil
 }
 
-func encodeSlog(enc zapcore.ObjectEncoder, attr slog.Attr) {
+func (zl *zapLogger) encodeSlog(enc zapcore.ObjectEncoder, attr slog.Attr) {
 	if attr.Equal(slog.Attr{}) {
 		// Ignore empty attribute.
 		return
@@ -102,8 +102,14 @@ func encodeSlog(enc zapcore.ObjectEncoder, attr slog.Attr) {
 	case slog.KindString:
 		enc.AddString(attr.Key, attr.Value.String())
 	case slog.KindLogValuer:
+		// Structured error?
+		if err, ok := attr.Value.Any().(error); ok {
+			zl.zapError(attr.Key, err).AddTo(enc)
+			return
+		}
+
 		// This includes klog.KObj.
-		encodeSlog(enc, slog.Attr{
+		zl.encodeSlog(enc, slog.Attr{
 			Key:   attr.Key,
 			Value: attr.Value.Resolve(),
 		})
@@ -124,32 +130,35 @@ func encodeSlog(enc zapcore.ObjectEncoder, attr slog.Attr) {
 		if attr.Key == "" {
 			// Inline group.
 			for _, attr := range attrs {
-				encodeSlog(enc, attr)
+				zl.encodeSlog(enc, attr)
 			}
 			return
 		}
 		if len(attrs) == 0 {
 			// Ignore empty group.
 			return
 		}
-		_ = enc.AddObject(attr.Key, marshalAttrs(attrs))
+		_ = enc.AddObject(attr.Key, marshalAttrs{zl: zl, attrs: attrs})
 	default:
 		// We have to go through reflection in zap.Any to get support
 		// for e.g. fmt.Stringer.
 		zap.Any(attr.Key, attr.Value.Any()).AddTo(enc)
 	}
 }
 
-type marshalAttrs []slog.Attr
+type marshalAttrs struct {
+	zl    *zapLogger
+	attrs []slog.Attr
+}
 
-func (attrs marshalAttrs) MarshalLogObject(enc zapcore.ObjectEncoder) error {
-	for _, attr := range attrs {
-		encodeSlog(enc, attr)
+func (m marshalAttrs) MarshalLogObject(enc zapcore.ObjectEncoder) error {
+	for _, attr := range m.attrs {
+		m.zl.encodeSlog(enc, attr)
 	}
 	return nil
 }
 
-var _ zapcore.ObjectMarshaler = marshalAttrs(nil)
+var _ zapcore.ObjectMarshaler = marshalAttrs{}
 
 func pcToCallerEntry(pc uintptr) zapcore.EntryCaller {
 	if pc == 0 {
@@ -172,7 +181,7 @@ func pcToCallerEntry(pc uintptr) zapcore.EntryCaller {
 
 func (zl *zapLogger) WithAttrs(attrs []slog.Attr) slogr.SlogSink {
 	newLogger := *zl
-	newLogger.l = newLogger.l.With(zap.Inline(marshalAttrs(attrs)))
+	newLogger.l = newLogger.l.With(zap.Inline(marshalAttrs{zl: zl, attrs: attrs}))
 	return &newLogger
 }
 

zapr.go

@@ -81,6 +81,10 @@ type zapLogger struct {
 	// Logger.Error calls.
 	errorKey string
 
+	// errorKeyDetailsSuffix gets appended to the field name
+	// when logging additional details obtained via MarshalLog.
+	errorKeyDetailsSuffix string
+
 	// allowZapFields enables logging of strongly-typed Zap
 	// fields. It is off by default because it breaks
 	// implementation agnosticism.
@@ -136,15 +140,15 @@ func (zl *zapLogger) handleFields(lvl int, args []interface{}, additional ...zap
 				continue
 			}
 			if zl.panicMessages {
-				zl.l.WithOptions(zap.AddCallerSkip(1)).DPanic("strongly-typed Zap Field passed to logr", zapIt("zap field", args[i]))
+				zl.l.WithOptions(zap.AddCallerSkip(1)).DPanic("strongly-typed Zap Field passed to logr", zl.zapIt("zap field", args[i]))
 			}
 			break
 		}
 
 		// make sure this isn't a mismatched key
 		if i == len(args)-1 {
 			if zl.panicMessages {
-				zl.l.WithOptions(zap.AddCallerSkip(1)).DPanic("odd number of arguments passed as key-value pairs for logging", zapIt("ignored key", args[i]))
+				zl.l.WithOptions(zap.AddCallerSkip(1)).DPanic("odd number of arguments passed as key-value pairs for logging", zl.zapIt("ignored key", args[i]))
 			}
 			break
 		}
@@ -156,12 +160,12 @@ func (zl *zapLogger) handleFields(lvl int, args []interface{}, additional ...zap
 		if !isString {
 			// if the key isn't a string, DPanic and stop logging
 			if zl.panicMessages {
-				zl.l.WithOptions(zap.AddCallerSkip(1)).DPanic("non-string key argument passed to logging, ignoring all later arguments", zapIt("invalid key", key))
+				zl.l.WithOptions(zap.AddCallerSkip(1)).DPanic("non-string key argument passed to logging, ignoring all later arguments", zl.zapIt("invalid key", key))
 			}
 			break
 		}
 
-		fields = append(fields, zapIt(keyStr, val))
+		fields = append(fields, zl.zapIt(keyStr, val))
 		i += 2
 	}
 
@@ -204,7 +208,7 @@ func (zl *zapLogger) Info(lvl int, msg string, keysAndVals ...interface{}) {
 
 func (zl *zapLogger) Error(err error, msg string, keysAndVals ...interface{}) {
 	if checkedEntry := zl.l.Check(zap.ErrorLevel, msg); checkedEntry != nil {
-		checkedEntry.Write(zl.handleFields(noLevel, keysAndVals, zap.NamedError(zl.errorKey, err))...)
+		checkedEntry.Write(zl.handleFields(noLevel, keysAndVals, zl.zapError(zl.errorKey, err))...)
 	}
 }
 
@@ -252,6 +256,7 @@ func NewLoggerWithOptions(l *zap.Logger, opts ...Option) logr.Logger {
 		l: log,
 	}
 	zl.errorKey = "error"
+	zl.errorKeyDetailsSuffix = "Details"
 	zl.panicMessages = true
 	for _, option := range opts {
 		option(zl)
@@ -281,6 +286,15 @@ func ErrorKey(key string) Option {
 	}
 }
 
+// ErrorKeyDetailsSuffix replaces the default "Details" suffix that gets
+// appended to the field name for an error when logging the error details
+// obtained through MarshalLog.
+func ErrorKeyDetailsSuffix(key string) Option {
+	return func(zl *zapLogger) {
+		zl.errorKeyDetailsSuffix = key
+	}
+}
+
 // AllowZapFields controls whether strongly-typed Zap fields may
 // be passed instead of a key/value pair. This is disabled by
 // default because it breaks implementation agnosticism.

zapr_noslog.go

@@ -24,11 +24,15 @@ import (
 	"go.uber.org/zap"
 )
 
-func zapIt(field string, val interface{}) zap.Field {
+func (zl *zapLogger) zapIt(field string, val interface{}) zap.Field {
 	// Handle types that implement logr.Marshaler: log the replacement
 	// object instead of the original one.
 	if marshaler, ok := val.(logr.Marshaler); ok {
 		field, val = invokeMarshaler(field, marshaler)
 	}
 	return zap.Any(field, val)
 }
+
+func (zl *zapLogger) zapError(field string, err error) zap.Field {
+	return zap.NamedError(field, err)
+}

zapr_noslog_test.go

@@ -61,3 +61,7 @@ func slogValuer(value interface{}) interface{} {
 
 func logWithSlog(_ logr.Logger, _ string, _, _ []interface{}) {
 }
+
+func slogStructuredError() error {
+	return nil
+}

zapr_slog.go

@@ -27,8 +27,10 @@ import (
 	"go.uber.org/zap/zapcore"
 )
 
-func zapIt(field string, val interface{}) zap.Field {
+func (zl *zapLogger) zapIt(field string, val interface{}) zap.Field {
 	switch valTyped := val.(type) {
+	case error:
+		return zl.zapError(field, valTyped)
 	case logr.Marshaler:
 		// Handle types that implement logr.Marshaler: log the replacement
 		// object instead of the original one.
@@ -39,10 +41,33 @@ func zapIt(field string, val interface{}) zap.Field {
 		val = slog.AnyValue(val).Resolve()
 	}
 	if slogValue, ok := val.(slog.Value); ok {
-		return zap.Inline(zapcore.ObjectMarshalerFunc(func(enc zapcore.ObjectEncoder) error {
-			encodeSlog(enc, slog.Attr{Key: field, Value: slogValue})
-			return nil
-		}))
+		return zl.zapInline(field, slogValue)
 	}
 	return zap.Any(field, val)
 }
+
+func (zl *zapLogger) zapError(field string, err error) zap.Field {
+	if err == nil {
+		return zap.Skip()
+	}
+	return zap.Inline(zapcore.ObjectMarshalerFunc(func(encoder zapcore.ObjectEncoder) error {
+		// Always log as a normal error first.
+		zap.NamedError(field, err).AddTo(encoder)
+
+		// Extra details are optional, but might be available if the error also
+		// implements slog.LogValuer.
+		if valuer, ok := err.(slog.LogValuer); ok {
+			value := slog.AnyValue(valuer)
+			value = value.Resolve()
+			zl.zapInline(field+zl.errorKeyDetailsSuffix, value).AddTo(encoder)
+		}
+		return nil
+	}))
+}
+
+func (zl *zapLogger) zapInline(key string, value slog.Value) zap.Field {
+	return zap.Inline(zapcore.ObjectMarshalerFunc(func(enc zapcore.ObjectEncoder) error {
+		zl.encodeSlog(enc, slog.Attr{Key: key, Value: value})
+		return nil
+	}))
+}

zapr_slog_test.go

@@ -77,3 +77,21 @@ func logWithSlog(l logr.Logger, msg string, withKeysValues, keysValues []interfa
 	}
 	logger.Info(msg, keysValues...)
 }
+
+func slogStructuredError() error {
+	return structuredError{}
+}
+
+type structuredError struct {
+}
+
+var _ error = structuredError{}
+var _ slog.LogValuer = structuredError{}
+
+func (err structuredError) Error() string {
+	return "hello world"
+}
+
+func (err structuredError) LogValue() slog.Value {
+	return slog.GroupValue(slog.Int("answer", 42), slog.String("thanks", "fish"))
+}

zapr_test.go

@@ -270,6 +270,13 @@ func TestInfo(t *testing.T) {
 			keysValues: []interface{}{slogGroup("obj", slogInt("int", 1), slogString("string", "hello"))},
 			needSlog:   true,
 		},
+		{
+			msg: "structured error",
+			formatSlog: `{"ts":%f,"caller":"zapr/zapr_test.go:%d","msg":"structured error","v":0,"myerr":"hello world","myerrDetails":{"answer":42,"thanks":"fish"}}
+`,
+			keysValues: []interface{}{"myerr", slogStructuredError()},
+			needSlog:   true,
+		},
 	}
 
 	test := func(t *testing.T, logNumeric *string, enablePanics *bool, allowZapFields *bool, useSlog bool, data testCase) {