From 5ecf788fcdd2e3e37533a6cbfc07512a597ed2be Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Fri, 12 Nov 2021 13:58:38 +0100 Subject: [PATCH 1/5] examples: use current klog, add structured logging example Structured logging with InfoS is formatted differently than traditional output, so it's worthwhile to have an example that demostrates that. The new example didn't compile initially because an older version of klog was used. This gets avoids by always using the source from the current directory. --- examples/go.mod | 4 +- examples/go.sum | 2 + .../structured_logging/structured_logging.go | 74 +++++++++++++++++++ 3 files changed, 79 insertions(+), 1 deletion(-) create mode 100644 examples/structured_logging/structured_logging.go diff --git a/examples/go.mod b/examples/go.mod index c348862d..2768f2c1 100644 --- a/examples/go.mod +++ b/examples/go.mod @@ -4,5 +4,7 @@ go 1.13 require ( github.com/golang/glog v0.0.0-20160126235308-23def4e6c14b - k8s.io/klog/v2 v2.0.0-20200324194303-db919253a3bc + k8s.io/klog/v2 v2.30.0 ) + +replace k8s.io/klog/v2 => ../ diff --git a/examples/go.sum b/examples/go.sum index d00155c9..4d41cc90 100644 --- a/examples/go.sum +++ b/examples/go.sum @@ -1,5 +1,7 @@ github.com/go-logr/logr v0.1.0 h1:M1Tv3VzNlEHg6uyACnRdtrploV2P7wZqH8BoQMtz0cg= github.com/go-logr/logr v0.1.0/go.mod h1:ixOQHD9gLJUVQQ2ZOR7zLEifBX6tGkNJF4QyIY7sIas= +github.com/go-logr/logr v1.2.0 h1:QK40JKJyMdUDz+h+xvCsru/bJhvG0UxvePV0ufL/AcE= +github.com/go-logr/logr v1.2.0/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A= github.com/golang/glog v0.0.0-20160126235308-23def4e6c14b h1:VKtxabqXZkF25pY9ekfRL6a582T4P37/31XEstQ5p58= github.com/golang/glog v0.0.0-20160126235308-23def4e6c14b/go.mod h1:SBH7ygxi8pfUlaOkMMuAQtPIUF8ecWP5IEl/CR7VP2Q= k8s.io/klog/v2 v2.0.0-20200324194303-db919253a3bc h1:E/enZ+SqXD3ChluFNvXqlLcUkqMQQDpiyGruRq5pjvY= diff --git a/examples/structured_logging/structured_logging.go b/examples/structured_logging/structured_logging.go new file mode 100644 index 00000000..6e80bd93 --- /dev/null +++ b/examples/structured_logging/structured_logging.go @@ -0,0 +1,74 @@ +package main + +import ( + "flag" + + "k8s.io/klog/v2" +) + +// MyStruct will be logged via %+v +type MyStruct struct { + Name string + Data string + internal int +} + +// MyStringer will be logged as string, with String providing that string. +type MyString MyStruct + +func (m MyString) String() string { + return m.Name + ": " + m.Data +} + +func main() { + klog.InitFlags(nil) + flag.Parse() + + someData := MyStruct{ + Name: "hello", + Data: "world", + } + + longData := MyStruct{ + Name: "long", + Data: `Multiple +lines +with quite a bit +of text.`, + } + + logData := MyStruct{ + Name: "log output from some program", + Data: `I0000 12:00:00.000000 123456 main.go:42] Starting +E0000 12:00:01.000000 123456 main.go:43] Failed for some reason +`, + } + + stringData := MyString(longData) + + klog.Infof("someData printed using InfoF: %v", someData) + klog.Infof("longData printed using InfoF: %v", longData) + klog.Infof(`stringData printed using InfoF, +with the message across multiple lines: +%v`, stringData) + klog.Infof("logData printed using InfoF:\n%v", logData) + + klog.Info("=============================================") + + klog.InfoS("using InfoS", "someData", someData) + klog.InfoS("using InfoS", "longData", longData) + klog.InfoS(`using InfoS with +the message across multiple lines`, + "int", 1, + "stringData", stringData, + "str", "another value") + klog.InfoS("using InfoS", "logData", logData) + klog.InfoS("using InfoS", "boolean", true, "int", 1, "float", 0.1) + + // The Kubernetes recommendation is to start the message with uppercase + // and not end with punctuation. See + // https://github.com/kubernetes/community/blob/HEAD/contributors/devel/sig-instrumentation/migration-to-structured-logging.md + klog.InfoS("Did something", "item", "foobar") + // Not recommended, but also works. + klog.InfoS("This is a full sentence.", "item", "foobar") +} From ae76ae01cfcecaa75607a5b7970855842f667933 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Fri, 26 Nov 2021 11:29:02 +0100 Subject: [PATCH 2/5] structured output: reuse buffer MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit There is a mechanism for allocating smallish buffers (< 256 bytes) only once and then reusing them. Doing that for the structured key/value pairs is an improvement (measured with https://github.com/kubernetes/kubernetes/pull/106594): $ $GOPATH/bin/benchstat /tmp/original /tmp/reuse-buffer name old time/op new time/op delta Logging/container/structured-36 41.6µs ± 1% 41.6µs ± 1% ~ (p=1.000 n=5+5) Logging/error-value/structured-36 4.01µs ± 3% 3.37µs ± 3% -16.01% (p=0.008 n=5+5) Logging/error/structured-36 3.91µs ± 1% 3.33µs ± 3% -14.90% (p=0.008 n=5+5) Logging/simple/structured-36 3.54µs ± 3% 2.98µs ± 3% -15.77% (p=0.008 n=5+5) Logging/values/structured-36 6.83µs ± 2% 5.31µs ± 5% -22.34% (p=0.008 n=5+5) name old alloc/op new alloc/op delta Logging/container/structured-36 10.4kB ± 0% 10.5kB ± 0% +0.61% (p=0.008 n=5+5) Logging/error-value/structured-36 432B ± 0% 320B ± 0% -25.93% (p=0.008 n=5+5) Logging/error/structured-36 448B ± 0% 336B ± 0% -25.00% (p=0.008 n=5+5) Logging/simple/structured-36 408B ± 0% 296B ± 0% -27.45% (p=0.008 n=5+5) Logging/values/structured-36 777B ± 0% 505B ± 0% -35.01% (p=0.008 n=5+5) name old allocs/op new allocs/op delta Logging/container/structured-36 64.0 ± 0% 64.0 ± 0% ~ (all equal) Logging/error-value/structured-36 9.00 ± 0% 7.00 ± 0% -22.22% (p=0.008 n=5+5) Logging/error/structured-36 10.0 ± 0% 8.0 ± 0% -20.00% (p=0.008 n=5+5) Logging/simple/structured-36 8.00 ± 0% 6.00 ± 0% -25.00% (p=0.008 n=5+5) Logging/values/structured-36 16.0 ± 0% 13.0 ± 0% -18.75% (p=0.008 n=5+5) --- klog.go | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/klog.go b/klog.go index 45efbb07..329c6c10 100644 --- a/klog.go +++ b/klog.go @@ -801,14 +801,17 @@ func (l *loggingT) infoS(logger *logr.Logger, filter LogFilter, depth int, msg s // printS is called from infoS and errorS if loggr is not specified. // set log severity by s func (l *loggingT) printS(err error, s severity, depth int, msg string, keysAndValues ...interface{}) { - b := &bytes.Buffer{} + // Only create a new buffer if we don't have one cached. + b := l.getBuffer() b.WriteString(fmt.Sprintf("%q", msg)) if err != nil { b.WriteByte(' ') b.WriteString(fmt.Sprintf("err=%q", err.Error())) } - kvListFormat(b, keysAndValues...) - l.printDepth(s, logging.logr, nil, depth+1, b) + kvListFormat(&b.Buffer, keysAndValues...) + l.printDepth(s, logging.logr, nil, depth+1, &b.Buffer) + // Make the buffer available for reuse. + l.putBuffer(b) } const missingValue = "(MISSING)" From aac832f981b9215987d33db11d845e54270fcf08 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Fri, 26 Nov 2021 11:50:38 +0100 Subject: [PATCH 3/5] structured output: reduce usage of Sprintf MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit We can avoid several allocations and use faster code (= strconv.Quote) by relying less on Sprintf. $ $GOPATH/bin/benchstat /tmp/reuse-buffer /tmp/strconv name old time/op new time/op delta Logging/container/structured-36 41.6µs ± 1% 39.5µs ± 2% -5.05% (p=0.008 n=5+5) Logging/error-value/structured-36 3.37µs ± 3% 3.13µs ± 0% -7.06% (p=0.016 n=5+4) Logging/error/structured-36 3.33µs ± 3% 3.09µs ± 2% -7.10% (p=0.008 n=5+5) Logging/simple/structured-36 2.98µs ± 3% 2.86µs ± 4% ~ (p=0.095 n=5+5) Logging/values/structured-36 5.31µs ± 5% 4.77µs ± 4% -10.17% (p=0.008 n=5+5) name old alloc/op new alloc/op delta Logging/container/structured-36 10.5kB ± 0% 9.3kB ± 0% -11.01% (p=0.008 n=5+5) Logging/error-value/structured-36 320B ± 0% 312B ± 0% -2.50% (p=0.008 n=5+5) Logging/error/structured-36 336B ± 0% 312B ± 0% -7.14% (p=0.008 n=5+5) Logging/simple/structured-36 296B ± 0% 288B ± 0% -2.70% (p=0.008 n=5+5) Logging/values/structured-36 505B ± 0% 464B ± 0% -8.12% (p=0.008 n=5+5) name old allocs/op new allocs/op delta Logging/container/structured-36 64.0 ± 0% 62.0 ± 0% -3.12% (p=0.008 n=5+5) Logging/error-value/structured-36 7.00 ± 0% 6.00 ± 0% -14.29% (p=0.008 n=5+5) Logging/error/structured-36 8.00 ± 0% 6.00 ± 0% -25.00% (p=0.008 n=5+5) Logging/simple/structured-36 6.00 ± 0% 5.00 ± 0% -16.67% (p=0.008 n=5+5) Logging/values/structured-36 13.0 ± 0% 11.0 ± 0% -15.38% (p=0.008 n=5+5) --- klog.go | 35 +++++++++++++++++++++++------------ 1 file changed, 23 insertions(+), 12 deletions(-) diff --git a/klog.go b/klog.go index 329c6c10..f8ee06e9 100644 --- a/klog.go +++ b/klog.go @@ -803,10 +803,10 @@ func (l *loggingT) infoS(logger *logr.Logger, filter LogFilter, depth int, msg s func (l *loggingT) printS(err error, s severity, depth int, msg string, keysAndValues ...interface{}) { // Only create a new buffer if we don't have one cached. b := l.getBuffer() - b.WriteString(fmt.Sprintf("%q", msg)) + b.WriteString(strconv.Quote(msg)) if err != nil { - b.WriteByte(' ') - b.WriteString(fmt.Sprintf("err=%q", err.Error())) + b.WriteString(" err=") + b.WriteString(strconv.Quote(err.Error())) } kvListFormat(&b.Buffer, keysAndValues...) l.printDepth(s, logging.logr, nil, depth+1, &b.Buffer) @@ -826,18 +826,29 @@ func kvListFormat(b *bytes.Buffer, keysAndValues ...interface{}) { v = missingValue } b.WriteByte(' ') + if k, ok := k.(string); ok { + // Avoid one allocation when the key is a string, which + // normally it should be. + b.WriteString(k) + } else { + b.WriteString(fmt.Sprintf("%s", k)) + } + b.WriteByte('=') - switch v.(type) { - case string, error: - b.WriteString(fmt.Sprintf("%s=%q", k, v)) + switch v := v.(type) { + case string: + b.WriteString(strconv.Quote(v)) + case error: + b.WriteString(strconv.Quote(v.Error())) case []byte: - b.WriteString(fmt.Sprintf("%s=%+q", k, v)) + // We cannot use the simpler strconv.Quote here + // because it does not escape unicode characters, which is + // expected by one test!? + b.WriteString(fmt.Sprintf("%+q", v)) + case fmt.Stringer: + b.WriteString(strconv.Quote(v.String())) default: - if _, ok := v.(fmt.Stringer); ok { - b.WriteString(fmt.Sprintf("%s=%q", k, v)) - } else { - b.WriteString(fmt.Sprintf("%s=%+v", k, v)) - } + b.WriteString(fmt.Sprintf("%+v", v)) } } } From 6749fe14f4ec9b252dd005986fbea1adb8403f19 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Fri, 26 Nov 2021 12:51:09 +0100 Subject: [PATCH 4/5] structured output: reorder type switch MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Checking common types first is slightly faster. No difference for simple benchmarks: $ $GOPATH/bin/benchstat /tmp/strconv /tmp/reorder name old time/op new time/op delta Logging/container/structured-36 39.5µs ± 2% 39.6µs ± 1% ~ (p=1.000 n=5+5) Logging/error-value/structured-36 3.13µs ± 0% 3.14µs ± 4% ~ (p=0.730 n=4+5) Logging/error/structured-36 3.09µs ± 2% 3.13µs ± 3% ~ (p=0.548 n=5+5) Logging/simple/structured-36 2.86µs ± 4% 2.91µs ± 2% ~ (p=0.310 n=5+5) Logging/values/structured-36 4.77µs ± 4% 4.77µs ± 5% ~ (p=0.841 n=5+5) name old alloc/op new alloc/op delta Logging/container/structured-36 9.35kB ± 0% 9.35kB ± 0% ~ (p=0.095 n=5+4) Logging/error-value/structured-36 312B ± 0% 312B ± 0% ~ (all equal) Logging/error/structured-36 312B ± 0% 312B ± 0% ~ (all equal) Logging/simple/structured-36 288B ± 0% 288B ± 0% ~ (all equal) Logging/values/structured-36 464B ± 0% 464B ± 0% ~ (all equal) name old allocs/op new allocs/op delta Logging/container/structured-36 62.0 ± 0% 62.0 ± 0% ~ (all equal) Logging/error-value/structured-36 6.00 ± 0% 6.00 ± 0% ~ (all equal) Logging/error/structured-36 6.00 ± 0% 6.00 ± 0% ~ (all equal) Logging/simple/structured-36 5.00 ± 0% 5.00 ± 0% ~ (all equal) Logging/values/structured-36 11.0 ± 0% 11.0 ± 0% ~ (all equal) It's a bigger win for a real kubelet log: $ $GOPATH/bin/benchstat /tmp/strconv-kubelet /tmp/reorder-kubelet name old time/op new time/op delta Logging/v5/kubelet/structured-36 1.17s ± 2% 1.15s ± 1% -1.37% (p=0.016 n=5+5) name old alloc/op new alloc/op delta Logging/v5/kubelet/structured-36 525MB ± 0% 525MB ± 0% ~ (p=0.548 n=5+5) name old allocs/op new allocs/op delta Logging/v5/kubelet/structured-36 3.86M ± 0% 3.86M ± 0% ~ (p=0.079 n=5+5) Args: total: 310746 strings: 106904 (34%) with line breaks: 11 (0% of all arguments) with API objects: 529 (0% of all arguments) types and their number of usage: Container:529 numbers: 14563 (4%) ObjectRef: 169306 (54%) others: 19973 (6%) --- klog.go | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/klog.go b/klog.go index f8ee06e9..4cf0b5e5 100644 --- a/klog.go +++ b/klog.go @@ -835,7 +835,14 @@ func kvListFormat(b *bytes.Buffer, keysAndValues ...interface{}) { } b.WriteByte('=') + // The type checks are sorted so that more frequently used ones + // come first because that is then faster in the common + // cases. In Kubernetes, ObjectRef (a Stringer) is more common + // than plain strings + // (https://github.com/kubernetes/kubernetes/pull/106594#issuecomment-975526235). switch v := v.(type) { + case fmt.Stringer: + b.WriteString(strconv.Quote(v.String())) case string: b.WriteString(strconv.Quote(v)) case error: @@ -845,8 +852,6 @@ func kvListFormat(b *bytes.Buffer, keysAndValues ...interface{}) { // because it does not escape unicode characters, which is // expected by one test!? b.WriteString(fmt.Sprintf("%+q", v)) - case fmt.Stringer: - b.WriteString(strconv.Quote(v.String())) default: b.WriteString(fmt.Sprintf("%+v", v)) } From fafe98e1ea27f704efbd8ce38bfb9fcb9058a6ab Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Tue, 9 Nov 2021 14:37:53 +0100 Subject: [PATCH 5/5] structured logging: support key/value pairs with line breaks MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The initial structured logging output (almost) always produced a single line per log message, with quoting of strings to represent line breaks as \n. This made the output hard to read (see https://github.com/kubernetes/kubernetes/issues/104868). It was still possible to get line breaks when formatting a value with `%+v` and that ended up emitting line breaks; this was probably not intended. Now string values are only quoted if they contain no line break. If they do, start/end markers delimit the text which appears on its own lines, with indention to ensure that those additional lines are not accidentally treated as a new log message when they happen to contain the klog header. It also makes the output more readable. Tabs are used as indention for the value because it makes it stand out visually and because it ensures that inline ">" characters are not mistaken for the end-of-value delimiter. The result of `fmt.Sprintf("%+v")` is printed verbatim without quoting when it contains no line break, otherwise as multi-line value with delimiter and indention. Traditional output: I1112 14:06:35.783354 328441 structured_logging.go:42] someData printed using InfoF: {hello world 0} I1112 14:06:35.783472 328441 structured_logging.go:43] longData printed using InfoF: {long Multiple lines with quite a bit of text. 0} I1112 14:06:35.783483 328441 structured_logging.go:44] stringData printed using InfoF, with the message across multiple lines: long: Multiple lines with quite a bit of text. I1112 14:06:35.898176 142908 structured_logging.go:54] logData printed using InfoF: {log output from some program I0000 12:00:00.000000 123456 main.go:42] Starting E0000 12:00:01.000000 123456 main.go:43] Failed for some reason 0} Old InfoS output before this commit: I1112 14:06:35.783512 328441 structured_logging.go:50] "using InfoS" someData={Name:hello Data:world internal:0} I1112 14:06:35.783529 328441 structured_logging.go:51] "using InfoS" longData={Name:long Data:Multiple lines with quite a bit of text. internal:0} I1112 14:06:35.783549 328441 structured_logging.go:52] "using InfoS with\nthe message across multiple lines" int=1 stringData="long: Multiple\nlines\nwith quite a bit\nof text." str="another value" I1112 14:06:35.783565 328441 structured_logging.go:61] "Did something" item="foobar" I1112 14:06:35.783576 328441 structured_logging.go:63] "This is a full sentence." item="foobar" I1112 14:06:35.898278 142908 structured_logging.go:65] "using InfoS" logData={Name:log output from some program Data:I0000 12:00:00.000000 123456 main.go:42] Starting E0000 12:00:01.000000 123456 main.go:43] Failed for some reason internal:0} New InfoS output: I1126 10:31:50.378182 121736 structured_logging.go:58] "using InfoS" someData={Name:hello Data:world internal:0} I1126 10:31:50.378204 121736 structured_logging.go:59] "using InfoS" longData=< {Name:long Data:Multiple lines with quite a bit of text. internal:0} > I1126 10:31:50.378228 121736 structured_logging.go:60] "using InfoS with\nthe message across multiple lines" int=1 stringData=< long: Multiple lines with quite a bit of text. > str="another value" I1126 10:31:50.378249 121736 structured_logging.go:65] "using InfoS" logData=< {Name:log output from some program Data:I0000 12:00:00.000000 123456 main.go:42] Starting E0000 12:00:01.000000 123456 main.go:43] Failed for some reason internal:0} > Performance is the same as before in most cases. Handling of a v1.Container struct with line breaks in the output gets faster, probably because printing each line individually is more efficient than quoting. $ $GOPATH/bin/benchstat /tmp/reorder /tmp/multi-line name old time/op new time/op delta Logging/container/structured-36 39.6µs ± 1% 21.5µs ± 0% -45.82% (p=0.008 n=5+5) Logging/error-value/structured-36 3.14µs ± 4% 3.11µs ± 2% ~ (p=0.548 n=5+5) Logging/error/structured-36 3.13µs ± 3% 3.13µs ± 3% ~ (p=1.000 n=5+5) Logging/simple/structured-36 2.91µs ± 2% 2.87µs ± 2% ~ (p=0.310 n=5+5) Logging/values/structured-36 4.77µs ± 5% 4.75µs ± 4% ~ (p=1.000 n=5+5) name old alloc/op new alloc/op delta Logging/container/structured-36 9.35kB ± 0% 9.59kB ± 0% +2.59% (p=0.016 n=4+5) Logging/error-value/structured-36 312B ± 0% 312B ± 0% ~ (all equal) Logging/error/structured-36 312B ± 0% 312B ± 0% ~ (all equal) Logging/simple/structured-36 288B ± 0% 288B ± 0% ~ (all equal) Logging/values/structured-36 464B ± 0% 464B ± 0% ~ (all equal) name old allocs/op new allocs/op delta Logging/container/structured-36 62.0 ± 0% 63.0 ± 0% +1.61% (p=0.008 n=5+5) Logging/error-value/structured-36 6.00 ± 0% 6.00 ± 0% ~ (all equal) Logging/error/structured-36 6.00 ± 0% 6.00 ± 0% ~ (all equal) Logging/simple/structured-36 5.00 ± 0% 5.00 ± 0% ~ (all equal) Logging/values/structured-36 11.0 ± 0% 11.0 ± 0% ~ (all equal) --- klog.go | 83 +++++++++++++++++++++++++++++++++++++++++++++------- klog_test.go | 46 +++++++++++++++++++++++++++-- 2 files changed, 116 insertions(+), 13 deletions(-) diff --git a/klog.go b/klog.go index 4cf0b5e5..4d174e8e 100644 --- a/klog.go +++ b/klog.go @@ -803,10 +803,12 @@ func (l *loggingT) infoS(logger *logr.Logger, filter LogFilter, depth int, msg s func (l *loggingT) printS(err error, s severity, depth int, msg string, keysAndValues ...interface{}) { // Only create a new buffer if we don't have one cached. b := l.getBuffer() + // The message is always quoted, even if it contains line breaks. + // If developers want multi-line output, they should use a small, fixed + // message and put the multi-line output into a value. b.WriteString(strconv.Quote(msg)) if err != nil { - b.WriteString(" err=") - b.WriteString(strconv.Quote(err.Error())) + kvListFormat(&b.Buffer, "err", err) } kvListFormat(&b.Buffer, keysAndValues...) l.printDepth(s, logging.logr, nil, depth+1, &b.Buffer) @@ -826,6 +828,10 @@ func kvListFormat(b *bytes.Buffer, keysAndValues ...interface{}) { v = missingValue } b.WriteByte(' ') + // Keys are assumed to be well-formed according to + // https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/migration-to-structured-logging.md#name-arguments + // for the sake of performance. Keys with spaces, + // special characters, etc. will break parsing. if k, ok := k.(string); ok { // Avoid one allocation when the key is a string, which // normally it should be. @@ -833,7 +839,6 @@ func kvListFormat(b *bytes.Buffer, keysAndValues ...interface{}) { } else { b.WriteString(fmt.Sprintf("%s", k)) } - b.WriteByte('=') // The type checks are sorted so that more frequently used ones // come first because that is then faster in the common @@ -842,19 +847,77 @@ func kvListFormat(b *bytes.Buffer, keysAndValues ...interface{}) { // (https://github.com/kubernetes/kubernetes/pull/106594#issuecomment-975526235). switch v := v.(type) { case fmt.Stringer: - b.WriteString(strconv.Quote(v.String())) + writeStringValue(b, true, v.String()) case string: - b.WriteString(strconv.Quote(v)) + writeStringValue(b, true, v) case error: - b.WriteString(strconv.Quote(v.Error())) + writeStringValue(b, true, v.Error()) case []byte: - // We cannot use the simpler strconv.Quote here - // because it does not escape unicode characters, which is - // expected by one test!? + // In https://github.com/kubernetes/klog/pull/237 it was decided + // to format byte slices with "%+q". The advantages of that are: + // - readable output if the bytes happen to be printable + // - non-printable bytes get represented as unicode escape + // sequences (\uxxxx) + // + // The downsides are that we cannot use the faster + // strconv.Quote here and that multi-line output is not + // supported. If developers know that a byte array is + // printable and they want multi-line output, they can + // convert the value to string before logging it. + b.WriteByte('=') b.WriteString(fmt.Sprintf("%+q", v)) default: - b.WriteString(fmt.Sprintf("%+v", v)) + writeStringValue(b, false, fmt.Sprintf("%+v", v)) + } + } +} + +func writeStringValue(b *bytes.Buffer, quote bool, v string) { + data := []byte(v) + index := bytes.IndexByte(data, '\n') + if index == -1 { + b.WriteByte('=') + if quote { + // Simple string, quote quotation marks and non-printable characters. + b.WriteString(strconv.Quote(v)) + return } + // Non-string with no line breaks. + b.WriteString(v) + return + } + + // Complex multi-line string, show as-is with indention like this: + // I... "hello world" key=< + // line 1 + // line 2 + // > + // + // Tabs indent the lines of the value while the end of string delimiter + // is indented with a space. That has two purposes: + // - visual difference between the two for a human reader because indention + // will be different + // - no ambiguity when some value line starts with the end delimiter + // + // One downside is that the output cannot distinguish between strings that + // end with a line break and those that don't because the end delimiter + // will always be on the next line. + b.WriteString("=<\n") + for index != -1 { + b.WriteByte('\t') + b.Write(data[0 : index+1]) + data = data[index+1:] + index = bytes.IndexByte(data, '\n') + } + if len(data) == 0 { + // String ended with line break, don't add another. + b.WriteString(" >") + } else { + // No line break at end of last line, write rest of string and + // add one. + b.WriteByte('\t') + b.Write(data) + b.WriteString("\n >") } } diff --git a/klog_test.go b/klog_test.go index 9a44c6be..2f65ef89 100644 --- a/klog_test.go +++ b/klog_test.go @@ -943,6 +943,12 @@ func TestVInfoS(t *testing.T) { return time.Date(2006, 1, 2, 15, 4, 5, .067890e9, time.Local) } pid = 1234 + myData := struct { + Data string + }{ + Data: `This is some long text +with a line break.`, + } var testDataInfo = []struct { msg string format string @@ -963,6 +969,26 @@ func TestVInfoS(t *testing.T) { format: "I0102 15:04:05.067890 1234 klog_test.go:%d] \"test\" err=\"test error\"\n", keysValues: []interface{}{"err", errors.New("test error")}, }, + { + msg: `first message line +second message line`, + format: `I0102 15:04:05.067890 1234 klog_test.go:%d] "first message line\nsecond message line" multiLine=< + first value line + second value line + > +`, + keysValues: []interface{}{"multiLine", `first value line +second value line`}, + }, + { + msg: `message`, + format: `I0102 15:04:05.067890 1234 klog_test.go:%d] "message" myData=< + {Data:This is some long text + with a line break.} + > +`, + keysValues: []interface{}{"myData", myData}, + }, } logging.verbosity.Set("2") @@ -987,7 +1013,7 @@ func TestVInfoS(t *testing.T) { want = "" } if contents(infoLog) != want { - t.Errorf("V(%d).InfoS has unexpected output: \n got:\t%s\nwant:\t%s", l, contents(infoLog), want) + t.Errorf("V(%d).InfoS has unexpected output:\ngot:\n%s\nwant:\n%s\n", l, contents(infoLog), want) } } } @@ -1031,7 +1057,7 @@ func TestErrorS(t *testing.T) { } want := fmt.Sprintf(e.format, line) if contents(errorLog) != want { - t.Errorf("ErrorS has wrong format: \n got:\t%s\nwant:\t%s", contents(errorLog), want) + t.Errorf("ErrorS has wrong format:\ngot:\n%s\nwant:\n%s\n", contents(errorLog), want) } } } @@ -1075,6 +1101,20 @@ func TestKvListFormat(t *testing.T) { keysValues: []interface{}{"pod", "kubedns", "bytes", []byte("��=� ⌘")}, want: " pod=\"kubedns\" bytes=\"\\ufffd\\ufffd=\\ufffd \\u2318\"", }, + { + keysValues: []interface{}{"multiLineString", `Hello world! + Starts with tab. + Starts with spaces. +No whitespace.`, + "pod", "kubedns", + }, + want: ` multiLineString=< + Hello world! + Starts with tab. + Starts with spaces. + No whitespace. + > pod="kubedns"`, + }, { keysValues: []interface{}{"pod", "kubedns", "maps", map[string]int{"three": 4}}, want: " pod=\"kubedns\" maps=map[three:4]", @@ -1113,7 +1153,7 @@ func TestKvListFormat(t *testing.T) { b := &bytes.Buffer{} kvListFormat(b, d.keysValues...) if b.String() != d.want { - t.Errorf("kvlist format error:\n got:\n\t%s\nwant:\t%s", b.String(), d.want) + t.Errorf("kvlist format error:\ngot:\n%s\nwant:\n%s\n", b.String(), d.want) } } }