Repository: kubernetes/klog (go)

Issue:
klog always logs verbosity 0 with component-base/logs
/kind bug

**What steps did you take and what happened:**

I'm currently trying to use `component-base/logs` in combination with controller-runtime in ClusterAPI (https://github.com/kubernetes-sigs/cluster-api/pull/6072).
When using `--logging-format=json` the log lines contain `v: 0` independent of the log level with which the line is actually logged.


**What did you expect to happen:**
Should log the verbosity with which the log line is logged.


**Anything else you would like to add:**
When component-base/logs the "log hierarchy" is roughly go-logr.Logger => klog => JSON logger (component-base/logs) => zap:
![image](https://user-images.githubusercontent.com/4662360/153864210-48b29f86-a5eb-4bc1-b17a-f5020890821f.png)


I think the log level get's lost here: https://github.com/kubernetes/klog/blob/main/klogr/klogr.go#L169-L173

**To reproduce**:
I've created a minimal controller here: https://github.com/sbueringer/cr-klog-issue (with k8s.io/component-base v0.23.3 and	k8s.io/klog/v2 v2.40.1)
The issue can be reproduced by running the controller against an arbitrary cluster (with Pods) via:
```
$  go run main.go --logging-format=json --v=4
...
{"ts":1644841271031.652,"caller":"cr-klog-issue/main.go:92","msg":"controller/pod: Verbosity 0","v":0,"reconciler group":"","reconciler kind":"Pod","name":"capi-kubeadm-control-plane-controller-manager-9769796f6-l8nf2","namespace":"capi-kubeadm-control-plane-system"}
{"ts":1644841271031.67,"caller":"cr-klog-issue/main.go:93","msg":"controller/pod: Verbosity 1","v":0,"reconciler group":"","reconciler kind":"Pod","name":"capi-kubeadm-control-plane-controller-manager-9769796f6-l8nf2","namespace":"capi-kubeadm-control-plane-system"}
{"ts":1644841271031.679,"caller":"cr-klog-issue/main.go:94","msg":"controller/pod: Verbosity 2","v":0,"reconciler group":"","reconciler kind":"Pod","name":"capi-kubeadm-control-plane-controller-manager-9769796f6-l8nf2","namespace":"capi-kubeadm-control-plane-system"}
{"ts":1644841271031.6858,"caller":"cr-klog-issue/main.go:95","msg":"controller/pod: Verbosity 3","v":0,"reconciler group":"","reconciler kind":"Pod","name":"capi-kubeadm-control-plane-controller-manager-9769796f6-l8nf2","namespace":"capi-kubeadm-control-plane-system"}
{"ts":1644841271031.693,"caller":"cr-klog-issue/main.go:96","msg":"controller/pod: Verbosity 4","v":0,"reconciler group":"","reconciler kind":"Pod","name":"capi-kubeadm-control-plane-controller-manager-9769796f6-l8nf2","namespace":"capi-kubeadm-control-plane-system"}
```



xref: Slack thread: https://kubernetes.slack.com/archives/CG3518SFJ/p1644596428193789



Pull request:
klogr verbosity
**What this PR does / why we need it**:

klogr must pass through the verbosity level in case that the underlying backend logger cares about it.

**Which issue(s) this PR fixes** *(optional, in `fixes #<issue number>(, fixes #<issue_number>, ...)` format, will close the issue(s) when PR gets merged)*:
Fixes #294 

**Special notes for your reviewer**:

The first commit enhances the output test so that it shows the bug. zapr is needed for that and the test also gets enhanced to support output mapping better.

The second commit then has the actual bug fix and shows that the test now works without a workaround.

**Release note**:
```release-note
klogr did not pass the verbosity through to klog, which caused loggers such as zapr to just record v=0.
```


Patch:
diff --git a/examples/go.mod b/examples/go.mod
index 2768f2c..d795666 100644
--- a/examples/go.mod
+++ b/examples/go.mod
@@ -3,7 +3,10 @@ module example
 go 1.13
 
 require (
+	github.com/go-logr/logr v1.2.2
+	github.com/go-logr/zapr v1.2.2
 	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 4d41cc9..5b43f39 100644
--- a/examples/go.sum
+++ b/examples/go.sum
@@ -1,8 +1,56 @@
-github.com/go-logr/logr v0.1.0 h1:M1Tv3VzNlEHg6uyACnRdtrploV2P7wZqH8BoQMtz0cg=
-github.com/go-logr/logr v0.1.0/go.mod h1:ixOQHD9gLJUVQQ2ZOR7zLEifBX6tGkNJF4QyIY7sIas=
-github.com/go-logr/logr v1.2.0 h1:QK40JKJyMdUDz+h+xvCsru/bJhvG0UxvePV0ufL/AcE=
+github.com/benbjohnson/clock v1.1.0 h1:Q92kusRqC1XV2MjkWETPvjJVqKetz1OzxZB7mHJLju8=
+github.com/benbjohnson/clock v1.1.0/go.mod h1:J11/hYXuz8f4ySSvYwY0FKfm+ezbsZBKZxNJlLklBHA=
+github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
+github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c=
+github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/go-logr/logr v1.2.0/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A=
+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/golang/glog v0.0.0-20160126235308-23def4e6c14b h1:VKtxabqXZkF25pY9ekfRL6a582T4P37/31XEstQ5p58=
 github.com/golang/glog v0.0.0-20160126235308-23def4e6c14b/go.mod h1:SBH7ygxi8pfUlaOkMMuAQtPIUF8ecWP5IEl/CR7VP2Q=
-k8s.io/klog/v2 v2.0.0-20200324194303-db919253a3bc h1:E/enZ+SqXD3ChluFNvXqlLcUkqMQQDpiyGruRq5pjvY=
-k8s.io/klog/v2 v2.0.0-20200324194303-db919253a3bc/go.mod h1:q4PVo0BneA7GsUJvFqoEvOCVmYJP0c5Y4VxrAYpJrIk=
+github.com/kr/pretty v0.1.0 h1:L/CwN0zerZDmRFUapSPitk6f+Q3+0za1rQkzVuMiMFI=
+github.com/kr/pretty v0.1.0/go.mod h1:dAy3ld7l9f0ibDNOQOHHMYYIIbhfbHSm3C4ZsoJORNo=
+github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ=
+github.com/kr/text v0.1.0 h1:45sCR5RtlFHMR4UwH9sdQ5TC8v0qDQCHnXt+kaKSTVE=
+github.com/kr/text v0.1.0/go.mod h1:4Jbv+DJW3UT/LiOwJeYQe1efqtUx/iVham/4vfdArNI=
+github.com/pkg/errors v0.8.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
+github.com/pkg/errors v0.9.1 h1:FEBLx1zS214owpjy7qsBeixbURkuhQAwrK5UwLGTwt4=
+github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
+github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
+github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
+github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
+github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI=
+github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4=
+github.com/stretchr/testify v1.7.0 h1:nwc3DEeHmmLAfoZucVR881uASk0Mfjw8xYJ99tb5CcY=
+github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
+go.uber.org/atomic v1.7.0 h1:ADUqmZGgLDDfbSL9ZmPxKTybcoEYHgpYfELNoN+7hsw=
+go.uber.org/atomic v1.7.0/go.mod h1:fEN4uk6kAWBTFdckzkM89CLk9XfWZrxpCo0nPH17wJc=
+go.uber.org/goleak v1.1.10 h1:z+mqJhf6ss6BSfSM671tgKyZBFPTTJM+HLxnhPC3wu0=
+go.uber.org/goleak v1.1.10/go.mod h1:8a7PlsEVH3e/a/GLqe5IIrQx6GzcnRmZEufDUTk4A7A=
+go.uber.org/multierr v1.6.0 h1:y6IPFStTAIT5Ytl7/XYmHvzXQ7S3g/IeZW9hyZ5thw4=
+go.uber.org/multierr v1.6.0/go.mod h1:cdWPpRnG4AhwMwsgIHip0KRBQjJy5kYEpYjJxpXp9iU=
+go.uber.org/zap v1.19.0 h1:mZQZefskPPCMIBCSEH0v2/iUqqLrYtaeqwD6FUGUnFE=
+go.uber.org/zap v1.19.0/go.mod h1:xg/QME4nWcxGxrpdeYfq7UvYrLh66cuVKdrbD1XF/NI=
+golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w=
+golang.org/x/lint v0.0.0-20190930215403-16217165b5de h1:5hukYrvBGR8/eNkX5mdUezrA6JiaEZDtJb9Ei+1LlBs=
+golang.org/x/lint v0.0.0-20190930215403-16217165b5de/go.mod h1:6SW0HCj/g11FgYtHlgUYUwCkIfeOF89ocIRzGO/8vkc=
+golang.org/x/net v0.0.0-20190311183353-d8887717615a/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg=
+golang.org/x/net v0.0.0-20190620200207-3b0461eec859/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s=
+golang.org/x/sync v0.0.0-20190423024810-112230192c58/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
+golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
+golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
+golang.org/x/tools v0.0.0-20190311212946-11955173bddd/go.mod h1:LCzVGOaR6xXOjkQ3onu1FJEFr0SW1gC7cKk1uF8kGRs=
+golang.org/x/tools v0.0.0-20191108193012-7d206e10da11 h1:Yq9t9jnGoR+dBuitxdo9l6Q7xh/zOyNnYUtDKaQ3x0E=
+golang.org/x/tools v0.0.0-20191108193012-7d206e10da11/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo=
+golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
+gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
+gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127 h1:qIbj1fsPNlZgppZ+VLlY7N33q108Sa+fhmuc+sWQYwY=
+gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
+gopkg.in/yaml.v2 v2.2.2/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=
+gopkg.in/yaml.v2 v2.2.8 h1:obN1ZagJSUGI0Ek/LBmuj4SNLPfIny3KsKFopxRdj10=
+gopkg.in/yaml.v2 v2.2.8/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=
+gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=
+gopkg.in/yaml.v3 v3.0.0-20210107192922-496545a6307b h1:h8qDotaEPuJATrMmW04NCwg7v22aHH28wwpauUhK9Oo=
+gopkg.in/yaml.v3 v3.0.0-20210107192922-496545a6307b/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=
diff --git a/klogr/klogr.go b/klogr/klogr.go
index 02433e8..8206c10 100644
--- a/klogr/klogr.go
+++ b/klogr/klogr.go
@@ -122,13 +122,13 @@ func (l klogger) Info(level int, msg string, kvList ...interface{}) {
 		trimmed := serialize.TrimDuplicates(l.values, kvList)
 		fixedStr := flatten(trimmed[0]...)
 		userStr := flatten(trimmed[1]...)
-		klog.InfoDepth(l.callDepth+1, l.prefix, " ", msgStr, " ", fixedStr, " ", userStr)
+		klog.V(klog.Level(level)).InfoDepth(l.callDepth+1, l.prefix, " ", msgStr, " ", fixedStr, " ", userStr)
 	case FormatKlog:
 		trimmed := serialize.TrimDuplicates(l.values, kvList)
 		if l.prefix != "" {
 			msg = l.prefix + ": " + msg
 		}
-		klog.InfoSDepth(l.callDepth+1, msg, append(trimmed[0], trimmed[1]...)...)
+		klog.V(klog.Level(level)).InfoSDepth(l.callDepth+1, msg, append(trimmed[0], trimmed[1]...)...)
 	}
 }
 


Test patch:
diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml
index 1e6806d..5ff4d89 100644
--- a/.github/workflows/test.yml
+++ b/.github/workflows/test.yml
@@ -14,11 +14,14 @@ jobs:
         go-version: ${{ matrix.go-version }}
     - name: Checkout code
       uses: actions/checkout@v2
-    - name: Test
+    - name: Test klog
       run: |
         go get -t -v ./...
         go test -v -race ./...
-        cd hack/tools && go test -v -race ./...
+    - name: Test hack/tools
+      run: cd hack/tools && go test -v -race ./...
+    - name: Test examples
+      run: cd examples && go test -v -race ./...
   lint:
     runs-on: ubuntu-latest
     steps:
diff --git a/examples/output_test/output_test.go b/examples/output_test/output_test.go
new file mode 100644
index 0000000..0624e3a
--- /dev/null
+++ b/examples/output_test/output_test.go
@@ -0,0 +1,153 @@
+/*
+Copyright 2022 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 output_test shows how to use k8s.io/klog/v2/test
+// and provides unit testing with dependencies that wouldn't
+// be acceptable for the main module.
+package output_test
+
+import (
+	"io"
+	"testing"
+
+	"github.com/go-logr/logr"
+	"github.com/go-logr/zapr"
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
+
+	"k8s.io/klog/v2"
+	"k8s.io/klog/v2/klogr"
+	"k8s.io/klog/v2/test"
+	"k8s.io/klog/v2/textlogger"
+)
+
+func init() {
+	test.InitKlog()
+}
+
+// TestKlogOutput tests klog output without a logger.
+func TestKlogOutput(t *testing.T) {
+	test.Output(t, test.OutputConfig{})
+}
+
+// TestTextloggerOutput tests the textlogger, directly and as backend.
+func TestTextloggerOutput(t *testing.T) {
+	newLogger := func(out io.Writer, v int, vmodule string) logr.Logger {
+		config := textlogger.NewConfig(
+			textlogger.Verbosity(v),
+			textlogger.Output(out),
+		)
+		if err := config.VModule().Set(vmodule); err != nil {
+			panic(err)
+		}
+		return textlogger.NewLogger(config)
+	}
+	t.Run("direct", func(t *testing.T) {
+		test.Output(t, test.OutputConfig{NewLogger: newLogger, SupportsVModule: true})
+	})
+	t.Run("klog-backend", func(t *testing.T) {
+		test.Output(t, test.OutputConfig{NewLogger: newLogger, AsBackend: true})
+	})
+}
+
+// TestTextloggerOutput tests the zapr, directly and as backend.
+func TestZaprOutput(t *testing.T) {
+	newLogger := func(out io.Writer, v int, vmodule string) logr.Logger {
+		return newZaprLogger(out, v)
+	}
+	t.Run("direct", func(t *testing.T) {
+		test.Output(t, test.OutputConfig{NewLogger: newLogger, ExpectedOutputMapping: test.ZaprOutputMappingDirect()})
+	})
+	t.Run("klog-backend", func(t *testing.T) {
+		test.Output(t, test.OutputConfig{NewLogger: newLogger, AsBackend: true, ExpectedOutputMapping: test.ZaprOutputMappingIndirect()})
+	})
+}
+
+// TestKlogrOutput tests klogr output via klog.
+func TestKlogrOutput(t *testing.T) {
+	test.Output(t, test.OutputConfig{
+		NewLogger: func(out io.Writer, v int, vmodule string) logr.Logger {
+			return klogr.NewWithOptions(klogr.WithFormat(klogr.FormatKlog))
+		},
+	})
+}
+
+// TestKlogrStackText tests klogr -> klog -> text logger.
+func TestKlogrStackText(t *testing.T) {
+	newLogger := func(out io.Writer, v int, vmodule string) logr.Logger {
+		// Backend: text output.
+		config := textlogger.NewConfig(
+			textlogger.Verbosity(v),
+			textlogger.Output(out),
+		)
+		if err := config.VModule().Set(vmodule); err != nil {
+			panic(err)
+		}
+		klog.SetLogger(textlogger.NewLogger(config))
+
+		// Frontend: klogr.
+		return klogr.NewWithOptions(klogr.WithFormat(klogr.FormatKlog))
+	}
+	test.Output(t, test.OutputConfig{NewLogger: newLogger, SupportsVModule: true})
+}
+
+// TestKlogrStackKlogr tests klogr -> klog -> zapr.
+//
+// This exposes whether verbosity is passed through correctly
+// (https://github.com/kubernetes/klog/issues/294) because klogr logging
+// records that.
+func TestKlogrStackZapr(t *testing.T) {
+	mapping := test.ZaprOutputMappingIndirect()
+
+	// klogr doesn't warn about invalid KVs and just inserts
+	// "(MISSING)".
+	for key, value := range map[string]string{
+		`I output.go:<LINE>] "odd arguments" akey="avalue" akey2="(MISSING)"
+`: `{"caller":"test/output.go:<LINE>","msg":"odd arguments","v":0,"akey":"avalue","akey2":"(MISSING)"}
+`,
+
+		`I output.go:<LINE>] "both odd" basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)"
+`: `{"caller":"test/output.go:<LINE>","msg":"both odd","v":0,"basekey1":"basevar1","basekey2":"(MISSING)","akey":"avalue","akey2":"(MISSING)"}
+`,
+	} {
+		mapping[key] = value
+	}
+
+	newLogger := func(out io.Writer, v int, vmodule string) logr.Logger {
+		// Backend: zapr as configured in k8s.io/component-base/logs/json.
+		klog.SetLogger(newZaprLogger(out, v))
+
+		// Frontend: klogr.
+		return klogr.NewWithOptions(klogr.WithFormat(klogr.FormatKlog))
+	}
+	test.Output(t, test.OutputConfig{NewLogger: newLogger, ExpectedOutputMapping: mapping})
+}
+
+func newZaprLogger(out io.Writer, v int) logr.Logger {
+	encoderConfig := &zapcore.EncoderConfig{
+		MessageKey:     "msg",
+		CallerKey:      "caller",
+		NameKey:        "logger",
+		EncodeDuration: zapcore.StringDurationEncoder,
+		EncodeCaller:   zapcore.ShortCallerEncoder,
+	}
+	encoder := zapcore.NewJSONEncoder(*encoderConfig)
+	zapV := -zapcore.Level(v)
+	core := zapcore.NewCore(encoder, zapcore.AddSync(out), zapV)
+	l := zap.New(core, zap.WithCaller(true))
+	logger := zapr.NewLoggerWithOptions(l, zapr.LogInfoLevel("v"), zapr.ErrorKey("err"))
+	return logger
+}
diff --git a/test/output.go b/test/output.go
index a417491..0c447a8 100644
--- a/test/output.go
+++ b/test/output.go
@@ -67,7 +67,9 @@ func InitKlog() {
 // later release.
 type OutputConfig struct {
 	// NewLogger is called to create a new logger. If nil, output via klog
-	// is tested. Support for -vmodule is optional.
+	// is tested. Support for -vmodule is optional.  ClearLogger is called
+	// after each test, therefore it is okay to user SetLogger without
+	// undoing that in the callback.
 	NewLogger func(out io.Writer, v int, vmodule string) logr.Logger
 
 	// AsBackend enables testing through klog and the logger set there with
@@ -187,10 +189,10 @@ func Output(t *testing.T, config OutputConfig) {
 		"odd WithValues": {
 			withValues: []interface{}{"keyWithoutValue"},
 			moreValues: []interface{}{"anotherKeyWithoutValue"},
-			text:       "test",
-			expectedOutput: `I output.go:<LINE>] "test" keyWithoutValue="(MISSING)"
-I output.go:<LINE>] "test" keyWithoutValue="(MISSING)" anotherKeyWithoutValue="(MISSING)"
-I output.go:<LINE>] "test" keyWithoutValue="(MISSING)"
+			text:       "odd WithValues",
+			expectedOutput: `I output.go:<LINE>] "odd WithValues" keyWithoutValue="(MISSING)"
+I output.go:<LINE>] "odd WithValues" keyWithoutValue="(MISSING)" anotherKeyWithoutValue="(MISSING)"
+I output.go:<LINE>] "odd WithValues" keyWithoutValue="(MISSING)"
 `,
 		},
 		"multiple WithValues": {
@@ -228,9 +230,9 @@ I output.go:<LINE>] "test" firstKey=1 secondKey=3
 `,
 		},
 		"handle odd-numbers of KVs": {
-			text:   "test",
+			text:   "odd arguments",
 			values: []interface{}{"akey", "avalue", "akey2"},
-			expectedOutput: `I output.go:<LINE>] "test" akey="avalue" akey2="(MISSING)"
+			expectedOutput: `I output.go:<LINE>] "odd arguments" akey="avalue" akey2="(MISSING)"
 `,
 		},
 		"html characters": {
@@ -247,9 +249,9 @@ I output.go:<LINE>] "test" firstKey=1 secondKey=3
 		},
 		"handle odd-numbers of KVs in both log values and Info args": {
 			withValues: []interface{}{"basekey1", "basevar1", "basekey2"},
-			text:       "test",
+			text:       "both odd",
 			values:     []interface{}{"akey", "avalue", "akey2"},
-			expectedOutput: `I output.go:<LINE>] "test" basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)"
+			expectedOutput: `I output.go:<LINE>] "both odd" basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)"
 `,
 		},
 		"KObj": {
@@ -289,6 +291,8 @@ I output.go:<LINE>] "test" firstKey=1 secondKey=3
 	}
 	for n, test := range tests {
 		t.Run(n, func(t *testing.T) {
+			defer klog.ClearLogger()
+
 			printWithLogger := func(logger logr.Logger) {
 				for _, name := range test.withNames {
 					logger = logger.WithName(name)
@@ -298,21 +302,21 @@ I output.go:<LINE>] "test" firstKey=1 secondKey=3
 				// the combination, then again the original logger.
 				// It must not have been modified. This produces
 				// three log entries.
-				logger = logger.WithValues(test.withValues...)
+				logger = logger.WithValues(test.withValues...) // <WITH-VALUES>
 				loggers := []logr.Logger{logger}
 				if test.moreValues != nil {
-					loggers = append(loggers, logger.WithValues(test.moreValues...), logger)
+					loggers = append(loggers, logger.WithValues(test.moreValues...), logger) // <WITH-VALUES-2>
 				}
 				if test.evenMoreValues != nil {
-					loggers = append(loggers, logger.WithValues(test.evenMoreValues...))
+					loggers = append(loggers, logger.WithValues(test.evenMoreValues...)) // <WITH-VALUES-3>
 				}
 				for _, logger := range loggers {
 					if test.withHelper {
-						loggerHelper(logger, test.text, test.values)
+						loggerHelper(logger, test.text, test.values) // <LINE>
 					} else if test.err != nil {
-						logger.Error(test.err, test.text, test.values...)
+						logger.Error(test.err, test.text, test.values...) // <LINE>
 					} else {
-						logger.V(test.v).Info(test.text, test.values...)
+						logger.V(test.v).Info(test.text, test.values...) // <LINE>
 					}
 				}
 			}
@@ -394,12 +398,17 @@ I output.go:<LINE>] "test" firstKey=1 secondKey=3
 				if repl, ok := config.ExpectedOutputMapping[expected]; ok {
 					expected = repl
 				}
+				expectedWithPlaceholder := expected
 				expected = strings.ReplaceAll(expected, "<LINE>", fmt.Sprintf("%d", callLine))
 				expected = strings.ReplaceAll(expected, "<WITH-VALUES>", fmt.Sprintf("%d", expectedLine-18))
 				expected = strings.ReplaceAll(expected, "<WITH-VALUES-2>", fmt.Sprintf("%d", expectedLine-15))
 				expected = strings.ReplaceAll(expected, "<WITH-VALUES-3>", fmt.Sprintf("%d", expectedLine-12))
 				if actual != expected {
-					t.Errorf("Output mismatch. Expected:\n%s\nActual:\n%s\n", expected, actual)
+					if expectedWithPlaceholder == test.expectedOutput {
+						t.Errorf("Output mismatch. Expected:\n%s\nActual:\n%s\n", expectedWithPlaceholder, actual)
+					} else {
+						t.Errorf("Output mismatch. klog:\n%s\nExpected:\n%s\nActual:\n%s\n", test.expectedOutput, expectedWithPlaceholder, actual)
+					}
 				}
 			}
 
@@ -414,7 +423,6 @@ I output.go:<LINE>] "test" firstKey=1 secondKey=3
 			if config.AsBackend {
 				testOutput(t, printWithKlogLine, func(buffer *bytes.Buffer) {
 					klog.SetLogger(config.NewLogger(buffer, 10, ""))
-					defer klog.ClearLogger()
 					printWithKlog()
 				})
 				return
@@ -645,9 +653,14 @@ I output.go:<LINE>] "test" firstKey=1 secondKey=3
 				if repl, ok := config.ExpectedOutputMapping[expected]; ok {
 					expected = repl
 				}
+				expectedWithPlaceholder := expected
 				expected = strings.ReplaceAll(expected, "<LINE>", fmt.Sprintf("%d", callLine))
 				if actual != expected {
-					t.Errorf("Output mismatch. Expected:\n%s\nActual:\n%s\n", expected, actual)
+					if expectedWithPlaceholder == test.output {
+						t.Errorf("Output mismatch. Expected:\n%s\nActual:\n%s\n", expectedWithPlaceholder, actual)
+					} else {
+						t.Errorf("Output mismatch. klog:\n%s\nExpected:\n%s\nActual:\n%s\n", test.output, expectedWithPlaceholder, actual)
+					}
 				}
 			})
 		}
diff --git a/test/output_test.go b/test/output_test.go
deleted file mode 100644
index 5a43a1c..0000000
--- a/test/output_test.go
+++ /dev/null
@@ -1,65 +0,0 @@
-/*
-Copyright 2021 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 test
-
-import (
-	"io"
-	"testing"
-
-	"github.com/go-logr/logr"
-
-	"k8s.io/klog/v2/klogr"
-	"k8s.io/klog/v2/textlogger"
-)
-
-func init() {
-	InitKlog()
-}
-
-// TestKlogOutput tests klog output without a logger.
-func TestKlogOutput(t *testing.T) {
-	Output(t, OutputConfig{})
-}
-
-// TestTextloggerOutput tests the textlogger, directly and as backend.
-func TestTextloggerOutput(t *testing.T) {
-	newLogger := func(out io.Writer, v int, vmodule string) logr.Logger {
-		config := textlogger.NewConfig(
-			textlogger.Verbosity(v),
-			textlogger.Output(out),
-		)
-		if err := config.VModule().Set(vmodule); err != nil {
-			panic(err)
-		}
-		return textlogger.NewLogger(config)
-	}
-	t.Run("direct", func(t *testing.T) {
-		Output(t, OutputConfig{NewLogger: newLogger, SupportsVModule: true})
-	})
-	t.Run("klog-backend", func(t *testing.T) {
-		Output(t, OutputConfig{NewLogger: newLogger, AsBackend: true})
-	})
-}
-
-// TestKlogrOutput tests klogr output via klog.
-func TestKlogrOutput(t *testing.T) {
-	Output(t, OutputConfig{
-		NewLogger: func(out io.Writer, v int, vmodule string) logr.Logger {
-			return klogr.NewWithOptions(klogr.WithFormat(klogr.FormatKlog))
-		},
-	})
-}
diff --git a/test/zapr.go b/test/zapr.go
new file mode 100644
index 0000000..0bd9473
--- /dev/null
+++ b/test/zapr.go
@@ -0,0 +1,246 @@
+/*
+Copyright 2022 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 test
+
+// ZaprOutputMappingDirect provides a mapping from klog output to the
+// corresponding zapr output when zapr is called directly.
+//
+// Experimental
+//
+// Notice: This package is EXPERIMENTAL and may be changed or removed in a
+// later release.
+func ZaprOutputMappingDirect() map[string]string {
+	return map[string]string{
+		`I output.go:<LINE>] "test" akey="<&>"
+`: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"akey":"<&>"}
+`,
+
+		`E output.go:<LINE>] "test" err="whoops"
+`: `{"caller":"test/output.go:<LINE>","msg":"test","err":"whoops"}
+`,
+
+		`I output.go:<LINE>] "helper" akey="avalue"
+`: `{"caller":"test/output.go:<LINE>","msg":"helper","v":0,"akey":"avalue"}
+`,
+
+		`I output.go:<LINE>] "hello/world: test" akey="avalue"
+`: `{"logger":"hello.world","caller":"test/output.go:<LINE>","msg":"test","v":0,"akey":"avalue"}
+`,
+
+		`I output.go:<LINE>] "test" X="y" duration="1m0s" A="b"
+`: `{"caller":"test/output.go:<LINE>","msg":"test","duration":"1h0m0s","X":"y","v":0,"duration":"1m0s","A":"b"}
+`,
+
+		`I output.go:<LINE>] "test" akey9="avalue9" akey8="avalue8" akey1="avalue1" akey5="avalue5" akey4="avalue4"
+`: `{"caller":"test/output.go:<LINE>","msg":"test","akey9":"avalue9","akey8":"avalue8","akey1":"avalue1","v":0,"akey5":"avalue5","akey4":"avalue4"}
+`,
+
+		`I output.go:<LINE>] "test"
+`: `{"caller":"test/output.go:<LINE>","msg":"test","v":0}
+`,
+
+		`I output.go:<LINE>] "\"quoted\"" key="\"quoted value\""
+`: `{"caller":"test/output.go:<LINE>","msg":"\"quoted\"","v":0,"key":"\"quoted value\""}
+`,
+
+		`I output.go:<LINE>] "test" err="whoops"
+`: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"err":"whoops"}
+`,
+
+		`I output.go:<LINE>] "test" pod="kube-system/pod-1"
+`: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"pod":{"name":"pod-1","namespace":"kube-system"}}
+`,
+
+		`I output.go:<LINE>] "test" pods=[kube-system/pod-1 kube-system/pod-2]
+`: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"pods":[{"name":"pod-1","namespace":"kube-system"},{"name":"pod-2","namespace":"kube-system"}]}
+`,
+
+		`I output.go:<LINE>] "test" akey="avalue"
+`: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"akey":"avalue"}
+`,
+
+		`I output.go:<LINE>] "me: test" akey="avalue"
+`: `{"logger":"me","caller":"test/output.go:<LINE>","msg":"test","v":0,"akey":"avalue"}
+`,
+
+		`I output.go:<LINE>] "test" akey="avalue2"
+`: `{"caller":"test/output.go:<LINE>","msg":"test","akey":"avalue","v":0,"akey":"avalue2"}
+`,
+
+		`I output.go:<LINE>] "you see me"
+`: `{"caller":"test/output.go:<LINE>","msg":"you see me","v":9}
+`,
+
+		`I output.go:<LINE>] "test" firstKey=1
+I output.go:<LINE>] "test" firstKey=1 secondKey=2
+I output.go:<LINE>] "test" firstKey=1
+I output.go:<LINE>] "test" firstKey=1 secondKey=3
+`: `{"caller":"test/output.go:<LINE>","msg":"test","firstKey":1,"v":0}
+{"caller":"test/output.go:<LINE>","msg":"test","firstKey":1,"secondKey":2,"v":0}
+{"caller":"test/output.go:<LINE>","msg":"test","firstKey":1,"v":0}
+{"caller":"test/output.go:<LINE>","msg":"test","firstKey":1,"secondKey":3,"v":0}
+`,
+
+		`I output.go:<LINE>] "odd WithValues" keyWithoutValue="(MISSING)"
+I output.go:<LINE>] "odd WithValues" keyWithoutValue="(MISSING)" anotherKeyWithoutValue="(MISSING)"
+I output.go:<LINE>] "odd WithValues" keyWithoutValue="(MISSING)"
+`: `{"caller":"test/output.go:<WITH-VALUES>","msg":"odd number of arguments passed as key-value pairs for logging","ignored key":"keyWithoutValue"}
+{"caller":"test/output.go:<WITH-VALUES-2>","msg":"odd number of arguments passed as key-value pairs for logging","ignored key":"anotherKeyWithoutValue"}
+{"caller":"test/output.go:<LINE>","msg":"odd WithValues","v":0}
+{"caller":"test/output.go:<LINE>","msg":"odd WithValues","v":0}
+{"caller":"test/output.go:<LINE>","msg":"odd WithValues","v":0}
+`,
+
+		`I output.go:<LINE>] "odd arguments" akey="avalue" akey2="(MISSING)"
+`: `{"caller":"test/output.go:<LINE>","msg":"odd number of arguments passed as key-value pairs for logging","ignored key":"akey2"}
+{"caller":"test/output.go:<LINE>","msg":"odd arguments","v":0,"akey":"avalue"}
+`,
+
+		`I output.go:<LINE>] "both odd" basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)"
+`: `{"caller":"test/output.go:<WITH-VALUES>","msg":"odd number of arguments passed as key-value pairs for logging","ignored key":"basekey2"}
+{"caller":"test/output.go:<LINE>","msg":"odd number of arguments passed as key-value pairs for logging","basekey1":"basevar1","ignored key":"akey2"}
+{"caller":"test/output.go:<LINE>","msg":"both odd","basekey1":"basevar1","v":0,"akey":"avalue"}
+`,
+
+		// klog.Info
+		`I output.go:<LINE>] "helloworld\n"
+`: `{"caller":"test/output.go:<LINE>","msg":"helloworld\n","v":0}
+`,
+
+		// klog.Infoln
+		`I output.go:<LINE>] "hello world\n"
+`: `{"caller":"test/output.go:<LINE>","msg":"hello world\n","v":0}
+`,
+
+		// klog.Error
+		`E output.go:<LINE>] "helloworld\n"
+`: `{"caller":"test/output.go:<LINE>","msg":"helloworld\n"}
+`,
+
+		// klog.Errorln
+		`E output.go:<LINE>] "hello world\n"
+`: `{"caller":"test/output.go:<LINE>","msg":"hello world\n"}
+`,
+
+		// klog.ErrorS
+		`E output.go:<LINE>] "world" err="hello"
+`: `{"caller":"test/output.go:<LINE>","msg":"world","err":"hello"}
+`,
+
+		// klog.InfoS
+		`I output.go:<LINE>] "hello" what="world"
+`: `{"caller":"test/output.go:<LINE>","msg":"hello","v":0,"what":"world"}
+`,
+
+		// klog.V(1).Info
+		`I output.go:<LINE>] "hellooneworld\n"
+`: `{"caller":"test/output.go:<LINE>","msg":"hellooneworld\n","v":1}
+`,
+
+		// klog.V(1).Infoln
+		`I output.go:<LINE>] "hello one world\n"
+`: `{"caller":"test/output.go:<LINE>","msg":"hello one world\n","v":1}
+`,
+
+		// klog.V(1).ErrorS
+		`E output.go:<LINE>] "one world" err="hello"
+`: `{"caller":"test/output.go:<LINE>","msg":"one world","err":"hello"}
+`,
+
+		// klog.V(1).InfoS
+		`I output.go:<LINE>] "hello" what="one world"
+`: `{"caller":"test/output.go:<LINE>","msg":"hello","v":1,"what":"one world"}
+`,
+	}
+}
+
+// ZaprOutputMappingIndirect provides a mapping from klog output to the
+// corresponding zapr output when zapr is called indirectly through
+// klog.
+//
+// This is different from ZaprOutputMappingDirect because:
+// - WithName gets added to the message by Output.
+// - zap uses . as separator instead of / between WithName values,
+//   here we get slashes because Output concatenates these values.
+// - WithValues are added to the normal key/value parameters by
+//   Output, which puts them after "v".
+// - Output does that without emitting the warning that we get
+//   from zapr.
+// - zap drops keys with missing values, here we get "(MISSING)".
+// - zap does not de-duplicate key/value pairs, here klog does that
+//   for it.
+//
+// Experimental
+//
+// Notice: This package is EXPERIMENTAL and may be changed or removed in a
+// later release.
+func ZaprOutputMappingIndirect() map[string]string {
+	mapping := ZaprOutputMappingDirect()
+
+	for key, value := range map[string]string{
+		`I output.go:<LINE>] "hello/world: test" akey="avalue"
+`: `{"caller":"test/output.go:<LINE>","msg":"hello/world: test","v":0,"akey":"avalue"}
+`,
+
+		`I output.go:<LINE>] "me: test" akey="avalue"
+`: `{"caller":"test/output.go:<LINE>","msg":"me: test","v":0,"akey":"avalue"}
+`,
+
+		`I output.go:<LINE>] "odd parameters" basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)"
+`: `{"caller":"test/output.go:<LINE>","msg":"odd number of arguments passed as key-value pairs for logging","ignored key":"akey2"}
+{"caller":"test/output.go:<LINE>","msg":"odd parameters","v":0,"basekey1":"basevar1","basekey2":"(MISSING)","akey":"avalue"}
+`,
+
+		`I output.go:<LINE>] "odd WithValues" keyWithoutValue="(MISSING)"
+I output.go:<LINE>] "odd WithValues" keyWithoutValue="(MISSING)" anotherKeyWithoutValue="(MISSING)"
+I output.go:<LINE>] "odd WithValues" keyWithoutValue="(MISSING)"
+`: `{"caller":"test/output.go:<LINE>","msg":"odd WithValues","v":0,"keyWithoutValue":"(MISSING)"}
+{"caller":"test/output.go:<LINE>","msg":"odd WithValues","v":0,"keyWithoutValue":"(MISSING)","anotherKeyWithoutValue":"(MISSING)"}
+{"caller":"test/output.go:<LINE>","msg":"odd WithValues","v":0,"keyWithoutValue":"(MISSING)"}
+`,
+
+		`I output.go:<LINE>] "both odd" basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)"
+`: `{"caller":"test/output.go:<LINE>","msg":"odd number of arguments passed as key-value pairs for logging","ignored key":"akey2"}
+{"caller":"test/output.go:<LINE>","msg":"both odd","v":0,"basekey1":"basevar1","basekey2":"(MISSING)","akey":"avalue"}
+`,
+
+		`I output.go:<LINE>] "test" akey9="avalue9" akey8="avalue8" akey1="avalue1" akey5="avalue5" akey4="avalue4"
+`: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"akey9":"avalue9","akey8":"avalue8","akey1":"avalue1","akey5":"avalue5","akey4":"avalue4"}
+`,
+
+		`I output.go:<LINE>] "test" akey="avalue2"
+`: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"akey":"avalue2"}
+`,
+
+		`I output.go:<LINE>] "test" X="y" duration="1m0s" A="b"
+`: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"X":"y","duration":"1m0s","A":"b"}
+`,
+
+		`I output.go:<LINE>] "test" firstKey=1
+I output.go:<LINE>] "test" firstKey=1 secondKey=2
+I output.go:<LINE>] "test" firstKey=1
+I output.go:<LINE>] "test" firstKey=1 secondKey=3
+`: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"firstKey":1}
+{"caller":"test/output.go:<LINE>","msg":"test","v":0,"firstKey":1,"secondKey":2}
+{"caller":"test/output.go:<LINE>","msg":"test","v":0,"firstKey":1}
+{"caller":"test/output.go:<LINE>","msg":"test","v":0,"firstKey":1,"secondKey":3}
+`,
+	} {
+		mapping[key] = value
+	}
+	return mapping
+}