From 07fe24617c36a733c3658831c4dd1d1088330345 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Thu, 27 May 2021 15:15:50 +0200 Subject: [PATCH 1/4] testinglogger: per-test, structured logging This logr implementation can be used in tests to ensure that output is associated with the currently running test. Compared to using the global klog instance in a standard Go test that has some advantages: - Log messages are associated with the currently running test. Tests can run in parallel without interleaving their output. - Log output is only printed when a test fails, unless "go test -v" is used. - Because of that, the logger can print more log messages by default, with 5 being used because that is recommended for debugging in https://github.com/kubernetes/community/blob/fbc5ca53d6bfd8388b335f7d0198b67a14b99d91/contributors/devel/sig-instrumentation/logging.md?plain=1#L34-L36 That threshold can be changed via -testing.v after registering that flag by importing k8s.io/klog/v2/ktesting/init. The motivation for hosting this logger in klog is that it shares the formatting code with klogr. Conceptually this is identical to go-logr/logr/testing, just the output is different (klog text format vs. JSON). $ go test -v ./testinglogger/example/ === RUN TestKlog example_test.go:69: INFO hello world example_test.go:70: ERROR failed err="failed: some error" example_test.go:71: INFO verbosity 1 example_test.go:72: INFO main/helper: with prefix example_test.go:73: INFO key/value pairs int=1 float=2 pair="(1, 2)" kobj="kube-system/sally" --- PASS: TestKlog (0.00s) The corresponding output from go-logr/logr/testing would be: === RUN TestLogr example_test.go:69: "ts"="2021-09-07 16:44:54.307551" "level"=0 "msg"="hello world" example_test.go:70: "ts"="2021-09-07 16:44:54.307664" "msg"="failed" "error"="failed: some error" example_test.go:71: "ts"="2021-09-07 16:44:54.307686" "level"=1 "msg"="verbosity 1" example_test.go:72: main/helper: "ts"="2021-09-07 16:44:54.307703" "level"=0 "msg"="with prefix" example_test.go:73: "ts"="2021-09-07 16:44:54.307733" "level"=0 "msg"="key/value pairs" "int"=1 "float"=2 "pair"={} "kobj"={"name":"sally","namespace":"kube-system"} --- PASS: TestLogr (0.00s) --- ktesting/example/example_test.go | 60 +++++++++++++ ktesting/init/init.go | 35 ++++++++ ktesting/options.go | 130 +++++++++++++++++++++++++++ ktesting/setup.go | 48 ++++++++++ ktesting/testinglogger.go | 139 +++++++++++++++++++++++++++++ ktesting/testinglogger_test.go | 147 +++++++++++++++++++++++++++++++ 6 files changed, 559 insertions(+) create mode 100644 ktesting/example/example_test.go create mode 100644 ktesting/init/init.go create mode 100644 ktesting/options.go create mode 100644 ktesting/setup.go create mode 100644 ktesting/testinglogger.go create mode 100644 ktesting/testinglogger_test.go diff --git a/ktesting/example/example_test.go b/ktesting/example/example_test.go new file mode 100644 index 00000000..79eeef44 --- /dev/null +++ b/ktesting/example/example_test.go @@ -0,0 +1,60 @@ +/* +Copyright 2021 The Kubernetes Authors. + +SPDX-License-Identifier: Apache-2.0 +*/ + +package example + +import ( + "fmt" + "testing" + + "k8s.io/klog/v2" + "k8s.io/klog/v2/internal/test" + "k8s.io/klog/v2/ktesting" + _ "k8s.io/klog/v2/ktesting/init" // add command line flags +) + +func TestKlogr(t *testing.T) { + logger, _ := ktesting.NewTestContext(t) + exampleOutput(logger) +} + +type pair struct { + a, b int +} + +func (p pair) String() string { + return fmt.Sprintf("(%d, %d)", p.a, p.b) +} + +var _ fmt.Stringer = pair{} + +type err struct { + msg string +} + +func (e err) Error() string { + return "failed: " + e.msg +} + +var _ error = err{} + +func exampleOutput(logger klog.Logger) { + logger.Info("hello world") + logger.Error(err{msg: "some error"}, "failed") + logger.V(1).Info("verbosity 1") + logger.WithName("main").WithName("helper").Info("with prefix") + obj := test.KMetadataMock{Name: "joe", NS: "kube-system"} + logger.Info("key/value pairs", + "int", 1, + "float", 2.0, + "pair", pair{a: 1, b: 2}, + "raw", obj, + "kobj", klog.KObj(obj), + ) + logger.V(4).Info("info message level 4") + logger.V(5).Info("info message level 5") + logger.V(6).Info("info message level 6") +} diff --git a/ktesting/init/init.go b/ktesting/init/init.go new file mode 100644 index 00000000..c1fa145a --- /dev/null +++ b/ktesting/init/init.go @@ -0,0 +1,35 @@ +/* +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 init registers the command line flags for k8s.io/klogr/testing in +// the flag.CommandLine. This is done during initialization, so merely +// importing it is enough. +// +// Experimental +// +// Notice: This package is EXPERIMENTAL and may be changed or removed in a +// later release. +package init + +import ( + "flag" + + "k8s.io/klog/v2/ktesting" +) + +func init() { + ktesting.DefaultConfig.AddFlags(flag.CommandLine) +} diff --git a/ktesting/options.go b/ktesting/options.go new file mode 100644 index 00000000..8cb13c40 --- /dev/null +++ b/ktesting/options.go @@ -0,0 +1,130 @@ +/* +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 ktesting + +import ( + "flag" + "strconv" + + "k8s.io/klog/v2/internal/verbosity" +) + +// Config influences logging in a test logger. To make this configurable via +// command line flags, instantiate this once per program and use AddFlags to +// bind command line flags to the instance before passing it to NewTestContext. +// +// Must be constructed with NewConfig. +// +// Experimental +// +// Notice: This type is EXPERIMENTAL and may be changed or removed in a +// later release. +type Config struct { + vstate *verbosity.VState + co configOptions +} + +// ConfigOption implements functional parameters for NewConfig. +// +// Experimental +// +// Notice: This type is EXPERIMENTAL and may be changed or removed in a +// later release. +type ConfigOption func(co *configOptions) + +type configOptions struct { + verbosityFlagName string + vmoduleFlagName string + verbosityDefault int +} + +// VerbosityFlagName overrides the default -testing.v for the verbosity level. +// +// Experimental +// +// Notice: This function is EXPERIMENTAL and may be changed or removed in a +// later release. +func VerbosityFlagName(name string) ConfigOption { + return func(co *configOptions) { + co.verbosityFlagName = name + } +} + +// VModulFlagName overrides the default -testing.vmodule for the per-module +// verbosity levels. +// +// Experimental +// +// Notice: This function is EXPERIMENTAL and may be changed or removed in a +// later release. +func VModuleFlagName(name string) ConfigOption { + return func(co *configOptions) { + co.vmoduleFlagName = name + } +} + +// Verbosity overrides the default verbosity level of 5. That default is higher +// than in klog itself because it enables logging entries for "the steps +// leading up to errors and warnings" and "troubleshooting" (see +// https://github.com/kubernetes/community/blob/9406b4352fe2d5810cb21cc3cb059ce5886de157/contributors/devel/sig-instrumentation/logging.md#logging-conventions), +// which is useful when debugging a failed test. `go test` only shows the log +// output for failed tests. To see all output, use `go test -v`. +// +// Experimental +// +// Notice: This function is EXPERIMENTAL and may be changed or removed in a +// later release. +func Verbosity(level int) ConfigOption { + return func(co *configOptions) { + co.verbosityDefault = level + } +} + +// NewConfig returns a configuration with recommended defaults and optional +// modifications. Command line flags are not bound to any FlagSet yet. +// +// Experimental +// +// Notice: This function is EXPERIMENTAL and may be changed or removed in a +// later release. +func NewConfig(opts ...ConfigOption) *Config { + c := &Config{ + co: configOptions{ + verbosityFlagName: "testing.v", + vmoduleFlagName: "testing.vmodule", + verbosityDefault: 5, + }, + } + for _, opt := range opts { + opt(&c.co) + } + + c.vstate = verbosity.New() + c.vstate.V().Set(strconv.FormatInt(int64(c.co.verbosityDefault), 10)) + return c +} + +// AddFlags registers the command line flags that control the configuration. +// +// Experimental +// +// Notice: This function is EXPERIMENTAL and may be changed or removed in a +// later release. +func (c *Config) AddFlags(fs *flag.FlagSet) { + fs.Var(c.vstate.V(), c.co.verbosityFlagName, "number for the log level verbosity of the testing logger") + fs.Var(c.vstate.VModule(), c.co.vmoduleFlagName, "comma-separated list of pattern=N log level settings for files matching the patterns") +} diff --git a/ktesting/setup.go b/ktesting/setup.go new file mode 100644 index 00000000..d3029ae9 --- /dev/null +++ b/ktesting/setup.go @@ -0,0 +1,48 @@ +/* +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 ktesting + +import ( + "context" + + "github.com/go-logr/logr" +) + +// DefaultConfig is the global default logging configuration for a unit +// test. It is used by NewTestContext and k8s.io/klogr/testing/init. +// +// Experimental +// +// Notice: This variable is EXPERIMENTAL and may be changed or removed in a +// later release. +var DefaultConfig = NewConfig() + +// NewTestContext returns a logger and context for use in a unit test case or +// benchmark. The tl parameter can be a testing.T or testing.B pointer that +// will receive all log output. Importing k8s.io/klogr/testing/init will add +// command line flags that modify the configuration of that log output. +// +// Experimental +// +// Notice: This function is EXPERIMENTAL and may be changed or removed in a +// later release. +func NewTestContext(tl TL) (logr.Logger, context.Context) { + logger := NewLogger(tl, DefaultConfig) + ctx := logr.NewContext(context.Background(), logger) + return logger, ctx + +} diff --git a/ktesting/testinglogger.go b/ktesting/testinglogger.go new file mode 100644 index 00000000..5269f89d --- /dev/null +++ b/ktesting/testinglogger.go @@ -0,0 +1,139 @@ +/* +Copyright 2019 The Kubernetes Authors. +Copyright 2020 Intel Coporation. + +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 testinglogger contains an implementation of the logr interface +// which is logging through a function like testing.TB.Log function. +// Therefore it can be used in standard Go tests and Gingko test suites +// to ensure that output is associated with the currently running test. +// +// Serialization of the structured log parameters is done in the same way +// as for klog.InfoS. +// +// Experimental +// +// Notice: This package is EXPERIMENTAL and may be changed or removed in a +// later release. +package ktesting + +import ( + "bytes" + + "github.com/go-logr/logr" + + "k8s.io/klog/v2/internal/serialize" + "k8s.io/klog/v2/internal/verbosity" +) + +// TL is the relevant subset of testing.TB. +// +// Experimental +// +// Notice: This type is EXPERIMENTAL and may be changed or removed in a +// later release. +type TL interface { + Helper() + Log(args ...interface{}) +} + +// NewLogger constructs a new logger for the given test interface. +// +// Experimental +// +// Notice: This type is EXPERIMENTAL and may be changed or removed in a +// later release. +func NewLogger(t TL, c *Config) logr.Logger { + return logr.New(&tlogger{ + t: t, + prefix: "", + values: nil, + config: c, + }) +} + +type tlogger struct { + t TL + prefix string + values []interface{} + config *Config +} + +func (l *tlogger) Init(info logr.RuntimeInfo) { +} + +func (l *tlogger) GetCallStackHelper() func() { + return l.t.Helper +} + +func (l *tlogger) Info(level int, msg string, kvList ...interface{}) { + l.t.Helper() + buffer := &bytes.Buffer{} + trimmed := serialize.TrimDuplicates(l.values, kvList) + serialize.KVListFormat(buffer, trimmed[0]...) + serialize.KVListFormat(buffer, trimmed[1]...) + l.log("INFO", msg, buffer) +} + +func (l *tlogger) Enabled(level int) bool { + return l.config.vstate.Enabled(verbosity.Level(level), 1) +} + +func (l *tlogger) Error(err error, msg string, kvList ...interface{}) { + l.t.Helper() + buffer := &bytes.Buffer{} + if err != nil { + serialize.KVListFormat(buffer, "err", err) + } + trimmed := serialize.TrimDuplicates(l.values, kvList) + serialize.KVListFormat(buffer, trimmed[0]...) + serialize.KVListFormat(buffer, trimmed[1]...) + l.log("ERROR", msg, buffer) +} + +func (l *tlogger) log(what, msg string, buffer *bytes.Buffer) { + l.t.Helper() + args := []interface{}{what} + if l.prefix != "" { + args = append(args, l.prefix+":") + } + args = append(args, msg) + if buffer.Len() > 0 { + // Skip leading space inserted by serialize.KVListFormat. + args = append(args, string(buffer.Bytes()[1:])) + } + l.t.Log(args...) +} + +// WithName returns a new logr.Logger with the specified name appended. klogr +// uses '/' characters to separate name elements. Callers should not pass '/' +// in the provided name string, but this library does not actually enforce that. +func (l *tlogger) WithName(name string) logr.LogSink { + new := *l + if len(l.prefix) > 0 { + new.prefix = l.prefix + "/" + } + new.prefix += name + return &new +} + +func (l *tlogger) WithValues(kvList ...interface{}) logr.LogSink { + new := *l + new.values = serialize.WithValues(l.values, kvList) + return &new +} + +var _ logr.LogSink = &tlogger{} +var _ logr.CallStackHelperLogSink = &tlogger{} diff --git a/ktesting/testinglogger_test.go b/ktesting/testinglogger_test.go new file mode 100644 index 00000000..430ece7c --- /dev/null +++ b/ktesting/testinglogger_test.go @@ -0,0 +1,147 @@ +/* +Copyright 2019 The Kubernetes Authors. +Copyright 2020 Intel Coporation. + +SPDX-License-Identifier: Apache-2.0 +*/ + +package ktesting + +import ( + "bytes" + "errors" + "fmt" + "testing" +) + +func TestInfo(t *testing.T) { + tests := map[string]struct { + text string + withValues []interface{} + keysAndValues []interface{} + names []string + err error + expectedOutput string + }{ + "should log with values passed to keysAndValues": { + text: "test", + keysAndValues: []interface{}{"akey", "avalue"}, + expectedOutput: `INFO test akey="avalue" +`, + }, + "should support single name": { + names: []string{"hello"}, + text: "test", + keysAndValues: []interface{}{"akey", "avalue"}, + expectedOutput: `INFO hello: test akey="avalue" +`, + }, + "should support multiple names": { + names: []string{"hello", "world"}, + text: "test", + keysAndValues: []interface{}{"akey", "avalue"}, + expectedOutput: `INFO hello/world: test akey="avalue" +`, + }, + "should not print duplicate keys with the same value": { + text: "test", + keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue"}, + expectedOutput: `INFO test akey="avalue" +`, + }, + "should only print the last duplicate key when the values are passed to Info": { + text: "test", + keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue2"}, + expectedOutput: `INFO test akey="avalue2" +`, + }, + "should only print the duplicate key that is passed to Info if one was passed to the logger": { + withValues: []interface{}{"akey", "avalue"}, + text: "test", + keysAndValues: []interface{}{"akey", "avalue"}, + expectedOutput: `INFO test akey="avalue" +`, + }, + "should only print the key passed to Info when one is already set on the logger": { + withValues: []interface{}{"akey", "avalue"}, + text: "test", + keysAndValues: []interface{}{"akey", "avalue2"}, + expectedOutput: `INFO test akey="avalue2" +`, + }, + "should correctly handle odd-numbers of KVs": { + text: "test", + keysAndValues: []interface{}{"akey", "avalue", "akey2"}, + expectedOutput: `INFO test akey="avalue" akey2="(MISSING)" +`, + }, + "should correctly html characters": { + text: "test", + keysAndValues: []interface{}{"akey", "<&>"}, + expectedOutput: `INFO test akey="<&>" +`, + }, + "should correctly handle odd-numbers of KVs in both log values and Info args": { + withValues: []interface{}{"basekey1", "basevar1", "basekey2"}, + text: "test", + keysAndValues: []interface{}{"akey", "avalue", "akey2"}, + expectedOutput: `INFO test basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)" +`, + }, + "should correctly print regular error types": { + text: "test", + keysAndValues: []interface{}{"err", errors.New("whoops")}, + expectedOutput: `INFO test err="whoops" +`, + }, + "should correctly print regular error types when using logr.Error": { + text: "test", + err: errors.New("whoops"), + expectedOutput: `ERROR test err="whoops" +`, + }, + } + for n, test := range tests { + t.Run(n, func(t *testing.T) { + var buffer logToBuf + klogr := NewLogger(&buffer, NewConfig()) + for _, name := range test.names { + klogr = klogr.WithName(name) + } + klogr = klogr.WithValues(test.withValues...) + + if test.err != nil { + klogr.Error(test.err, test.text, test.keysAndValues...) + } else { + klogr.Info(test.text, test.keysAndValues...) + } + + actual := buffer.String() + if actual != test.expectedOutput { + t.Errorf("expected %q did not match actual %q", test.expectedOutput, actual) + } + }) + } +} + +func TestCallDepth(t *testing.T) { + logger := NewLogger(t, NewConfig()) + logger.Info("hello world") +} + +type logToBuf struct { + bytes.Buffer +} + +func (l *logToBuf) Helper() { +} + +func (l *logToBuf) Log(args ...interface{}) { + for i, arg := range args { + if i > 0 { + l.Write([]byte(" ")) + } + l.Write([]byte(fmt.Sprintf("%s", arg))) + } + l.Write([]byte("\n")) +} From 64be5637edad883da0b6bca0af865711439095be Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Mon, 7 Feb 2022 11:10:05 +0100 Subject: [PATCH 2/4] move Kubernetes helper code into separate file The goal is to have only "legacy" code in klog.go. --- k8s_references.go | 94 +++++++++++++++++++++++++++++++++++++++++++++++ klog.go | 71 ----------------------------------- 2 files changed, 94 insertions(+), 71 deletions(-) create mode 100644 k8s_references.go diff --git a/k8s_references.go b/k8s_references.go new file mode 100644 index 00000000..db58f8ba --- /dev/null +++ b/k8s_references.go @@ -0,0 +1,94 @@ +/* +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 klog + +import ( + "fmt" + "reflect" + + "github.com/go-logr/logr" +) + +// ObjectRef references a kubernetes object +type ObjectRef struct { + Name string `json:"name"` + Namespace string `json:"namespace,omitempty"` +} + +func (ref ObjectRef) String() string { + if ref.Namespace != "" { + return fmt.Sprintf("%s/%s", ref.Namespace, ref.Name) + } + return ref.Name +} + +// MarshalLog ensures that loggers with support for structured output will log +// as a struct by removing the String method via a custom type. +func (ref ObjectRef) MarshalLog() interface{} { + type or ObjectRef + return or(ref) +} + +var _ logr.Marshaler = ObjectRef{} + +// KMetadata is a subset of the kubernetes k8s.io/apimachinery/pkg/apis/meta/v1.Object interface +// this interface may expand in the future, but will always be a subset of the +// kubernetes k8s.io/apimachinery/pkg/apis/meta/v1.Object interface +type KMetadata interface { + GetName() string + GetNamespace() string +} + +// KObj returns ObjectRef from ObjectMeta +func KObj(obj KMetadata) ObjectRef { + if obj == nil { + return ObjectRef{} + } + if val := reflect.ValueOf(obj); val.Kind() == reflect.Ptr && val.IsNil() { + return ObjectRef{} + } + + return ObjectRef{ + Name: obj.GetName(), + Namespace: obj.GetNamespace(), + } +} + +// KRef returns ObjectRef from name and namespace +func KRef(namespace, name string) ObjectRef { + return ObjectRef{ + Name: name, + Namespace: namespace, + } +} + +// KObjs returns slice of ObjectRef from an slice of ObjectMeta +func KObjs(arg interface{}) []ObjectRef { + s := reflect.ValueOf(arg) + if s.Kind() != reflect.Slice { + return nil + } + objectRefs := make([]ObjectRef, 0, s.Len()) + for i := 0; i < s.Len(); i++ { + if v, ok := s.Index(i).Interface().(KMetadata); ok { + objectRefs = append(objectRefs, KObj(v)) + } else { + return nil + } + } + return objectRefs +} diff --git a/klog.go b/klog.go index 3435461d..d455c45c 100644 --- a/klog.go +++ b/klog.go @@ -81,7 +81,6 @@ import ( "math" "os" "path/filepath" - "reflect" "runtime" "strconv" "strings" @@ -1536,73 +1535,3 @@ type LogFilter interface { func SetLogFilter(filter LogFilter) { logging.filter = filter } - -// ObjectRef references a kubernetes object -type ObjectRef struct { - Name string `json:"name"` - Namespace string `json:"namespace,omitempty"` -} - -func (ref ObjectRef) String() string { - if ref.Namespace != "" { - return fmt.Sprintf("%s/%s", ref.Namespace, ref.Name) - } - return ref.Name -} - -// MarshalLog ensures that loggers with support for structured output will log -// as a struct by removing the String method via a custom type. -func (ref ObjectRef) MarshalLog() interface{} { - type or ObjectRef - return or(ref) -} - -var _ logr.Marshaler = ObjectRef{} - -// KMetadata is a subset of the kubernetes k8s.io/apimachinery/pkg/apis/meta/v1.Object interface -// this interface may expand in the future, but will always be a subset of the -// kubernetes k8s.io/apimachinery/pkg/apis/meta/v1.Object interface -type KMetadata interface { - GetName() string - GetNamespace() string -} - -// KObj returns ObjectRef from ObjectMeta -func KObj(obj KMetadata) ObjectRef { - if obj == nil { - return ObjectRef{} - } - if val := reflect.ValueOf(obj); val.Kind() == reflect.Ptr && val.IsNil() { - return ObjectRef{} - } - - return ObjectRef{ - Name: obj.GetName(), - Namespace: obj.GetNamespace(), - } -} - -// KRef returns ObjectRef from name and namespace -func KRef(namespace, name string) ObjectRef { - return ObjectRef{ - Name: name, - Namespace: namespace, - } -} - -// KObjs returns slice of ObjectRef from an slice of ObjectMeta -func KObjs(arg interface{}) []ObjectRef { - s := reflect.ValueOf(arg) - if s.Kind() != reflect.Slice { - return nil - } - objectRefs := make([]ObjectRef, 0, s.Len()) - for i := 0; i < s.Len(); i++ { - if v, ok := s.Index(i).Interface().(KMetadata); ok { - objectRefs = append(objectRefs, KObj(v)) - } else { - return nil - } - } - return objectRefs -} From d8885505366606dbacabd9c781a7aba7ff458e12 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Mon, 7 Feb 2022 11:43:16 +0100 Subject: [PATCH 3/4] make klog sufficient for working with logr As discussed in https://github.com/kubernetes/enhancements/pull/3078, enabling code that only imports klog for all logging makes life simpler for developers. This was also the reason why KObj was added to klog instead of a separate helper package. --- imports.go | 58 ++++++++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 58 insertions(+) create mode 100644 imports.go diff --git a/imports.go b/imports.go new file mode 100644 index 00000000..43cd0819 --- /dev/null +++ b/imports.go @@ -0,0 +1,58 @@ +/* +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 klog + +import ( + "github.com/go-logr/logr" +) + +// The reason for providing these aliases is to allow code to work with logr +// without directly importing it. + +// Logger in this package is exactly the same as logr.Logger. +// +// Experimental +// +// Notice: This type is EXPERIMENTAL and may be changed or removed in a +// later release. +type Logger = logr.Logger + +// LogSink in this package is exactly the same as logr.LogSink. +// +// Experimental +// +// Notice: This type is EXPERIMENTAL and may be changed or removed in a +// later release. +type LogSink = logr.LogSink + +// Runtimeinfo in this package is exactly the same as logr.RuntimeInfo. +// +// Experimental +// +// Notice: This type is EXPERIMENTAL and may be changed or removed in a +// later release. +type RuntimeInfo = logr.RuntimeInfo + +var ( + // New is an alias for logr.New. + // + // Experimental + // + // Notice: This variable is EXPERIMENTAL and may be changed or removed in a + // later release. + New = logr.New +) From 260ac219dda6b7427653d082b1265b95303166ec Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Mon, 7 Feb 2022 12:26:00 +0100 Subject: [PATCH 4/4] contextual logging This moves the global logger into a separate file together with the functions that implement contextual logging. The advantage of SetLoggerWithOptions over alternatives like a SetContextualLogger without options is that it can be used as a drop-in replacement for SetLogger. This allows us to deprecate SetLogger. Whether we actually do that is kept open for now. --- contextual.go | 246 ++++++++++++++++++++++++++++ contextual_test.go | 43 +++++ examples/output_test/output_test.go | 55 ++++++- klog.go | 109 +++++------- klogr.go | 92 +++++++++++ 5 files changed, 473 insertions(+), 72 deletions(-) create mode 100644 contextual.go create mode 100644 contextual_test.go create mode 100644 klogr.go diff --git a/contextual.go b/contextual.go new file mode 100644 index 00000000..67492670 --- /dev/null +++ b/contextual.go @@ -0,0 +1,246 @@ +/* +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 klog + +import ( + "context" + + "github.com/go-logr/logr" +) + +// This file provides the implementation of +// https://github.com/kubernetes/enhancements/tree/master/keps/sig-instrumentation/1602-structured-logging +// +// SetLogger and ClearLogger were originally added to klog.go and got moved +// here. Contextual logging adds a way to retrieve a Logger for direct logging +// without the logging calls in klog.go. +// +// The global variables are expected to be modified only during sequential +// parts of a program (init, serial tests) and therefore are not protected by +// mutex locking. + +var ( + // contextualLoggingEnabled controls whether contextual logging is + // active. Disabling it may have some small performance benefit. + contextualLoggingEnabled = true + + // globalLogger is the global Logger chosen by users of klog, nil if + // none is available. + globalLogger *Logger + + // contextualLogger defines whether globalLogger may get called + // directly. + contextualLogger bool + + // klogLogger is used as fallback for logging through the normal klog code + // when no Logger is set. + klogLogger logr.Logger = logr.New(&klogger{}) +) + +// SetLogger sets a Logger implementation that will be used as backing +// implementation of the traditional klog log calls. klog will do its own +// verbosity checks before calling logger.V().Info. logger.Error is always +// called, regardless of the klog verbosity settings. +// +// If set, all log lines will be suppressed from the regular output, and +// redirected to the logr implementation. +// Use as: +// ... +// klog.SetLogger(zapr.NewLogger(zapLog)) +// +// To remove a backing logr implemention, use ClearLogger. Setting an +// empty logger with SetLogger(logr.Logger{}) does not work. +// +// Modifying the logger is not thread-safe and should be done while no other +// goroutines invoke log calls, usually during program initialization. +func SetLogger(logger logr.Logger) { + SetLoggerWithOptions(logger) +} + +// SetLoggerWithOptions is a more flexible version of SetLogger. Without +// additional options, it behaves exactly like SetLogger. By passing +// ContextualLogger(true) as option, it can be used to set a logger that then +// will also get called directly by applications which retrieve it via +// FromContext, Background, or TODO. +// +// Supporting direct calls is recommended because it avoids the overhead of +// routing log entries through klogr into klog and then into the actual Logger +// backend. +// +// Experimental +// +// Notice: This function is EXPERIMENTAL and may be changed or removed in a +// later release. +func SetLoggerWithOptions(logger logr.Logger, opts ...LoggerOption) { + globalLogger = &logger + var o loggerOptions + for _, opt := range opts { + opt(&o) + } + contextualLogger = o.contextualLogger +} + +// ContextualLogger determines whether the logger passed to +// SetLoggerWithOptions may also get called directly. Such a logger cannot rely +// on verbosity checking in klog. +// +// Experimental +// +// Notice: This function is EXPERIMENTAL and may be changed or removed in a +// later release. +func ContextualLogger(enabled bool) LoggerOption { + return func(o *loggerOptions) { + o.contextualLogger = enabled + } +} + +// LoggerOption implements the functional parameter paradigm for +// SetLoggerWithOptions. +// +// Experimental +// +// Notice: This type is EXPERIMENTAL and may be changed or removed in a +// later release. +type LoggerOption func(o *loggerOptions) + +type loggerOptions struct { + contextualLogger bool +} + +// SetContextualLogger does the same as SetLogger, but in addition the +// logger may also get called directly by code that retrieves it +// with FromContext, TODO or Background. The logger therefore must +// implements its own verbosity checking. +func SetContextualLogger(logger logr.Logger) { + globalLogger = &logger + contextualLogger = true +} + +// ClearLogger removes a backing Logger implementation if one was set earlier +// with SetLogger. +// +// Modifying the logger is not thread-safe and should be done while no other +// goroutines invoke log calls, usually during program initialization. +func ClearLogger() { + globalLogger = nil +} + +// EnableContextualLogging controls whether contextual logging is enabled. +// By default it is enabled. When disabled, FromContext avoids looking up +// the logger in the context and always returns the global logger. +// LoggerWithValues, LoggerWithName, and NewContext become no-ops +// and return their input logger respectively context. This may be useful +// to avoid the additional overhead for contextual logging. +// +// This must be called during initialization before goroutines are started. +// +// Experimental +// +// Notice: This function is EXPERIMENTAL and may be changed or removed in a +// later release. +func EnableContextualLogging(enabled bool) { + contextualLoggingEnabled = enabled +} + +// FromContext retrieves a logger set by the caller or, if not set, +// falls back to the program's global logger (a Logger instance or klog +// itself). +// +// Experimental +// +// Notice: This function is EXPERIMENTAL and may be changed or removed in a +// later release. +func FromContext(ctx context.Context) Logger { + if contextualLoggingEnabled { + if logger, err := logr.FromContext(ctx); err == nil { + return logger + } + } + + return Background() +} + +// TODO can be used as a last resort by code that has no means of +// receiving a logger from its caller. FromContext or an explicit logger +// parameter should be used instead. +// +// Experimental +// +// Notice: This function is EXPERIMENTAL and may be changed or removed in a +// later release. +func TODO() Logger { + return Background() +} + +// Background retrieves the fallback logger. It should not be called before +// that logger was initialized by the program and not by code that should +// better receive a logger via its parameters. TODO can be used as a temporary +// solution for such code. +// +// Experimental +// +// Notice: This function is EXPERIMENTAL and may be changed or removed in a +// later release. +func Background() Logger { + if globalLogger != nil && contextualLogger { + return *globalLogger + } + + return klogLogger +} + +// LoggerWithValues returns logger.WithValues(...kv) when +// contextual logging is enabled, otherwise the logger. +// +// Experimental +// +// Notice: This function is EXPERIMENTAL and may be changed or removed in a +// later release. +func LoggerWithValues(logger Logger, kv ...interface{}) Logger { + if contextualLoggingEnabled { + return logger.WithValues(kv...) + } + return logger +} + +// LoggerWithName returns logger.WithName(name) when contextual logging is +// enabled, otherwise the logger. +// +// Experimental +// +// Notice: This function is EXPERIMENTAL and may be changed or removed in a +// later release. +func LoggerWithName(logger Logger, name string) Logger { + if contextualLoggingEnabled { + return logger.WithName(name) + } + return logger +} + +// NewContext returns logr.NewContext(ctx, logger) when +// contextual logging is enabled, otherwise ctx. +// +// Experimental +// +// Notice: This function is EXPERIMENTAL and may be changed or removed in a +// later release. +func NewContext(ctx context.Context, logger Logger) context.Context { + if contextualLoggingEnabled { + return logr.NewContext(ctx, logger) + } + return ctx +} diff --git a/contextual_test.go b/contextual_test.go new file mode 100644 index 00000000..fc95f05f --- /dev/null +++ b/contextual_test.go @@ -0,0 +1,43 @@ +/* +Copyright 2022 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 klog_test + +import ( + "fmt" + + "github.com/go-logr/logr" + "k8s.io/klog/v2" +) + +func ExampleSetLogger() { + // Logger is only used as backend, Background() returns klogr. + klog.SetLogger(logr.Discard()) + fmt.Printf("logger after SetLogger: %T\n", klog.Background().GetSink()) + + // Logger is only used as backend, Background() returns klogr. + klog.SetLoggerWithOptions(logr.Discard(), klog.ContextualLogger(false)) + fmt.Printf("logger after SetLoggerWithOptions with ContextualLogger(false): %T\n", klog.Background().GetSink()) + + // Logger is used as backend and directly. + klog.SetLoggerWithOptions(logr.Discard(), klog.ContextualLogger(true)) + fmt.Printf("logger after SetLoggerWithOptions with ContextualLogger(true): %T\n", klog.Background().GetSink()) + + // Output: + // logger after SetLogger: *klog.klogger + // logger after SetLoggerWithOptions with ContextualLogger(false): *klog.klogger + // logger after SetLoggerWithOptions with ContextualLogger(true): logr.discardLogSink +} diff --git a/examples/output_test/output_test.go b/examples/output_test/output_test.go index 0624e3a7..b4170121 100644 --- a/examples/output_test/output_test.go +++ b/examples/output_test/output_test.go @@ -85,7 +85,7 @@ func TestKlogrOutput(t *testing.T) { }) } -// TestKlogrStackText tests klogr -> klog -> text logger. +// TestKlogrStackText tests klogr.klogr -> klog -> text logger. func TestKlogrStackText(t *testing.T) { newLogger := func(out io.Writer, v int, vmodule string) logr.Logger { // Backend: text output. @@ -104,7 +104,7 @@ func TestKlogrStackText(t *testing.T) { test.Output(t, test.OutputConfig{NewLogger: newLogger, SupportsVModule: true}) } -// TestKlogrStackKlogr tests klogr -> klog -> zapr. +// TestKlogrStackKlogr tests klogr.klogr -> klog -> zapr. // // This exposes whether verbosity is passed through correctly // (https://github.com/kubernetes/klog/issues/294) because klogr logging @@ -136,6 +136,57 @@ func TestKlogrStackZapr(t *testing.T) { test.Output(t, test.OutputConfig{NewLogger: newLogger, ExpectedOutputMapping: mapping}) } +// TestKlogrInternalStackText tests klog.klogr (the simplified version used for contextual logging) -> klog -> text logger. +func TestKlogrInternalStackText(t *testing.T) { + newLogger := func(out io.Writer, v int, vmodule string) logr.Logger { + // Backend: text output. + config := textlogger.NewConfig( + textlogger.Verbosity(v), + textlogger.Output(out), + ) + if err := config.VModule().Set(vmodule); err != nil { + panic(err) + } + klog.SetLogger(textlogger.NewLogger(config)) + + // Frontend: internal klogr. + return klog.NewKlogr() + } + test.Output(t, test.OutputConfig{NewLogger: newLogger, SupportsVModule: true}) +} + +// TestKlogrInternalStackKlogr tests klog.klogr (the simplified version used for contextual logging) -> klog -> zapr. +// +// This exposes whether verbosity is passed through correctly +// (https://github.com/kubernetes/klog/issues/294) because klogr logging +// records that. +func TestKlogrInternalStackZapr(t *testing.T) { + mapping := test.ZaprOutputMappingIndirect() + + // klogr doesn't warn about invalid KVs and just inserts + // "(MISSING)". + for key, value := range map[string]string{ + `I output.go:] "odd arguments" akey="avalue" akey2="(MISSING)" +`: `{"caller":"test/output.go:","msg":"odd arguments","v":0,"akey":"avalue","akey2":"(MISSING)"} +`, + + `I output.go:] "both odd" basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)" +`: `{"caller":"test/output.go:","msg":"both odd","v":0,"basekey1":"basevar1","basekey2":"(MISSING)","akey":"avalue","akey2":"(MISSING)"} +`, + } { + mapping[key] = value + } + + newLogger := func(out io.Writer, v int, vmodule string) logr.Logger { + // Backend: zapr as configured in k8s.io/component-base/logs/json. + klog.SetLogger(newZaprLogger(out, v)) + + // Frontend: internal klogr. + return klog.NewKlogr() + } + test.Output(t, test.OutputConfig{NewLogger: newLogger, ExpectedOutputMapping: mapping}) +} + func newZaprLogger(out io.Writer, v int) logr.Logger { encoderConfig := &zapcore.EncoderConfig{ MessageKey: "msg", diff --git a/klog.go b/klog.go index d455c45c..e2eb0f5c 100644 --- a/klog.go +++ b/klog.go @@ -483,9 +483,6 @@ type loggingT struct { // If true, add the file directory to the header addDirHeader bool - // If set, all output will be redirected unconditionally to the provided logr.Logger - logr *logr.Logger - // If true, messages will not be propagated to lower severity log levels oneOutput bool @@ -685,7 +682,7 @@ func (l *loggingT) printS(err error, s severity.Severity, depth int, msg string, serialize.KVListFormat(&b.Buffer, "err", err) } serialize.KVListFormat(&b.Buffer, keysAndValues...) - l.printDepth(s, logging.logr, nil, depth+1, &b.Buffer) + l.printDepth(s, globalLogger, nil, depth+1, &b.Buffer) // Make the buffer available for reuse. l.bufferCache.PutBuffer(b) } @@ -707,34 +704,6 @@ func (rb *redirectBuffer) Write(bytes []byte) (n int, err error) { return rb.w.Write(bytes) } -// SetLogger will set the backing logr implementation for klog. -// If set, all log lines will be suppressed from the regular Output, and -// redirected to the logr implementation. -// Use as: -// ... -// klog.SetLogger(zapr.NewLogger(zapLog)) -// -// To remove a backing logr implemention, use ClearLogger. Setting an -// empty logger with SetLogger(logr.Logger{}) does not work. -// -// Modifying the logger is not thread-safe and should be done while no other -// goroutines invoke log calls, usually during program initialization. -func SetLogger(logr logr.Logger) { - logging.logr = &logr -} - -// ClearLogger removes a backing logr implementation if one was set earlier -// with SetLogger. -// -// Modifying the logger is not thread-safe and should be done while no other -// goroutines invoke log calls, usually during program initialization. -func ClearLogger() { - logging.mu.Lock() - defer logging.mu.Unlock() - - logging.logr = nil -} - // SetOutput sets the output destination for all severities func SetOutput(w io.Writer) { logging.mu.Lock() @@ -790,7 +759,7 @@ func (l *loggingT) output(s severity.Severity, log *logr.Logger, buf *buffer.Buf // TODO: set 'severity' and caller information as structured log info // keysAndValues := []interface{}{"severity", severityName[s], "file", file, "line", line} if s == severity.ErrorLog { - logging.logr.WithCallDepth(depth+3).Error(nil, string(data)) + globalLogger.WithCallDepth(depth+3).Error(nil, string(data)) } else { log.WithCallDepth(depth + 3).Info(string(data)) } @@ -1111,7 +1080,7 @@ func (lb logBridge) Write(b []byte) (n int, err error) { } // printWithFileLine with alsoToStderr=true, so standard log messages // always appear on standard error. - logging.printWithFileLine(severity.Severity(lb), logging.logr, logging.filter, file, line, true, text) + logging.printWithFileLine(severity.Severity(lb), globalLogger, logging.filter, file, line, true, text) return len(b), nil } @@ -1149,10 +1118,10 @@ type Verbose struct { } func newVerbose(level Level, b bool) Verbose { - if logging.logr == nil { + if globalLogger == nil { return Verbose{b, nil} } - v := logging.logr.V(int(level)) + v := globalLogger.V(int(level)) return Verbose{b, &v} } @@ -1271,7 +1240,7 @@ func (v Verbose) InfoS(msg string, keysAndValues ...interface{}) { // InfoSDepth acts as InfoS but uses depth to determine which call frame to log. // InfoSDepth(0, "msg") is the same as InfoS("msg"). func InfoSDepth(depth int, msg string, keysAndValues ...interface{}) { - logging.infoS(logging.logr, logging.filter, depth, msg, keysAndValues...) + logging.infoS(globalLogger, logging.filter, depth, msg, keysAndValues...) } // InfoSDepth is equivalent to the global InfoSDepth function, guarded by the value of v. @@ -1300,37 +1269,37 @@ func (v Verbose) ErrorS(err error, msg string, keysAndValues ...interface{}) { // Info logs to the INFO log. // Arguments are handled in the manner of fmt.Print; a newline is appended if missing. func Info(args ...interface{}) { - logging.print(severity.InfoLog, logging.logr, logging.filter, args...) + logging.print(severity.InfoLog, globalLogger, logging.filter, args...) } // InfoDepth acts as Info but uses depth to determine which call frame to log. // InfoDepth(0, "msg") is the same as Info("msg"). func InfoDepth(depth int, args ...interface{}) { - logging.printDepth(severity.InfoLog, logging.logr, logging.filter, depth, args...) + logging.printDepth(severity.InfoLog, globalLogger, logging.filter, depth, args...) } // Infoln logs to the INFO log. // Arguments are handled in the manner of fmt.Println; a newline is always appended. func Infoln(args ...interface{}) { - logging.println(severity.InfoLog, logging.logr, logging.filter, args...) + logging.println(severity.InfoLog, globalLogger, logging.filter, args...) } // InfolnDepth acts as Infoln but uses depth to determine which call frame to log. // InfolnDepth(0, "msg") is the same as Infoln("msg"). func InfolnDepth(depth int, args ...interface{}) { - logging.printlnDepth(severity.InfoLog, logging.logr, logging.filter, depth, args...) + logging.printlnDepth(severity.InfoLog, globalLogger, logging.filter, depth, args...) } // Infof logs to the INFO log. // Arguments are handled in the manner of fmt.Printf; a newline is appended if missing. func Infof(format string, args ...interface{}) { - logging.printf(severity.InfoLog, logging.logr, logging.filter, format, args...) + logging.printf(severity.InfoLog, globalLogger, logging.filter, format, args...) } // InfofDepth acts as Infof but uses depth to determine which call frame to log. // InfofDepth(0, "msg", args...) is the same as Infof("msg", args...). func InfofDepth(depth int, format string, args ...interface{}) { - logging.printfDepth(severity.InfoLog, logging.logr, logging.filter, depth, format, args...) + logging.printfDepth(severity.InfoLog, globalLogger, logging.filter, depth, format, args...) } // InfoS structured logs to the INFO log. @@ -1342,79 +1311,79 @@ func InfofDepth(depth int, format string, args ...interface{}) { // output: // >> I1025 00:15:15.525108 1 controller_utils.go:116] "Pod status updated" pod="kubedns" status="ready" func InfoS(msg string, keysAndValues ...interface{}) { - logging.infoS(logging.logr, logging.filter, 0, msg, keysAndValues...) + logging.infoS(globalLogger, logging.filter, 0, msg, keysAndValues...) } // Warning logs to the WARNING and INFO logs. // Arguments are handled in the manner of fmt.Print; a newline is appended if missing. func Warning(args ...interface{}) { - logging.print(severity.WarningLog, logging.logr, logging.filter, args...) + logging.print(severity.WarningLog, globalLogger, logging.filter, args...) } // WarningDepth acts as Warning but uses depth to determine which call frame to log. // WarningDepth(0, "msg") is the same as Warning("msg"). func WarningDepth(depth int, args ...interface{}) { - logging.printDepth(severity.WarningLog, logging.logr, logging.filter, depth, args...) + logging.printDepth(severity.WarningLog, globalLogger, logging.filter, depth, args...) } // Warningln logs to the WARNING and INFO logs. // Arguments are handled in the manner of fmt.Println; a newline is always appended. func Warningln(args ...interface{}) { - logging.println(severity.WarningLog, logging.logr, logging.filter, args...) + logging.println(severity.WarningLog, globalLogger, logging.filter, args...) } // WarninglnDepth acts as Warningln but uses depth to determine which call frame to log. // WarninglnDepth(0, "msg") is the same as Warningln("msg"). func WarninglnDepth(depth int, args ...interface{}) { - logging.printlnDepth(severity.WarningLog, logging.logr, logging.filter, depth, args...) + logging.printlnDepth(severity.WarningLog, globalLogger, logging.filter, depth, args...) } // Warningf logs to the WARNING and INFO logs. // Arguments are handled in the manner of fmt.Printf; a newline is appended if missing. func Warningf(format string, args ...interface{}) { - logging.printf(severity.WarningLog, logging.logr, logging.filter, format, args...) + logging.printf(severity.WarningLog, globalLogger, logging.filter, format, args...) } // WarningfDepth acts as Warningf but uses depth to determine which call frame to log. // WarningfDepth(0, "msg", args...) is the same as Warningf("msg", args...). func WarningfDepth(depth int, format string, args ...interface{}) { - logging.printfDepth(severity.WarningLog, logging.logr, logging.filter, depth, format, args...) + logging.printfDepth(severity.WarningLog, globalLogger, logging.filter, depth, format, args...) } // Error logs to the ERROR, WARNING, and INFO logs. // Arguments are handled in the manner of fmt.Print; a newline is appended if missing. func Error(args ...interface{}) { - logging.print(severity.ErrorLog, logging.logr, logging.filter, args...) + logging.print(severity.ErrorLog, globalLogger, logging.filter, args...) } // ErrorDepth acts as Error but uses depth to determine which call frame to log. // ErrorDepth(0, "msg") is the same as Error("msg"). func ErrorDepth(depth int, args ...interface{}) { - logging.printDepth(severity.ErrorLog, logging.logr, logging.filter, depth, args...) + logging.printDepth(severity.ErrorLog, globalLogger, logging.filter, depth, args...) } // Errorln logs to the ERROR, WARNING, and INFO logs. // Arguments are handled in the manner of fmt.Println; a newline is always appended. func Errorln(args ...interface{}) { - logging.println(severity.ErrorLog, logging.logr, logging.filter, args...) + logging.println(severity.ErrorLog, globalLogger, logging.filter, args...) } // ErrorlnDepth acts as Errorln but uses depth to determine which call frame to log. // ErrorlnDepth(0, "msg") is the same as Errorln("msg"). func ErrorlnDepth(depth int, args ...interface{}) { - logging.printlnDepth(severity.ErrorLog, logging.logr, logging.filter, depth, args...) + logging.printlnDepth(severity.ErrorLog, globalLogger, logging.filter, depth, args...) } // Errorf logs to the ERROR, WARNING, and INFO logs. // Arguments are handled in the manner of fmt.Printf; a newline is appended if missing. func Errorf(format string, args ...interface{}) { - logging.printf(severity.ErrorLog, logging.logr, logging.filter, format, args...) + logging.printf(severity.ErrorLog, globalLogger, logging.filter, format, args...) } // ErrorfDepth acts as Errorf but uses depth to determine which call frame to log. // ErrorfDepth(0, "msg", args...) is the same as Errorf("msg", args...). func ErrorfDepth(depth int, format string, args ...interface{}) { - logging.printfDepth(severity.ErrorLog, logging.logr, logging.filter, depth, format, args...) + logging.printfDepth(severity.ErrorLog, globalLogger, logging.filter, depth, format, args...) } // ErrorS structured logs to the ERROR, WARNING, and INFO logs. @@ -1427,52 +1396,52 @@ func ErrorfDepth(depth int, format string, args ...interface{}) { // output: // >> E1025 00:15:15.525108 1 controller_utils.go:114] "Failed to update pod status" err="timeout" func ErrorS(err error, msg string, keysAndValues ...interface{}) { - logging.errorS(err, logging.logr, logging.filter, 0, msg, keysAndValues...) + logging.errorS(err, globalLogger, logging.filter, 0, msg, keysAndValues...) } // ErrorSDepth acts as ErrorS but uses depth to determine which call frame to log. // ErrorSDepth(0, "msg") is the same as ErrorS("msg"). func ErrorSDepth(depth int, err error, msg string, keysAndValues ...interface{}) { - logging.errorS(err, logging.logr, logging.filter, depth, msg, keysAndValues...) + logging.errorS(err, globalLogger, logging.filter, depth, msg, keysAndValues...) } // Fatal logs to the FATAL, ERROR, WARNING, and INFO logs, // including a stack trace of all running goroutines, then calls os.Exit(255). // Arguments are handled in the manner of fmt.Print; a newline is appended if missing. func Fatal(args ...interface{}) { - logging.print(severity.FatalLog, logging.logr, logging.filter, args...) + logging.print(severity.FatalLog, globalLogger, logging.filter, args...) } // FatalDepth acts as Fatal but uses depth to determine which call frame to log. // FatalDepth(0, "msg") is the same as Fatal("msg"). func FatalDepth(depth int, args ...interface{}) { - logging.printDepth(severity.FatalLog, logging.logr, logging.filter, depth, args...) + logging.printDepth(severity.FatalLog, globalLogger, logging.filter, depth, args...) } // Fatalln logs to the FATAL, ERROR, WARNING, and INFO logs, // including a stack trace of all running goroutines, then calls os.Exit(255). // Arguments are handled in the manner of fmt.Println; a newline is always appended. func Fatalln(args ...interface{}) { - logging.println(severity.FatalLog, logging.logr, logging.filter, args...) + logging.println(severity.FatalLog, globalLogger, logging.filter, args...) } // FatallnDepth acts as Fatalln but uses depth to determine which call frame to log. // FatallnDepth(0, "msg") is the same as Fatalln("msg"). func FatallnDepth(depth int, args ...interface{}) { - logging.printlnDepth(severity.FatalLog, logging.logr, logging.filter, depth, args...) + logging.printlnDepth(severity.FatalLog, globalLogger, logging.filter, depth, args...) } // Fatalf logs to the FATAL, ERROR, WARNING, and INFO logs, // including a stack trace of all running goroutines, then calls os.Exit(255). // Arguments are handled in the manner of fmt.Printf; a newline is appended if missing. func Fatalf(format string, args ...interface{}) { - logging.printf(severity.FatalLog, logging.logr, logging.filter, format, args...) + logging.printf(severity.FatalLog, globalLogger, logging.filter, format, args...) } // FatalfDepth acts as Fatalf but uses depth to determine which call frame to log. // FatalfDepth(0, "msg", args...) is the same as Fatalf("msg", args...). func FatalfDepth(depth int, format string, args ...interface{}) { - logging.printfDepth(severity.FatalLog, logging.logr, logging.filter, depth, format, args...) + logging.printfDepth(severity.FatalLog, globalLogger, logging.filter, depth, format, args...) } // fatalNoStacks is non-zero if we are to exit without dumping goroutine stacks. @@ -1483,41 +1452,41 @@ var fatalNoStacks uint32 // Arguments are handled in the manner of fmt.Print; a newline is appended if missing. func Exit(args ...interface{}) { atomic.StoreUint32(&fatalNoStacks, 1) - logging.print(severity.FatalLog, logging.logr, logging.filter, args...) + logging.print(severity.FatalLog, globalLogger, logging.filter, args...) } // ExitDepth acts as Exit but uses depth to determine which call frame to log. // ExitDepth(0, "msg") is the same as Exit("msg"). func ExitDepth(depth int, args ...interface{}) { atomic.StoreUint32(&fatalNoStacks, 1) - logging.printDepth(severity.FatalLog, logging.logr, logging.filter, depth, args...) + logging.printDepth(severity.FatalLog, globalLogger, logging.filter, depth, args...) } // Exitln logs to the FATAL, ERROR, WARNING, and INFO logs, then calls os.Exit(1). func Exitln(args ...interface{}) { atomic.StoreUint32(&fatalNoStacks, 1) - logging.println(severity.FatalLog, logging.logr, logging.filter, args...) + logging.println(severity.FatalLog, globalLogger, logging.filter, args...) } // ExitlnDepth acts as Exitln but uses depth to determine which call frame to log. // ExitlnDepth(0, "msg") is the same as Exitln("msg"). func ExitlnDepth(depth int, args ...interface{}) { atomic.StoreUint32(&fatalNoStacks, 1) - logging.printlnDepth(severity.FatalLog, logging.logr, logging.filter, depth, args...) + logging.printlnDepth(severity.FatalLog, globalLogger, logging.filter, depth, args...) } // Exitf logs to the FATAL, ERROR, WARNING, and INFO logs, then calls os.Exit(1). // Arguments are handled in the manner of fmt.Printf; a newline is appended if missing. func Exitf(format string, args ...interface{}) { atomic.StoreUint32(&fatalNoStacks, 1) - logging.printf(severity.FatalLog, logging.logr, logging.filter, format, args...) + logging.printf(severity.FatalLog, globalLogger, logging.filter, format, args...) } // ExitfDepth acts as Exitf but uses depth to determine which call frame to log. // ExitfDepth(0, "msg", args...) is the same as Exitf("msg", args...). func ExitfDepth(depth int, format string, args ...interface{}) { atomic.StoreUint32(&fatalNoStacks, 1) - logging.printfDepth(severity.FatalLog, logging.logr, logging.filter, depth, format, args...) + logging.printfDepth(severity.FatalLog, globalLogger, logging.filter, depth, format, args...) } // LogFilter is a collection of functions that can filter all logging calls, diff --git a/klogr.go b/klogr.go new file mode 100644 index 00000000..cdb3834f --- /dev/null +++ b/klogr.go @@ -0,0 +1,92 @@ +/* +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 klog + +import ( + "github.com/go-logr/logr" + + "k8s.io/klog/v2/internal/serialize" +) + +// NewKlogr returns a logger that is functionally identical to +// klogr.NewWithOptions(klogr.FormatKlog), i.e. it passes through to klog. The +// difference is that it uses a simpler implementation. +// +// Experimental +// +// Notice: This function is EXPERIMENTAL and may be changed or removed in a +// later release. +func NewKlogr() Logger { + return New(&klogger{}) +} + +// klogger is a subset of klogr/klogr.go. It had to be copied to break an +// import cycle (klogr wants to use klog, and klog wants to use klogr). +type klogger struct { + level int + callDepth int + prefix string + values []interface{} +} + +func (l *klogger) Init(info logr.RuntimeInfo) { + l.callDepth += info.CallDepth +} + +func (l klogger) Info(level int, msg string, kvList ...interface{}) { + trimmed := serialize.TrimDuplicates(l.values, kvList) + if l.prefix != "" { + msg = l.prefix + ": " + msg + } + V(Level(level)).InfoSDepth(l.callDepth+1, msg, append(trimmed[0], trimmed[1]...)...) +} + +func (l klogger) Enabled(level int) bool { + return V(Level(level)).Enabled() +} + +func (l klogger) Error(err error, msg string, kvList ...interface{}) { + trimmed := serialize.TrimDuplicates(l.values, kvList) + if l.prefix != "" { + msg = l.prefix + ": " + msg + } + ErrorSDepth(l.callDepth+1, err, msg, append(trimmed[0], trimmed[1]...)...) +} + +// WithName returns a new logr.Logger with the specified name appended. klogr +// uses '/' characters to separate name elements. Callers should not pass '/' +// in the provided name string, but this library does not actually enforce that. +func (l klogger) WithName(name string) logr.LogSink { + if len(l.prefix) > 0 { + l.prefix = l.prefix + "/" + } + l.prefix += name + return &l +} + +func (l klogger) WithValues(kvList ...interface{}) logr.LogSink { + l.values = serialize.WithValues(l.values, kvList) + return &l +} + +func (l klogger) WithCallDepth(depth int) logr.LogSink { + l.callDepth += depth + return &l +} + +var _ logr.LogSink = &klogger{} +var _ logr.CallDepthLogSink = &klogger{}