-
Notifications
You must be signed in to change notification settings - Fork 35
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
level: Support multi-line log writes #7
Conversation
LevelFilter previously assumed that it would always receive writes one line at a time. Although that is the behavior of the "log" package itself, log output is sometimes delivered indirectly through other channels. For example, Terraform (and some other HashiCorp software) uses mitchellh/panicwrap to recognize crashes, which means that log lines are received indirectly through pipe from the panicwrap child process, which seems to introduce some additional line buffering. This appears to be the root cause of hashicorp/terraform#6468. Since removing panicwrap from Terraform would hurt its user experience, here we instead make LevelFilter a little more forgiving to accept multiple messages in a single write as long as messages are never split across multiple writes. This does not change the result for callers that are using the "log" package directly, and it makes the behavior a little more resilient to other intermediaries processing log output, as long as those intermediaries don't cause any atomic writes to be split into multiple parts before they reach the log writer.
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.
Yep this seems reasonable.
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.
Log message as accepted by the this and the standard logger often have multi-line message. In terraform for example, splitting and filtering on \n is going to let through a whole bunch of text graphs with no descriptions. Providers also heavily use multi-line output, though that is going through hclog, so it may already have every line prefixed. In order to filter core logs, I think we're going to have split only on \n[LEVEL]
where LEVEL
is only one of those specifically accepted by this logger.
Another issue I haven't dug into is that splitting like this is causing terraform to hang completely. I believe this is due to the read-write loops in prefixedio, but that is just a guess at this point.
(oops, didn't mean to delete mitchell's comment, moved mine and took his out with it)
Yikes, that's right. I forgot that's a thing (newlines in the log messages).
A fair point! And one I should've thought of, because a similar log aggregation doodad in a previous job suffered exactly the same fate. 🙄 I don't think prefix matching is going to cut it here because the messages emitted from some components have various other prefixes attached to them that would mess that up. I think I'm going to just close this out for now, and maybe for the time being we'll just remove |
LevelFilter
previously assumed that it would always receive writes one line at a time. Although that is the behavior of the"log"
package itself, log output is sometimes delivered indirectly through other channels. For example, Terraform (and some other HashiCorp software) usesmitchellh/panicwrap
to recognize crashes, which means that log lines are received indirectly through pipe from thepanicwrap
child process, which seems to introduce some additional buffering.This appears to be the root cause of hashicorp/terraform#6468. Since removing
panicwrap
from Terraform would hurt its user experience, here we instead makeLevelFilter
a little more forgiving to accept multiple messages in a single write as long as messages are never split acrossmultiple writes.
This does not change the results for callers that are using the
"log"
package directly, and it makes the behavior a little more resilient to other intermediaries processing log output, as long as those intermediaries don't cause any atomic writes to be split into multiple parts before they reach the log writer. That is true forpanicwrap
's pipes, allowing Terraform's log output to then be filtered correctly in spite ofpanicwrap
.