Merge pull request #197 from pohly/klogr-output-format

klogr output format

klog.go

@@ -772,32 +772,32 @@ func (l *loggingT) printWithFileLine(s severity, logr logr.Logger, filter LogFil
 }
 
 // if loggr is specified, will call loggr.Error, otherwise output with logging module.
-func (l *loggingT) errorS(err error, loggr logr.Logger, filter LogFilter, msg string, keysAndValues ...interface{}) {
+func (l *loggingT) errorS(err error, loggr logr.Logger, filter LogFilter, depth int, msg string, keysAndValues ...interface{}) {
 	if filter != nil {
 		msg, keysAndValues = filter.FilterS(msg, keysAndValues)
 	}
 	if loggr != nil {
 		loggr.Error(err, msg, keysAndValues...)
 		return
 	}
-	l.printS(err, msg, keysAndValues...)
+	l.printS(err, depth+1, msg, keysAndValues...)
 }
 
 // if loggr is specified, will call loggr.Info, otherwise output with logging module.
-func (l *loggingT) infoS(loggr logr.Logger, filter LogFilter, msg string, keysAndValues ...interface{}) {
+func (l *loggingT) infoS(loggr logr.Logger, filter LogFilter, depth int, msg string, keysAndValues ...interface{}) {
 	if filter != nil {
 		msg, keysAndValues = filter.FilterS(msg, keysAndValues)
 	}
 	if loggr != nil {
 		loggr.Info(msg, keysAndValues...)
 		return
 	}
-	l.printS(nil, msg, keysAndValues...)
+	l.printS(nil, depth+1, msg, keysAndValues...)
 }
 
 // printS is called from infoS and errorS if loggr is not specified.
 // if err arguments is specified, will output to errorLog severity
-func (l *loggingT) printS(err error, msg string, keysAndValues ...interface{}) {
+func (l *loggingT) printS(err error, depth int, msg string, keysAndValues ...interface{}) {
 	b := &bytes.Buffer{}
 	b.WriteString(fmt.Sprintf("%q", msg))
 	if err != nil {
@@ -811,7 +811,7 @@ func (l *loggingT) printS(err error, msg string, keysAndValues ...interface{}) {
 	} else {
 		s = errorLog
 	}
-	l.printDepth(s, logging.logr, nil, 2, b)
+	l.printDepth(s, logging.logr, nil, depth+1, b)
 }
 
 const missingValue = "(MISSING)"
@@ -1359,22 +1359,28 @@ func (v Verbose) Infof(format string, args ...interface{}) {
 // See the documentation of V for usage.
 func (v Verbose) InfoS(msg string, keysAndValues ...interface{}) {
 	if v.enabled {
-		logging.infoS(v.logr, v.filter, msg, keysAndValues...)
+		logging.infoS(v.logr, v.filter, 0, msg, keysAndValues...)
 	}
 }
 
+// InfoSDepth acts as InfoS but uses depth to determine which call frame to log.
+// InfoSDepth(0, "msg") is the same as InfoS("msg").
+func InfoSDepth(depth int, msg string, keysAndValues ...interface{}) {
+	logging.infoS(logging.logr, logging.filter, depth, msg, keysAndValues...)
+}
+
 // Deprecated: Use ErrorS instead.
 func (v Verbose) Error(err error, msg string, args ...interface{}) {
 	if v.enabled {
-		logging.errorS(err, v.logr, v.filter, msg, args...)
+		logging.errorS(err, v.logr, v.filter, 0, msg, args...)
 	}
 }
 
 // ErrorS is equivalent to the global Error function, guarded by the value of v.
 // See the documentation of V for usage.
 func (v Verbose) ErrorS(err error, msg string, keysAndValues ...interface{}) {
 	if v.enabled {
-		logging.errorS(err, v.logr, v.filter, msg, keysAndValues...)
+		logging.errorS(err, v.logr, v.filter, 0, msg, keysAndValues...)
 	}
 }
 
@@ -1411,7 +1417,7 @@ func Infof(format string, args ...interface{}) {
 // output:
 // >> I1025 00:15:15.525108       1 controller_utils.go:116] "Pod status updated" pod="kubedns" status="ready"
 func InfoS(msg string, keysAndValues ...interface{}) {
-	logging.infoS(logging.logr, logging.filter, msg, keysAndValues...)
+	logging.infoS(logging.logr, logging.filter, 0, msg, keysAndValues...)
 }
 
 // Warning logs to the WARNING and INFO logs.
@@ -1472,7 +1478,13 @@ func Errorf(format string, args ...interface{}) {
 // output:
 // >> E1025 00:15:15.525108       1 controller_utils.go:114] "Failed to update pod status" err="timeout"
 func ErrorS(err error, msg string, keysAndValues ...interface{}) {
-	logging.errorS(err, logging.logr, logging.filter, msg, keysAndValues...)
+	logging.errorS(err, logging.logr, logging.filter, 0, msg, keysAndValues...)
+}
+
+// ErrorSDepth acts as ErrorS but uses depth to determine which call frame to log.
+// ErrorSDepth(0, "msg") is the same as ErrorS("msg").
+func ErrorSDepth(depth int, err error, msg string, keysAndValues ...interface{}) {
+	logging.errorS(err, logging.logr, logging.filter, depth, msg, keysAndValues...)
 }
 
 // Fatal logs to the FATAL, ERROR, WARNING, and INFO logs,

klog_test.go

@@ -822,7 +822,7 @@ func TestKRef(t *testing.T) {
 	}
 }
 
-// Test that InfoS works as advertised.
+// Test that InfoS and InfoSDepth work as advertised.
 func TestInfoS(t *testing.T) {
 	setFlags()
 	defer logging.swap(logging.newBuffers())
@@ -857,17 +857,23 @@ func TestInfoS(t *testing.T) {
 		},
 	}
 
-	for _, data := range testDataInfo {
-		logging.file[infoLog] = &flushBuffer{}
-		InfoS(data.msg, data.keysValues...)
-		var line int
-		n, err := fmt.Sscanf(contents(infoLog), data.format, &line)
-		if n != 1 || err != nil {
-			t.Errorf("log format error: %d elements, error %s:\n%s", n, err, contents(infoLog))
-		}
-		want := fmt.Sprintf(data.format, line)
-		if contents(infoLog) != want {
-			t.Errorf("InfoS has wrong format: \n got:\t%s\nwant:\t%s", contents(infoLog), want)
+	functions := []func(msg string, keyAndValues ...interface{}){
+		InfoS,
+		myInfoS,
+	}
+	for _, f := range functions {
+		for _, data := range testDataInfo {
+			logging.file[infoLog] = &flushBuffer{}
+			f(data.msg, data.keysValues...)
+			var line int
+			n, err := fmt.Sscanf(contents(infoLog), data.format, &line)
+			if n != 1 || err != nil {
+				t.Errorf("log format error: %d elements, error %s:\n%s", n, err, contents(infoLog))
+			}
+			want := fmt.Sprintf(data.format, line)
+			if contents(infoLog) != want {
+				t.Errorf("InfoS has wrong format: \n got:\t%s\nwant:\t%s", contents(infoLog), want)
+			}
 		}
 	}
 }
@@ -930,7 +936,7 @@ func TestVInfoS(t *testing.T) {
 	}
 }
 
-// Test that ErrorS works as advertised.
+// Test that ErrorS and ErrorSDepth work as advertised.
 func TestErrorS(t *testing.T) {
 	setFlags()
 	defer logging.swap(logging.newBuffers())
@@ -939,16 +945,24 @@ func TestErrorS(t *testing.T) {
 	}
 	logging.logFile = ""
 	pid = 1234
-	ErrorS(fmt.Errorf("update status failed"), "Failed to update pod status", "pod", "kubedns")
-	var line int
-	format := "E0102 15:04:05.067890    1234 klog_test.go:%d] \"Failed to update pod status\" err=\"update status failed\" pod=\"kubedns\"\n"
-	n, err := fmt.Sscanf(contents(errorLog), format, &line)
-	if n != 1 || err != nil {
-		t.Errorf("log format error: %d elements, error %s:\n%s", n, err, contents(errorLog))
+
+	functions := []func(err error, msg string, keyAndValues ...interface{}){
+		ErrorS,
+		myErrorS,
 	}
-	want := fmt.Sprintf(format, line)
-	if contents(errorLog) != want {
-		t.Errorf("ErrorS has wrong format: \n got:\t%s\nwant:\t%s", contents(errorLog), want)
+	for _, f := range functions {
+		logging.file[errorLog] = &flushBuffer{}
+		f(fmt.Errorf("update status failed"), "Failed to update pod status", "pod", "kubedns")
+		var line int
+		format := "E0102 15:04:05.067890    1234 klog_test.go:%d] \"Failed to update pod status\" err=\"update status failed\" pod=\"kubedns\"\n"
+		n, err := fmt.Sscanf(contents(errorLog), format, &line)
+		if n != 1 || err != nil {
+			t.Errorf("log format error: %d elements, error %s:\n%s", n, err, contents(errorLog))
+		}
+		want := fmt.Sprintf(format, line)
+		if contents(errorLog) != want {
+			t.Errorf("ErrorS has wrong format: \n got:\t%s\nwant:\t%s", contents(errorLog), want)
+		}
 	}
 }
 

klog_wrappers_test.go

@@ -0,0 +1,27 @@
+// Copyright 2020 The Kubernetes 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 klog
+
+// These helper functions must be in a separate source file because the
+// tests in klog_test.go compare the logged source code file name against
+// "klog_test.go". "klog_wrappers_test.go" must *not* be logged.
+
+func myInfoS(msg string, keyAndValues ...interface{}) {
+	InfoSDepth(1, msg, keyAndValues...)
+}
+
+func myErrorS(err error, msg string, keyAndValues ...interface{}) {
+	ErrorSDepth(1, err, msg, keyAndValues...)
+}

klogr/README.md

@@ -5,4 +5,15 @@ in terms of Kubernetes' [klog](https://github.com/kubernetes/klog).  This
 provides a relatively minimalist API to logging in Go, backed by a well-proven
 implementation.
 
+Because klogr was implemented before klog itself added supported for
+structured logging, the default in klogr is to serialize key/value
+pairs with JSON and log the result as text messages via klog. This
+does not work well when klog itself forwards output to a structured
+logger.
+
+Therefore the recommended approach is to let klogr pass all log
+messages through to klog and deal with structured logging there. Just
+beware that the output of klog without a structured logger is meant to
+be human-readable, in contrast to the JSON-based traditional format.
+
 This is a BETA grade implementation.

klogr/klogr.go

@@ -14,26 +14,65 @@ import (
 	"k8s.io/klog/v2"
 )
 
-// New returns a logr.Logger which is implemented by klog.
+// Option is a functional option that reconfigures the logger created with New.
+type Option func(*klogger)
+
+// Format defines how log output is produced.
+type Format string
+
+const (
+	// FormatSerialize tells klogr to turn key/value pairs into text itself
+	// before invoking klog.
+	FormatSerialize Format = "Serialize"
+
+	// FormatKlog tells klogr to pass all text messages and key/value pairs
+	// directly to klog. Klog itself then serializes in a human-readable
+	// format and optionally passes on to a structure logging backend.
+	FormatKlog Format = "Klog"
+)
+
+// WithFormat selects the output format.
+func WithFormat(format Format) Option {
+	return func(l *klogger) {
+		l.format = format
+	}
+}
+
+// New returns a logr.Logger which serializes output itself
+// and writes it via klog.
 func New() logr.Logger {
-	return klogger{
+	return NewWithOptions(WithFormat(FormatSerialize))
+}
+
+// NewWithOptions returns a logr.Logger which serializes as determined
+// by the WithFormat option and writes via klog. The default is
+// FormatKlog.
+func NewWithOptions(options ...Option) logr.Logger {
+	l := klogger{
 		level:  0,
 		prefix: "",
 		values: nil,
+		format: FormatKlog,
+	}
+	for _, option := range options {
+		option(&l)
 	}
+	return l
 }
 
 type klogger struct {
 	level  int
 	prefix string
 	values []interface{}
+	format Format
 }
 
 func (l klogger) clone() klogger {
 	return klogger{
 		level:  l.level,
 		prefix: l.prefix,
 		values: copySlice(l.values),
+		format: l.format,
 	}
 }
 
@@ -149,11 +188,20 @@ func pretty(value interface{}) string {
 
 func (l klogger) Info(msg string, kvList ...interface{}) {
 	if l.Enabled() {
-		msgStr := flatten("msg", msg)
-		trimmed := trimDuplicates(l.values, kvList)
-		fixedStr := flatten(trimmed[0]...)
-		userStr := flatten(trimmed[1]...)
-		klog.InfoDepth(framesToCaller(), l.prefix, " ", msgStr, " ", fixedStr, " ", userStr)
+		switch l.format {
+		case FormatSerialize:
+			msgStr := flatten("msg", msg)
+			trimmed := trimDuplicates(l.values, kvList)
+			fixedStr := flatten(trimmed[0]...)
+			userStr := flatten(trimmed[1]...)
+			klog.InfoDepth(framesToCaller(), l.prefix, " ", msgStr, " ", fixedStr, " ", userStr)
+		case FormatKlog:
+			trimmed := trimDuplicates(l.values, kvList)
+			if l.prefix != "" {
+				msg = l.prefix + ": " + msg
+			}
+			klog.InfoSDepth(framesToCaller(), msg, append(trimmed[0], trimmed[1]...)...)
+		}
 	}
 }
 
@@ -167,11 +215,20 @@ func (l klogger) Error(err error, msg string, kvList ...interface{}) {
 	if err != nil {
 		loggableErr = err.Error()
 	}
-	errStr := flatten("error", loggableErr)
-	trimmed := trimDuplicates(l.values, kvList)
-	fixedStr := flatten(trimmed[0]...)
-	userStr := flatten(trimmed[1]...)
-	klog.ErrorDepth(framesToCaller(), l.prefix, " ", msgStr, " ", errStr, " ", fixedStr, " ", userStr)
+	switch l.format {
+	case FormatSerialize:
+		errStr := flatten("error", loggableErr)
+		trimmed := trimDuplicates(l.values, kvList)
+		fixedStr := flatten(trimmed[0]...)
+		userStr := flatten(trimmed[1]...)
+		klog.ErrorDepth(framesToCaller(), l.prefix, " ", msgStr, " ", errStr, " ", fixedStr, " ", userStr)
+	case FormatKlog:
+		trimmed := trimDuplicates(l.values, kvList)
+		if l.prefix != "" {
+			msg = l.prefix + ": " + msg
+		}
+		klog.ErrorSDepth(framesToCaller(), err, msg, append(trimmed[0], trimmed[1]...)...)
+	}
 }
 
 func (l klogger) V(level int) logr.Logger {