diff --git a/log/klogv2/klogv2.go b/log/klogv2/klogv2.go index 57bfac83c..f34739d5f 100644 --- a/log/klogv2/klogv2.go +++ b/log/klogv2/klogv2.go @@ -14,14 +14,18 @@ // 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 package klogv2 import ( + "fmt" + "sort" + "strings" + "sync" + "github.com/virtual-kubelet/virtual-kubelet/log" "k8s.io/klog/v2" ) @@ -29,70 +33,127 @@ import ( // Ensure log.Logger is fully implemented during compile time. var _ log.Logger = (*adapter)(nil) -// adapter implements the `log.Logger` interface for klogv2 -type adapter struct { - fields map[string]interface{} +type fieldMap struct { + log.Fields + processedFields string + sync.Once } -// FromKlogv2 creates a new `log.Logger` from the provided entry -func FromKlogv2(fields map[string]interface{}) log.Logger { - return &adapter{fields} +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 { + fields fieldMap +} + +// New creates a new `log.Logger` from the provided entry +func New(fields log.Fields) log.Logger { + if fields == nil { + fields = make(log.Fields) + } + return &adapter{ + fields: fieldMap{Fields: 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.String()) + 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.String()) } func (l *adapter) Warn(args ...interface{}) { - klog.Warning(args, l.fields) + args = append(args, l.fields.String()) + 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.String()) } func (l *adapter) Error(args ...interface{}) { - klog.Error(args, l.fields) + args = append(args, l.fields.String()) + 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.String()) } func (l *adapter) Fatal(args ...interface{}) { - klog.Fatal(args, l.fields) + args = append(args, l.fields.String()) + 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.String()) } // 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(log.Fields) + for k, v := range l.fields.Fields { + 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. +// 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, " ")) } diff --git a/log/klogv2/klogv2_test.go b/log/klogv2/klogv2_test.go new file mode 100644 index 000000000..625dbe034 --- /dev/null +++ b/log/klogv2/klogv2_test.go @@ -0,0 +1,67 @@ +// 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 { + desc string + fields *fieldMap + expected string + }{ + { + desc: "fieldMap with nil fields", + fields: &fieldMap{Fields: nil}, + expected: "", + }, + { + desc: "fieldMap with empty fields", + fields: &fieldMap{Fields: make(log.Fields)}, + expected: "", + }, + { + desc: "fieldMap with single field", + fields: &fieldMap{Fields: map[string]interface{}{"one": 1}}, + expected: " [one=1]", + }, + { + desc: "fieldMap with two fields", + fields: &fieldMap{Fields: map[string]interface{}{"one": 1, "two": 2}}, + expected: " [one=1 two=2]", + }, + } + + for _, tt := range tests { + 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) + } + }) + } +}