diff --git a/cmd/kube-apiserver/app/server.go b/cmd/kube-apiserver/app/server.go index 2e3f9b8ad76..0cd54e8a4ee 100644 --- a/cmd/kube-apiserver/app/server.go +++ b/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) diff --git a/cmd/kube-controller-manager/app/controllermanager.go b/cmd/kube-controller-manager/app/controllermanager.go index f6b7cde405b..6d402568fa5 100644 --- a/cmd/kube-controller-manager/app/controllermanager.go +++ b/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) } diff --git a/cmd/kube-scheduler/app/server.go b/cmd/kube-scheduler/app/server.go index 93ef04d60d7..e6bda61b6e6 100644 --- a/cmd/kube-scheduler/app/server.go +++ b/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) } diff --git a/cmd/kubelet/app/server.go b/cmd/kubelet/app/server.go index 17b544033c4..86c73b030d5 100644 --- a/cmd/kubelet/app/server.go +++ b/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) } diff --git a/staging/src/k8s.io/component-base/logs/example/README.md b/staging/src/k8s.io/component-base/logs/example/README.md index 2dcf65274a0..213255adaf8 100644 --- a/staging/src/k8s.io/component-base/logs/example/README.md +++ b/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" +``` diff --git a/staging/src/k8s.io/component-base/logs/example/cmd/logger.go b/staging/src/k8s.io/component-base/logs/example/cmd/logger.go index adc00569d5f..020ad071cc0 100644 --- a/staging/src/k8s.io/component-base/logs/example/cmd/logger.go +++ b/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 { diff --git a/staging/src/k8s.io/component-base/logs/json/json.go b/staging/src/k8s.io/component-base/logs/json/json.go index a39a60dcd05..0171f66afb6 100644 --- a/staging/src/k8s.io/component-base/logs/json/json.go +++ b/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. diff --git a/staging/src/k8s.io/component-base/logs/json/json_benchmark_test.go b/staging/src/k8s.io/component-base/logs/json/json_benchmark_test.go index ca4d6949090..76b9fad3429 100644 --- a/staging/src/k8s.io/component-base/logs/json/json_benchmark_test.go +++ b/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() { diff --git a/staging/src/k8s.io/component-base/logs/json/json_test.go b/staging/src/k8s.io/component-base/logs/json/json_test.go index 1801bf9d875..e634c9bfbe9 100644 --- a/staging/src/k8s.io/component-base/logs/json/json_test.go +++ b/staging/src/k8s.io/component-base/logs/json/json_test.go @@ -24,6 +24,7 @@ import ( "time" "github.com/stretchr/testify/assert" + "k8s.io/component-base/config" "go.uber.org/zap" "go.uber.org/zap/zapcore" @@ -38,6 +39,7 @@ func TestZapLoggerInfo(t *testing.T) { msg string format string keysValues []interface{} + names []string }{ { msg: "test", @@ -59,12 +61,25 @@ func TestZapLoggerInfo(t *testing.T) { format: "{\"ts\":%f,\"caller\":\"json/json_test.go:%d\",\"msg\":\"test for duration value argument\",\"v\":0,\"duration\":\"5s\"}\n", keysValues: []interface{}{"duration", time.Duration(5 * time.Second)}, }, + { + msg: "test for WithName", + names: []string{"hello", "world"}, + format: "{\"ts\":%f,\"logger\":\"hello.world\",\"caller\":\"json/json_test.go:%d\",\"msg\":\"test for WithName\",\"v\":0}\n", + }, + { + msg: "test for duplicate keys", + format: "{\"ts\":%f,\"caller\":\"json/json_test.go:%d\",\"msg\":\"test for duplicate keys\",\"v\":0,\"akey\":\"avalue\",\"akey\":\"anothervalue\"}\n", + keysValues: []interface{}{"akey", "avalue", "akey", "anothervalue"}, + }, } for _, data := range testDataInfo { var buffer bytes.Buffer writer := zapcore.AddSync(&buffer) - sampleInfoLogger, _ := NewJSONLogger(writer, nil, nil) + sampleInfoLogger, _ := NewJSONLogger(0, writer, nil, nil) + for _, name := range data.names { + sampleInfoLogger = sampleInfoLogger.WithName(name) + } // nolint:logcheck // The linter cannot and doesn't need to check the key/value pairs. sampleInfoLogger.Info(data.msg, data.keysValues...) logStr := buffer.String() @@ -95,10 +110,16 @@ func TestZapLoggerInfo(t *testing.T) { // TestZapLoggerEnabled test ZapLogger enabled func TestZapLoggerEnabled(t *testing.T) { - sampleInfoLogger, _ := NewJSONLogger(nil, nil, nil) - for i := 0; i < 11; i++ { - if !sampleInfoLogger.V(i).Enabled() { - t.Errorf("V(%d).Info should be enabled", i) + verbosityLevel := 10 + sampleInfoLogger, _ := NewJSONLogger(config.VerbosityLevel(verbosityLevel), nil, nil, nil) + for v := 0; v <= verbosityLevel; v++ { + enabled := sampleInfoLogger.V(v).Enabled() + expectEnabled := v <= verbosityLevel + if !expectEnabled && enabled { + t.Errorf("V(%d).Info should be disabled", v) + } + if expectEnabled && !enabled { + t.Errorf("V(%d).Info should be enabled", v) } } } @@ -109,24 +130,37 @@ func TestZapLoggerV(t *testing.T) { return time.Date(1970, time.January, 1, 0, 0, 0, 123, time.UTC) } - for i := 0; i < 11; i++ { + verbosityLevel := 10 + for v := 0; v <= verbosityLevel; v++ { var buffer bytes.Buffer writer := zapcore.AddSync(&buffer) - sampleInfoLogger, _ := NewJSONLogger(writer, nil, nil) - sampleInfoLogger.V(i).Info("test", "ns", "default", "podnum", 2, "time", time.Microsecond) + sampleInfoLogger, _ := NewJSONLogger(config.VerbosityLevel(verbosityLevel), writer, nil, nil) + sampleInfoLogger.V(v).Info("test", "ns", "default", "podnum", 2, "time", time.Microsecond) logStr := buffer.String() - var v, lineNo int + + shouldHaveLogged := v <= verbosityLevel + if logged := logStr != ""; logged != shouldHaveLogged { + if logged { + t.Fatalf("Expected no output at v=%d, got: %s", v, logStr) + } + t.Fatalf("Expected output at v=%d, got none.", v) + } + if !shouldHaveLogged { + continue + } + + var actualV, lineNo int expectFormat := "{\"ts\":0.000123,\"caller\":\"json/json_test.go:%d\",\"msg\":\"test\",\"v\":%d,\"ns\":\"default\",\"podnum\":2,\"time\":\"1µs\"}\n" - n, err := fmt.Sscanf(logStr, expectFormat, &lineNo, &v) + n, err := fmt.Sscanf(logStr, expectFormat, &lineNo, &actualV) if n != 2 || err != nil { t.Errorf("log format error: %d elements, error %s:\n%s", n, err, logStr) } - if v != i { - t.Errorf("V(%d).Info...) returned v=%d. expected v=%d", i, v, i) + if actualV != v { + t.Errorf("V(%d).Info...) returned v=%d. expected v=%d", v, actualV, v) } expect := fmt.Sprintf(expectFormat, lineNo, v) if !assert.Equal(t, logStr, expect) { - t.Errorf("V(%d).Info has wrong format \n expect:%s\n got:%s", i, expect, logStr) + t.Errorf("V(%d).Info has wrong format \n expect:%s\n got:%s", v, expect, logStr) } buffer.Reset() } @@ -139,7 +173,7 @@ func TestZapLoggerError(t *testing.T) { timeNow = func() time.Time { return time.Date(1970, time.January, 1, 0, 0, 0, 123, time.UTC) } - sampleInfoLogger, _ := NewJSONLogger(writer, nil, nil) + sampleInfoLogger, _ := NewJSONLogger(0, writer, nil, nil) sampleInfoLogger.Error(fmt.Errorf("invalid namespace:%s", "default"), "wrong namespace", "ns", "default", "podnum", 2, "time", time.Microsecond) logStr := buffer.String() var ts float64 @@ -157,7 +191,7 @@ func TestZapLoggerError(t *testing.T) { func TestZapLoggerStreams(t *testing.T) { var infoBuffer, errorBuffer bytes.Buffer - log, _ := NewJSONLogger(zapcore.AddSync(&infoBuffer), zapcore.AddSync(&errorBuffer), nil) + log, _ := NewJSONLogger(0, zapcore.AddSync(&infoBuffer), zapcore.AddSync(&errorBuffer), nil) log.Error(fmt.Errorf("some error"), "failed") log.Info("hello world") diff --git a/staging/src/k8s.io/component-base/logs/json/klog_test.go b/staging/src/k8s.io/component-base/logs/json/klog_test.go index 19c26590e6c..c5f0ae7719b 100644 --- a/staging/src/k8s.io/component-base/logs/json/klog_test.go +++ b/staging/src/k8s.io/component-base/logs/json/klog_test.go @@ -239,7 +239,7 @@ func TestKlogIntegration(t *testing.T) { t.Run(tc.name, func(t *testing.T) { var buffer bytes.Buffer writer := zapcore.AddSync(&buffer) - logger, _ := NewJSONLogger(writer, nil, nil) + logger, _ := NewJSONLogger(100, writer, nil, nil) klog.SetLogger(logger) defer klog.ClearLogger() @@ -270,7 +270,7 @@ func TestKlogIntegration(t *testing.T) { func TestKlogV(t *testing.T) { var buffer testBuff writer := zapcore.AddSync(&buffer) - logger, _ := NewJSONLogger(writer, nil, nil) + logger, _ := NewJSONLogger(100, writer, nil, nil) klog.SetLogger(logger) defer klog.ClearLogger() fs := flag.FlagSet{} diff --git a/staging/src/k8s.io/component-base/logs/json/register/register_test.go b/staging/src/k8s.io/component-base/logs/json/register/register_test.go index 0c08198a1b8..ebc71395b99 100644 --- a/staging/src/k8s.io/component-base/logs/json/register/register_test.go +++ b/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) + } }) } } diff --git a/staging/src/k8s.io/component-base/logs/kube_features.go b/staging/src/k8s.io/component-base/logs/kube_features.go new file mode 100644 index 00000000000..b8ddf09df3f --- /dev/null +++ b/staging/src/k8s.io/component-base/logs/kube_features.go @@ -0,0 +1,47 @@ +/* +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 logs + +import ( + "k8s.io/component-base/featuregate" +) + +const ( + // owner: @pohly + // kep: http://kep.k8s.io/3077 + // alpha: v1.24 + // + // Enables looking up a logger from a context.Context instead of using + // the global fallback logger and manipulating the logger that is + // used by a call chain. + ContextualLogging featuregate.Feature = "ContextualLogging" + + // contextualLoggingDefault must remain false while in alpha. It can + // become true in beta. + contextualLoggingDefault = false +) + +func featureGates() map[featuregate.Feature]featuregate.FeatureSpec { + return map[featuregate.Feature]featuregate.FeatureSpec{ + ContextualLogging: {Default: contextualLoggingDefault, PreRelease: featuregate.Alpha}, + } +} + +// AddFeatureGates adds all feature gates used by this package. +func AddFeatureGates(mutableFeatureGate featuregate.MutableFeatureGate) error { + return mutableFeatureGate.Add(featureGates()) +} diff --git a/staging/src/k8s.io/component-base/logs/logs.go b/staging/src/k8s.io/component-base/logs/logs.go index d1088e7bd3c..da815e11669 100644 --- a/staging/src/k8s.io/component-base/logs/logs.go +++ b/staging/src/k8s.io/component-base/logs/logs.go @@ -168,6 +168,16 @@ func (writer KlogWriter) Write(data []byte) (n int, err error) { // InitLogs initializes logs the way we want for Kubernetes. // It should be called after parsing flags. If called before that, // it will use the default log settings. +// +// InitLogs disables support for contextual logging in klog while +// that Kubernetes feature is not considered stable yet. Commands +// which want to support contextual logging can: +// - call klog.EnableContextualLogging after calling InitLogs, +// with a fixed `true` or depending on some command line flag or +// a feature gate check +// - set up a FeatureGate instance, the advanced logging configuration +// with Options and call Options.ValidateAndApply with the FeatureGate; +// k8s.io/component-base/logs/example/cmd demonstrates how to do that func InitLogs() { log.SetOutput(KlogWriter{}) log.SetFlags(0) @@ -176,6 +186,10 @@ func InitLogs() { // Otherwise LoggingConfiguration.Apply will do this. klog.StartFlushDaemon(logFlushFreq) } + + // This is the default in Kubernetes. Options.ValidateAndApply + // will override this with the result of a feature gate check. + klog.EnableContextualLogging(false) } // FlushLogs flushes logs immediately. This should be called at the end of diff --git a/staging/src/k8s.io/component-base/logs/options.go b/staging/src/k8s.io/component-base/logs/options.go index 551fe5a3661..91e602992f6 100644 --- a/staging/src/k8s.io/component-base/logs/options.go +++ b/staging/src/k8s.io/component-base/logs/options.go @@ -24,6 +24,7 @@ import ( utilerrors "k8s.io/apimachinery/pkg/util/errors" "k8s.io/component-base/config" "k8s.io/component-base/config/v1alpha1" + "k8s.io/component-base/featuregate" "k8s.io/component-base/logs/registry" "k8s.io/klog/v2" ) @@ -46,12 +47,15 @@ func NewOptions() *Options { // This should be invoked as early as possible because then the rest of the program // startup (including validation of other options) will already run with the final // logging configuration. -func (o *Options) ValidateAndApply() error { +// +// The optional FeatureGate controls logging features. If nil, the default for +// these features is used. +func (o *Options) ValidateAndApply(featureGate featuregate.FeatureGate) error { errs := o.validate() if len(errs) > 0 { return utilerrors.NewAggregate(errs) } - o.apply() + o.apply(featureGate) return nil } @@ -74,14 +78,23 @@ func (o *Options) AddFlags(fs *pflag.FlagSet) { } // apply set klog logger from LogFormat type -func (o *Options) apply() { +func (o *Options) apply(featureGate featuregate.FeatureGate) { + contextualLoggingEnabled := contextualLoggingDefault + if featureGate != nil { + contextualLoggingEnabled = featureGate.Enabled(ContextualLogging) + } + // if log format not exists, use nil loggr factory, _ := registry.LogRegistry.Get(o.Config.Format) if factory == nil { klog.ClearLogger() } else { - log, flush := factory.Create(o.Config.Options) - klog.SetLoggerWithOptions(log, klog.FlushLogger(flush)) + // This logger will do its own verbosity checking, using the exact same + // configuration as klog itself. + log, flush := factory.Create(o.Config) + // Therefore it can get called directly. However, we only allow that + // when the feature is enabled. + klog.SetLoggerWithOptions(log, klog.ContextualLogger(contextualLoggingEnabled), klog.FlushLogger(flush)) } if err := loggingFlags.Lookup("v").Value.Set(o.Config.Verbosity.String()); err != nil { panic(fmt.Errorf("internal error while setting klog verbosity: %v", err)) @@ -90,4 +103,5 @@ func (o *Options) apply() { panic(fmt.Errorf("internal error while setting klog vmodule: %v", err)) } klog.StartFlushDaemon(o.Config.FlushFrequency) + klog.EnableContextualLogging(contextualLoggingEnabled) } diff --git a/staging/src/k8s.io/component-base/logs/options_test.go b/staging/src/k8s.io/component-base/logs/options_test.go index bf3b19870ef..0d6ed1c314c 100644 --- a/staging/src/k8s.io/component-base/logs/options_test.go +++ b/staging/src/k8s.io/component-base/logs/options_test.go @@ -18,12 +18,16 @@ package logs import ( "bytes" + "context" "testing" + "github.com/go-logr/logr" "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/klog/v2" ) @@ -89,7 +93,7 @@ func TestOptions(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) } - err := o.ValidateAndApply() + err := o.ValidateAndApply(nil /* We don't care about feature gates here. */) defer klog.StopFlushDaemon() if !assert.ElementsMatch(t, tc.errs.ToAggregate(), err) { @@ -99,3 +103,42 @@ func TestOptions(t *testing.T) { }) } } + +func TestContextualLogging(t *testing.T) { + t.Run("enabled", func(t *testing.T) { + testContextualLogging(t, true) + }) + + t.Run("disabled", func(t *testing.T) { + testContextualLogging(t, false) + }) +} + +func testContextualLogging(t *testing.T, enabled bool) { + var err error + + o := NewOptions() + featureGate := featuregate.NewFeatureGate() + AddFeatureGates(featureGate) + err = featureGate.SetFromMap(map[string]bool{string(ContextualLogging): enabled}) + require.NoError(t, err) + err = o.ValidateAndApply(featureGate) + require.NoError(t, err) + defer klog.StopFlushDaemon() + defer klog.EnableContextualLogging(true) + + ctx := context.Background() + logger := klog.NewKlogr().WithName("contextual") + ctx = logr.NewContext(ctx, logger) + if enabled { + assert.Equal(t, logger, klog.FromContext(ctx), "FromContext") + assert.NotEqual(t, ctx, klog.NewContext(ctx, logger), "NewContext") + assert.NotEqual(t, logger, klog.LoggerWithName(logger, "foo"), "LoggerWithName") + assert.NotEqual(t, logger, klog.LoggerWithValues(logger, "x", "y"), "LoggerWithValues") + } else { + assert.NotEqual(t, logger, klog.FromContext(ctx), "FromContext") + assert.Equal(t, ctx, klog.NewContext(ctx, logger), "NewContext") + assert.Equal(t, logger, klog.LoggerWithName(logger, "foo"), "LoggerWithName") + assert.Equal(t, logger, klog.LoggerWithValues(logger, "x", "y"), "LoggerWithValues") + } +} diff --git a/staging/src/k8s.io/component-base/logs/registry/registry.go b/staging/src/k8s.io/component-base/logs/registry/registry.go index 145c0b8fd03..be2c3260c9e 100644 --- a/staging/src/k8s.io/component-base/logs/registry/registry.go +++ b/staging/src/k8s.io/component-base/logs/registry/registry.go @@ -41,7 +41,7 @@ type LogFormatFactory interface { // Returning a flush function for the logger is optional. // If provided, the caller must ensure that it is called // periodically (if desired) and at program exit. - Create(options config.FormatOptions) (log logr.Logger, flush func()) + Create(c config.LoggingConfiguration) (log logr.Logger, flush func()) } // NewLogFormatRegistry return new init LogFormatRegistry struct diff --git a/test/integration/logs/benchmark/benchmark_test.go b/test/integration/logs/benchmark/benchmark_test.go index e810e88f3a3..157406b9935 100644 --- a/test/integration/logs/benchmark/benchmark_test.go +++ b/test/integration/logs/benchmark/benchmark_test.go @@ -175,6 +175,7 @@ func benchmarkOutputFormats(b *testing.B, config loadGeneratorConfig, discard bo generateOutput(b, config, nil, out) }) b.Run("JSON", func(b *testing.B) { + options := logs.NewOptions() var logger logr.Logger var flush func() var out1, out2 *os.File @@ -193,15 +194,14 @@ func benchmarkOutputFormats(b *testing.B, config loadGeneratorConfig, discard bo } b.Run("single-stream", func(b *testing.B) { if discard { - logger, flush = logsjson.NewJSONLogger(logsjson.AddNopSync(&output), nil, nil) + logger, flush = logsjson.NewJSONLogger(options.Config.Verbosity, logsjson.AddNopSync(&output), nil, nil) } else { stderr := os.Stderr os.Stderr = out1 defer func() { os.Stderr = stderr }() - options := logs.NewOptions() - logger, flush = logsjson.Factory{}.Create(options.Config.Options) + logger, flush = logsjson.Factory{}.Create(options.Config) } klog.SetLogger(logger) defer klog.ClearLogger() @@ -210,7 +210,7 @@ func benchmarkOutputFormats(b *testing.B, config loadGeneratorConfig, discard bo b.Run("split-stream", func(b *testing.B) { if discard { - logger, flush = logsjson.NewJSONLogger(logsjson.AddNopSync(&output), logsjson.AddNopSync(&output), nil) + logger, flush = logsjson.NewJSONLogger(options.Config.Verbosity, logsjson.AddNopSync(&output), logsjson.AddNopSync(&output), nil) } else { stdout, stderr := os.Stdout, os.Stderr os.Stdout, os.Stderr = out1, out2 @@ -219,7 +219,7 @@ func benchmarkOutputFormats(b *testing.B, config loadGeneratorConfig, discard bo }() options := logs.NewOptions() options.Config.Options.JSON.SplitStream = true - logger, flush = logsjson.Factory{}.Create(options.Config.Options) + logger, flush = logsjson.Factory{}.Create(options.Config) } klog.SetLogger(logger) defer klog.ClearLogger() diff --git a/test/integration/logs/benchmark/common_test.go b/test/integration/logs/benchmark/common_test.go index 9adcf50b014..78602d1341e 100644 --- a/test/integration/logs/benchmark/common_test.go +++ b/test/integration/logs/benchmark/common_test.go @@ -23,6 +23,7 @@ import ( "github.com/go-logr/logr" "go.uber.org/zap/zapcore" + "k8s.io/component-base/logs" logsjson "k8s.io/component-base/logs/json" "k8s.io/klog/v2" ) @@ -60,7 +61,8 @@ func newJSONLogger(out io.Writer) logr.Logger { encoderConfig := &zapcore.EncoderConfig{ MessageKey: "msg", } - logger, _ := logsjson.NewJSONLogger(zapcore.AddSync(out), nil, encoderConfig) + options := logs.NewOptions() + logger, _ := logsjson.NewJSONLogger(options.Config.Verbosity, zapcore.AddSync(out), nil, encoderConfig) return logger }