Repository navigation
parser: hand each message the offset of the last line it consumed - #36
Conversation
There was a problem hiding this comment.
Code Review
This pull request introduces log line offset tracking within the parser and multiline collector to ensure that readers can safely resume after a crash without duplicating or skipping messages. It updates the LogEntry and Message structs to carry the offset of the last consumed line, manages offsets for partial lines from interleaved streams, and adds comprehensive unit tests. The review feedback identifies a critical edge case where interleaving split lines from different streams can lead to unsafe offset progression and duplicate or malformed log fragments upon restart. To address this, the reviewer suggests tracking a maximum unsafe offset (maxUnsafeOffset) in the parser to prevent premature offset advancement when completing or expiring interleaved split lines.
| // Two streams' split lines interleave in the source, so with | ||
| // more than one at a time no offset is safe to acknowledge. | ||
| if len(expired) > 1 || len(partials) > 0 { | ||
| entry.Offset = 0 | ||
| } |
There was a problem hiding this comment.
There is a subtle edge case with interleaving split lines from different streams that can lead to duplicate and malformed/incomplete log fragments on restart.
The Scenario
- Stream A Part 1 arrives at
Offset 15(Partial).partialstracksAat15. - Stream B Part 1 arrives at
Offset 20(Partial).partialstracksAat15andBat20. - Stream A Part 2 arrives at
Offset 25(Final), completing Stream A. Sincelen(partials) > 0(Stream B is pending), Stream A's completed line getsOffset = 0and is delivered. - Stream B never completes and eventually expires.
partials.expiredreturns Stream B (Offset 20). Sincelen(expired) == 1andlen(partials) == 0, the conditionlen(expired) > 1 || len(partials) > 0isfalse. Stream B's expired line keepsOffset = 20and is delivered. - The consumer saves progress as
Offset = 20and the system crashes. - On restart, the reader resumes from
Offset = 20, skipping Stream A's Part 1 (Offset 15) but re-reading Stream A's Part 2 (Offset 25), delivering it as a standalone, incomplete/malformed message.
Solution
To prevent this, we should track the maximum unsafe offset (e.g., by adding a maxUnsafeOffset int64 field to the Parser struct). Any subsequent line with an offset less than this maximum unsafe offset must also have its offset set to 0 to prevent unsafe progression.
// Two streams' split lines interleave in the source, so with
// more than one at a time no offset is safe to acknowledge.
if len(expired) > 1 || len(partials) > 0 {
if entry.Offset > p.maxUnsafeOffset {
p.maxUnsafeOffset = entry.Offset
}
entry.Offset = 0
} else if entry.Offset < p.maxUnsafeOffset {
entry.Offset = 0
} else {
p.maxUnsafeOffset = 0
}There was a problem hiding this comment.
Good catch. The scenario is real: B's expired line acknowledged 20, a position inside A's joined line that was already passed on. A restart there re-read A's last part as a line of its own. It was a malformed duplicate, not a loss.
Fixed with a variant of your suggestion. While a split line is pending, the parser records the furthest offset it held back. When the last pending split line leaves (completed or expired), its message acknowledges the furthest offset read, since everything read by then has been passed on, and the record is cleared. Your version zeroes later lines until one passes the mark. This one moves the position forward instead.
When several split lines expire together, the last of them now acknowledges too, where before all of them carried 0.
TestPendingPartialAcknowledgesLinesPassedOnMeanwhile is your scenario: B's message carried 20 before the fix and carries 25 with it.
| // Another stream's split line started earlier in the source and | ||
| // is not passed on yet: acknowledging this line would skip it. | ||
| if len(partials) > 0 { | ||
| entry.Offset = 0 | ||
| } |
There was a problem hiding this comment.
Apply the same maximum unsafe offset tracking logic here when completing a split line while other partial lines are still pending.
// Another stream's split line started earlier in the source and
// is not passed on yet: acknowledging this line would skip it.
if len(partials) > 0 {
if entry.Offset > p.maxUnsafeOffset {
p.maxUnsafeOffset = entry.Offset
}
entry.Offset = 0
} else if entry.Offset < p.maxUnsafeOffset {
entry.Offset = 0
} else {
p.maxUnsafeOffset = 0
}There was a problem hiding this comment.
Same fix, applied here: one acknowledge helper now sets the offset on both paths. See the reply on line 156.
A log reader that saves its position must only save past lines whose message has been passed on. LogEntry gets an optional Offset (where the line ends in its source); the parser gives each message the Offset of the last line it consumed, including lines dropped over the size limit, as a new last argument of the message callback. While another stream's split line is still being joined, messages carry 0 so a reader never saves past the split line's first part.
f97fdd5 to
f0a9784
Compare
mayankpande88
left a comment
There was a problem hiding this comment.
Looks correct to me: I could not find a case where a message acknowledges past a line that has not been passed on.
Checked:
MultilineCollector.Addflushes the previous message beforeadd()raisesm.offset, so a new message's first line never leaks its offset into the previous one.- Lines over the size limit raise the offset before the limit check, so they are covered.
- Split-line hold: held lines entered the collector before the line that later carries their offset, so they are in that message or an earlier one.
- Dropped lines (invalid UTF-8, decode errors, empty lines outside a message) carry no offset; the next acknowledgement covers them.
- An unflushed message at
Stop()is never acknowledged, so it is re-read: at least once, as intended.
Two things:
-
A split line that never ends blocks acknowledgements for the whole source (
partialLines.expired). Expiry is keyed on the latest part's arrival, so a stream that keeps producingPparts never expires, e.g. a progress bar on stdout written without a newline, which the runtime splits every 16 KiB. While it lasts, every message from the other stream carries 0, the reader's position never advances, and a restart re-reads everything since. Suggest also expiring a pending line by the age of its first part. -
Doc nit on
LogEntry.Offset: themax()logic assumes offsets only increase within a source. node-agent#407 handles truncation and rotation by encoding a generation in the high bits, but nothing here tells another caller to do that. A sentence on the field would cover it.
Neither blocks merging; (1) can be a follow-up.
…outages
Container logs were lost whenever the agent, the logs endpoint or its
backend restarted: readers started at the end of each file with no saved
position, a refused connection dropped the batch without a retry, the
queue (2048) dropped records when full, and nothing was flushed on exit.
- Positions (LOGS_POSITIONS_FILE): each file's position is saved every
10 s and on SIGTERM, only up to lines whose records the endpoint
accepted (counted in emit order through the batch processor, with the
offset of each message's last line from logparser). After a restart the
reader resumes there; a truncated file starts at 0.
- First run: on the agent's first run on a node, files present when it
starts are read from their end, as before; files found after the
initial container scan (a new container, or a crash-looping container's
new file) are read from 0. Once a positions file exists, any unknown
file is read from 0.
- Stale positions (LOGS_POSITIONS_MAX_AGE, default 24h, 0 disables): a
positions file saved longer ago than this is ignored and the first-run
rule applies, so a long downtime does not send a burst of old lines.
The age comes from saved_at in the file, or its mtime for older files.
- Rotation: the old file is read to its end before the new one, and the
saved position stays in the oldest file with undelivered lines. Acks
are tracked across any number of rotations before the first ack. A
file rotated while the agent was down is found again by its inode in
the same directory and finished first; files rotated in between are
not read, and a warning says how many.
- Retries: only known-transient errors are retried until accepted:
connection and timeout errors, 5xx, 408 and 429 (429/503 also by the
OTLP client with no time limit). Anything else (another 4xx, a response
that is not OTLP) drops the batch.
- Backpressure: readers stop reading while 2048 records or 16 MiB wait,
so the queue (8192, blocking) never fills and emitting, which runs under
the parser's lock that /metrics also takes, never blocks. journald,
which no reader can pause, is dropped past 4096 waiting records, with
a warning at most once a minute.
- SIGTERM: stop reading, drop new journald records, deliver what was read
(up to 15 s), save.
- node_agent_log_records_dropped_total{reason} counts dropped records:
backpressure, shutdown, rejected.
- logparser is pinned to the merge commit of nudgebee/logparser#36.
Without LOGS_ENDPOINT nothing changes except that rotation reads the old
file to its end.
…outages
Container logs were lost whenever the agent, the logs endpoint or its
backend restarted: readers started at the end of each file with no saved
position, a refused connection dropped the batch without a retry, the
queue (2048) dropped records when full, and nothing was flushed on exit.
- Positions (LOGS_POSITIONS_FILE): each file's position is saved every
10 s and on SIGTERM, only up to lines whose records the endpoint
accepted (counted in emit order through the batch processor, with the
offset of each message's last line from logparser). After a restart the
reader resumes there; a truncated file starts at 0.
- First run: on the agent's first run on a node, files present when it
starts are read from their end, as before; files found after the
initial container scan (a new container, or a crash-looping container's
new file) are read from 0. Once a positions file exists, any unknown
file is read from 0.
- Stale positions (LOGS_POSITIONS_MAX_AGE, default 24h, 0 disables): a
positions file saved longer ago than this is ignored and the first-run
rule applies, so a long downtime does not send a burst of old lines.
The age comes from saved_at in the file, or its mtime for older files.
- Rotation: the old file is read to its end before the new one, and the
saved position stays in the oldest file with undelivered lines. Acks
are tracked across any number of rotations before the first ack. A
file rotated while the agent was down is found again by its inode in
the same directory and finished first; files rotated in between are
not read, and a warning says how many.
- Retries: only known-transient errors are retried until accepted:
connection and timeout errors, 5xx, 408 and 429 (429/503 also by the
OTLP client with no time limit). Anything else (another 4xx, a response
that is not OTLP) drops the batch.
- Backpressure: readers stop reading while 2048 records or 16 MiB wait,
so the queue (8192, blocking) never fills and emitting, which runs under
the parser's lock that /metrics also takes, never blocks. journald,
which no reader can pause, is dropped past 4096 waiting records, with
a warning at most once a minute.
- SIGTERM: stop reading, drop new journald records, deliver what was read
(up to 15 s), save.
- node_agent_log_records_dropped_total{reason} counts dropped records:
backpressure, shutdown, rejected.
- logparser is pinned to the merge commit of nudgebee/logparser#36.
Without LOGS_ENDPOINT nothing changes except that rotation reads the old
file to its end.
Two gaps found on a kind cluster are closed. A rotated file's saved
position is kept while the file is there under its rotated name, instead
of dropped at the first save after the restart, so a reader that starts
after container discovery (~28 s) still reads its last lines. A reader
paused by backpressure while the kubelet rotates its file more than once
reads the rotated files that are not gzipped yet before the new file; the
ones gzipped before it got to them are skipped with a warning.
…outages (#407) Container logs were lost whenever the agent, the logs endpoint or its backend restarted: readers started at the end of each file with no saved position, a refused connection dropped the batch without a retry, the queue (2048) dropped records when full, and nothing was flushed on exit. - Positions (LOGS_POSITIONS_FILE): each file's position is saved every 10 s and on SIGTERM, only up to lines whose records the endpoint accepted (counted in emit order through the batch processor, with the offset of each message's last line from logparser). After a restart the reader resumes there; a truncated file starts at 0. - First run: on the agent's first run on a node, files present when it starts are read from their end, as before; files found after the initial container scan (a new container, or a crash-looping container's new file) are read from 0. Once a positions file exists, any unknown file is read from 0. - Stale positions (LOGS_POSITIONS_MAX_AGE, default 24h, 0 disables): a positions file saved longer ago than this is ignored and the first-run rule applies, so a long downtime does not send a burst of old lines. The age comes from saved_at in the file, or its mtime for older files. - Rotation: the old file is read to its end before the new one, and the saved position stays in the oldest file with undelivered lines. Acks are tracked across any number of rotations before the first ack. A file rotated while the agent was down is found again by its inode in the same directory and finished first; files rotated in between are not read, and a warning says how many. - Retries: only known-transient errors are retried until accepted: connection and timeout errors, 5xx, 408 and 429 (429/503 also by the OTLP client with no time limit). Anything else (another 4xx, a response that is not OTLP) drops the batch. - Backpressure: readers stop reading while 2048 records or 16 MiB wait, so the queue (8192, blocking) never fills and emitting, which runs under the parser's lock that /metrics also takes, never blocks. journald, which no reader can pause, is dropped past 4096 waiting records, with a warning at most once a minute. - SIGTERM: stop reading, drop new journald records, deliver what was read (up to 15 s), save. - node_agent_log_records_dropped_total{reason} counts dropped records: backpressure, shutdown, rejected. - logparser is pinned to the merge commit of nudgebee/logparser#36. Without LOGS_ENDPOINT nothing changes except that rotation reads the old file to its end. Two gaps found on a kind cluster are closed. A rotated file's saved position is kept while the file is there under its rotated name, instead of dropped at the first save after the restart, so a reader that starts after container discovery (~28 s) still reads its last lines. A reader paused by backpressure while the kubelet rotates its file more than once reads the rotated files that are not gzipped yet before the new file; the ones gzipped before it got to them are skipped with a warning.
Summary
A log reader that saves its position in a file can only save past lines whose message has already been passed on. Otherwise a restart skips lines that were read but not yet delivered.
LogEntrygets an optionalOffset: where the line ends in its source.Offsetof the last line it consumed, as a new last argument of the message callback. That includes lines dropped over the size limit.0. A reader therefore never saves past the first part of a split line.Breaking: the callback signature gains an argument. node-agent is the only caller, and its matching change is in a follow-up PR there.
Test plan
go test ./...andgo vet ./...pass.offset_test.gocovers single lines, multiline messages, joined split lines across both streams, and lines over the size limit. Removing the split-line hold makes the split-line case fail.