From b390d018c76bf83f1b0e818bc9f2feb5982234dc Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Mon, 7 Feb 2022 15:28:12 +0100 Subject: [PATCH] logs: pass verbosity to loggers When a Logger gets called directly via contextual logging, it has to do its own verbosity check and therefore needs to know what the intended verbosity level is. This used to work previously because all verbosity checks were done in klog before invoking the Logger. --- .../k8s.io/component-base/logs/json/json.go | 21 ++++---- .../logs/json/json_benchmark_test.go | 6 +-- .../component-base/logs/json/json_test.go | 50 +++++++++++++------ .../component-base/logs/json/klog_test.go | 4 +- .../src/k8s.io/component-base/logs/options.go | 7 ++- .../component-base/logs/registry/registry.go | 2 +- .../logs/benchmark/benchmark_test.go | 10 ++-- .../integration/logs/benchmark/common_test.go | 4 +- 8 files changed, 66 insertions(+), 38 deletions(-) diff --git a/staging/src/k8s.io/component-base/logs/json/json.go b/staging/src/k8s.io/component-base/logs/json/json.go index bdbcec71a16..0171f66afb6 100644 --- a/staging/src/k8s.io/component-base/logs/json/json.go +++ b/staging/src/k8s.io/component-base/logs/json/json.go @@ -38,7 +38,10 @@ var ( // NewJSONLogger creates a new json logr.Logger and its associated // flush function. The separate error stream is optional and may be nil. // The encoder config is also optional. -func NewJSONLogger(infoStream, errorStream zapcore.WriteSyncer, encoderConfig *zapcore.EncoderConfig) (logr.Logger, func()) { +func NewJSONLogger(v config.VerbosityLevel, infoStream, errorStream zapcore.WriteSyncer, encoderConfig *zapcore.EncoderConfig) (logr.Logger, func()) { + // zap levels are inverted: everything with a verbosity >= threshold gets logged. + zapV := -zapcore.Level(v) + if encoderConfig == nil { encoderConfig = &zapcore.EncoderConfig{ MessageKey: "msg", @@ -54,13 +57,13 @@ func NewJSONLogger(infoStream, errorStream zapcore.WriteSyncer, encoderConfig *z encoder := zapcore.NewJSONEncoder(*encoderConfig) var core zapcore.Core if errorStream == nil { - core = zapcore.NewCore(encoder, infoStream, zapcore.Level(-127)) + core = zapcore.NewCore(encoder, infoStream, zapV) } else { highPriority := zap.LevelEnablerFunc(func(lvl zapcore.Level) bool { - return lvl >= zapcore.ErrorLevel + return lvl >= zapcore.ErrorLevel && lvl >= zapV }) lowPriority := zap.LevelEnablerFunc(func(lvl zapcore.Level) bool { - return lvl < zapcore.ErrorLevel + return lvl < zapcore.ErrorLevel && lvl >= zapV }) core = zapcore.NewTee( zapcore.NewCore(encoder, errorStream, highPriority), @@ -84,7 +87,7 @@ type Factory struct{} var _ registry.LogFormatFactory = Factory{} -func (f Factory) Create(options config.FormatOptions) (logr.Logger, func()) { +func (f Factory) Create(c config.LoggingConfiguration) (logr.Logger, func()) { // We intentionally avoid all os.File.Sync calls. Output is unbuffered, // therefore we don't need to flush, and calling the underlying fsync // would just slow down writing. @@ -94,9 +97,9 @@ func (f Factory) Create(options config.FormatOptions) (logr.Logger, func()) { // doesn't need to worry about data not being written because of a // system crash or powerloss. stderr := zapcore.Lock(AddNopSync(os.Stderr)) - if options.JSON.SplitStream { + if c.Options.JSON.SplitStream { stdout := zapcore.Lock(AddNopSync(os.Stdout)) - size := options.JSON.InfoBufferSize.Value() + size := c.Options.JSON.InfoBufferSize.Value() if size > 0 { // Prevent integer overflow. if size > 2*1024*1024*1024 { @@ -108,10 +111,10 @@ func (f Factory) Create(options config.FormatOptions) (logr.Logger, func()) { } } // stdout for info messages, stderr for errors. - return NewJSONLogger(stdout, stderr, nil) + return NewJSONLogger(c.Verbosity, stdout, stderr, nil) } // Write info messages and errors to stderr to prevent mixing with normal program output. - return NewJSONLogger(stderr, nil, nil) + return NewJSONLogger(c.Verbosity, stderr, nil, nil) } // AddNoSync adds a NOP Sync implementation. diff --git a/staging/src/k8s.io/component-base/logs/json/json_benchmark_test.go b/staging/src/k8s.io/component-base/logs/json/json_benchmark_test.go index ca4d6949090..76b9fad3429 100644 --- a/staging/src/k8s.io/component-base/logs/json/json_benchmark_test.go +++ b/staging/src/k8s.io/component-base/logs/json/json_benchmark_test.go @@ -26,7 +26,7 @@ import ( var writer = zapcore.AddSync(&writeSyncer{}) func BenchmarkInfoLoggerInfo(b *testing.B) { - logger, _ := NewJSONLogger(writer, nil, nil) + logger, _ := NewJSONLogger(0, writer, nil, nil) b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { @@ -55,7 +55,7 @@ func BenchmarkInfoLoggerInfo(b *testing.B) { } func BenchmarkZapLoggerError(b *testing.B) { - logger, _ := NewJSONLogger(writer, nil, nil) + logger, _ := NewJSONLogger(0, writer, nil, nil) b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { @@ -85,7 +85,7 @@ func BenchmarkZapLoggerError(b *testing.B) { } func BenchmarkZapLoggerV(b *testing.B) { - logger, _ := NewJSONLogger(writer, nil, nil) + logger, _ := NewJSONLogger(1, writer, nil, nil) b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { diff --git a/staging/src/k8s.io/component-base/logs/json/json_test.go b/staging/src/k8s.io/component-base/logs/json/json_test.go index 30c3cc3e48d..e634c9bfbe9 100644 --- a/staging/src/k8s.io/component-base/logs/json/json_test.go +++ b/staging/src/k8s.io/component-base/logs/json/json_test.go @@ -24,6 +24,7 @@ import ( "time" "github.com/stretchr/testify/assert" + "k8s.io/component-base/config" "go.uber.org/zap" "go.uber.org/zap/zapcore" @@ -75,7 +76,7 @@ func TestZapLoggerInfo(t *testing.T) { for _, data := range testDataInfo { var buffer bytes.Buffer writer := zapcore.AddSync(&buffer) - sampleInfoLogger, _ := NewJSONLogger(writer, nil, nil) + sampleInfoLogger, _ := NewJSONLogger(0, writer, nil, nil) for _, name := range data.names { sampleInfoLogger = sampleInfoLogger.WithName(name) } @@ -109,10 +110,16 @@ func TestZapLoggerInfo(t *testing.T) { // TestZapLoggerEnabled test ZapLogger enabled func TestZapLoggerEnabled(t *testing.T) { - sampleInfoLogger, _ := NewJSONLogger(nil, nil, nil) - for i := 0; i < 11; i++ { - if !sampleInfoLogger.V(i).Enabled() { - t.Errorf("V(%d).Info should be enabled", i) + verbosityLevel := 10 + sampleInfoLogger, _ := NewJSONLogger(config.VerbosityLevel(verbosityLevel), nil, nil, nil) + for v := 0; v <= verbosityLevel; v++ { + enabled := sampleInfoLogger.V(v).Enabled() + expectEnabled := v <= verbosityLevel + if !expectEnabled && enabled { + t.Errorf("V(%d).Info should be disabled", v) + } + if expectEnabled && !enabled { + t.Errorf("V(%d).Info should be enabled", v) } } } @@ -123,24 +130,37 @@ func TestZapLoggerV(t *testing.T) { return time.Date(1970, time.January, 1, 0, 0, 0, 123, time.UTC) } - for i := 0; i < 11; i++ { + verbosityLevel := 10 + for v := 0; v <= verbosityLevel; v++ { var buffer bytes.Buffer writer := zapcore.AddSync(&buffer) - sampleInfoLogger, _ := NewJSONLogger(writer, nil, nil) - sampleInfoLogger.V(i).Info("test", "ns", "default", "podnum", 2, "time", time.Microsecond) + sampleInfoLogger, _ := NewJSONLogger(config.VerbosityLevel(verbosityLevel), writer, nil, nil) + sampleInfoLogger.V(v).Info("test", "ns", "default", "podnum", 2, "time", time.Microsecond) logStr := buffer.String() - var v, lineNo int + + shouldHaveLogged := v <= verbosityLevel + if logged := logStr != ""; logged != shouldHaveLogged { + if logged { + t.Fatalf("Expected no output at v=%d, got: %s", v, logStr) + } + t.Fatalf("Expected output at v=%d, got none.", v) + } + if !shouldHaveLogged { + continue + } + + var actualV, lineNo int expectFormat := "{\"ts\":0.000123,\"caller\":\"json/json_test.go:%d\",\"msg\":\"test\",\"v\":%d,\"ns\":\"default\",\"podnum\":2,\"time\":\"1µs\"}\n" - n, err := fmt.Sscanf(logStr, expectFormat, &lineNo, &v) + n, err := fmt.Sscanf(logStr, expectFormat, &lineNo, &actualV) if n != 2 || err != nil { t.Errorf("log format error: %d elements, error %s:\n%s", n, err, logStr) } - if v != i { - t.Errorf("V(%d).Info...) returned v=%d. expected v=%d", i, v, i) + if actualV != v { + t.Errorf("V(%d).Info...) returned v=%d. expected v=%d", v, actualV, v) } expect := fmt.Sprintf(expectFormat, lineNo, v) if !assert.Equal(t, logStr, expect) { - t.Errorf("V(%d).Info has wrong format \n expect:%s\n got:%s", i, expect, logStr) + t.Errorf("V(%d).Info has wrong format \n expect:%s\n got:%s", v, expect, logStr) } buffer.Reset() } @@ -153,7 +173,7 @@ func TestZapLoggerError(t *testing.T) { timeNow = func() time.Time { return time.Date(1970, time.January, 1, 0, 0, 0, 123, time.UTC) } - sampleInfoLogger, _ := NewJSONLogger(writer, nil, nil) + sampleInfoLogger, _ := NewJSONLogger(0, writer, nil, nil) sampleInfoLogger.Error(fmt.Errorf("invalid namespace:%s", "default"), "wrong namespace", "ns", "default", "podnum", 2, "time", time.Microsecond) logStr := buffer.String() var ts float64 @@ -171,7 +191,7 @@ func TestZapLoggerError(t *testing.T) { func TestZapLoggerStreams(t *testing.T) { var infoBuffer, errorBuffer bytes.Buffer - log, _ := NewJSONLogger(zapcore.AddSync(&infoBuffer), zapcore.AddSync(&errorBuffer), nil) + log, _ := NewJSONLogger(0, zapcore.AddSync(&infoBuffer), zapcore.AddSync(&errorBuffer), nil) log.Error(fmt.Errorf("some error"), "failed") log.Info("hello world") diff --git a/staging/src/k8s.io/component-base/logs/json/klog_test.go b/staging/src/k8s.io/component-base/logs/json/klog_test.go index 19c26590e6c..c5f0ae7719b 100644 --- a/staging/src/k8s.io/component-base/logs/json/klog_test.go +++ b/staging/src/k8s.io/component-base/logs/json/klog_test.go @@ -239,7 +239,7 @@ func TestKlogIntegration(t *testing.T) { t.Run(tc.name, func(t *testing.T) { var buffer bytes.Buffer writer := zapcore.AddSync(&buffer) - logger, _ := NewJSONLogger(writer, nil, nil) + logger, _ := NewJSONLogger(100, writer, nil, nil) klog.SetLogger(logger) defer klog.ClearLogger() @@ -270,7 +270,7 @@ func TestKlogIntegration(t *testing.T) { func TestKlogV(t *testing.T) { var buffer testBuff writer := zapcore.AddSync(&buffer) - logger, _ := NewJSONLogger(writer, nil, nil) + logger, _ := NewJSONLogger(100, writer, nil, nil) klog.SetLogger(logger) defer klog.ClearLogger() fs := flag.FlagSet{} diff --git a/staging/src/k8s.io/component-base/logs/options.go b/staging/src/k8s.io/component-base/logs/options.go index 551fe5a3661..15d8fe579b5 100644 --- a/staging/src/k8s.io/component-base/logs/options.go +++ b/staging/src/k8s.io/component-base/logs/options.go @@ -80,8 +80,11 @@ func (o *Options) apply() { if factory == nil { klog.ClearLogger() } else { - log, flush := factory.Create(o.Config.Options) - klog.SetLoggerWithOptions(log, klog.FlushLogger(flush)) + // This logger will do its own verbosity checking, using the exact same + // configuration as klog itself. + log, flush := factory.Create(o.Config) + // Therefore it can get called directly. + klog.SetLoggerWithOptions(log, klog.ContextualLogger(true), klog.FlushLogger(flush)) } if err := loggingFlags.Lookup("v").Value.Set(o.Config.Verbosity.String()); err != nil { panic(fmt.Errorf("internal error while setting klog verbosity: %v", err)) diff --git a/staging/src/k8s.io/component-base/logs/registry/registry.go b/staging/src/k8s.io/component-base/logs/registry/registry.go index 145c0b8fd03..be2c3260c9e 100644 --- a/staging/src/k8s.io/component-base/logs/registry/registry.go +++ b/staging/src/k8s.io/component-base/logs/registry/registry.go @@ -41,7 +41,7 @@ type LogFormatFactory interface { // Returning a flush function for the logger is optional. // If provided, the caller must ensure that it is called // periodically (if desired) and at program exit. - Create(options config.FormatOptions) (log logr.Logger, flush func()) + Create(c config.LoggingConfiguration) (log logr.Logger, flush func()) } // NewLogFormatRegistry return new init LogFormatRegistry struct diff --git a/test/integration/logs/benchmark/benchmark_test.go b/test/integration/logs/benchmark/benchmark_test.go index e810e88f3a3..157406b9935 100644 --- a/test/integration/logs/benchmark/benchmark_test.go +++ b/test/integration/logs/benchmark/benchmark_test.go @@ -175,6 +175,7 @@ func benchmarkOutputFormats(b *testing.B, config loadGeneratorConfig, discard bo generateOutput(b, config, nil, out) }) b.Run("JSON", func(b *testing.B) { + options := logs.NewOptions() var logger logr.Logger var flush func() var out1, out2 *os.File @@ -193,15 +194,14 @@ func benchmarkOutputFormats(b *testing.B, config loadGeneratorConfig, discard bo } b.Run("single-stream", func(b *testing.B) { if discard { - logger, flush = logsjson.NewJSONLogger(logsjson.AddNopSync(&output), nil, nil) + logger, flush = logsjson.NewJSONLogger(options.Config.Verbosity, logsjson.AddNopSync(&output), nil, nil) } else { stderr := os.Stderr os.Stderr = out1 defer func() { os.Stderr = stderr }() - options := logs.NewOptions() - logger, flush = logsjson.Factory{}.Create(options.Config.Options) + logger, flush = logsjson.Factory{}.Create(options.Config) } klog.SetLogger(logger) defer klog.ClearLogger() @@ -210,7 +210,7 @@ func benchmarkOutputFormats(b *testing.B, config loadGeneratorConfig, discard bo b.Run("split-stream", func(b *testing.B) { if discard { - logger, flush = logsjson.NewJSONLogger(logsjson.AddNopSync(&output), logsjson.AddNopSync(&output), nil) + logger, flush = logsjson.NewJSONLogger(options.Config.Verbosity, logsjson.AddNopSync(&output), logsjson.AddNopSync(&output), nil) } else { stdout, stderr := os.Stdout, os.Stderr os.Stdout, os.Stderr = out1, out2 @@ -219,7 +219,7 @@ func benchmarkOutputFormats(b *testing.B, config loadGeneratorConfig, discard bo }() options := logs.NewOptions() options.Config.Options.JSON.SplitStream = true - logger, flush = logsjson.Factory{}.Create(options.Config.Options) + logger, flush = logsjson.Factory{}.Create(options.Config) } klog.SetLogger(logger) defer klog.ClearLogger() diff --git a/test/integration/logs/benchmark/common_test.go b/test/integration/logs/benchmark/common_test.go index 9adcf50b014..78602d1341e 100644 --- a/test/integration/logs/benchmark/common_test.go +++ b/test/integration/logs/benchmark/common_test.go @@ -23,6 +23,7 @@ import ( "github.com/go-logr/logr" "go.uber.org/zap/zapcore" + "k8s.io/component-base/logs" logsjson "k8s.io/component-base/logs/json" "k8s.io/klog/v2" ) @@ -60,7 +61,8 @@ func newJSONLogger(out io.Writer) logr.Logger { encoderConfig := &zapcore.EncoderConfig{ MessageKey: "msg", } - logger, _ := logsjson.NewJSONLogger(zapcore.AddSync(out), nil, encoderConfig) + options := logs.NewOptions() + logger, _ := logsjson.NewJSONLogger(options.Config.Verbosity, zapcore.AddSync(out), nil, encoderConfig) return logger }