klogr: add support for structured logging via klog

Now that klog has support for structured logging, it makes sense to
use that also through klogr. The log output without a structured
logger becomes more readable and key/value semantic is not lost
anymore with a structured logger.

However, revising the output handling is a breaking change for those
who depend on the traditional output. Therefore this is implemented in
a backward compatible way:
- code calling New() without parameters continues to work and
  gets the traditional behavior
- deferring the complete output handling to klog is enabled
  via a functional option

klogr/README.md

@@ -5,4 +5,15 @@ in terms of Kubernetes' [klog](https://github.com/kubernetes/klog).  This
 provides a relatively minimalist API to logging in Go, backed by a well-proven
 implementation.
 
+Because klogr was implemented before klog itself added supported for
+structured logging, the default in klogr is to serialize key/value
+pairs with JSON and log the result as text messages via klog. This
+does not work well when klog itself forwards output to a structured
+logger.
+
+Therefore the recommended approach is to let klogr pass all log
+messages through to klog and deal with structured logging there. Just
+beware that the output of klog without a structured logger is meant to
+be human-readable, in contrast to the JSON-based traditional format.
+
 This is a BETA grade implementation.

klogr/klogr.go

@@ -14,26 +14,62 @@ import (
 	"k8s.io/klog/v2"
 )
 
+// Option is a functional option that reconfigures the logger created with New.
+type Option func(*klogger)
+
+// Format defines how log output is produced.
+type Format string
+
+const (
+	// FormatSerialize tells klogr to turn key/value pairs into text itself
+	// before invoking klog.
+	FormatSerialize Format = "Serialize"
+
+	// FormatKlog tells klogr to pass all text messages and key/value pairs
+	// directly to klog. Klog itself then serializes in a human-readable
+	// format and optionally passes on to a structure logging backend.
+	FormatKlog Format = "Klog"
+)
+
+// WithFormat selects the output format. Default is FormatSerialize as in
+// previous releases of klog.
+func WithFormat(format Format) Option {
+	return func(l *klogger) {
+		l.format = format
+	}
+}
+
 // New returns a logr.Logger which is implemented by klog.
