handle panics in MarshalLog, Error, String

The previous fix only covered fmt.Stringer.String in klog, but not klogr.
error.Error and logr.Marshaler.MarshalLog have the same problem. The
replacement string now captures the error, which makes it consistent with
go-logr/logr#130.

Two different corner cases may be handled differently:
- panic for a nil object
- panic for a valid object

Only zapr v1.2.3 handles the panic in MarshalLog.

Author: pohly

examples/go.mod

@@ -4,7 +4,7 @@ go 1.13
 
 require (
 	github.com/go-logr/logr v1.2.2
-	github.com/go-logr/zapr v1.2.2
+	github.com/go-logr/zapr v1.2.3
 	github.com/golang/glog v0.0.0-20160126235308-23def4e6c14b
 	go.uber.org/zap v1.19.0
 	k8s.io/klog/v2 v2.30.0

examples/go.sum

@@ -8,6 +8,8 @@ github.com/go-logr/logr v1.2.2 h1:ahHml/yUpnlb96Rp8HCvtYVPY8ZYpxq3g7UYchIYwbs=
 github.com/go-logr/logr v1.2.2/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A=
 github.com/go-logr/zapr v1.2.2 h1:5YNlIL6oZLydaV4dOFjL8YpgXF/tPeTbnpatnu3cq6o=
 github.com/go-logr/zapr v1.2.2/go.mod h1:eIauM6P8qSvTw5o2ez6UEAfGjQKrxQTl5EoK+Qa2oG4=
+github.com/go-logr/zapr v1.2.3 h1:a9vnzlIBPQBBkeaR9IuMUfmVOrQlkoC4YfPoFkX3T7A=
+github.com/go-logr/zapr v1.2.3/go.mod h1:eIauM6P8qSvTw5o2ez6UEAfGjQKrxQTl5EoK+Qa2oG4=
 github.com/golang/glog v0.0.0-20160126235308-23def4e6c14b h1:VKtxabqXZkF25pY9ekfRL6a582T4P37/31XEstQ5p58=
 github.com/golang/glog v0.0.0-20160126235308-23def4e6c14b/go.mod h1:SBH7ygxi8pfUlaOkMMuAQtPIUF8ecWP5IEl/CR7VP2Q=
 github.com/kr/pretty v0.1.0 h1:L/CwN0zerZDmRFUapSPitk6f+Q3+0za1rQkzVuMiMFI=

internal/serialize/keyvalues.go

@@ -126,11 +126,11 @@ func KVListFormat(b *bytes.Buffer, keysAndValues ...interface{}) {
 		// (https://github.com/kubernetes/kubernetes/pull/106594#issuecomment-975526235).
 		switch v := v.(type) {
 		case fmt.Stringer:
-			writeStringValue(b, true, stringerToString(v))
+			writeStringValue(b, true, StringerToString(v))
 		case string:
 			writeStringValue(b, true, v)
 		case error:
-			writeStringValue(b, true, v.Error())
+			writeStringValue(b, true, ErrorToString(v))
 		case []byte:
 			// In https://github.com/kubernetes/klog/pull/237 it was decided
 			// to format byte slices with "%+q". The advantages of that are:
@@ -151,16 +151,30 @@ func KVListFormat(b *bytes.Buffer, keysAndValues ...interface{}) {
 	}
 }
 
-func stringerToString(s fmt.Stringer) (ret string) {
+// StringerToString converts a Stringer to a string,
+// handling panics if they occur.
+func StringerToString(s fmt.Stringer) (ret string) {
 	defer func() {
 		if err := recover(); err != nil {
-			ret = "nil"
+			ret = fmt.Sprintf("<panic: %s>", err)
 		}
 	}()
 	ret = s.String()
 	return
 }
 
+// ErrorToString converts an error to a string,
+// handling panics if they occur.
+func ErrorToString(err error) (ret string) {
+	defer func() {
+		if err := recover(); err != nil {
+			ret = fmt.Sprintf("<panic: %s>", err)
+		}
+	}()
+	ret = err.Error()
+	return
+}
+
 func writeStringValue(b *bytes.Buffer, quote bool, v string) {
 	data := []byte(v)
 	index := bytes.IndexByte(data, '\n')

internal/serialize/keyvalues_test.go

@@ -137,7 +137,7 @@ No whitespace.`,
 		},
 		{
 			keysValues: []interface{}{"point-1", point{100, 200}, "point-2", emptyPoint},
-			want:       " point-1=\"x=100, y=200\" point-2=\"nil\"",
+			want:       " point-1=\"x=100, y=200\" point-2=\"<panic: value method k8s.io/klog/v2/internal/serialize_test.point.String called using nil *point pointer>\"",
 		},
 	}
 

klogr/klogr.go

@@ -140,7 +140,7 @@ func (l klogger) Error(err error, msg string, kvList ...interface{}) {
 	msgStr := flatten("msg", msg)
 	var loggableErr interface{}
 	if err != nil {
-		loggableErr = err.Error()
+		loggableErr = serialize.ErrorToString(err)
 	}
 	switch l.format {
 	case FormatSerialize:

test/output.go

@@ -286,6 +286,42 @@ I output.go:<LINE>] "test" firstKey=1 secondKey=3
 			text: "test",
 			err:  errors.New("whoops"),
 			expectedOutput: `E output.go:<LINE>] "test" err="whoops"
+`,
+		},
+		"Error() for nil": {
+			text: "error nil",
+			err:  (*customErrorJSON)(nil),
+			expectedOutput: `E output.go:<LINE>] "error nil" err="<panic: runtime error: invalid memory address or nil pointer dereference>"
+`,
+		},
+		"String() for nil": {
+			text:   "stringer nil",
+			values: []interface{}{"stringer", (*stringer)(nil)},
+			expectedOutput: `I output.go:<LINE>] "stringer nil" stringer="<panic: runtime error: invalid memory address or nil pointer dereference>"
+`,
+		},
+		"MarshalLog() for nil": {
+			text:   "marshaler nil",
+			values: []interface{}{"obj", (*klog.ObjectRef)(nil)},
+			expectedOutput: `I output.go:<LINE>] "marshaler nil" obj="<panic: value method k8s.io/klog/v2.ObjectRef.String called using nil *ObjectRef pointer>"
+`,
+		},
+		"Error() that panics": {
+			text: "error panic",
+			err:  faultyError{},
+			expectedOutput: `E output.go:<LINE>] "error panic" err="<panic: fake Error panic>"
+`,
+		},
+		"String() that panics": {
+			text:   "stringer panic",
+			values: []interface{}{"stringer", faultyStringer{}},
+			expectedOutput: `I output.go:<LINE>] "stringer panic" stringer="<panic: fake String panic>"
+`,
+		},
+		"MarshalLog() that panics": {
+			text:   "marshaler panic",
+			values: []interface{}{"obj", faultyMarshaler{}},
+			expectedOutput: `I output.go:<LINE>] "marshaler panic" obj={}
 `,
 		},
 	}
@@ -699,3 +735,41 @@ func (e *customErrorJSON) Error() string {
 func (e *customErrorJSON) MarshalJSON() ([]byte, error) {
 	return json.Marshal(strings.ToUpper(e.s))
 }
+
+type stringer struct {
+	s string
+}
+
+// String crashes when called for nil.
+func (s *stringer) String() string {
+	return s.s
+}
+
+var _ fmt.Stringer = &stringer{}
+
+type faultyStringer struct{}
+
+// String always panics.
+func (f faultyStringer) String() string {
+	panic("fake String panic")
+}
+
+var _ fmt.Stringer = faultyStringer{}
+
+type faultyMarshaler struct{}
+
+// MarshalLog always panics.
+func (f faultyMarshaler) MarshalLog() interface{} {
+	panic("fake MarshalLog panic")
+}
+
+var _ logr.Marshaler = faultyMarshaler{}
+
+type faultyError struct{}
+
+// Error always panics.
+func (f faultyError) Error() string {
+	panic("fake Error panic")
+}
+
+var _ error = faultyError{}

test/zapr.go

@@ -114,6 +114,31 @@ I output.go:<LINE>] "odd WithValues" keyWithoutValue="(MISSING)"
 `: `{"caller":"test/output.go:<WITH-VALUES>","msg":"odd number of arguments passed as key-value pairs for logging","ignored key":"basekey2"}
 {"caller":"test/output.go:<LINE>","msg":"odd number of arguments passed as key-value pairs for logging","basekey1":"basevar1","ignored key":"akey2"}
 {"caller":"test/output.go:<LINE>","msg":"both odd","basekey1":"basevar1","v":0,"akey":"avalue"}
+`,
+
+		`I output.go:<LINE>] "marshaler nil" obj="<panic: value method k8s.io/klog/v2.ObjectRef.String called using nil *ObjectRef pointer>"
+`: `{"caller":"test/output.go:<LINE>","msg":"marshaler nil","v":0,"objError":"PANIC=value method k8s.io/klog/v2.ObjectRef.MarshalLog called using nil *ObjectRef pointer"}
+`,
+
+		// zap replaces a panic for a nil object with <nil>.
+		`E output.go:<LINE>] "error nil" err="<panic: runtime error: invalid memory address or nil pointer dereference>"
+`: `{"caller":"test/output.go:<LINE>","msg":"error nil","err":"<nil>"}
+`,
+
+		`I output.go:<LINE>] "stringer nil" stringer="<panic: runtime error: invalid memory address or nil pointer dereference>"
+`: `{"caller":"test/output.go:<LINE>","msg":"stringer nil","v":0,"stringer":"<nil>"}
+`,
+
+		`I output.go:<LINE>] "stringer panic" stringer="<panic: fake String panic>"
+`: `{"caller":"test/output.go:<LINE>","msg":"stringer panic","v":0,"stringerError":"PANIC=fake String panic"}
+`,
+
+		`E output.go:<LINE>] "error panic" err="<panic: fake Error panic>"
+`: `{"caller":"test/output.go:<LINE>","msg":"error panic","errError":"PANIC=fake Error panic"}
+`,
+
+		`I output.go:<LINE>] "marshaler panic" obj={}
+`: `{"caller":"test/output.go:<LINE>","msg":"marshaler panic","v":0,"objError":"PANIC=fake MarshalLog panic"}
 `,
 
 		// klog.Info