Skip to content

Commit

Permalink
ktesting: use klog-like header
Browse files Browse the repository at this point in the history 
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
  • Loading branch information
@pohly
pohly committed Feb 2, 2023
1 parent 1025055 commit 8b4cfd2
Show file tree
Hide file tree
Showing 3 changed files with 63 additions and 29 deletions.
30 changes: 29 additions & 1 deletion internal/buffer/buffer.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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])
}
37 changes: 21 additions & 16 deletions ktesting/testinglogger.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -42,16 +42,17 @@ limitations under the License.
package ktesting

import (
"bytes"
"strings"
"sync"
"time"

"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"
)

Expand Down Expand Up @@ -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()
Expand All @@ -263,7 +264,7 @@ type tloggerShared struct {

testName string
config *Config
buffer buffer
buffer logBuffer
callDepth int
}

Expand Down Expand Up @@ -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 {
Expand All @@ -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...)

Expand Down
25 changes: 13 additions & 12 deletions ktesting/testinglogger_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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"
`,
},
}
Expand All @@ -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)
}
Expand Down

0 comments on commit 8b4cfd2

Please sign in to comment.