Skip to content

output: handle WithName like zapr does #391

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 1 commit into from
Oct 26, 2023
+133 −78
Merged

output: handle WithName like zapr does #391

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
41 changes: 29 additions & 12 deletions klogr.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -22,6 +22,11 @@ import (
"k8s.io/klog/v2/internal/serialize"
)

const (
// nameKey is used to log the `WithName` values as an additional attribute.
nameKey = "logger"
)

// NewKlogr returns a logger that is functionally identical to
// klogr.NewWithOptions(klogr.FormatKlog), i.e. it passes through to klog. The
// difference is that it uses a simpler implementation.
Expand All @@ -33,8 +38,13 @@ func NewKlogr() Logger {
// import cycle (klogr wants to use klog, and klog wants to use klogr).
type klogger struct {
callDepth int
prefix string
values []interface{}

// hasPrefix is true if the first entry in values is the special
// nameKey key/value. Such an entry gets added and later updated in
// WithName.
hasPrefix bool

values []interface{}
}

func (l *klogger) Init(info logr.RuntimeInfo) {
Expand All @@ -43,9 +53,6 @@ func (l *klogger) Init(info logr.RuntimeInfo) {

func (l *klogger) Info(level int, msg string, kvList ...interface{}) {
merged := serialize.MergeKVs(l.values, kvList)
if l.prefix != "" {
msg = l.prefix + ": " + msg
}
// Skip this function.
VDepth(l.callDepth+1, Level(level)).InfoSDepth(l.callDepth+1, msg, merged...)
}
Expand All @@ -57,20 +64,30 @@ func (l *klogger) Enabled(level int) bool {

func (l *klogger) Error(err error, msg string, kvList ...interface{}) {
merged := serialize.MergeKVs(l.values, kvList)
if l.prefix != "" {
msg = l.prefix + ": " + msg
}
ErrorSDepth(l.callDepth+1, err, msg, merged...)
}

// WithName returns a new logr.Logger with the specified name appended. klogr
// uses '/' characters to separate name elements. Callers should not pass '/'
// uses '.' characters to separate name elements. Callers should not pass '.'
// in the provided name string, but this library does not actually enforce that.
func (l klogger) WithName(name string) logr.LogSink {
if len(l.prefix) > 0 {
l.prefix = l.prefix + "/"
if l.hasPrefix {
// Copy slice and modify value. No length checks and type
// assertions are needed because hasPrefix is only true if the
// first two elements exist and are key/value strings.
v := make([]interface{}, 0, len(l.values))
v = append(v, l.values...)
prefix, _ := v[1].(string)
v[1] = prefix + "." + name
l.values = v
} else {
// Preprend new key/value pair.
v := make([]interface{}, 0, 2+len(l.values))
v = append(v, nameKey, name)
v = append(v, l.values...)
l.values = v
l.hasPrefix = true
}
l.prefix += name
return &l
}

Expand Down
51 changes: 34 additions & 17 deletions klogr/klogr.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,11 @@ import (
"k8s.io/klog/v2/internal/serialize"
)

const (
// nameKey is used to log the `WithName` values as an additional attribute.
nameKey = "logger"
)

// Option is a functional option that reconfigures the logger created with New.
type Option func(*klogger)

Expand All @@ -23,7 +28,7 @@ type Format string

const (
// FormatSerialize tells klogr to turn key/value pairs into text itself
// before invoking klog.
// before invoking klog. Key/value pairs are sorted by key.
FormatSerialize Format = "Serialize"

// FormatKlog tells klogr to pass all text messages and key/value pairs
Expand Down Expand Up @@ -51,7 +56,6 @@ func New() logr.Logger {
func NewWithOptions(options ...Option) logr.Logger {
l := klogger{
level: 0,
prefix: "",
values: nil,
format: FormatKlog,
}
Expand All @@ -64,9 +68,14 @@ func NewWithOptions(options ...Option) logr.Logger {
type klogger struct {
level int
callDepth int
prefix string
values []interface{}
format Format

// hasPrefix is true if the first entry in values is the special
// nameKey key/value. Such an entry gets added and later updated in
// WithName.
hasPrefix bool

values []interface{}
format Format
}

func (l *klogger) Init(info logr.RuntimeInfo) {
Expand Down Expand Up @@ -127,12 +136,9 @@ func (l *klogger) Info(level int, msg string, kvList ...interface{}) {
msgStr := flatten("msg", msg)
merged := serialize.MergeKVs(l.values, kvList)
kvStr := flatten(merged...)
klog.VDepth(l.callDepth+1, klog.Level(level)).InfoDepth(l.callDepth+1, l.prefix, " ", msgStr, " ", kvStr)
klog.VDepth(l.callDepth+1, klog.Level(level)).InfoDepth(l.callDepth+1, msgStr, " ", kvStr)
case FormatKlog:
merged := serialize.MergeKVs(l.values, kvList)
if l.prefix != "" {
msg = l.prefix + ": " + msg
}
klog.VDepth(l.callDepth+1, klog.Level(level)).InfoSDepth(l.callDepth+1, msg, merged...)
}
}
Expand All @@ -153,24 +159,35 @@ func (l *klogger) Error(err error, msg string, kvList ...interface{}) {
errStr := flatten("error", loggableErr)
merged := serialize.MergeKVs(l.values, kvList)
kvStr := flatten(merged...)
klog.ErrorDepth(l.callDepth+1, l.prefix, " ", msgStr, " ", errStr, " ", kvStr)
klog.ErrorDepth(l.callDepth+1, msgStr, " ", errStr, " ", kvStr)
case FormatKlog:
merged := serialize.MergeKVs(l.values, kvList)
if l.prefix != "" {
msg = l.prefix + ": " + msg
}
klog.ErrorSDepth(l.callDepth+1, err, msg, merged...)
}
}

// WithName returns a new logr.Logger with the specified name appended. klogr
// uses '/' characters to separate name elements. Callers should not pass '/'
// uses '.' characters to separate name elements. Callers should not pass '.'
// in the provided name string, but this library does not actually enforce that.
func (l klogger) WithName(name string) logr.LogSink {
if len(l.prefix) > 0 {
l.prefix = l.prefix + "/"
if l.hasPrefix {
// Copy slice and modify value. No length checks and type
// assertions are needed because hasPrefix is only true if the
// first two elements exist and are key/value strings.
v := make([]interface{}, 0, len(l.values))
v = append(v, l.values...)
prefix, _ := v[1].(string)
prefix = prefix + "." + name
v[1] = prefix
l.values = v
} else {
// Preprend new key/value pair.
v := make([]interface{}, 0, 2+len(l.values))
v = append(v, nameKey, name)
v = append(v, l.values...)
Comment on lines +186 to +187
Copy link

@harshanarayana harshanarayana Oct 26, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
v = append(v, nameKey, name)
v = append(v, l.values...)
v = append(v, nameKey, name, l.values...)

I might be nitpicking, but Would the above one make it more easier ?
Copy link
Author

@pohly pohly Oct 26, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It would, but Go doesn't support this: one can either append multiple values or provide those values through a slice, but not both.
Copy link

@harshanarayana harshanarayana Oct 26, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah ! Sorry, never mind. my thought about reviewing something on python slipped into this thread as well. You are right. Thanks for clarifying.
l.values = v
l.hasPrefix = true
}
l.prefix += name
return &l
}

Expand Down
38 changes: 21 additions & 17 deletions klogr/klogr_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -42,7 +42,7 @@ func testOutput(t *testing.T, format string) {
klogr: createLogger().V(0),
text: "test",
keysAndValues: []interface{}{"akey", "avalue"},
expectedOutput: ` "msg"="test" "akey"="avalue"
expectedOutput: `"msg"="test" "akey"="avalue"
Copy link

@harshanarayana harshanarayana Oct 26, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I like that this empty space at the start is going away.
Copy link
Author

@pohly pohly Oct 26, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes. That space was the result of some overly simplistic code for injecting the prefix, which is now gone.
`,
expectedKlogOutput: `"test" akey="avalue"
`,
Expand All @@ -51,25 +51,29 @@ func testOutput(t *testing.T, format string) {
klogr: createLogger().V(0).WithName("me"),
text: "test",
keysAndValues: []interface{}{"akey", "avalue"},
expectedOutput: `me "msg"="test" "akey"="avalue"
// Sorted by keys.
expectedOutput: `"msg"="test" "akey"="avalue" "logger"="me"
`,
expectedKlogOutput: `"me: test" akey="avalue"
// Not sorted by keys.
expectedKlogOutput: `"test" logger="me" akey="avalue"
`,
},
"should log with multiple names and values passed to keysAndValues": {
klogr: createLogger().V(0).WithName("hello").WithName("world"),
text: "test",
keysAndValues: []interface{}{"akey", "avalue"},
expectedOutput: `hello/world "msg"="test" "akey"="avalue"
// Sorted by keys.
expectedOutput: `"msg"="test" "akey"="avalue" "logger"="hello.world"
`,
expectedKlogOutput: `"hello/world: test" akey="avalue"
// Not sorted by keys.
expectedKlogOutput: `"test" logger="hello.world" akey="avalue"
`,
},
"may print duplicate keys with the same value": {
klogr: createLogger().V(0),
text: "test",
keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue"},
expectedOutput: ` "msg"="test" "akey"="avalue"
expectedOutput: `"msg"="test" "akey"="avalue"
`,
expectedKlogOutput: `"test" akey="avalue" akey="avalue"
`,
Expand All @@ -78,7 +82,7 @@ func testOutput(t *testing.T, format string) {
klogr: createLogger().V(0),
text: "test",
keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue2"},
expectedOutput: ` "msg"="test" "akey"="avalue2"
expectedOutput: `"msg"="test" "akey"="avalue2"
`,
expectedKlogOutput: `"test" akey="avalue" akey="avalue2"
`,
Expand All @@ -87,7 +91,7 @@ func testOutput(t *testing.T, format string) {
klogr: createLogger().WithValues("akey", "avalue"),
text: "test",
keysAndValues: []interface{}{"akey", "avalue"},
expectedOutput: ` "msg"="test" "akey"="avalue"
expectedOutput: `"msg"="test" "akey"="avalue"
`,
expectedKlogOutput: `"test" akey="avalue"
`,
Expand All @@ -96,7 +100,7 @@ func testOutput(t *testing.T, format string) {
klogr: createLogger().WithValues("akey9", "avalue9", "akey8", "avalue8", "akey1", "avalue1"),
text: "test",
keysAndValues: []interface{}{"akey5", "avalue5", "akey4", "avalue4"},
expectedOutput: ` "msg"="test" "akey1"="avalue1" "akey4"="avalue4" "akey5"="avalue5" "akey8"="avalue8" "akey9"="avalue9"
expectedOutput: `"msg"="test" "akey1"="avalue1" "akey4"="avalue4" "akey5"="avalue5" "akey8"="avalue8" "akey9"="avalue9"
`,
expectedKlogOutput: `"test" akey9="avalue9" akey8="avalue8" akey1="avalue1" akey5="avalue5" akey4="avalue4"
`,
Expand All @@ -105,7 +109,7 @@ func testOutput(t *testing.T, format string) {
klogr: createLogger().WithValues("akey", "avalue"),
text: "test",
keysAndValues: []interface{}{"akey", "avalue2"},
expectedOutput: ` "msg"="test" "akey"="avalue2"
expectedOutput: `"msg"="test" "akey"="avalue2"
`,
expectedKlogOutput: `"test" akey="avalue2"
`,
Expand All @@ -114,7 +118,7 @@ func testOutput(t *testing.T, format string) {
klogr: createLogger(),
text: "test",
keysAndValues: []interface{}{"akey", "avalue", "akey2"},
expectedOutput: ` "msg"="test" "akey"="avalue" "akey2"="(MISSING)"
expectedOutput: `"msg"="test" "akey"="avalue" "akey2"="(MISSING)"
`,
expectedKlogOutput: `"test" akey="avalue" akey2="(MISSING)"
`,
Expand All @@ -124,7 +128,7 @@ func testOutput(t *testing.T, format string) {
text: "test",
keysAndValues: []interface{}{"akey", "avalue", "akey2"},
// klogr format sorts all key/value pairs.
expectedOutput: ` "msg"="test" "akey"="avalue" "akey2"="(MISSING)" "keyWithoutValue"="(MISSING)"
expectedOutput: `"msg"="test" "akey"="avalue" "akey2"="(MISSING)" "keyWithoutValue"="(MISSING)"
`,
expectedKlogOutput: `"test" keyWithoutValue="(MISSING)" akey="avalue" akey2="(MISSING)"
`,
Expand All @@ -133,7 +137,7 @@ func testOutput(t *testing.T, format string) {
klogr: createLogger(),
text: "test",
keysAndValues: []interface{}{"akey", "<&>"},
expectedOutput: ` "msg"="test" "akey"="<&>"
expectedOutput: `"msg"="test" "akey"="<&>"
`,
expectedKlogOutput: `"test" akey="<&>"
`,
Expand All @@ -143,7 +147,7 @@ func testOutput(t *testing.T, format string) {
text: "test",
keysAndValues: []interface{}{"akey", "avalue", "akey2"},
// klogr format sorts all key/value pairs.
expectedOutput: ` "msg"="test" "akey"="avalue" "akey2"="(MISSING)" "basekey1"="basevar1" "basekey2"="(MISSING)"
expectedOutput: `"msg"="test" "akey"="avalue" "akey2"="(MISSING)" "basekey1"="basevar1" "basekey2"="(MISSING)"
`,
expectedKlogOutput: `"test" basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)"
`,
Expand All @@ -152,7 +156,7 @@ func testOutput(t *testing.T, format string) {
klogr: createLogger().V(0),
text: "test",
keysAndValues: []interface{}{"err", errors.New("whoops")},
expectedOutput: ` "msg"="test" "err"="whoops"
expectedOutput: `"msg"="test" "err"="whoops"
`,
expectedKlogOutput: `"test" err="whoops"
`,
Expand All @@ -161,7 +165,7 @@ func testOutput(t *testing.T, format string) {
klogr: createLogger().V(0),
text: "test",
keysAndValues: []interface{}{"err", &customErrorJSON{"whoops"}},
expectedOutput: ` "msg"="test" "err"="WHOOPS"
expectedOutput: `"msg"="test" "err"="WHOOPS"
`,
expectedKlogOutput: `"test" err="whoops"
`,
Expand All @@ -170,7 +174,7 @@ func testOutput(t *testing.T, format string) {
klogr: createLogger().V(0),
text: "test",
err: errors.New("whoops"),
expectedOutput: ` "msg"="test" "error"="whoops"
expectedOutput: `"msg"="test" "error"="whoops"
`,
expectedKlogOutput: `"test" err="whoops"
`,
Expand Down
10 changes: 5 additions & 5 deletions ktesting/testinglogger_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -216,7 +216,7 @@ func TestStop(t *testing.T) {
// have the < > markers.
//
// Full output:
// testinglogger_test.go:194] "TestStop/Sub leaked goroutine: WARNING: test kept at least one goroutine running after test completion" callstack=<
// testinglogger_test.go:194] "WARNING: test kept at least one goroutine running after test completion" logger="TestStop/Sub leaked goroutine" callstack=<
// goroutine 23 [running]:
// k8s.io/klog/v2/internal/dbg.Stacks(0x0)
// /nvme/gopath/src/k8s.io/klog/internal/dbg/dbg.go:34 +0x8a
Expand All @@ -233,11 +233,11 @@ func TestStop(t *testing.T) {
// >
actual = regexp.MustCompile(`(?m)^\t.*?\n`).ReplaceAllString(actual, ``)

expected := fmt.Sprintf(`testinglogger_test.go:%d] "TestStop/Sub leaked goroutine: WARNING: test kept at least one goroutine running after test completion" callstack=<
expected := fmt.Sprintf(`testinglogger_test.go:%d] "WARNING: test kept at least one goroutine running after test completion" logger="TestStop/Sub leaked goroutine" callstack=<
>
testinglogger_test.go:%d] "TestStop/Sub leaked goroutine: simple info message"
testinglogger_test.go:%d] "TestStop/Sub leaked goroutine: error message"
testinglogger_test.go:%d] "TestStop/Sub leaked goroutine/me: complex info message" completed=true anotherValue=1
testinglogger_test.go:%d] "simple info message" logger="TestStop/Sub leaked goroutine"
testinglogger_test.go:%d] "error message" logger="TestStop/Sub leaked goroutine"
testinglogger_test.go:%d] "complex info message" logger="TestStop/Sub leaked goroutine.me" completed=true anotherValue=1
`,
line+1, line+1, line+2, line+3)
if actual != expected {
Expand Down
Loading