diff --git a/test/output.go b/test/output.go new file mode 100644 index 000000000..f0a883ebf --- /dev/null +++ b/test/output.go @@ -0,0 +1,464 @@ +/* +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 contains a reusable unit test for logging output and behavior. +// +// Experimental +// +// Notice: This package is EXPERIMENTAL and may be changed or removed in a +// later release. +package test + +import ( + "bytes" + "encoding/json" + "errors" + "flag" + "fmt" + "io" + "regexp" + "runtime" + "strings" + "testing" + "time" + + "github.com/go-logr/logr" + + "k8s.io/klog/v2" +) + +// InitKlog must be called once in an init function of a test package to +// configure klog for testing with Output. +// +// Experimental +// +// Notice: This function is EXPERIMENTAL and may be changed or removed in a +// later release. +func InitKlog() { + // klog gets configured so that it writes to a single output file that + // will be set during tests with SetOutput. + klog.InitFlags(nil) + flag.Set("v", "10") + flag.Set("log_file", "/dev/null") + flag.Set("logtostderr", "false") + flag.Set("alsologtostderr", "false") + flag.Set("stderrthreshold", "10") +} + +// OutputConfig contains optional settings for Output. +// +// Experimental +// +// Notice: This type is EXPERIMENTAL and may be changed or removed in a +// 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. + NewLogger func(out io.Writer, v int, vmodule string) logr.Logger + + // AsBackend enables testing through klog and the logger set there with + // SetLogger. + AsBackend bool + + // ExpectedOutputMapping replaces the builtin expected output for test + // cases with something else. If nil or a certain case is not present, + // the original text is used. + // + // The expected output uses as a placeholder for the line of the + // log call. The source code is always the output.go file itself. When + // testing a logger directly, is used for the first + // WithValues call, for a second and + // for a third. + ExpectedOutputMapping map[string]string + + // SupportsVModule indicates that the logger supports the vmodule + // parameter. Ignored when logging through klog. + SupportsVModule bool +} + +// Output covers various special cases of emitting log output. +// It can be used for arbitrary logr.Logger implementations. +// +// The expected output is what klog would print. When testing loggers +// that emit different output, a mapping from klog output to the +// corresponding logger output must be provided, otherwise the +// test will compare against the expected klog output. +// +// Loggers will be tested with direct calls to Info or +// as backend for klog. +// +// Experimental +// +// Notice: This function is EXPERIMENTAL and may be changed or removed in a +// later release. The test cases and thus the expected output also may +// change. +func Output(t *testing.T, config OutputConfig) { + tests := map[string]struct { + withHelper bool // use wrappers that get skipped during stack unwinding + withNames []string + // For a first WithValues call: logger1 := logger.WithValues() + withValues []interface{} + // For another WithValues call: logger2 := logger1.WithValues() + moreValues []interface{} + // For another WithValues call on the same logger as before: logger3 := logger1.WithValues() + evenMoreValues []interface{} + v int + vmodule string + text string + values []interface{} + err error + expectedOutput string + }{ + "log with values": { + text: "test", + values: []interface{}{"akey", "avalue"}, + expectedOutput: `I output.go:] "test" akey="avalue" +`, + }, + "call depth": { + text: "helper", + withHelper: true, + values: []interface{}{"akey", "avalue"}, + expectedOutput: `I output.go:] "helper" akey="avalue" +`, + }, + "verbosity enabled": { + text: "you see me", + v: 9, + expectedOutput: `I output.go:] "you see me" +`, + }, + "verbosity disabled": { + text: "you don't see me", + v: 11, + }, + "vmodule": { + text: "v=11: you see me because of -vmodule output=11", + v: 11, + vmodule: "output=11", + }, + "other vmodule": { + text: "v=11: you still don't see me because of -vmodule output_helper=11", + v: 11, + vmodule: "output_helper=11", + }, + "log with name and values": { + withNames: []string{"me"}, + text: "test", + values: []interface{}{"akey", "avalue"}, + expectedOutput: `I output.go:] "me: test" akey="avalue" +`, + }, + "log with multiple names and values": { + withNames: []string{"hello", "world"}, + text: "test", + values: []interface{}{"akey", "avalue"}, + expectedOutput: `I output.go:] "hello/world: test" akey="avalue" +`, + }, + "override single value": { + withValues: []interface{}{"akey", "avalue"}, + text: "test", + values: []interface{}{"akey", "avalue2"}, + expectedOutput: `I output.go:] "test" akey="avalue2" +`, + }, + "override WithValues": { + withValues: []interface{}{"duration", time.Hour, "X", "y"}, + text: "test", + values: []interface{}{"duration", time.Minute, "A", "b"}, + expectedOutput: `I output.go:] "test" X="y" duration="1m0s" A="b" +`, + }, + "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)" +`, + }, + "multiple WithValues": { + withValues: []interface{}{"firstKey", 1}, + moreValues: []interface{}{"secondKey", 2}, + evenMoreValues: []interface{}{"secondKey", 3}, + text: "test", + expectedOutput: `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 +`, + }, + "empty WithValues": { + withValues: []interface{}{}, + text: "test", + expectedOutput: `I output.go:] "test" +`, + }, + // TODO: unify behavior of loggers. + // klog doesn't deduplicate, klogr and textlogger do. We can ensure via static code analysis + // that this doesn't occur, so we shouldn't pay the runtime overhead for deduplication here + // and remove that from klogr and textlogger (https://github.com/kubernetes/klog/issues/286). + // "print duplicate keys in arguments": { + // text: "test", + // values: []interface{}{"akey", "avalue", "akey", "avalue2"}, + // expectedOutput: `I output.go:] "test" akey="avalue" akey="avalue2" + // `, + // }, + "preserve order of key/value pairs": { + withValues: []interface{}{"akey9", "avalue9", "akey8", "avalue8", "akey1", "avalue1"}, + text: "test", + values: []interface{}{"akey5", "avalue5", "akey4", "avalue4"}, + expectedOutput: `I output.go:] "test" akey9="avalue9" akey8="avalue8" akey1="avalue1" akey5="avalue5" akey4="avalue4" +`, + }, + "handle odd-numbers of KVs": { + text: "test", + values: []interface{}{"akey", "avalue", "akey2"}, + expectedOutput: `I output.go:] "test" akey="avalue" akey2="(MISSING)" +`, + }, + "html characters": { + text: "test", + values: []interface{}{"akey", "<&>"}, + expectedOutput: `I output.go:] "test" akey="<&>" +`, + }, + "quotation": { + text: `"quoted"`, + values: []interface{}{"key", `"quoted value"`}, + expectedOutput: `I output.go:] "\"quoted\"" key="\"quoted value\"" +`, + }, + "handle odd-numbers of KVs in both log values and Info args": { + withValues: []interface{}{"basekey1", "basevar1", "basekey2"}, + text: "test", + values: []interface{}{"akey", "avalue", "akey2"}, + expectedOutput: `I output.go:] "test" basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)" +`, + }, + "KObj": { + text: "test", + values: []interface{}{"pod", klog.KObj(&kmeta{Name: "pod-1", Namespace: "kube-system"})}, + expectedOutput: `I output.go:] "test" pod="kube-system/pod-1" +`, + }, + "KObjs": { + text: "test", + values: []interface{}{"pods", + klog.KObjs([]interface{}{ + &kmeta{Name: "pod-1", Namespace: "kube-system"}, + &kmeta{Name: "pod-2", Namespace: "kube-system"}, + })}, + expectedOutput: `I output.go:] "test" pods=[kube-system/pod-1 kube-system/pod-2] +`, + }, + "regular error types as value": { + text: "test", + values: []interface{}{"err", errors.New("whoops")}, + expectedOutput: `I output.go:] "test" err="whoops" +`, + }, + "ignore MarshalJSON": { + text: "test", + values: []interface{}{"err", &customErrorJSON{"whoops"}}, + expectedOutput: `I output.go:] "test" err="whoops" +`, + }, + "regular error types when using logr.Error": { + text: "test", + err: errors.New("whoops"), + expectedOutput: `E output.go:] "test" err="whoops" +`, + }, + } + for n, test := range tests { + t.Run(n, func(t *testing.T) { + printWithLogger := func(logger logr.Logger) { + for _, name := range test.withNames { + logger = logger.WithName(name) + } + // When we have multiple WithValues calls, we test + // first with the initial set of additional values, then + // the combination, then again the original logger. + // It must not have been modified. This produces + // three log entries. + logger = logger.WithValues(test.withValues...) + loggers := []logr.Logger{logger} + if test.moreValues != nil { + loggers = append(loggers, logger.WithValues(test.moreValues...), logger) + } + if test.evenMoreValues != nil { + loggers = append(loggers, logger.WithValues(test.evenMoreValues...)) + } + for _, logger := range loggers { + if test.withHelper { + loggerHelper(logger, test.text, test.values) + } else if test.err != nil { + logger.Error(test.err, test.text, test.values...) + } else { + logger.V(test.v).Info(test.text, test.values...) + } + } + } + _, _, printWithLoggerLine, _ := runtime.Caller(0) + + printWithKlog := func() { + kv := []interface{}{} + haveKeyInValues := func(key interface{}) bool { + for i := 0; i < len(test.values); i += 2 { + if key == test.values[i] { + return true + } + } + return false + } + appendKV := func(withValues []interface{}) { + if len(withValues)%2 != 0 { + withValues = append(withValues, "(MISSING)") + } + for i := 0; i < len(withValues); i += 2 { + if !haveKeyInValues(withValues[i]) { + kv = append(kv, withValues[i], withValues[i+1]) + } + } + } + // Here we need to emulate the handling of WithValues above. + appendKV(test.withValues) + kvs := [][]interface{}{copySlice(kv)} + if test.moreValues != nil { + appendKV(test.moreValues) + kvs = append(kvs, copySlice(kv), copySlice(kvs[0])) + } + if test.evenMoreValues != nil { + kv = copySlice(kvs[0]) + appendKV(test.evenMoreValues) + kvs = append(kvs, copySlice(kv)) + } + for _, kv := range kvs { + if len(test.values) > 0 { + kv = append(kv, test.values...) + } + text := test.text + if len(test.withNames) > 0 { + text = strings.Join(test.withNames, "/") + ": " + text + } + if test.withHelper { + klogHelper(text, kv) + } else if test.err != nil { + klog.ErrorS(test.err, text, kv...) + } else { + klog.V(klog.Level(test.v)).InfoS(text, kv...) + } + } + } + _, _, printWithKlogLine, _ := runtime.Caller(0) + + testOutput := func(t *testing.T, expectedLine int, print func(buffer *bytes.Buffer)) { + var tmpWriteBuffer bytes.Buffer + klog.SetOutput(&tmpWriteBuffer) + print(&tmpWriteBuffer) + klog.Flush() + + actual := tmpWriteBuffer.String() + // Strip varying header. + re := `(?m)^(.).... ..:..:......... ....... output.go` + actual = regexp.MustCompile(re).ReplaceAllString(actual, `${1} output.go`) + + // Inject expected line. This matches the if checks above, which are + // the same for both printWithKlog and printWithLogger. + callLine := expectedLine + if test.withHelper { + callLine -= 8 + } else if test.err != nil { + callLine -= 6 + } else { + callLine -= 4 + } + expected := test.expectedOutput + if repl, ok := config.ExpectedOutputMapping[expected]; ok { + expected = repl + } + 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 config.NewLogger == nil { + // Test klog. + testOutput(t, printWithKlogLine, func(buffer *bytes.Buffer) { + printWithKlog() + }) + return + } + + if config.AsBackend { + testOutput(t, printWithKlogLine, func(buffer *bytes.Buffer) { + klog.SetLogger(config.NewLogger(buffer, 10, "")) + defer klog.ClearLogger() + printWithKlog() + }) + return + } + + if test.vmodule != "" && !config.SupportsVModule { + t.Skip("vmodule not supported") + } + + testOutput(t, printWithLoggerLine, func(buffer *bytes.Buffer) { + printWithLogger(config.NewLogger(buffer, 10, test.vmodule)) + }) + }) + } +} + +func copySlice(in []interface{}) []interface{} { + return append([]interface{}{}, in...) +} + +type kmeta struct { + Name, Namespace string +} + +func (k kmeta) GetName() string { + return k.Name +} + +func (k kmeta) GetNamespace() string { + return k.Namespace +} + +var _ klog.KMetadata = kmeta{} + +type customErrorJSON struct { + s string +} + +var _ error = &customErrorJSON{} +var _ json.Marshaler = &customErrorJSON{} + +func (e *customErrorJSON) Error() string { + return e.s +} + +func (e *customErrorJSON) MarshalJSON() ([]byte, error) { + return json.Marshal(strings.ToUpper(e.s)) +} diff --git a/test/output_helper.go b/test/output_helper.go new file mode 100644 index 000000000..499395e38 --- /dev/null +++ b/test/output_helper.go @@ -0,0 +1,32 @@ +/* +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 ( + "github.com/go-logr/logr" + + "k8s.io/klog/v2" +) + +func loggerHelper(logger logr.Logger, msg string, kv []interface{}) { + logger = logger.WithCallDepth(1) + logger.Info(msg, kv...) +} + +func klogHelper(msg string, kv []interface{}) { + klog.InfoSDepth(1, msg, kv...) +} diff --git a/test/output_test.go b/test/output_test.go new file mode 100644 index 000000000..9b3161761 --- /dev/null +++ b/test/output_test.go @@ -0,0 +1,62 @@ +/* +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" +) + +func init() { + InitKlog() +} + +// TestKlogOutput tests klog output without a logger. +func TestKlogOutput(t *testing.T) { + Output(t, OutputConfig{}) +} + +// TestKlogrOutput tests klogr output via klog. +func TestKlogrOutput(t *testing.T) { + // klogr currently doesn't produce exactly the same output as klog. + // TODO: fix that. + mapping := map[string]string{ + `I output.go:] "test" keyWithoutValue="(MISSING)" +I output.go:] "test" keyWithoutValue="(MISSING)" anotherKeyWithoutValue="(MISSING)" +I output.go:] "test" keyWithoutValue="(MISSING)" +`: `I output.go:] "test" keyWithoutValue= +I output.go:] "test" keyWithoutValue="anotherKeyWithoutValue" +I output.go:] "test" keyWithoutValue= +`, + `I output.go:] "test" akey="avalue" akey2="(MISSING)" +`: `I output.go:] "test" akey="avalue" akey2= +`, + `I output.go:] "test" basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)" +`: `I output.go:] "test" basekey1="basevar1" basekey2= akey="avalue" akey2= +`, + } + Output(t, OutputConfig{ + NewLogger: func(out io.Writer, v int, vmodule string) logr.Logger { + return klogr.NewWithOptions(klogr.WithFormat(klogr.FormatKlog)) + }, + ExpectedOutputMapping: mapping, + }) +}