Repository: kubernetes/klog
Pull request #363 (2023-01-24 10:48:58)

textlogger write through
**What this PR does / why we need it**:

https://github.com/kubernetes/kubernetes/pull/114672 uses the textlogger for output routing instead of the legacy code in klog. However, this changes the output for unstructured output (gets quoted) and makes it slower (double encoding).

To avoid both, this PR adds an API for setting a logger that can take formatted data from klog and then writes it directly.

**Release note**:
```release-note
NONE
```


Patch:
diff --git a/contextual.go b/contextual.go
index 2428963..005513f 100644
--- a/contextual.go
+++ b/contextual.go
@@ -70,11 +70,14 @@ func SetLogger(logger logr.Logger) {
 // routing log entries through klogr into klog and then into the actual Logger
 // backend.
 func SetLoggerWithOptions(logger logr.Logger, opts ...LoggerOption) {
-	logging.logger = &logger
 	logging.loggerOptions = loggerOptions{}
 	for _, opt := range opts {
 		opt(&logging.loggerOptions)
 	}
+	logging.logger = &logWriter{
+		Logger:          logger,
+		writeKlogBuffer: logging.loggerOptions.writeKlogBuffer,
+	}
 }
 
 // ContextualLogger determines whether the logger passed to
@@ -93,6 +96,22 @@ func FlushLogger(flush func()) LoggerOption {
 	}
 }
 
+// WriteKlogBuffer sets a callback that will be invoked by klog to write output
+// produced by non-structured log calls like Infof.
+//
+// The buffer will contain exactly the same data that klog normally would write
+// into its own output stream(s). In particular this includes the header, if
+// klog is configured to write one. The callback then can divert that data into
+// its own output streams. The buffer may or may not end in a line break.
+//
+// Without such a callback, klog will call the logger's Info or Error method
+// with just the message string (i.e. no header).
+func WriteKlogBuffer(write func([]byte)) LoggerOption {
+	return func(o *loggerOptions) {
+		o.writeKlogBuffer = write
+	}
+}
+
 // LoggerOption implements the functional parameter paradigm for
 // SetLoggerWithOptions.
 type LoggerOption func(o *loggerOptions)
@@ -100,6 +119,13 @@ type LoggerOption func(o *loggerOptions)
 type loggerOptions struct {
 	contextualLogger bool
 	flush            func()
+	writeKlogBuffer  func([]byte)
+}
+
+// logWriter combines a logger (always set) with a write callback (optional).
+type logWriter struct {
+	Logger
+	writeKlogBuffer func([]byte)
 }
 
 // ClearLogger removes a backing Logger implementation if one was set earlier
