Merge pull request #108995 from pohly/log-contextual

contextual logging

cmd/kube-apiserver/app/server.go

@@ -34,6 +34,7 @@ import (
 	extensionsapiserver "k8s.io/apiextensions-apiserver/pkg/apiserver"
 	utilerrors "k8s.io/apimachinery/pkg/util/errors"
 	utilnet "k8s.io/apimachinery/pkg/util/net"
+	utilruntime "k8s.io/apimachinery/pkg/util/runtime"
 	"k8s.io/apimachinery/pkg/util/sets"
 	"k8s.io/apiserver/pkg/admission"
 	"k8s.io/apiserver/pkg/authorization/authorizer"
@@ -80,6 +81,10 @@ import (
 	"k8s.io/kubernetes/pkg/serviceaccount"
 )
 
+func init() {
+	utilruntime.Must(logs.AddFeatureGates(utilfeature.DefaultMutableFeatureGate))
+}
+
 // NewAPIServerCommand creates a *cobra.Command object with default parameters
 func NewAPIServerCommand() *cobra.Command {
 	s := options.NewServerRunOptions()
@@ -104,7 +109,7 @@ cluster's shared state through which all other components interact.`,
 
 			// Activate logging as soon as possible, after that
 			// show flags with the final logging configuration.
-			if err := s.Logs.ValidateAndApply(); err != nil {
+			if err := s.Logs.ValidateAndApply(utilfeature.DefaultFeatureGate); err != nil {
 				return err
 			}
 			cliflag.PrintFlags(fs)

cmd/kube-controller-manager/app/controllermanager.go

@@ -73,6 +73,10 @@ import (
 	"k8s.io/kubernetes/pkg/serviceaccount"
 )
 
+func init() {
+	utilruntime.Must(logs.AddFeatureGates(utilfeature.DefaultMutableFeatureGate))
+}
+
 const (
 	// ControllerStartJitter is the Jitter used when starting controller managers
 	ControllerStartJitter = 1.0
@@ -118,7 +122,7 @@ controller, and serviceaccounts controller.`,
 
 			// Activate logging as soon as possible, after that
 			// show flags with the final logging configuration.
-			if err := s.Logs.ValidateAndApply(); err != nil {
+			if err := s.Logs.ValidateAndApply(utilfeature.DefaultFeatureGate); err != nil {
 				fmt.Fprintf(os.Stderr, "%v\n", err)
 				os.Exit(1)
 			}

cmd/kube-scheduler/app/server.go

@@ -27,6 +27,7 @@ import (
 	"github.com/spf13/cobra"
 
 	utilerrors "k8s.io/apimachinery/pkg/util/errors"
+	utilruntime "k8s.io/apimachinery/pkg/util/runtime"
 	"k8s.io/apiserver/pkg/authentication/authenticator"
 	"k8s.io/apiserver/pkg/authorization/authorizer"
 	genericapifilters "k8s.io/apiserver/pkg/endpoints/filters"
@@ -36,6 +37,7 @@ import (
 	"k8s.io/apiserver/pkg/server/healthz"
 	"k8s.io/apiserver/pkg/server/mux"
 	"k8s.io/apiserver/pkg/server/routes"
+	utilfeature "k8s.io/apiserver/pkg/util/feature"
 	"k8s.io/client-go/informers"
 	"k8s.io/client-go/kubernetes/scheme"
 	"k8s.io/client-go/tools/events"
@@ -59,6 +61,10 @@ import (
 	"k8s.io/kubernetes/pkg/scheduler/profile"
 )
 
+func init() {
+	utilruntime.Must(logs.AddFeatureGates(utilfeature.DefaultMutableFeatureGate))
+}
+
 // Option configures a framework.Registry.
 type Option func(runtime.Registry) error
 
@@ -113,7 +119,7 @@ func runCommand(cmd *cobra.Command, opts *options.Options, registryOptions ...Op
 
 	// Activate logging as soon as possible, after that
 	// show flags with the final logging configuration.
-	if err := opts.Logs.ValidateAndApply(); err != nil {
+	if err := opts.Logs.ValidateAndApply(utilfeature.DefaultFeatureGate); err != nil {
 		fmt.Fprintf(os.Stderr, "%v\n", err)
 		os.Exit(1)
 	}

cmd/kubelet/app/server.go

@@ -45,6 +45,7 @@ import (
 	"k8s.io/apimachinery/pkg/runtime"
 	"k8s.io/apimachinery/pkg/types"
 	utilnet "k8s.io/apimachinery/pkg/util/net"
+	utilruntime "k8s.io/apimachinery/pkg/util/runtime"
 	"k8s.io/apimachinery/pkg/util/sets"
 	"k8s.io/apimachinery/pkg/util/wait"
 	genericapiserver "k8s.io/apiserver/pkg/server"
@@ -103,6 +104,10 @@ import (
 	netutils "k8s.io/utils/net"
 )
 
+func init() {
+	utilruntime.Must(logs.AddFeatureGates(utilfeature.DefaultMutableFeatureGate))
+}
+
 const (
 	// Kubelet component name
 	componentKubelet = "kubelet"
@@ -226,7 +231,7 @@ HTTP server: The kubelet can also listen for HTTP and respond to a simple API
 			// Config and flags parsed, now we can initialize logging.
 			logs.InitLogs()
 			logOption := &logs.Options{Config: kubeletConfig.Logging}
-			if err := logOption.ValidateAndApply(); err != nil {
+			if err := logOption.ValidateAndApply(utilfeature.DefaultFeatureGate); err != nil {
 				klog.ErrorS(err, "Failed to initialize logging")
 				os.Exit(1)
 			}

staging/src/k8s.io/component-base/logs/example/README.md

@@ -13,11 +13,18 @@ go run ./staging/src/k8s.io/component-base/logs/example/cmd/logger.go
 
 Expected output:
 ```
-I0605 22:03:07.224293 3228948 logger.go:58] Log using Infof, key: value
-I0605 22:03:07.224378 3228948 logger.go:59] "Log using InfoS" key="value"
-E0605 22:03:07.224393 3228948 logger.go:61] Log using Errorf, err: fail
-E0605 22:03:07.224402 3228948 logger.go:62] "Log using ErrorS" err="fail"
-I0605 22:03:07.224407 3228948 logger.go:64] Log message has been redacted. Log argument #0 contains: [secret-key]
+I0329 11:36:38.734334   99095 logger.go:44] "Oops, I shouldn't be logging yet!"
+This is normal output via stdout.
+This is other output via stderr.
+I0329 11:36:38.734575   99095 logger.go:76] Log using Infof, key: value
+I0329 11:36:38.734592   99095 logger.go:77] "Log using InfoS" key="value"
+E0329 11:36:38.734604   99095 logger.go:79] Log using Errorf, err: fail
+E0329 11:36:38.734619   99095 logger.go:80] "Log using ErrorS" err="fail"
+I0329 11:36:38.734631   99095 logger.go:82] Log with sensitive key, data: {"secret"}
+I0329 11:36:38.734653   99095 logger.go:87] "Now the default logger is set, but using the one from the context is still better."
+I0329 11:36:38.734674   99095 logger.go:90] "Log sensitive data through context" data={Key:secret}
+I0329 11:36:38.734693   99095 logger.go:94] "runtime" duration="1m0s"
+I0329 11:36:38.734710   99095 logger.go:95] "another runtime" duration="1m0s"
 ```
 
 ## JSON 
@@ -29,11 +36,18 @@ go run ./staging/src/k8s.io/component-base/logs/example/cmd/logger.go --logging-
 
 Expected output:
 ```
