Merge pull request #115308 from pohly/logs-goflag-example

logs examples
This commit is contained in:
Kubernetes Prow Robot 2023-01-26 02:14:26 -08:00 committed by GitHub
commit 668477e994
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
5 changed files with 188 additions and 45 deletions

View File

@ -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.
@ -20,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"
```
@ -43,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"}
```
@ -65,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"
```
@ -100,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"
```

View File

@ -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"`
}

View File

@ -0,0 +1,56 @@
/*
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")
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.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.
klog.LoggerWithValues(klog.LoggerWithName(logger, "myname"), "duration", time.Hour).Info("runtime", "duration", time.Minute)
logger.Info("another runtime", "duration", time.Hour, "duration", time.Minute)
}

View File

@ -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)
}

View File

@ -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()
}