Merge pull request #102437 from MadhavJivrajani/structured-logging/source-code-location

Add info about source code location in JSON logging

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{
+	if checkedEntry := l.l.Check(zapcore.InfoLevel, msg); checkedEntry != nil {
-		Time:    timeNow(),
+		checkedEntry.Write(l.handleFields(keysAndVals)...)
-		Message: msg,
 	}
-	checkedEntry := l.l.Core().Check(entry, nil)
-	checkedEntry.Write(l.handleFields(keysAndVals)...)
 }
 
-// dPanic write message to DPanicLevel level log
+// dPanic write message to DPanicLevel level log we need implement this because we need
-// we need implement this because unit test case need stub time.Now
+// to have the "v" field as well.
-// otherwise the ts field always changed
 func (l *zapLogger) dPanic(msg string) {
-	entry := zapcore.Entry{
+	if checkedEntry := l.l.Check(zapcore.DPanicLevel, msg); checkedEntry != nil {
-		Level:   zapcore.DPanicLevel,
+		checkedEntry.Write(zap.Int("v", l.lvl))
-		Time:    timeNow(),
-		Message: msg,
 	}
-	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{
+	if checkedEntry := l.l.Check(zap.ErrorLevel, msg); checkedEntry != nil {
-		Level:   zapcore.ErrorLevel,
+		checkedEntry.Write(l.handleFields(keysAndVals, handleError(err))...)
-		Time:    timeNow(),
-		Message: msg,
 	}
-	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{}

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)
+		logStrLines := strings.Split(logStr, "\n")
-		if n != 1 || err != nil {
+		dataFormatLines := strings.Split(data.format, "\n")
-			t.Errorf("log format error: %d elements, error %s:\n%s", n, err, logStr)
+		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) {
+		for i := range logStrLines {
-			t.Errorf("Info has wrong format \n expect:%s\n got:%s", expect, logStr)
+			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 v, lineNo int
-		var expectFormat string
+		expectFormat := "{\"ts\":0.000123,\"caller\":\"json/json_test.go:%d\",\"msg\":\"test\",\"v\":%d,\"ns\":\"default\",\"podnum\":2,\"time\":\"1µs\"}\n"
-		expectFormat = "{\"ts\":0.000123,\"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, &v)
+		if n != 2 || err != nil {
-		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)
+		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"}`
+	var lineNo int
-	n, err := fmt.Sscanf(logStr, expectFormat, &ts)
+	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"}`
-	if n != 1 || err != nil {
+	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)
 	}

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)
+			n, err := fmt.Sscanf(logString, tc.format, &ts, &lineNo)
-			if n != 1 || err != nil {
+			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))