From cff40a7bcc170c473c223081fd0103fd042dc44b Mon Sep 17 00:00:00 2001 From: Madhav Jivrajani Date: Sun, 30 May 2021 13:27:16 +0530 Subject: [PATCH] Add info about source code location in JSON logging - Add `EncodeCaller` field in `encoderConfig` - Use `ShortCallerEncoder` as `EncodeCaller - Add CallerKey to encoderConfig - Get frame of calling function based on what logging function is called (Info, Error, dPanic) - Using obtained frame (if obtainable), set the Caller in the zapcore.Entry to indicate source code info - Update tests to reflect the new format Fix call frame depth implementation - Implement zapLogger.WithCallDepth to implement the logr.CallDepthLogger interface - Add a custom time encoder that use timeNow() stub instead of calling it manually in a zap Entry - Update json logger unit tests and klog integration tests Signed-off-by: Madhav Jivrajani --- .../k8s.io/component-base/logs/json/json.go | 58 ++++++++++++------- .../component-base/logs/json/json_test.go | 58 ++++++++++++------- .../component-base/logs/json/klog_test.go | 57 ++++++++++-------- 3 files changed, 105 insertions(+), 68 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 fb6f93f0f2a..6c1b578f5b5 100644 --- a/staging/src/k8s.io/component-base/logs/json/json.go +++ b/staging/src/k8s.io/component-base/logs/json/json.go @@ -57,15 +57,26 @@ var zapConfig = zap.Config{ Sampling: nil, Encoding: "json", EncoderConfig: zapcore.EncoderConfig{ - MessageKey: "msg", + MessageKey: "msg", + + CallerKey: "caller", TimeKey: "ts", - EncodeTime: zapcore.EpochMillisTimeEncoder, + EncodeTime: epochMillisTimeEncoder, EncodeDuration: zapcore.StringDurationEncoder, + EncodeCaller: zapcore.ShortCallerEncoder, }, OutputPaths: []string{"stdout"}, ErrorOutputPaths: []string{"stderr"}, } +// this has the same implementation as zapcore.EpochMillisTimeEncoder but +// uses timeNow() which is stubbed out for testing purposes. +func epochMillisTimeEncoder(_ time.Time, enc zapcore.PrimitiveArrayEncoder) { + nanos := timeNow().UnixNano() + millis := float64(nanos) / float64(time.Millisecond) + enc.AppendFloat64(millis) +} + // zapLogger is a logr.Logger that uses Zap to record log. type zapLogger struct { // NB: this looks very similar to zap.SugaredLogger, but @@ -84,25 +95,17 @@ func (l *zapLogger) Enabled() bool { // Info write message to error level log func (l *zapLogger) Info(msg string, keysAndVals ...interface{}) { - entry := zapcore.Entry{ - Time: timeNow(), - Message: msg, + if checkedEntry := l.l.Check(zapcore.InfoLevel, msg); checkedEntry != nil { + checkedEntry.Write(l.handleFields(keysAndVals)...) } - 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 +// dPanic write message to DPanicLevel level log we need implement this because we need +// to have the "v" field as well. func (l *zapLogger) dPanic(msg string) { - entry := zapcore.Entry{ - Level: zapcore.DPanicLevel, - Time: timeNow(), - Message: msg, + if checkedEntry := l.l.Check(zapcore.DPanicLevel, msg); checkedEntry != nil { + checkedEntry.Write(zap.Int("v", l.lvl)) } - checkedEntry := l.l.Core().Check(entry, nil) - checkedEntry.Write(zap.Int("v", l.lvl)) } // handleFields converts a bunch of arbitrary key-value pairs into Zap fields. It takes @@ -146,13 +149,9 @@ func (l *zapLogger) handleFields(args []interface{}, additional ...zap.Field) [] // Error write log message to error level func (l *zapLogger) Error(err error, msg string, keysAndVals ...interface{}) { - entry := zapcore.Entry{ - Level: zapcore.ErrorLevel, - Time: timeNow(), - Message: msg, + if checkedEntry := l.l.Check(zap.ErrorLevel, msg); checkedEntry != nil { + checkedEntry.Write(l.handleFields(keysAndVals, handleError(err))...) } - checkedEntry := l.l.Core().Check(entry, nil) - checkedEntry.Write(l.handleFields(keysAndVals, handleError(err))...) } func handleError(err error) zap.Field { @@ -178,3 +177,18 @@ func (l *zapLogger) WithName(name string) logr.Logger { l.l = l.l.Named(name) return l } + +func (l *zapLogger) WithCallDepth(depth int) logr.Logger { + return l.newLoggerWithExtraSkip(depth) +} + +// newLoggerWithExtraSkip allows creation of loggers with variable levels of callstack skipping +func (l *zapLogger) newLoggerWithExtraSkip(callerSkip int) logr.Logger { + log := l.l.WithOptions(zap.AddCallerSkip(callerSkip)) + return &zapLogger{ + l: log, + lvl: l.lvl, + } +} + +var _ logr.CallDepthLogger = &zapLogger{} 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 b2d16217760..d16e49be965 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 @@ -20,6 +20,7 @@ import ( "bufio" "bytes" "fmt" + "strings" "testing" "time" @@ -41,22 +42,22 @@ func TestZapLoggerInfo(t *testing.T) { }{ { msg: "test", - format: "{\"ts\":%f,\"msg\":\"test\",\"v\":0,\"ns\":\"default\",\"podnum\":2}\n", + format: "{\"ts\":%f,\"caller\":\"json/json_test.go:%d\",\"msg\":\"test\",\"v\":0,\"ns\":\"default\",\"podnum\":2}\n", keysValues: []interface{}{"ns", "default", "podnum", 2}, }, { msg: "test for strongly typed Zap field", - 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", + format: "{\"ts\":%f,\"caller\":\"json/json.go:%d\",\"msg\":\"strongly-typed Zap Field passed to logr\",\"v\":0}\n{\"ts\":%f,\"caller\":\"json/json_test.go:%d\",\"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: "{\"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", + format: "{\"ts\":%f,\"caller\":\"json/json.go:%d\",\"msg\":\"non-string key argument passed to logging, ignoring all later arguments\",\"v\":0}\n{\"ts\":%f,\"caller\":\"json/json_test.go:%d\",\"msg\":\"test for non-string key argument\",\"v\":0,\"ns\":\"default\",\"podnum\":2}\n", keysValues: []interface{}{"ns", "default", "podnum", 2, 200, "replica", "Running", 10}, }, { msg: "test for duration value argument", - format: "{\"ts\":%f,\"msg\":\"test for duration value argument\",\"v\":0,\"duration\":\"5s\"}\n", + format: "{\"ts\":%f,\"caller\":\"json/json_test.go:%d\",\"msg\":\"test for duration value argument\",\"v\":0,\"duration\":\"5s\"}\n", keysValues: []interface{}{"duration", time.Duration(5 * time.Second)}, }, } @@ -68,14 +69,27 @@ func TestZapLoggerInfo(t *testing.T) { sampleInfoLogger.Info(data.msg, data.keysValues...) writer.Flush() logStr := buffer.String() - var ts float64 - 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) + + logStrLines := strings.Split(logStr, "\n") + dataFormatLines := strings.Split(data.format, "\n") + if !assert.Equal(t, len(logStrLines), len(dataFormatLines)) { + t.Errorf("Info has wrong format: no. of lines in log is incorrect \n expect:%d\n got:%d", len(dataFormatLines), len(logStrLines)) } - expect := fmt.Sprintf(data.format, ts) - if !assert.Equal(t, expect, logStr) { - t.Errorf("Info has wrong format \n expect:%s\n got:%s", expect, logStr) + + for i := range logStrLines { + if len(logStrLines[i]) == 0 && len(dataFormatLines[i]) == 0 { + continue + } + var ts float64 + var lineNo int + n, err := fmt.Sscanf(logStrLines[i], dataFormatLines[i], &ts, &lineNo) + if n != 2 || err != nil { + t.Errorf("log format error: %d elements, error %s:\n%s", n, err, logStrLines[i]) + } + expect := fmt.Sprintf(dataFormatLines[i], ts, lineNo) + if !assert.Equal(t, expect, logStrLines[i]) { + t.Errorf("Info has wrong format \n expect:%s\n got:%s", expect, logStrLines[i]) + } } } } @@ -103,17 +117,16 @@ func TestZapLoggerV(t *testing.T) { sampleInfoLogger.V(i).Info("test", "ns", "default", "podnum", 2, "time", time.Microsecond) writer.Flush() logStr := buffer.String() - var v int - var expectFormat string - expectFormat = "{\"ts\":0.000123,\"msg\":\"test\",\"v\":%d,\"ns\":\"default\",\"podnum\":2,\"time\":\"1µs\"}\n" - n, err := fmt.Sscanf(logStr, expectFormat, &v) - if n != 1 || err != nil { + var v, 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) + 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) } - expect := fmt.Sprintf(expectFormat, 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) } @@ -129,16 +142,17 @@ func TestZapLoggerError(t *testing.T) { return time.Date(1970, time.January, 1, 0, 0, 0, 123, time.UTC) } var sampleInfoLogger = NewJSONLogger(zapcore.AddSync(writer)) - sampleInfoLogger.Error(fmt.Errorf("ivailid namespace:%s", "default"), "wrong namespace", "ns", "default", "podnum", 2, "time", time.Microsecond) + sampleInfoLogger.Error(fmt.Errorf("invalid namespace:%s", "default"), "wrong namespace", "ns", "default", "podnum", 2, "time", time.Microsecond) writer.Flush() logStr := buffer.String() var ts float64 - expectFormat := `{"ts":%f,"msg":"wrong namespace","v":0,"ns":"default","podnum":2,"time":"1µs","err":"ivailid namespace:default"}` - n, err := fmt.Sscanf(logStr, expectFormat, &ts) - if n != 1 || err != nil { + var lineNo int + expectFormat := `{"ts":%f,"caller":"json/json_test.go:%d","msg":"wrong namespace","v":0,"ns":"default","podnum":2,"time":"1µs","err":"invalid namespace:default"}` + n, err := fmt.Sscanf(logStr, expectFormat, &ts, &lineNo) + if n != 2 || err != nil { t.Errorf("log format error: %d elements, error %s:\n%s", n, err, logStr) } - expect := fmt.Sprintf(expectFormat, ts) + expect := fmt.Sprintf(expectFormat, ts, lineNo) if !assert.JSONEq(t, expect, logStr) { t.Errorf("Info has wrong format \n expect:%s\n got:%s", expect, logStr) } 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 932e3a9d790..244e6302c68 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 @@ -32,6 +32,9 @@ import ( ) func TestKlogIntegration(t *testing.T) { + timeNow = func() time.Time { + return time.Date(1970, time.January, 1, 0, 0, 0, 123, time.UTC) + } fs := flag.FlagSet{} klog.InitFlags(&fs) err := fs.Set("v", fmt.Sprintf("%d", 1)) @@ -48,126 +51,126 @@ func TestKlogIntegration(t *testing.T) { fun: func() { klog.Info("test ", 1) }, - format: `{"ts":%f,"msg":"test 1\n","v":0}`, + format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test 1\n","v":0}`, }, { name: "V(1).Info", fun: func() { klog.V(1).Info("test ", 1) }, - format: `{"ts":%f,"msg":"test 1\n","v":1}`, + format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test 1\n","v":1}`, }, { name: "Infof", fun: func() { klog.Infof("test %d", 1) }, - format: `{"ts":%f,"msg":"test 1\n","v":0}`, + format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test 1\n","v":0}`, }, { name: "V(1).Infof", fun: func() { klog.V(1).Infof("test %d", 1) }, - format: `{"ts":%f,"msg":"test 1\n","v":1}`, + format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test 1\n","v":1}`, }, { name: "Infoln", fun: func() { klog.Infoln("test", 1) }, - format: `{"ts":%f,"msg":"test 1\n","v":0}`, + format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test 1\n","v":0}`, }, { name: "V(1).Infoln", fun: func() { klog.V(1).Infoln("test", 1) }, - format: `{"ts":%f,"msg":"test 1\n","v":1}`, + format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test 1\n","v":1}`, }, { name: "InfoDepth", fun: func() { klog.InfoDepth(1, "test ", 1) }, - format: `{"ts":%f,"msg":"test 1\n","v":0}`, + format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test 1\n","v":0}`, }, { name: "InfoS", fun: func() { klog.InfoS("test", "count", 1) }, - format: `{"ts":%f,"msg":"test","v":0,"count":1}`, + format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test","v":0,"count":1}`, }, { name: "V(1).InfoS", fun: func() { klog.V(1).InfoS("test", "count", 1) }, - format: `{"ts":%f,"msg":"test","v":1,"count":1}`, + format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test","v":1,"count":1}`, }, { name: "InfoSDepth", fun: func() { klog.InfoSDepth(1, "test", "count", 1) }, - format: `{"ts":%f,"msg":"test","v":0,"count":1}`, + format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test","v":0,"count":1}`, }, { name: "Warning", fun: func() { klog.Warning("test ", 1) }, - format: `{"ts":%f,"msg":"test 1\n","v":0}`, + format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test 1\n","v":0}`, }, { name: "WarningDepth", fun: func() { klog.WarningDepth(1, "test ", 1) }, - format: `{"ts":%f,"msg":"test 1\n","v":0}`, + format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test 1\n","v":0}`, }, { name: "Warningln", fun: func() { klog.Warningln("test", 1) }, - format: `{"ts":%f,"msg":"test 1\n","v":0}`, + format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test 1\n","v":0}`, }, { name: "Warningf", fun: func() { klog.Warningf("test %d", 1) }, - format: `{"ts":%f,"msg":"test 1\n","v":0}`, + format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test 1\n","v":0}`, }, { name: "Error", fun: func() { klog.Error("test ", 1) }, - format: `{"ts":%f,"msg":"test 1\n","v":0}`, + format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test 1\n","v":0}`, }, { name: "ErrorDepth", fun: func() { klog.ErrorDepth(1, "test ", 1) }, - format: `{"ts":%f,"msg":"test 1\n","v":0}`, + format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test 1\n","v":0}`, }, { name: "Errorln", fun: func() { klog.Errorln("test", 1) }, - format: `{"ts":%f,"msg":"test 1\n","v":0}`, + format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test 1\n","v":0}`, }, { name: "Errorf", fun: func() { klog.Errorf("test %d", 1) }, - format: `{"ts":%f,"msg":"test 1\n","v":0}`, + format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test 1\n","v":0}`, }, { name: "ErrorS", @@ -175,7 +178,7 @@ func TestKlogIntegration(t *testing.T) { err := errors.New("fail") klog.ErrorS(err, "test", "count", 1) }, - format: `{"ts":%f,"msg":"test","v":0,"count":1,"err":"fail"}`, + format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test","v":0,"count":1,"err":"fail"}`, }, { name: "ErrorSDepth", @@ -183,7 +186,7 @@ func TestKlogIntegration(t *testing.T) { err := errors.New("fail") klog.ErrorSDepth(1, err, "test", "count", 1) }, - format: `{"ts":%f,"msg":"test","v":0,"count":1,"err":"fail"}`, + format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test","v":0,"count":1,"err":"fail"}`, }, } for _, tc := range tcs { @@ -195,12 +198,13 @@ func TestKlogIntegration(t *testing.T) { tc.fun() var ts float64 + var lineNo int logString := strings.TrimSuffix(buffer.String(), "\n") - n, err := fmt.Sscanf(logString, tc.format, &ts) - if n != 1 || err != nil { + n, err := fmt.Sscanf(logString, tc.format, &ts, &lineNo) + if n != 2 || err != nil { t.Errorf("log format error: %d elements, error %s:\n%s", n, err, logString) } - expect := fmt.Sprintf(tc.format, ts) + expect := fmt.Sprintf(tc.format, ts, lineNo) if !assert.Equal(t, expect, logString) { t.Errorf("Info has wrong format \n expect:%s\n got:%s", expect, logString) } @@ -219,7 +223,12 @@ func TestKlogV(t *testing.T) { klog.InitFlags(&fs) totalLogsWritten := 0 - defer fs.Set("v", "0") + defer func() { + err := fs.Set("v", "0") + if err != nil { + t.Fatalf("Failed to reset verbosity to 0") + } + }() for i := 0; i < 11; i++ { err := fs.Set("v", fmt.Sprintf("%d", i))