Repository: kubernetes/klog
Pull request #197 (2020-11-23 10:06:00)

klogr output format
**What this PR does / why we need it**:

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.

**Special notes for your reviewer**:

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 with a new `NewWithOptions` function.
`New` retains the original behavior.

**Release note**:
```release-note
klogr can be configured to let klog deal with key/value pairs by creating an instance with NewWithOptions
```

k8s-ci-robot: [APPROVALNOTIFIER] This PR is **NOT APPROVED**

This pull-request has been approved by: *<a href="https://github.com/kubernetes/klog/pull/197#" title="Author self-approved">pohly</a>*
To complete the [pull request process](https://git.k8s.io/community/contributors/guide/owners.md#the-code-review-process), please assign **piosz** after the PR has been reviewed.
You can assign the PR to them by writing `/assign @piosz` in a comment when ready.

The full list of commands accepted by this bot can be found [here](https://go.k8s.io/bot-commands?repo=kubernetes%2Fklog).

<details open>
Needs approval from an approver in each of these files:

- **[OWNERS](https://github.com/kubernetes/klog/blob/master/OWNERS)**

Approvers can indicate their approval by writing `/approve` in a comment
Approvers can cancel approval by writing `/approve cancel` in a comment
</details>
<!-- META={"approvers":["piosz"]} -->
pohly: Rebased and force-pushed to re-trigger testing. apidiff should pass, now that PR #199 is merged.
pohly: apidiff is flagging the `New` change as an API change:
```
New: changed from func() github.com/go-logr/logr.Logger to func(...Option) github.com/go-logr/logr.Logger
```

However, in practice that is backwards compatible because `New()` without parameters is still valid and has the same semantic as before.


munnerz: That isn't true if anyone is passing a reference to the New function in code anywhere - would make NewWithOptions or similar be an issue to do to avoid the apidiff errors?
pohly: > That isn't true if anyone is passing a reference to the New function in code anywhere

True, I hadn't considered that.

> would make NewWithOptions or similar be an issue to do to avoid the apidiff errors?

Yes, let's use that.
pohly: > > would make NewWithOptions or similar be an issue to do to avoid the apidiff errors?
> 
> Yes, let's use that.

Done. I used the opportunity to change the default format in `NewWithOptions`. I see a certain risk that replacing `New()` with `NewWithOptions()` will unexpectedly change the format, but the advantage of new code doing the "right thing" with the shorter `NewWithOptions()` instead of `NewWithOptions(WithFormat(FormatKlog))` IMHO is worth that risk.

dims: /assign @DirectXMan12 @serathius 
k8s-ci-robot: @pohly: PR needs rebase.

<details>

Instructions for interacting with me using PR comments are available [here](https://git.k8s.io/community/contributors/guide/pull-requests.md).  If you have questions or suggestions related to my behavior, please file an issue against the [kubernetes/test-infra](https://github.com/kubernetes/test-infra/issues/new?title=Prow%20issue:) repository.
</details>

Patch:
diff --git a/klog.go b/klog.go
index 23cced6..fe2b724 100644
--- a/klog.go
+++ b/klog.go
@@ -772,7 +772,7 @@ func (l *loggingT) printWithFileLine(s severity, logr logr.Logger, filter LogFil
 }
 
 // if loggr is specified, will call loggr.Error, otherwise output with logging module.
-func (l *loggingT) errorS(err error, loggr logr.Logger, filter LogFilter, msg string, keysAndValues ...interface{}) {
+func (l *loggingT) errorS(err error, loggr logr.Logger, filter LogFilter, depth int, msg string, keysAndValues ...interface{}) {
 	if filter != nil {
 		msg, keysAndValues = filter.FilterS(msg, keysAndValues)
 	}
@@ -780,11 +780,11 @@ func (l *loggingT) errorS(err error, loggr logr.Logger, filter LogFilter, msg st
 		loggr.Error(err, msg, keysAndValues...)
 		return
 	}
-	l.printS(err, msg, keysAndValues...)
+	l.printS(err, depth+1, msg, keysAndValues...)
 }
 
 // if loggr is specified, will call loggr.Info, otherwise output with logging module.
-func (l *loggingT) infoS(loggr logr.Logger, filter LogFilter, msg string, keysAndValues ...interface{}) {
+func (l *loggingT) infoS(loggr logr.Logger, filter LogFilter, depth int, msg string, keysAndValues ...interface{}) {
 	if filter != nil {
 		msg, keysAndValues = filter.FilterS(msg, keysAndValues)
 	}
@@ -792,12 +792,12 @@ func (l *loggingT) infoS(loggr logr.Logger, filter LogFilter, msg string, keysAn
 		loggr.Info(msg, keysAndValues...)
 		return
 	}
-	l.printS(nil, msg, keysAndValues...)
+	l.printS(nil, depth+1, msg, keysAndValues...)
 }
 
 // printS is called from infoS and errorS if loggr is not specified.
 // if err arguments is specified, will output to errorLog severity
-func (l *loggingT) printS(err error, msg string, keysAndValues ...interface{}) {
+func (l *loggingT) printS(err error, depth int, msg string, keysAndValues ...interface{}) {
 	b := &bytes.Buffer{}
 	b.WriteString(fmt.Sprintf("%q", msg))
 	if err != nil {
@@ -811,7 +811,7 @@ func (l *loggingT) printS(err error, msg string, keysAndValues ...interface{}) {
 	} else {
 		s = errorLog
 	}
-	l.printDepth(s, logging.logr, nil, 2, b)
+	l.printDepth(s, logging.logr, nil, depth+1, b)
 }
 
 const missingValue = "(MISSING)"
@@ -1359,14 +1359,20 @@ func (v Verbose) Infof(format string, args ...interface{}) {
 // See the documentation of V for usage.
 func (v Verbose) InfoS(msg string, keysAndValues ...interface{}) {
 	if v.enabled {
-		logging.infoS(v.logr, v.filter, msg, keysAndValues...)
+		logging.infoS(v.logr, v.filter, 0, msg, keysAndValues...)
 	}
 }
 
+// InfoSDepth acts as InfoS but uses depth to determine which call frame to log.
+// InfoSDepth(0, "msg") is the same as InfoS("msg").
+func InfoSDepth(depth int, msg string, keysAndValues ...interface{}) {
+	logging.infoS(logging.logr, logging.filter, depth, msg, keysAndValues...)
+}
+
 // Deprecated: Use ErrorS instead.
 func (v Verbose) Error(err error, msg string, args ...interface{}) {
 	if v.enabled {
-		logging.errorS(err, v.logr, v.filter, msg, args...)
+		logging.errorS(err, v.logr, v.filter, 0, msg, args...)
 	}
 }
 
@@ -1374,7 +1380,7 @@ func (v Verbose) Error(err error, msg string, args ...interface{}) {
 // See the documentation of V for usage.
 func (v Verbose) ErrorS(err error, msg string, keysAndValues ...interface{}) {
 	if v.enabled {
-		logging.errorS(err, v.logr, v.filter, msg, keysAndValues...)
+		logging.errorS(err, v.logr, v.filter, 0, msg, keysAndValues...)
 	}
 }
 
@@ -1411,7 +1417,7 @@ func Infof(format string, args ...interface{}) {
 // output:
 // >> I1025 00:15:15.525108       1 controller_utils.go:116] "Pod status updated" pod="kubedns" status="ready"
 func InfoS(msg string, keysAndValues ...interface{}) {
-	logging.infoS(logging.logr, logging.filter, msg, keysAndValues...)
+	logging.infoS(logging.logr, logging.filter, 0, msg, keysAndValues...)
 }
 
 // Warning logs to the WARNING and INFO logs.
@@ -1472,7 +1478,13 @@ func Errorf(format string, args ...interface{}) {
 // output:
 // >> E1025 00:15:15.525108       1 controller_utils.go:114] "Failed to update pod status" err="timeout"
 func ErrorS(err error, msg string, keysAndValues ...interface{}) {
-	logging.errorS(err, logging.logr, logging.filter, msg, keysAndValues...)
+	logging.errorS(err, logging.logr, logging.filter, 0, msg, keysAndValues...)
+}
+
+// ErrorSDepth acts as ErrorS but uses depth to determine which call frame to log.
+// ErrorSDepth(0, "msg") is the same as ErrorS("msg").
+func ErrorSDepth(depth int, err error, msg string, keysAndValues ...interface{}) {
+	logging.errorS(err, logging.logr, logging.filter, depth, msg, keysAndValues...)
 }
 
 // Fatal logs to the FATAL, ERROR, WARNING, and INFO logs,
diff --git a/klogr/README.md b/klogr/README.md
index cfa5de6..c43fa81 100644
--- a/klogr/README.md
+++ b/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.
diff --git a/klogr/klogr.go b/klogr/klogr.go
index 227d07b..a774aee 100644
--- a/klogr/klogr.go
+++ b/klogr/klogr.go
@@ -14,19 +14,57 @@ import (
 	"k8s.io/klog/v2"
 )
 
-// New returns a logr.Logger which is implemented by klog.
+// 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.
+func WithFormat(format Format) Option {
+	return func(l *klogger) {
+		l.format = format
+	}
+}
+
+// New returns a logr.Logger which serializes output itself
+// and writes it via klog.
 func New() logr.Logger {
-	return klogger{
+	return NewWithOptions(WithFormat(FormatSerialize))
+}
+
+// NewWithOptions returns a logr.Logger which serializes as determined
+// by the WithFormat option and writes via klog. The default is
+// FormatKlog.
+func NewWithOptions(options ...Option) logr.Logger {
+	l := klogger{
 		level:  0,
 		prefix: "",
 		values: nil,
+		format: FormatKlog,
+	}
+	for _, option := range options {
+		option(&l)
 	}
+	return l
 }
 
 type klogger struct {
 	level  int
 	prefix string
 	values []interface{}
+	format Format
 }
 
 func (l klogger) clone() klogger {
@@ -34,6 +72,7 @@ func (l klogger) clone() klogger {
 		level:  l.level,
 		prefix: l.prefix,
 		values: copySlice(l.values),
+		format: l.format,
 	}
 }
 
@@ -149,11 +188,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 +215,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 {


Test patch:
diff --git a/klog_test.go b/klog_test.go
index bf7a063..e45265e 100644
--- a/klog_test.go
+++ b/klog_test.go
@@ -822,7 +822,7 @@ func TestKRef(t *testing.T) {
 	}
 }
 
-// Test that InfoS works as advertised.
+// Test that InfoS and InfoSDepth work as advertised.
 func TestInfoS(t *testing.T) {
 	setFlags()
 	defer logging.swap(logging.newBuffers())
@@ -857,17 +857,23 @@ func TestInfoS(t *testing.T) {
 		},
 	}
 
-	for _, data := range testDataInfo {
-		logging.file[infoLog] = &flushBuffer{}
-		InfoS(data.msg, data.keysValues...)
-		var line int
-		n, err := fmt.Sscanf(contents(infoLog), data.format, &line)
-		if n != 1 || err != nil {
-			t.Errorf("log format error: %d elements, error %s:\n%s", n, err, contents(infoLog))
-		}
-		want := fmt.Sprintf(data.format, line)
-		if contents(infoLog) != want {
-			t.Errorf("InfoS has wrong format: \n got:\t%s\nwant:\t%s", contents(infoLog), want)
+	functions := []func(msg string, keyAndValues ...interface{}){
+		InfoS,
+		myInfoS,
+	}
+	for _, f := range functions {
+		for _, data := range testDataInfo {
+			logging.file[infoLog] = &flushBuffer{}
+			f(data.msg, data.keysValues...)
+			var line int
+			n, err := fmt.Sscanf(contents(infoLog), data.format, &line)
+			if n != 1 || err != nil {
+				t.Errorf("log format error: %d elements, error %s:\n%s", n, err, contents(infoLog))
+			}
+			want := fmt.Sprintf(data.format, line)
+			if contents(infoLog) != want {
+				t.Errorf("InfoS has wrong format: \n got:\t%s\nwant:\t%s", contents(infoLog), want)
+			}
 		}
 	}
 }
@@ -930,7 +936,7 @@ func TestVInfoS(t *testing.T) {
 	}
 }
 
-// Test that ErrorS works as advertised.
+// Test that ErrorS and ErrorSDepth work as advertised.
 func TestErrorS(t *testing.T) {
 	setFlags()
 	defer logging.swap(logging.newBuffers())
@@ -939,16 +945,24 @@ func TestErrorS(t *testing.T) {
 	}
 	logging.logFile = ""
 	pid = 1234
-	ErrorS(fmt.Errorf("update status failed"), "Failed to update pod status", "pod", "kubedns")
-	var line int
-	format := "E0102 15:04:05.067890    1234 klog_test.go:%d] \"Failed to update pod status\" err=\"update status failed\" pod=\"kubedns\"\n"
-	n, err := fmt.Sscanf(contents(errorLog), format, &line)
-	if n != 1 || err != nil {
-		t.Errorf("log format error: %d elements, error %s:\n%s", n, err, contents(errorLog))
+
+	functions := []func(err error, msg string, keyAndValues ...interface{}){
+		ErrorS,
+		myErrorS,
 	}
-	want := fmt.Sprintf(format, line)
-	if contents(errorLog) != want {
-		t.Errorf("ErrorS has wrong format: \n got:\t%s\nwant:\t%s", contents(errorLog), want)
+	for _, f := range functions {
+		logging.file[errorLog] = &flushBuffer{}
+		f(fmt.Errorf("update status failed"), "Failed to update pod status", "pod", "kubedns")
+		var line int
+		format := "E0102 15:04:05.067890    1234 klog_test.go:%d] \"Failed to update pod status\" err=\"update status failed\" pod=\"kubedns\"\n"
+		n, err := fmt.Sscanf(contents(errorLog), format, &line)
+		if n != 1 || err != nil {
+			t.Errorf("log format error: %d elements, error %s:\n%s", n, err, contents(errorLog))
+		}
+		want := fmt.Sprintf(format, line)
+		if contents(errorLog) != want {
+			t.Errorf("ErrorS has wrong format: \n got:\t%s\nwant:\t%s", contents(errorLog), want)
+		}
 	}
 }
 
diff --git a/klog_wrappers_test.go b/klog_wrappers_test.go
new file mode 100644
index 0000000..10325f5
--- /dev/null
+++ b/klog_wrappers_test.go
@@ -0,0 +1,27 @@
+// Copyright 2020 The Kubernetes Authors.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package klog
+
+// These helper functions must be in a separate source file because the
+// tests in klog_test.go compare the logged source code file name against
+// "klog_test.go". "klog_wrappers_test.go" must *not* be logged.
+
+func myInfoS(msg string, keyAndValues ...interface{}) {
+	InfoSDepth(1, msg, keyAndValues...)
+}
+
+func myErrorS(err error, msg string, keyAndValues ...interface{}) {
+	ErrorSDepth(1, err, msg, keyAndValues...)
+}
diff --git a/klogr/klogr_test.go b/klogr/klogr_test.go
index 38b4410..cb86cc3 100644
--- a/klogr/klogr_test.go
+++ b/klogr/klogr_test.go
@@ -13,86 +13,157 @@ import (
 	"github.com/go-logr/logr"
 )
 
-func TestInfo(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.Parse()
+const (
+	formatDefault = "Default"
+	formatNew     = "New"
+)
 
+func testOutput(t *testing.T, format string) {
+	new := func() logr.Logger {
+		switch format {
+		case formatNew:
+			return New()
+		case formatDefault:
+			return NewWithOptions()
+		default:
+			return NewWithOptions(WithFormat(Format(format)))
+		}
+	}
 	tests := map[string]struct {
-		klogr          logr.Logger
-		text           string
-		keysAndValues  []interface{}
-		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().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"),
+			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"),
+			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().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().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().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 in the default format and dump the logger pairs first": {
+			klogr:         new().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().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().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().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().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),
+			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"
 `,
 		},
 	}
@@ -100,25 +171,56 @@ func TestInfo(t *testing.T) {
 		t.Run(n, func(t *testing.T) {
 			klogr := test.klogr
 			if klogr == nil {
-				klogr = New()
+				klogr = new()
 			}
 
 			// hijack the klog output
 			tmpWriteBuffer := bytes.NewBuffer(nil)
 			klog.SetOutput(tmpWriteBuffer)
 
-			klogr.Info(test.text, test.keysAndValues...)
+			if test.err != nil {
+				klogr.Error(test.err, test.text, test.keysAndValues...)
+			} else {
+				klogr.Info(test.text, test.keysAndValues...)
+			}
+
 			// call Flush to ensure the text isn't still buffered
 			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) || format == formatDefault {
+				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{
+		formatNew,
+		formatDefault,
+		string(FormatSerialize),
+		string(FormatKlog),
+	}
+	for _, format := range formats {
+		t.Run(format, func(t *testing.T) {
+			testOutput(t, format)
+		})
+	}
+}
+
 type customErrorJSON struct {
 	s string
 }