From a753466fe4ff168b3f92243334d3220a079568e6 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 25 Jan 2023 08:43:01 +0100 Subject: [PATCH] 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() +}