From c2b4863f404c973bf185ecb3fd36e9e1e63b7a30 Mon Sep 17 00:00:00 2001 From: Pires Date: Thu, 14 Jan 2021 18:13:41 +0000 Subject: [PATCH 1/4] log: fix klog depth Signed-off-by: Pires --- log/klogv2/klogv2.go | 54 ++++++++++++++++++++++++++++++++++---------- 1 file changed, 42 insertions(+), 12 deletions(-) diff --git a/log/klogv2/klogv2.go b/log/klogv2/klogv2.go index 57bfac83c..6bf842f04 100644 --- a/log/klogv2/klogv2.go +++ b/log/klogv2/klogv2.go @@ -22,6 +22,10 @@ package klogv2 import ( + "fmt" + "sort" + "strings" + "github.com/virtual-kubelet/virtual-kubelet/log" "k8s.io/klog/v2" ) @@ -31,52 +35,64 @@ var _ log.Logger = (*adapter)(nil) // adapter implements the `log.Logger` interface for klogv2 type adapter struct { - fields map[string]interface{} + fields string } // FromKlogv2 creates a new `log.Logger` from the provided entry func FromKlogv2(fields map[string]interface{}) log.Logger { - return &adapter{fields} + return &adapter{fields: processFields(fields)} } func (l *adapter) Debug(args ...interface{}) { - klog.V(4).Info(args, l.fields) + if klog.V(4).Enabled() { + l.Info(args...) + } } func (l *adapter) Debugf(format string, args ...interface{}) { - klog.V(4).Infof(format, args, l.fields) + if klog.V(4).Enabled() { + l.Infof(format, args...) + } } func (l *adapter) Info(args ...interface{}) { - klog.Info(args, l.fields) + args = append(args, l.fields) + klog.InfoDepth(1, args...) } func (l *adapter) Infof(format string, args ...interface{}) { - klog.Infof(format, args, l.fields) + formattedArgs := fmt.Sprintf(format, args...) + klog.InfoDepth(1, formattedArgs, l.fields) } func (l *adapter) Warn(args ...interface{}) { - klog.Warning(args, l.fields) + args = append(args, l.fields) + klog.WarningDepth(1, args...) } func (l *adapter) Warnf(format string, args ...interface{}) { - klog.Warningf(format, args, l.fields) + formattedArgs := fmt.Sprintf(format, args...) + klog.WarningDepth(1, formattedArgs, l.fields) } func (l *adapter) Error(args ...interface{}) { - klog.Error(args, l.fields) + args = append(args, l.fields) + klog.ErrorDepth(1, args...) } func (l *adapter) Errorf(format string, args ...interface{}) { - klog.Errorf(format, args, l.fields) + formattedArgs := fmt.Sprintf(format, args...) + klog.ErrorDepth(1, formattedArgs, l.fields) } func (l *adapter) Fatal(args ...interface{}) { - klog.Fatal(args, l.fields) + args = append(args, l.fields) + klog.FatalDepth(1, args...) } func (l *adapter) Fatalf(format string, args ...interface{}) { - klog.Fatalf(format, args, l.fields) + formattedArgs := fmt.Sprintf(format, args...) + klog.FatalDepth(1, formattedArgs, l.fields) } // WithField adds a field to the log entry. @@ -96,3 +112,17 @@ func (l *adapter) WithFields(fields log.Fields) log.Logger { func (l *adapter) WithError(err error) log.Logger { return l.WithField("err", err) } + +// processFields prepares a string to be appended to every log call. +// This is called once to avoid costly log operations. +func processFields(fields map[string]interface{}) string { + processedFields := make([]string, 0, len(fields)) + for k, v := range fields { + processedFields = append(processedFields, fmt.Sprintf("%s=%+v", k, v)) + } + // Order fields lexically for easier reading. + sort.Strings(processedFields) + + // Resulting string forcibly starts with an empty space. + return fmt.Sprintf(" [%s]", strings.Join(processedFields, " ")) +} From 46bfb01cd45709b9927df4362ed58ad7426f2bee Mon Sep 17 00:00:00 2001 From: Pires Date: Thu, 14 Jan 2021 20:51:18 +0000 Subject: [PATCH 2/4] log: fix klogv2 With* funcs Signed-off-by: Pires --- log/klogv2/klogv2.go | 35 +++++++++++++++++++++++------------ 1 file changed, 23 insertions(+), 12 deletions(-) diff --git a/log/klogv2/klogv2.go b/log/klogv2/klogv2.go index 6bf842f04..cc54729f3 100644 --- a/log/klogv2/klogv2.go +++ b/log/klogv2/klogv2.go @@ -14,8 +14,7 @@ // Package klogv2 implements a virtual-kubelet/log.Logger using klogv2 as a backend // -// You can use this by creating a klogv2 logger and calling `FromKlogv2(fields)`. -// If you want this to be the default logger for virtual-kubelet, set `log.L` to the value returned by `FromKlogv2` +// If you want this to be the default logger for virtual-kubelet, set `log.L` to the value returned by `New(fields)` // // We recommend reading the klog conventions to build a better understanding of levels and when they should apply // https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/logging.md @@ -35,12 +34,16 @@ var _ log.Logger = (*adapter)(nil) // adapter implements the `log.Logger` interface for klogv2 type adapter struct { - fields string + rawFields map[string]interface{} + fields string } -// FromKlogv2 creates a new `log.Logger` from the provided entry -func FromKlogv2(fields map[string]interface{}) log.Logger { - return &adapter{fields: processFields(fields)} +// New creates a new `log.Logger` from the provided entry +func New(fields map[string]interface{}) log.Logger { + return &adapter{ + rawFields: fields, + fields: processFields(fields), + } } func (l *adapter) Debug(args ...interface{}) { @@ -97,20 +100,28 @@ func (l *adapter) Fatalf(format string, args ...interface{}) { // WithField adds a field to the log entry. func (l *adapter) WithField(key string, val interface{}) log.Logger { - fields := map[string]interface{}{ - key: val, - } - return FromKlogv2(fields) + return l.WithFields(map[string]interface{}{key: val}) } // WithFields adds multiple fields to a log entry. func (l *adapter) WithFields(fields log.Fields) log.Logger { - return FromKlogv2(fields) + // Clone existing fields. + newFields := make(map[string]interface{}) + for k, v := range l.rawFields { + newFields[k] = v + } + // Append new fields. + // Existing keys will be overwritten. + for k, v := range fields { + newFields[k] = v + } + + return New(fields) } // WithError adds an error to the log entry func (l *adapter) WithError(err error) log.Logger { - return l.WithField("err", err) + return l.WithFields(map[string]interface{}{"err": err}) } // processFields prepares a string to be appended to every log call. From 25b8c546a0ff396e8e15575e3218e7e3585ac902 Mon Sep 17 00:00:00 2001 From: Pires Date: Thu, 14 Jan 2021 22:41:45 +0000 Subject: [PATCH 3/4] log: process fields only on first klog call Signed-off-by: Pires --- log/klogv2/klogv2.go | 50 ++++++++++++++++++++++---------- log/klogv2/klogv2_test.go | 60 +++++++++++++++++++++++++++++++++++++++ 2 files changed, 95 insertions(+), 15 deletions(-) create mode 100644 log/klogv2/klogv2_test.go diff --git a/log/klogv2/klogv2.go b/log/klogv2/klogv2.go index cc54729f3..f34739d5f 100644 --- a/log/klogv2/klogv2.go +++ b/log/klogv2/klogv2.go @@ -24,6 +24,7 @@ import ( "fmt" "sort" "strings" + "sync" "github.com/virtual-kubelet/virtual-kubelet/log" "k8s.io/klog/v2" @@ -32,17 +33,36 @@ import ( // Ensure log.Logger is fully implemented during compile time. var _ log.Logger = (*adapter)(nil) +type fieldMap struct { + log.Fields + processedFields string + sync.Once +} + +func (f *fieldMap) String() string { + // Process if not processed before. + f.Do(func() { + // Only process if any fields have been set. + if len(f.Fields) > 0 && len(f.processedFields) == 0 { + f.processedFields = processFields(f.Fields) + } + }) + + return f.processedFields +} + // adapter implements the `log.Logger` interface for klogv2 type adapter struct { - rawFields map[string]interface{} - fields string + fields fieldMap } // New creates a new `log.Logger` from the provided entry -func New(fields map[string]interface{}) log.Logger { +func New(fields log.Fields) log.Logger { + if fields == nil { + fields = make(log.Fields) + } return &adapter{ - rawFields: fields, - fields: processFields(fields), + fields: fieldMap{Fields: fields}, } } @@ -59,43 +79,43 @@ func (l *adapter) Debugf(format string, args ...interface{}) { } func (l *adapter) Info(args ...interface{}) { - args = append(args, l.fields) + args = append(args, l.fields.String()) klog.InfoDepth(1, args...) } func (l *adapter) Infof(format string, args ...interface{}) { formattedArgs := fmt.Sprintf(format, args...) - klog.InfoDepth(1, formattedArgs, l.fields) + klog.InfoDepth(1, formattedArgs, l.fields.String()) } func (l *adapter) Warn(args ...interface{}) { - args = append(args, l.fields) + args = append(args, l.fields.String()) klog.WarningDepth(1, args...) } func (l *adapter) Warnf(format string, args ...interface{}) { formattedArgs := fmt.Sprintf(format, args...) - klog.WarningDepth(1, formattedArgs, l.fields) + klog.WarningDepth(1, formattedArgs, l.fields.String()) } func (l *adapter) Error(args ...interface{}) { - args = append(args, l.fields) + args = append(args, l.fields.String()) klog.ErrorDepth(1, args...) } func (l *adapter) Errorf(format string, args ...interface{}) { formattedArgs := fmt.Sprintf(format, args...) - klog.ErrorDepth(1, formattedArgs, l.fields) + klog.ErrorDepth(1, formattedArgs, l.fields.String()) } func (l *adapter) Fatal(args ...interface{}) { - args = append(args, l.fields) + args = append(args, l.fields.String()) klog.FatalDepth(1, args...) } func (l *adapter) Fatalf(format string, args ...interface{}) { formattedArgs := fmt.Sprintf(format, args...) - klog.FatalDepth(1, formattedArgs, l.fields) + klog.FatalDepth(1, formattedArgs, l.fields.String()) } // WithField adds a field to the log entry. @@ -106,8 +126,8 @@ func (l *adapter) WithField(key string, val interface{}) log.Logger { // WithFields adds multiple fields to a log entry. func (l *adapter) WithFields(fields log.Fields) log.Logger { // Clone existing fields. - newFields := make(map[string]interface{}) - for k, v := range l.rawFields { + newFields := make(log.Fields) + for k, v := range l.fields.Fields { newFields[k] = v } // Append new fields. diff --git a/log/klogv2/klogv2_test.go b/log/klogv2/klogv2_test.go new file mode 100644 index 000000000..85c6fd169 --- /dev/null +++ b/log/klogv2/klogv2_test.go @@ -0,0 +1,60 @@ +// Copyright © 2021 The virtual-kubelet authors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. +package klogv2 + +import ( + "testing" + + "github.com/virtual-kubelet/virtual-kubelet/log" +) + +func TestFieldMap_String(t *testing.T) { + var tests = []struct { + fields fieldMap + expected string + }{ + { + fieldMap{Fields: nil}, + "", + }, + { + fieldMap{Fields: make(log.Fields)}, + "", + }, + { + fieldMap{Fields: map[string]interface{}{"one": 1}}, + " [one=1]", + }, + { + fieldMap{Fields: map[string]interface{}{"one": 1, "two": 2}}, + " [one=1 two=2]", + }, + } + + for _, tt := range tests { + // Assert fields haven't been processed yet. + if len(tt.fields.processedFields) > 0 { + t.Fatal("fields shouldn't have been processed yet") + } + // Assert fields have been processed, if any. + actual := tt.fields.String() + if len(tt.fields.Fields) > 0 && len(tt.fields.processedFields) == 0 { + t.Fatal("fields should have been processed by now") + } + // Assert processFields yields desired results. + if actual != tt.expected { + t.Fatalf("expected: %s, got: %s", actual, tt.expected) + } + } +} From cb0e18e6a12c59f3e70470cb5257f094f91b2c31 Mon Sep 17 00:00:00 2001 From: Pires Date: Fri, 15 Jan 2021 18:47:50 +0000 Subject: [PATCH 4/4] log: refactor klogv2 tests Signed-off-by: Pires --- log/klogv2/klogv2_test.go | 51 ++++++++++++++++++++++----------------- 1 file changed, 29 insertions(+), 22 deletions(-) diff --git a/log/klogv2/klogv2_test.go b/log/klogv2/klogv2_test.go index 85c6fd169..625dbe034 100644 --- a/log/klogv2/klogv2_test.go +++ b/log/klogv2/klogv2_test.go @@ -21,40 +21,47 @@ import ( func TestFieldMap_String(t *testing.T) { var tests = []struct { - fields fieldMap + desc string + fields *fieldMap expected string }{ { - fieldMap{Fields: nil}, - "", + desc: "fieldMap with nil fields", + fields: &fieldMap{Fields: nil}, + expected: "", }, { - fieldMap{Fields: make(log.Fields)}, - "", + desc: "fieldMap with empty fields", + fields: &fieldMap{Fields: make(log.Fields)}, + expected: "", }, { - fieldMap{Fields: map[string]interface{}{"one": 1}}, - " [one=1]", + desc: "fieldMap with single field", + fields: &fieldMap{Fields: map[string]interface{}{"one": 1}}, + expected: " [one=1]", }, { - fieldMap{Fields: map[string]interface{}{"one": 1, "two": 2}}, - " [one=1 two=2]", + desc: "fieldMap with two fields", + fields: &fieldMap{Fields: map[string]interface{}{"one": 1, "two": 2}}, + expected: " [one=1 two=2]", }, } for _, tt := range tests { - // Assert fields haven't been processed yet. - if len(tt.fields.processedFields) > 0 { - t.Fatal("fields shouldn't have been processed yet") - } - // Assert fields have been processed, if any. - actual := tt.fields.String() - if len(tt.fields.Fields) > 0 && len(tt.fields.processedFields) == 0 { - t.Fatal("fields should have been processed by now") - } - // Assert processFields yields desired results. - if actual != tt.expected { - t.Fatalf("expected: %s, got: %s", actual, tt.expected) - } + t.Run(tt.desc, func(t *testing.T) { + // Assert fields haven't been processed yet. + if len(tt.fields.processedFields) > 0 { + t.Fatal("fields shouldn't have been processed yet") + } + // Assert fields have been processed, if any. + actual := tt.fields.String() + if len(tt.fields.Fields) > 0 && len(tt.fields.processedFields) == 0 { + t.Fatal("fields should have been processed by now") + } + // Assert processFields yields desired results. + if actual != tt.expected { + t.Fatalf("expected: %s, got: %s", actual, tt.expected) + } + }) } }