From cc856bbc4c50f2f46025ce2eb9aafaca1348be92 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Sun, 3 Sep 2023 20:44:32 +0200 Subject: [PATCH 1/2] update to logr 1.3.0 LogSink.Enabled is sensitive to stack unwinding. logr v1.2.0 got this wrong by calling LogSink.Enabled at different depths for Logger.Info and Logger.Enabled, therefore this test fails with that version. logr v1.3.0 changes the behavior to the more sane "LogSink.Enabled needs to skip one level, regardless where it is called". The Discard log sink implementation changed such that a discard logger doesn't have a sink at all anymore. Go < 1.18 is no longer supported by logr. --- contextual_test.go | 2 +- examples/go.mod | 2 +- examples/go.sum | 4 +-- go.mod | 2 +- go.sum | 4 +-- klogr.go | 3 +- klogr/klogr.go | 3 +- klogr_helper_test.go | 35 +++++++++++++++++++++ klogr_test.go | 67 ++++++++++++++++++++++++++++++++++++++++ textlogger/textlogger.go | 4 +-- 10 files changed, 112 insertions(+), 14 deletions(-) create mode 100644 klogr_helper_test.go create mode 100644 klogr_test.go diff --git a/contextual_test.go b/contextual_test.go index 80e14fa30..27aeb4e89 100644 --- a/contextual_test.go +++ b/contextual_test.go @@ -41,7 +41,7 @@ func ExampleSetLogger() { // Output: // logger after SetLogger: *klog.klogger // logger after SetLoggerWithOptions with ContextualLogger(false): *klog.klogger - // logger after SetLoggerWithOptions with ContextualLogger(true): logr.discardLogSink + // logger after SetLoggerWithOptions with ContextualLogger(true): } func ExampleFlushLogger() { diff --git a/examples/go.mod b/examples/go.mod index 7aff88925..b4ef2a622 100644 --- a/examples/go.mod +++ b/examples/go.mod @@ -3,7 +3,7 @@ module k8s.io/klog/examples go 1.13 require ( - github.com/go-logr/logr v1.2.2 + github.com/go-logr/logr v1.3.0 github.com/go-logr/zapr v1.2.3 github.com/golang/glog v0.0.0-20160126235308-23def4e6c14b go.uber.org/goleak v1.1.12 diff --git a/examples/go.sum b/examples/go.sum index bd1b6f63a..96988bafa 100644 --- a/examples/go.sum +++ b/examples/go.sum @@ -3,9 +3,9 @@ github.com/benbjohnson/clock v1.1.0/go.mod h1:J11/hYXuz8f4ySSvYwY0FKfm+ezbsZBKZx github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= -github.com/go-logr/logr v1.2.0/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A= -github.com/go-logr/logr v1.2.2 h1:ahHml/yUpnlb96Rp8HCvtYVPY8ZYpxq3g7UYchIYwbs= github.com/go-logr/logr v1.2.2/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A= +github.com/go-logr/logr v1.3.0 h1:2y3SDp0ZXuc6/cjLSZ+Q3ir+QB9T/iG5yYRXqsagWSY= +github.com/go-logr/logr v1.3.0/go.mod h1:9T104GzyrTigFIr8wt5mBrctHMim0Nb2HLGrmQ40KvY= github.com/go-logr/zapr v1.2.3 h1:a9vnzlIBPQBBkeaR9IuMUfmVOrQlkoC4YfPoFkX3T7A= github.com/go-logr/zapr v1.2.3/go.mod h1:eIauM6P8qSvTw5o2ez6UEAfGjQKrxQTl5EoK+Qa2oG4= github.com/golang/glog v0.0.0-20160126235308-23def4e6c14b h1:VKtxabqXZkF25pY9ekfRL6a582T4P37/31XEstQ5p58= diff --git a/go.mod b/go.mod index 31aefba74..15f54c276 100644 --- a/go.mod +++ b/go.mod @@ -2,4 +2,4 @@ module k8s.io/klog/v2 go 1.13 -require github.com/go-logr/logr v1.2.0 +require github.com/go-logr/logr v1.3.0 diff --git a/go.sum b/go.sum index 919fbadbc..391a9f524 100644 --- a/go.sum +++ b/go.sum @@ -1,2 +1,2 @@ -github.com/go-logr/logr v1.2.0 h1:QK40JKJyMdUDz+h+xvCsru/bJhvG0UxvePV0ufL/AcE= -github.com/go-logr/logr v1.2.0/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A= +github.com/go-logr/logr v1.3.0 h1:2y3SDp0ZXuc6/cjLSZ+Q3ir+QB9T/iG5yYRXqsagWSY= +github.com/go-logr/logr v1.3.0/go.mod h1:9T104GzyrTigFIr8wt5mBrctHMim0Nb2HLGrmQ40KvY= diff --git a/klogr.go b/klogr.go index a3e5f9772..9c148dd7e 100644 --- a/klogr.go +++ b/klogr.go @@ -58,8 +58,7 @@ func (l *klogger) Info(level int, msg string, kvList ...interface{}) { } func (l *klogger) Enabled(level int) bool { - // Skip this function and logr.Logger.Info where Enabled is called. - return VDepth(l.callDepth+2, Level(level)).Enabled() + return VDepth(l.callDepth+1, Level(level)).Enabled() } func (l *klogger) Error(err error, msg string, kvList ...interface{}) { diff --git a/klogr/klogr.go b/klogr/klogr.go index 73b0de25f..fe215deea 100644 --- a/klogr/klogr.go +++ b/klogr/klogr.go @@ -144,8 +144,7 @@ func (l *klogger) Info(level int, msg string, kvList ...interface{}) { } func (l *klogger) Enabled(level int) bool { - // Skip this function and logr.Logger.Info where Enabled is called. - return klog.VDepth(l.callDepth+2, klog.Level(level)).Enabled() + return klog.VDepth(l.callDepth+1, klog.Level(level)).Enabled() } func (l *klogger) Error(err error, msg string, kvList ...interface{}) { diff --git a/klogr_helper_test.go b/klogr_helper_test.go new file mode 100644 index 000000000..8ae119f19 --- /dev/null +++ b/klogr_helper_test.go @@ -0,0 +1,35 @@ +/* +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 klog_test + +import ( + "testing" + + "k8s.io/klog/v2" +) + +func testVerbosity(t *testing.T, logger klog.Logger) { + // This runs with -v=5 -vmodule=klog_helper_test=10. + logger.V(11).Info("v11 not visible from klogr_helper_test.go") + if logger.V(11).Enabled() { + t.Error("V(11).Enabled() in klogr_helper_test.go should have returned false.") + } + logger.V(10).Info("v10 visible from klogr_helper_test.go") + if !logger.V(10).Enabled() { + t.Error("V(10).Enabled() in klogr_helper_test.go should have returned true.") + } +} diff --git a/klogr_test.go b/klogr_test.go new file mode 100644 index 000000000..199750318 --- /dev/null +++ b/klogr_test.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 klog_test + +import ( + "bytes" + "flag" + "regexp" + "testing" + + "k8s.io/klog/v2" +) + +func TestVerbosity(t *testing.T) { + state := klog.CaptureState() + defer state.Restore() + + var fs flag.FlagSet + klog.InitFlags(&fs) + if err := fs.Set("v", "5"); err != nil { + t.Fatalf("unexpected error: %v", err) + } + if err := fs.Set("vmodule", "klogr_helper_test=10"); err != nil { + t.Fatalf("unexpected error: %v", err) + } + if err := fs.Set("logtostderr", "false"); err != nil { + t.Fatalf("unexpected error: %v", err) + } + var buffer bytes.Buffer + klog.SetOutput(&buffer) + logger := klog.Background() + + // -v=5 is in effect here. + logger.V(6).Info("v6 not visible from klogr_test.go") + if logger.V(6).Enabled() { + t.Error("V(6).Enabled() in klogr_test.go should have returned false.") + } + logger.V(5).Info("v5 visible from klogr_test.go") + if !logger.V(5).Enabled() { + t.Error("V(5).Enabled() in klogr_test.go should have returned true.") + } + + // Now test with -v=5 -vmodule=klogr_helper_test=10. + testVerbosity(t, logger) + + klog.Flush() + expected := `^.*v5 visible from klogr_test.go.* +.*v10 visible from klogr_helper_test.go.* +` + if !regexp.MustCompile(expected).Match(buffer.Bytes()) { + t.Errorf("Output did not match regular expression.\nOutput:\n%s\n\nRegular expression:\n%s\n", buffer.String(), expected) + } +} diff --git a/textlogger/textlogger.go b/textlogger/textlogger.go index 809b4553f..1299539d2 100644 --- a/textlogger/textlogger.go +++ b/textlogger/textlogger.go @@ -77,9 +77,7 @@ func (l *tlogger) WithCallDepth(depth int) logr.LogSink { } func (l *tlogger) Enabled(level int) bool { - // Skip this function and the Logger.Info call, then - // also any additional stack frames from WithCallDepth. - return l.config.vstate.Enabled(verbosity.Level(level), 2+l.callDepth) + return l.config.vstate.Enabled(verbosity.Level(level), 1+l.callDepth) } func (l *tlogger) Info(_ int, msg string, kvList ...interface{}) { From 44eadc3e71f44b0c1d05d418f56b9ad2a26dbb22 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Thu, 14 Sep 2023 11:43:00 +0200 Subject: [PATCH 2/2] add slog support When compiled with Go >= 1.21, special support for log/slog gets enabled automatically: - The formatting of key/value pairs supports slog.Value and slog.LogValuer, regardless of where those come from. - A slog.GroupValue is formatted as a JSON object. - The logger returned by klog.Background() and the textlogger support usage as a backend for the slog API, via slogr.NewSlogHandler, with builtin support for handling a slog.Record. However, -vmodule does not work when called like that because stack unwinding during the Enabled check finds the wrong source code. - KObj (= ObjectRef) and the type behind KObjSlice support the slog.LogValuer interface and thus get formatted properly by slog backends. The klogr package doesn't get updated. It shouldn't be used anymore. To make that clearer, it gets marked as "deprecated". Examples demonstrate the resulting output. That output has to be exactly the same when used as test, so pid and time get set to fixed values. --- contextual_test.go | 43 +++++++ internal/buffer/buffer.go | 9 ++ internal/serialize/keyvalues.go | 71 +---------- internal/serialize/keyvalues_no_slog.go | 97 ++++++++++++++ internal/serialize/keyvalues_slog.go | 155 +++++++++++++++++++++++ internal/sloghandler/sloghandler_slog.go | 96 ++++++++++++++ k8s_references_slog.go | 39 ++++++ klog.go | 13 +- klogr.go | 1 + klogr/klogr.go | 4 + klogr_slog.go | 96 ++++++++++++++ klogr_slog_test.go | 116 +++++++++++++++++ textlogger/options.go | 14 ++ textlogger/textlogger.go | 20 ++- textlogger/textlogger_slog.go | 52 ++++++++ textlogger/textlogger_slog_test.go | 91 +++++++++++++ textlogger/textlogger_test.go | 77 +++++++++++ 17 files changed, 915 insertions(+), 79 deletions(-) create mode 100644 internal/serialize/keyvalues_no_slog.go create mode 100644 internal/serialize/keyvalues_slog.go create mode 100644 internal/sloghandler/sloghandler_slog.go create mode 100644 k8s_references_slog.go create mode 100644 klogr_slog.go create mode 100644 klogr_slog_test.go create mode 100644 textlogger/textlogger_slog.go create mode 100644 textlogger/textlogger_slog_test.go create mode 100644 textlogger/textlogger_test.go diff --git a/contextual_test.go b/contextual_test.go index 27aeb4e89..8d37d53c7 100644 --- a/contextual_test.go +++ b/contextual_test.go @@ -17,7 +17,10 @@ limitations under the License. package klog_test import ( + "context" "fmt" + "runtime" + "testing" "github.com/go-logr/logr" "k8s.io/klog/v2" @@ -56,3 +59,43 @@ func ExampleFlushLogger() { // Output: // flushing... } + +func BenchmarkPassingLogger(b *testing.B) { + b.Run("with context", func(b *testing.B) { + ctx := klog.NewContext(context.Background(), klog.Background()) + var finalCtx context.Context + for n := b.N; n > 0; n-- { + finalCtx = passCtx(ctx) + } + runtime.KeepAlive(finalCtx) + }) + + b.Run("without context", func(b *testing.B) { + logger := klog.Background() + var finalLogger klog.Logger + for n := b.N; n > 0; n-- { + finalLogger = passLogger(logger) + } + runtime.KeepAlive(finalLogger) + }) +} + +func BenchmarkExtractLogger(b *testing.B) { + b.Run("from context", func(b *testing.B) { + ctx := klog.NewContext(context.Background(), klog.Background()) + var finalLogger klog.Logger + for n := b.N; n > 0; n-- { + finalLogger = extractCtx(ctx) + } + runtime.KeepAlive(finalLogger) + }) +} + +//go:noinline +func passCtx(ctx context.Context) context.Context { return ctx } + +//go:noinline +func extractCtx(ctx context.Context) klog.Logger { return klog.FromContext(ctx) } + +//go:noinline +func passLogger(logger klog.Logger) klog.Logger { return logger } diff --git a/internal/buffer/buffer.go b/internal/buffer/buffer.go index 475e1bf3d..46de00fb0 100644 --- a/internal/buffer/buffer.go +++ b/internal/buffer/buffer.go @@ -30,6 +30,9 @@ import ( var ( // Pid is inserted into log headers. Can be overridden for tests. Pid = os.Getpid() + + // Time, if set, will be used instead of the actual current time. + Time *time.Time ) // Buffer holds a single byte.Buffer for reuse. The zero value is ready for @@ -121,6 +124,9 @@ func (buf *Buffer) FormatHeader(s severity.Severity, file string, line int, now // Avoid Fprintf, for speed. The format is so simple that we can do it quickly by hand. // It's worth about 3X. Fprintf is hard. + if Time != nil { + now = *Time + } _, month, day := now.Date() hour, minute, second := now.Clock() // Lmmdd hh:mm:ss.uuuuuu threadid file:line] @@ -156,6 +162,9 @@ func (buf *Buffer) SprintHeader(s severity.Severity, now time.Time) string { // Avoid Fprintf, for speed. The format is so simple that we can do it quickly by hand. // It's worth about 3X. Fprintf is hard. + if Time != nil { + now = *Time + } _, month, day := now.Date() hour, minute, second := now.Clock() // Lmmdd hh:mm:ss.uuuuuu threadid file:line] diff --git a/internal/serialize/keyvalues.go b/internal/serialize/keyvalues.go index bcdf5f8ee..d1a4751c9 100644 --- a/internal/serialize/keyvalues.go +++ b/internal/serialize/keyvalues.go @@ -172,73 +172,6 @@ func KVListFormat(b *bytes.Buffer, keysAndValues ...interface{}) { Formatter{}.KVListFormat(b, keysAndValues...) } -// KVFormat serializes one key/value pair into the provided buffer. -// A space gets inserted before the pair. -func (f Formatter) KVFormat(b *bytes.Buffer, k, v interface{}) { - b.WriteByte(' ') - // Keys are assumed to be well-formed according to - // https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/migration-to-structured-logging.md#name-arguments - // for the sake of performance. Keys with spaces, - // special characters, etc. will break parsing. - if sK, ok := k.(string); ok { - // Avoid one allocation when the key is a string, which - // normally it should be. - b.WriteString(sK) - } else { - b.WriteString(fmt.Sprintf("%s", k)) - } - - // The type checks are sorted so that more frequently used ones - // come first because that is then faster in the common - // cases. In Kubernetes, ObjectRef (a Stringer) is more common - // than plain strings - // (https://github.com/kubernetes/kubernetes/pull/106594#issuecomment-975526235). - switch v := v.(type) { - case textWriter: - writeTextWriterValue(b, v) - case fmt.Stringer: - writeStringValue(b, StringerToString(v)) - case string: - writeStringValue(b, v) - case error: - writeStringValue(b, ErrorToString(v)) - case logr.Marshaler: - value := MarshalerToValue(v) - // A marshaler that returns a string is useful for - // delayed formatting of complex values. We treat this - // case like a normal string. This is useful for - // multi-line support. - // - // We could do this by recursively formatting a value, - // but that comes with the risk of infinite recursion - // if a marshaler returns itself. Instead we call it - // only once and rely on it returning the intended - // value directly. - switch value := value.(type) { - case string: - writeStringValue(b, value) - default: - f.formatAny(b, value) - } - case []byte: - // In https://github.com/kubernetes/klog/pull/237 it was decided - // to format byte slices with "%+q". The advantages of that are: - // - readable output if the bytes happen to be printable - // - non-printable bytes get represented as unicode escape - // sequences (\uxxxx) - // - // The downsides are that we cannot use the faster - // strconv.Quote here and that multi-line output is not - // supported. If developers know that a byte array is - // printable and they want multi-line output, they can - // convert the value to string before logging it. - b.WriteByte('=') - b.WriteString(fmt.Sprintf("%+q", v)) - default: - f.formatAny(b, v) - } -} - func KVFormat(b *bytes.Buffer, k, v interface{}) { Formatter{}.KVFormat(b, k, v) } @@ -251,6 +184,10 @@ func (f Formatter) formatAny(b *bytes.Buffer, v interface{}) { b.WriteString(f.AnyToStringHook(v)) return } + formatAsJSON(b, v) +} + +func formatAsJSON(b *bytes.Buffer, v interface{}) { encoder := json.NewEncoder(b) l := b.Len() if err := encoder.Encode(v); err != nil { diff --git a/internal/serialize/keyvalues_no_slog.go b/internal/serialize/keyvalues_no_slog.go new file mode 100644 index 000000000..d9c7d1546 --- /dev/null +++ b/internal/serialize/keyvalues_no_slog.go @@ -0,0 +1,97 @@ +//go:build !go1.21 +// +build !go1.21 + +/* +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 serialize + +import ( + "bytes" + "fmt" + + "github.com/go-logr/logr" +) + +// KVFormat serializes one key/value pair into the provided buffer. +// A space gets inserted before the pair. +func (f Formatter) KVFormat(b *bytes.Buffer, k, v interface{}) { + // This is the version without slog support. Must be kept in sync with + // the version in keyvalues_slog.go. + + b.WriteByte(' ') + // Keys are assumed to be well-formed according to + // https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/migration-to-structured-logging.md#name-arguments + // for the sake of performance. Keys with spaces, + // special characters, etc. will break parsing. + if sK, ok := k.(string); ok { + // Avoid one allocation when the key is a string, which + // normally it should be. + b.WriteString(sK) + } else { + b.WriteString(fmt.Sprintf("%s", k)) + } + + // The type checks are sorted so that more frequently used ones + // come first because that is then faster in the common + // cases. In Kubernetes, ObjectRef (a Stringer) is more common + // than plain strings + // (https://github.com/kubernetes/kubernetes/pull/106594#issuecomment-975526235). + switch v := v.(type) { + case textWriter: + writeTextWriterValue(b, v) + case fmt.Stringer: + writeStringValue(b, StringerToString(v)) + case string: + writeStringValue(b, v) + case error: + writeStringValue(b, ErrorToString(v)) + case logr.Marshaler: + value := MarshalerToValue(v) + // A marshaler that returns a string is useful for + // delayed formatting of complex values. We treat this + // case like a normal string. This is useful for + // multi-line support. + // + // We could do this by recursively formatting a value, + // but that comes with the risk of infinite recursion + // if a marshaler returns itself. Instead we call it + // only once and rely on it returning the intended + // value directly. + switch value := value.(type) { + case string: + writeStringValue(b, value) + default: + f.formatAny(b, value) + } + case []byte: + // In https://github.com/kubernetes/klog/pull/237 it was decided + // to format byte slices with "%+q". The advantages of that are: + // - readable output if the bytes happen to be printable + // - non-printable bytes get represented as unicode escape + // sequences (\uxxxx) + // + // The downsides are that we cannot use the faster + // strconv.Quote here and that multi-line output is not + // supported. If developers know that a byte array is + // printable and they want multi-line output, they can + // convert the value to string before logging it. + b.WriteByte('=') + b.WriteString(fmt.Sprintf("%+q", v)) + default: + f.formatAny(b, v) + } +} diff --git a/internal/serialize/keyvalues_slog.go b/internal/serialize/keyvalues_slog.go new file mode 100644 index 000000000..89acf9772 --- /dev/null +++ b/internal/serialize/keyvalues_slog.go @@ -0,0 +1,155 @@ +//go:build go1.21 +// +build go1.21 + +/* +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 serialize + +import ( + "bytes" + "fmt" + "log/slog" + "strconv" + + "github.com/go-logr/logr" +) + +// KVFormat serializes one key/value pair into the provided buffer. +// A space gets inserted before the pair. +func (f Formatter) KVFormat(b *bytes.Buffer, k, v interface{}) { + // This is the version without slog support. Must be kept in sync with + // the version in keyvalues_slog.go. + + b.WriteByte(' ') + // Keys are assumed to be well-formed according to + // https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/migration-to-structured-logging.md#name-arguments + // for the sake of performance. Keys with spaces, + // special characters, etc. will break parsing. + if sK, ok := k.(string); ok { + // Avoid one allocation when the key is a string, which + // normally it should be. + b.WriteString(sK) + } else { + b.WriteString(fmt.Sprintf("%s", k)) + } + + // The type checks are sorted so that more frequently used ones + // come first because that is then faster in the common + // cases. In Kubernetes, ObjectRef (a Stringer) is more common + // than plain strings + // (https://github.com/kubernetes/kubernetes/pull/106594#issuecomment-975526235). + // + // slog.LogValuer does not need to be handled here because the handler will + // already have resolved such special values to the final value for logging. + switch v := v.(type) { + case textWriter: + writeTextWriterValue(b, v) + case slog.Value: + // This must come before fmt.Stringer because slog.Value implements + // fmt.Stringer, but does not produce the output that we want. + b.WriteByte('=') + generateJSON(b, v) + case fmt.Stringer: + writeStringValue(b, StringerToString(v)) + case string: + writeStringValue(b, v) + case error: + writeStringValue(b, ErrorToString(v)) + case logr.Marshaler: + value := MarshalerToValue(v) + // A marshaler that returns a string is useful for + // delayed formatting of complex values. We treat this + // case like a normal string. This is useful for + // multi-line support. + // + // We could do this by recursively formatting a value, + // but that comes with the risk of infinite recursion + // if a marshaler returns itself. Instead we call it + // only once and rely on it returning the intended + // value directly. + switch value := value.(type) { + case string: + writeStringValue(b, value) + default: + f.formatAny(b, value) + } + case slog.LogValuer: + value := slog.AnyValue(v).Resolve() + if value.Kind() == slog.KindString { + writeStringValue(b, value.String()) + } else { + b.WriteByte('=') + generateJSON(b, value) + } + case []byte: + // In https://github.com/kubernetes/klog/pull/237 it was decided + // to format byte slices with "%+q". The advantages of that are: + // - readable output if the bytes happen to be printable + // - non-printable bytes get represented as unicode escape + // sequences (\uxxxx) + // + // The downsides are that we cannot use the faster + // strconv.Quote here and that multi-line output is not + // supported. If developers know that a byte array is + // printable and they want multi-line output, they can + // convert the value to string before logging it. + b.WriteByte('=') + b.WriteString(fmt.Sprintf("%+q", v)) + default: + f.formatAny(b, v) + } +} + +// generateJSON has the same preference for plain strings as KVFormat. +// In contrast to KVFormat it always produces valid JSON with no line breaks. +func generateJSON(b *bytes.Buffer, v interface{}) { + switch v := v.(type) { + case slog.Value: + switch v.Kind() { + case slog.KindGroup: + // Format as a JSON group. We must not involve f.AnyToStringHook (if there is any), + // because there is no guarantee that it produces valid JSON. + b.WriteByte('{') + for i, attr := range v.Group() { + if i > 0 { + b.WriteByte(',') + } + b.WriteString(strconv.Quote(attr.Key)) + b.WriteByte(':') + generateJSON(b, attr.Value) + } + b.WriteByte('}') + case slog.KindLogValuer: + generateJSON(b, v.Resolve()) + default: + // Peel off the slog.Value wrapper and format the actual value. + generateJSON(b, v.Any()) + } + case fmt.Stringer: + b.WriteString(strconv.Quote(StringerToString(v))) + case logr.Marshaler: + generateJSON(b, MarshalerToValue(v)) + case slog.LogValuer: + generateJSON(b, slog.AnyValue(v).Resolve().Any()) + case string: + b.WriteString(strconv.Quote(v)) + case error: + b.WriteString(strconv.Quote(v.Error())) + default: + formatAsJSON(b, v) + } +} diff --git a/internal/sloghandler/sloghandler_slog.go b/internal/sloghandler/sloghandler_slog.go new file mode 100644 index 000000000..21f1697d0 --- /dev/null +++ b/internal/sloghandler/sloghandler_slog.go @@ -0,0 +1,96 @@ +//go:build go1.21 +// +build go1.21 + +/* +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 sloghandler + +import ( + "context" + "log/slog" + "runtime" + "strings" + "time" + + "k8s.io/klog/v2/internal/severity" +) + +func Handle(_ context.Context, record slog.Record, groups string, printWithInfos func(file string, line int, now time.Time, err error, s severity.Severity, msg string, kvList []interface{})) error { + now := record.Time + if now.IsZero() { + // This format doesn't support printing entries without a time. + now = time.Now() + } + + // slog has numeric severity levels, with 0 as default "info", negative for debugging, and + // positive with some pre-defined levels for more important. Those ranges get mapped to + // the corresponding klog levels where possible, with "info" the default that is used + // also for negative debug levels. + level := record.Level + s := severity.InfoLog + switch { + case level >= slog.LevelError: + s = severity.ErrorLog + case level >= slog.LevelWarn: + s = severity.WarningLog + } + + var file string + var line int + if record.PC != 0 { + // Same as https://cs.opensource.google/go/x/exp/+/642cacee:slog/record.go;drc=642cacee5cc05231f45555a333d07f1005ffc287;l=70 + fs := runtime.CallersFrames([]uintptr{record.PC}) + f, _ := fs.Next() + if f.File != "" { + file = f.File + if slash := strings.LastIndex(file, "/"); slash >= 0 { + file = file[slash+1:] + } + line = f.Line + } + } else { + file = "???" + line = 1 + } + + kvList := make([]interface{}, 0, 2*record.NumAttrs()) + record.Attrs(func(attr slog.Attr) bool { + kvList = appendAttr(groups, kvList, attr) + return true + }) + + printWithInfos(file, line, now, nil, s, record.Message, kvList) + return nil +} + +func Attrs2KVList(groups string, attrs []slog.Attr) []interface{} { + kvList := make([]interface{}, 0, 2*len(attrs)) + for _, attr := range attrs { + kvList = appendAttr(groups, kvList, attr) + } + return kvList +} + +func appendAttr(groups string, kvList []interface{}, attr slog.Attr) []interface{} { + var key string + if groups != "" { + key = groups + "." + attr.Key + } else { + key = attr.Key + } + return append(kvList, key, attr.Value) +} diff --git a/k8s_references_slog.go b/k8s_references_slog.go new file mode 100644 index 000000000..5522c84c7 --- /dev/null +++ b/k8s_references_slog.go @@ -0,0 +1,39 @@ +//go:build go1.21 +// +build go1.21 + +/* +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 ( + "log/slog" +) + +func (ref ObjectRef) LogValue() slog.Value { + if ref.Namespace != "" { + return slog.GroupValue(slog.String("name", ref.Name), slog.String("namespace", ref.Namespace)) + } + return slog.GroupValue(slog.String("name", ref.Name)) +} + +var _ slog.LogValuer = ObjectRef{} + +func (ks kobjSlice) LogValue() slog.Value { + return slog.AnyValue(ks.MarshalLog()) +} + +var _ slog.LogValuer = kobjSlice{} diff --git a/klog.go b/klog.go index dc270cc84..72502db3a 100644 --- a/klog.go +++ b/klog.go @@ -655,16 +655,15 @@ func (l *loggingT) header(s severity.Severity, depth int) (*buffer.Buffer, strin } } } - return l.formatHeader(s, file, line), file, line + return l.formatHeader(s, file, line, timeNow()), file, line } // formatHeader formats a log header using the provided file name and line number. -func (l *loggingT) formatHeader(s severity.Severity, file string, line int) *buffer.Buffer { +func (l *loggingT) formatHeader(s severity.Severity, file string, line int, now time.Time) *buffer.Buffer { buf := buffer.GetBuffer() if l.skipHeaders { return buf } - now := timeNow() buf.FormatHeader(s, file, line, now) return buf } @@ -703,6 +702,10 @@ func (l *loggingT) printDepth(s severity.Severity, logger *logWriter, filter Log } buf, file, line := l.header(s, depth) + l.printWithInfos(buf, file, line, s, logger, filter, depth+1, args...) +} + +func (l *loggingT) printWithInfos(buf *buffer.Buffer, file string, line int, s severity.Severity, logger *logWriter, filter LogFilter, depth int, args ...interface{}) { // If a logger is set and doesn't support writing a formatted buffer, // we clear the generated header as we rely on the backing // logger implementation to print headers. @@ -751,7 +754,7 @@ func (l *loggingT) printfDepth(s severity.Severity, logger *logWriter, filter Lo // alsoLogToStderr is true, the log message always appears on standard error; it // will also appear in the log file unless --logtostderr is set. func (l *loggingT) printWithFileLine(s severity.Severity, logger *logWriter, filter LogFilter, file string, line int, alsoToStderr bool, args ...interface{}) { - buf := l.formatHeader(s, file, line) + buf := l.formatHeader(s, file, line, timeNow()) // If a logger is set and doesn't support writing a formatted buffer, // we clear the generated header as we rely on the backing // logger implementation to print headers. @@ -806,7 +809,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.logger, nil, depth+1, &b.Buffer) + l.printDepth(s, nil, nil, depth+1, &b.Buffer) // Make the buffer available for reuse. buffer.PutBuffer(b) } diff --git a/klogr.go b/klogr.go index 9c148dd7e..efec96fd4 100644 --- a/klogr.go +++ b/klogr.go @@ -45,6 +45,7 @@ type klogger struct { hasPrefix bool values []interface{} + groups string } func (l *klogger) Init(info logr.RuntimeInfo) { diff --git a/klogr/klogr.go b/klogr/klogr.go index fe215deea..a154960cd 100644 --- a/klogr/klogr.go +++ b/klogr/klogr.go @@ -46,6 +46,8 @@ func WithFormat(format Format) Option { // New returns a logr.Logger which serializes output itself // and writes it via klog. +// +// Deprecated: this uses a custom, out-dated output format. Use textlogger.NewLogger instead. func New() logr.Logger { return NewWithOptions(WithFormat(FormatSerialize)) } @@ -53,6 +55,8 @@ func New() logr.Logger { // NewWithOptions returns a logr.Logger which serializes as determined // by the WithFormat option and writes via klog. The default is // FormatKlog. +// +// Deprecated: FormatSerialize is out-dated. For FormatKlog, use textlogger.NewLogger instead. func NewWithOptions(options ...Option) logr.Logger { l := klogger{ level: 0, diff --git a/klogr_slog.go b/klogr_slog.go new file mode 100644 index 000000000..f7bf74030 --- /dev/null +++ b/klogr_slog.go @@ -0,0 +1,96 @@ +//go:build go1.21 +// +build go1.21 + +/* +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 klog + +import ( + "context" + "log/slog" + "strconv" + "time" + + "github.com/go-logr/logr/slogr" + + "k8s.io/klog/v2/internal/buffer" + "k8s.io/klog/v2/internal/serialize" + "k8s.io/klog/v2/internal/severity" + "k8s.io/klog/v2/internal/sloghandler" +) + +func (l *klogger) Handle(ctx context.Context, record slog.Record) error { + if logging.logger != nil { + if slogSink, ok := logging.logger.GetSink().(slogr.SlogSink); ok { + // Let that logger do the work. + return slogSink.Handle(ctx, record) + } + } + + return sloghandler.Handle(ctx, record, l.groups, slogOutput) +} + +// slogOutput corresponds to several different functions in klog.go. +// It goes through some of the same checks and formatting steps before +// it ultimately converges by calling logging.printWithInfos. +func slogOutput(file string, line int, now time.Time, err error, s severity.Severity, msg string, kvList []interface{}) { + // See infoS. + if logging.logger != nil { + // Taking this path happens when klog has a logger installed + // as backend which doesn't support slog. Not good, we have to + // guess about the call depth and drop the actual location. + logger := logging.logger.WithCallDepth(2) + if s > severity.ErrorLog { + logger.Error(err, msg, kvList...) + } else { + logger.Info(msg, kvList...) + } + return + } + + // See printS. + b := buffer.GetBuffer() + b.WriteString(strconv.Quote(msg)) + if err != nil { + serialize.KVListFormat(&b.Buffer, "err", err) + } + serialize.KVListFormat(&b.Buffer, kvList...) + + // See print + header. + buf := logging.formatHeader(s, file, line, now) + logging.printWithInfos(buf, file, line, s, nil, nil, 0, &b.Buffer) + + buffer.PutBuffer(b) +} + +func (l *klogger) WithAttrs(attrs []slog.Attr) slogr.SlogSink { + clone := *l + clone.values = serialize.WithValues(l.values, sloghandler.Attrs2KVList(l.groups, attrs)) + return &clone +} + +func (l *klogger) WithGroup(name string) slogr.SlogSink { + clone := *l + if clone.groups != "" { + clone.groups += "." + name + } else { + clone.groups = name + } + return &clone +} + +var _ slogr.SlogSink = &klogger{} diff --git a/klogr_slog_test.go b/klogr_slog_test.go new file mode 100644 index 000000000..b6431a716 --- /dev/null +++ b/klogr_slog_test.go @@ -0,0 +1,116 @@ +//go:build go1.21 +// +build go1.21 + +/* +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 klog_test + +import ( + "errors" + "flag" + "fmt" + "log/slog" + "os" + "time" + + "github.com/go-logr/logr/slogr" + "k8s.io/klog/v2" + internal "k8s.io/klog/v2/internal/buffer" +) + +var _ slog.LogValuer = coordinates{} + +type coordinates struct { + x, y int +} + +func (c coordinates) LogValue() slog.Value { + return slog.GroupValue(slog.Attr{Key: "X", Value: slog.IntValue(c.x)}, slog.Attr{Key: "Y", Value: slog.IntValue(c.y)}) +} + +func ExampleBackground_Slog() { + // Temporarily reconfigure for output to stdout, with -v=4. + state := klog.CaptureState() + defer state.Restore() + var fs flag.FlagSet + klog.InitFlags(&fs) + if err := fs.Set("logtostderr", "false"); err != nil { + fmt.Println(err) + } + if err := fs.Set("alsologtostderr", "false"); err != nil { + fmt.Println(err) + } + if err := fs.Set("v", "4"); err != nil { + fmt.Println(err) + } + if err := fs.Set("one_output", "true"); err != nil { + fmt.Println(err) + } + if err := fs.Set("skip_headers", "false"); err != nil { + fmt.Println(err) + } + klog.SetOutput(os.Stdout) + + // To get consistent output for each run. + ts, _ := time.Parse(time.RFC3339, "2000-12-24T12:30:40Z") + internal.Time = &ts + internal.Pid = 123 + + logrLogger := klog.Background() + slogHandler := slogr.NewSlogHandler(logrLogger) + slogLogger := slog.New(slogHandler) + + // Note that -vmodule does not work when using the slog API because + // stack unwinding during the Enabled check leads to the wrong source + // code. + slogLogger.Debug("A debug message") + slogLogger.Log(nil, slog.LevelDebug-1, "A debug message with even lower level, not printed.") + slogLogger.Info("An info message") + slogLogger.Warn("A warning") + slogLogger.Error("An error", "err", errors.New("fake error")) + + // The slog API supports grouping, in contrast to the logr API. + slogLogger.WithGroup("top").With("int", 42, slog.Group("variables", "a", 1, "b", 2)).Info("Grouping", + "sub", slog.GroupValue( + slog.Attr{Key: "str", Value: slog.StringValue("abc")}, + slog.Attr{Key: "bool", Value: slog.BoolValue(true)}, + slog.Attr{Key: "bottom", Value: slog.GroupValue(slog.Attr{Key: "coordinates", Value: slog.AnyValue(coordinates{x: -1, y: -2})})}, + ), + "duration", slog.DurationValue(time.Second), + slog.Float64("pi", 3.12), + "e", 2.71, + "moreCoordinates", coordinates{x: 100, y: 200}, + ) + + // slog special values are also supported when passed through the logr API. + // This works with the textlogger, but might not work with other implementations + // and thus isn't portable. Passing attributes (= key and value in a single + // parameter) is not supported. + logrLogger.Info("slog values", + "variables", slog.GroupValue(slog.Int("a", 1), slog.Int("b", 2)), + "duration", slog.DurationValue(time.Second), + "coordinates", coordinates{x: 100, y: 200}, + ) + + // Output: + // I1224 12:30:40.000000 123 klogr_slog_test.go:80] "A debug message" + // I1224 12:30:40.000000 123 klogr_slog_test.go:82] "An info message" + // W1224 12:30:40.000000 123 klogr_slog_test.go:83] "A warning" + // E1224 12:30:40.000000 123 klogr_slog_test.go:84] "An error" err="fake error" + // I1224 12:30:40.000000 123 klogr_slog_test.go:87] "Grouping" top.sub={"str":"abc","bool":true,"bottom":{"coordinates":{"X":-1,"Y":-2}}} top.duration="1s" top.pi=3.12 top.e=2.71 top.moreCoordinates={"X":100,"Y":200} + // I1224 12:30:40.000000 123 klogr_slog_test.go:103] "slog values" variables={"a":1,"b":2} duration="1s" coordinates={"X":100,"Y":200} +} diff --git a/textlogger/options.go b/textlogger/options.go index 7ae8d9378..a5c253003 100644 --- a/textlogger/options.go +++ b/textlogger/options.go @@ -21,6 +21,7 @@ import ( "io" "os" "strconv" + "time" "k8s.io/klog/v2/internal/verbosity" ) @@ -56,6 +57,7 @@ type configOptions struct { verbosityFlagName string vmoduleFlagName string verbosityDefault int + fixedTime *time.Time output io.Writer } @@ -91,6 +93,18 @@ func Output(output io.Writer) ConfigOption { } } +// FixedTime overrides the actual time with a fixed time. Useful only for testing. +// +// # Experimental +// +// Notice: This function is EXPERIMENTAL and may be changed or removed in a +// later release. +func FixedTime(ts time.Time) ConfigOption { + return func(co *configOptions) { + co.fixedTime = &ts + } +} + // NewConfig returns a configuration with recommended defaults and optional // modifications. Command line flags are not bound to any FlagSet yet. func NewConfig(opts ...ConfigOption) *Config { diff --git a/textlogger/textlogger.go b/textlogger/textlogger.go index 1299539d2..235ecff5c 100644 --- a/textlogger/textlogger.go +++ b/textlogger/textlogger.go @@ -63,6 +63,7 @@ type tlogger struct { hasPrefix bool values []interface{} + groups string config *Config } @@ -89,10 +90,6 @@ func (l *tlogger) Error(err error, msg string, kvList ...interface{}) { } func (l *tlogger) print(err error, s severity.Severity, msg string, kvList []interface{}) { - // Only create a new buffer if we don't have one cached. - b := buffer.GetBuffer() - defer buffer.PutBuffer(b) - // Determine caller. // +1 for this frame, +1 for Info/Error. _, file, line, ok := runtime.Caller(l.callDepth + 2) @@ -101,13 +98,22 @@ func (l *tlogger) print(err error, s severity.Severity, msg string, kvList []int line = 1 } else { if slash := strings.LastIndex(file, "/"); slash >= 0 { - path := file - file = path[slash+1:] + file = file[slash+1:] } } + l.printWithInfos(file, line, time.Now(), err, s, msg, kvList) +} + +func (l *tlogger) printWithInfos(file string, line int, now time.Time, err error, s severity.Severity, msg string, kvList []interface{}) { + // Only create a new buffer if we don't have one cached. + b := buffer.GetBuffer() + defer buffer.PutBuffer(b) + // Format header. - now := TimeNow() + if l.config.co.fixedTime != nil { + now = *l.config.co.fixedTime + } b.FormatHeader(s, file, line, now) // The message is always quoted, even if it contains line breaks. diff --git a/textlogger/textlogger_slog.go b/textlogger/textlogger_slog.go new file mode 100644 index 000000000..af0fab00e --- /dev/null +++ b/textlogger/textlogger_slog.go @@ -0,0 +1,52 @@ +//go:build go1.21 +// +build go1.21 + +/* +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 textlogger + +import ( + "context" + "log/slog" + + "github.com/go-logr/logr/slogr" + + "k8s.io/klog/v2/internal/serialize" + "k8s.io/klog/v2/internal/sloghandler" +) + +func (l *tlogger) Handle(ctx context.Context, record slog.Record) error { + return sloghandler.Handle(ctx, record, l.groups, l.printWithInfos) +} + +func (l *tlogger) WithAttrs(attrs []slog.Attr) slogr.SlogSink { + clone := *l + clone.values = serialize.WithValues(l.values, sloghandler.Attrs2KVList(l.groups, attrs)) + return &clone +} + +func (l *tlogger) WithGroup(name string) slogr.SlogSink { + clone := *l + if clone.groups != "" { + clone.groups += "." + name + } else { + clone.groups = name + } + return &clone +} + +var _ slogr.SlogSink = &tlogger{} diff --git a/textlogger/textlogger_slog_test.go b/textlogger/textlogger_slog_test.go new file mode 100644 index 000000000..f92c8a771 --- /dev/null +++ b/textlogger/textlogger_slog_test.go @@ -0,0 +1,91 @@ +//go:build go1.21 +// +build go1.21 + +/* +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 textlogger_test + +import ( + "errors" + "log/slog" + "os" + "time" + + "github.com/go-logr/logr/slogr" + internal "k8s.io/klog/v2/internal/buffer" + "k8s.io/klog/v2/textlogger" +) + +var _ slog.LogValuer = coordinates{} + +type coordinates struct { + x, y int +} + +func (c coordinates) LogValue() slog.Value { + return slog.GroupValue(slog.Attr{Key: "X", Value: slog.IntValue(c.x)}, slog.Attr{Key: "Y", Value: slog.IntValue(c.y)}) +} + +func ExampleNewLogger_Slog() { + ts, _ := time.Parse(time.RFC3339, "2000-12-24T12:30:40Z") + internal.Pid = 123 // To get consistent output for each run. + config := textlogger.NewConfig( + textlogger.FixedTime(ts), // To get consistent output for each run. + textlogger.Verbosity(4), // Matches slog.LevelDebug. + textlogger.Output(os.Stdout), + ) + logrLogger := textlogger.NewLogger(config) + slogHandler := slogr.NewSlogHandler(logrLogger) + slogLogger := slog.New(slogHandler) + + slogLogger.Debug("A debug message") + slogLogger.Log(nil, slog.LevelDebug-1, "A debug message with even lower level, not printed.") + slogLogger.Info("An info message") + slogLogger.Warn("A warning") + slogLogger.Error("An error", "err", errors.New("fake error")) + + // The slog API supports grouping, in contrast to the logr API. + slogLogger.WithGroup("top").With("int", 42, slog.Group("variables", "a", 1, "b", 2)).Info("Grouping", + "sub", slog.GroupValue( + slog.Attr{Key: "str", Value: slog.StringValue("abc")}, + slog.Attr{Key: "bool", Value: slog.BoolValue(true)}, + slog.Attr{Key: "bottom", Value: slog.GroupValue(slog.Attr{Key: "coordinates", Value: slog.AnyValue(coordinates{x: -1, y: -2})})}, + ), + "duration", slog.DurationValue(time.Second), + slog.Float64("pi", 3.12), + "e", 2.71, + "moreCoordinates", coordinates{x: 100, y: 200}, + ) + + // slog special values are also supported when passed through the logr API. + // This works with the textlogger, but might not work with other implementations + // and thus isn't portable. Passing attributes (= key and value in a single + // parameter) is not supported. + logrLogger.Info("slog values", + "variables", slog.GroupValue(slog.Int("a", 1), slog.Int("b", 2)), + "duration", slog.DurationValue(time.Second), + "coordinates", coordinates{x: 100, y: 200}, + ) + + // Output: + // I1224 12:30:40.000000 123 textlogger_slog_test.go:55] "A debug message" + // I1224 12:30:40.000000 123 textlogger_slog_test.go:57] "An info message" + // W1224 12:30:40.000000 123 textlogger_slog_test.go:58] "A warning" + // E1224 12:30:40.000000 123 textlogger_slog_test.go:59] "An error" err="fake error" + // I1224 12:30:40.000000 123 textlogger_slog_test.go:62] "Grouping" top.int=42 top.variables={"a":1,"b":2} top.sub={"str":"abc","bool":true,"bottom":{"coordinates":{"X":-1,"Y":-2}}} top.duration="1s" top.pi=3.12 top.e=2.71 top.moreCoordinates={"X":100,"Y":200} + // I1224 12:30:40.000000 123 textlogger_slog_test.go:78] "slog values" variables={"a":1,"b":2} duration="1s" coordinates={"X":100,"Y":200} +} diff --git a/textlogger/textlogger_test.go b/textlogger/textlogger_test.go new file mode 100644 index 000000000..438289457 --- /dev/null +++ b/textlogger/textlogger_test.go @@ -0,0 +1,77 @@ +/* +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 textlogger_test + +import ( + "errors" + "os" + "time" + + "github.com/go-logr/logr" + "k8s.io/klog/v2" + internal "k8s.io/klog/v2/internal/buffer" + "k8s.io/klog/v2/textlogger" +) + +var _ logr.Marshaler = coordinatesMarshaler{} + +type coordinatesMarshaler struct { + x, y int +} + +func (c coordinatesMarshaler) MarshalLog() interface{} { + return map[string]int{"X": c.x, "Y": c.y} +} + +type variables struct { + A, B int +} + +func ExampleNewLogger() { + ts, _ := time.Parse(time.RFC3339, "2000-12-24T12:30:40Z") + internal.Pid = 123 // To get consistent output for each run. + config := textlogger.NewConfig( + textlogger.FixedTime(ts), // To get consistent output for each run. + textlogger.Verbosity(4), // Matches Kubernetes "debug" level. + textlogger.Output(os.Stdout), + ) + logger := textlogger.NewLogger(config) + + logger.V(4).Info("A debug message") + logger.V(5).Info("A debug message with even lower level, not printed.") + logger.Info("An info message") + logger.Error(errors.New("fake error"), "An error") + logger.WithValues("int", 42).Info("With values", + "duration", time.Second, + "float", 3.12, + "coordinates", coordinatesMarshaler{x: 100, y: 200}, + "variables", variables{A: 1, B: 2}, + ) + // The logr API supports skipping functions during stack unwinding, in contrast to slog. + someHelper(logger, "hello world") + + // Output: + // I1224 12:30:40.000000 123 textlogger_test.go:54] "A debug message" + // I1224 12:30:40.000000 123 textlogger_test.go:56] "An info message" + // E1224 12:30:40.000000 123 textlogger_test.go:57] "An error" err="fake error" + // I1224 12:30:40.000000 123 textlogger_test.go:58] "With values" int=42 duration="1s" float=3.12 coordinates={"X":100,"Y":200} variables={"A":1,"B":2} + // I1224 12:30:40.000000 123 textlogger_test.go:65] "hello world" +} + +func someHelper(logger klog.Logger, msg string) { + logger.WithCallDepth(1).Info(msg) +}