Repository navigation
[SLES-3037] fix: reassemble log records Lambda splits into pieces - #1415
Conversation
There was a problem hiding this comment.
🟢 Approval recommended
The stitching logic is bounded, thoroughly tested, and correctly integrated with telemetry handling.
0 open findings
What changed in this PR
Reworks telemetry stitching to recover oversized Lambda log records split within or across POST payloads.
Changes:
- Detects and removes split-record seams.
- Supports multi-piece and cross-POST recovery with fallback handling.
- Adds comprehensive boundary and regression tests.
| File | Description |
|---|---|
bottlecap/src/extension/telemetry/stitch.rs |
Implements generalized record reassembly and tests. |
bottlecap/src/extension/telemetry/listener.rs |
Uses the revised stitching API. |
🧠 Review effort: Balanced
Give feedback about Copilot approvals in this survey to enter a drawing for a $150 gift card.
I'm also doing this in #1414. Feel free to approve and rebase on my changes to make your PR smaller. |
1b5eca7 to
d6f0a71
Compare
269ced9 to
b92a519
Compare
lym953
left a comment
There was a problem hiding this comment.
🤖 Written by Claude, reviewed by @lym953 before posting.
Thanks, the new design recovers every cut I tried, in one POST and in two. The only exception is a short first piece, which you excluded on purpose. Two smaller problems and one question are inline.
| } | ||
| _ => return false, | ||
| }, | ||
| Some((record, _)) if event.kind != record.kind => { |
There was a problem hiding this comment.
🤖 Written by Claude, reviewed by @lym953 before posting.
When runtimeDone comes before the joined record, the logs processor sends that log line with an empty request ID.
This branch moves an event of another type ahead of the cut record, and keeps_runtime_done_whole_after_a_cut_piece expects this for runtimeDone. The logs processor handles events in order:
- A function log line without its own
requestIdtakes the request ID of the current invocation (processor.rs#L486-L497). runtimeDoneclears that ID (processor.rs#L346-L347).- A line with no request ID goes to the orphan queue (processor.rs#L555-L556).
- When the next log line with a request ID arrives, the lines in the orphan queue get the current request ID (processor.rs#L860-L865). After
runtimeDone, that next line isREPORT, and the current request ID is empty.
I sent this sequence through the processor's process in a test: START of req-1, the joined record {"items":[{"id":1},{"id":23}]} and runtimeDone in the order below, then platform.report, then START of req-2.
| Order of the two events | Request ID on the joined log line in the output |
|---|---|
Joined log line, then runtimeDone |
req-1 |
runtimeDone, then joined log line |
"" (empty) |
Did the repro show runtimeDone between two pieces? If it did, one option is to put events of another type after the joined record, in their original order. A JSON line that holds its own requestId does not have this problem.
There was a problem hiding this comment.
Good find, you're right about the ordering. Though a full fix would make the cross-POST join more complex, since instead of appending the next POST it'd have to remember where the cut record ends and splice the next piece in ahead of the held events. We haven't seen runtimeDone land between two pieces so far, and if it does happen runtimeDone and its metrics still get handled and the line still gets sent, just without the request ID. So, I’m thinking of leaving this as-is for now and handling that in a follow-up, so that we can get the hang fix out as soon as possible.
|
🤖 Written by Claude, reviewed by @lym953 before posting. Thanks for the changes. I ran these on d1a1465:
Two requests, neither blocking:
|
Overview
Follow-up to #1357 (SLES-2997). That fix added
stitch.rsto recover telemetry payloads broken by an oversized log record, and raisedmaxBytesto 1 MiB. Customers on v100 still hit the same timeouts. The stitcher was in place, but their payloads never reached it.#1357 assumed the Telemetry API cuts a record at
maxBytesand resumes it in the next POST under the same envelope. That isn't what happens. Lambda itself cuts any log line longer than about 256 KiB into pieces, whatevermaxBytesis, and sends each piece as its own event with its own timestamp. For JSON log lines, each piece's raw bytes become that event's record value, so no payload containing a piece parses. The stitcher's assumptions failed in three ways:maxBytes, several pieces land in one POST. The stitcher only handled a split across two POSTs, so a single body like this was dropped.Eofparse failures were held. A cut right after a\or a complete value fails asSyntax, so it was rejected outright.So these payloads were still discarded,
platform.runtimeDonewent with them, and the on-demand loop waited until the sandbox timed out. The original repro passed because, at 256 KiBmaxBytes, each piece ended its own POST and both pieces shared a timestamp, which happens to fit the old model.Changes (extension/telemetry/stitch.rs)
-,.ore) and the next event is a log piece of the same type. The pieces are joined and the payload rebuilt. A whole record before a boundary means a normal boundary, so aplatform.*event likeruntimeDoneis never absorbed.Performance: unchanged for payloads that parse, since the stitcher only runs after a failed parse. Recovering a payload parses each record value on its own, and the cut record again for each piece added, bounded by the 4 MiB fragment cap and 64 seams. That's a few ms for a ~1 MiB record, and only on payloads that previously hung the invocation.
Known gaps
runtimeDonelands between two pieces, it's moved ahead of the joined line, so the line is sent without its request ID. We haven't seen this happen; follow-up ticket.Testing
\usequences and multi-byte text inside a string, and one with arrays of objects in its structure, cut at every char boundary: as pieces in one payload (with and without an extension log line between them) and as a piece split across two POSTs. Each case must reassemble the exact record plusruntimeDone. Cuts that leave the payload valid JSON are skipped as the known gap above.runtimeDoneafter a cut piece is kept whole and delivered with the joined record.