From 44eadc3e71f44b0c1d05d418f56b9ad2a26dbb22 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Thu, 14 Sep 2023 11:43:00 +0200 Subject: [PATCH] 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 27aeb4e8..8d37d53c 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 475e1bf3..46de00fb 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 bcdf5f8e..d1a4751c 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 00000000..d9c7d154 --- /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 00000000..89acf977 --- /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 00000000..21f1697d --- /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 00000000..5522c84c --- /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 dc270cc8..72502db3 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 9c148dd7..efec96fd 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 fe215dee..a154960c 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 00000000..f7bf7403 --- /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 00000000..b6431a71 --- /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 7ae8d937..a5c25300 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 1299539d..235ecff5 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 00000000..af0fab00 --- /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 00000000..f92c8a77 --- /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 00000000..43828945 --- /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) +}