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.

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.

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() {

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)
+	verbosityLevel := 10
-	for i := 0; i < 11; i++ {
+	sampleInfoLogger, _ := NewJSONLogger(config.VerbosityLevel(verbosityLevel), nil, nil, nil)
-		if !sampleInfoLogger.V(i).Enabled() {
+	for v := 0; v <= verbosityLevel; v++ {
-			t.Errorf("V(%d).Info should be enabled", i)
+		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, _ := NewJSONLogger(config.VerbosityLevel(verbosityLevel), writer, nil, nil)
-		sampleInfoLogger.V(i).Info("test", "ns", "default", "podnum", 2, "time", time.Microsecond)
+		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 {
+		if actualV != v {
-			t.Errorf("V(%d).Info...) returned v=%d. expected v=%d", i, v, i)
+			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")

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{}

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)
+		// This logger will do its own verbosity checking, using the exact same
-		klog.SetLoggerWithOptions(log, klog.FlushLogger(flush))
+		// 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))

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

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)
-				logger, flush = logsjson.Factory{}.Create(options.Config.Options)
 			}
 			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()

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
 }