diff --git a/klog.go b/klog.go index 45efbb07..f855190b 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 9a44c6be..01e12490 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) } } }