diff --git a/klog.go b/klog.go index 45efbb075..f855190bf 100644 --- a/klog.go +++ b/klog.go @@ -88,6 +88,7 @@ import ( "sync" "sync/atomic" "time" + "unicode" "github.com/go-logr/logr" ) @@ -802,10 +803,16 @@ func (l *loggingT) infoS(logger *logr.Logger, filter LogFilter, depth int, msg s // set log severity by s func (l *loggingT) printS(err error, s severity, depth int, msg string, keysAndValues ...interface{}) { b := &bytes.Buffer{} - b.WriteString(fmt.Sprintf("%q", msg)) + // The message is never quoted. New lines get indented. + writeString(b, msg) + // Enhance readability by inserting : between message and key/value + // pairs, but only when the message does not already end with + // punctation. + if len(msg) > 0 && !unicode.IsPunct(rune(msg[len(msg)-1])) { + b.WriteString(":") + } if err != nil { - b.WriteByte(' ') - b.WriteString(fmt.Sprintf("err=%q", err.Error())) + kvListFormat(b, "err", err) } kvListFormat(b, keysAndValues...) l.printDepth(s, logging.logr, nil, depth+1, b) @@ -824,21 +831,50 @@ func kvListFormat(b *bytes.Buffer, keysAndValues ...interface{}) { } b.WriteByte(' ') - switch v.(type) { - case string, error: - b.WriteString(fmt.Sprintf("%s=%q", k, v)) + switch v := v.(type) { + case string: + writeStringValue(b, k, true, v) + case error: + writeStringValue(b, k, true, v.Error()) case []byte: b.WriteString(fmt.Sprintf("%s=%+q", k, v)) default: - if _, ok := v.(fmt.Stringer); ok { - b.WriteString(fmt.Sprintf("%s=%q", k, v)) + if s, ok := v.(fmt.Stringer); ok { + writeStringValue(b, k, true, s.String()) } else { - b.WriteString(fmt.Sprintf("%s=%+v", k, v)) + writeStringValue(b, k, false, fmt.Sprintf("%+v", v)) } } } } +func writeStringValue(b *bytes.Buffer, k interface{}, quoteV bool, v string) { + if !strings.Contains(v, "\n") { + b.WriteString(fmt.Sprintf("%s=", k)) + if quoteV { + // 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. + b.WriteString(fmt.Sprintf("===start of %s===\n ", k)) + writeString(b, v) + b.WriteString(fmt.Sprintf("\n ===end of %s===", k)) +} + +func writeString(b *bytes.Buffer, s string) { + for i, line := range strings.Split(s, "\n") { + if i > 0 { + b.WriteString("\n ") + } + b.WriteString(line) + } +} + // redirectBuffer is used to set an alternate destination for the logs type redirectBuffer struct { w io.Writer diff --git a/klog_test.go b/klog_test.go index 9a44c6be3..01e12490b 100644 --- a/klog_test.go +++ b/klog_test.go @@ -894,22 +894,22 @@ func TestInfoS(t *testing.T) { }{ { msg: "test", - format: "I0102 15:04:05.067890 1234 klog_test.go:%d] \"test\" pod=\"kubedns\"\n", + format: "I0102 15:04:05.067890 1234 klog_test.go:%d] test: pod=\"kubedns\"\n", keysValues: []interface{}{"pod", "kubedns"}, }, { msg: "test", - format: "I0102 15:04:05.067890 1234 klog_test.go:%d] \"test\" replicaNum=20\n", + format: "I0102 15:04:05.067890 1234 klog_test.go:%d] test: replicaNum=20\n", keysValues: []interface{}{"replicaNum", 20}, }, { msg: "test", - format: "I0102 15:04:05.067890 1234 klog_test.go:%d] \"test\" err=\"test error\"\n", + format: "I0102 15:04:05.067890 1234 klog_test.go:%d] test: err=\"test error\"\n", keysValues: []interface{}{"err", errors.New("test error")}, }, { msg: "test", - format: "I0102 15:04:05.067890 1234 klog_test.go:%d] \"test\" err=\"test error\"\n", + format: "I0102 15:04:05.067890 1234 klog_test.go:%d] test: err=\"test error\"\n", keysValues: []interface{}{"err", errors.New("test error")}, }, } @@ -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 @@ -950,19 +956,40 @@ func TestVInfoS(t *testing.T) { }{ { msg: "test", - format: "I0102 15:04:05.067890 1234 klog_test.go:%d] \"test\" pod=\"kubedns\"\n", + format: "I0102 15:04:05.067890 1234 klog_test.go:%d] test: pod=\"kubedns\"\n", keysValues: []interface{}{"pod", "kubedns"}, }, { msg: "test", - format: "I0102 15:04:05.067890 1234 klog_test.go:%d] \"test\" replicaNum=20\n", + format: "I0102 15:04:05.067890 1234 klog_test.go:%d] test: replicaNum=20\n", keysValues: []interface{}{"replicaNum", 20}, }, { msg: "test", - format: "I0102 15:04:05.067890 1234 klog_test.go:%d] \"test\" err=\"test error\"\n", + 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 + second message line: ===start of multiLine=== + first value line + second value line + ===end of multiLine=== +`, + keysValues: []interface{}{"multiLine", `first value line +second value line`}, + }, + { + msg: `message`, + format: `I0102 15:04:05.067890 1234 klog_test.go:%d] message: ===start of myData=== + {Data:This is some long text + with a line break.} + ===end of myData=== +`, + keysValues: []interface{}{"myData", myData}, + }, } logging.verbosity.Set("2") @@ -987,7 +1014,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) } } } @@ -1014,11 +1041,11 @@ func TestErrorS(t *testing.T) { }{ { err: fmt.Errorf("update status failed"), - format: "E0102 15:04:05.067890 1234 klog_test.go:%d] \"Failed to update pod status\" err=\"update status failed\" pod=\"kubedns\"\n", + format: "E0102 15:04:05.067890 1234 klog_test.go:%d] Failed to update pod status: err=\"update status failed\" pod=\"kubedns\"\n", }, { err: nil, - format: "E0102 15:04:05.067890 1234 klog_test.go:%d] \"Failed to update pod status\" pod=\"kubedns\"\n", + format: "E0102 15:04:05.067890 1234 klog_test.go:%d] Failed to update pod status: pod=\"kubedns\"\n", }, } for _, e := range errorList { @@ -1031,7 +1058,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 +1102,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: ` ===start of multiLineString=== + Hello world! + Starts with tab. + Starts with spaces. + No whitespace. + ===end of multiLineString=== pod="kubedns"`, + }, { keysValues: []interface{}{"pod", "kubedns", "maps", map[string]int{"three": 4}}, want: " pod=\"kubedns\" maps=map[three:4]", @@ -1113,7 +1154,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) } } } diff --git a/klogr/klogr_test.go b/klogr/klogr_test.go index 7775b436e..a4b09f433 100644 --- a/klogr/klogr_test.go +++ b/klogr/klogr_test.go @@ -43,7 +43,7 @@ func testOutput(t *testing.T, format string) { keysAndValues: []interface{}{"akey", "avalue"}, expectedOutput: ` "msg"="test" "akey"="avalue" `, - expectedKlogOutput: `"test" akey="avalue" + expectedKlogOutput: `test: akey="avalue" `, }, "should log with name and values passed to keysAndValues": { @@ -52,7 +52,7 @@ func testOutput(t *testing.T, format string) { keysAndValues: []interface{}{"akey", "avalue"}, expectedOutput: `me "msg"="test" "akey"="avalue" `, - expectedKlogOutput: `"me: test" akey="avalue" + expectedKlogOutput: `me: test: akey="avalue" `, }, "should log with multiple names and values passed to keysAndValues": { @@ -61,7 +61,7 @@ func testOutput(t *testing.T, format string) { keysAndValues: []interface{}{"akey", "avalue"}, expectedOutput: `hello/world "msg"="test" "akey"="avalue" `, - expectedKlogOutput: `"hello/world: test" akey="avalue" + expectedKlogOutput: `hello/world: test: akey="avalue" `, }, "should not print duplicate keys with the same value": { @@ -70,7 +70,7 @@ func testOutput(t *testing.T, format string) { keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue"}, expectedOutput: ` "msg"="test" "akey"="avalue" `, - expectedKlogOutput: `"test" akey="avalue" + expectedKlogOutput: `test: akey="avalue" `, }, "should only print the last duplicate key when the values are passed to Info": { @@ -79,7 +79,7 @@ func testOutput(t *testing.T, format string) { keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue2"}, expectedOutput: ` "msg"="test" "akey"="avalue2" `, - expectedKlogOutput: `"test" akey="avalue2" + expectedKlogOutput: `test: akey="avalue2" `, }, "should only print the duplicate key that is passed to Info if one was passed to the logger": { @@ -88,7 +88,7 @@ func testOutput(t *testing.T, format string) { keysAndValues: []interface{}{"akey", "avalue"}, expectedOutput: ` "msg"="test" "akey"="avalue" `, - expectedKlogOutput: `"test" akey="avalue" + expectedKlogOutput: `test: akey="avalue" `, }, "should sort within logger and parameter key/value pairs in the default format and dump the logger pairs first": { @@ -97,7 +97,7 @@ func testOutput(t *testing.T, format string) { keysAndValues: []interface{}{"akey5", "avalue5", "akey4", "avalue4"}, expectedOutput: ` "msg"="test" "akey1"="avalue1" "akey8"="avalue8" "akey9"="avalue9" "akey4"="avalue4" "akey5"="avalue5" `, - expectedKlogOutput: `"test" akey9="avalue9" akey8="avalue8" akey1="avalue1" akey5="avalue5" akey4="avalue4" + expectedKlogOutput: `test: akey9="avalue9" akey8="avalue8" akey1="avalue1" akey5="avalue5" akey4="avalue4" `, }, "should only print the key passed to Info when one is already set on the logger": { @@ -106,7 +106,7 @@ func testOutput(t *testing.T, format string) { keysAndValues: []interface{}{"akey", "avalue2"}, expectedOutput: ` "msg"="test" "akey"="avalue2" `, - expectedKlogOutput: `"test" akey="avalue2" + expectedKlogOutput: `test: akey="avalue2" `, }, "should correctly handle odd-numbers of KVs": { @@ -115,7 +115,7 @@ func testOutput(t *testing.T, format string) { keysAndValues: []interface{}{"akey", "avalue", "akey2"}, expectedOutput: ` "msg"="test" "akey"="avalue" "akey2"=null `, - expectedKlogOutput: `"test" akey="avalue" akey2= + expectedKlogOutput: `test: akey="avalue" akey2= `, }, "should correctly html characters": { @@ -124,7 +124,7 @@ func testOutput(t *testing.T, format string) { keysAndValues: []interface{}{"akey", "<&>"}, expectedOutput: ` "msg"="test" "akey"="<&>" `, - expectedKlogOutput: `"test" akey="<&>" + expectedKlogOutput: `test: akey="<&>" `, }, "should correctly handle odd-numbers of KVs in both log values and Info args": { @@ -133,7 +133,7 @@ func testOutput(t *testing.T, format string) { keysAndValues: []interface{}{"akey", "avalue", "akey2"}, expectedOutput: ` "msg"="test" "basekey1"="basevar1" "basekey2"=null "akey"="avalue" "akey2"=null `, - expectedKlogOutput: `"test" basekey1="basevar1" basekey2= akey="avalue" akey2= + expectedKlogOutput: `test: basekey1="basevar1" basekey2= akey="avalue" akey2= `, }, "should correctly print regular error types": { @@ -142,7 +142,7 @@ func testOutput(t *testing.T, format string) { keysAndValues: []interface{}{"err", errors.New("whoops")}, expectedOutput: ` "msg"="test" "err"="whoops" `, - expectedKlogOutput: `"test" err="whoops" + expectedKlogOutput: `test: err="whoops" `, }, "should use MarshalJSON in the default format if an error type implements it": { @@ -151,7 +151,7 @@ func testOutput(t *testing.T, format string) { keysAndValues: []interface{}{"err", &customErrorJSON{"whoops"}}, expectedOutput: ` "msg"="test" "err"="WHOOPS" `, - expectedKlogOutput: `"test" err="whoops" + expectedKlogOutput: `test: err="whoops" `, }, "should correctly print regular error types when using logr.Error": { @@ -163,9 +163,9 @@ func testOutput(t *testing.T, format string) { "msg"="test" "error"="whoops" "msg"="test" "error"="whoops" `, - expectedKlogOutput: `"test" err="whoops" -"test" err="whoops" -"test" err="whoops" + expectedKlogOutput: `test: err="whoops" +test: err="whoops" +test: err="whoops" `, }, }