structured logging: support values with line breaks

[pohly]

What this PR does / why we need it:

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 string values are only quoted if they contain no line break. If they do,
start/end markers delimit the text which appears on its own lines, with
indention to ensure that those additional lines are not accidentally treated as
a new log message when they happen to contain the klog header. It also makes
the output more readable.

The result of fmt.Sprintf("%+v") is printed verbatim without quoting when it
contains no line break, otherwise as multi-line value with delimiter and
indention.

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.
 I1112 14:06:35.898176  142908 structured_logging.go:54] logData printed using InfoF:
 {log output from some program I0000 12:00:00.000000  123456 main.go:42] Starting
 E0000 12:00:01.000000  123456 main.go:43] Failed for some reason
  0}

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"
 I1112 14:06:35.898278  142908 structured_logging.go:65] "using InfoS" logData={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
  internal:0}

New InfoS output:

I1126 10:31:50.378182  121736 structured_logging.go:58] "using InfoS" someData={Name:hello Data:world internal:0}
I1126 10:31:50.378204  121736 structured_logging.go:59] "using InfoS" longData=<
	{Name:long Data:Multiple
	lines
	with quite a bit
	of text. internal:0}
 >
I1126 10:31:50.378228  121736 structured_logging.go:60] "using InfoS with\nthe message across multiple lines" int=1 stringData=<
	long: Multiple
	lines
	with quite a bit
	of text.
 > str="another value"
I1126 10:31:50.378249  121736 structured_logging.go:65] "using InfoS" logData=<
	{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
	 internal:0}
 >

Which issue(s) this PR fixes:

Fixes kubernetes/kubernetes#106262, kubernetes/kubernetes#106428

Special notes for your reviewer:
kubernetes/kubernetes#106262, kubernetes/kubernetes#106428
Compared to PR #268, the format changes in this PR are smaller: the main message is still printed as before (quoted string). Only special string values are formatted differently.

The PR also contains some performance improvements in the original implementation. The initial set of commits could be merged without the format change. See commit messages for benchmark results of each individual change.

Release note:

In structured output (= InfoS, ErrorS), values with line breaks will be printed across multiple lines to make the output more readable. Every new line gets indented by one space (more readable, splitting into individual messages can be done reliably). Performance was improved.

[serathius]

/lgtm
This looks great!

As this is a log format change I would like to make sure we reach consensus before merging.
/hold
/cc @dims @thockin
Please confirm that you are ok with this.

Also let's set some lazy consensus deadline for Wed 01.12

[pohly]

I'd like to propose another enhancement for the new format: when some multi-line string contains the <<< delimiter, parsers cannot distinguish between that and the one added when printing that string:

... someString>>>
 First Line
 <<<
 Last line
 <<< someInt=1

This can be solved by indenting the text with a tab and the delimiter with a single space:

... someString>>>
	First Line
	<<<
	Last line
 <<< someInt=1

The reason why I didn't implement that from the beginning is that I was worried about indenting too much and making it less readable when the lines then don't fit into a narrow console anymore.

Another alternative would be to use two spaces, at the cost of making the output slightly larger.

Thoughts?

[thockin]

I'm honestly not sure this is better. It feels very ad-hoc. Is there a semi-formal grammaar for how one should expect to parse such a long line?

[pohly]

Here's one:

<message> ::= <header>" "<quoted-string><values>"\n"
# zero or more values, separated by space from message or previous value
<values> ::= |" "<value>|" "<value><values>
# Finding the end of the value depends on how it starts (simple value on the same line or multi-line).
<value> ::= <key>("="<simple value>|">>>\n"<multi-line value>)
<simple value> ::= <number>|<quoted string>|<boolean>|<struct>|<map>|<list>
# A multi-line value ends on the first line with " <<<".
<multi-line value> ::= <lines>" <<<"
<lines> ::= |<line>|<line><lines>
# Any line starting with \t is part of the value.
<line> ::= "\t"<any non-\n character>"\n"

Note that struct, map and list are basically unparsable reliably when embedded inside a single line because the output of %+v does not escape strings when emitting them. That problem exists with or without this patch and I don't think we should try to address it. If someone wants reliable parsing with a well-defined format that covers all possible values, they should use JSON.

[pohly]

Here's an example for logstash/grok. To try it out, use https://grokdebug.herokuapp.com/ and enter

• text:

"hello world" someString="with \"quotation marks\"" anotherString>>>
	First Line
	<<<
	Last line
 <<< someInt=1

• pattern:

%{QUOTEDSTRING:message} someString=%{QUOTEDSTRING:someString} anotherString>>>\n%{MULTILINE:anotherString} <<< someInt=%{INT:someInt}

• click "Add custom patterns" and define MULTILINE there:

MULTILINE (\t.*\n)*

