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/ktesting/testinglogger.go b/ktesting/testinglogger.go index 0c87a953..cbdd0f64 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 bb1efe6a..2609bce1 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) }