-{"ts":1624215726270.3562,"caller":"cmd/logger.go:58","msg":"Log using Infof, key: value\n","v":0}
-{"ts":1624215726270.4377,"caller":"cmd/logger.go:59","msg":"Log using InfoS","v":0,"key":"value"}
-{"ts":1624215726270.6724,"caller":"cmd/logger.go:61","msg":"Log using Errorf, err: fail\n","v":0}
-{"ts":1624215726270.7566,"caller":"cmd/logger.go:62","msg":"Log using ErrorS","err":"fail","v":0}
-{"ts":1624215726270.8428,"caller":"cmd/logger.go:64","msg":"Log with sensitive key, data: {\"secret\"}\n","v":0}
+I0329 11:38:01.782592   99945 logger.go:44] "Oops, I shouldn't be logging yet!"
+This is normal output via stdout.
+This is other output via stderr.
+{"ts":1648546681782.9036,"caller":"cmd/logger.go:76","msg":"Log using Infof, key: value\n","v":0}
+{"ts":1648546681782.9392,"caller":"cmd/logger.go:77","msg":"Log using InfoS","v":0,"key":"value"}
+{"ts":1648546681782.9763,"caller":"cmd/logger.go:79","msg":"Log using Errorf, err: fail\n"}
+{"ts":1648546681782.9915,"caller":"cmd/logger.go:80","msg":"Log using ErrorS","err":"fail"}
+{"ts":1648546681783.0208,"caller":"cmd/logger.go:82","msg":"Log with sensitive key, data: {\"secret\"}\n","v":0}
+{"ts":1648546681783.0364,"caller":"cmd/logger.go:87","msg":"Now the default logger is set, but using the one from the context is still better.","v":0}
+{"ts":1648546681783.0552,"caller":"cmd/logger.go:90","msg":"Log sensitive data through context","v":0,"data":{"key":"secret"}}
+{"ts":1648546681783.1091,"caller":"cmd/logger.go:94","msg":"runtime","v":0,"duration":"1m0s"}
+{"ts":1648546681783.1257,"caller":"cmd/logger.go:95","msg":"another runtime","v":0,"duration":"1h0m0s","duration":"1m0s"}
 ```
 
 ## Verbosity
@@ -42,13 +56,53 @@ Expected output:
 go run ./staging/src/k8s.io/component-base/logs/example/cmd/logger.go -v1
 ```
 
