Repository: go-logr/logr (go)

Issue:
funcr: handle fmt.Stringer that panics on nil
I ran into this with klog in Kubernetes (see https://github.com/kubernetes/klog/issues/278). While I haven't tested it, funcr is probably also affected, at least here but potentially also elsewhere:
https://github.com/go-logr/logr/blob/99e02a994f50f904b6b201df394776cf687238a9/funcr/funcr.go#L360

The problem is that log calls might pass a nil pointer for a struct which implements `fmt.Stringer`, but then segfaults when called. Here's an example:
https://github.com/kubernetes/kubernetes/blob/a1e8a5bf39d48719dfbcf49ea09223ee04840502/pkg/kubelet/kubelet.go#L2334-L2335

I think it is reasonable to expect that a logging implementation is resilient against such problems. That means that funcr must either check for nil beforehand or deal with the panic. I'm undecided. Perhaps `fmt.Sprintf("%q", <nil stringer>)` can serve as reference.




Pull request:
funcr: Handle nil Stringer, Marshaler, error
Produce a useful error rather than panic.

Fixes #125 

Patch:
diff --git a/funcr/funcr.go b/funcr/funcr.go
index 166e245..7accdb0 100644
--- a/funcr/funcr.go
+++ b/funcr/funcr.go
@@ -351,15 +351,15 @@ func (f Formatter) prettyWithFlags(value interface{}, flags uint32, depth int) s
 	if v, ok := value.(logr.Marshaler); ok {
 		// Replace the value with what the type wants to get logged.
 		// That then gets handled below via reflection.
-		value = v.MarshalLog()
+		value = invokeMarshaler(v)
 	}
 
 	// Handle types that want to format themselves.
 	switch v := value.(type) {
 	case fmt.Stringer:
-		value = v.String()
+		value = invokeStringer(v)
 	case error:
-		value = v.Error()
+		value = invokeError(v)
 	}
 
 	// Handling the most common types without reflect is a small perf win.
@@ -597,6 +597,33 @@ func isEmpty(v reflect.Value) bool {
 	return false
 }
 
+func invokeMarshaler(m logr.Marshaler) (ret interface{}) {
+	defer func() {
+		if r := recover(); r != nil {
+			ret = fmt.Sprintf("<panic: %s>", r)
+		}
+	}()
+	return m.MarshalLog()
+}
+
+func invokeStringer(s fmt.Stringer) (ret string) {
+	defer func() {
+		if r := recover(); r != nil {
+			ret = fmt.Sprintf("<panic: %s>", r)
+		}
+	}()
+	return s.String()
+}
+
+func invokeError(e error) (ret string) {
+	defer func() {
+		if r := recover(); r != nil {
+			ret = fmt.Sprintf("<panic: %s>", r)
+		}
+	}()
+	return e.Error()
+}
+
 // Caller represents the original call site for a log line, after considering
 // logr.Logger.WithCallDepth and logr.Logger.WithCallStackHelper.  The File and
 // Line fields will always be provided, while the Func field is optional.


Test patch:
diff --git a/benchmark/benchmark_test.go b/benchmark/benchmark_test.go
index a165cf4..cd111bc 100644
--- a/benchmark/benchmark_test.go
+++ b/benchmark/benchmark_test.go
@@ -102,6 +102,45 @@ func doWithCallDepth(b *testing.B, log logr.Logger) {
 	}
 }
 
