From 8e6a2660a8688f32ee350b42e6510851e07192f8 Mon Sep 17 00:00:00 2001 From: yuzhiquan Date: Sat, 4 Jul 2020 13:36:36 +0800 Subject: [PATCH] fix json log verbose remove vmodule support; add klog v test case;some refactor update follow review comment add enabled test case, and some nit fix enabled func fix as review comment --- .../src/k8s.io/component-base/logs/json/BUILD | 1 + .../k8s.io/component-base/logs/json/json.go | 54 ++++---- .../logs/json/json_benchmark_test.go | 8 +- .../component-base/logs/json/json_test.go | 122 +++++++++++++----- .../src/k8s.io/component-base/logs/options.go | 4 +- 5 files changed, 120 insertions(+), 69 deletions(-) diff --git a/staging/src/k8s.io/component-base/logs/json/BUILD b/staging/src/k8s.io/component-base/logs/json/BUILD index 49cbe6cb8db..3fb7831c877 100644 --- a/staging/src/k8s.io/component-base/logs/json/BUILD +++ b/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", ], ) 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 3d7f9187fab..f9bb55656fa 100644 --- a/staging/src/k8s.io/component-base/logs/json/json.go +++ b/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, + l: log, } } -func int8LevelEncoder(l zapcore.Level, enc zapcore.PrimitiveArrayEncoder) { - lvl := int8(l) - if lvl < 0 { - lvl = -lvl - } - 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) } 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 7e81b0e68ef..f01c3fad346 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 @@ -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), 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 eff46a025ab..58ea5d1103e 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 @@ -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 +} diff --git a/staging/src/k8s.io/component-base/logs/options.go b/staging/src/k8s.io/component-base/logs/options.go index 56381105da9..00e62e65c8c 100644 --- a/staging/src/k8s.io/component-base/logs/options.go +++ b/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