From 708ae6185502efd239742ffd2e04031c6e1e5551 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Tue, 15 Feb 2022 12:57:24 +0100 Subject: [PATCH] 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 https://github.com/go-logr/logr/pull/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. --- examples/go.mod | 2 +- examples/go.sum | 2 + internal/serialize/keyvalues.go | 22 +++++++-- internal/serialize/keyvalues_test.go | 2 +- klogr/klogr.go | 2 +- test/output.go | 74 ++++++++++++++++++++++++++++ test/zapr.go | 25 ++++++++++ 7 files changed, 122 insertions(+), 7 deletions(-) diff --git a/examples/go.mod b/examples/go.mod index d7956666..9c164845 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 5b43f393..b7fda524 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 4f583912..d8973136 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("", 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("", 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/internal/serialize/keyvalues_test.go b/internal/serialize/keyvalues_test.go index f7fdaba3..affb887e 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=\"\"", }, } diff --git a/klogr/klogr.go b/klogr/klogr.go index 8206c10d..48cb6581 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: diff --git a/test/output.go b/test/output.go index 0c447a82..bec12018 100644 --- a/test/output.go +++ b/test/output.go @@ -286,6 +286,42 @@ I output.go:] "test" firstKey=1 secondKey=3 text: "test", err: errors.New("whoops"), expectedOutput: `E output.go:] "test" err="whoops" +`, + }, + "Error() for nil": { + text: "error nil", + err: (*customErrorJSON)(nil), + expectedOutput: `E output.go:] "error nil" err="" +`, + }, + "String() for nil": { + text: "stringer nil", + values: []interface{}{"stringer", (*stringer)(nil)}, + expectedOutput: `I output.go:] "stringer nil" stringer="" +`, + }, + "MarshalLog() for nil": { + text: "marshaler nil", + values: []interface{}{"obj", (*klog.ObjectRef)(nil)}, + expectedOutput: `I output.go:] "marshaler nil" obj="" +`, + }, + "Error() that panics": { + text: "error panic", + err: faultyError{}, + expectedOutput: `E output.go:] "error panic" err="" +`, + }, + "String() that panics": { + text: "stringer panic", + values: []interface{}{"stringer", faultyStringer{}}, + expectedOutput: `I output.go:] "stringer panic" stringer="" +`, + }, + "MarshalLog() that panics": { + text: "marshaler panic", + values: []interface{}{"obj", faultyMarshaler{}}, + expectedOutput: `I output.go:] "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 0bd94731..20b118aa 100644 --- a/test/zapr.go +++ b/test/zapr.go @@ -114,6 +114,31 @@ I output.go:] "odd WithValues" keyWithoutValue="(MISSING)" `: `{"caller":"test/output.go:","msg":"odd number of arguments passed as key-value pairs for logging","ignored key":"basekey2"} {"caller":"test/output.go:","msg":"odd number of arguments passed as key-value pairs for logging","basekey1":"basevar1","ignored key":"akey2"} {"caller":"test/output.go:","msg":"both odd","basekey1":"basevar1","v":0,"akey":"avalue"} +`, + + `I output.go:] "marshaler nil" obj="" +`: `{"caller":"test/output.go:","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 . + `E output.go:] "error nil" err="" +`: `{"caller":"test/output.go:","msg":"error nil","err":""} +`, + + `I output.go:] "stringer nil" stringer="" +`: `{"caller":"test/output.go:","msg":"stringer nil","v":0,"stringer":""} +`, + + `I output.go:] "stringer panic" stringer="" +`: `{"caller":"test/output.go:","msg":"stringer panic","v":0,"stringerError":"PANIC=fake String panic"} +`, + + `E output.go:] "error panic" err="" +`: `{"caller":"test/output.go:","msg":"error panic","errError":"PANIC=fake Error panic"} +`, + + `I output.go:] "marshaler panic" obj={} +`: `{"caller":"test/output.go:","msg":"marshaler panic","v":0,"objError":"PANIC=fake MarshalLog panic"} `, // klog.Info