Skip to content

Commit

Permalink
structured logging: support log messages with line breaks
Browse files Browse the repository at this point in the history 
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
kubernetes/kubernetes#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 the message is never quoted, as in non-structured output. String values are
quoted if they contain no line break. If they do, start/end markers delimit the
text which appears on its own lines.

All additional lines of a structure log message get indented by one space. This
makes it obvious where a new log message starts, which is an improvement
compared to the traditional format.

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.

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"

New InfoS output:

 I1112 15:01:48.696617  413871 structured_logging.go:50] using InfoS: someData={Name:hello Data:world internal:0}
 I1112 15:01:48.696646  413871 structured_logging.go:51] using InfoS: ===start of longData===
  {Name:long Data:Multiple
  lines
  with quite a bit
  of text. internal:0}
  ===end of longData===
 I1112 15:01:48.696677  413871 structured_logging.go:52] using InfoS with
  the message across multiple lines: int=1 ===start of stringData===
  long: Multiple
  lines
  with quite a bit
  of text.
  ===end of stringData=== str="another value"
 I1112 15:01:48.696704  413871 structured_logging.go:61] Did something: item="foobar"
 I1112 15:01:48.696719  413871 structured_logging.go:63] This is a full sentence. item="foobar"
  • Loading branch information
@pohly
pohly committed Nov 12, 2021
1 parent 0fe7e2d commit 74672eb
Show file tree
Hide file tree
Showing 3 changed files with 114 additions and 37 deletions.
54 changes: 45 additions & 9 deletions klog.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -88,6 +88,7 @@ import (
"sync"
"sync/atomic"
"time"
"unicode"

"github.com/go-logr/logr"
)
Expand Down Expand Up @@ -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)
Expand All @@ -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
Expand Down
65 changes: 53 additions & 12 deletions klog_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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")},
},
}
Expand Down Expand Up @@ -943,26 +943,53 @@ 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
keysValues []interface{}
}{
{
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")
Expand All @@ -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)
}
}
}
Expand All @@ -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 {
Expand All @@ -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)
}
}
}
Expand Down Expand Up @@ -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]",
Expand Down Expand Up @@ -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)
}
}
}
Expand Down
32 changes: 16 additions & 16 deletions klogr/klogr_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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": {
Expand All @@ -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": {
Expand All @@ -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": {
Expand All @@ -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": {
Expand All @@ -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": {
Expand All @@ -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": {
Expand All @@ -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": {
Expand All @@ -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": {
Expand All @@ -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=<nil>
expectedKlogOutput: `test: akey="avalue" akey2=<nil>
`,
},
"should correctly html characters": {
Expand All @@ -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": {
Expand All @@ -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=<nil> akey="avalue" akey2=<nil>
expectedKlogOutput: `test: basekey1="basevar1" basekey2=<nil> akey="avalue" akey2=<nil>
`,
},
"should correctly print regular error types": {
Expand All @@ -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": {
Expand All @@ -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": {
Expand All @@ -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"
`,
},
}
Expand Down

0 comments on commit 74672eb

Please sign in to comment.