From 8b4cfd2c73a1eb6dcd9c36b199f9f1db026f078a Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 1 Feb 2023 17:59:21 +0100 Subject: [PATCH 1/3] ktesting: use klog-like header In practice, replacing normal klog text output with ktesting lost the time stamps. This is perhaps not important for unit tests, but for benchmarking those can be crucial. Now ktesting uses a stripped down klog header: - The source code location comes first, because that is printed by the testing package. - Instead if INFO and ERROR, the short I and E are used. - The useless tid/pid part isn't present. Example: $ go test -v ./ktesting/example/ === RUN TestKlogr example_test.go:45: I0201 17:58:36.235936] hello world example_test.go:46: E0201 17:58:36.236052] failed err="failed: some error" example_test.go:47: I0201 17:58:36.236086] verbosity 1 example_test.go:48: I0201 17:58:36.236110] main/helper: with prefix example_test.go:50: I0201 17:58:36.236154] key/value pairs int=1 float=2 pair="(1, 2)" raw={Name:joe NS:kube-system} kobj="kube-system/joe" example_test.go:57: I0201 17:58:36.236187] info message level 4 example_test.go:58: I0201 17:58:36.236209] info message level 5 --- PASS: TestKlogr (0.00s) PASS --- internal/buffer/buffer.go | 30 ++++++++++++++++++++++++++- ktesting/testinglogger.go | 37 +++++++++++++++++++--------------- ktesting/testinglogger_test.go | 25 ++++++++++++----------- 3 files changed, 63 insertions(+), 29 deletions(-) diff --git a/internal/buffer/buffer.go b/internal/buffer/buffer.go index d53b49da3..121cbf70b 100644 --- a/internal/buffer/buffer.go +++ b/internal/buffer/buffer.go @@ -99,7 +99,8 @@ func (buf *Buffer) someDigits(i, d int) int { return copy(buf.Tmp[i:], buf.Tmp[j:]) } -// FormatHeader formats a log header using the provided file name and line number. +// FormatHeader formats a log header using the provided file name and line number +// and writes it into the buffer. func (buf *Buffer) FormatHeader(s severity.Severity, file string, line int, now time.Time) { if line < 0 { line = 0 // not a real line number, but acceptable to someDigits @@ -135,3 +136,30 @@ func (buf *Buffer) FormatHeader(s severity.Severity, file string, line int, now buf.Tmp[n+2] = ' ' buf.Write(buf.Tmp[:n+3]) } + +// SprintHeader formats a log header and returns a string. This is a simpler +// version of FormatHeader for use in ktesting. +func (buf *Buffer) SprintHeader(s severity.Severity, now time.Time) string { + if s > severity.FatalLog { + s = severity.InfoLog // for safety. + } + + // 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. + _, month, day := now.Date() + hour, minute, second := now.Clock() + // Lmmdd hh:mm:ss.uuuuuu threadid file:line] + buf.Tmp[0] = severity.Char[s] + buf.twoDigits(1, int(month)) + buf.twoDigits(3, day) + buf.Tmp[5] = ' ' + buf.twoDigits(6, hour) + buf.Tmp[8] = ':' + buf.twoDigits(9, minute) + buf.Tmp[11] = ':' + buf.twoDigits(12, second) + buf.Tmp[14] = '.' + buf.nDigits(6, 15, now.Nanosecond()/1000, '0') + buf.Tmp[21] = ']' + return string(buf.Tmp[:22]) +} diff --git a/ktesting/testinglogger.go b/ktesting/testinglogger.go index 0c87a953b..cbdd0f647 100644 --- a/ktesting/testinglogger.go +++ b/ktesting/testinglogger.go @@ -42,7 +42,6 @@ limitations under the License. package ktesting import ( - "bytes" "strings" "sync" "time" @@ -50,8 +49,10 @@ import ( "github.com/go-logr/logr" "k8s.io/klog/v2" + "k8s.io/klog/v2/internal/buffer" "k8s.io/klog/v2/internal/dbg" "k8s.io/klog/v2/internal/serialize" + "k8s.io/klog/v2/internal/severity" "k8s.io/klog/v2/internal/verbosity" ) @@ -230,19 +231,19 @@ type Underlier interface { GetBuffer() Buffer } -type buffer struct { +type logBuffer struct { mutex sync.Mutex text strings.Builder log Log } -func (b *buffer) String() string { +func (b *logBuffer) String() string { b.mutex.Lock() defer b.mutex.Unlock() return b.text.String() } -func (b *buffer) Data() Log { +func (b *logBuffer) Data() Log { b.mutex.Lock() defer b.mutex.Unlock() return b.log.DeepCopy() @@ -263,7 +264,7 @@ type tloggerShared struct { testName string config *Config - buffer buffer + buffer logBuffer callDepth int } @@ -318,9 +319,9 @@ func (l tlogger) Info(level int, msg string, kvList ...interface{}) { } l.shared.t.Helper() - buffer := &bytes.Buffer{} - serialize.MergeAndFormatKVs(buffer, l.values, kvList) - l.log(LogInfo, msg, level, buffer, nil, kvList) + buf := buffer.GetBuffer() + serialize.MergeAndFormatKVs(&buf.Buffer, l.values, kvList) + l.log(LogInfo, msg, level, buf, nil, kvList) } func (l tlogger) Enabled(level int) bool { @@ -336,24 +337,28 @@ func (l tlogger) Error(err error, msg string, kvList ...interface{}) { } l.shared.t.Helper() - buffer := &bytes.Buffer{} + buf := buffer.GetBuffer() if err != nil { - serialize.KVFormat(buffer, "err", err) + serialize.KVFormat(&buf.Buffer, "err", err) } - serialize.MergeAndFormatKVs(buffer, l.values, kvList) - l.log(LogError, msg, 0, buffer, err, kvList) + serialize.MergeAndFormatKVs(&buf.Buffer, l.values, kvList) + l.log(LogError, msg, 0, buf, err, kvList) } -func (l tlogger) log(what LogType, msg string, level int, buffer *bytes.Buffer, err error, kvList []interface{}) { +func (l tlogger) log(what LogType, msg string, level int, buf *buffer.Buffer, err error, kvList []interface{}) { l.shared.t.Helper() - args := []interface{}{what} + s := severity.InfoLog + if what == LogError { + s = severity.ErrorLog + } + args := []interface{}{buf.SprintHeader(s, time.Now())} if l.prefix != "" { args = append(args, l.prefix+":") } args = append(args, msg) - if buffer.Len() > 0 { + if buf.Len() > 0 { // Skip leading space inserted by serialize.KVListFormat. - args = append(args, string(buffer.Bytes()[1:])) + args = append(args, string(buf.Bytes()[1:])) } l.shared.t.Log(args...) diff --git a/ktesting/testinglogger_test.go b/ktesting/testinglogger_test.go index bb1efe6a1..2609bce12 100644 --- a/ktesting/testinglogger_test.go +++ b/ktesting/testinglogger_test.go @@ -33,78 +33,78 @@ func TestInfo(t *testing.T) { "should log with values passed to keysAndValues": { text: "test", keysAndValues: []interface{}{"akey", "avalue"}, - expectedOutput: `INFO test akey="avalue" + expectedOutput: `Ixxx test akey="avalue" `, }, "should support single name": { names: []string{"hello"}, text: "test", keysAndValues: []interface{}{"akey", "avalue"}, - expectedOutput: `INFO hello: test akey="avalue" + expectedOutput: `Ixxx hello: test akey="avalue" `, }, "should support multiple names": { names: []string{"hello", "world"}, text: "test", keysAndValues: []interface{}{"akey", "avalue"}, - expectedOutput: `INFO hello/world: test akey="avalue" + expectedOutput: `Ixxx hello/world: test akey="avalue" `, }, "should not print duplicate keys with the same value": { text: "test", keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue"}, - expectedOutput: `INFO test akey="avalue" akey="avalue" + expectedOutput: `Ixxx test akey="avalue" akey="avalue" `, }, "should only print the last duplicate key when the values are passed to Info": { text: "test", keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue2"}, - expectedOutput: `INFO test akey="avalue" akey="avalue2" + expectedOutput: `Ixxx test akey="avalue" akey="avalue2" `, }, "should only print the duplicate key that is passed to Info if one was passed to the logger": { withValues: []interface{}{"akey", "avalue"}, text: "test", keysAndValues: []interface{}{"akey", "avalue"}, - expectedOutput: `INFO test akey="avalue" + expectedOutput: `Ixxx test akey="avalue" `, }, "should only print the key passed to Info when one is already set on the logger": { withValues: []interface{}{"akey", "avalue"}, text: "test", keysAndValues: []interface{}{"akey", "avalue2"}, - expectedOutput: `INFO test akey="avalue2" + expectedOutput: `Ixxx test akey="avalue2" `, }, "should correctly handle odd-numbers of KVs": { text: "test", keysAndValues: []interface{}{"akey", "avalue", "akey2"}, - expectedOutput: `INFO test akey="avalue" akey2="(MISSING)" + expectedOutput: `Ixxx test akey="avalue" akey2="(MISSING)" `, }, "should correctly html characters": { text: "test", keysAndValues: []interface{}{"akey", "<&>"}, - expectedOutput: `INFO test akey="<&>" + expectedOutput: `Ixxx test akey="<&>" `, }, "should correctly handle odd-numbers of KVs in both log values and Info args": { withValues: []interface{}{"basekey1", "basevar1", "basekey2"}, text: "test", keysAndValues: []interface{}{"akey", "avalue", "akey2"}, - expectedOutput: `INFO test basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)" + expectedOutput: `Ixxx test basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)" `, }, "should correctly print regular error types": { text: "test", keysAndValues: []interface{}{"err", errors.New("whoops")}, - expectedOutput: `INFO test err="whoops" + expectedOutput: `Ixxx test err="whoops" `, }, "should correctly print regular error types when using logr.Error": { text: "test", err: errors.New("whoops"), - expectedOutput: `ERROR test err="whoops" + expectedOutput: `Exxx test err="whoops" `, }, } @@ -124,6 +124,7 @@ func TestInfo(t *testing.T) { } actual := buffer.String() + actual = regexp.MustCompile(`([IE])[[:digit:]]{4} [[:digit:]]{2}:[[:digit:]]{2}:[[:digit:]]{2}\.[[:digit:]]{6}\] `).ReplaceAllString(actual, `${1}xxx `) if actual != test.expectedOutput { t.Errorf("Expected:\n%sActual:\n%s\n", test.expectedOutput, actual) } From d1139259a646881a7e20d0c2ffb3fe0a23170e89 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 1 Feb 2023 19:25:35 +0100 Subject: [PATCH 2/3] ktesting: capture log entries only if requested Most users won't need this feature. It was enabled by default to keep the API simple and because the primary goal was unit testing, but benchmarks also need this and there unnecessary overhead needs to be avoided. --- ktesting/contextual_test.go | 13 ++++++++++--- ktesting/example_test.go | 28 +++++++++++++++++++++++++++- ktesting/options.go | 16 ++++++++++++++++ ktesting/testinglogger.go | 22 ++++++++++++++++++++++ ktesting/testinglogger_test.go | 4 +++- 5 files changed, 78 insertions(+), 5 deletions(-) diff --git a/ktesting/contextual_test.go b/ktesting/contextual_test.go index f260fb0aa..1b927e8ef 100644 --- a/ktesting/contextual_test.go +++ b/ktesting/contextual_test.go @@ -16,7 +16,8 @@ import ( ) func TestContextual(t *testing.T) { - logger, ctx := ktesting.NewTestContext(t) + var buffer ktesting.BufferTL + logger, ctx := ktesting.NewTestContext(&buffer) doSomething(ctx) @@ -33,8 +34,14 @@ func TestContextual(t *testing.T) { } actual := testingLogger.GetBuffer().String() - expected := `INFO hello world -INFO foo: hello also from me + if actual != "" { + t.Errorf("testinglogger should not have buffered, got:\n%s", actual) + } + + actual = buffer.String() + actual = headerRe.ReplaceAllString(actual, "${1}xxx] ") + expected := `Ixxx] hello world +Ixxx] foo: hello also from me ` if actual != expected { t.Errorf("mismatch in captured output, expected:\n%s\ngot:\n%s\n", expected, actual) diff --git a/ktesting/example_test.go b/ktesting/example_test.go index c2fa390c5..81f0a46ed 100644 --- a/ktesting/example_test.go +++ b/ktesting/example_test.go @@ -25,7 +25,12 @@ import ( ) func ExampleUnderlier() { - logger := ktesting.NewLogger(ktesting.NopTL{}, ktesting.NewConfig(ktesting.Verbosity(4))) + logger := ktesting.NewLogger(ktesting.NopTL{}, + ktesting.NewConfig( + ktesting.Verbosity(4), + ktesting.BufferLogs(true), + ), + ) logger.Error(errors.New("failure"), "I failed", "what", "something") logger.WithValues("request", 42).WithValues("anotherValue", "fish").Info("hello world") @@ -69,3 +74,24 @@ func ExampleUnderlier() { // log entry #3: {Timestamp:0001-01-01 00:00:00 +0000 UTC Type:INFO Prefix:example Message:with name Verbosity:0 Err: WithKVList:[] ParameterKVList:[]} // log entry #4: {Timestamp:0001-01-01 00:00:00 +0000 UTC Type:INFO Prefix: Message:higher verbosity Verbosity:4 Err: WithKVList:[] ParameterKVList:[]} } + +func ExampleDefaults() { + var buffer ktesting.BufferTL + logger := ktesting.NewLogger(&buffer, ktesting.NewConfig()) + + logger.Error(errors.New("failure"), "I failed", "what", "something") + logger.V(5).Info("Logged at level 5.") + logger.V(6).Info("Not logged at level 6.") + + testingLogger, ok := logger.GetSink().(ktesting.Underlier) + if !ok { + panic("Should have had a ktesting LogSink!?") + } + fmt.Printf(">> %s <<\n", testingLogger.GetBuffer().String()) // Should be empty. + fmt.Print(headerRe.ReplaceAllString(buffer.String(), "${1}...] ")) // Should not be empty. + + // Output: + // >> << + // E...] I failed err="failure" what="something" + // I...] Logged at level 5. +} diff --git a/ktesting/options.go b/ktesting/options.go index 743b51eba..ab78fe690 100644 --- a/ktesting/options.go +++ b/ktesting/options.go @@ -50,6 +50,7 @@ type configOptions struct { verbosityFlagName string vmoduleFlagName string verbosityDefault int + bufferLogs bool } // VerbosityFlagName overrides the default -testing.v for the verbosity level. @@ -94,6 +95,21 @@ func Verbosity(level int) ConfigOption { } } +// BufferLogs controls whether log entries are captured in memory in addition +// to being printed. Off by default. Unit tests that want to verify that +// log entries are emitted as expected can turn this on and then retrieve +// the captured log through the Underlier LogSink interface. +// +// # Experimental +// +// Notice: This function is EXPERIMENTAL and may be changed or removed in a +// later release. +func BufferLogs(enabled bool) ConfigOption { + return func(co *configOptions) { + co.bufferLogs = enabled + } +} + // NewConfig returns a configuration with recommended defaults and optional // modifications. Command line flags are not bound to any FlagSet yet. // diff --git a/ktesting/testinglogger.go b/ktesting/testinglogger.go index cbdd0f647..506485e3a 100644 --- a/ktesting/testinglogger.go +++ b/ktesting/testinglogger.go @@ -42,6 +42,7 @@ limitations under the License. package ktesting import ( + "fmt" "strings" "sync" "time" @@ -81,6 +82,23 @@ func (n NopTL) Log(args ...interface{}) {} var _ TL = NopTL{} +// BufferTL implements TL with an in-memory buffer. +// +// # Experimental +// +// Notice: This type is EXPERIMENTAL and may be changed or removed in a +// later release. +type BufferTL struct { + strings.Builder +} + +func (n *BufferTL) Helper() {} +func (n *BufferTL) Log(args ...interface{}) { + n.Builder.WriteString(fmt.Sprintln(args...)) +} + +var _ TL = &BufferTL{} + // NewLogger constructs a new logger for the given test interface. // // Beware that testing.T does not support logging after the test that @@ -362,6 +380,10 @@ func (l tlogger) log(what LogType, msg string, level int, buf *buffer.Buffer, er } l.shared.t.Log(args...) + if !l.shared.config.co.bufferLogs { + return + } + l.shared.buffer.mutex.Lock() defer l.shared.buffer.mutex.Unlock() diff --git a/ktesting/testinglogger_test.go b/ktesting/testinglogger_test.go index 2609bce12..6de1834d4 100644 --- a/ktesting/testinglogger_test.go +++ b/ktesting/testinglogger_test.go @@ -21,6 +21,8 @@ import ( "k8s.io/klog/v2/ktesting" ) +var headerRe = regexp.MustCompile(`([IE])[[:digit:]]{4} [[:digit:]]{2}:[[:digit:]]{2}:[[:digit:]]{2}\.[[:digit:]]{6}\] `) + func TestInfo(t *testing.T) { tests := map[string]struct { text string @@ -124,7 +126,7 @@ func TestInfo(t *testing.T) { } actual := buffer.String() - actual = regexp.MustCompile(`([IE])[[:digit:]]{4} [[:digit:]]{2}:[[:digit:]]{2}:[[:digit:]]{2}\.[[:digit:]]{6}\] `).ReplaceAllString(actual, `${1}xxx `) + actual = headerRe.ReplaceAllString(actual, `${1}xxx `) if actual != test.expectedOutput { t.Errorf("Expected:\n%sActual:\n%s\n", test.expectedOutput, actual) } From 1b27ee81c79d836aa1aa5369f4f7a7bc832fd21b Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Thu, 2 Feb 2023 13:23:15 +0100 Subject: [PATCH 3/3] ktesting: allow overriding default formatter The intended usage is to replace fmt.Sprintf("%+v") with gomega.format.Object + YAML support, therefore the only public API change is in the (still experimental) ktesting. Internally the additional function pointer gets passed through via a new Formatter struct. To minimize the impact on klog and textlogger, the package-level functions still exist and use an empty Formatter. --- internal/serialize/keyvalues.go | 46 ++++++++++++++++++++++++++------- ktesting/example_test.go | 19 ++++++++------ ktesting/options.go | 16 ++++++++++++ ktesting/testinglogger.go | 10 ++++--- 4 files changed, 70 insertions(+), 21 deletions(-) diff --git a/internal/serialize/keyvalues.go b/internal/serialize/keyvalues.go index f9558c3d2..1dc81a15f 100644 --- a/internal/serialize/keyvalues.go +++ b/internal/serialize/keyvalues.go @@ -95,9 +95,15 @@ func MergeKVs(first, second []interface{}) []interface{} { return merged } +type Formatter struct { + AnyToStringHook AnyToStringFunc +} + +type AnyToStringFunc func(v interface{}) string + // MergeKVsInto is a variant of MergeKVs which directly formats the key/value // pairs into a buffer. -func MergeAndFormatKVs(b *bytes.Buffer, first, second []interface{}) { +func (f Formatter) MergeAndFormatKVs(b *bytes.Buffer, first, second []interface{}) { if len(first) == 0 && len(second) == 0 { // Nothing to do at all. return @@ -107,7 +113,7 @@ func MergeAndFormatKVs(b *bytes.Buffer, first, second []interface{}) { // Nothing to be overridden, second slice is well-formed // and can be used directly. for i := 0; i < len(second); i += 2 { - KVFormat(b, second[i], second[i+1]) + f.KVFormat(b, second[i], second[i+1]) } return } @@ -127,24 +133,28 @@ func MergeAndFormatKVs(b *bytes.Buffer, first, second []interface{}) { if overrides[key] { continue } - KVFormat(b, key, first[i+1]) + f.KVFormat(b, key, first[i+1]) } // Round down. l := len(second) l = l / 2 * 2 for i := 1; i < l; i += 2 { - KVFormat(b, second[i-1], second[i]) + f.KVFormat(b, second[i-1], second[i]) } if len(second)%2 == 1 { - KVFormat(b, second[len(second)-1], missingValue) + f.KVFormat(b, second[len(second)-1], missingValue) } } +func MergeAndFormatKVs(b *bytes.Buffer, first, second []interface{}) { + Formatter{}.MergeAndFormatKVs(b, first, second) +} + const missingValue = "(MISSING)" // KVListFormat serializes all key/value pairs into the provided buffer. // A space gets inserted before the first pair and between each pair. -func KVListFormat(b *bytes.Buffer, keysAndValues ...interface{}) { +func (f Formatter) KVListFormat(b *bytes.Buffer, keysAndValues ...interface{}) { for i := 0; i < len(keysAndValues); i += 2 { var v interface{} k := keysAndValues[i] @@ -153,13 +163,17 @@ func KVListFormat(b *bytes.Buffer, keysAndValues ...interface{}) { } else { v = missingValue } - KVFormat(b, k, v) + f.KVFormat(b, k, v) } } +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 KVFormat(b *bytes.Buffer, k, v interface{}) { +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 @@ -203,7 +217,7 @@ func KVFormat(b *bytes.Buffer, k, v interface{}) { case string: writeStringValue(b, true, value) default: - writeStringValue(b, false, fmt.Sprintf("%+v", value)) + writeStringValue(b, false, f.AnyToString(value)) } case []byte: // In https://github.com/kubernetes/klog/pull/237 it was decided @@ -220,8 +234,20 @@ func KVFormat(b *bytes.Buffer, k, v interface{}) { b.WriteByte('=') b.WriteString(fmt.Sprintf("%+q", v)) default: - writeStringValue(b, false, fmt.Sprintf("%+v", v)) + writeStringValue(b, false, f.AnyToString(v)) + } +} + +func KVFormat(b *bytes.Buffer, k, v interface{}) { + Formatter{}.KVFormat(b, k, v) +} + +// AnyToString is the historic fallback formatter. +func (f Formatter) AnyToString(v interface{}) string { + if f.AnyToStringHook != nil { + return f.AnyToStringHook(v) } + return fmt.Sprintf("%+v", v) } // StringerToString converts a Stringer to a string, diff --git a/ktesting/example_test.go b/ktesting/example_test.go index 81f0a46ed..3fc688bf1 100644 --- a/ktesting/example_test.go +++ b/ktesting/example_test.go @@ -29,10 +29,13 @@ func ExampleUnderlier() { ktesting.NewConfig( ktesting.Verbosity(4), ktesting.BufferLogs(true), + ktesting.AnyToString(func(value interface{}) string { + return fmt.Sprintf("### %+v ###", value) + }), ), ) - logger.Error(errors.New("failure"), "I failed", "what", "something") + logger.Error(errors.New("failure"), "I failed", "what", "something", "data", struct{ field int }{field: 1}) logger.WithValues("request", 42).WithValues("anotherValue", "fish").Info("hello world") logger.WithValues("request", 42, "anotherValue", "fish").Info("hello world 2", "yetAnotherValue", "thanks") logger.WithName("example").Info("with name") @@ -62,24 +65,24 @@ func ExampleUnderlier() { } // Output: - // ERROR I failed err="failure" what="something" - // INFO hello world request=42 anotherValue="fish" - // INFO hello world 2 request=42 anotherValue="fish" yetAnotherValue="thanks" + // ERROR I failed err="failure" what="something" data=### {field:1} ### + // INFO hello world request=### 42 ### anotherValue="fish" + // INFO hello world 2 request=### 42 ### anotherValue="fish" yetAnotherValue="thanks" // INFO example: with name // INFO higher verbosity // - // log entry #0: {Timestamp:0001-01-01 00:00:00 +0000 UTC Type:ERROR Prefix: Message:I failed Verbosity:0 Err:failure WithKVList:[] ParameterKVList:[what something]} + // log entry #0: {Timestamp:0001-01-01 00:00:00 +0000 UTC Type:ERROR Prefix: Message:I failed Verbosity:0 Err:failure WithKVList:[] ParameterKVList:[what something data {field:1}]} // log entry #1: {Timestamp:0001-01-01 00:00:00 +0000 UTC Type:INFO Prefix: Message:hello world Verbosity:0 Err: WithKVList:[request 42 anotherValue fish] ParameterKVList:[]} // log entry #2: {Timestamp:0001-01-01 00:00:00 +0000 UTC Type:INFO Prefix: Message:hello world 2 Verbosity:0 Err: WithKVList:[request 42 anotherValue fish] ParameterKVList:[yetAnotherValue thanks]} // log entry #3: {Timestamp:0001-01-01 00:00:00 +0000 UTC Type:INFO Prefix:example Message:with name Verbosity:0 Err: WithKVList:[] ParameterKVList:[]} // log entry #4: {Timestamp:0001-01-01 00:00:00 +0000 UTC Type:INFO Prefix: Message:higher verbosity Verbosity:4 Err: WithKVList:[] ParameterKVList:[]} } -func ExampleDefaults() { +func ExampleNewLogger() { var buffer ktesting.BufferTL logger := ktesting.NewLogger(&buffer, ktesting.NewConfig()) - logger.Error(errors.New("failure"), "I failed", "what", "something") + logger.Error(errors.New("failure"), "I failed", "what", "something", "data", struct{ field int }{field: 1}) logger.V(5).Info("Logged at level 5.") logger.V(6).Info("Not logged at level 6.") @@ -92,6 +95,6 @@ func ExampleDefaults() { // Output: // >> << - // E...] I failed err="failure" what="something" + // E...] I failed err="failure" what="something" data={field:1} // I...] Logged at level 5. } diff --git a/ktesting/options.go b/ktesting/options.go index ab78fe690..c9bb3da80 100644 --- a/ktesting/options.go +++ b/ktesting/options.go @@ -20,6 +20,7 @@ import ( "flag" "strconv" + "k8s.io/klog/v2/internal/serialize" "k8s.io/klog/v2/internal/verbosity" ) @@ -47,12 +48,27 @@ type Config struct { type ConfigOption func(co *configOptions) type configOptions struct { + anyToString serialize.AnyToStringFunc verbosityFlagName string vmoduleFlagName string verbosityDefault int bufferLogs bool } +// AnyToString overrides the default formatter for values that are not +// supported directly by klog. The default is `fmt.Sprintf("%+v")`. +// The formatter must not panic. +// +// # Experimental +// +// Notice: This function is EXPERIMENTAL and may be changed or removed in a +// later release. +func AnyToString(anyToString func(value interface{}) string) ConfigOption { + return func(co *configOptions) { + co.anyToString = anyToString + } +} + // VerbosityFlagName overrides the default -testing.v for the verbosity level. // // # Experimental diff --git a/ktesting/testinglogger.go b/ktesting/testinglogger.go index 506485e3a..434b1533c 100644 --- a/ktesting/testinglogger.go +++ b/ktesting/testinglogger.go @@ -118,6 +118,9 @@ func NewLogger(t TL, c *Config) logr.Logger { config: c, }, } + if c.co.anyToString != nil { + l.shared.formatter.AnyToStringHook = c.co.anyToString + } type testCleanup interface { Cleanup(func()) @@ -280,6 +283,7 @@ type tloggerShared struct { // it logs after test completion. goroutineWarningDone bool + formatter serialize.Formatter testName string config *Config buffer logBuffer @@ -338,7 +342,7 @@ func (l tlogger) Info(level int, msg string, kvList ...interface{}) { l.shared.t.Helper() buf := buffer.GetBuffer() - serialize.MergeAndFormatKVs(&buf.Buffer, l.values, kvList) + l.shared.formatter.MergeAndFormatKVs(&buf.Buffer, l.values, kvList) l.log(LogInfo, msg, level, buf, nil, kvList) } @@ -357,9 +361,9 @@ func (l tlogger) Error(err error, msg string, kvList ...interface{}) { l.shared.t.Helper() buf := buffer.GetBuffer() if err != nil { - serialize.KVFormat(&buf.Buffer, "err", err) + l.shared.formatter.KVFormat(&buf.Buffer, "err", err) } - serialize.MergeAndFormatKVs(&buf.Buffer, l.values, kvList) + l.shared.formatter.MergeAndFormatKVs(&buf.Buffer, l.values, kvList) l.log(LogError, msg, 0, buf, err, kvList) }