structured logging: support values with line breaks

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 => ../

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=

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

klog.go

@@ -801,14 +801,19 @@ 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{}
-	b.WriteString(fmt.Sprintf("%q", msg))
+	// 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.WriteByte(' ')
-		b.WriteString(fmt.Sprintf("err=%q", err.Error()))
+		kvListFormat(&b.Buffer, "err", err)
 	}
-	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)"
@@ -823,22 +828,99 @@ 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.
+			b.WriteString(k)
+		} else {
+			b.WriteString(fmt.Sprintf("%s", k))
+		}
 
-		switch v.(type) {
-		case string, error:
-			b.WriteString(fmt.Sprintf("%s=%q", k, v))
+		// 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:
+			writeStringValue(b, true, v.String())
+		case string:
+			writeStringValue(b, true, v)
+		case error:
+			writeStringValue(b, true, v.Error())
 		case []byte:
-			b.WriteString(fmt.Sprintf("%s=%+q", k, v))
+			// 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:
-			if _, ok := v.(fmt.Stringer); ok {
-				b.WriteString(fmt.Sprintf("%s=%q", k, v))
-			} else {
-				b.WriteString(fmt.Sprintf("%s=%+v", k, 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=<
+	// <tab>line 1
+	// <tab>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 >")
+	}
+}
+
 // redirectBuffer is used to set an alternate destination for the logs
 type redirectBuffer struct {
 	w io.Writer

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