Merge pull request kubernetes#92788 from yuzhiquan/fix-json-verbose

Fix JSON logger verbose

Author: k8s-ci-robot

staging/src/k8s.io/component-base/logs/json/BUILD

@@ -24,6 +24,7 @@ go_test(
         "//vendor/github.com/stretchr/testify/assert:go_default_library",
         "//vendor/go.uber.org/zap:go_default_library",
         "//vendor/go.uber.org/zap/zapcore:go_default_library",
+        "//vendor/k8s.io/klog/v2:go_default_library",
     ],
 )
 

staging/src/k8s.io/component-base/logs/json/json.go

@@ -40,35 +40,38 @@ type zapLogger struct {
 	// NB: this looks very similar to zap.SugaredLogger, but
 	// deals with our desire to have multiple verbosity levels.
 	l   *zap.Logger
-	lvl zapcore.Level
+	lvl int
 }
 
 // implement logr.Logger
 var _ logr.Logger = &zapLogger{}
 
+// Enabled should always return true
 func (l *zapLogger) Enabled() bool {
-	return l.l.Core().Enabled(l.lvl)
+	return true
 }
 
 // Info write message to error level log
 func (l *zapLogger) Info(msg string, keysAndVals ...interface{}) {
-	if checkedEntry := l.l.Check(l.lvl, msg); checkedEntry != nil {
-		checkedEntry.Time = timeNow()
-		checkedEntry.Write(l.handleFields(keysAndVals)...)
+	entry := zapcore.Entry{
+		Time:    timeNow(),
+		Message: msg,
 	}
+	checkedEntry := l.l.Core().Check(entry, nil)
+	checkedEntry.Write(l.handleFields(keysAndVals)...)
 }
 
 // dPanic write message to DPanicLevel level log
 // we need implement this because unit test case need stub time.Now
 // otherwise the ts field always changed
-func (l *zapLogger) dPanic(msg string, keysAndVals ...interface{}) {
+func (l *zapLogger) dPanic(msg string) {
 	entry := zapcore.Entry{
 		Level:   zapcore.DPanicLevel,
 		Time:    timeNow(),
 		Message: msg,
 	}
 	checkedEntry := l.l.Core().Check(entry, nil)
-	checkedEntry.Write(l.handleFields(keysAndVals)...)
+	checkedEntry.Write(zap.Int("v", l.lvl))
 }
 
 // handleFields converts a bunch of arbitrary key-value pairs into Zap fields.  It takes
@@ -78,18 +81,19 @@ func (l *zapLogger) handleFields(args []interface{}, additional ...zap.Field) []
 	// a slightly modified version of zap.SugaredLogger.sweetenFields
 	if len(args) == 0 {
 		// fast-return if we have no suggared fields.
-		return additional
+		return append(additional, zap.Int("v", l.lvl))
 	}
 
 	// unlike Zap, we can be pretty sure users aren't passing structured
 	// fields (since logr has no concept of that), so guess that we need a
 	// little less space.
-	fields := make([]zap.Field, 0, len(args)/2+len(additional))
+	fields := make([]zap.Field, 0, len(args)/2+len(additional)+1)
+	fields = append(fields, zap.Int("v", l.lvl))
 	for i := 0; i < len(args)-1; i += 2 {
 		// check just in case for strongly-typed Zap fields, which is illegal (since
 		// it breaks implementation agnosticism), so we can give a better error message.
 		if _, ok := args[i].(zap.Field); ok {
-			l.dPanic("strongly-typed Zap Field passed to logr", zap.Any("zap field", args[i]))
+			l.dPanic("strongly-typed Zap Field passed to logr")
 			break
 		}
 
@@ -98,8 +102,8 @@ func (l *zapLogger) handleFields(args []interface{}, additional ...zap.Field) []
 		key, val := args[i], args[i+1]
 		keyStr, isString := key.(string)
 		if !isString {
-			// if the key isn't a string, DPanic and stop logging
-			l.dPanic("non-string key argument passed to logging, ignoring all later arguments", zap.Any("invalid key", key))
+			// if the key isn't a string, stop logging
+			l.dPanic("non-string key argument passed to logging, ignoring all later arguments")
 			break
 		}
 
@@ -120,10 +124,10 @@ func (l *zapLogger) Error(err error, msg string, keysAndVals ...interface{}) {
 	checkedEntry.Write(l.handleFields(keysAndVals, handleError(err))...)
 }
 
-// V return info logr.Logger with specified level
+// V return info logr.Logger  with specified level
 func (l *zapLogger) V(level int) logr.Logger {
 	return &zapLogger{
-		lvl: l.lvl - zapcore.Level(level),
+		lvl: l.lvl + level,
 		l:   l.l,
 	}
 }
@@ -140,19 +144,17 @@ func (l *zapLogger) WithName(name string) logr.Logger {
 	return l
 }
 
-// encoderConfig config zap json encoder key format, and encodetime format
+// encoderConfig config zap encodetime format
 var encoderConfig = zapcore.EncoderConfig{
 	MessageKey: "msg",
 
-	LevelKey:    "v",
-	EncodeLevel: int8LevelEncoder,
-
 	TimeKey:    "ts",
 	EncodeTime: zapcore.EpochMillisTimeEncoder,
 }
 
 // NewJSONLogger creates a new json logr.Logger using the given Zap Logger to log.
-func NewJSONLogger(l *zap.Logger, w zapcore.WriteSyncer) logr.Logger {
+func NewJSONLogger(w zapcore.WriteSyncer) logr.Logger {
+	l, _ := zap.NewProduction()
 	if w == nil {
 		w = os.Stdout
 	}
@@ -162,24 +164,14 @@ func NewJSONLogger(l *zap.Logger, w zapcore.WriteSyncer) logr.Logger {
 				return zapcore.NewCore(zapcore.NewJSONEncoder(encoderConfig), zapcore.AddSync(w), zapcore.DebugLevel)
 			}))
 	return &zapLogger{
-		l:   log,
-		lvl: zap.DebugLevel,
-	}
-}
-
-func int8LevelEncoder(l zapcore.Level, enc zapcore.PrimitiveArrayEncoder) {
-	lvl := int8(l)
-	if lvl < 0 {
-		lvl = -lvl
+		l: log,
 	}
-	enc.AppendInt8(lvl)
 }
 
 func handleError(err error) zap.Field {
 	return zap.NamedError("err", err)
 }
 
 func init() {
-	l, _ := zap.NewProduction()
-	JSONLogger = NewJSONLogger(l, nil)
+	JSONLogger = NewJSONLogger(nil)
 }

staging/src/k8s.io/component-base/logs/json/json_benchmark_test.go

@@ -21,8 +21,6 @@ import (
 	"fmt"
 	"testing"
 	"time"
-
-	"go.uber.org/zap"
 )
 
 var record = struct {
@@ -61,7 +59,7 @@ var record = struct {
 func BenchmarkInfoLoggerInfo(b *testing.B) {
 	b.RunParallel(func(pb *testing.PB) {
 		for pb.Next() {
-			jLogger := NewJSONLogger(zap.NewExample(), nil)
+			jLogger := NewJSONLogger(nil)
 			jLogger.Info("test",
 				"str", "foo",
 				"int64-1", int64(1),
@@ -98,7 +96,7 @@ func BenchmarkInfoLoggerInfoStandardJSON(b *testing.B) {
 func BenchmarkZapLoggerError(b *testing.B) {
 	b.RunParallel(func(pb *testing.PB) {
 		for pb.Next() {
-			jLogger := NewJSONLogger(zap.NewExample(), nil)
+			jLogger := NewJSONLogger(nil)
 			jLogger.Error(fmt.Errorf("test for error:%s", "default"),
 				"test",
 				"str", "foo",
@@ -135,7 +133,7 @@ func BenchmarkZapLoggerErrorStandardJSON(b *testing.B) {
 func BenchmarkZapLoggerV(b *testing.B) {
 	b.RunParallel(func(pb *testing.PB) {
 		for pb.Next() {
-			jLogger := NewJSONLogger(zap.NewExample(), nil)
+			jLogger := NewJSONLogger(nil)
 			jLogger.V(1).Info("test",
 				"str", "foo",
 				"int64-1", int64(1),

staging/src/k8s.io/component-base/logs/json/json_test.go

@@ -19,6 +19,7 @@ package logs
 import (
 	"bufio"
 	"bytes"
+	"flag"
 	"fmt"
 	"testing"
 	"time"
@@ -27,10 +28,12 @@ import (
 
 	"go.uber.org/zap"
 	"go.uber.org/zap/zapcore"
+
+	"k8s.io/klog/v2"
 )
 
-// TestInfoLoggerInfo test infologger json info format
-func TestInfoLoggerInfo(t *testing.T) {
+// TestZapLoggerInfo test ZapLogger json info format
+func TestZapLoggerInfo(t *testing.T) {
 	timeNow = func() time.Time {
 		return time.Date(1970, time.January, 1, 0, 0, 0, 123, time.UTC)
 	}
@@ -41,30 +44,29 @@ func TestInfoLoggerInfo(t *testing.T) {
 	}{
 		{
 			msg:        "test",
-			format:     "{\"v\":1,\"ts\":%f,\"msg\":\"test\",\"ns\":\"default\",\"podnum\":2}\n",
+			format:     "{\"ts\":%f,\"msg\":\"test\",\"v\":0,\"ns\":\"default\",\"podnum\":2}\n",
 			keysValues: []interface{}{"ns", "default", "podnum", 2},
 		},
 		{
 			msg:        "test for strongly typed Zap field",
-			format:     "{\"v\":3,\"ts\":%f,\"msg\":\"strongly-typed Zap Field passed to logr\"}\n{\"v\":1,\"ts\":0.000123,\"msg\":\"test for strongly typed Zap field\",\"ns\":\"default\",\"podnum\":2}\n",
+			format:     "{\"ts\":%f,\"msg\":\"strongly-typed Zap Field passed to logr\",\"v\":0}\n{\"ts\":0.000123,\"msg\":\"test for strongly typed Zap field\",\"v\":0,\"ns\":\"default\",\"podnum\":2}\n",
 			keysValues: []interface{}{"ns", "default", "podnum", 2, zap.Int("attempt", 3), "attempt", "Running", 10},
 		},
 		{
 			msg:        "test for non-string key argument",
-			format:     "{\"v\":3,\"ts\":%f,\"msg\":\"non-string key argument passed to logging, ignoring all later arguments\"}\n{\"v\":1,\"ts\":0.000123,\"msg\":\"test for non-string key argument\",\"ns\":\"default\",\"podnum\":2}\n",
+			format:     "{\"ts\":%f,\"msg\":\"non-string key argument passed to logging, ignoring all later arguments\",\"v\":0}\n{\"ts\":0.000123,\"msg\":\"test for non-string key argument\",\"v\":0,\"ns\":\"default\",\"podnum\":2}\n",
 			keysValues: []interface{}{"ns", "default", "podnum", 2, 200, "replica", "Running", 10},
 		},
 	}
 
-	for i, data := range testDataInfo {
+	for _, data := range testDataInfo {
 		var buffer bytes.Buffer
 		writer := bufio.NewWriter(&buffer)
-		var sampleInfoLogger = NewJSONLogger(zap.NewExample(), zapcore.AddSync(writer))
+		var sampleInfoLogger = NewJSONLogger(zapcore.AddSync(writer))
 		sampleInfoLogger.Info(data.msg, data.keysValues...)
 		writer.Flush()
 		logStr := buffer.String()
 		var ts float64
-		fmt.Println(i, logStr)
 		n, err := fmt.Sscanf(logStr, data.format, &ts)
 		if n != 1 || err != nil {
 			t.Errorf("log format error: %d elements, error %s:\n%s", n, err, logStr)
@@ -76,49 +78,60 @@ func TestInfoLoggerInfo(t *testing.T) {
 	}
 }
 
-// TestInfoLoggerEnabled test jsonlogger should always enabled
-func TestInfoLoggerEnabled(t *testing.T) {
-	var sampleInfoLogger = NewJSONLogger(zap.NewExample(), nil)
-	if !sampleInfoLogger.Enabled() {
-		t.Error("info logger should always enabled")
+// TestZapLoggerEnabled test ZapLogger enabled
+func TestZapLoggerEnabled(t *testing.T) {
+	var sampleInfoLogger = NewJSONLogger(nil)
+	for i := 0; i < 11; i++ {
+		if !sampleInfoLogger.V(i).Enabled() {
+			t.Errorf("V(%d).Info should be enabled", i)
+		}
 	}
 }
 
-// TestInfoLoggerInfo test infologger V set log level func
+// TestZapLoggerV test ZapLogger V set log level func
 func TestZapLoggerV(t *testing.T) {
-	var buffer bytes.Buffer
-	writer := bufio.NewWriter(&buffer)
 	timeNow = func() time.Time {
 		return time.Date(1970, time.January, 1, 0, 0, 0, 123, time.UTC)
 	}
-	var sampleInfoLogger = NewJSONLogger(zap.NewExample(), zapcore.AddSync(writer))
-	sampleInfoLogger.V(2).Info("test", "ns", "default", "podnum", 2)
-	writer.Flush()
-	logStr := buffer.String()
-	var ts float64
-	expectFormat := `{"v":1,"ts":%f,"msg":"test","ns":"default","podnum":2}`
-	n, err := fmt.Sscanf(logStr, expectFormat, &ts)
-	if n != 0 || err == nil {
-		t.Errorf("log format error: %d elements, error %s:\n%s", n, err, logStr)
-	}
-	if !assert.Empty(t, logStr) {
-		t.Errorf("Info log: %s should empty", logStr)
+
+	for i := 0; i < 11; i++ {
+		var buffer bytes.Buffer
+		writer := bufio.NewWriter(&buffer)
+		var sampleInfoLogger = NewJSONLogger(zapcore.AddSync(writer))
+		sampleInfoLogger.V(i).Info("test", "ns", "default", "podnum", 2)
+		writer.Flush()
+		logStr := buffer.String()
+		var v int
+		var expectFormat string
+		expectFormat = "{\"ts\":0.000123,\"msg\":\"test\",\"v\":%d,\"ns\":\"default\",\"podnum\":2}\n"
+		n, err := fmt.Sscanf(logStr, expectFormat, &v)
+		if n != 1 || 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)
+		}
+		expect := fmt.Sprintf(expectFormat, v)
+		if !assert.Equal(t, logStr, expect) {
+			t.Errorf("V(%d).Info has wrong format \n expect:%s\n got:%s", i, expect, logStr)
+		}
+		buffer.Reset()
 	}
 }
 
-// TestZapLoggerError test infologger json error format
+// TestZapLoggerError test ZapLogger json error format
 func TestZapLoggerError(t *testing.T) {
 	var buffer bytes.Buffer
 	writer := bufio.NewWriter(&buffer)
 	timeNow = func() time.Time {
 		return time.Date(1970, time.January, 1, 0, 0, 0, 123, time.UTC)
 	}
-	var sampleInfoLogger = NewJSONLogger(zap.NewExample(), zapcore.AddSync(writer))
+	var sampleInfoLogger = NewJSONLogger(zapcore.AddSync(writer))
 	sampleInfoLogger.Error(fmt.Errorf("ivailid namespace:%s", "default"), "wrong namespace", "ns", "default", "podnum", 2)
 	writer.Flush()
 	logStr := buffer.String()
 	var ts float64
-	expectFormat := `{"v":2,"ts":%f,"msg":"wrong namespace","ns":"default","podnum":2,"err":"ivailid namespace:default"}`
+	expectFormat := `{"ts":%f,"msg":"wrong namespace","v":0,"ns":"default","podnum":2,"err":"ivailid namespace:default"}`
 	n, err := fmt.Sscanf(logStr, expectFormat, &ts)
 	if n != 1 || err != nil {
 		t.Errorf("log format error: %d elements, error %s:\n%s", n, err, logStr)
@@ -128,3 +141,50 @@ func TestZapLoggerError(t *testing.T) {
 		t.Errorf("Info has wrong format \n expect:%s\n got:%s", expect, logStr)
 	}
 }
+
+// TestKlogV test klog -v(--verbose) func available with json logger
+func TestKlogV(t *testing.T) {
+	var buffer testBuff
+	logger := NewJSONLogger(&buffer)
+	klog.SetLogger(logger)
+	defer klog.SetLogger(nil)
+	fs := flag.FlagSet{}
+	klog.InitFlags(&fs)
+	totalLogsWritten := 0
+
+	defer fs.Set("v", "0")
+
+	for i := 0; i < 11; i++ {
+		err := fs.Set("v", fmt.Sprintf("%d", i))
+		if err != nil {
+			t.Fatalf("Failed to set verbosity")
+		}
+		for j := 0; j < 11; j++ {
+			klog.V(klog.Level(j)).Info("test")
+			logWritten := buffer.writeCount > 0
+			totalLogsWritten += buffer.writeCount
+			buffer.writeCount = 0
+			if logWritten == (i < j) {
+				t.Errorf("klog.V(%d).Info(...) wrote log when -v=%d", j, i)
+			}
+		}
+	}
+	if totalLogsWritten != 66 {
+		t.Fatalf("Unexpected number of logs written, got %d, expected 66", totalLogsWritten)
+	}
+}
+
+type testBuff struct {
+	writeCount int
+}
+
+// Sync syncs data to file
+func (b *testBuff) Sync() error {
+	return nil
+}
+
+// Write writes data to buffer
+func (b *testBuff) Write(p []byte) (int, error) {
+	b.writeCount++
+	return len(p), nil
+}

staging/src/k8s.io/component-base/logs/options.go

@@ -34,8 +34,8 @@ const (
 
 // List of logs (k8s.io/klog + k8s.io/component-base/logs) flags supported by all logging formats
 var supportedLogsFlags = map[string]struct{}{
-	"v":       {},
-	"vmodule": {},
+	"v": {},
+	// TODO: support vmodule after 1.19 Alpha
 }
 
 // Options has klog format parameters