From 3fe5b3e09d065812cbfae85c745ddbbecc85b722 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Tue, 29 Mar 2022 11:02:11 +0200 Subject: [PATCH 1/5] json: test WithName At the moment, the zap configuration ignores the WithName values. --- .../src/k8s.io/component-base/logs/json/json_test.go | 10 ++++++++++ 1 file changed, 10 insertions(+) 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..178a42270b8 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 @@ -38,6 +38,7 @@ func TestZapLoggerInfo(t *testing.T) { msg string format string keysValues []interface{} + names []string }{ { msg: "test", @@ -59,12 +60,21 @@ 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"}, + // TODO: log names + format: "{\"ts\":%f,\"caller\":\"json/json_test.go:%d\",\"msg\":\"test for WithName\",\"v\":0}\n", + }, } for _, data := range testDataInfo { var buffer bytes.Buffer writer := zapcore.AddSync(&buffer) sampleInfoLogger, _ := NewJSONLogger(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() From ab318cf89f63da69ee305d6c53121b4cd5691203 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 20 Oct 2021 13:42:45 +0200 Subject: [PATCH 2/5] json: enable WithName logging The name added to a logger via WithName only gets printed when a key is chosen. "logger" is used as in the zap examples. This becomes relevant once we support contextual logging. When logging through klog the name is always empty. --- staging/src/k8s.io/component-base/logs/json/json.go | 1 + staging/src/k8s.io/component-base/logs/json/json_test.go | 7 +++---- 2 files changed, 4 insertions(+), 4 deletions(-) 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..bdbcec71a16 100644 --- a/staging/src/k8s.io/component-base/logs/json/json.go +++ b/staging/src/k8s.io/component-base/logs/json/json.go @@ -43,6 +43,7 @@ func NewJSONLogger(infoStream, errorStream zapcore.WriteSyncer, encoderConfig *z encoderConfig = &zapcore.EncoderConfig{ MessageKey: "msg", CallerKey: "caller", + NameKey: "logger", TimeKey: "ts", EncodeTime: epochMillisTimeEncoder, EncodeDuration: zapcore.StringDurationEncoder, 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 178a42270b8..76082a6309d 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 @@ -61,10 +61,9 @@ func TestZapLoggerInfo(t *testing.T) { keysValues: []interface{}{"duration", time.Duration(5 * time.Second)}, }, { - msg: "test for WithName", - names: []string{"hello", "world"}, - // TODO: log names - format: "{\"ts\":%f,\"caller\":\"json/json_test.go:%d\",\"msg\":\"test for WithName\",\"v\":0}\n", + 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", }, } From ef30d845d93628158a9dadd70928f89761eba595 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Tue, 26 Oct 2021 20:59:04 +0200 Subject: [PATCH 3/5] json: test handling of duplicate keys We want to see in the output when keys are used more than once. This should be fixed because parsing the log messages as JSON will only preserve one of the values. --- staging/src/k8s.io/component-base/logs/json/json_test.go | 5 +++++ 1 file changed, 5 insertions(+) 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 76082a6309d..30c3cc3e48d 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 @@ -65,6 +65,11 @@ func TestZapLoggerInfo(t *testing.T) { 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 { From b390d018c76bf83f1b0e818bc9f2feb5982234dc Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Mon, 7 Feb 2022 15:28:12 +0100 Subject: [PATCH 4/5] logs: pass verbosity to loggers When a Logger gets called directly via contextual logging, it has to do its own verbosity check and therefore needs to know what the intended verbosity level is. This used to work previously because all verbosity checks were done in klog before invoking the Logger. --- .../k8s.io/component-base/logs/json/json.go | 21 ++++---- .../logs/json/json_benchmark_test.go | 6 +-- .../component-base/logs/json/json_test.go | 50 +++++++++++++------ .../component-base/logs/json/klog_test.go | 4 +- .../src/k8s.io/component-base/logs/options.go | 7 ++- .../component-base/logs/registry/registry.go | 2 +- .../logs/benchmark/benchmark_test.go | 10 ++-- .../integration/logs/benchmark/common_test.go | 4 +- 8 files changed, 66 insertions(+), 38 deletions(-) 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 bdbcec71a16..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,7 +38,10 @@ 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", @@ -54,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), @@ -84,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. @@ -94,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 { @@ -108,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 30c3cc3e48d..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" @@ -75,7 +76,7 @@ func TestZapLoggerInfo(t *testing.T) { 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) } @@ -109,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) } } } @@ -123,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() } @@ -153,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 @@ -171,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/options.go b/staging/src/k8s.io/component-base/logs/options.go index 551fe5a3661..15d8fe579b5 100644 --- a/staging/src/k8s.io/component-base/logs/options.go +++ b/staging/src/k8s.io/component-base/logs/options.go @@ -80,8 +80,11 @@ func (o *Options) apply() { 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. + klog.SetLoggerWithOptions(log, klog.ContextualLogger(true), 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)) 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 } From 7de1b05e85cf1c6250f311a365016b2869e11b18 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 2 Feb 2022 16:15:36 +0100 Subject: [PATCH 5/5] 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 | 7 +- .../app/controllermanager.go | 6 +- cmd/kube-scheduler/app/server.go | 8 +- cmd/kubelet/app/server.go | 7 +- .../component-base/logs/example/README.md | 88 +++++++++++++++---- .../component-base/logs/example/cmd/logger.go | 37 +++++++- .../logs/json/register/register_test.go | 38 ++++++-- .../component-base/logs/kube_features.go | 47 ++++++++++ .../src/k8s.io/component-base/logs/logs.go | 14 +++ .../src/k8s.io/component-base/logs/options.go | 21 +++-- .../component-base/logs/options_test.go | 45 +++++++++- 11 files changed, 283 insertions(+), 35 deletions(-) create mode 100644 staging/src/k8s.io/component-base/logs/kube_features.go 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 e74aa6e2122..e4a0bff305d 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 d150afd11d8..5bc3d63526d 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/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 15d8fe579b5..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,7 +78,12 @@ 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 { @@ -83,8 +92,9 @@ func (o *Options) apply() { // 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. - klog.SetLoggerWithOptions(log, klog.ContextualLogger(true), klog.FlushLogger(flush)) + // 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)) @@ -93,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") + } +}