logtree: capture multiple lines in leveled log entries
This implements a solution to a disputed answer to the following
question:
“What happens when someone calls Infof("foo\nbar")?”
Multiple answers immediately present themselves:
a) Don't do anything, whatever consumers logs needs to expect that
they might contain newlines.
b) Yell/error/panic so that the programmer doesn't do this.
c) Split the one Info call into multiple Info calls, one per line,
somewhere in the logging path.
Following the argumentation for these we establish the follwoing
requirments for any solution:
1) We want the programmer to be able to log multiple lines from a
single Info call and have that not fail. This is especially
important for reliability - we don't want an accidental codepath
that suddenly starts printing %s-formatted user-controlled
messages to start erroring out in production. This rules out b).
2) We want to allow emitting multiple lines that will not be
interleaved when viewing the log data. This rules out c).
3) We want to prohibit log injection by malicious \n-containing
payloads (in case of %s-formatted user-controlled content). This
rules out a).
4) If multiple lines are allowed in a leveled payload, the type
system should support that, so that log consumers/tools will not
forget to account for the possible newlines. This too rules out
a).
With these in mind, we instead opt for a different solutions: changing
the API of logtree and logging protos to contain multiple possible lines
per single log entry. This is a breaking change, but since all access to
logs is currently self-contained within the Monogon OS codebase, we can
afford this.
To support this change, we change the access API (at LogEntry and
LeveledPayload level) to contain two different methods for retrieving
the canonical representation of an entry:
fn String() string
which returns a string with possible intra-string newlines (but no
trailing newlines), but with each newline-delimited chunk having the
canonical text representation prefix for this message. This prevents
newline injection into logs creating fake prefixes.
fn Strings() (prefix string, lines []string)
which returns a common prefix for this entry (in its text
representation) and a set of lines that were contained in the original
log entry. This allows slightly smarter consuming code to make more
active decisions regarding the rendering of a multi-line entry, while
still providing a canonical text formatted representation of that log
entry.
These permit simple log access code that prints log data into a terminal
(or terminal-like view), like dbg, to continue using the String() call.
In fact, no changes had to be made to dbg for it to continue working,
even though the API underneath changed.
Naturally, raw logging entries continue to contain only a single line,
so no change is implemented in the LineBuffer API. The containing
LogEntry for raw log entries emits single-lined Strings() results and no
newline-containing strings in String() results.
Test Plan: Updated unit tests to cover this.
X-Origin-Diff: phab/D650
GitOrigin-RevId: 4e339a930c4cbefff91b289b07bc31f774745eca
diff --git a/core/pkg/logtree/payload.go b/core/pkg/logtree/payload.go
index ca7a0a0..6338118 100644
--- a/core/pkg/logtree/payload.go
+++ b/core/pkg/logtree/payload.go
@@ -25,11 +25,13 @@
apb "git.monogon.dev/source/nexantic.git/core/proto/api"
)
-// LeveledPayload is a log entry for leveled logs (as per leveled.go). It contains not only the log message itself and
-// its severity, but also additional metadata that would be usually seen in a text representation of a leveled log entry.
+// LeveledPayload is a log entry for leveled logs (as per leveled.go). It contains the input to these calls (severity and
+// message split into newline-delimited messages) and additional metadata that would be usually seen in a text
+// representation of a leveled log entry.
type LeveledPayload struct {
- // message is the log message, rendered from a leveled log call like Infof(), Warningf(), ...
- message string
+ // messages is the list of messages contained in this payload. This list is built from splitting up the given message
+ // from the user by newline.
+ messages []string
// timestamp is the time at which this message was emitted.
timestamp time.Time
// severity is the leveled Severity at which this message was emitted.
@@ -40,22 +42,60 @@
line int
}
+// String returns a canonical representation of this payload as a single string prefixed with metadata. If the original
+// message was logged with newlines, this representation will also contain newlines, with each original message part
+// prefixed by the metadata.
+// For an alternative call that will instead return a canonical prefix and a list of lines in the message, see Strings().
func (p *LeveledPayload) String() string {
- // Same format as in glog:
- // Lmmdd hh:mm:ss.uuuuuu threadid file:line]
- // Except, threadid is (currently) always zero. In the future this field might be used for something different.
+ prefix, lines := p.Strings()
+ res := make([]string, len(p.messages))
+ for i, line := range lines {
+ res[i] = fmt.Sprintf("%s%s", prefix, line)
+ }
+ return strings.Join(res, "\n")
+}
+// Strings returns the canonical representation of this payload split into a prefix and all lines that were contained in
+// the original message. This is meant to be displayed to the user by showing the prefix before each line, concatenated
+// together - possibly in a table form with the prefixes all unified with a rowspan-like mechanism.
+//
+// For example, this function can return:
+// prefix = "I1102 17:20:06.921395 foo.go:42] "
+// lines = []string{"current tags:", " - one", " - two"}
+//
+// With this data, the result should be presented to users this way in text form:
+// I1102 17:20:06.921395 foo.go:42] current tags:
+// I1102 17:20:06.921395 foo.go:42] - one
+// I1102 17:20:06.921395 foo.go:42] - two
+//
+// Or, in a table layout:
+// .-----------------------------------------------------------.
+// | I1102 17:20:06.921395 0 foo.go:42] : current tags: |
+// | :------------------|
+// | : - one |
+// | :------------------|
+// | : - two |
+// '-----------------------------------------------------------'
+//
+func (p *LeveledPayload) Strings() (prefix string, lines []string) {
_, month, day := p.timestamp.Date()
hour, minute, second := p.timestamp.Clock()
nsec := p.timestamp.Nanosecond() / 1000
+ // Same format as in glog, but without treadid.
+ // Lmmdd hh:mm:ss.uuuuuu file:line]
// TODO(q3k): rewrite this to printf-less code.
- return fmt.Sprintf("%s%02d%02d %02d:%02d:%02d.%06d % 7d %s:%d] %s", p.severity, month, day, hour, minute, second,
- nsec, 0, p.file, p.line, p.message)
+ prefix = fmt.Sprintf("%s%02d%02d %02d:%02d:%02d.%06d %s:%d] ", p.severity, month, day, hour, minute, second, nsec, p.file, p.line)
+
+ lines = p.messages
+ return
}
-// Message returns the inner message of this entry, ie. what was passed to the actual logging method.
-func (p *LeveledPayload) Message() string { return p.message }
+// Message returns the inner message lines of this entry, ie. what was passed to the actual logging method, but split by
+// newlines.
+func (p *LeveledPayload) Messages() []string { return p.messages }
+
+func (p *LeveledPayload) MessagesJoined() string { return strings.Join(p.messages, "\n") }
// Timestamp returns the time at which this entry was logged.
func (p *LeveledPayload) Timestamp() time.Time { return p.timestamp }
@@ -70,7 +110,7 @@
// Proto converts a LeveledPayload to protobuf format.
func (p *LeveledPayload) Proto() *apb.LogEntry_Leveled {
return &apb.LogEntry_Leveled{
- Message: p.Message(),
+ Lines: p.Messages(),
Timestamp: p.Timestamp().UnixNano(),
Severity: p.Severity().ToProto(),
Location: p.Location(),
@@ -93,7 +133,7 @@
return nil, fmt.Errorf("invalid location line number: %w", err)
}
return &LeveledPayload{
- message: p.Message,
+ messages: p.Lines,
timestamp: time.Unix(0, p.Timestamp),
severity: severity,
file: file,