diff --git a/internal/buffer/buffer.go b/internal/buffer/buffer.go index d53b49da..121cbf70 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/internal/serialize/keyvalues.go b/internal/serialize/keyvalues.go index f9558c3d..1dc81a15 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/contextual_test.go b/ktesting/contextual_test.go index f260fb0a..1b927e8e 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 c2fa390c..3fc688bf 100644 --- a/ktesting/example_test.go +++ b/ktesting/example_test.go @@ -25,9 +25,17 @@ 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), + 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") @@ -57,15 +65,36 @@ 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 ExampleNewLogger() { + var buffer ktesting.BufferTL + logger := ktesting.NewLogger(&buffer, ktesting.NewConfig()) + + 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.") + + 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" data={field:1} + // I...] Logged at level 5. +} diff --git a/ktesting/options.go b/ktesting/options.go index 743b51eb..c9bb3da8 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,9 +48,25 @@ 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. @@ -94,6 +111,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 0c87a953..434b1533 100644 --- a/ktesting/testinglogger.go +++ b/ktesting/testinglogger.go @@ -42,7 +42,7 @@ limitations under the License. package ktesting import ( - "bytes" + "fmt" "strings" "sync" "time" @@ -50,8 +50,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" ) @@ -80,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 @@ -99,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()) @@ -230,19 +252,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() @@ -261,9 +283,10 @@ type tloggerShared struct { // it logs after test completion. goroutineWarningDone bool + formatter serialize.Formatter testName string config *Config - buffer buffer + buffer logBuffer callDepth int } @@ -318,9 +341,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() + l.shared.formatter.MergeAndFormatKVs(&buf.Buffer, l.values, kvList) + l.log(LogInfo, msg, level, buf, nil, kvList) } func (l tlogger) Enabled(level int) bool { @@ -336,27 +359,35 @@ 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) + l.shared.formatter.KVFormat(&buf.Buffer, "err", err) } - serialize.MergeAndFormatKVs(buffer, l.values, kvList) - l.log(LogError, msg, 0, buffer, err, kvList) + l.shared.formatter.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...) + 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 bb1efe6a..6de1834d 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 @@ -33,78 +35,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 +126,7 @@ func TestInfo(t *testing.T) { } actual := buffer.String() + actual = headerRe.ReplaceAllString(actual, `${1}xxx `) if actual != test.expectedOutput { t.Errorf("Expected:\n%sActual:\n%s\n", test.expectedOutput, actual) }