+The expected output now includes `Log less important message`:
 ```
-I0914 10:31:12.342958   54086 logger.go:61] Log using Infof, key: value
-I0914 10:31:12.343021   54086 logger.go:62] "Log using InfoS" key="value"
-E0914 10:31:12.343053   54086 logger.go:64] Log using Errorf, err: fail
-E0914 10:31:12.343064   54086 logger.go:65] "Log using ErrorS" err="fail"
-I0914 10:31:12.343073   54086 logger.go:67] Log with sensitive key, data: {"secret"}
-I0914 10:31:12.343090   54086 logger.go:68] Log less important message
+I0329 11:38:23.145695  100190 logger.go:44] "Oops, I shouldn't be logging yet!"
+This is normal output via stdout.
+This is other output via stderr.
+I0329 11:38:23.145944  100190 logger.go:76] Log using Infof, key: value
+I0329 11:38:23.145961  100190 logger.go:77] "Log using InfoS" key="value"
+E0329 11:38:23.145973  100190 logger.go:79] Log using Errorf, err: fail
+E0329 11:38:23.145989  100190 logger.go:80] "Log using ErrorS" err="fail"
+I0329 11:38:23.146000  100190 logger.go:82] Log with sensitive key, data: {"secret"}
+I0329 11:38:23.146017  100190 logger.go:83] Log less important message
+I0329 11:38:23.146034  100190 logger.go:87] "Now the default logger is set, but using the one from the context is still better."
+I0329 11:38:23.146055  100190 logger.go:90] "Log sensitive data through context" data={Key:secret}
+I0329 11:38:23.146074  100190 logger.go:94] "runtime" duration="1m0s"
+I0329 11:38:23.146091  100190 logger.go:95] "another runtime" duration="1m0s"
 ```
 
-The last line is not printed at the default log level.
+## Contextual logging
+
+Contextual logging enables the caller of the function to add a string prefix
+and additional key/value pairs to a logger and then pass the updated logger
+into functions via a `context` parameter.
+
+At the moment, this functionality is controlled in Kubernetes with the
+`ContextualLogging` feature gate and disabled by
+default. `klog.LoggerWithValues`, `klog.LoggerWithName`, `klog.NewContext` just
+return the original instance when contextual logging is
+disabled. `klog.FromContext` doesn't check the context for a logger and instead
+returns the global logger.
+
+```console
+go run ./staging/src/k8s.io/component-base/logs/example/cmd/logger.go --feature-gates ContextualLogging=true
+```
+
+The expected output now includes `example` (added by caller) and `myname`
+(added by callee) as prefix and the caller's `foo="bar"` key/value pair:
+```
+I0329 11:47:36.830458  101057 logger.go:44] "Oops, I shouldn't be logging yet!"
+This is normal output via stdout.
+This is other output via stderr.
+I0329 11:47:36.830715  101057 logger.go:76] Log using Infof, key: value
+I0329 11:47:36.830731  101057 logger.go:77] "Log using InfoS" key="value"
+E0329 11:47:36.830745  101057 logger.go:79] Log using Errorf, err: fail
+E0329 11:47:36.830760  101057 logger.go:80] "Log using ErrorS" err="fail"
+I0329 11:47:36.830772  101057 logger.go:82] Log with sensitive key, data: {"secret"}
+I0329 11:47:36.830795  101057 logger.go:87] "Now the default logger is set, but using the one from the context is still better."
+I0329 11:47:36.830818  101057 logger.go:90] "example: Log sensitive data through context" foo="bar" data={Key:secret}
+I0329 11:47:36.830841  101057 logger.go:94] "example/myname: runtime" foo="bar" duration="1m0s"
+I0329 11:47:36.830859  101057 logger.go:95] "example: another runtime" foo="bar" duration="1m0s"
+```

