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