Skip to content

Commit

Permalink
add slog support
Browse files Browse the repository at this point in the history
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.
  • Loading branch information
pohly committed Oct 30, 2023
1 parent cc856bb commit 44eadc3
Show file tree
Hide file tree
Showing 17 changed files with 915 additions and 79 deletions.
43 changes: 43 additions & 0 deletions contextual_test.go
Expand Up @@ -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"
Expand Down Expand Up @@ -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 }
9 changes: 9 additions & 0 deletions internal/buffer/buffer.go
Expand Up @@ -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
Expand Down Expand Up @@ -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]
Expand Down Expand Up @@ -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]
Expand Down
71 changes: 4 additions & 67 deletions internal/serialize/keyvalues.go
Expand Up @@ -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)
}
Expand All @@ -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 {
Expand Down
97 changes: 97 additions & 0 deletions 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)
}
}

0 comments on commit 44eadc3

Please sign in to comment.