staging/src/k8s.io/component-base/logs/example/cmd/logger.go

@@ -17,21 +17,32 @@ limitations under the License.
 package main
 
 import (
+	"context"
 	"errors"
 	"fmt"
 	"os"
+	"time"
 
 	"github.com/spf13/cobra"
 
+	"k8s.io/apimachinery/pkg/util/runtime"
 	"k8s.io/component-base/cli"
+	"k8s.io/component-base/featuregate"
 	"k8s.io/component-base/logs"
 	"k8s.io/klog/v2"
 
 	_ "k8s.io/component-base/logs/json/register"
 )
 
+var featureGate = featuregate.NewFeatureGate()
+
 func main() {
+	runtime.Must(logs.AddFeatureGates(featureGate))
 	command := NewLoggerCommand()
+
+	// Intentionally broken: logging is not initialized yet.
+	klog.TODO().Info("Oops, I shouldn't be logging yet!")
+
 	code := cli.Run(command)
 	os.Exit(code)
 }
@@ -40,18 +51,26 @@ func NewLoggerCommand() *cobra.Command {
 	o := logs.NewOptions()
 	cmd := &cobra.Command{
 		Run: func(cmd *cobra.Command, args []string) {
-			if err := o.ValidateAndApply(); err != nil {
+			logs.InitLogs()
+			if err := o.ValidateAndApply(featureGate); err != nil {
 				fmt.Fprintf(os.Stderr, "%v\n", err)
 				os.Exit(1)
 			}
-			runLogger()
+
+			// Initialize contextual logging.
+			logger := klog.Background().WithName("example").WithValues("foo", "bar")
+			ctx := klog.NewContext(context.Background(), logger)
+
+			runLogger(ctx)
 		},
 	}
+	logs.AddFeatureGates(featureGate)
+	featureGate.AddFlag(cmd.Flags())
 	o.AddFlags(cmd.Flags())
 	return cmd
 }
 
-func runLogger() {
+func runLogger(ctx context.Context) {
 	fmt.Println("This is normal output via stdout.")
 	fmt.Fprintln(os.Stderr, "This is other output via stderr.")
 	klog.Infof("Log using Infof, key: %s", "value")
@@ -62,6 +81,18 @@ func runLogger() {
 	data := SensitiveData{Key: "secret"}
 	klog.Infof("Log with sensitive key, data: %q", data)
 	klog.V(1).Info("Log less important message")
+
+	// This is the fallback that can be used if neither logger nor context
+	// are available... but it's better to pass some kind of parameter.
+	klog.TODO().Info("Now the default logger is set, but using the one from the context is still better.")
+
+	logger := klog.FromContext(ctx)
+	logger.Info("Log sensitive data through context", "data", data)
+
+	// This intentionally uses the same key/value multiple times. Only the
+	// second example could be detected via static code analysis.
+	klog.LoggerWithValues(klog.LoggerWithName(logger, "myname"), "duration", time.Hour).Info("runtime", "duration", time.Minute)
+	logger.Info("another runtime", "duration", time.Hour, "duration", time.Minute)
 }
 
 type SensitiveData struct {

staging/src/k8s.io/component-base/logs/json/json.go

@@ -38,11 +38,15 @@ var (
 // NewJSONLogger creates a new json logr.Logger and its associated
 // flush function. The separate error stream is optional and may be nil.
 // The encoder config is also optional.
-func NewJSONLogger(infoStream, errorStream zapcore.WriteSyncer, encoderConfig *zapcore.EncoderConfig) (logr.Logger, func()) {
+func NewJSONLogger(v config.VerbosityLevel, infoStream, errorStream zapcore.WriteSyncer, encoderConfig *zapcore.EncoderConfig) (logr.Logger, func()) {
+	// zap levels are inverted: everything with a verbosity >= threshold gets logged.
+	zapV := -zapcore.Level(v)
+
 	if encoderConfig == nil {
 		encoderConfig = &zapcore.EncoderConfig{
 			MessageKey:     "msg",
 			CallerKey:      "caller",
+			NameKey:        "logger",
 			TimeKey:        "ts",
 			EncodeTime:     epochMillisTimeEncoder,
 			EncodeDuration: zapcore.StringDurationEncoder,
@@ -53,13 +57,13 @@ func NewJSONLogger(infoStream, errorStream zapcore.WriteSyncer, encoderConfig *z
 	encoder := zapcore.NewJSONEncoder(*encoderConfig)
 	var core zapcore.Core
 	if errorStream == nil {
-		core = zapcore.NewCore(encoder, infoStream, zapcore.Level(-127))
+		core = zapcore.NewCore(encoder, infoStream, zapV)
 	} else {
 		highPriority := zap.LevelEnablerFunc(func(lvl zapcore.Level) bool {
-			return lvl >= zapcore.ErrorLevel
+			return lvl >= zapcore.ErrorLevel && lvl >= zapV
 		})
 		lowPriority := zap.LevelEnablerFunc(func(lvl zapcore.Level) bool {
-			return lvl < zapcore.ErrorLevel
+			return lvl < zapcore.ErrorLevel && lvl >= zapV
 		})
 		core = zapcore.NewTee(
 			zapcore.NewCore(encoder, errorStream, highPriority),
@@ -83,7 +87,7 @@ type Factory struct{}
 
 var _ registry.LogFormatFactory = Factory{}
 
-func (f Factory) Create(options config.FormatOptions) (logr.Logger, func()) {
+func (f Factory) Create(c config.LoggingConfiguration) (logr.Logger, func()) {
 	// We intentionally avoid all os.File.Sync calls. Output is unbuffered,
 	// therefore we don't need to flush, and calling the underlying fsync
 	// would just slow down writing.
@@ -93,9 +97,9 @@ func (f Factory) Create(options config.FormatOptions) (logr.Logger, func()) {
 	// doesn't need to worry about data not being written because of a
 	// system crash or powerloss.
 	stderr := zapcore.Lock(AddNopSync(os.Stderr))
-	if options.JSON.SplitStream {
+	if c.Options.JSON.SplitStream {
 		stdout := zapcore.Lock(AddNopSync(os.Stdout))
-		size := options.JSON.InfoBufferSize.Value()
+		size := c.Options.JSON.InfoBufferSize.Value()
 		if size > 0 {
 			// Prevent integer overflow.
 			if size > 2*1024*1024*1024 {
@@ -107,10 +111,10 @@ func (f Factory) Create(options config.FormatOptions) (logr.Logger, func()) {
 			}
 		}
 		// stdout for info messages, stderr for errors.
-		return NewJSONLogger(stdout, stderr, nil)
+		return NewJSONLogger(c.Verbosity, stdout, stderr, nil)
 	}
 	// Write info messages and errors to stderr to prevent mixing with normal program output.
-	return NewJSONLogger(stderr, nil, nil)
+	return NewJSONLogger(c.Verbosity, stderr, nil, nil)
 }
 
 // AddNoSync adds a NOP Sync implementation.

staging/src/k8s.io/component-base/logs/json/json_benchmark_test.go

@@ -26,7 +26,7 @@ import (
 var writer = zapcore.AddSync(&writeSyncer{})
 
 func BenchmarkInfoLoggerInfo(b *testing.B) {
-	logger, _ := NewJSONLogger(writer, nil, nil)
+	logger, _ := NewJSONLogger(0, writer, nil, nil)
 	b.ResetTimer()
 	b.RunParallel(func(pb *testing.PB) {
 		for pb.Next() {
@@ -55,7 +55,7 @@ func BenchmarkInfoLoggerInfo(b *testing.B) {
 }
 
 func BenchmarkZapLoggerError(b *testing.B) {
-	logger, _ := NewJSONLogger(writer, nil, nil)
+	logger, _ := NewJSONLogger(0, writer, nil, nil)
 	b.ResetTimer()
 	b.RunParallel(func(pb *testing.PB) {
 		for pb.Next() {
@@ -85,7 +85,7 @@ func BenchmarkZapLoggerError(b *testing.B) {
 }
 
 func BenchmarkZapLoggerV(b *testing.B) {
-	logger, _ := NewJSONLogger(writer, nil, nil)
+	logger, _ := NewJSONLogger(1, writer, nil, nil)
 	b.ResetTimer()
 	b.RunParallel(func(pb *testing.PB) {
 		for pb.Next() {