From 05a75d8e95604ed5fce26d34e38cd9471d608c42 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Sun, 3 Sep 2023 20:44:32 +0200 Subject: [PATCH] klogr test: check vmodule support LogSink.Enabled is sensitive to stack unwinding. logr v1.2.0 gets this wrong by calling LogSink.Enabled at different depths for Logger.Info and Logger.Enabled, therefore this test fails with that version. logr v1.3.0 changes the behavior to the more sane "LogSink.Enabled needs to skip one level, regardless where it is called". The Discard log sink implementation changed such that a discard logger doesn't have a sink at all anymore. --- contextual_test.go | 2 +- go.mod | 2 ++ go.sum | 4 +-- klogr.go | 3 +- klogr/klogr.go | 3 +- klogr_helper_test.go | 35 +++++++++++++++++++++ klogr_test.go | 67 ++++++++++++++++++++++++++++++++++++++++ textlogger/textlogger.go | 4 +-- 8 files changed, 110 insertions(+), 10 deletions(-) create mode 100644 klogr_helper_test.go create mode 100644 klogr_test.go diff --git a/contextual_test.go b/contextual_test.go index 80e14fa30..27aeb4e89 100644 --- a/contextual_test.go +++ b/contextual_test.go @@ -41,7 +41,7 @@ func ExampleSetLogger() { // Output: // logger after SetLogger: *klog.klogger // logger after SetLoggerWithOptions with ContextualLogger(false): *klog.klogger - // logger after SetLoggerWithOptions with ContextualLogger(true): logr.discardLogSink + // logger after SetLoggerWithOptions with ContextualLogger(true): } func ExampleFlushLogger() { diff --git a/go.mod b/go.mod index 31aefba74..c780c0b20 100644 --- a/go.mod +++ b/go.mod @@ -3,3 +3,5 @@ module k8s.io/klog/v2 go 1.13 require github.com/go-logr/logr v1.2.0 + +replace github.com/go-logr/logr => github.com/thockin/logr v1.2.4-0.20230904175353-af7b2b77007b diff --git a/go.sum b/go.sum index 919fbadbc..bac5c8bb2 100644 --- a/go.sum +++ b/go.sum @@ -1,2 +1,2 @@ -github.com/go-logr/logr v1.2.0 h1:QK40JKJyMdUDz+h+xvCsru/bJhvG0UxvePV0ufL/AcE= -github.com/go-logr/logr v1.2.0/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A= +github.com/thockin/logr v1.2.4-0.20230904175353-af7b2b77007b h1:YID/5LYjxvOBDCGOTA5Sqfm6fEMcpU5R0L5tRQO0TDc= +github.com/thockin/logr v1.2.4-0.20230904175353-af7b2b77007b/go.mod h1:9T104GzyrTigFIr8wt5mBrctHMim0Nb2HLGrmQ40KvY= diff --git a/klogr.go b/klogr.go index 15de00e21..cad04cf35 100644 --- a/klogr.go +++ b/klogr.go @@ -52,8 +52,7 @@ func (l *klogger) Info(level int, msg string, kvList ...interface{}) { } func (l *klogger) Enabled(level int) bool { - // Skip this function and logr.Logger.Info where Enabled is called. - return VDepth(l.callDepth+2, Level(level)).Enabled() + return VDepth(l.callDepth+1, Level(level)).Enabled() } func (l *klogger) Error(err error, msg string, kvList ...interface{}) { diff --git a/klogr/klogr.go b/klogr/klogr.go index db5b5c789..9875ca2eb 100644 --- a/klogr/klogr.go +++ b/klogr/klogr.go @@ -136,8 +136,7 @@ func (l *klogger) Info(level int, msg string, kvList ...interface{}) { } func (l *klogger) Enabled(level int) bool { - // Skip this function and logr.Logger.Info where Enabled is called. - return klog.VDepth(l.callDepth+2, klog.Level(level)).Enabled() + return klog.VDepth(l.callDepth, klog.Level(level)).Enabled() } func (l *klogger) Error(err error, msg string, kvList ...interface{}) { diff --git a/klogr_helper_test.go b/klogr_helper_test.go new file mode 100644 index 000000000..8ae119f19 --- /dev/null +++ b/klogr_helper_test.go @@ -0,0 +1,35 @@ +/* +Copyright 2023 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 ( + "testing" + + "k8s.io/klog/v2" +) + +func testVerbosity(t *testing.T, logger klog.Logger) { + // This runs with -v=5 -vmodule=klog_helper_test=10. + logger.V(11).Info("v11 not visible from klogr_helper_test.go") + if logger.V(11).Enabled() { + t.Error("V(11).Enabled() in klogr_helper_test.go should have returned false.") + } + logger.V(10).Info("v10 visible from klogr_helper_test.go") + if !logger.V(10).Enabled() { + t.Error("V(10).Enabled() in klogr_helper_test.go should have returned true.") + } +} diff --git a/klogr_test.go b/klogr_test.go new file mode 100644 index 000000000..199750318 --- /dev/null +++ b/klogr_test.go @@ -0,0 +1,67 @@ +/* +Copyright 2023 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 ( + "bytes" + "flag" + "regexp" + "testing" + + "k8s.io/klog/v2" +) + +func TestVerbosity(t *testing.T) { + state := klog.CaptureState() + defer state.Restore() + + var fs flag.FlagSet + klog.InitFlags(&fs) + if err := fs.Set("v", "5"); err != nil { + t.Fatalf("unexpected error: %v", err) + } + if err := fs.Set("vmodule", "klogr_helper_test=10"); err != nil { + t.Fatalf("unexpected error: %v", err) + } + if err := fs.Set("logtostderr", "false"); err != nil { + t.Fatalf("unexpected error: %v", err) + } + var buffer bytes.Buffer + klog.SetOutput(&buffer) + logger := klog.Background() + + // -v=5 is in effect here. + logger.V(6).Info("v6 not visible from klogr_test.go") + if logger.V(6).Enabled() { + t.Error("V(6).Enabled() in klogr_test.go should have returned false.") + } + logger.V(5).Info("v5 visible from klogr_test.go") + if !logger.V(5).Enabled() { + t.Error("V(5).Enabled() in klogr_test.go should have returned true.") + } + + // Now test with -v=5 -vmodule=klogr_helper_test=10. + testVerbosity(t, logger) + + klog.Flush() + expected := `^.*v5 visible from klogr_test.go.* +.*v10 visible from klogr_helper_test.go.* +` + if !regexp.MustCompile(expected).Match(buffer.Bytes()) { + t.Errorf("Output did not match regular expression.\nOutput:\n%s\n\nRegular expression:\n%s\n", buffer.String(), expected) + } +} diff --git a/textlogger/textlogger.go b/textlogger/textlogger.go index 3c0e079ad..4fdf5567b 100644 --- a/textlogger/textlogger.go +++ b/textlogger/textlogger.go @@ -83,9 +83,7 @@ func (l *tlogger) WithCallDepth(depth int) logr.LogSink { } func (l *tlogger) Enabled(level int) bool { - // Skip this function and the Logger.Info call, then - // also any additional stack frames from WithCallDepth. - return l.config.vstate.Enabled(verbosity.Level(level), 2+l.callDepth) + return l.config.vstate.Enabled(verbosity.Level(level), 1+l.callDepth) } func (l *tlogger) Info(level int, msg string, kvList ...interface{}) {