logging: add ContextualLogging feature

InitLogs overrides the klog default and turns contextual logging off. This
ensures that it is only enabled in Kubernetes commands that explicitly enable
it via a feature gate. A feature gate for it gets defined in
k8s.io/component-base/logs and is then used by Options.ValidateAndApply.

The effect of disabling contextual logging is very limited according to
benchmarks with kube-scheduler. The feature gets added anyway to satisfy the
PRR recommendation that features should be controllable.

The following commands have support for contextual logging:
- kube-apiserver
- kube-controller-manager
- kubelet
- kube-scheduler
- component-base/logs example

Supporting a feature gate check in ValidateAndApply and not in InitLogs is a
simplification: changing InitLogs to accept a FeatureGate would have implied
changing also component-base/cli.Run. This didn't seem worthwhile because
ValidateAndApply already covers the relevant commands.

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/register/register_test.go

@@ -22,9 +22,12 @@ import (
 
 	"github.com/spf13/pflag"
 	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
 
 	"k8s.io/apimachinery/pkg/util/validation/field"
+	"k8s.io/component-base/featuregate"
 	"k8s.io/component-base/logs"
+	"k8s.io/klog/v2"
 )
 
 func TestJSONFlag(t *testing.T) {
@@ -42,11 +45,13 @@ func TestJSONFlag(t *testing.T) {
 
 func TestJSONFormatRegister(t *testing.T) {
 	newOptions := logs.NewOptions()
+	klogr := klog.Background()
 	testcases := []struct {
-		name string
-		args []string
-		want *logs.Options
-		errs field.ErrorList
+		name              string
+		args              []string
+		contextualLogging bool
+		want              *logs.Options
+		errs              field.ErrorList
 	}{
 		{
 			name: "JSON log format",
@@ -57,6 +62,16 @@ func TestJSONFormatRegister(t *testing.T) {
 				return &logs.Options{*c}
 			}(),
 		},
+		{
+			name:              "JSON direct",
+			args:              []string{"--logging-format=json"},
+			contextualLogging: true,
+			want: func() *logs.Options {
+				c := newOptions.Config.DeepCopy()
+				c.Format = logs.JSONLogFormat
+				return &logs.Options{*c}
+			}(),
+		},
 		{
 			name: "Unsupported log format",
 			args: []string{"--logging-format=test"},
@@ -83,11 +98,24 @@ func TestJSONFormatRegister(t *testing.T) {
 			if !assert.Equal(t, tc.want, o) {
 				t.Errorf("Wrong Validate() result for %q. expect %v, got %v", tc.name, tc.want, o)
 			}
-			errs := o.ValidateAndApply()
+			featureGate := featuregate.NewFeatureGate()
+			logs.AddFeatureGates(featureGate)
+			err := featureGate.SetFromMap(map[string]bool{string(logs.ContextualLogging): tc.contextualLogging})
+			require.NoError(t, err)
+			errs := o.ValidateAndApply(featureGate)
+			defer klog.ClearLogger()
 			if !assert.ElementsMatch(t, tc.errs, errs) {
 				t.Errorf("Wrong Validate() result for %q.\n expect:\t%+v\n got:\t%+v", tc.name, tc.errs, errs)
 
 			}
+			currentLogger := klog.Background()
+			isKlogr := currentLogger == klogr
+			if tc.contextualLogging && isKlogr {
+				t.Errorf("Expected to get zapr as logger, got: %T", currentLogger)
+			}
+			if !tc.contextualLogging && !isKlogr {
+				t.Errorf("Expected to get klogr as logger, got: %T", currentLogger)
+			}
 		})
 	}
 }