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 }