test: move output test to example, include zapr

To reproduce the loss of verbosity in
klogr (kubernetes#294) we need a backend which
actually emits the verbosity. zapr does that and also happens to be the logging
implementation used in Kubernetes for JSON, so it makes sense to test with
that.

The expected output mapping may be useful also for testing in Kubernetes,
therefore it gets exported by k8s.io/klog/v2/test.

Because k8s.io/klog/v2 must not depend on zapr, the actual output test gets
moved to the examples. The downside is that "go test ./..." no longer runs it.
One has to remember to enter the "examples" directory. The GitHub action gets
updated to do that.

.github/workflows/test.yml

@@ -19,6 +19,7 @@ jobs:
         go get -t -v ./...
         go test -v -race ./...
         cd hack/tools && go test -v -race ./...
+        cd examples && go test -v -race ./...
   lint:
     runs-on: ubuntu-latest
     steps:

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
 )
 

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=

examples/output_test/output_test.go

@@ -0,0 +1,158 @@
+/*
+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"
+	"strings"
+	"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()
+	for key, value := range mapping {
+		// BUG (https://github.com/kubernetes/klog/issues/294): verbosity is lost
+		mapping[key] = strings.ReplaceAll(value, `"v":9`, `"v":0`)
+	}
+
+	// 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
+}