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