diff --git a/examples/output_test/output_test.go b/examples/output_test/output_test.go index 697dc459..872612f7 100644 --- a/examples/output_test/output_test.go +++ b/examples/output_test/output_test.go @@ -34,12 +34,13 @@ import ( "k8s.io/klog/v2/textlogger" ) +func newLogger(out io.Writer, v int, vmodule string) logr.Logger { + return newZaprLogger(out, v) +} + // TestZaprOutput tests the zapr, directly and as backend. func TestZaprOutput(t *testing.T) { test.InitKlog(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()}) }) @@ -48,6 +49,12 @@ func TestZaprOutput(t *testing.T) { }) } +// Benchmark direct zapr output. +func BenchmarkZaprOutput(b *testing.B) { + test.InitKlog(b) + test.Benchmark(b, test.OutputConfig{NewLogger: newLogger, ExpectedOutputMapping: test.ZaprOutputMappingDirect()}) +} + // TestKlogrStackText tests klogr.klogr -> klog -> text logger. func TestKlogrStackText(t *testing.T) { test.InitKlog(t) diff --git a/output_test.go b/output_test.go index 7e38e12c..c5434d60 100644 --- a/output_test.go +++ b/output_test.go @@ -26,18 +26,27 @@ import ( "k8s.io/klog/v2/test" ) -// TestKlogOutput tests klog output without a logger. +// klogConfig tests klog output without a logger. +var klogConfig = test.OutputConfig{} + func TestKlogOutput(t *testing.T) { test.InitKlog(t) - test.Output(t, test.OutputConfig{}) + test.Output(t, klogConfig) +} + +func BenchmarkKlogOutput(b *testing.B) { + test.InitKlog(b) + test.Benchmark(b, klogConfig) +} + +// klogKlogrConfig tests klogr output via klog, using the klog/v2 klogr. +var klogKLogrConfig = test.OutputConfig{ + NewLogger: func(out io.Writer, v int, vmodule string) logr.Logger { + return klog.NewKlogr() + }, } -// TestKlogKlogrOutput tests klogr output via klog, using the klog/v2 klogr. func TestKlogrOutput(t *testing.T) { test.InitKlog(t) - test.Output(t, test.OutputConfig{ - NewLogger: func(out io.Writer, v int, vmodule string) logr.Logger { - return klog.NewKlogr() - }, - }) + test.Output(t, klogKLogrConfig) } diff --git a/test/output.go b/test/output.go index 1b79a945..16553f2b 100644 --- a/test/output.go +++ b/test/output.go @@ -108,6 +108,389 @@ type OutputConfig struct { SupportsVModule bool } +type testcase 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 +} + +var tests = map[string]testcase{ + "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: "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": { + 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" +`, + }, + "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: "odd arguments", + values: []interface{}{"akey", "avalue", "akey2"}, + expectedOutput: `I output.go:] "odd arguments" 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: "both odd", + values: []interface{}{"akey", "avalue", "akey2"}, + expectedOutput: `I output.go:] "both odd" 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] +`, + }, + "KObjSlice okay": { + text: "test", + values: []interface{}{"pods", + klog.KObjSlice([]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]" +`, + }, + "KObjSlice nil arg": { + text: "test", + values: []interface{}{"pods", + klog.KObjSlice(nil)}, + expectedOutput: `I output.go:] "test" pods="[]" +`, + }, + "KObjSlice int arg": { + text: "test", + values: []interface{}{"pods", + klog.KObjSlice(1)}, + expectedOutput: `I output.go:] "test" pods="" +`, + }, + "KObjSlice nil entry": { + text: "test", + values: []interface{}{"pods", + klog.KObjSlice([]interface{}{ + &kmeta{Name: "pod-1", Namespace: "kube-system"}, + nil, + })}, + expectedOutput: `I output.go:] "test" pods="[kube-system/pod-1 ]" +`, + }, + "KObjSlice ints": { + text: "test", + values: []interface{}{"ints", + klog.KObjSlice([]int{1, 2, 3})}, + expectedOutput: `I output.go:] "test" ints="" +`, + }, + "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" +`, + }, + "Error() for nil": { + text: "error nil", + err: (*customErrorJSON)(nil), + expectedOutput: `E output.go:] "error nil" err="" +`, + }, + "String() for nil": { + text: "stringer nil", + values: []interface{}{"stringer", (*stringer)(nil)}, + expectedOutput: `I output.go:] "stringer nil" stringer="" +`, + }, + "MarshalLog() for nil": { + text: "marshaler nil", + values: []interface{}{"obj", (*klog.ObjectRef)(nil)}, + expectedOutput: `I output.go:] "marshaler nil" obj="" +`, + }, + "Error() that panics": { + text: "error panic", + err: faultyError{}, + expectedOutput: `E output.go:] "error panic" err="" +`, + }, + "String() that panics": { + text: "stringer panic", + values: []interface{}{"stringer", faultyStringer{}}, + expectedOutput: `I output.go:] "stringer panic" stringer="" +`, + }, + "MarshalLog() that panics": { + text: "marshaler panic", + values: []interface{}{"obj", faultyMarshaler{}}, + expectedOutput: `I output.go:] "marshaler panic" obj="" +`, + }, + "MarshalLog() that returns itself": { + text: "marshaler recursion", + values: []interface{}{"obj", recursiveMarshaler{}}, + expectedOutput: `I output.go:] "marshaler recursion" obj={} +`, + }, + "handle integer keys": { + withValues: []interface{}{1, "value", 2, "value2"}, + text: "integer keys", + values: []interface{}{"akey", "avalue", "akey2"}, + expectedOutput: `I output.go:] "integer keys" %!s(int=1)="value" %!s(int=2)="value2" akey="avalue" akey2="(MISSING)" +`, + }, + "struct keys": { + withValues: []interface{}{struct{ name string }{"name"}, "value", "test", "other value"}, + text: "struct keys", + values: []interface{}{"key", "val"}, + expectedOutput: `I output.go:] "struct keys" {name}="value" test="other value" key="val" +`, + }, + "map keys": { + withValues: []interface{}{}, + text: "map keys", + values: []interface{}{map[string]bool{"test": true}, "test"}, + expectedOutput: `I output.go:] "map keys" map[test:%!s(bool=true)]="test" +`, + }, +} + +func printWithLogger(logger logr.Logger, test testcase) { + 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...) // + } + } +} + +var _, _, printWithLoggerLine, _ = runtime.Caller(0) // anchor for finding the line numbers above + +func initPrintWithKlog(tb testing.TB, test testcase) { + if test.withHelper && test.vmodule != "" { + tb.Skip("klog does not support -vmodule properly when using helper functions") + } + + state := klog.CaptureState() + tb.Cleanup(state.Restore) + + var fs flag.FlagSet + klog.InitFlags(&fs) + if err := fs.Set("v", "10"); err != nil { + tb.Fatalf("unexpected error: %v", err) + } + if err := fs.Set("vmodule", test.vmodule); err != nil { + tb.Fatalf("unexpected error: %v", err) + } +} + +func printWithKlog(test testcase) { + 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...) + } + } +} + +var _, _, printWithKlogLine, _ = runtime.Caller(0) // anchor for finding the line numbers above + // Output covers various special cases of emitting log output. // It can be used for arbitrary logr.Logger implementations. // @@ -125,370 +508,10 @@ type OutputConfig struct { // 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: "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": { - 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" -`, - }, - "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: "odd arguments", - values: []interface{}{"akey", "avalue", "akey2"}, - expectedOutput: `I output.go:] "odd arguments" 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: "both odd", - values: []interface{}{"akey", "avalue", "akey2"}, - expectedOutput: `I output.go:] "both odd" 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] -`, - }, - "KObjSlice okay": { - text: "test", - values: []interface{}{"pods", - klog.KObjSlice([]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]" -`, - }, - "KObjSlice nil arg": { - text: "test", - values: []interface{}{"pods", - klog.KObjSlice(nil)}, - expectedOutput: `I output.go:] "test" pods="[]" -`, - }, - "KObjSlice int arg": { - text: "test", - values: []interface{}{"pods", - klog.KObjSlice(1)}, - expectedOutput: `I output.go:] "test" pods="" -`, - }, - "KObjSlice nil entry": { - text: "test", - values: []interface{}{"pods", - klog.KObjSlice([]interface{}{ - &kmeta{Name: "pod-1", Namespace: "kube-system"}, - nil, - })}, - expectedOutput: `I output.go:] "test" pods="[kube-system/pod-1 ]" -`, - }, - "KObjSlice ints": { - text: "test", - values: []interface{}{"ints", - klog.KObjSlice([]int{1, 2, 3})}, - expectedOutput: `I output.go:] "test" ints="" -`, - }, - "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" -`, - }, - "Error() for nil": { - text: "error nil", - err: (*customErrorJSON)(nil), - expectedOutput: `E output.go:] "error nil" err="" -`, - }, - "String() for nil": { - text: "stringer nil", - values: []interface{}{"stringer", (*stringer)(nil)}, - expectedOutput: `I output.go:] "stringer nil" stringer="" -`, - }, - "MarshalLog() for nil": { - text: "marshaler nil", - values: []interface{}{"obj", (*klog.ObjectRef)(nil)}, - expectedOutput: `I output.go:] "marshaler nil" obj="" -`, - }, - "Error() that panics": { - text: "error panic", - err: faultyError{}, - expectedOutput: `E output.go:] "error panic" err="" -`, - }, - "String() that panics": { - text: "stringer panic", - values: []interface{}{"stringer", faultyStringer{}}, - expectedOutput: `I output.go:] "stringer panic" stringer="" -`, - }, - "MarshalLog() that panics": { - text: "marshaler panic", - values: []interface{}{"obj", faultyMarshaler{}}, - expectedOutput: `I output.go:] "marshaler panic" obj="" -`, - }, - "MarshalLog() that returns itself": { - text: "marshaler recursion", - values: []interface{}{"obj", recursiveMarshaler{}}, - expectedOutput: `I output.go:] "marshaler recursion" obj={} -`, - }, - "handle integer keys": { - withValues: []interface{}{1, "value", 2, "value2"}, - text: "integer keys", - values: []interface{}{"akey", "avalue", "akey2"}, - expectedOutput: `I output.go:] "integer keys" %!s(int=1)="value" %!s(int=2)="value2" akey="avalue" akey2="(MISSING)" -`, - }, - "struct keys": { - withValues: []interface{}{struct{ name string }{"name"}, "value", "test", "other value"}, - text: "struct keys", - values: []interface{}{"key", "val"}, - expectedOutput: `I output.go:] "struct keys" {name}="value" test="other value" key="val" -`, - }, - "map keys": { - withValues: []interface{}{}, - text: "map keys", - values: []interface{}{map[string]bool{"test": true}, "test"}, - expectedOutput: `I output.go:] "map keys" map[test:%!s(bool=true)]="test" -`, - }, - } 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) - } - // 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) @@ -530,16 +553,16 @@ I output.go:] "test" firstKey=1 secondKey=3 if config.NewLogger == nil { // Test klog. - testOutput(t, printWithKlogLine, func(buffer *bytes.Buffer) { - printWithKlog() + testOutput(t, printWithKlogLine-1, func(buffer *bytes.Buffer) { + printWithKlog(test) }) return } if config.AsBackend { - testOutput(t, printWithKlogLine, func(buffer *bytes.Buffer) { + testOutput(t, printWithKlogLine-1, func(buffer *bytes.Buffer) { klog.SetLogger(config.NewLogger(buffer, 10, "")) - printWithKlog() + printWithKlog(test) }) return } @@ -548,8 +571,8 @@ I output.go:] "test" firstKey=1 secondKey=3 t.Skip("vmodule not supported") } - testOutput(t, printWithLoggerLine, func(buffer *bytes.Buffer) { - printWithLogger(config.NewLogger(buffer, 10, test.vmodule)) + testOutput(t, printWithLoggerLine-1, func(buffer *bytes.Buffer) { + printWithLogger(config.NewLogger(buffer, 10, test.vmodule), test) }) }) } @@ -783,6 +806,55 @@ I output.go:] "test" firstKey=1 secondKey=3 } } +// Benchmark covers various special cases of emitting log output. +// It can be used for arbitrary logr.Logger implementations. +// +// 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 Benchmark(b *testing.B, config OutputConfig) { + for n, test := range tests { + b.Run(n, func(b *testing.B) { + state := klog.CaptureState() + defer state.Restore() + klog.SetOutput(io.Discard) + initPrintWithKlog(b, test) + b.ResetTimer() + + if config.NewLogger == nil { + // Test klog. + for i := 0; i < b.N; i++ { + printWithKlog(test) + } + return + } + + if config.AsBackend { + klog.SetLogger(config.NewLogger(io.Discard, 10, "")) + for i := 0; i < b.N; i++ { + printWithKlog(test) + } + return + } + + if test.vmodule != "" && !config.SupportsVModule { + b.Skip("vmodule not supported") + } + + logger := config.NewLogger(io.Discard, 10, test.vmodule) + b.ResetTimer() + for i := 0; i < b.N; i++ { + printWithLogger(logger, test) + } + }) + } +} + func copySlice(in []interface{}) []interface{} { return append([]interface{}{}, in...) } diff --git a/textlogger/output_test.go b/textlogger/output_test.go index 9a3bc95e..9aeb0bc2 100644 --- a/textlogger/output_test.go +++ b/textlogger/output_test.go @@ -26,23 +26,34 @@ import ( "k8s.io/klog/v2/textlogger" ) -// TestTextloggerOutput tests the textlogger, directly and as backend. +// These test cover the textlogger, directly and as backend. +func newLogger(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) +} + +var ( + directConfig = test.OutputConfig{NewLogger: newLogger, SupportsVModule: true} + indirectConfig = test.OutputConfig{NewLogger: newLogger, AsBackend: true} +) + func TestTextloggerOutput(t *testing.T) { test.InitKlog(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}) + test.Output(t, directConfig) }) t.Run("klog-backend", func(t *testing.T) { - test.Output(t, test.OutputConfig{NewLogger: newLogger, AsBackend: true}) + test.Output(t, indirectConfig) }) } + +func BenchmarkTextloggerOutput(b *testing.B) { + test.InitKlog(b) + test.Benchmark(b, directConfig) +}