Repository: kubernetes/klog
Pull request #325 (2022-05-10 09:14:54)

support logr.Marshaler
**What this PR does / why we need it**:

A type that implements only logr.Marshaler but not fmt.Stringer is useful for
delayed formatting. It is not required to return a struct. A plain string may
also be useful.

klog now supports such types by invoking MarshalLog once and then printing the
value as string (including multi-line support) if that is the result or with
the default "%+v".

**Special notes for your reviewer**:

See discussion in https://github.com/kubernetes/klog/pull/322#issuecomment-1112541499

**Release note**:
```release-note
klog now supports logr.Marshaler values by invoking MarshalLog once and then printing the
value as string (including multi-line support) if that is the result or with
the default "%+v". This is useful for custom types which delay expensive formatting until the
result is really needed.
```


Patch:
diff --git a/internal/serialize/keyvalues.go b/internal/serialize/keyvalues.go
index d897313..a3350f7 100644
--- a/internal/serialize/keyvalues.go
+++ b/internal/serialize/keyvalues.go
@@ -20,6 +20,8 @@ import (
 	"bytes"
 	"fmt"
 	"strconv"
+
+	"github.com/go-logr/logr"
 )
 
 // WithValues implements LogSink.WithValues. The old key/value pairs are
@@ -131,6 +133,24 @@ func KVListFormat(b *bytes.Buffer, keysAndValues ...interface{}) {
 			writeStringValue(b, true, v)
 		case error:
 			writeStringValue(b, true, ErrorToString(v))
+		case logr.Marshaler:
+			value := MarshalerToValue(v)
+			// A marshaler that returns a string is useful for
+			// delayed formatting of complex values. We treat this
+			// case like a normal string. This is useful for
+			// multi-line support.
+			//
+			// We could do this by recursively formatting a value,
+			// but that comes with the risk of infinite recursion
+			// if a marshaler returns itself. Instead we call it
+			// only once and rely on it returning the intended
+			// value directly.
+			switch value := value.(type) {
+			case string:
+				writeStringValue(b, true, value)
+			default:
+				writeStringValue(b, false, fmt.Sprintf("%+v", 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:
@@ -163,6 +183,18 @@ func StringerToString(s fmt.Stringer) (ret string) {
 	return
 }
 
+// MarshalerToValue invokes a marshaler and catches
+// panics.
+func MarshalerToValue(m logr.Marshaler) (ret interface{}) {
+	defer func() {
+		if err := recover(); err != nil {
+			ret = fmt.Sprintf("<panic: %s>", err)
+		}
+	}()
+	ret = m.MarshalLog()
+	return
+}
+
 // ErrorToString converts an error to a string,
 // handling panics if they occur.
 func ErrorToString(err error) (ret string) {
diff --git a/klog.go b/klog.go
index 072e159..8f5871a 100644
--- a/klog.go
+++ b/klog.go
@@ -41,10 +41,6 @@
 //
 //	-logtostderr=true
 //		Logs are written to standard error instead of to files.
-//              This shortcuts most of the usual output routing:
-//              -alsologtostderr, -stderrthreshold and -log_dir have no
-//              effect and output redirection at runtime with SetOutput is
-//              ignored.
 //	-alsologtostderr=false
 //		Logs are written to standard error as well as to files.
 //	-stderrthreshold=ERROR
@@ -408,19 +404,19 @@ func InitFlags(flagset *flag.FlagSet) {
 		flagset = flag.CommandLine
 	}
 
-	flagset.StringVar(&logging.logDir, "log_dir", logging.logDir, "If non-empty, write log files in this directory (no effect when -logtostderr=true)")
-	flagset.StringVar(&logging.logFile, "log_file", logging.logFile, "If non-empty, use this log file (no effect when -logtostderr=true)")
+	flagset.StringVar(&logging.logDir, "log_dir", logging.logDir, "If non-empty, write log files in this directory")
+	flagset.StringVar(&logging.logFile, "log_file", logging.logFile, "If non-empty, use this log file")
 	flagset.Uint64Var(&logging.logFileMaxSizeMB, "log_file_max_size", logging.logFileMaxSizeMB,
-		"Defines the maximum size a log file can grow to (no effect when -logtostderr=true). Unit is megabytes. "+
+		"Defines the maximum size a log file can grow to. Unit is megabytes. "+
 			"If the value is 0, the maximum file size is unlimited.")
 	flagset.BoolVar(&logging.toStderr, "logtostderr", logging.toStderr, "log to standard error instead of files")
-	flagset.BoolVar(&logging.alsoToStderr, "alsologtostderr", logging.alsoToStderr, "log to standard error as well as files (no effect when -logtostderr=true)")
+	flagset.BoolVar(&logging.alsoToStderr, "alsologtostderr", logging.alsoToStderr, "log to standard error as well as files")
 	flagset.Var(&logging.verbosity, "v", "number for the log level verbosity")
 	flagset.BoolVar(&logging.addDirHeader, "add_dir_header", logging.addDirHeader, "If true, adds the file directory to the header of the log messages")
 	flagset.BoolVar(&logging.skipHeaders, "skip_headers", logging.skipHeaders, "If true, avoid header prefixes in the log messages")
-	flagset.BoolVar(&logging.oneOutput, "one_output", logging.oneOutput, "If true, only write logs to their native severity level (vs also writing to each lower severity level; no effect when -logtostderr=true)")
-	flagset.BoolVar(&logging.skipLogHeaders, "skip_log_headers", logging.skipLogHeaders, "If true, avoid headers when opening log files (no effect when -logtostderr=true)")
-	flagset.Var(&logging.stderrThreshold, "stderrthreshold", "logs at or above this threshold go to stderr when writing to files and stderr (no effect when -logtostderr=true or -alsologtostderr=false)")
+	flagset.BoolVar(&logging.oneOutput, "one_output", logging.oneOutput, "If true, only write logs to their native severity level (vs also writing to each lower severity level)")
+	flagset.BoolVar(&logging.skipLogHeaders, "skip_log_headers", logging.skipLogHeaders, "If true, avoid headers when opening log files")
+	flagset.Var(&logging.stderrThreshold, "stderrthreshold", "logs at or above this threshold go to stderr")
 	flagset.Var(&logging.vmodule, "vmodule", "comma-separated list of pattern=N settings for file-filtered logging")
 	flagset.Var(&logging.traceLocation, "log_backtrace_at", "when logging hits line file:N, emit a stack trace")
 }


Test patch:
diff --git a/test/output.go b/test/output.go
index bec1201..d7f05b3 100644
--- a/test/output.go
+++ b/test/output.go
@@ -321,7 +321,13 @@ I output.go:<LINE>] "test" firstKey=1 secondKey=3
 		"MarshalLog() that panics": {
 			text:   "marshaler panic",
 			values: []interface{}{"obj", faultyMarshaler{}},
-			expectedOutput: `I output.go:<LINE>] "marshaler panic" obj={}
+			expectedOutput: `I output.go:<LINE>] "marshaler panic" obj="<panic: fake MarshalLog panic>"
+`,
+		},
+		"MarshalLog() that returns itself": {
+			text:   "marshaler recursion",
+			values: []interface{}{"obj", recursiveMarshaler{}},
+			expectedOutput: `I output.go:<LINE>] "marshaler recursion" obj={}
 `,
 		},
 	}
@@ -765,6 +771,15 @@ func (f faultyMarshaler) MarshalLog() interface{} {
 
 var _ logr.Marshaler = faultyMarshaler{}
 
+type recursiveMarshaler struct{}
+
+// MarshalLog returns itself, which could cause the logger to recurse infinitely.
+func (r recursiveMarshaler) MarshalLog() interface{} {
+	return r
+}
+
+var _ logr.Marshaler = recursiveMarshaler{}
+
 type faultyError struct{}
 
 // Error always panics.
diff --git a/test/zapr.go b/test/zapr.go
index 20b118a..ccf3af1 100644
--- a/test/zapr.go
+++ b/test/zapr.go
@@ -137,8 +137,12 @@ I output.go:<LINE>] "odd WithValues" keyWithoutValue="(MISSING)"
 `: `{"caller":"test/output.go:<LINE>","msg":"error panic","errError":"PANIC=fake Error panic"}
 `,
 
-		`I output.go:<LINE>] "marshaler panic" obj={}
+		`I output.go:<LINE>] "marshaler panic" obj="<panic: fake MarshalLog panic>"
 `: `{"caller":"test/output.go:<LINE>","msg":"marshaler panic","v":0,"objError":"PANIC=fake MarshalLog panic"}
+`,
+
+		`I output.go:<LINE>] "marshaler recursion" obj={}
+`: `{"caller":"test/output.go:<LINE>","msg":"marshaler recursion","v":0,"obj":{}}
 `,
 
 		// klog.Info