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.
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 |
LevelFilterpreviously 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/panicwrapto recognize crashes, which means that log lines are received indirectly through pipe from thepanicwrapchild process, which seems to introduce some additional buffering.This appears to be the root cause of hashicorp/terraform#6468. Since removing
panicwrapfrom Terraform would hurt its user experience, here we instead makeLevelFiltera 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.