+type Tstringer struct{ s string }
+
+func (t Tstringer) String() string {
+	return t.s
+}
+
+//go:noinline
+func doStringerValue(b *testing.B, log logr.Logger) {
+	for i := 0; i < b.N; i++ {
+		log.Info("this is", "a", Tstringer{"stringer"})
+	}
+}
+
+type Terror struct{ s string }
+
+func (t Terror) Error() string {
+	return t.s
+}
+
+//go:noinline
+func doErrorValue(b *testing.B, log logr.Logger) {
+	for i := 0; i < b.N; i++ {
+		log.Info("this is", "an", Terror{"error"})
+	}
+}
+
+type Tmarshaler struct{ s string }
+
+func (t Tmarshaler) MarshalLog() interface{} {
+	return t.s
+}
+
+//go:noinline
+func doMarshalerValue(b *testing.B, log logr.Logger) {
+	for i := 0; i < b.N; i++ {
+		log.Info("this is", "a", Tmarshaler{"marshaler"})
+	}
+}
+
 func BenchmarkDiscardLogInfoOneArg(b *testing.B) {
 	var log logr.Logger = logr.Discard()
 	doInfoOneArg(b, log)
@@ -219,3 +258,18 @@ func BenchmarkFuncrWithCallDepth(b *testing.B) {
 	var log logr.Logger = funcr.New(noopKV, funcr.Options{})
 	doWithCallDepth(b, log)
 }
+
+func BenchmarkFuncrJSONLogInfoStringerValue(b *testing.B) {
+	var log logr.Logger = funcr.NewJSON(noopJSON, funcr.Options{})
+	doStringerValue(b, log)
+}
+
+func BenchmarkFuncrJSONLogInfoErrorValue(b *testing.B) {
+	var log logr.Logger = funcr.NewJSON(noopJSON, funcr.Options{})
+	doErrorValue(b, log)
+}
+
+func BenchmarkFuncrJSONLogInfoMarshalerValue(b *testing.B) {
+	var log logr.Logger = funcr.NewJSON(noopJSON, funcr.Options{})
+	doMarshalerValue(b, log)
+}
diff --git a/funcr/funcr_test.go b/funcr/funcr_test.go
index a6da5b6..8693810 100644
--- a/funcr/funcr_test.go
+++ b/funcr/funcr_test.go
@@ -52,7 +52,7 @@ func (p pointErr) MarshalText() ([]byte, error) {
 }
 
 // Logging this should result in the MarshalLog() value.
-type Tmarshaler string
+type Tmarshaler struct{ val string }
 
 func (t Tmarshaler) MarshalLog() interface{} {
 	return struct{ Inner string }{"I am a logr.Marshaler"}
@@ -66,8 +66,15 @@ func (t Tmarshaler) Error() string {
 	return "Error(): you should not see this"
 }
 
+// Logging this should result in a panic.
+type Tmarshalerpanic struct{ val string }
+
+func (t Tmarshalerpanic) MarshalLog() interface{} {
+	panic("Tmarshalerpanic")
+}
+
 // Logging this should result in the String() value.
-type Tstringer string
+type Tstringer struct{ val string }
 
 func (t Tstringer) String() string {
 	return "I am a fmt.Stringer"
@@ -77,6 +84,27 @@ func (t Tstringer) Error() string {
 	return "Error(): you should not see this"
 }
 
+// Logging this should result in a panic.
+type Tstringerpanic struct{ val string }
+
+func (t Tstringerpanic) String() string {
+	panic("Tstringerpanic")
+}
+
+// Logging this should result in the Error() value.
+type Terror struct{ val string }
+
+func (t Terror) Error() string {
+	return "I am an error"
+}
+
+// Logging this should result in a panic.
+type Terrorpanic struct{ val string }
+
+func (t Terrorpanic) Error() string {
+	panic("Terrorpanic")
+}
+
 type TjsontagsString struct {
 	String1 string `json:"string1"`           // renamed
 	String2 string `json:"-"`                 // ignored
@@ -351,16 +379,52 @@ func TestPretty(t *testing.T) {
 			},
 		},
 		{
-			val: Tmarshaler("foobar"),
+			val: Tmarshaler{"foobar"},
 			exp: `{"Inner":"I am a logr.Marshaler"}`,
 		},
 		{
-			val: Tstringer("foobar"),
+			val: &Tmarshaler{"foobar"},
+			exp: `{"Inner":"I am a logr.Marshaler"}`,
+		},
+		{
+			val: (*Tmarshaler)(nil),
+			exp: `"<panic: value method github.com/go-logr/logr/funcr.Tmarshaler.MarshalLog called using nil *Tmarshaler pointer>"`,
+		},
+		{
+			val: Tmarshalerpanic{"foobar"},
+			exp: `"<panic: Tmarshalerpanic>"`,
+		},
+		{
+			val: Tstringer{"foobar"},
+			exp: `"I am a fmt.Stringer"`,
+		},
+		{
+			val: &Tstringer{"foobar"},
 			exp: `"I am a fmt.Stringer"`,
 		},
 		{
-			val: fmt.Errorf("error"),
-			exp: `"error"`,
+			val: (*Tstringer)(nil),
+			exp: `"<panic: value method github.com/go-logr/logr/funcr.Tstringer.String called using nil *Tstringer pointer>"`,
+		},
+		{
+			val: Tstringerpanic{"foobar"},
+			exp: `"<panic: Tstringerpanic>"`,
+		},
+		{
+			val: Terror{"foobar"},
+			exp: `"I am an error"`,
+		},
+		{
+			val: &Terror{"foobar"},
+			exp: `"I am an error"`,
+		},
+		{
+			val: (*Terror)(nil),
+			exp: `"<panic: value method github.com/go-logr/logr/funcr.Terror.Error called using nil *Terror pointer>"`,
+		},
+		{
+			val: Terrorpanic{"foobar"},
+			exp: `"<panic: Terrorpanic>"`,
 		},
 		{
 			val: TjsontagsString{