From d9d92da972753ad4b472740367c7670835cdeb2f Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 23 Nov 2022 12:50:48 +0100 Subject: [PATCH] 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. --- slogzapr.go | 31 ++++++++++++++++++++----------- zapr.go | 24 +++++++++++++++++++----- zapr_noslog.go | 6 +++++- zapr_noslog_test.go | 4 ++++ zapr_slog.go | 35 ++++++++++++++++++++++++++++++----- zapr_slog_test.go | 20 ++++++++++++++++++++ zapr_test.go | 7 +++++++ 7 files changed, 105 insertions(+), 22 deletions(-) diff --git a/slogzapr.go b/slogzapr.go index 84f56e4..79fb794 100644 --- a/slogzapr.go +++ b/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,7 +130,7 @@ 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 } @@ -132,7 +138,7 @@ func encodeSlog(enc zapcore.ObjectEncoder, attr slog.Attr) { // 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. @@ -140,16 +146,19 @@ func encodeSlog(enc zapcore.ObjectEncoder, attr slog.Attr) { } } -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 } diff --git a/zapr.go b/zapr.go index c8503ab..b2c8682 100644 --- a/zapr.go +++ b/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,7 +140,7 @@ 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 } @@ -144,7 +148,7 @@ func (zl *zapLogger) handleFields(lvl int, args []interface{}, additional ...zap // 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. diff --git a/zapr_noslog.go b/zapr_noslog.go index ec8517b..64ea0c5 100644 --- a/zapr_noslog.go +++ b/zapr_noslog.go @@ -24,7 +24,7 @@ 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 { @@ -32,3 +32,7 @@ func zapIt(field string, val interface{}) zap.Field { } return zap.Any(field, val) } + +func (zl *zapLogger) zapError(field string, err error) zap.Field { + return zap.NamedError(field, err) +} diff --git a/zapr_noslog_test.go b/zapr_noslog_test.go index 6fb36df..15b75d6 100644 --- a/zapr_noslog_test.go +++ b/zapr_noslog_test.go @@ -61,3 +61,7 @@ func slogValuer(value interface{}) interface{} { func logWithSlog(_ logr.Logger, _ string, _, _ []interface{}) { } + +func slogStructuredError() error { + return nil +} diff --git a/zapr_slog.go b/zapr_slog.go index f072036..c3c2322 100644 --- a/zapr_slog.go +++ b/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 + })) +} diff --git a/zapr_slog_test.go b/zapr_slog_test.go index 0663a28..4c88044 100644 --- a/zapr_slog_test.go +++ b/zapr_slog_test.go @@ -20,6 +20,7 @@ limitations under the License. package zapr_test import ( + "errors" "log/slog" "github.com/go-logr/logr" @@ -77,3 +78,22 @@ func logWithSlog(l logr.Logger, msg string, withKeysValues, keysValues []interfa } logger.Info(msg, keysValues...) } + +func slogStructuredError() error { + return structuredError{ + error: errors.New("hello world"), + Value: slog.GroupValue(slog.Int("answer", 42), slog.String("thanks", "fish")), + } +} + +type structuredError struct { + error + slog.Value +} + +var _ error = structuredError{} +var _ slog.LogValuer = structuredError{} + +func (err structuredError) LogValue() slog.Value { + return err.Value +} diff --git a/zapr_test.go b/zapr_test.go index 131638a..88aa598 100644 --- a/zapr_test.go +++ b/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) {