@@ -152,7 +178,7 @@ func Background() Logger {
 	if logging.loggerOptions.contextualLogger {
 		// Is non-nil because logging.loggerOptions.contextualLogger is
 		// only true if a logger was set.
-		return *logging.logger
+		return logging.logger.Logger
 	}
 
 	return klogLogger
diff --git a/klog.go b/klog.go
index c5d98ad..466eeaf 100644
--- a/klog.go
+++ b/klog.go
@@ -91,8 +91,6 @@ import (
 	"sync/atomic"
 	"time"
 
-	"github.com/go-logr/logr"
-
 	"k8s.io/klog/v2/internal/buffer"
 	"k8s.io/klog/v2/internal/clock"
 	"k8s.io/klog/v2/internal/dbg"
@@ -453,7 +451,7 @@ type settings struct {
 
 	// logger is the global Logger chosen by users of klog, nil if
 	// none is available.
-	logger *Logger
+	logger *logWriter
 
 	// loggerOptions contains the options that were supplied for
 	// globalLogger.
@@ -525,6 +523,11 @@ func (s settings) deepCopy() settings {
 	}
 	s.vmodule.filter = filter
 
+	if s.logger != nil {
+		logger := *s.logger
+		s.logger = &logger
+	}
+
 	return s
 }
 
@@ -668,15 +671,16 @@ func (l *loggingT) formatHeader(s severity.Severity, file string, line int) *buf
 	return buf
 }
 
-func (l *loggingT) println(s severity.Severity, logger *logr.Logger, filter LogFilter, args ...interface{}) {
+func (l *loggingT) println(s severity.Severity, logger *logWriter, filter LogFilter, args ...interface{}) {
 	l.printlnDepth(s, logger, filter, 1, args...)
 }
 
-func (l *loggingT) printlnDepth(s severity.Severity, logger *logr.Logger, filter LogFilter, depth int, args ...interface{}) {
+func (l *loggingT) printlnDepth(s severity.Severity, logger *logWriter, filter LogFilter, depth int, args ...interface{}) {
 	buf, file, line := l.header(s, depth)
-	// if logger is set, we clear the generated header as we rely on the backing
-	// logger implementation to print headers
-	if logger != nil {
+	// If a logger is set and doesn't support writing a formatted buffer,
+	// we clear the generated header as we rely on the backing
+	// logger implementation to print headers.
+	if logger != nil && logger.writeKlogBuffer == nil {
 		buffer.PutBuffer(buf)
 		buf = buffer.GetBuffer()
 	}
@@ -687,15 +691,16 @@ func (l *loggingT) printlnDepth(s severity.Severity, logger *logr.Logger, filter
 	l.output(s, logger, buf, depth, file, line, false)
 }
 
-func (l *loggingT) print(s severity.Severity, logger *logr.Logger, filter LogFilter, args ...interface{}) {
+func (l *loggingT) print(s severity.Severity, logger *logWriter, filter LogFilter, args ...interface{}) {
 	l.printDepth(s, logger, filter, 1, args...)
 }
 
-func (l *loggingT) printDepth(s severity.Severity, logger *logr.Logger, filter LogFilter, depth int, args ...interface{}) {
+func (l *loggingT) printDepth(s severity.Severity, logger *logWriter, filter LogFilter, depth int, args ...interface{}) {
 	buf, file, line := l.header(s, depth)
-	// if logr is set, we clear the generated header as we rely on the backing
-	// logr implementation to print headers
-	if logger != nil {
+	// If a logger is set and doesn't support writing a formatted buffer,
+	// we clear the generated header as we rely on the backing
+	// logger implementation to print headers.
+	if logger != nil && logger.writeKlogBuffer == nil {
 		buffer.PutBuffer(buf)
 		buf = buffer.GetBuffer()
 	}
@@ -709,15 +714,16 @@ func (l *loggingT) printDepth(s severity.Severity, logger *logr.Logger, filter L
 	l.output(s, logger, buf, depth, file, line, false)
 }
 
-func (l *loggingT) printf(s severity.Severity, logger *logr.Logger, filter LogFilter, format string, args ...interface{}) {
+func (l *loggingT) printf(s severity.Severity, logger *logWriter, filter LogFilter, format string, args ...interface{}) {
 	l.printfDepth(s, logger, filter, 1, format, args...)
 }
 
-func (l *loggingT) printfDepth(s severity.Severity, logger *logr.Logger, filter LogFilter, depth int, format string, args ...interface{}) {
+func (l *loggingT) printfDepth(s severity.Severity, logger *logWriter, filter LogFilter, depth int, format string, args ...interface{}) {
 	buf, file, line := l.header(s, depth)
-	// if logr is set, we clear the generated header as we rely on the backing
-	// logr implementation to print headers
-	if logger != nil {
+	// If a logger is set and doesn't support writing a formatted buffer,
+	// we clear the generated header as we rely on the backing
+	// logger implementation to print headers.
+	if logger != nil && logger.writeKlogBuffer == nil {
 		buffer.PutBuffer(buf)
 		buf = buffer.GetBuffer()
 	}
@@ -734,11 +740,12 @@ func (l *loggingT) printfDepth(s severity.Severity, logger *logr.Logger, filter
 // printWithFileLine behaves like print but uses the provided file and line number.  If
 // alsoLogToStderr is true, the log message always appears on standard error; it
 // will also appear in the log file unless --logtostderr is set.
-func (l *loggingT) printWithFileLine(s severity.Severity, logger *logr.Logger, filter LogFilter, file string, line int, alsoToStderr bool, args ...interface{}) {
+func (l *loggingT) printWithFileLine(s severity.Severity, logger *logWriter, filter LogFilter, file string, line int, alsoToStderr bool, args ...interface{}) {
 	buf := l.formatHeader(s, file, line)
-	// if logr is set, we clear the generated header as we rely on the backing
-	// logr implementation to print headers
-	if logger != nil {
+	// If a logger is set and doesn't support writing a formatted buffer,
+	// we clear the generated header as we rely on the backing
+	// logger implementation to print headers.
+	if logger != nil && logger.writeKlogBuffer == nil {
 		buffer.PutBuffer(buf)
 		buf = buffer.GetBuffer()
 	}
@@ -753,7 +760,7 @@ func (l *loggingT) printWithFileLine(s severity.Severity, logger *logr.Logger, f
 }
 
 // if loggr is specified, will call loggr.Error, otherwise output with logging module.
-func (l *loggingT) errorS(err error, logger *logr.Logger, filter LogFilter, depth int, msg string, keysAndValues ...interface{}) {
+func (l *loggingT) errorS(err error, logger *logWriter, filter LogFilter, depth int, msg string, keysAndValues ...interface{}) {
 	if filter != nil {
 		msg, keysAndValues = filter.FilterS(msg, keysAndValues)
 	}
@@ -765,7 +772,7 @@ func (l *loggingT) errorS(err error, logger *logr.Logger, filter LogFilter, dept
 }
 
 // if loggr is specified, will call loggr.Info, otherwise output with logging module.
-func (l *loggingT) infoS(logger *logr.Logger, filter LogFilter, depth int, msg string, keysAndValues ...interface{}) {
+func (l *loggingT) infoS(logger *logWriter, filter LogFilter, depth int, msg string, keysAndValues ...interface{}) {
 	if filter != nil {
 		msg, keysAndValues = filter.FilterS(msg, keysAndValues)
 	}
@@ -846,7 +853,7 @@ func LogToStderr(stderr bool) {
 }
 
 // output writes the data to the log files and releases the buffer.
-func (l *loggingT) output(s severity.Severity, log *logr.Logger, buf *buffer.Buffer, depth int, file string, line int, alsoToStderr bool) {
+func (l *loggingT) output(s severity.Severity, logger *logWriter, buf *buffer.Buffer, depth int, file string, line int, alsoToStderr bool) {
 	var isLocked = true
 	l.mu.Lock()
 	defer func() {
@@ -862,13 +869,17 @@ func (l *loggingT) output(s severity.Severity, log *logr.Logger, buf *buffer.Buf
 		}
 	}
 	data := buf.Bytes()
-	if log != nil {
-		// TODO: set 'severity' and caller information as structured log info
-		// keysAndValues := []interface{}{"severity", severityName[s], "file", file, "line", line}
-		if s == severity.ErrorLog {
-			logging.logger.WithCallDepth(depth+3).Error(nil, string(data))
+	if logger != nil {
+		if logger.writeKlogBuffer != nil {
+			logger.writeKlogBuffer(data)
 		} else {
-			log.WithCallDepth(depth + 3).Info(string(data))
+			// TODO: set 'severity' and caller information as structured log info
+			// keysAndValues := []interface{}{"severity", severityName[s], "file", file, "line", line}
+			if s == severity.ErrorLog {
+				logger.WithCallDepth(depth+3).Error(nil, string(data))
+			} else {
+				logger.WithCallDepth(depth + 3).Info(string(data))
+			}
 		}
 	} else if l.toStderr {
 		os.Stderr.Write(data)
@@ -1277,7 +1288,7 @@ func (l *loggingT) setV(pc uintptr) Level {
 // See the documentation of V for more information.
 type Verbose struct {
 	enabled bool
-	logr    *logr.Logger
+	logger  *logWriter
 }
 
 func newVerbose(level Level, b bool) Verbose {
@@ -1285,7 +1296,7 @@ func newVerbose(level Level, b bool) Verbose {
 		return Verbose{b, nil}
 	}
 	v := logging.logger.V(int(level))
-	return Verbose{b, &v}
+	return Verbose{b, &logWriter{Logger: v, writeKlogBuffer: logging.loggerOptions.writeKlogBuffer}}
 }
 
 // V reports whether verbosity at the call site is at least the requested level.
@@ -1359,7 +1370,7 @@ func (v Verbose) Enabled() bool {
 // See the documentation of V for usage.
 func (v Verbose) Info(args ...interface{}) {
 	if v.enabled {
-		logging.print(severity.InfoLog, v.logr, logging.filter, args...)
+		logging.print(severity.InfoLog, v.logger, logging.filter, args...)
 	}
 }
 
@@ -1367,7 +1378,7 @@ func (v Verbose) Info(args ...interface{}) {
 // See the documentation of V for usage.
 func (v Verbose) InfoDepth(depth int, args ...interface{}) {
 	if v.enabled {
-		logging.printDepth(severity.InfoLog, v.logr, logging.filter, depth, args...)
+		logging.printDepth(severity.InfoLog, v.logger, logging.filter, depth, args...)
 	}
 }
 
@@ -1375,7 +1386,7 @@ func (v Verbose) InfoDepth(depth int, args ...interface{}) {
 // See the documentation of V for usage.
 func (v Verbose) Infoln(args ...interface{}) {
 	if v.enabled {
-		logging.println(severity.InfoLog, v.logr, logging.filter, args...)
+		logging.println(severity.InfoLog, v.logger, logging.filter, args...)
 	}
 }
 
@@ -1383,7 +1394,7 @@ func (v Verbose) Infoln(args ...interface{}) {
 // See the documentation of V for usage.
 func (v Verbose) InfolnDepth(depth int, args ...interface{}) {
 	if v.enabled {
-		logging.printlnDepth(severity.InfoLog, v.logr, logging.filter, depth, args...)
+		logging.printlnDepth(severity.InfoLog, v.logger, logging.filter, depth, args...)
 	}
 }
 
@@ -1391,7 +1402,7 @@ func (v Verbose) InfolnDepth(depth int, args ...interface{}) {
 // See the documentation of V for usage.
 func (v Verbose) Infof(format string, args ...interface{}) {
 	if v.enabled {
-		logging.printf(severity.InfoLog, v.logr, logging.filter, format, args...)
+		logging.printf(severity.InfoLog, v.logger, logging.filter, format, args...)
 	}
 }
 
@@ -1399,7 +1410,7 @@ func (v Verbose) Infof(format string, args ...interface{}) {
 // See the documentation of V for usage.
 func (v Verbose) InfofDepth(depth int, format string, args ...interface{}) {
 	if v.enabled {
-		logging.printfDepth(severity.InfoLog, v.logr, logging.filter, depth, format, args...)
+		logging.printfDepth(severity.InfoLog, v.logger, logging.filter, depth, format, args...)
 	}
 }
 
@@ -1407,7 +1418,7 @@ func (v Verbose) InfofDepth(depth int, 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, logging.filter, 0, msg, keysAndValues...)
+		logging.infoS(v.logger, logging.filter, 0, msg, keysAndValues...)
 	}
 }
 
@@ -1421,14 +1432,14 @@ func InfoSDepth(depth int, msg string, keysAndValues ...interface{}) {
 // See the documentation of V for usage.
 func (v Verbose) InfoSDepth(depth int, msg string, keysAndValues ...interface{}) {
 	if v.enabled {
-		logging.infoS(v.logr, logging.filter, depth, msg, keysAndValues...)
+		logging.infoS(v.logger, 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, logging.filter, 0, msg, args...)
+		logging.errorS(err, v.logger, logging.filter, 0, msg, args...)
 	}
 }
 
@@ -1436,7 +1447,7 @@ func (v Verbose) Error(err error, msg string, args ...interface{}) {
 // 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, logging.filter, 0, msg, keysAndValues...)
+		logging.errorS(err, v.logger, logging.filter, 0, msg, keysAndValues...)
 	}
 }
 
diff --git a/textlogger/textlogger.go b/textlogger/textlogger.go
index be946e0..b53b3b7 100644
--- a/textlogger/textlogger.go
+++ b/textlogger/textlogger.go
@@ -134,6 +134,10 @@ func (l *tlogger) print(err error, s severity.Severity, msg string, kvList []int
 	l.config.co.output.Write(b.Bytes())
 }
 
+func (l *tlogger) WriteKlogBuffer(data []byte) {
+	l.config.co.output.Write(data)
+}
+
 // WithName returns a new logr.Logger with the specified name appended.  klogr
 // uses '/' characters to separate name elements.  Callers should not pass '/'
 // in the provided name string, but this library does not actually enforce that.
@@ -152,5 +156,15 @@ func (l *tlogger) WithValues(kvList ...interface{}) logr.LogSink {
 	return &new
 }
 
+// KlogBufferWriter is implemented by the textlogger LogSink.
+type KlogBufferWriter interface {
+	// WriteKlogBuffer takes a pre-formatted buffer prepared by klog and
+	// writes it unchanged to the output stream. Can be used with
+	// klog.WriteKlogBuffer when setting a logger through
+	// klog.SetLoggerWithOptions.
+	WriteKlogBuffer([]byte)
+}
+
 var _ logr.LogSink = &tlogger{}
 var _ logr.CallDepthLogSink = &tlogger{}
+var _ KlogBufferWriter = &tlogger{}


Test patch:
diff --git a/klog_test.go b/klog_test.go
index 96f337a..58eeb26 100644
--- a/klog_test.go
+++ b/klog_test.go
@@ -2196,7 +2196,7 @@ func TestSettingsDeepCopy(t *testing.T) {
 	logger := logr.Discard()
 
 	settings := settings{
-		logger: &logger,
+		logger: &logWriter{Logger: logger},
 		vmodule: moduleSpec{
 			filter: []modulePat{
 				{pattern: "a"},
diff --git a/test/output.go b/test/output.go
index 4dc52f7..ecba5d4 100644
--- a/test/output.go
+++ b/test/output.go
@@ -39,6 +39,7 @@ import (
 	"github.com/go-logr/logr"
 
 	"k8s.io/klog/v2"
+	"k8s.io/klog/v2/textlogger"
 )
 
 // InitKlog must be called in a test to configure klog for testing.
@@ -577,7 +578,7 @@ func Output(t *testing.T, config OutputConfig) {
 
 			if config.AsBackend {
 				testOutput(t, printWithKlogLine-1, func(buffer *bytes.Buffer) {
-					klog.SetLogger(config.NewLogger(buffer, 10, test.vmodule))
+					setLogger(config.NewLogger(buffer, 10, test.vmodule))
 					printWithKlog(test)
 				})
 				return
@@ -765,10 +766,11 @@ func Output(t *testing.T, config OutputConfig) {
 		for i, test := range tests {
 			t.Run(test.name, func(t *testing.T) {
 				var buffer bytes.Buffer
+				haveWriteKlogBuffer := false
 				if config.NewLogger == nil {
 					klog.SetOutput(&buffer)
 				} else {
-					klog.SetLogger(config.NewLogger(&buffer, 10, ""))
+					haveWriteKlogBuffer = setLogger(config.NewLogger(&buffer, 10, ""))
 					defer klog.ClearLogger()
 				}
 				test.logFunc()
@@ -789,6 +791,7 @@ func Output(t *testing.T, config OutputConfig) {
 				// result, including a trailing newline, to
 				// Logger.Info.
 				if config.NewLogger != nil &&
+					!haveWriteKlogBuffer &&
 					!strings.HasSuffix(test.name, "S") &&
 					!strings.HasSuffix(test.name, "SDepth") {
 					// klog: I output.go:<LINE>] hello world
@@ -851,7 +854,7 @@ func Benchmark(b *testing.B, config OutputConfig) {
 			}
 
 			if config.AsBackend {
-				klog.SetLogger(config.NewLogger(io.Discard, 10, ""))
+				setLogger(config.NewLogger(io.Discard, 10, ""))
 				for i := 0; i < b.N; i++ {
 					printWithKlog(test)
 				}
@@ -871,6 +874,17 @@ func Benchmark(b *testing.B, config OutputConfig) {
 	}
 }
 
+func setLogger(logger logr.Logger) bool {
+	haveWriteKlogBuffer := false
+	var opts []klog.LoggerOption
+	if writer, ok := logger.GetSink().(textlogger.KlogBufferWriter); ok {
+		opts = append(opts, klog.WriteKlogBuffer(writer.WriteKlogBuffer))
+		haveWriteKlogBuffer = true
+	}
+	klog.SetLoggerWithOptions(logger, opts...)
+	return haveWriteKlogBuffer
+}
+
 func copySlice(in []interface{}) []interface{} {
 	return append([]interface{}{}, in...)
 }