Merge pull request #299 from pohly/handler-panics-in-error

handle panics in MarshalLog, Error, String

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