From 6977d140ef0cd93cd7e3eb8bf1a0d66ecf4a5031 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Mon, 14 Feb 2022 19:12:50 +0100 Subject: [PATCH] test: move output test to example, include zapr To reproduce the loss of verbosity in klogr (https://github.com/kubernetes/klog/issues/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 | 3 +- examples/go.mod | 3 + examples/go.sum | 58 +++++- examples/output_test/output_test.go | 158 ++++++++++++++++ test/output.go | 278 ++++++++++++++++++++++++++-- test/output_test.go | 65 ------- 6 files changed, 476 insertions(+), 89 deletions(-) create mode 100644 examples/output_test/output_test.go delete mode 100644 test/output_test.go diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index 1e6806d1c..cebf8602f 100644 --- a/.github/workflows/test.yml +++ b/.github/workflows/test.yml @@ -18,7 +18,8 @@ jobs: run: | go get -t -v ./... go test -v -race ./... - cd hack/tools && go test -v -race ./... + cd hack/tools && go test -v -race ./... && cd ../.. + cd examples && go test -v -race ./... && cd .. lint: runs-on: ubuntu-latest steps: diff --git a/examples/go.mod b/examples/go.mod index 2768f2c1e..d7956666e 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 4d41cc903..5b43f393e 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/examples/output_test/output_test.go b/examples/output_test/output_test.go new file mode 100644 index 000000000..a6ef0abb2 --- /dev/null +++ b/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:] "odd arguments" akey="avalue" akey2="(MISSING)" +`: `{"caller":"test/output.go:","msg":"odd arguments","v":0,"akey":"avalue","akey2":"(MISSING)"} +`, + + `I output.go:] "both odd" basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)" +`: `{"caller":"test/output.go:","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 a41749140..73ea5b006 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:] "test" keyWithoutValue="(MISSING)" -I output.go:] "test" keyWithoutValue="(MISSING)" anotherKeyWithoutValue="(MISSING)" -I output.go:] "test" keyWithoutValue="(MISSING)" + text: "odd WithValues", + expectedOutput: `I output.go:] "odd WithValues" keyWithoutValue="(MISSING)" +I output.go:] "odd WithValues" keyWithoutValue="(MISSING)" anotherKeyWithoutValue="(MISSING)" +I output.go:] "odd WithValues" keyWithoutValue="(MISSING)" `, }, "multiple WithValues": { @@ -228,9 +230,9 @@ I output.go:] "test" firstKey=1 secondKey=3 `, }, "handle odd-numbers of KVs": { - text: "test", + text: "odd arguments", values: []interface{}{"akey", "avalue", "akey2"}, - expectedOutput: `I output.go:] "test" akey="avalue" akey2="(MISSING)" + expectedOutput: `I output.go:] "odd arguments" akey="avalue" akey2="(MISSING)" `, }, "html characters": { @@ -247,9 +249,9 @@ I output.go:] "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:] "test" basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)" + expectedOutput: `I output.go:] "both odd" basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)" `, }, "KObj": { @@ -289,6 +291,8 @@ I output.go:] "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:] "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...) // loggers := []logr.Logger{logger} if test.moreValues != nil { - loggers = append(loggers, logger.WithValues(test.moreValues...), logger) + loggers = append(loggers, logger.WithValues(test.moreValues...), logger) // } if test.evenMoreValues != nil { - loggers = append(loggers, logger.WithValues(test.evenMoreValues...)) + loggers = append(loggers, logger.WithValues(test.evenMoreValues...)) // } for _, logger := range loggers { if test.withHelper { - loggerHelper(logger, test.text, test.values) + loggerHelper(logger, test.text, test.values) // } else if test.err != nil { - logger.Error(test.err, test.text, test.values...) + logger.Error(test.err, test.text, test.values...) // } else { - logger.V(test.v).Info(test.text, test.values...) + logger.V(test.v).Info(test.text, test.values...) // } } } @@ -394,12 +398,17 @@ I output.go:] "test" firstKey=1 secondKey=3 if repl, ok := config.ExpectedOutputMapping[expected]; ok { expected = repl } + expectedWithPlaceholder := expected expected = strings.ReplaceAll(expected, "", fmt.Sprintf("%d", callLine)) expected = strings.ReplaceAll(expected, "", fmt.Sprintf("%d", expectedLine-18)) expected = strings.ReplaceAll(expected, "", fmt.Sprintf("%d", expectedLine-15)) expected = strings.ReplaceAll(expected, "", 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:] "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:] "test" firstKey=1 secondKey=3 if repl, ok := config.ExpectedOutputMapping[expected]; ok { expected = repl } + expectedWithPlaceholder := expected expected = strings.ReplaceAll(expected, "", 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) + } } }) } @@ -686,3 +699,232 @@ func (e *customErrorJSON) Error() string { func (e *customErrorJSON) MarshalJSON() ([]byte, error) { return json.Marshal(strings.ToUpper(e.s)) } + +// 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:] "test" akey="<&>" +`: `{"caller":"test/output.go:","msg":"test","v":0,"akey":"<&>"} +`, + + `E output.go:] "test" err="whoops" +`: `{"caller":"test/output.go:","msg":"test","err":"whoops"} +`, + + `I output.go:] "helper" akey="avalue" +`: `{"caller":"test/output.go:","msg":"helper","v":0,"akey":"avalue"} +`, + + `I output.go:] "hello/world: test" akey="avalue" +`: `{"logger":"hello.world","caller":"test/output.go:","msg":"test","v":0,"akey":"avalue"} +`, + + `I output.go:] "test" X="y" duration="1m0s" A="b" +`: `{"caller":"test/output.go:","msg":"test","duration":"1h0m0s","X":"y","v":0,"duration":"1m0s","A":"b"} +`, + + `I output.go:] "test" akey9="avalue9" akey8="avalue8" akey1="avalue1" akey5="avalue5" akey4="avalue4" +`: `{"caller":"test/output.go:","msg":"test","akey9":"avalue9","akey8":"avalue8","akey1":"avalue1","v":0,"akey5":"avalue5","akey4":"avalue4"} +`, + + `I output.go:] "test" +`: `{"caller":"test/output.go:","msg":"test","v":0} +`, + + `I output.go:] "\"quoted\"" key="\"quoted value\"" +`: `{"caller":"test/output.go:","msg":"\"quoted\"","v":0,"key":"\"quoted value\""} +`, + + `I output.go:] "test" err="whoops" +`: `{"caller":"test/output.go:","msg":"test","v":0,"err":"whoops"} +`, + + `I output.go:] "test" pod="kube-system/pod-1" +`: `{"caller":"test/output.go:","msg":"test","v":0,"pod":{"name":"pod-1","namespace":"kube-system"}} +`, + + `I output.go:] "test" pods=[kube-system/pod-1 kube-system/pod-2] +`: `{"caller":"test/output.go:","msg":"test","v":0,"pods":[{"name":"pod-1","namespace":"kube-system"},{"name":"pod-2","namespace":"kube-system"}]} +`, + + `I output.go:] "test" akey="avalue" +`: `{"caller":"test/output.go:","msg":"test","v":0,"akey":"avalue"} +`, + + `I output.go:] "me: test" akey="avalue" +`: `{"logger":"me","caller":"test/output.go:","msg":"test","v":0,"akey":"avalue"} +`, + + `I output.go:] "test" akey="avalue2" +`: `{"caller":"test/output.go:","msg":"test","akey":"avalue","v":0,"akey":"avalue2"} +`, + + `I output.go:] "you see me" +`: `{"caller":"test/output.go:","msg":"you see me","v":9} +`, + + `I output.go:] "test" firstKey=1 +I output.go:] "test" firstKey=1 secondKey=2 +I output.go:] "test" firstKey=1 +I output.go:] "test" firstKey=1 secondKey=3 +`: `{"caller":"test/output.go:","msg":"test","firstKey":1,"v":0} +{"caller":"test/output.go:","msg":"test","firstKey":1,"secondKey":2,"v":0} +{"caller":"test/output.go:","msg":"test","firstKey":1,"v":0} +{"caller":"test/output.go:","msg":"test","firstKey":1,"secondKey":3,"v":0} +`, + + `I output.go:] "odd WithValues" keyWithoutValue="(MISSING)" +I output.go:] "odd WithValues" keyWithoutValue="(MISSING)" anotherKeyWithoutValue="(MISSING)" +I output.go:] "odd WithValues" keyWithoutValue="(MISSING)" +`: `{"caller":"test/output.go:","msg":"odd number of arguments passed as key-value pairs for logging","ignored key":"keyWithoutValue"} +{"caller":"test/output.go:","msg":"odd number of arguments passed as key-value pairs for logging","ignored key":"anotherKeyWithoutValue"} +{"caller":"test/output.go:","msg":"odd WithValues","v":0} +{"caller":"test/output.go:","msg":"odd WithValues","v":0} +{"caller":"test/output.go:","msg":"odd WithValues","v":0} +`, + + `I output.go:] "odd arguments" akey="avalue" akey2="(MISSING)" +`: `{"caller":"test/output.go:","msg":"odd number of arguments passed as key-value pairs for logging","ignored key":"akey2"} +{"caller":"test/output.go:","msg":"odd arguments","v":0,"akey":"avalue"} +`, + + `I output.go:] "both odd" basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)" +`: `{"caller":"test/output.go:","msg":"odd number of arguments passed as key-value pairs for logging","ignored key":"basekey2"} +{"caller":"test/output.go:","msg":"odd number of arguments passed as key-value pairs for logging","basekey1":"basevar1","ignored key":"akey2"} +{"caller":"test/output.go:","msg":"both odd","basekey1":"basevar1","v":0,"akey":"avalue"} +`, + + // klog.Info + `I output.go:] "helloworld\n" +`: `{"caller":"test/output.go:","msg":"helloworld\n","v":0} +`, + + // klog.Infoln + `I output.go:] "hello world\n" +`: `{"caller":"test/output.go:","msg":"hello world\n","v":0} +`, + + // klog.Error + `E output.go:] "helloworld\n" +`: `{"caller":"test/output.go:","msg":"helloworld\n"} +`, + + // klog.Errorln + `E output.go:] "hello world\n" +`: `{"caller":"test/output.go:","msg":"hello world\n"} +`, + + // klog.ErrorS + `E output.go:] "world" err="hello" +`: `{"caller":"test/output.go:","msg":"world","err":"hello"} +`, + + // klog.InfoS + `I output.go:] "hello" what="world" +`: `{"caller":"test/output.go:","msg":"hello","v":0,"what":"world"} +`, + + // klog.V(1).Info + `I output.go:] "hellooneworld\n" +`: `{"caller":"test/output.go:","msg":"hellooneworld\n","v":1} +`, + + // klog.V(1).Infoln + `I output.go:] "hello one world\n" +`: `{"caller":"test/output.go:","msg":"hello one world\n","v":1} +`, + + // klog.V(1).ErrorS + `E output.go:] "one world" err="hello" +`: `{"caller":"test/output.go:","msg":"one world","err":"hello"} +`, + + // klog.V(1).InfoS + `I output.go:] "hello" what="one world" +`: `{"caller":"test/output.go:","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:] "hello/world: test" akey="avalue" +`: `{"caller":"test/output.go:","msg":"hello/world: test","v":0,"akey":"avalue"} +`, + + `I output.go:] "me: test" akey="avalue" +`: `{"caller":"test/output.go:","msg":"me: test","v":0,"akey":"avalue"} +`, + + `I output.go:] "odd parameters" basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)" +`: `{"caller":"test/output.go:","msg":"odd number of arguments passed as key-value pairs for logging","ignored key":"akey2"} +{"caller":"test/output.go:","msg":"odd parameters","v":0,"basekey1":"basevar1","basekey2":"(MISSING)","akey":"avalue"} +`, + + `I output.go:] "odd WithValues" keyWithoutValue="(MISSING)" +I output.go:] "odd WithValues" keyWithoutValue="(MISSING)" anotherKeyWithoutValue="(MISSING)" +I output.go:] "odd WithValues" keyWithoutValue="(MISSING)" +`: `{"caller":"test/output.go:","msg":"odd WithValues","v":0,"keyWithoutValue":"(MISSING)"} +{"caller":"test/output.go:","msg":"odd WithValues","v":0,"keyWithoutValue":"(MISSING)","anotherKeyWithoutValue":"(MISSING)"} +{"caller":"test/output.go:","msg":"odd WithValues","v":0,"keyWithoutValue":"(MISSING)"} +`, + + `I output.go:] "both odd" basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)" +`: `{"caller":"test/output.go:","msg":"odd number of arguments passed as key-value pairs for logging","ignored key":"akey2"} +{"caller":"test/output.go:","msg":"both odd","v":0,"basekey1":"basevar1","basekey2":"(MISSING)","akey":"avalue"} +`, + + `I output.go:] "test" akey9="avalue9" akey8="avalue8" akey1="avalue1" akey5="avalue5" akey4="avalue4" +`: `{"caller":"test/output.go:","msg":"test","v":0,"akey9":"avalue9","akey8":"avalue8","akey1":"avalue1","akey5":"avalue5","akey4":"avalue4"} +`, + + `I output.go:] "test" akey="avalue2" +`: `{"caller":"test/output.go:","msg":"test","v":0,"akey":"avalue2"} +`, + + `I output.go:] "test" X="y" duration="1m0s" A="b" +`: `{"caller":"test/output.go:","msg":"test","v":0,"X":"y","duration":"1m0s","A":"b"} +`, + + `I output.go:] "test" firstKey=1 +I output.go:] "test" firstKey=1 secondKey=2 +I output.go:] "test" firstKey=1 +I output.go:] "test" firstKey=1 secondKey=3 +`: `{"caller":"test/output.go:","msg":"test","v":0,"firstKey":1} +{"caller":"test/output.go:","msg":"test","v":0,"firstKey":1,"secondKey":2} +{"caller":"test/output.go:","msg":"test","v":0,"firstKey":1} +{"caller":"test/output.go:","msg":"test","v":0,"firstKey":1,"secondKey":3} +`, + } { + mapping[key] = value + } + return mapping +} diff --git a/test/output_test.go b/test/output_test.go deleted file mode 100644 index 5a43a1ced..000000000 --- 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)) - }, - }) -}