diff --git a/examples/go.mod b/examples/go.mod index c348862d..2768f2c1 100644 --- a/examples/go.mod +++ b/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 => ../ diff --git a/examples/go.sum b/examples/go.sum index d00155c9..4d41cc90 100644 --- a/examples/go.sum +++ b/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= diff --git a/examples/structured_logging/structured_logging.go b/examples/structured_logging/structured_logging.go new file mode 100644 index 00000000..6e80bd93 --- /dev/null +++ b/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") +} diff --git a/klog.go b/klog.go index 45efbb07..4d174e8e 100644 --- a/klog.go +++ b/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=< + // 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 >") + } +} + // 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..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) } } }