github/kubernetes
1
0
Fork 0
mirror of https://github.com/k3s-io/kubernetes.git synced 2025-07-24 04:06:03 +00:00
Code Issues Projects Releases Wiki Activity

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

Browse Source 
Fix JSON logger verbose
This commit is contained in:
Kubernetes Prow Robot 2020-07-10 15:42:00 -07:00 committed by GitHub
commit 7ceac2baf0
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
5 changed files with 120 additions and 69 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

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

@ -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",
],
)

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

@ -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)
}

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

@ -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),

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

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

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

@ -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