Repository: kubernetes/klog (go)

Issue:
handle panics in error.Error
/kind feature

**Describe the solution you'd like**

When klog calls error.Error(), it should catch panics the same way it currently does for fmt.Stringer().

/assign


Pull request:
handle panics in MarshalLog, Error, String
**What this PR does / why we need it**:

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
https://github.com/go-logr/logr/pull/130.

**Which issue(s) this PR fixes** *(optional, in `fixes #<issue number>(, fixes #<issue_number>, ...)` format, will close the issue(s) when PR gets merged)*:
Fixes #284 

**Special notes for your reviewer**:

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.

**Release note**:

```release-note
handle Error calls that panic (klog) and String (klogr)
```


Patch:
diff --git a/examples/go.mod b/examples/go.mod
index d795666..9c16484 100644
--- a/examples/go.mod
+++ b/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
diff --git a/examples/go.sum b/examples/go.sum
index 5b43f39..b7fda52 100644
--- a/examples/go.sum
+++ b/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=
diff --git a/internal/serialize/keyvalues.go b/internal/serialize/keyvalues.go
index 4f58391..d897313 100644
--- a/internal/serialize/keyvalues.go
+++ b/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')
diff --git a/klogr/klogr.go b/klogr/klogr.go
index 8206c10..48cb658 100644
--- a/klogr/klogr.go
+++ b/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 patch:
diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml
index 38793a3..cebf860 100644
--- a/.github/workflows/test.yml
+++ b/.github/workflows/test.yml
@@ -4,7 +4,7 @@ jobs:
   test:
     strategy:
       matrix:
-        go-version: [1.14, 1.15, 1.16, 1.17]
+        go-versions: [1.14.x, 1.15.x, 1.16.x, 1.17.x]
         platform: [ubuntu-latest, macos-latest, windows-latest]
     runs-on: ${{ matrix.platform }}
     steps:
@@ -14,14 +14,12 @@ jobs:
         go-version: ${{ matrix.go-version }}
     - name: Checkout code
       uses: actions/checkout@v2
-    - name: Test klog
+    - name: Test
       run: |
         go get -t -v ./...
         go test -v -race ./...
-    - name: Test hack/tools
-      run: cd hack/tools && go test -v -race ./...
-    - name: Test examples
-      run: cd examples && go test -v -race ./...
+        cd hack/tools && go test -v -race ./... && cd ../..
+        cd examples && go test -v -race ./... && cd ..
   lint:
     runs-on: ubuntu-latest
     steps:
diff --git a/internal/serialize/keyvalues_test.go b/internal/serialize/keyvalues_test.go
index f7fdaba..affb887 100644
--- a/internal/serialize/keyvalues_test.go
+++ b/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>\"",
 		},
 	}
 
diff --git a/test/output.go b/test/output.go
index 0c447a8..bec1201 100644
--- a/test/output.go
+++ b/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{}
diff --git a/test/zapr.go b/test/zapr.go
index 0bd9473..20b118a 100644
--- a/test/zapr.go
+++ b/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