From a753466fe4ff168b3f92243334d3220a079568e6 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 25 Jan 2023 08:43:01 +0100 Subject: [PATCH 1/3] logs: add examples for Go flag and unit testing All examples use the same code for producing output. Only the way how logging is configured is different. --- .../component-base/logs/example/README.md | 5 +- .../component-base/logs/example/cmd/logger.go | 44 +++--------- .../component-base/logs/example/example.go | 62 +++++++++++++++++ .../logs/example/stdlib/logger.go | 67 +++++++++++++++++++ .../logs/example/test/logger_test.go | 53 +++++++++++++++ 5 files changed, 194 insertions(+), 37 deletions(-) create mode 100644 staging/src/k8s.io/component-base/logs/example/example.go create mode 100644 staging/src/k8s.io/component-base/logs/example/stdlib/logger.go create mode 100644 staging/src/k8s.io/component-base/logs/example/test/logger_test.go 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 213255adaf8..3159fd87cc9 100644 --- a/staging/src/k8s.io/component-base/logs/example/README.md +++ b/staging/src/k8s.io/component-base/logs/example/README.md @@ -1,6 +1,9 @@ # Example -This directory includes example logger setup allowing users to easily check and test impact of logging configuration. +This directory includes example logger binaries which show how to use +component-base/logs and what effect the different command line options have. +Like most Kubernetes components, `cmd` uses Cobra and pflags. `stdlib` uses +just plain Go libraries. `test` contains a unit test with per-test output. Below we can see examples of how some features work. 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 5b8ed2e4d0d..b0d4f9baaca 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 @@ -18,10 +18,9 @@ package main import ( "context" - "errors" "fmt" "os" - "time" + "strings" "github.com/spf13/cobra" @@ -30,6 +29,7 @@ import ( "k8s.io/component-base/featuregate" "k8s.io/component-base/logs" logsapi "k8s.io/component-base/logs/api/v1" + "k8s.io/component-base/logs/example" "k8s.io/klog/v2" _ "k8s.io/component-base/logs/json/register" @@ -40,10 +40,6 @@ var featureGate = featuregate.NewFeatureGate() func main() { runtime.Must(logsapi.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) } @@ -57,12 +53,17 @@ func NewLoggerCommand() *cobra.Command { fmt.Fprintf(os.Stderr, "%v\n", err) os.Exit(1) } + if len(args) > 0 { + fmt.Fprintf(os.Stderr, "Unexpected additional command line arguments:\n %s\n", strings.Join(args, "\n ")) + os.Exit(1) + } // Initialize contextual logging. logger := klog.LoggerWithValues(klog.LoggerWithName(klog.Background(), "example"), "foo", "bar") ctx := klog.NewContext(context.Background(), logger) - runLogger(ctx) + // Produce some output. + example.Run(ctx) }, } logsapi.AddFeatureGates(featureGate) @@ -70,32 +71,3 @@ func NewLoggerCommand() *cobra.Command { logsapi.AddFlags(c, cmd.Flags()) return cmd } - -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") - klog.InfoS("Log using InfoS", "key", "value") - err := errors.New("fail") - klog.Errorf("Log using Errorf, err: %v", err) - klog.ErrorS(err, "Log using ErrorS") - 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 { - Key string `json:"key" datapolicy:"secret-key"` -} diff --git a/staging/src/k8s.io/component-base/logs/example/example.go b/staging/src/k8s.io/component-base/logs/example/example.go new file mode 100644 index 00000000000..b2d2ab0d2e9 --- /dev/null +++ b/staging/src/k8s.io/component-base/logs/example/example.go @@ -0,0 +1,62 @@ +/* +Copyright 2023 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 example shows how a library uses contextual logging. +package example + +import ( + "context" + "errors" + "fmt" + "os" + "time" + + "k8s.io/klog/v2" +) + +func init() { + // Intentionally broken: logging is not initialized yet. + klog.TODO().Info("Oops, I shouldn't be logging yet!") +} + +func Run(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") + klog.InfoS("Log using InfoS", "key", "value") + err := errors.New("fail") + klog.Errorf("Log using Errorf, err: %v", err) + klog.ErrorS(err, "Log using ErrorS") + 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 { + Key string `json:"key" datapolicy:"secret-key"` +} diff --git a/staging/src/k8s.io/component-base/logs/example/stdlib/logger.go b/staging/src/k8s.io/component-base/logs/example/stdlib/logger.go new file mode 100644 index 00000000000..f13edcf9922 --- /dev/null +++ b/staging/src/k8s.io/component-base/logs/example/stdlib/logger.go @@ -0,0 +1,67 @@ +/* +Copyright 2023 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 main + +import ( + "context" + "flag" + "fmt" + "os" + "strings" + + "k8s.io/apimachinery/pkg/util/runtime" + "k8s.io/component-base/featuregate" + "k8s.io/component-base/logs" + logsapi "k8s.io/component-base/logs/api/v1" + "k8s.io/component-base/logs/example" + "k8s.io/klog/v2" + + _ "k8s.io/component-base/logs/json/register" +) + +func main() { + // Set up command line, including a feature gate parameter and logging options. + featureGate := featuregate.NewFeatureGate() + runtime.Must(logsapi.AddFeatureGates(featureGate)) + flag.Var(featureGate, "feature-gate", + "A set of key=value pairs that describe feature gates for alpha/experimental features. "+ + "Options are:\n"+strings.Join(featureGate.KnownFeatures(), "\n")) + c := logsapi.NewLoggingConfiguration() + logsapi.AddGoFlags(c, flag.CommandLine) + + // Parse flags and apply the result. logs.InitLogs disables contextual + // logging while it is still alpha. The feature gate parameter must be + // used to enable it explicitly. + flag.Parse() + logs.InitLogs() + if err := logsapi.ValidateAndApply(c, featureGate); err != nil { + fmt.Fprintf(os.Stderr, "%v\n", err) + os.Exit(1) + } + args := flag.CommandLine.Args() + if len(args) > 0 { + fmt.Fprintf(os.Stderr, "Unexpected additional command line arguments:\n %s\n", strings.Join(args, "\n ")) + os.Exit(1) + } + + // Initialize contextual logging. + logger := klog.LoggerWithValues(klog.LoggerWithName(klog.Background(), "example"), "foo", "bar") + ctx := klog.NewContext(context.Background(), logger) + + // Produce some output. + example.Run(ctx) +} diff --git a/staging/src/k8s.io/component-base/logs/example/test/logger_test.go b/staging/src/k8s.io/component-base/logs/example/test/logger_test.go new file mode 100644 index 00000000000..5d8c389778e --- /dev/null +++ b/staging/src/k8s.io/component-base/logs/example/test/logger_test.go @@ -0,0 +1,53 @@ +/* +Copyright 2023 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 logger_test demonstrates how to write unit tests with per-test +// output. Per-test output only works for code which supports contextual +// logging. +package logger_test + +import ( + "flag" + "testing" + + "k8s.io/component-base/logs/example" + "k8s.io/klog/v2/ktesting" + // This import could be used to add command line flags for per-test + // output with a default verbosity of 5. This example instead + // uses a TestMain where the default verbosity gets lowered. + // "k8s.io/klog/v2/ktesting/init" +) + +func TestLogger(t *testing.T) { + // Produce some output in two different tests which run in parallel. + for _, testcase := range []string{"abc", "xyz"} { + t.Run(testcase, func(t *testing.T) { + t.Parallel() + _ /* logger */, ctx := ktesting.NewTestContext(t) + example.Run(ctx) + }) + } +} + +func TestMain(m *testing.M) { + // Run with verbosity 2, this is the default log level in production. + // The name of the flags also could be customized here. The defaults + // are -testing.v and -testing.vmodule. + ktesting.DefaultConfig = ktesting.NewConfig(ktesting.Verbosity(2)) + ktesting.DefaultConfig.AddFlags(flag.CommandLine) + flag.Parse() + m.Run() +} From 0a38a5e68aca40f4a71d9646bc62a8a769d07782 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 25 Jan 2023 08:45:12 +0100 Subject: [PATCH 2/3] logs: remove example of secret data Dynamic log sanitization (https://github.com/kubernetes/enhancements/tree/master/keps/sig-instrumentation/1753-logs-sanitization) got removed a while back, there's no need to have it in the example anymore. --- staging/src/k8s.io/component-base/logs/example/README.md | 8 -------- staging/src/k8s.io/component-base/logs/example/example.go | 7 ------- 2 files changed, 15 deletions(-) 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 3159fd87cc9..a2a3a295115 100644 --- a/staging/src/k8s.io/component-base/logs/example/README.md +++ b/staging/src/k8s.io/component-base/logs/example/README.md @@ -23,9 +23,7 @@ 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" ``` @@ -46,9 +44,7 @@ This is other output via stderr. {"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"} ``` @@ -68,10 +64,8 @@ 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" ``` @@ -103,9 +97,7 @@ 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/example.go b/staging/src/k8s.io/component-base/logs/example/example.go index b2d2ab0d2e9..fc6ce68f62a 100644 --- a/staging/src/k8s.io/component-base/logs/example/example.go +++ b/staging/src/k8s.io/component-base/logs/example/example.go @@ -40,8 +40,6 @@ func Run(ctx context.Context) { err := errors.New("fail") klog.Errorf("Log using Errorf, err: %v", err) klog.ErrorS(err, "Log using ErrorS") - 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 @@ -49,14 +47,9 @@ func Run(ctx context.Context) { 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 { - Key string `json:"key" datapolicy:"secret-key"` -} From 74885d1a1dbeb81bfdf4508f6c699544eed1abf8 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 25 Jan 2023 08:49:05 +0100 Subject: [PATCH 3/3] logs: add logger.V(5).Info example This is relevant for unit tests where normally such output would be shown when using ktesting. --- staging/src/k8s.io/component-base/logs/example/example.go | 1 + 1 file changed, 1 insertion(+) diff --git a/staging/src/k8s.io/component-base/logs/example/example.go b/staging/src/k8s.io/component-base/logs/example/example.go index fc6ce68f62a..48e6763d540 100644 --- a/staging/src/k8s.io/component-base/logs/example/example.go +++ b/staging/src/k8s.io/component-base/logs/example/example.go @@ -47,6 +47,7 @@ func Run(ctx context.Context) { klog.TODO().Info("Now the default logger is set, but using the one from the context is still better.") logger := klog.FromContext(ctx) + logger.V(5).Info("Log less important message at V=5 through context") // This intentionally uses the same key/value multiple times. Only the // second example could be detected via static code analysis.