-func New() logr.Logger {
-	return klogger{
+//
+// Whether it serializes key/value pairs itself (the traditional
+// behavior, enabled by default) or lets klog do that is configurable
+// via the Format option.
+func New(options ...Option) logr.Logger {
+	l := klogger{
 		level:  0,
 		prefix: "",
 		values: nil,
+		format: FormatSerialize,
 	}
+	for _, option := range options {
+		option(&l)
+	}
+	return l
 }
 
 type klogger struct {
 	level  int
 	prefix string
 	values []interface{}
+	format Format
 }
 
 func (l klogger) clone() klogger {
 	return klogger{
 		level:  l.level,
 		prefix: l.prefix,
 		values: copySlice(l.values),
+		format: l.format,
 	}
 }
 
@@ -149,11 +185,20 @@ func pretty(value interface{}) string {
 
 func (l klogger) Info(msg string, kvList ...interface{}) {
 	if l.Enabled() {
-		msgStr := flatten("msg", msg)
-		trimmed := trimDuplicates(l.values, kvList)
-		fixedStr := flatten(trimmed[0]...)
-		userStr := flatten(trimmed[1]...)
-		klog.InfoDepth(framesToCaller(), l.prefix, " ", msgStr, " ", fixedStr, " ", userStr)
+		switch l.format {
+		case FormatSerialize:
+			msgStr := flatten("msg", msg)
+			trimmed := trimDuplicates(l.values, kvList)
+			fixedStr := flatten(trimmed[0]...)
+			userStr := flatten(trimmed[1]...)
+			klog.InfoDepth(framesToCaller(), l.prefix, " ", msgStr, " ", fixedStr, " ", userStr)
+		case FormatKlog:
+			trimmed := trimDuplicates(l.values, kvList)
+			if l.prefix != "" {
+				msg = l.prefix + ": " + msg
+			}
+			klog.InfoSDepth(framesToCaller(), msg, append(trimmed[0], trimmed[1]...)...)
+		}
 	}
 }
 
@@ -167,11 +212,20 @@ func (l klogger) Error(err error, msg string, kvList ...interface{}) {
 	if err != nil {
 		loggableErr = err.Error()
 	}
-	errStr := flatten("error", loggableErr)
-	trimmed := trimDuplicates(l.values, kvList)
-	fixedStr := flatten(trimmed[0]...)
-	userStr := flatten(trimmed[1]...)
-	klog.ErrorDepth(framesToCaller(), l.prefix, " ", msgStr, " ", errStr, " ", fixedStr, " ", userStr)
+	switch l.format {
+	case FormatSerialize:
+		errStr := flatten("error", loggableErr)
+		trimmed := trimDuplicates(l.values, kvList)
+		fixedStr := flatten(trimmed[0]...)
+		userStr := flatten(trimmed[1]...)
+		klog.ErrorDepth(framesToCaller(), l.prefix, " ", msgStr, " ", errStr, " ", fixedStr, " ", userStr)
+	case FormatKlog:
+		trimmed := trimDuplicates(l.values, kvList)
+		if l.prefix != "" {
+			msg = l.prefix + ": " + msg
+		}
+		klog.ErrorSDepth(framesToCaller(), err, msg, append(trimmed[0], trimmed[1]...)...)
+	}
 }
 
 func (l klogger) V(level int) logr.Logger {

klogr/klogr_test.go

@@ -13,127 +13,158 @@ import (
 	"github.com/go-logr/logr"
 )
 
-func TestOutput(t *testing.T) {
-	klog.InitFlags(nil)
-	flag.CommandLine.Set("v", "10")
-	flag.CommandLine.Set("skip_headers", "true")
-	flag.CommandLine.Set("logtostderr", "false")
-	flag.CommandLine.Set("alsologtostderr", "false")
-	flag.CommandLine.Set("stderrthreshold", "10")
-	flag.Parse()
+const (
+	formatDefault = "Default"
+)
 
+func testOutput(t *testing.T, format string) {
+	var options []Option
+	if format != formatDefault {
+		options = append(options, WithFormat(Format(format)))
+	}
 	tests := map[string]struct {
-		klogr          logr.Logger
-		text           string
-		keysAndValues  []interface{}
-		err            error
-		expectedOutput string
+		klogr              logr.Logger
+		text               string
+		keysAndValues      []interface{}
+		err                error
+		expectedOutput     string
+		expectedKlogOutput string
 	}{
 		"should log with values passed to keysAndValues": {
-			klogr:         New().V(0),
+			klogr:         New(options...).V(0),
 			text:          "test",
 			keysAndValues: []interface{}{"akey", "avalue"},
 			expectedOutput: ` "msg"="test"  "akey"="avalue"
+`,
+			expectedKlogOutput: `"test" akey="avalue"
 `,
 		},
 		"should log with name and values passed to keysAndValues": {
-			klogr:         New().V(0).WithName("me"),
+			klogr:         New(options...).V(0).WithName("me"),
 			text:          "test",
 			keysAndValues: []interface{}{"akey", "avalue"},
 			expectedOutput: `me "msg"="test"  "akey"="avalue"
+`,
+			expectedKlogOutput: `"me: test" akey="avalue"
 `,
 		},
 		"should log with multiple names and values passed to keysAndValues": {
-			klogr:         New().V(0).WithName("hello").WithName("world"),
+			klogr:         New(options...).V(0).WithName("hello").WithName("world"),
 			text:          "test",
 			keysAndValues: []interface{}{"akey", "avalue"},
 			expectedOutput: `hello/world "msg"="test"  "akey"="avalue"
+`,
+			expectedKlogOutput: `"hello/world: test" akey="avalue"
 `,
 		},
 		"should not print duplicate keys with the same value": {
-			klogr:         New().V(0),
+			klogr:         New(options...).V(0),
 			text:          "test",
 			keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue"},
 			expectedOutput: ` "msg"="test"  "akey"="avalue"
+`,
+			expectedKlogOutput: `"test" akey="avalue"
 `,
 		},
 		"should only print the last duplicate key when the values are passed to Info": {
-			klogr:         New().V(0),
+			klogr:         New(options...).V(0),
 			text:          "test",
 			keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue2"},
 			expectedOutput: ` "msg"="test"  "akey"="avalue2"
+`,
+			expectedKlogOutput: `"test" akey="avalue2"
 `,
 		},
 		"should only print the duplicate key that is passed to Info if one was passed to the logger": {
-			klogr:         New().WithValues("akey", "avalue"),
+			klogr:         New(options...).WithValues("akey", "avalue"),
 			text:          "test",
 			keysAndValues: []interface{}{"akey", "avalue"},
 			expectedOutput: ` "msg"="test"  "akey"="avalue"
+`,
+			expectedKlogOutput: `"test" akey="avalue"
 `,
 		},
-		"should sort within logger and parameter key/value pairs and dump the logger pairs first": {
-			klogr:         New().WithValues("akey9", "avalue9", "akey8", "avalue8", "akey1", "avalue1"),
+		"should sort within logger and parameter key/value pairs in the default format and dump the logger pairs first": {
+			klogr:         New(options...).WithValues("akey9", "avalue9", "akey8", "avalue8", "akey1", "avalue1"),
 			text:          "test",
 			keysAndValues: []interface{}{"akey5", "avalue5", "akey4", "avalue4"},
 			expectedOutput: ` "msg"="test" "akey1"="avalue1" "akey8"="avalue8" "akey9"="avalue9" "akey4"="avalue4" "akey5"="avalue5"
+`,
+			expectedKlogOutput: `"test" akey9="avalue9" akey8="avalue8" akey1="avalue1" akey5="avalue5" akey4="avalue4"
 `,
 		},
 		"should only print the key passed to Info when one is already set on the logger": {
-			klogr:         New().WithValues("akey", "avalue"),
+			klogr:         New(options...).WithValues("akey", "avalue"),
 			text:          "test",
 			keysAndValues: []interface{}{"akey", "avalue2"},
 			expectedOutput: ` "msg"="test"  "akey"="avalue2"
+`,
+			expectedKlogOutput: `"test" akey="avalue2"
 `,
 		},
 		"should correctly handle odd-numbers of KVs": {
 			text:          "test",
 			keysAndValues: []interface{}{"akey", "avalue", "akey2"},
 			expectedOutput: ` "msg"="test"  "akey"="avalue" "akey2"=null
+`,
+			expectedKlogOutput: `"test" akey="avalue" akey2=<nil>
 `,
 		},
 		"should correctly html characters": {
 			text:          "test",
 			keysAndValues: []interface{}{"akey", "<&>"},
 			expectedOutput: ` "msg"="test"  "akey"="<&>"
+`,
+			expectedKlogOutput: `"test" akey="<&>"
 `,
 		},
 		"should correctly handle odd-numbers of KVs in both log values and Info args": {
-			klogr:         New().WithValues("basekey1", "basevar1", "basekey2"),
+			klogr:         New(options...).WithValues("basekey1", "basevar1", "basekey2"),
 			text:          "test",
 			keysAndValues: []interface{}{"akey", "avalue", "akey2"},
 			expectedOutput: ` "msg"="test" "basekey1"="basevar1" "basekey2"=null "akey"="avalue" "akey2"=null
+`,
+			expectedKlogOutput: `"test" basekey1="basevar1" basekey2=<nil> akey="avalue" akey2=<nil>
 `,
 		},
 		"should correctly print regular error types": {
-			klogr:         New().V(0),
+			klogr:         New(options...).V(0),
 			text:          "test",
 			keysAndValues: []interface{}{"err", errors.New("whoops")},
 			expectedOutput: ` "msg"="test"  "err"="whoops"
+`,
+			expectedKlogOutput: `"test" err="whoops"
 `,
 		},
-		"should use MarshalJSON if an error type implements it": {
-			klogr:         New().V(0),
+		"should use MarshalJSON in the default format if an error type implements it": {
+			klogr:         New(options...).V(0),
 			text:          "test",
 			keysAndValues: []interface{}{"err", &customErrorJSON{"whoops"}},
 			expectedOutput: ` "msg"="test"  "err"="WHOOPS"
+`,
+			expectedKlogOutput: `"test" err="whoops"
 `,
 		},
 		"should correctly print regular error types when using logr.Error": {
-			klogr: New().V(0),
+			klogr: New(options...).V(0),
 			text:  "test",
 			err:   errors.New("whoops"),
 			// The message is printed to three different log files (info, warning, error), so we see it three times in our output buffer.
 			expectedOutput: ` "msg"="test" "error"="whoops"  
  "msg"="test" "error"="whoops"  
  "msg"="test" "error"="whoops"  
+`,
+			expectedKlogOutput: `"test" err="whoops"
+"test" err="whoops"
+"test" err="whoops"
 `,
 		},
 	}
 	for n, test := range tests {
 		t.Run(n, func(t *testing.T) {
 			klogr := test.klogr
 			if klogr == nil {
-				klogr = New()
+				klogr = New(options...)
 			}
 
 			// hijack the klog output
@@ -150,13 +181,38 @@ func TestOutput(t *testing.T) {
 			klog.Flush()
 
 			actual := tmpWriteBuffer.String()
-			if actual != test.expectedOutput {
-				t.Errorf("expected %q did not match actual %q", test.expectedOutput, actual)
+			expectedOutput := test.expectedOutput
+			if format == string(FormatKlog) {
+				expectedOutput = test.expectedKlogOutput
+			}
+			if actual != expectedOutput {
+				t.Errorf("expected %q did not match actual %q", expectedOutput, actual)
 			}
 		})
 	}
 }
 
+func TestOutput(t *testing.T) {
+	klog.InitFlags(nil)
+	flag.CommandLine.Set("v", "10")
+	flag.CommandLine.Set("skip_headers", "true")
+	flag.CommandLine.Set("logtostderr", "false")
+	flag.CommandLine.Set("alsologtostderr", "false")
+	flag.CommandLine.Set("stderrthreshold", "10")
+	flag.Parse()
+
+	formats := []string{
+		formatDefault,
+		string(FormatSerialize),
+		string(FormatKlog),
+	}
+	for _, format := range formats {
+		t.Run(format, func(t *testing.T) {
+			testOutput(t, format)
+		})
+	}
+}
+
 type customErrorJSON struct {
 	s string
 }