From 8b4cfd2c73a1eb6dcd9c36b199f9f1db026f078a Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 1 Feb 2023 17:59:21 +0100 Subject: [PATCH] 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) }