structured logging: support log messages with line breaks #268
There are no files selected for viewing
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -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") | ||
| } |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -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{} | ||
| // 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])) && (err != nil || len(keysAndValues) > 0) { | ||
| b.WriteString(" |") | ||
| } | ||
| if err != nil { | ||
| 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 := 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 s, ok := v.(fmt.Stringer); ok { | ||
| writeStringValue(b, k, true, s.String()) | ||
| } else { | ||
| 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. | ||
|
There was a problem hiding this comment. I don't see any benefit of adding built in markers for logs. They
K8s logs already have multi line logs that provide their own markers, thus I think we should leave it up user to provide There was a problem hiding this comment. I think there's a misunderstanding. The markers are not delimiters for messages. They are delimiters for values. With the current InfoS format, the quotation marks provides those delimiters. But they result in output that is basically unreadable for a human, which defeats the purpose of the text output. There was a problem hiding this comment.
That's a valid point. We could make them shorter. For example: That's four bytes ( Line breaks are the same with new line plus space instead of If the text contains many quotation marks, this format might actually be shorter because those don't need to be escaped. |
||
| b.WriteString(fmt.Sprintf("%s>>>\n ", k)) | ||
| writeString(b, v) | ||
| b.WriteString("\n <<<") | ||
| } | ||
|
|
||
| func writeString(b *bytes.Buffer, s string) { | ||
| for i, line := range strings.Split(s, "\n") { | ||
|
There was a problem hiding this comment. Does strings.Split here needlessly copies the string into slices? There was a problem hiding this comment. Yes. I'll add benchmarking and make the code more efficient before merging. Right now I am only looking for feedback on the format. /hold There was a problem hiding this comment. #273 has detailed benchmark data. |
||
| 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 | ||
|
|
||
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Oops, something went wrong.
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I don't agree with this change, we decided on quoting the string as this gives us predictable and somewhat parsable output (not everyone will imminently switch to JSON). Idea of quoting was related to message being treated as structured metadata. This is based on idea that JSON uses "msg" key to store message, so we though that message should be written as other string values with one difference of
msg=being skipped.There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This PR or the line you commented on, the
:separator? I can drop that separator, it's not important.But quoting is a major problem. I get what was meant to be achieved with it, but IMHO the effect on readability was not considered. it now prevents conversion to structured logging because developers will complain or even go as far as filing bugs and reverting the conversion.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I agree with Marek, JSON should not become a dependency for log parsing, the raw log output should be parsable
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
The current text format is not machine-readable. If that was the goal, then we have bugs in its implementation around handling of structs.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
So as you are both against this proposal, how do you suggest we should deal with cases where developers want multi-line output in a readable format (kubernetes/kubernetes#104868)?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I think we should separate how we consider multi line for different part of logs. In my opinion multiline:
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Agreed.
And how to you propose to do that?
We need an API for it and a serialization format that log parsers then will understand.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I can buy that argument. So let me propose a solution just for multi-line values in #273
I'm going to close this PR here in favor of that one.
/close