Post-processing is required in logstash to remove quoting in QUOTEDSTRING and the leading tab in MULTILINE.

[pohly]

A simpler grok pattern would just match for the header at the start of a line and then greedily match the entire rest of the message. That would be similar to the existing fluentd example in k/k.

With this PR, such an approach works reliably. Without it, it doesn't.

[pohly]

@serathius I pushed another commit with the tab character for indention. Can you take another look?

[pohly]

@thockin: please also take another look. See the comments above about approaches for parsing the revised format.

[thockin]

Is this >>><<< format something you made up or is it some standard I don't know?

I'm mostly concerned that we don't make up syntax on the fly (which, IME, always ends in tears).

[thockin]

This doesn't seem correct - should we fix it?

[pohly]

According to the PR which introduced the corresponding test case, %+q was intentionally used to handle non-printable characters: #237 (comment)

[thockin]

I kind of disagree with that PR - if you pass a []byte, there's NOTHING that requires it be a printable string. If you want a string, convert it to a string. Funcr does not do that, for example.

Aside from that - do we make assertions that our log output will always be ASCII? We do not do this format checking for keys

[pohly]

I don't have any background about why it was decided to handle bytes that way. But because I don't know, I also don't want to change established behavior in this PR.

@serathius, @dims: do you remember?

[pohly]

Is this >>><<< format something you made up or is it some standard I don't know?

I made it up after trying out some other alternatives, including delimiters like vvvv <key> vvvv + ^^^ <key> ^^^^ and key=vvv start of string vvv + ^^^^^^ - see #268 where we originally discussed this.

I'm mostly concerned that we don't make up syntax on the fly (which, IME, always ends in tears).

I don't mind using some established convention, but it has to fit into the key/value pair flow and shouldn't be too verbose because log volume is still a concern. Analysis of a kubelet log showed that messages with line breaks were rare, but perhaps they are more common elsewhere.

[thockin]

I don't mind using some established convention, but it has to fit into the key/value pair flow and shouldn't be too verbose because log volume is still a concern. Analysis of a kubelet log showed that messages with line breaks were rare, but perhaps they are more common elsewhere.

I don't have a particular convention in mind (other than not doing multi-line
at all, which is my preference and please don't ever send a PR to make funcr do
this :)

I recognize that it's already effectively unparseable today, so we're not
making it much worse. But it's not really much better.

This form adds a trailing newline to multi-line strings which don't have one,
which is kind of a corruption. That's one concern I have, but maybe it is
overlookable.

Looking at it from first-principles, the "right" way to do this is to define an
escape, process the (arbitrary) content for that escape, and then render.
E.g. key=<A string with multi-line capabilities but \> close bracket needs escape.
This is non-standard and slow. If you don't do it, though, the string could
contain the special-string terminator and confuse parsers. So you chose >>>
and <<< since Go's %+v doesn't use it and they are less likely to occur
naturally (interesting you put them in the non-natural (to me) directions).

But you actually defined your own own escape - the leading character of the
line. In theory, you could simply use < and > since you know the
end-of-string indicator ( >) can only be found at the 0th character on a new
line. But to ensure that, you need to corrupt that trailing newline.

What if you ALWAYS add a trailing newline? Sometimes you would end up with
blank lines but at least it would be parseable.

E.g. consider input values A="foo\bar" and B="qux\nzorb\n"

Your log output could look like:

<header...> A=<foo
  <tab>  bar
 > B=<qux
  <tab>  zorb

 >

Note I retained the '=' for human's sake, and I used < and > since Go's %+v
doesn't use them (I think?). You could use << >> or ( ) or (( )) if you
prefer, or keep >>> <<<. It doesn't matter. I like the = personally - it
makes the key=value notion regular.

You could make it maybe even easier by always adding a leading newline:

<header...> A=<
  <tab>  foo
  <tab>  bar
 > B=<
  <tab>  qux
  <tab>  zorb

 >

That's easier to read by far and still unambiguous, I think. Any line that
starts with a tab is part of a multi-line, and any line that starts with a
space is a "continue" line. Just make sure that it's not possible to trip that
up with ill-formed keys or logger names or (heaven help me) file names that
start with spaces (play stupid games, win stupid prizes?).

Now, I'll restate my preference: don't even open this can of worms :) But if
we're going to do it in non-JSON output mode, at least we can say we really
thought it out, and show our work.

[thockin]

I kind of disagree with that PR - if you pass a []byte, there's NOTHING that requires it be a printable string. If you want a string, convert it to a string. Funcr does not do that, for example.

Aside from that - do we make assertions that our log output will always be ASCII? We do not do this format checking for keys

[pohly]

Before I comment, let me point out that we discussed the purpose of this text format in last weeks structured logging working group meeting and the conclusion was captured by @serathius in kubernetes/community#6255.

