Skip to content

Commit 8b4cfd2

Browse files
pohlypohly
committed
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
1 parent 1025055 commit 8b4cfd2

File tree

3 files changed

+63
-29
lines changed

3 files changed

+63
-29
lines changed

‎internal/buffer/buffer.go‎

Lines changed: 29 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -99,7 +99,8 @@ func (buf *Buffer) someDigits(i, d int) int {
9999
return copy(buf.Tmp[i:], buf.Tmp[j:])
100100
}
101101

102-
// FormatHeader formats a log header using the provided file name and line number.
102+
// FormatHeader formats a log header using the provided file name and line number
103+
// and writes it into the buffer.
103104
func (buf *Buffer) FormatHeader(s severity.Severity, file string, line int, now time.Time) {
104105
if line < 0 {
105106
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
135136
buf.Tmp[n+2] = ' '
136137
buf.Write(buf.Tmp[:n+3])
137138
}
139+
140+
// SprintHeader formats a log header and returns a string. This is a simpler
141+
// version of FormatHeader for use in ktesting.
142+
func (buf *Buffer) SprintHeader(s severity.Severity, now time.Time) string {
143+
if s > severity.FatalLog {
144+
s = severity.InfoLog // for safety.
145+
}
146+
147+
// Avoid Fprintf, for speed. The format is so simple that we can do it quickly by hand.
148+
// It's worth about 3X. Fprintf is hard.
149+
_, month, day := now.Date()
150+
hour, minute, second := now.Clock()
151+
// Lmmdd hh:mm:ss.uuuuuu threadid file:line]
152+
buf.Tmp[0] = severity.Char[s]
153+
buf.twoDigits(1, int(month))
154+
buf.twoDigits(3, day)
155+
buf.Tmp[5] = ' '
156+
buf.twoDigits(6, hour)
157+
buf.Tmp[8] = ':'
158+
buf.twoDigits(9, minute)
159+
buf.Tmp[11] = ':'
160+
buf.twoDigits(12, second)
161+
buf.Tmp[14] = '.'
162+
buf.nDigits(6, 15, now.Nanosecond()/1000, '0')
163+
buf.Tmp[21] = ']'
164+
return string(buf.Tmp[:22])
165+
}

‎ktesting/testinglogger.go‎

Lines changed: 21 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -42,16 +42,17 @@ limitations under the License.
4242
package ktesting
4343

4444
import (
45-
"bytes"
4645
"strings"
4746
"sync"
4847
"time"
4948

5049
"github.com/go-logr/logr"
5150

5251
"k8s.io/klog/v2"
52+
"k8s.io/klog/v2/internal/buffer"
5353
"k8s.io/klog/v2/internal/dbg"
5454
"k8s.io/klog/v2/internal/serialize"
55+
"k8s.io/klog/v2/internal/severity"
5556
"k8s.io/klog/v2/internal/verbosity"
5657
)
5758

@@ -230,19 +231,19 @@ type Underlier interface {
230231
GetBuffer() Buffer
231232
}
232233

233-
type buffer struct {
234+
type logBuffer struct {
234235
mutex sync.Mutex
235236
text strings.Builder
236237
log Log
237238
}
238239

239-
func (b *buffer) String() string {
240+
func (b *logBuffer) String() string {
240241
b.mutex.Lock()
241242
defer b.mutex.Unlock()
242243
return b.text.String()
243244
}
244245

245-
func (b *buffer) Data() Log {
246+
func (b *logBuffer) Data() Log {
246247
b.mutex.Lock()
247248
defer b.mutex.Unlock()
248249
return b.log.DeepCopy()
@@ -263,7 +264,7 @@ type tloggerShared struct {
263264

264265
testName string
265266
config *Config
266-
buffer buffer
267+
buffer logBuffer
267268
callDepth int
268269
}
269270

@@ -318,9 +319,9 @@ func (l tlogger) Info(level int, msg string, kvList ...interface{}) {
318319
}
319320

320321
l.shared.t.Helper()
321-
buffer := &bytes.Buffer{}
322-
serialize.MergeAndFormatKVs(buffer, l.values, kvList)
323-
l.log(LogInfo, msg, level, buffer, nil, kvList)
322+
buf := buffer.GetBuffer()
323+
serialize.MergeAndFormatKVs(&buf.Buffer, l.values, kvList)
324+
l.log(LogInfo, msg, level, buf, nil, kvList)
324325
}
325326

326327
func (l tlogger) Enabled(level int) bool {
@@ -336,24 +337,28 @@ func (l tlogger) Error(err error, msg string, kvList ...interface{}) {
336337
}
337338

338339
l.shared.t.Helper()
339-
buffer := &bytes.Buffer{}
340+
buf := buffer.GetBuffer()
340341
if err != nil {
341-
serialize.KVFormat(buffer, "err", err)
342+
serialize.KVFormat(&buf.Buffer, "err", err)
342343
}
343-
serialize.MergeAndFormatKVs(buffer, l.values, kvList)
344-
l.log(LogError, msg, 0, buffer, err, kvList)
344+
serialize.MergeAndFormatKVs(&buf.Buffer, l.values, kvList)
345+
l.log(LogError, msg, 0, buf, err, kvList)
345346
}
346347

347-
func (l tlogger) log(what LogType, msg string, level int, buffer *bytes.Buffer, err error, kvList []interface{}) {
348+
func (l tlogger) log(what LogType, msg string, level int, buf *buffer.Buffer, err error, kvList []interface{}) {
348349
l.shared.t.Helper()
349-
args := []interface{}{what}
350+
s := severity.InfoLog
351+
if what == LogError {
352+
s = severity.ErrorLog
353+
}
354+
args := []interface{}{buf.SprintHeader(s, time.Now())}
350355
if l.prefix != "" {
351356
args = append(args, l.prefix+":")
352357
}
353358
args = append(args, msg)
354-
if buffer.Len() > 0 {
359+
if buf.Len() > 0 {
355360
// Skip leading space inserted by serialize.KVListFormat.
356-
args = append(args, string(buffer.Bytes()[1:]))
361+
args = append(args, string(buf.Bytes()[1:]))
357362
}
358363
l.shared.t.Log(args...)
359364

‎ktesting/testinglogger_test.go‎

Lines changed: 13 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -33,78 +33,78 @@ func TestInfo(t *testing.T) {
3333
"should log with values passed to keysAndValues": {
3434
text: "test",
3535
keysAndValues: []interface{}{"akey", "avalue"},
36-
expectedOutput: `INFO test akey="avalue"
36+
expectedOutput: `Ixxx test akey="avalue"
3737
`,
3838
},
3939
"should support single name": {
4040
names: []string{"hello"},
4141
text: "test",
4242
keysAndValues: []interface{}{"akey", "avalue"},
43-
expectedOutput: `INFO hello: test akey="avalue"
43+
expectedOutput: `Ixxx hello: test akey="avalue"
4444
`,
4545
},
4646
"should support multiple names": {
4747
names: []string{"hello", "world"},
4848
text: "test",
4949
keysAndValues: []interface{}{"akey", "avalue"},
50-
expectedOutput: `INFO hello/world: test akey="avalue"
50+
expectedOutput: `Ixxx hello/world: test akey="avalue"
5151
`,
5252
},
5353
"should not print duplicate keys with the same value": {
5454
text: "test",
5555
keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue"},
56-
expectedOutput: `INFO test akey="avalue" akey="avalue"
56+
expectedOutput: `Ixxx test akey="avalue" akey="avalue"
5757
`,
5858
},
5959
"should only print the last duplicate key when the values are passed to Info": {
6060
text: "test",
6161
keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue2"},
62-
expectedOutput: `INFO test akey="avalue" akey="avalue2"
62+
expectedOutput: `Ixxx test akey="avalue" akey="avalue2"
6363
`,
6464
},
6565
"should only print the duplicate key that is passed to Info if one was passed to the logger": {
6666
withValues: []interface{}{"akey", "avalue"},
6767
text: "test",
6868
keysAndValues: []interface{}{"akey", "avalue"},
69-
expectedOutput: `INFO test akey="avalue"
69+
expectedOutput: `Ixxx test akey="avalue"
7070
`,
7171
},
7272
"should only print the key passed to Info when one is already set on the logger": {
7373
withValues: []interface{}{"akey", "avalue"},
7474
text: "test",
7575
keysAndValues: []interface{}{"akey", "avalue2"},
76-
expectedOutput: `INFO test akey="avalue2"
76+
expectedOutput: `Ixxx test akey="avalue2"
7777
`,
7878
},
7979
"should correctly handle odd-numbers of KVs": {
8080
text: "test",
8181
keysAndValues: []interface{}{"akey", "avalue", "akey2"},
82-
expectedOutput: `INFO test akey="avalue" akey2="(MISSING)"
82+
expectedOutput: `Ixxx test akey="avalue" akey2="(MISSING)"
8383
`,
8484
},
8585
"should correctly html characters": {
8686
text: "test",
8787
keysAndValues: []interface{}{"akey", "<&>"},
88-
expectedOutput: `INFO test akey="<&>"
88+
expectedOutput: `Ixxx test akey="<&>"
8989
`,
9090
},
9191
"should correctly handle odd-numbers of KVs in both log values and Info args": {
9292
withValues: []interface{}{"basekey1", "basevar1", "basekey2"},
9393
text: "test",
9494
keysAndValues: []interface{}{"akey", "avalue", "akey2"},
95-
expectedOutput: `INFO test basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)"
95+
expectedOutput: `Ixxx test basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)"
9696
`,
9797
},
9898
"should correctly print regular error types": {
9999
text: "test",
100100
keysAndValues: []interface{}{"err", errors.New("whoops")},
101-
expectedOutput: `INFO test err="whoops"
101+
expectedOutput: `Ixxx test err="whoops"
102102
`,
103103
},
104104
"should correctly print regular error types when using logr.Error": {
105105
text: "test",
106106
err: errors.New("whoops"),
107-
expectedOutput: `ERROR test err="whoops"
107+
expectedOutput: `Exxx test err="whoops"
108108
`,
109109
},
110110
}
@@ -124,6 +124,7 @@ func TestInfo(t *testing.T) {
124124
}
125125

126126
actual := buffer.String()
127+
actual = regexp.MustCompile(`([IE])[[:digit:]]{4} [[:digit:]]{2}:[[:digit:]]{2}:[[:digit:]]{2}\.[[:digit:]]{6}\] `).ReplaceAllString(actual, `${1}xxx `)
127128
if actual != test.expectedOutput {
128129
t.Errorf("Expected:\n%sActual:\n%s\n", test.expectedOutput, actual)
129130
}

0 commit comments

Comments
 (0)