From f6e8786fdfc8090197c89a1b004ba70e42787f0a Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Mon, 16 Jan 2023 10:58:02 +0100 Subject: [PATCH 01/14] klogr: avoid calling Info/Error/Enabled through auto-generated code These functions get called for a pointer because that is what we use to implement the LogSink interface. The variant of these functions which take a value instead of a pointer was never used, so providing directly what is needed instead of relying on the compiler to generate that is more efficient (less code, avoids one extra callstack entry at runtime). The With* functions must continue to take a value because they need to modify that copy. --- klogr.go | 6 +++--- klogr/klogr.go | 6 +++--- 2 files changed, 6 insertions(+), 6 deletions(-) diff --git a/klogr.go b/klogr.go index 027a4014a..f0d3566ad 100644 --- a/klogr.go +++ b/klogr.go @@ -42,7 +42,7 @@ func (l *klogger) Init(info logr.RuntimeInfo) { l.callDepth += info.CallDepth } -func (l klogger) Info(level int, msg string, kvList ...interface{}) { +func (l *klogger) Info(level int, msg string, kvList ...interface{}) { merged := serialize.MergeKVs(l.values, kvList) if l.prefix != "" { msg = l.prefix + ": " + msg @@ -50,11 +50,11 @@ func (l klogger) Info(level int, msg string, kvList ...interface{}) { V(Level(level)).InfoSDepth(l.callDepth+1, msg, merged...) } -func (l klogger) Enabled(level int) bool { +func (l *klogger) Enabled(level int) bool { return V(Level(level)).Enabled() } -func (l klogger) Error(err error, msg string, kvList ...interface{}) { +func (l *klogger) Error(err error, msg string, kvList ...interface{}) { merged := serialize.MergeKVs(l.values, kvList) if l.prefix != "" { msg = l.prefix + ": " + msg diff --git a/klogr/klogr.go b/klogr/klogr.go index c94e551ed..c56a46194 100644 --- a/klogr/klogr.go +++ b/klogr/klogr.go @@ -119,7 +119,7 @@ func pretty(value interface{}) string { return strings.TrimSpace(string(buffer.Bytes())) } -func (l klogger) Info(level int, msg string, kvList ...interface{}) { +func (l *klogger) Info(level int, msg string, kvList ...interface{}) { switch l.format { case FormatSerialize: msgStr := flatten("msg", msg) @@ -135,11 +135,11 @@ func (l klogger) Info(level int, msg string, kvList ...interface{}) { } } -func (l klogger) Enabled(level int) bool { +func (l *klogger) Enabled(level int) bool { return klog.V(klog.Level(level)).Enabled() } -func (l klogger) Error(err error, msg string, kvList ...interface{}) { +func (l *klogger) Error(err error, msg string, kvList ...interface{}) { msgStr := flatten("msg", msg) var loggableErr interface{} if err != nil { From e23e29ecda0e5e033a5ee3e011344985926a051b Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Fri, 25 Nov 2022 10:01:48 +0100 Subject: [PATCH 02/14] test: move InitKlog into tests This makes it possible to use test.Output inside packages that have other tests. --- examples/output_test/output_test.go | 12 ++++++---- test/output.go | 34 +++++++++++++++++++++-------- 2 files changed, 33 insertions(+), 13 deletions(-) diff --git a/examples/output_test/output_test.go b/examples/output_test/output_test.go index ac10f92f8..bd4e4787f 100644 --- a/examples/output_test/output_test.go +++ b/examples/output_test/output_test.go @@ -34,17 +34,15 @@ import ( "k8s.io/klog/v2/textlogger" ) -func init() { - test.InitKlog() -} - // TestKlogOutput tests klog output without a logger. func TestKlogOutput(t *testing.T) { + test.InitKlog(t) test.Output(t, test.OutputConfig{}) } // TestTextloggerOutput tests the textlogger, directly and as backend. 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), @@ -65,6 +63,7 @@ func TestTextloggerOutput(t *testing.T) { // 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) } @@ -78,6 +77,7 @@ func TestZaprOutput(t *testing.T) { // TestKlogrOutput tests klogr output via klog. 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 klogr.NewWithOptions(klogr.WithFormat(klogr.FormatKlog)) @@ -87,6 +87,7 @@ func TestKlogrOutput(t *testing.T) { // TestKlogrStackText tests klogr.klogr -> klog -> text logger. func TestKlogrStackText(t *testing.T) { + test.InitKlog(t) newLogger := func(out io.Writer, v int, vmodule string) logr.Logger { // Backend: text output. config := textlogger.NewConfig( @@ -110,6 +111,7 @@ func TestKlogrStackText(t *testing.T) { // (https://github.com/kubernetes/klog/issues/294) because klogr logging // records that. func TestKlogrStackZapr(t *testing.T) { + test.InitKlog(t) mapping := test.ZaprOutputMappingIndirect() // klogr doesn't warn about invalid KVs and just inserts @@ -150,6 +152,7 @@ func TestKlogrStackZapr(t *testing.T) { // TestKlogrInternalStackText tests klog.klogr (the simplified version used for contextual logging) -> klog -> text logger. func TestKlogrInternalStackText(t *testing.T) { + test.InitKlog(t) newLogger := func(out io.Writer, v int, vmodule string) logr.Logger { // Backend: text output. config := textlogger.NewConfig( @@ -173,6 +176,7 @@ func TestKlogrInternalStackText(t *testing.T) { // (https://github.com/kubernetes/klog/issues/294) because klogr logging // records that. func TestKlogrInternalStackZapr(t *testing.T) { + test.InitKlog(t) mapping := test.ZaprOutputMappingIndirect() // klogr doesn't warn about invalid KVs and just inserts diff --git a/test/output.go b/test/output.go index 5b80ebcdf..1b79a945e 100644 --- a/test/output.go +++ b/test/output.go @@ -41,22 +41,38 @@ import ( "k8s.io/klog/v2" ) -// InitKlog must be called once in an init function of a test package to -// configure klog for testing with Output. +// InitKlog must be called in a test to configure klog for testing. +// The previous klog configuration will be restored automatically +// after the test. +// +// The returned flag set has the klog flags registered. It can +// be used to make further changes to the klog configuration. // // # Experimental // // Notice: This function is EXPERIMENTAL and may be changed or removed in a // later release. -func InitKlog() { +func InitKlog(tb testing.TB) *flag.FlagSet { + state := klog.CaptureState() + tb.Cleanup(state.Restore) + + expectNoError := func(err error) { + if err != nil { + tb.Fatalf("unexpected error: %v", err) + } + } + // 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") + var fs flag.FlagSet + klog.InitFlags(&fs) + expectNoError(fs.Set("v", "10")) + expectNoError(fs.Set("log_file", "/dev/null")) + expectNoError(fs.Set("logtostderr", "false")) + expectNoError(fs.Set("alsologtostderr", "false")) + expectNoError(fs.Set("stderrthreshold", "10")) + + return &fs } // OutputConfig contains optional settings for Output. From 50cdc4aef6fd6d0cb960023c93766b15d691eeee Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Mon, 16 Jan 2023 11:01:40 +0100 Subject: [PATCH 03/14] klogr: fix vmodule support When klogr called V(), it didn't pass the callstack offset, which broke evaluation of the -vmodule patterns. A new VWithOffset klog API is needed to fix this. A unit test for this will follow. --- klog.go | 9 ++++++++- klogr.go | 6 ++++-- klogr/klogr.go | 7 ++++--- 3 files changed, 16 insertions(+), 6 deletions(-) diff --git a/klog.go b/klog.go index 1bd11b675..bcf60cf97 100644 --- a/klog.go +++ b/klog.go @@ -1313,6 +1313,13 @@ func newVerbose(level Level, b bool) Verbose { // less than or equal to the value of the -vmodule pattern matching the source file // containing the call. func V(level Level) Verbose { + return VDepth(1, level) +} + +// VDepth is a variant of V that accepts a number of stack frames that will be +// skipped when checking the -vmodule patterns. VDepth(0) is equivalent to +// V(). +func VDepth(depth int, level Level) Verbose { // This function tries hard to be cheap unless there's work to do. // The fast path is two atomic loads and compares. @@ -1329,7 +1336,7 @@ func V(level Level) Verbose { // but if V logging is enabled we're slow anyway. logging.mu.Lock() defer logging.mu.Unlock() - if runtime.Callers(2, logging.pcs[:]) == 0 { + if runtime.Callers(2+depth, logging.pcs[:]) == 0 { return newVerbose(level, false) } // runtime.Callers returns "return PCs", but we want diff --git a/klogr.go b/klogr.go index f0d3566ad..15de00e21 100644 --- a/klogr.go +++ b/klogr.go @@ -47,11 +47,13 @@ func (l *klogger) Info(level int, msg string, kvList ...interface{}) { if l.prefix != "" { msg = l.prefix + ": " + msg } - V(Level(level)).InfoSDepth(l.callDepth+1, msg, merged...) + // Skip this function. + VDepth(l.callDepth+1, Level(level)).InfoSDepth(l.callDepth+1, msg, merged...) } func (l *klogger) Enabled(level int) bool { - return V(Level(level)).Enabled() + // Skip this function and logr.Logger.Info where Enabled is called. + return VDepth(l.callDepth+2, Level(level)).Enabled() } func (l *klogger) Error(err error, msg string, kvList ...interface{}) { diff --git a/klogr/klogr.go b/klogr/klogr.go index c56a46194..db5b5c789 100644 --- a/klogr/klogr.go +++ b/klogr/klogr.go @@ -125,18 +125,19 @@ func (l *klogger) Info(level int, msg string, kvList ...interface{}) { msgStr := flatten("msg", msg) merged := serialize.MergeKVs(l.values, kvList) kvStr := flatten(merged...) - klog.V(klog.Level(level)).InfoDepth(l.callDepth+1, l.prefix, " ", msgStr, " ", kvStr) + klog.VDepth(l.callDepth+1, klog.Level(level)).InfoDepth(l.callDepth+1, l.prefix, " ", msgStr, " ", kvStr) case FormatKlog: merged := serialize.MergeKVs(l.values, kvList) if l.prefix != "" { msg = l.prefix + ": " + msg } - klog.V(klog.Level(level)).InfoSDepth(l.callDepth+1, msg, merged...) + klog.VDepth(l.callDepth+1, klog.Level(level)).InfoSDepth(l.callDepth+1, msg, merged...) } } func (l *klogger) Enabled(level int) bool { - return klog.V(klog.Level(level)).Enabled() + // Skip this function and logr.Logger.Info where Enabled is called. + return klog.VDepth(l.callDepth+2, klog.Level(level)).Enabled() } func (l *klogger) Error(err error, msg string, kvList ...interface{}) { From 676a553c1f374ccaea6cbab55d2b372964e4116c Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Fri, 25 Nov 2022 10:18:20 +0100 Subject: [PATCH 04/14] klogr: use test.InitKlog Besides sharing code, it's also better in two regards: - restores state after test - avoids triple printing of errors --- klogr/klogr_test.go | 16 +++------------- 1 file changed, 3 insertions(+), 13 deletions(-) diff --git a/klogr/klogr_test.go b/klogr/klogr_test.go index 22ec1dc30..53b9e450d 100644 --- a/klogr/klogr_test.go +++ b/klogr/klogr_test.go @@ -4,11 +4,11 @@ import ( "bytes" "encoding/json" "errors" - "flag" "strings" "testing" "k8s.io/klog/v2" + "k8s.io/klog/v2/test" "github.com/go-logr/logr" ) @@ -169,14 +169,9 @@ func testOutput(t *testing.T, format string) { klogr: new().V(0), text: "test", err: errors.New("whoops"), - // The message is printed to three different log files (info, warning, error), so we see it three times in our output buffer. expectedOutput: ` "msg"="test" "error"="whoops" - "msg"="test" "error"="whoops" - "msg"="test" "error"="whoops" `, expectedKlogOutput: `"test" err="whoops" -"test" err="whoops" -"test" err="whoops" `, }, } @@ -209,13 +204,8 @@ func testOutput(t *testing.T, format string) { } func TestOutput(t *testing.T) { - klog.InitFlags(nil) - flag.CommandLine.Set("v", "10") - flag.CommandLine.Set("skip_headers", "true") - flag.CommandLine.Set("logtostderr", "false") - flag.CommandLine.Set("alsologtostderr", "false") - flag.CommandLine.Set("stderrthreshold", "10") - flag.Parse() + fs := test.InitKlog(t) + fs.Set("skip_headers", "true") formats := []string{ formatNew, From c57c59c3ec11b127058d124d72327c51a91b496e Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Mon, 16 Jan 2023 11:01:40 +0100 Subject: [PATCH 05/14] textlogger: fix vmodule support When Logger.Info called Enabled, the wrong number of stack frames were skipped. A unit test for this will follow. --- textlogger/textlogger.go | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/textlogger/textlogger.go b/textlogger/textlogger.go index 17706d6da..3c6cda645 100644 --- a/textlogger/textlogger.go +++ b/textlogger/textlogger.go @@ -88,7 +88,9 @@ func (l *tlogger) WithCallDepth(depth int) logr.LogSink { } func (l *tlogger) Enabled(level int) bool { - return l.config.Enabled(verbosity.Level(level), 1) + // Skip this function and the Logger.Info call, then + // also any additional stack frames from WithCallDepth. + return l.config.Enabled(verbosity.Level(level), 2+l.callDepth) } func (l *tlogger) Info(level int, msg string, kvList ...interface{}) { From 723e7f46df5d160c3d20ed5a4f9f9e4570fd6973 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Fri, 25 Nov 2022 10:15:11 +0100 Subject: [PATCH 06/14] move output tests into packages Previously it was necessary to enter the "examples" module to run output tests for code in the main module. Now "go test ./..." at the root or in individual directories also runs these tests. --- examples/output_test/output_test.go | 37 ---------------------- klogr/output_test.go | 37 ++++++++++++++++++++++ output_test.go | 43 ++++++++++++++++++++++++++ textlogger/output_test.go | 48 +++++++++++++++++++++++++++++ 4 files changed, 128 insertions(+), 37 deletions(-) create mode 100644 klogr/output_test.go create mode 100644 output_test.go create mode 100644 textlogger/output_test.go diff --git a/examples/output_test/output_test.go b/examples/output_test/output_test.go index bd4e4787f..697dc459d 100644 --- a/examples/output_test/output_test.go +++ b/examples/output_test/output_test.go @@ -34,33 +34,6 @@ import ( "k8s.io/klog/v2/textlogger" ) -// TestKlogOutput tests klog output without a logger. -func TestKlogOutput(t *testing.T) { - test.InitKlog(t) - test.Output(t, test.OutputConfig{}) -} - -// TestTextloggerOutput tests the textlogger, directly and as backend. -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}) - }) - t.Run("klog-backend", func(t *testing.T) { - test.Output(t, test.OutputConfig{NewLogger: newLogger, AsBackend: true}) - }) -} - // TestZaprOutput tests the zapr, directly and as backend. func TestZaprOutput(t *testing.T) { test.InitKlog(t) @@ -75,16 +48,6 @@ func TestZaprOutput(t *testing.T) { }) } -// TestKlogrOutput tests klogr output via klog. -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 klogr.NewWithOptions(klogr.WithFormat(klogr.FormatKlog)) - }, - }) -} - // TestKlogrStackText tests klogr.klogr -> klog -> text logger. func TestKlogrStackText(t *testing.T) { test.InitKlog(t) diff --git a/klogr/output_test.go b/klogr/output_test.go new file mode 100644 index 000000000..aa87e9530 --- /dev/null +++ b/klogr/output_test.go @@ -0,0 +1,37 @@ +/* +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 klogr_test + +import ( + "io" + "testing" + + "github.com/go-logr/logr" + + "k8s.io/klog/v2/klogr" + "k8s.io/klog/v2/test" +) + +// TestKlogrOutput tests klogr output via klog. +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 klogr.NewWithOptions(klogr.WithFormat(klogr.FormatKlog)) + }, + }) +} diff --git a/output_test.go b/output_test.go new file mode 100644 index 000000000..7e38e12c3 --- /dev/null +++ b/output_test.go @@ -0,0 +1,43 @@ +/* +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 klog_test + +import ( + "io" + "testing" + + "github.com/go-logr/logr" + + "k8s.io/klog/v2" + "k8s.io/klog/v2/test" +) + +// TestKlogOutput tests klog output without a logger. +func TestKlogOutput(t *testing.T) { + test.InitKlog(t) + test.Output(t, test.OutputConfig{}) +} + +// 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() + }, + }) +} diff --git a/textlogger/output_test.go b/textlogger/output_test.go new file mode 100644 index 000000000..9a3bc95e3 --- /dev/null +++ b/textlogger/output_test.go @@ -0,0 +1,48 @@ +/* +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 textlogger_test + +import ( + "io" + "testing" + + "github.com/go-logr/logr" + + "k8s.io/klog/v2/test" + "k8s.io/klog/v2/textlogger" +) + +// TestTextloggerOutput tests the textlogger, directly and as backend. +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}) + }) + t.Run("klog-backend", func(t *testing.T) { + test.Output(t, test.OutputConfig{NewLogger: newLogger, AsBackend: true}) + }) +} From 8c600103520012be0def9a162c415460988d73f1 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Fri, 25 Nov 2022 10:43:20 +0100 Subject: [PATCH 07/14] use output test cases also for benchmarking So far, the output tests were only used for correctness checking. But they cover a variety of scenarios for which there were no benchmarks, therefore it makes sense to also use them for that. --- examples/output_test/output_test.go | 13 +- output_test.go | 25 +- test/output.go | 804 +++++++++++++++------------- textlogger/output_test.go | 37 +- 4 files changed, 489 insertions(+), 390 deletions(-) diff --git a/examples/output_test/output_test.go b/examples/output_test/output_test.go index 697dc459d..872612f72 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 7e38e12c3..c5434d600 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 1b79a945e..16553f2b4 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 9a3bc95e3..9aeb0bc27 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) +} From 4aa7aa6a7b9c8ee9dad77a83baf966d0f5eaf205 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Mon, 16 Jan 2023 11:25:47 +0100 Subject: [PATCH 08/14] test: unit tests for vmodule support Text logger and the two klogr implementations both got this wrong. --- test/output.go | 24 ++++++++++++++++++++---- test/output_helper.go | 4 ++-- test/zapr.go | 5 +++++ 3 files changed, 27 insertions(+), 6 deletions(-) diff --git a/test/output.go b/test/output.go index 16553f2b4..bfd026c2f 100644 --- a/test/output.go +++ b/test/output.go @@ -153,12 +153,28 @@ var tests = map[string]testcase{ text: "v=11: you see me because of -vmodule output=11", v: 11, vmodule: "output=11", + expectedOutput: `I output.go:] "v=11: you see me because of -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", }, + "vmodule with helper": { + text: "v=11: you see me because of -vmodule output=11", + withHelper: true, + v: 11, + vmodule: "output=11", + expectedOutput: `I output.go:] "v=11: you see me because of -vmodule output=11" +`, + }, + "other vmodule with helper": { + text: "v=11: you still don't see me because of -vmodule output_helper=11", + withHelper: true, + v: 11, + vmodule: "output_helper=11", + }, "log with name and values": { withNames: []string{"me"}, text: "test", @@ -410,7 +426,7 @@ func printWithLogger(logger logr.Logger, test testcase) { } for _, logger := range loggers { if test.withHelper { - loggerHelper(logger, test.text, test.values) // + loggerHelper(logger.V(test.v), test.text, test.values) // } else if test.err != nil { logger.Error(test.err, test.text, test.values...) // } else { @@ -480,7 +496,7 @@ func printWithKlog(test testcase) { text = strings.Join(test.withNames, "/") + ": " + text } if test.withHelper { - klogHelper(text, kv) + klogHelper(klog.Level(test.v), text, kv) } else if test.err != nil { klog.ErrorS(test.err, text, kv...) } else { @@ -510,7 +526,7 @@ var _, _, printWithKlogLine, _ = runtime.Caller(0) // anchor for finding the lin func Output(t *testing.T, config OutputConfig) { for n, test := range tests { t.Run(n, func(t *testing.T) { - defer klog.ClearLogger() + initPrintWithKlog(t, test) testOutput := func(t *testing.T, expectedLine int, print func(buffer *bytes.Buffer)) { var tmpWriteBuffer bytes.Buffer @@ -561,7 +577,7 @@ func Output(t *testing.T, config OutputConfig) { if config.AsBackend { testOutput(t, printWithKlogLine-1, func(buffer *bytes.Buffer) { - klog.SetLogger(config.NewLogger(buffer, 10, "")) + klog.SetLogger(config.NewLogger(buffer, 10, test.vmodule)) printWithKlog(test) }) return diff --git a/test/output_helper.go b/test/output_helper.go index 499395e38..58b7348f9 100644 --- a/test/output_helper.go +++ b/test/output_helper.go @@ -27,6 +27,6 @@ func loggerHelper(logger logr.Logger, msg string, kv []interface{}) { logger.Info(msg, kv...) } -func klogHelper(msg string, kv []interface{}) { - klog.InfoSDepth(1, msg, kv...) +func klogHelper(level klog.Level, msg string, kv []interface{}) { + klog.V(level).InfoSDepth(1, msg, kv...) } diff --git a/test/zapr.go b/test/zapr.go index 9f6cd8b4c..48cf2c3da 100644 --- a/test/zapr.go +++ b/test/zapr.go @@ -319,6 +319,11 @@ I output.go:] "test" firstKey=1 secondKey=3 `: `{"caller":"test/output.go:","msg":"non-string key argument passed to logging, ignoring all later arguments","invalid key":{"test":true}} {"caller":"test/output.go:","msg":"map keys","v":0} `, + + // zapr does not support vmodule checks and thus always + // discards these messages. + `I output.go:] "v=11: you see me because of -vmodule output=11" +`: ``, } { mapping[key] = value } From 718ea4546fda4471f1c824bec5a9001d969669a8 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Fri, 25 Nov 2022 12:43:34 +0100 Subject: [PATCH 09/14] buffer: use sync.Pool MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit This simplifies the code. Instead of different instances, the package now maintains a global pool. This makes the text logger struct a bit smaller and thus cheaper to copy in the With* functions. Performance is about the same as before: name old time/op new time/op delta Header-36 1.68µs ± 7% 1.62µs ± 6% ~ (p=0.246 n=5+5) HeaderWithDir-36 1.63µs ± 6% 1.59µs ± 6% ~ (p=0.690 n=5+5) name old alloc/op new alloc/op delta Header-36 216B ± 0% 216B ± 0% ~ (all equal) HeaderWithDir-36 216B ± 0% 216B ± 0% ~ (all equal) name old allocs/op new allocs/op delta Header-36 2.00 ± 0% 2.00 ± 0% ~ (all equal) HeaderWithDir-36 2.00 ± 0% 2.00 ± 0% ~ (all equal) The text logger didn't actually return the buffer. Now it does. --- internal/buffer/buffer.go | 40 +++++++++------------------------------ klog.go | 29 ++++++++++++---------------- klog_test.go | 4 ++-- textlogger/textlogger.go | 19 +++++++++---------- 4 files changed, 32 insertions(+), 60 deletions(-) diff --git a/internal/buffer/buffer.go b/internal/buffer/buffer.go index ac88682a2..d53b49da3 100644 --- a/internal/buffer/buffer.go +++ b/internal/buffer/buffer.go @@ -40,44 +40,22 @@ type Buffer struct { next *Buffer } -// Buffers manages the reuse of individual buffer instances. It is thread-safe. -type Buffers struct { - // mu protects the free list. It is separate from the main mutex - // so buffers can be grabbed and printed to without holding the main lock, - // for better parallelization. - mu sync.Mutex - - // freeList is a list of byte buffers, maintained under mu. - freeList *Buffer +var buffers = sync.Pool{ + New: func() interface{} { + return new(Buffer) + }, } // GetBuffer returns a new, ready-to-use buffer. -func (bl *Buffers) GetBuffer() *Buffer { - bl.mu.Lock() - b := bl.freeList - if b != nil { - bl.freeList = b.next - } - bl.mu.Unlock() - if b == nil { - b = new(Buffer) - } else { - b.next = nil - b.Reset() - } +func GetBuffer() *Buffer { + b := buffers.Get().(*Buffer) + b.Reset() return b } // PutBuffer returns a buffer to the free list. -func (bl *Buffers) PutBuffer(b *Buffer) { - if b.Len() >= 256 { - // Let big buffers die a natural death. - return - } - bl.mu.Lock() - b.next = bl.freeList - bl.freeList = b - bl.mu.Unlock() +func PutBuffer(b *Buffer) { + buffers.Put(b) } // Some custom tiny helper functions to print the log header efficiently. diff --git a/klog.go b/klog.go index bcf60cf97..c5d98ad38 100644 --- a/klog.go +++ b/klog.go @@ -532,11 +532,6 @@ func (s settings) deepCopy() settings { type loggingT struct { settings - // bufferCache maintains the free list. It uses its own mutex - // so buffers can be grabbed and printed to without holding the main lock, - // for better parallelization. - bufferCache buffer.Buffers - // flushD holds a flushDaemon that frequently flushes log file buffers. // Uses its own mutex. flushD *flushDaemon @@ -664,7 +659,7 @@ func (l *loggingT) header(s severity.Severity, depth int) (*buffer.Buffer, strin // formatHeader formats a log header using the provided file name and line number. func (l *loggingT) formatHeader(s severity.Severity, file string, line int) *buffer.Buffer { - buf := l.bufferCache.GetBuffer() + buf := buffer.GetBuffer() if l.skipHeaders { return buf } @@ -682,8 +677,8 @@ func (l *loggingT) printlnDepth(s severity.Severity, logger *logr.Logger, filter // if logger is set, we clear the generated header as we rely on the backing // logger implementation to print headers if logger != nil { - l.bufferCache.PutBuffer(buf) - buf = l.bufferCache.GetBuffer() + buffer.PutBuffer(buf) + buf = buffer.GetBuffer() } if filter != nil { args = filter.Filter(args) @@ -701,8 +696,8 @@ func (l *loggingT) printDepth(s severity.Severity, logger *logr.Logger, filter L // if logr is set, we clear the generated header as we rely on the backing // logr implementation to print headers if logger != nil { - l.bufferCache.PutBuffer(buf) - buf = l.bufferCache.GetBuffer() + buffer.PutBuffer(buf) + buf = buffer.GetBuffer() } if filter != nil { args = filter.Filter(args) @@ -723,8 +718,8 @@ func (l *loggingT) printfDepth(s severity.Severity, logger *logr.Logger, filter // if logr is set, we clear the generated header as we rely on the backing // logr implementation to print headers if logger != nil { - l.bufferCache.PutBuffer(buf) - buf = l.bufferCache.GetBuffer() + buffer.PutBuffer(buf) + buf = buffer.GetBuffer() } if filter != nil { format, args = filter.FilterF(format, args) @@ -744,8 +739,8 @@ func (l *loggingT) printWithFileLine(s severity.Severity, logger *logr.Logger, f // if logr is set, we clear the generated header as we rely on the backing // logr implementation to print headers if logger != nil { - l.bufferCache.PutBuffer(buf) - buf = l.bufferCache.GetBuffer() + buffer.PutBuffer(buf) + buf = buffer.GetBuffer() } if filter != nil { args = filter.Filter(args) @@ -785,7 +780,7 @@ func (l *loggingT) infoS(logger *logr.Logger, filter LogFilter, depth int, msg s // set log severity by s func (l *loggingT) printS(err error, s severity.Severity, depth int, msg string, keysAndValues ...interface{}) { // Only create a new buffer if we don't have one cached. - b := l.bufferCache.GetBuffer() + b := buffer.GetBuffer() // The message is always quoted, even if it contains line breaks. // If developers want multi-line output, they should use a small, fixed // message and put the multi-line output into a value. @@ -796,7 +791,7 @@ func (l *loggingT) printS(err error, s severity.Severity, depth int, msg string, serialize.KVListFormat(&b.Buffer, keysAndValues...) l.printDepth(s, logging.logger, nil, depth+1, &b.Buffer) // Make the buffer available for reuse. - l.bufferCache.PutBuffer(b) + buffer.PutBuffer(b) } // redirectBuffer is used to set an alternate destination for the logs @@ -948,7 +943,7 @@ func (l *loggingT) output(s severity.Severity, log *logr.Logger, buf *buffer.Buf timeoutFlush(ExitFlushTimeout) OsExit(255) // C++ uses -1, which is silly because it's anded with 255 anyway. } - l.bufferCache.PutBuffer(buf) + buffer.PutBuffer(buf) if stats := severityStats[s]; stats != nil { atomic.AddInt64(&stats.lines, 1) diff --git a/klog_test.go b/klog_test.go index e6e8922cc..96f337ac5 100644 --- a/klog_test.go +++ b/klog_test.go @@ -623,7 +623,7 @@ func TestLogBacktraceAt(t *testing.T) { func BenchmarkHeader(b *testing.B) { for i := 0; i < b.N; i++ { buf, _, _ := logging.header(severity.InfoLog, 0) - logging.bufferCache.PutBuffer(buf) + buffer.PutBuffer(buf) } } @@ -631,7 +631,7 @@ func BenchmarkHeaderWithDir(b *testing.B) { logging.addDirHeader = true for i := 0; i < b.N; i++ { buf, _, _ := logging.header(severity.InfoLog, 0) - logging.bufferCache.PutBuffer(buf) + buffer.PutBuffer(buf) } } diff --git a/textlogger/textlogger.go b/textlogger/textlogger.go index 3c6cda645..360888cc8 100644 --- a/textlogger/textlogger.go +++ b/textlogger/textlogger.go @@ -56,19 +56,17 @@ var ( // later release. The behavior of the returned Logger may change. func NewLogger(c *Config) logr.Logger { return logr.New(&tlogger{ - prefix: "", - values: nil, - config: c, - bufferCache: &buffer.Buffers{}, + prefix: "", + values: nil, + config: c, }) } type tlogger struct { - callDepth int - prefix string - values []interface{} - config *Config - bufferCache *buffer.Buffers + callDepth int + prefix string + values []interface{} + config *Config } func copySlice(in []interface{}) []interface{} { @@ -103,7 +101,8 @@ func (l *tlogger) Error(err error, msg string, kvList ...interface{}) { func (l *tlogger) print(err error, s severity.Severity, msg string, kvList []interface{}) { // Only create a new buffer if we don't have one cached. - b := l.bufferCache.GetBuffer() + b := buffer.GetBuffer() + defer buffer.PutBuffer(b) // Determine caller. // +1 for this frame, +1 for Info/Error. From 1c00d46b28fca5f5cf9329630f39979d2f09ef8f Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Fri, 25 Nov 2022 09:40:17 +0100 Subject: [PATCH 10/14] textlogger: remove some dead code --- textlogger/textlogger.go | 6 ------ 1 file changed, 6 deletions(-) diff --git a/textlogger/textlogger.go b/textlogger/textlogger.go index 360888cc8..203d5b9ab 100644 --- a/textlogger/textlogger.go +++ b/textlogger/textlogger.go @@ -69,12 +69,6 @@ type tlogger struct { config *Config } -func copySlice(in []interface{}) []interface{} { - out := make([]interface{}, len(in)) - copy(out, in) - return out -} - func (l *tlogger) Init(info logr.RuntimeInfo) { l.callDepth = info.CallDepth } From ab80bfcc0816c326823225e25000c967607243d8 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Fri, 16 Dec 2022 14:56:07 +0100 Subject: [PATCH 11/14] serialize: combine merging and formatting This avoids one memory allocation (for the intermediate slice), copying and loops. --- internal/serialize/keyvalues.go | 163 +++++++++++++++++++++----------- ktesting/testinglogger.go | 8 +- textlogger/textlogger.go | 5 +- 3 files changed, 112 insertions(+), 64 deletions(-) diff --git a/internal/serialize/keyvalues.go b/internal/serialize/keyvalues.go index ad6bf1116..0bff64d04 100644 --- a/internal/serialize/keyvalues.go +++ b/internal/serialize/keyvalues.go @@ -91,6 +91,51 @@ func MergeKVs(first, second []interface{}) []interface{} { return merged } +// MergeKVsInto is a variant of MergeKVs which directly formats the key/value +// pairs into a buffer. +func MergeAndFormatKVs(b *bytes.Buffer, first, second []interface{}) { + if len(first) == 0 && len(second) == 0 { + // Nothing to do at all. + return + } + + if len(first) == 0 && len(second)%2 == 0 { + // Nothing to be overridden, second slice is well-formed + // and can be used directly. + for i := 0; i < len(second); i += 2 { + KVFormat(b, second[i], second[i+1]) + } + return + } + + // Determine which keys are in the second slice so that we can skip + // them when iterating over the first one. The code intentionally + // favors performance over completeness: we assume that keys are string + // constants and thus compare equal when the string values are equal. A + // string constant being overridden by, for example, a fmt.Stringer is + // not handled. + overrides := map[interface{}]bool{} + for i := 0; i < len(second); i += 2 { + overrides[second[i]] = true + } + for i := 0; i < len(first); i += 2 { + key := first[i] + if overrides[key] { + continue + } + KVFormat(b, key, first[i+1]) + } + // Round down. + l := len(second) + l = l / 2 * 2 + for i := 1; i < l; i += 2 { + KVFormat(b, second[i-1], second[i]) + } + if len(second)%2 == 1 { + KVFormat(b, second[len(second)-1], missingValue) + } +} + const missingValue = "(MISSING)" // KVListFormat serializes all key/value pairs into the provided buffer. @@ -104,66 +149,72 @@ func KVListFormat(b *bytes.Buffer, keysAndValues ...interface{}) { } else { v = missingValue } - b.WriteByte(' ') - // Keys are assumed to be well-formed according to - // https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/migration-to-structured-logging.md#name-arguments - // for the sake of performance. Keys with spaces, - // special characters, etc. will break parsing. - if sK, ok := k.(string); ok { - // Avoid one allocation when the key is a string, which - // normally it should be. - b.WriteString(sK) - } else { - b.WriteString(fmt.Sprintf("%s", k)) - } + KVFormat(b, k, v) + } +} - // The type checks are sorted so that more frequently used ones - // come first because that is then faster in the common - // cases. In Kubernetes, ObjectRef (a Stringer) is more common - // than plain strings - // (https://github.com/kubernetes/kubernetes/pull/106594#issuecomment-975526235). - switch v := v.(type) { - case fmt.Stringer: - writeStringValue(b, true, StringerToString(v)) +// KVFormat serializes one key/value pair into the provided buffer. +// A space gets inserted before the pair. +func KVFormat(b *bytes.Buffer, k, v interface{}) { + b.WriteByte(' ') + // Keys are assumed to be well-formed according to + // https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/migration-to-structured-logging.md#name-arguments + // for the sake of performance. Keys with spaces, + // special characters, etc. will break parsing. + if sK, ok := k.(string); ok { + // Avoid one allocation when the key is a string, which + // normally it should be. + b.WriteString(sK) + } else { + b.WriteString(fmt.Sprintf("%s", k)) + } + + // The type checks are sorted so that more frequently used ones + // come first because that is then faster in the common + // cases. In Kubernetes, ObjectRef (a Stringer) is more common + // than plain strings + // (https://github.com/kubernetes/kubernetes/pull/106594#issuecomment-975526235). + switch v := v.(type) { + case fmt.Stringer: + writeStringValue(b, true, StringerToString(v)) + case string: + writeStringValue(b, true, v) + case error: + writeStringValue(b, true, ErrorToString(v)) + case logr.Marshaler: + value := MarshalerToValue(v) + // A marshaler that returns a string is useful for + // delayed formatting of complex values. We treat this + // case like a normal string. This is useful for + // multi-line support. + // + // We could do this by recursively formatting a value, + // but that comes with the risk of infinite recursion + // if a marshaler returns itself. Instead we call it + // only once and rely on it returning the intended + // value directly. + switch value := value.(type) { case string: - writeStringValue(b, true, v) - case error: - writeStringValue(b, true, ErrorToString(v)) - case logr.Marshaler: - value := MarshalerToValue(v) - // A marshaler that returns a string is useful for - // delayed formatting of complex values. We treat this - // case like a normal string. This is useful for - // multi-line support. - // - // We could do this by recursively formatting a value, - // but that comes with the risk of infinite recursion - // if a marshaler returns itself. Instead we call it - // only once and rely on it returning the intended - // value directly. - switch value := value.(type) { - case string: - writeStringValue(b, true, value) - default: - writeStringValue(b, false, fmt.Sprintf("%+v", value)) - } - case []byte: - // In https://github.com/kubernetes/klog/pull/237 it was decided - // to format byte slices with "%+q". The advantages of that are: - // - readable output if the bytes happen to be printable - // - non-printable bytes get represented as unicode escape - // sequences (\uxxxx) - // - // The downsides are that we cannot use the faster - // strconv.Quote here and that multi-line output is not - // supported. If developers know that a byte array is - // printable and they want multi-line output, they can - // convert the value to string before logging it. - b.WriteByte('=') - b.WriteString(fmt.Sprintf("%+q", v)) + writeStringValue(b, true, value) default: - writeStringValue(b, false, fmt.Sprintf("%+v", v)) + writeStringValue(b, false, fmt.Sprintf("%+v", value)) } + case []byte: + // In https://github.com/kubernetes/klog/pull/237 it was decided + // to format byte slices with "%+q". The advantages of that are: + // - readable output if the bytes happen to be printable + // - non-printable bytes get represented as unicode escape + // sequences (\uxxxx) + // + // The downsides are that we cannot use the faster + // strconv.Quote here and that multi-line output is not + // supported. If developers know that a byte array is + // printable and they want multi-line output, they can + // convert the value to string before logging it. + b.WriteByte('=') + b.WriteString(fmt.Sprintf("%+q", v)) + default: + writeStringValue(b, false, fmt.Sprintf("%+v", v)) } } diff --git a/ktesting/testinglogger.go b/ktesting/testinglogger.go index 67bbd857f..0c87a953b 100644 --- a/ktesting/testinglogger.go +++ b/ktesting/testinglogger.go @@ -319,8 +319,7 @@ func (l tlogger) Info(level int, msg string, kvList ...interface{}) { l.shared.t.Helper() buffer := &bytes.Buffer{} - merged := serialize.MergeKVs(l.values, kvList) - serialize.KVListFormat(buffer, merged...) + serialize.MergeAndFormatKVs(buffer, l.values, kvList) l.log(LogInfo, msg, level, buffer, nil, kvList) } @@ -339,10 +338,9 @@ func (l tlogger) Error(err error, msg string, kvList ...interface{}) { l.shared.t.Helper() buffer := &bytes.Buffer{} if err != nil { - serialize.KVListFormat(buffer, "err", err) + serialize.KVFormat(buffer, "err", err) } - merged := serialize.MergeKVs(l.values, kvList) - serialize.KVListFormat(buffer, merged...) + serialize.MergeAndFormatKVs(buffer, l.values, kvList) l.log(LogError, msg, 0, buffer, err, kvList) } diff --git a/textlogger/textlogger.go b/textlogger/textlogger.go index 203d5b9ab..be946e0f5 100644 --- a/textlogger/textlogger.go +++ b/textlogger/textlogger.go @@ -125,10 +125,9 @@ func (l *tlogger) print(err error, s severity.Severity, msg string, kvList []int // message and put the multi-line output into a value. b.WriteString(strconv.Quote(msg)) if err != nil { - serialize.KVListFormat(&b.Buffer, "err", err) + serialize.KVFormat(&b.Buffer, "err", err) } - merged := serialize.MergeKVs(l.values, kvList) - serialize.KVListFormat(&b.Buffer, merged...) + serialize.MergeAndFormatKVs(&b.Buffer, l.values, kvList) if b.Len() == 0 || b.Bytes()[b.Len()-1] != '\n' { b.WriteByte('\n') } From 3d96ccccf3b4c12ccb85cf607f2f4e2baabaffda Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Thu, 22 Dec 2022 17:09:45 +0100 Subject: [PATCH 12/14] KObj: optimize string concatenation MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Using a strings.Builder reduces the number of allocations: name old time/op new time/op delta KlogOutput/KObjSlice_okay-36 15.2µs ± 5% 14.8µs ± 4% ~ (p=0.151 n=5+5) KlogOutput/KObjSlice_nil_entry-36 14.4µs ± 5% 13.6µs ± 3% -5.25% (p=0.032 n=5+5) KlogOutput/KObj-36 13.5µs ± 8% 13.5µs ± 6% ~ (p=0.841 n=5+5) KlogOutput/KObjSlice_ints-36 15.3µs ± 5% 15.2µs ± 4% ~ (p=0.841 n=5+5) KlogOutput/KObjSlice_nil_arg-36 12.8µs ± 2% 12.8µs ± 6% ~ (p=0.841 n=5+5) KlogOutput/KObjSlice_int_arg-36 14.1µs ± 4% 13.8µs ± 3% ~ (p=0.310 n=5+5) KlogOutput/KObjs-36 14.1µs ± 8% 13.6µs ± 8% ~ (p=0.690 n=5+5) name old alloc/op new alloc/op delta KlogOutput/KObjSlice_okay-36 2.89kB ± 0% 2.82kB ± 0% -2.23% (p=0.008 n=5+5) KlogOutput/KObjSlice_nil_entry-36 2.65kB ± 0% 2.62kB ± 0% ~ (p=0.079 n=4+5) KlogOutput/KObj-36 2.50kB ± 0% 2.47kB ± 0% -1.30% (p=0.000 n=4+5) KlogOutput/KObjSlice_ints-36 2.90kB ± 0% 2.90kB ± 0% ~ (p=1.000 n=5+5) KlogOutput/KObjSlice_nil_arg-36 2.41kB ± 0% 2.41kB ± 0% ~ (all equal) KlogOutput/KObjSlice_int_arg-36 2.67kB ± 0% 2.67kB ± 0% ~ (all equal) KlogOutput/KObjs-36 2.72kB ± 0% 2.65kB ± 0% -2.38% (p=0.008 n=5+5) name old allocs/op new allocs/op delta KlogOutput/KObjSlice_okay-36 46.0 ± 0% 42.0 ± 0% -8.70% (p=0.008 n=5+5) KlogOutput/KObjSlice_nil_entry-36 40.0 ± 0% 38.0 ± 0% -5.00% (p=0.008 n=5+5) KlogOutput/KObj-36 36.0 ± 0% 34.0 ± 0% -5.56% (p=0.008 n=5+5) KlogOutput/KObjSlice_ints-36 39.0 ± 0% 39.0 ± 0% ~ (all equal) KlogOutput/KObjSlice_nil_arg-36 35.0 ± 0% 35.0 ± 0% ~ (all equal) KlogOutput/KObjSlice_int_arg-36 37.0 ± 0% 37.0 ± 0% ~ (all equal) KlogOutput/KObjs-36 42.0 ± 0% 38.0 ± 0% -9.52% (p=0.008 n=5+5) --- k8s_references.go | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/k8s_references.go b/k8s_references.go index 2c218f698..a6436b5d1 100644 --- a/k8s_references.go +++ b/k8s_references.go @@ -19,6 +19,7 @@ package klog import ( "fmt" "reflect" + "strings" "github.com/go-logr/logr" ) @@ -31,7 +32,12 @@ type ObjectRef struct { func (ref ObjectRef) String() string { if ref.Namespace != "" { - return fmt.Sprintf("%s/%s", ref.Namespace, ref.Name) + var builder strings.Builder + builder.Grow(len(ref.Namespace) + len(ref.Name) + 1) + builder.WriteString(ref.Namespace) + builder.WriteRune('/') + builder.WriteString(ref.Name) + return builder.String() } return ref.Name } From 64ee6cf977ff7fbd56320f8a4afd95143e8ff0fb Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Thu, 22 Dec 2022 18:19:13 +0100 Subject: [PATCH 13/14] KObj, KObjSlice: format more efficiently as text MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The klog text format avoids some string allocation by calling WriteText instead of String when encountering such values. A positive side effect is that KObjSlice now gets logged like KObjs, i.e. pods=[namespace1/name1 namespace2/name2] Previously, it was written as a quoted string. To achieve the best performance, WriteText is passed a bytes.Buffer pointer instead of a io.Writer. This avoids an interface allocation for the parameter and provides access to the underlying methods. Benchmarks involving these types benefit while other are the same as before: name old time/op new time/op delta KlogOutput/KObj-36 12.7µs ±10% 13.1µs ± 1% ~ (p=0.151 n=5+5) KlogOutput/KObjs-36 13.4µs ± 7% 14.0µs ± 5% ~ (p=0.310 n=5+5) KlogOutput/KObjSlice_okay-36 14.8µs ± 4% 13.0µs ± 3% -12.33% (p=0.008 n=5+5) KlogOutput/KObjSlice_int_arg-36 14.0µs ± 6% 12.3µs ±10% -12.60% (p=0.008 n=5+5) KlogOutput/KObjSlice_ints-36 15.5µs ± 4% 12.8µs ± 6% -17.85% (p=0.008 n=5+5) KlogOutput/KObjSlice_nil_entry-36 14.2µs ±13% 12.6µs ± 3% -11.39% (p=0.008 n=5+5) KlogOutput/KObjSlice_nil_arg-36 12.6µs ± 6% 12.9µs ± 3% ~ (p=0.690 n=5+5) name old alloc/op new alloc/op delta KlogOutput/KObj-36 2.47kB ± 0% 2.41kB ± 0% -2.29% (p=0.008 n=5+5) KlogOutput/KObjs-36 2.65kB ± 0% 2.65kB ± 0% ~ (all equal) KlogOutput/KObjSlice_okay-36 2.82kB ± 0% 2.45kB ± 0% -13.37% (p=0.008 n=5+5) KlogOutput/KObjSlice_int_arg-36 2.67kB ± 0% 2.45kB ± 0% -8.42% (p=0.029 n=4+4) KlogOutput/KObjSlice_ints-36 2.90kB ± 0% 2.49kB ± 0% -14.37% (p=0.000 n=4+5) KlogOutput/KObjSlice_nil_entry-36 2.62kB ± 0% 2.43kB ± 0% -7.34% (p=0.000 n=4+5) KlogOutput/KObjSlice_nil_arg-36 2.41kB ± 0% 2.40kB ± 0% -0.66% (p=0.016 n=5+4) name old allocs/op new allocs/op delta KlogOutput/KObj-36 34.0 ± 0% 32.0 ± 0% -5.88% (p=0.008 n=5+5) KlogOutput/KObjs-36 38.0 ± 0% 38.0 ± 0% ~ (all equal) KlogOutput/KObjSlice_okay-36 42.0 ± 0% 32.0 ± 0% -23.81% (p=0.008 n=5+5) KlogOutput/KObjSlice_int_arg-36 37.0 ± 0% 32.0 ± 0% -13.51% (p=0.008 n=5+5) KlogOutput/KObjSlice_ints-36 39.0 ± 0% 33.0 ± 0% -15.38% (p=0.008 n=5+5) KlogOutput/KObjSlice_nil_entry-36 38.0 ± 0% 32.0 ± 0% -15.79% (p=0.008 n=5+5) KlogOutput/KObjSlice_nil_arg-36 35.0 ± 0% 32.0 ± 0% -8.57% (p=0.008 n=5+5) --- internal/serialize/keyvalues.go | 16 ++++++++ k8s_references.go | 70 +++++++++++++++++++++++++++------ test/output.go | 10 ++--- test/zapr.go | 12 ++---- 4 files changed, 84 insertions(+), 24 deletions(-) diff --git a/internal/serialize/keyvalues.go b/internal/serialize/keyvalues.go index 0bff64d04..f9558c3d2 100644 --- a/internal/serialize/keyvalues.go +++ b/internal/serialize/keyvalues.go @@ -24,6 +24,10 @@ import ( "github.com/go-logr/logr" ) +type textWriter interface { + WriteText(*bytes.Buffer) +} + // WithValues implements LogSink.WithValues. The old key/value pairs are // assumed to be well-formed, the new ones are checked and padded if // necessary. It returns a new slice. @@ -175,6 +179,8 @@ func KVFormat(b *bytes.Buffer, k, v interface{}) { // than plain strings // (https://github.com/kubernetes/kubernetes/pull/106594#issuecomment-975526235). switch v := v.(type) { + case textWriter: + writeTextWriterValue(b, v) case fmt.Stringer: writeStringValue(b, true, StringerToString(v)) case string: @@ -254,6 +260,16 @@ func ErrorToString(err error) (ret string) { return } +func writeTextWriterValue(b *bytes.Buffer, v textWriter) { + b.WriteRune('=') + defer func() { + if err := recover(); err != nil { + fmt.Fprintf(b, `""`, err) + } + }() + v.WriteText(b) +} + func writeStringValue(b *bytes.Buffer, quote bool, v string) { data := []byte(v) index := bytes.IndexByte(data, '\n') diff --git a/k8s_references.go b/k8s_references.go index a6436b5d1..ecd3f8b69 100644 --- a/k8s_references.go +++ b/k8s_references.go @@ -17,6 +17,7 @@ limitations under the License. package klog import ( + "bytes" "fmt" "reflect" "strings" @@ -42,6 +43,20 @@ func (ref ObjectRef) String() string { return ref.Name } +func (ref ObjectRef) WriteText(out *bytes.Buffer) { + out.WriteRune('"') + ref.writeUnquoted(out) + out.WriteRune('"') +} + +func (ref ObjectRef) writeUnquoted(out *bytes.Buffer) { + if ref.Namespace != "" { + out.WriteString(ref.Namespace) + out.WriteRune('/') + } + out.WriteString(ref.Name) +} + // MarshalLog ensures that loggers with support for structured output will log // as a struct by removing the String method via a custom type. func (ref ObjectRef) MarshalLog() interface{} { @@ -123,31 +138,31 @@ var _ fmt.Stringer = kobjSlice{} var _ logr.Marshaler = kobjSlice{} func (ks kobjSlice) String() string { - objectRefs, err := ks.process() - if err != nil { - return err.Error() + objectRefs, errStr := ks.process() + if errStr != "" { + return errStr } return fmt.Sprintf("%v", objectRefs) } func (ks kobjSlice) MarshalLog() interface{} { - objectRefs, err := ks.process() - if err != nil { - return err.Error() + objectRefs, errStr := ks.process() + if errStr != "" { + return errStr } return objectRefs } -func (ks kobjSlice) process() ([]interface{}, error) { +func (ks kobjSlice) process() (objs []interface{}, err string) { s := reflect.ValueOf(ks.arg) switch s.Kind() { case reflect.Invalid: // nil parameter, print as nil. - return nil, nil + return nil, "" case reflect.Slice: // Okay, handle below. default: - return nil, fmt.Errorf("", ks.arg) + return nil, fmt.Sprintf("", ks.arg) } objectRefs := make([]interface{}, 0, s.Len()) for i := 0; i < s.Len(); i++ { @@ -157,8 +172,41 @@ func (ks kobjSlice) process() ([]interface{}, error) { } else if v, ok := item.(KMetadata); ok { objectRefs = append(objectRefs, KObj(v)) } else { - return nil, fmt.Errorf("", item) + return nil, fmt.Sprintf("", item) + } + } + return objectRefs, "" +} + +var nilToken = []byte("") + +func (ks kobjSlice) WriteText(out *bytes.Buffer) { + s := reflect.ValueOf(ks.arg) + switch s.Kind() { + case reflect.Invalid: + // nil parameter, print as empty slice. + out.WriteString("[]") + return + case reflect.Slice: + // Okay, handle below. + default: + fmt.Fprintf(out, `""`, ks.arg) + return + } + out.Write([]byte{'['}) + defer out.Write([]byte{']'}) + for i := 0; i < s.Len(); i++ { + if i > 0 { + out.Write([]byte{' '}) + } + item := s.Index(i).Interface() + if item == nil { + out.Write(nilToken) + } else if v, ok := item.(KMetadata); ok { + KObj(v).writeUnquoted(out) + } else { + fmt.Fprintf(out, "", item) + return } } - return objectRefs, nil } diff --git a/test/output.go b/test/output.go index bfd026c2f..4dc52f766 100644 --- a/test/output.go +++ b/test/output.go @@ -290,14 +290,14 @@ I output.go:] "test" firstKey=1 secondKey=3 &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]" + 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="[]" + expectedOutput: `I output.go:] "test" pods=[] `, }, "KObjSlice int arg": { @@ -314,14 +314,14 @@ I output.go:] "test" firstKey=1 secondKey=3 &kmeta{Name: "pod-1", Namespace: "kube-system"}, nil, })}, - expectedOutput: `I output.go:] "test" pods="[kube-system/pod-1 ]" + 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="" + expectedOutput: `I output.go:] "test" ints=[] `, }, "regular error types as value": { @@ -357,7 +357,7 @@ I output.go:] "test" firstKey=1 secondKey=3 "MarshalLog() for nil": { text: "marshaler nil", values: []interface{}{"obj", (*klog.ObjectRef)(nil)}, - expectedOutput: `I output.go:] "marshaler nil" obj="" + expectedOutput: `I output.go:] "marshaler nil" obj="" `, }, "Error() that panics": { diff --git a/test/zapr.go b/test/zapr.go index 48cf2c3da..680e022db 100644 --- a/test/zapr.go +++ b/test/zapr.go @@ -73,11 +73,7 @@ func ZaprOutputMappingDirect() map[string]string { `: `{"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" 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" pods="[]" + `I output.go:] "test" pods=[] `: `{"caller":"test/output.go:","msg":"test","v":0,"pods":null} `, @@ -85,11 +81,11 @@ func ZaprOutputMappingDirect() map[string]string { `: `{"caller":"test/output.go:","msg":"test","v":0,"pods":""} `, - `I output.go:] "test" ints="" + `I output.go:] "test" ints=[] `: `{"caller":"test/output.go:","msg":"test","v":0,"ints":""} `, - `I output.go:] "test" pods="[kube-system/pod-1 ]" + `I output.go:] "test" pods=[kube-system/pod-1 ] `: `{"caller":"test/output.go:","msg":"test","v":0,"pods":[{"name":"pod-1","namespace":"kube-system"},null]} `, @@ -140,7 +136,7 @@ I output.go:] "odd WithValues" keyWithoutValue="(MISSING)" {"caller":"test/output.go:","msg":"both odd","basekey1":"basevar1","v":0,"akey":"avalue"} `, - `I output.go:] "marshaler nil" obj="" + `I output.go:] "marshaler nil" obj="" `: `{"caller":"test/output.go:","msg":"marshaler nil","v":0,"objError":"PANIC=value method k8s.io/klog/v2.ObjectRef.MarshalLog called using nil *ObjectRef pointer"} `, From a9dc48ed3468305ca93be1a6dbfc21f4a511eeaa Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Mon, 16 Jan 2023 11:42:45 +0100 Subject: [PATCH 14/14] github: bump golangci-lint image version It looks like golangci-lint comes with a fixed version of Go, one which is too old for the code: level=error msg="Running error: gofmt: analysis skipped: errors in package: [/go/src/k8s.io/klog/test/output.go:846:22: Discard not declared by package io /go/src/k8s.io/klog/test/output.go:864:40: Discard not declared by package io /go/src/k8s.io/klog/test/output.go:876:35: Discard not declared by package io]" io.Discard was introduced in Go 1.16, using it should be fine and is reflected in our Go version test matrix (>= 1.17). --- .github/workflows/test.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index cca0121f3..870d1a2f7 100644 --- a/.github/workflows/test.yml +++ b/.github/workflows/test.yml @@ -30,7 +30,7 @@ jobs: - name: Lint run: | docker run --rm -v `pwd`:/go/src/k8s.io/klog -w /go/src/k8s.io/klog \ - golangci/golangci-lint:v1.23.8 golangci-lint run --disable-all -v \ + golangci/golangci-lint:v1.50.1 golangci-lint run --disable-all -v \ -E govet -E misspell -E gofmt -E ineffassign -E golint apidiff: runs-on: ubuntu-latest