The key part for this PR is that the purpose of the text format is:

• Maintain backward compatibility with klog format.
• Human-readable, multiline support.

Note that machine-parsing is not a goal. JSON does that so much better (faster, well-defined), it really should be used if that is how log output will be used.

Avoiding ambiguity in the output and thus making it somewhat machine-parsable is a nice additional benefit, but comes second after human-readable. That's why always using quoted strings is bad.

[pohly]

don't ever send a PR to make funcr do this :)

I won't, because funcr serves a different purpose. It's goal is machine-parsing, while this format here is for humans.

I recognize that it's already effectively unparseable today, so we're not
making it much worse. But it's not really much better.

It's better for humans 😁

This form adds a trailing newline to multi-line strings which don't have one,
which is kind of a corruption. That's one concern I have, but maybe it is
overlookable.

I was aware of that downside and should have mentioned it. There are test cases for both. I now also added that to the code comments.

Looking at it from first-principles, the "right" way to do this is to define an
escape, process the (arbitrary) content for that escape, and then render.
E.g. key=<A string with multi-line capabilities but > close bracket needs escape.
This is non-standard and slow. If you don't do it, though, the string could
contain the special-string terminator and confuse parsers. So you chose >>>
and <<< since Go's %+v doesn't use it and they are less likely to occur
naturally (interesting you put them in the non-natural (to me) directions).

The main reason why I chose indention over escaping is that we want compatibility with the traditional format. That format hasn't been formally specified, but what people do in practice is to break at those lines that start with the special klog header. If I wanted to avoid indention, I would have to escape that header.

I chose >>> because it looked nice. Direction is probably subjective. To me it conveys "here's the text", i.e. it points towards the following text. But I agree that other interpretations are also possible, and I see that <key> as a notation makes <<< a more natural choice. Both works for me.

But you actually defined your own own escape - the leading character of the
line. In theory, you could simply use < and > since you know the
end-of-string indicator ( >) can only be found at the 0th character on a new
line. But to ensure that, you need to corrupt that trailing newline.

See above. Any line emitted without a leading whitespace is a risk for confusing existing parsers which don't know about this new format.

What if you ALWAYS add a trailing newline? Sometimes you would end up with
blank lines but at least it would be parseable.

I decided against that because it prioritizes accuracy over readability. I'm also not sure whether developers seeing such a blank line would understand that it's not a bug, but rather a feature.

E.g. consider input values A="foo\bar" and B="qux\nzorb\n"

Your log output could look like:

<header...> A=<foo
  <tab>  bar
 > B=<qux
 <tab>  zorb

I don't have a problem with using =< as start and > as end delimiter.

One small advantage of a longer delimiter is that it is easier to fast-forward by searching for >>>. Searching for just > might work less well, one has to remember to search for the regex ^ >.

You could make it maybe even easier by always adding a leading newline:

I had already written a comment about that when I got to this part 😁 Yes, let's keep this additional newline.

That's easier to read by far and still unambiguous, I think. Any line that
starts with a tab is part of a multi-line, and any line that starts with a
space is a "continue" line.

Exactly.

Just make sure that it's not possible to trip that
up with ill-formed keys or logger names or (heaven help me) file names that
start with spaces (play stupid games, win stupid prizes?).

Now, I'll restate my preference: don't even open this can of worms :)

Me neither. If developers want to shoot themselves in the foot, we should let them.

But if we're going to do it in non-JSON output mode, at least we can say we really
thought it out, and show our work.

So do we agree that we only need to settle on the exact delimiters and otherwise the PR is okay (with some comment updates)?

Let's give @serathius and @shivanshu1333 some time to comment, then I'll switch to =< and > if I don't hear otherwise.

[thockin]

I like the = simply because we can say it's always key=value.

Whether =< ... > or =<<< ... >>> or =>>> ... <<< or other, I don't much care.

I had already written a comment about that when I got to this part grin Yes, let's keep this additional newline.

I think it helps reading a lot. Will take another look at the PR

[thockin]

Let me know when to look again, if you do add comments, change the delimiters, and/or add the leading newline

[thockin]

so my only issues are:

1. to add "=" or not
2. delimiters

[pohly]

My preference is =< with newline at the start and > at the end.

[pohly]

@serathius : I've switched to =< + '>' and squashed commits into reasonable chunks. Okay to merge?

[serathius]

LGTM, @thockin any remaining comments?

[thockin]

/lgtm

[k8s-ci-robot]

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: pohly, serathius, thockin

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

• OWNERS [serathius,thockin]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

[pohly]

/hold cancel

[shiva1333]

@pohly thanks for all the changes, the output looks much better now!
nit: Let's update the PR description as well with new output

[pohly]

nit: Let's update the PR description as well with new output

Done.