contextual logging

contextual.go

@@ -0,0 +1,246 @@
+/*
+Copyright 2021 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
+
+import (
+	"context"
+
+	"github.com/go-logr/logr"
+)
+
+// This file provides the implementation of
+// https://github.com/kubernetes/enhancements/tree/master/keps/sig-instrumentation/1602-structured-logging
+//
+// SetLogger and ClearLogger were originally added to klog.go and got moved
+// here. Contextual logging adds a way to retrieve a Logger for direct logging
+// without the logging calls in klog.go.
+//
+// The global variables are expected to be modified only during sequential
+// parts of a program (init, serial tests) and therefore are not protected by
+// mutex locking.
+
+var (
+	// contextualLoggingEnabled controls whether contextual logging is
+	// active. Disabling it may have some small performance benefit.
+	contextualLoggingEnabled = true
+
+	// globalLogger is the global Logger chosen by users of klog, nil if
+	// none is available.
+	globalLogger *Logger
+
+	// contextualLogger defines whether globalLogger may get called
+	// directly.
+	contextualLogger bool
+
+	// klogLogger is used as fallback for logging through the normal klog code
+	// when no Logger is set.
+	klogLogger logr.Logger = logr.New(&klogger{})
+)
+
+// SetLogger sets a Logger implementation that will be used as backing
+// implementation of the traditional klog log calls. klog will do its own
+// verbosity checks before calling logger.V().Info. logger.Error is always
+// called, regardless of the klog verbosity settings.
+//
+// If set, all log lines will be suppressed from the regular output, and
+// redirected to the logr implementation.
+// Use as:
+//   ...
+//   klog.SetLogger(zapr.NewLogger(zapLog))
+//
+// To remove a backing logr implemention, use ClearLogger. Setting an
+// empty logger with SetLogger(logr.Logger{}) does not work.
+//
+// Modifying the logger is not thread-safe and should be done while no other
+// goroutines invoke log calls, usually during program initialization.
+func SetLogger(logger logr.Logger) {
+	SetLoggerWithOptions(logger)
+}
+
+// SetLoggerWithOptions is a more flexible version of SetLogger. Without
+// additional options, it behaves exactly like SetLogger. By passing
+// ContextualLogger(true) as option, it can be used to set a logger that then
+// will also get called directly by applications which retrieve it via
+// FromContext, Background, or TODO.
+//
+// Supporting direct calls is recommended because it avoids the overhead of
+// routing log entries through klogr into klog and then into the actual Logger
+// backend.
+//
+// Experimental
+//
+// Notice: This function is EXPERIMENTAL and may be changed or removed in a
+// later release.
+func SetLoggerWithOptions(logger logr.Logger, opts ...LoggerOption) {
+	globalLogger = &logger
+	var o loggerOptions
+	for _, opt := range opts {
+		opt(&o)
+	}
+	contextualLogger = o.contextualLogger
+}
+
+// ContextualLogger determines whether the logger passed to
+// SetLoggerWithOptions may also get called directly. Such a logger cannot rely
+// on verbosity checking in klog.
+//
+// Experimental
+//
+// Notice: This function is EXPERIMENTAL and may be changed or removed in a
+// later release.
+func ContextualLogger(enabled bool) LoggerOption {
+	return func(o *loggerOptions) {
+		o.contextualLogger = enabled
+	}
+}
+
+// LoggerOption implements the functional parameter paradigm for
+// SetLoggerWithOptions.
+//
+// Experimental
+//
+// Notice: This type is EXPERIMENTAL and may be changed or removed in a
+// later release.
+type LoggerOption func(o *loggerOptions)
+
+type loggerOptions struct {
+	contextualLogger bool
+}
+
+// SetContextualLogger does the same as SetLogger, but in addition the
+// logger may also get called directly by code that retrieves it
+// with FromContext, TODO or Background. The logger therefore must
+// implements its own verbosity checking.
+func SetContextualLogger(logger logr.Logger) {
+	globalLogger = &logger
+	contextualLogger = true
+}
+
+// ClearLogger removes a backing Logger implementation if one was set earlier
+// with SetLogger.
+//
+// Modifying the logger is not thread-safe and should be done while no other
+// goroutines invoke log calls, usually during program initialization.
+func ClearLogger() {
+	globalLogger = nil
+}
+
+// EnableContextualLogging controls whether contextual logging is enabled.
+// By default it is enabled. When disabled, FromContext avoids looking up
+// the logger in the context and always returns the global logger.
+// LoggerWithValues, LoggerWithName, and NewContext become no-ops
+// and return their input logger respectively context. This may be useful
+// to avoid the additional overhead for contextual logging.
+//
+// This must be called during initialization before goroutines are started.
+//
+// Experimental
+//
+// Notice: This function is EXPERIMENTAL and may be changed or removed in a
+// later release.
+func EnableContextualLogging(enabled bool) {
+	contextualLoggingEnabled = enabled
+}
+
+// FromContext retrieves a logger set by the caller or, if not set,
+// falls back to the program's global logger (a Logger instance or klog
+// itself).
+//
+// Experimental
+//
+// Notice: This function is EXPERIMENTAL and may be changed or removed in a
+// later release.
+func FromContext(ctx context.Context) Logger {
+	if contextualLoggingEnabled {
+		if logger, err := logr.FromContext(ctx); err == nil {
+			return logger
+		}
+	}
+
+	return Background()
+}
+
+// TODO can be used as a last resort by code that has no means of
+// receiving a logger from its caller. FromContext or an explicit logger
+// parameter should be used instead.
+//
+// Experimental
+//
+// Notice: This function is EXPERIMENTAL and may be changed or removed in a
+// later release.
+func TODO() Logger {
+	return Background()
+}
+
+// Background retrieves the fallback logger. It should not be called before
+// that logger was initialized by the program and not by code that should
+// better receive a logger via its parameters. TODO can be used as a temporary
+// solution for such code.
+//
+// Experimental
+//
+// Notice: This function is EXPERIMENTAL and may be changed or removed in a
+// later release.
+func Background() Logger {
+	if globalLogger != nil && contextualLogger {
+		return *globalLogger
+	}
+
+	return klogLogger
+}
+
+// LoggerWithValues returns logger.WithValues(...kv) when
+// contextual logging is enabled, otherwise the logger.
+//
+// Experimental
+//
+// Notice: This function is EXPERIMENTAL and may be changed or removed in a
+// later release.
+func LoggerWithValues(logger Logger, kv ...interface{}) Logger {
+	if contextualLoggingEnabled {
+		return logger.WithValues(kv...)
+	}
+	return logger
+}
+
+// LoggerWithName returns logger.WithName(name) when contextual logging is
+// enabled, otherwise the logger.
+//
+// Experimental
+//
+// Notice: This function is EXPERIMENTAL and may be changed or removed in a
+// later release.
+func LoggerWithName(logger Logger, name string) Logger {
+	if contextualLoggingEnabled {
+		return logger.WithName(name)
+	}
+	return logger
+}
+
+// NewContext returns logr.NewContext(ctx, logger) when
+// contextual logging is enabled, otherwise ctx.
+//
+// Experimental
+//
+// Notice: This function is EXPERIMENTAL and may be changed or removed in a
+// later release.
+func NewContext(ctx context.Context, logger Logger) context.Context {
+	if contextualLoggingEnabled {
+		return logr.NewContext(ctx, logger)
+	}
+	return ctx
+}

contextual_test.go

@@ -0,0 +1,43 @@
+/*
+Copyright 2022 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_test
+
+import (
+	"fmt"
+
+	"github.com/go-logr/logr"
+	"k8s.io/klog/v2"
+)
+
+func ExampleSetLogger() {
+	// Logger is only used as backend, Background() returns klogr.
+	klog.SetLogger(logr.Discard())
+	fmt.Printf("logger after SetLogger: %T\n", klog.Background().GetSink())
+
+	// Logger is only used as backend, Background() returns klogr.
+	klog.SetLoggerWithOptions(logr.Discard(), klog.ContextualLogger(false))
+	fmt.Printf("logger after SetLoggerWithOptions with ContextualLogger(false): %T\n", klog.Background().GetSink())
+
+	// Logger is used as backend and directly.
+	klog.SetLoggerWithOptions(logr.Discard(), klog.ContextualLogger(true))
+	fmt.Printf("logger after SetLoggerWithOptions with ContextualLogger(true): %T\n", klog.Background().GetSink())
+
+	// Output:
+	// logger after SetLogger: *klog.klogger
+	// logger after SetLoggerWithOptions with ContextualLogger(false): *klog.klogger
+	// logger after SetLoggerWithOptions with ContextualLogger(true): logr.discardLogSink
+}

examples/output_test/output_test.go

@@ -85,7 +85,7 @@ func TestKlogrOutput(t *testing.T) {
 	})
 }
 
-// TestKlogrStackText tests klogr -> klog -> text logger.
+// TestKlogrStackText tests klogr.klogr -> klog -> text logger.
 func TestKlogrStackText(t *testing.T) {
 	newLogger := func(out io.Writer, v int, vmodule string) logr.Logger {
 		// Backend: text output.
@@ -104,7 +104,7 @@ func TestKlogrStackText(t *testing.T) {
 	test.Output(t, test.OutputConfig{NewLogger: newLogger, SupportsVModule: true})
 }
 
-// TestKlogrStackKlogr tests klogr -> klog -> zapr.
+// TestKlogrStackKlogr tests klogr.klogr -> klog -> zapr.
 //
 // This exposes whether verbosity is passed through correctly
 // (https://github.com/kubernetes/klog/issues/294) because klogr logging
@@ -136,6 +136,57 @@ func TestKlogrStackZapr(t *testing.T) {
 	test.Output(t, test.OutputConfig{NewLogger: newLogger, ExpectedOutputMapping: mapping})
 }
 
+// TestKlogrInternalStackText tests klog.klogr (the simplified version used for contextual logging) -> klog -> text logger.
+func TestKlogrInternalStackText(t *testing.T) {
+	newLogger := func(out io.Writer, v int, vmodule string) logr.Logger {
+		// Backend: text output.
+		config := textlogger.NewConfig(
+			textlogger.Verbosity(v),
+			textlogger.Output(out),
+		)
+		if err := config.VModule().Set(vmodule); err != nil {
+			panic(err)
+		}
+		klog.SetLogger(textlogger.NewLogger(config))
+
+		// Frontend: internal klogr.
+		return klog.NewKlogr()
+	}
+	test.Output(t, test.OutputConfig{NewLogger: newLogger, SupportsVModule: true})
+}
+
+// TestKlogrInternalStackKlogr tests klog.klogr (the simplified version used for contextual logging) -> klog -> zapr.
+//
+// This exposes whether verbosity is passed through correctly
+// (https://github.com/kubernetes/klog/issues/294) because klogr logging
+// records that.
+func TestKlogrInternalStackZapr(t *testing.T) {
+	mapping := test.ZaprOutputMappingIndirect()
+
+	// klogr doesn't warn about invalid KVs and just inserts
+	// "(MISSING)".
+	for key, value := range map[string]string{
+		`I output.go:<LINE>] "odd arguments" akey="avalue" akey2="(MISSING)"
+`: `{"caller":"test/output.go:<LINE>","msg":"odd arguments","v":0,"akey":"avalue","akey2":"(MISSING)"}
+`,
+
+		`I output.go:<LINE>] "both odd" basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)"
+`: `{"caller":"test/output.go:<LINE>","msg":"both odd","v":0,"basekey1":"basevar1","basekey2":"(MISSING)","akey":"avalue","akey2":"(MISSING)"}
+`,
+	} {
+		mapping[key] = value
+	}
+
+	newLogger := func(out io.Writer, v int, vmodule string) logr.Logger {
+		// Backend: zapr as configured in k8s.io/component-base/logs/json.
+		klog.SetLogger(newZaprLogger(out, v))
+
+		// Frontend: internal klogr.
+		return klog.NewKlogr()
+	}
+	test.Output(t, test.OutputConfig{NewLogger: newLogger, ExpectedOutputMapping: mapping})
+}
+
 func newZaprLogger(out io.Writer, v int) logr.Logger {
 	encoderConfig := &zapcore.EncoderConfig{
 		MessageKey:     "msg",