handle panics in logr.Marshaler.MarshalLog

The function might panic. The conclusion in
go-logr/logr#130 was that the logger should
record that.

zapr only needs to do that when it calls MarshalLog. Strings and errors are
handled by zap.

For the sake of simplicity no attempt is made to detect the reason for the
panic. In case of a panic, the key is replaced by "<key>Error" and the value
with "PANIC=<panic reason>". This is consistent with how zap handles panics.

Author: pohly

zapr.go

@@ -54,6 +54,8 @@ limitations under the License.
 package zapr
 
 import (
+	"fmt"
+
 	"github.com/go-logr/logr"
 	"go.uber.org/zap"
 	"go.uber.org/zap/zapcore"
@@ -170,11 +172,21 @@ func 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 {
-		val = marshaler.MarshalLog()
+		field, val = invokeMarshaler(field, marshaler)
 	}
 	return zap.Any(field, val)
 }
 
+func invokeMarshaler(field string, m logr.Marshaler) (f string, ret interface{}) {
+	defer func() {
+		if r := recover(); r != nil {
+			ret = fmt.Sprintf("PANIC=%s", r)
+			f = field + "Error"
+		}
+	}()
+	return field, m.MarshalLog()
+}
+
 func (zl *zapLogger) Init(ri logr.RuntimeInfo) {
 	zl.l = zl.l.WithOptions(zap.AddCallerSkip(ri.CallDepth))
 }

zapr_test.go

@@ -47,6 +47,40 @@ type discard struct{}
 
 func (d discard) Write(p []byte) (n int, err error) { return n, nil }
 
+type marshaler struct {
+	msg string
+}
+
+func (m *marshaler) String() string {
+	return m.msg
+}
+
+func (m *marshaler) MarshalLog() interface{} {
+	return "msg=" + m.msg
+}
+
+var _ fmt.Stringer = &marshaler{}
+var _ logr.Marshaler = &marshaler{}
+
+type stringer struct {
+	msg string
+}
+
+func (s *stringer) String() string {
+	return s.msg
+}
+
+var _ fmt.Stringer = &stringer{}
+
+type stringerPanic struct {
+}
+
+func (s *stringerPanic) String() string {
+	panic("fake panic")
+}
+
+var _ fmt.Stringer = &stringerPanic{}
+
 func newZapLogger(lvl zapcore.Level, w zapcore.WriteSyncer) *zap.Logger {
 	if w == nil {
 		w = zapcore.AddSync(discard{})
@@ -164,6 +198,33 @@ func TestInfo(t *testing.T) {
 `,
 			keysValues: []interface{}{"duration", time.Duration(5 * time.Second)},
 		},
+		{
+			msg: "valid marshaler",
+			format: `{"ts":%f,"caller":"zapr/zapr_test.go:%d","msg":"valid marshaler","v":0,"obj":"msg=hello"}
+`,
+			keysValues: []interface{}{"obj", &marshaler{msg: "hello"}},
+		},
+		{
+			msg: "nil marshaler",
+			// Handled by our code: it just formats the error.
+			format: `{"ts":%f,"caller":"zapr/zapr_test.go:%d","msg":"nil marshaler","v":0,"objError":"PANIC=runtime error: invalid memory address or nil pointer dereference"}
+`,
+			keysValues: []interface{}{"obj", (*marshaler)(nil)},
+		},
+		{
+			msg: "nil stringer",
+			// Handled by zap: it detects a nil pointer.
+			format: `{"ts":%f,"caller":"zapr/zapr_test.go:%d","msg":"nil stringer","v":0,"obj":"<nil>"}
+`,
+			keysValues: []interface{}{"obj", (*stringer)(nil)},
+		},
+		{
+			msg: "panic stringer",
+			// Handled by zap: it prints the panic, but using a different key and format than funcr.
+			format: `{"ts":%f,"caller":"zapr/zapr_test.go:%d","msg":"panic stringer","v":0,"objError":"PANIC=fake panic"}
+`,
+			keysValues: []interface{}{"obj", &stringerPanic{}},
+		},
 	}
 
 	test := func(t *testing.T, logNumeric *string, enablePanics *bool, allowZapFields *bool, data testCase) {