fix(aws-serverless): Keep the Lambda extension polling past 300s invocations - #24219
LuccaRebelloToledo wants to merge 9 commits into
Conversation
d38c2a3 to
ba75461
Compare
4a517e2 to
67b97e7
Compare
…cations `/event/next` acknowledges the previous event and waits for the next one, so the poll stays open for the whole of the following invocation. Node's `fetch` caps that at undici's 300s `headersTimeout`, and the rejection escapes a loop with no `try`/`catch` — the extension never asks for another event, and Lambda holds every later invocation on that execution environment until the function timeout. The poll now uses `http.request`, which has no default timeout. It carries no deadline either: the poll also spans the environment's frozen idle time, which is unbounded, so a socket deadline would fire on thaw and destroy a poll that was about to be answered. TCP keep-alive covers the case a deadline was there for. A failed poll is retried with capped backoff, bounded so a failure that stops recovering exits rather than logging every 5s forever. A refused poll — 4xx other than 408 and 429 — and a body that is not the event JSON are both failures rather than events, so neither resets the backoff or slips past the SHUTDOWN check. Exiting reports to the Extensions API first, so Lambda recycles the environment instead of leaving it registered and silent. Failures are reported through `console`: `debug` is only enabled from `Sentry.init`, which this process never calls. Fixes getsentry#24218 Co-authored-by: Claude Opus 5 <noreply@anthropic.com>
67b97e7 to
3793baf
Compare
msonnb
left a comment
There was a problem hiding this comment.
thanks for the PR! two suggestions but besides that LGTM.
| if (isClientError(err)) { | ||
| throw err; | ||
| } |
There was a problem hiding this comment.
Could we also treat 500 errors as fatal here? The Extension API docs define it as an unrecoverable container error and say the extension should exit promptly.
There was a problem hiding this comment.
Good catch — and I think it should go further. The docs list only 200, 403 and 500 for /event/next, so 408/429 aren't part of this contract at all; I brought a generic HTTP taxonomy to an endpoint that doesn't use one.
Proposing to drop RETRYABLE_CLIENT_ERRORS entirely and treat any non-2xx as fatal, leaving the retry/backoff path for transport errors only (ECONNRESET and friends), which carry no status code. That matches "Extension should exit promptly" and is less code than what's there now.
There was a problem hiding this comment.
You approved the version I proposed — any non-2xx fatal, exit promptly — and then I measured it and changed my mind. Flagging that here rather than letting you find it in the diff.
Measured on the RIE under {"events":["SHUTDOWN"]}, extension acting during invocation 2 of a 3s handler:
| behaviour | customer sees |
|---|---|
process.exit(1) |
502 Extension.Crash at 0.016s |
process.exit(0) |
502 Extension.Crash at 0.019s |
/exit/error then exit |
502 Extension.ExitError at 0.020s |
| stop polling, stay alive | 200 at 3.022s, next 200 at 3.008s |
The exit code doesn't save you and reporting first doesn't save you — the process ending is the act that fails the customer's invocation.
So the statuses are what you asked for and the consequence isn't: TERMINAL_POLL_STATUSES = [403, 500], acted on after three consecutive confirmations (~306ms, prompt by any reading), and what stops is the loop rather than the process. The confirmations are there because a 500 is also how the API answers a poll issued while the environment is already tearing down, which clears on its own.
That's only safe because of the other half of this PR. run never read an INVOKE event, so the extension now registers for SHUTDOWN alone and is out of the gate that holds each invocation. Same bundle, only the events array differing, extension deliberately stopped: ["SHUTDOWN"] → 0.107s per invocation, no reset; ["INVOKE","SHUTDOWN"] → 22.134s and Reset initiated: Timeout every time.
One exception, and it's the part I had wrong in my own proposal too. Giving up while the init phase is still waiting on us leaves us holding every invocation: 32.203s wall and 30,000ms billed, against under half a second and no billed duration at all for a crash that lets Lambda recycle. So the rule is "exit only while we are still what init is waiting for" — registration failures and a give-up before the first answered poll exit; anything after that parks.
Two caveats on that, both measured after I first wrote this. The gate actually releases when a poll reaches the API, not when one is answered — a client can't observe that once the transport dies, so pollAccepted keys off a resolved next() and under-reports. And under ["SHUTDOWN"] the API holds the first poll for the environment's life, so it normally resolves only at shutdown: the park branch is reached when the API answers a poll with something that isn't a shutdown event and then starts failing, not on the common transport failure. Erring towards exit is deliberate — exiting with the gate open costs one invocation, parking with it closed costs every invocation for the life of the environment.
This is the one place the PR argues with the docs' "exit promptly". If you'd rather we take it literally, it's one branch and I'll change it — the 502 above is what it costs.
| // Returns on SHUTDOWN. The process is left to idle rather than exiting, so envelopes the | ||
| // tunnel is still forwarding get their chance to land before Lambda reaps the environment. | ||
| await extension.run(); |
There was a problem hiding this comment.
Could we keep track of and drain any pending envelopes within the shutdown deadline, then explicitly finish shutdown? This always maxes out the 2000ms shutdown duration limit, which is billed as Lambda execution time to the user.
There was a problem hiding this comment.
Agreed, and my rationale in that comment doesn't hold up. It claims lingering gives in-flight envelopes a chance to land, but the tunnel fires fetch(...).catch(...) without tracking anything, so nothing is actually awaited — at 2,000ms Lambda SIGKILLs the process and takes any in-flight upload with it. Draining is better for envelope delivery, not just for the shutdown duration.
Plan: track in-flight tunnel requests, await them on SHUTDOWN bounded by the event's deadlineMs, then exit explicitly.
Worth noting this isn't new in this PR — the process lingered before it too — but since this PR is what made the extension SHUTDOWN-aware, it's the right place to fix it.
There was a problem hiding this comment.
agree that this is pre-existing, so feel free to tackle in a follow-up PR (or let us handle it). Your proposed plan sounds good though.
There was a problem hiding this comment.
Thanks — I took the plan but not the follow-up, and I'd rather say why than have it look like I missed the offer.
Draining is better for delivery, not just for the bill. Measured on the extension's own clock, from its shutdown event to its exit: 311-318ms with nothing pending, clean exit code every time. On the platform's clock — which starts ~610ms earlier, when the runtime gets SIGTERM — that is a 920-930ms shutdown window against the 2,002-2,005ms a never-exiting extension burns before the SIGKILL, so the saving is about 1.08s per teardown rather than the 1.7s those two figures invite you to subtract.
Still happy to carve it out if you'd rather review it on its own — say the word and I'll split it.
Two things it turned out the drain has to get right, neither of which I'd have guessed:
The deadline can't be trusted as an epoch. AWS's own documented example payload carries deadlineMs: 676051. Read as epoch millis that yields a negative budget and drops whatever is in flight — measured, an 8MB envelope destroyed entirely where a guarded version delivered all 8,388,678 bytes. Anything that isn't a plausible remaining window now falls back to the 2,000ms Lambda enforces anyway.
Returning the instant the pending set empties is too early. The runtime gets SIGTERM ~605ms before the extension is released, and its handlers post through this tunnel — a process.on('SIGTERM', () => Sentry.flush()) hook, or @sentry/node's own beforeExit flushes. Measured against this branch's build: the runtime's posts at t+20/100/400ms after the shutdown event all reach Sentry, while a build that returns as soon as the pending set is empty (+6ms) delivers none of them, all ECONNREFUSED. A fourth post at t+900ms never goes out at all — Lambda has killed the runtime by then — so that one is lost either way and is not something the drain can save. The affected population is exactly the one this layer creates — Lambda only sends the runtime a SIGTERM because an external extension is registered.
Tracking goes through makePromiseBuffer from @sentry/core rather than a hand-rolled Set; its drain(timeout) already unrefs the loser timer, which my first version was getting wrong.
Separately, while I was in this file I found something worse than the shutdown window: @sentry/node gzips any body over 32KiB, and the tunnel parsed the raw bytes as the envelope header, so every large event was answered 500 and dropped. Measured with the real layer and the real SDK — 30,000 bytes through, 31,500 bytes gone, clean flip at GZIP_THRESHOLD. It predates this PR. Details and the regression test are in the description; that one is genuinely independent and I'll split it out on request.
|
👋 @isaacs — Please review this PR when you get a chance! |
…-invocation The `/event/next` poll and `/register` now go through `http.request` with no deadline at any layer, the extension subscribes to SHUTDOWN alone so it is out of the per-invocation gate, and the process exits only while it still holds the init phase. The tunnel drains in-flight envelopes against the shutdown deadline, and reads `content-encoding`, which every envelope over 32KiB carries. Fixes getsentry#24218 Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Fails against a layer built without the fix: the compressed header never parses, so the DSN allowlist is never reached and a rejected DSN answers 500, not 403. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
There was a problem hiding this comment.
Cursor Bugbot has reviewed your changes and found 1 potential issue.
❌ Bugbot Autofix is OFF. To automatically fix reported issues with cloud agents, enable autofix in the Cursor dashboard.
Want reviews to match your repository better? Bugbot Learning can learn team-specific rules from PR activity. A team admin can enable Learning in the Cursor dashboard.
Reviewed by Cursor Bugbot for commit 1764199. Configure here.
…nk at a time A one-shot inflate bounds the whole body, and `makeNodeTransport` only compresses past 32KiB — so every envelope that arrives gzipped exceeded a cap small enough to protect the memory the extension shares with the function, and was answered 500 and dropped. Only the first line is ever needed, so it is read incrementally and the stream stops at the newline. The tests gzipped envelopes of a few hundred bytes, which is below the size at which the SDK compresses at all, so they never reached the path they were written for. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
…encoding read `@types/node` types `content-encoding` as `string | undefined` — `set-cookie` is the one it collects into an array — and duplicates arrive joined as `"gzip, identity"` rather than as two values. The `Array.isArray` guard was covering a state that cannot occur, and it was the only reason the forwarded value looked like it was being treated differently from the one used for the lookup. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Measured A/B: the phase releases when a poll reaches the Extensions API, not when the API answers one. A client cannot observe the former once the transport dies, so `pollAccepted` still keys off a resolved `next()` — but it under-reports rather than matching the platform, and the comments now say so. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
…hey exist to cross The sizes were literals that happened to work. What matters is that the envelope clears both bounds: the SDK compresses nothing below `GZIP_THRESHOLD`, and a one-shot inflate capped at `ENVELOPE_HEADER_MAX_BYTES` is what the streaming header read replaced, so anything smaller exercises neither. The dropped-header assertion also spells out the error it expects rather than matching a substring of it. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
… SDK's private one Mirroring `@sentry/node`'s 32KiB gzip threshold made the test's input depend on a constant it cannot import and would not notice moving. The bound that actually decides this test is `ENVELOPE_HEADER_MAX_BYTES` — the one a single-shot inflate would have tripped over — and a size derived from it clears the SDK threshold anyway. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
|
Hi @msonnb — moving this back to draft and asking for a steer before either of us spends more time on it. Your review was right on both counts, and acting on it is what grew this. Dropping the INVOKE subscription changed what the exit policy can safely do, so those two ended up load-bearing on each other, and validating that surfaced a separate pre-existing bug — envelopes over 32KiB were being dropped before this PR existed. What started as "the long poll has a timeout" is now five subjects in one diff, which is more than is fair to review in one pass. I'd rather split it than ask you to carry that. The seam I'd pick:
Happy to do that split, keep it as one, or drop anything you think doesn't belong here. Whichever is least work for you — I just don't want to keep building on a shape you'd rather not merge. |

Two changes that only work together, so the argument for the second is the argument for the first.
The bug. The
/event/nextlong poll ran throughfetch, so undici's 300sheadersTimeoutkilled it on any invocation longer than that. The rejection escaped an uncaughtwhile (true)and the extension stopped polling — and Lambda holds an invocation open until the runtime and every registered extension have asked for the next event, so every later invocation on that sandbox ran to the function timeout. Mechanism, production numbers and a repro that needs no AWS account are in #24218.Two things the issue does not say, both measured against a pre-fix build of this branch in the AWS RIE. The failure is completely silent:
Sentry Lambda extensionappears exactly once in a full control log, and that once is the DSN advisory. And the handler is not what breaks — it finished in 2.366ms and the runtime reported success; Lambda then held the response for the remaining 330s waiting on the extension.Why the poll has no deadline. AWS is explicit on
/event/next: "Do not set a timeout on the GET call, as the extension can be suspended for a period of time until there is an event to return." (https://docs.aws.amazon.com/lambda/latest/dg/runtimes-extensions-api.html#extensions-api-next) So the fix is not a bigger timeout, it is no timeout —http.requestwithagent: false, plus TCP keep-alive for a peer that vanishes without a FIN/RST.agent: falsematters more than it looks.http.globalAgent.options.timeoutis 5000 while'timeout' in http.globalAgentis false, so every check written againstagent.timeoutreadsundefinedand passes. That timeout is inert today only because Node'semitRequestTimeoutis a no-op without a'timeout'listener; it goes live the moment someone adds the idiomatic one.Registration goes through the same path, and that is not cosmetic. Measured in the RIE with
/registerhonoured by RAPID in 2ms and its response withheld:fetchabandons it at 303.044s withUND_ERR_HEADERS_TIMEOUT,registerreads that as a transport failure and retries, and RAPID refuses the retry403 Extension.InvalidExtensionState— the extension then exits. Onhttp.requestthe same scenario holds one POST open for 310,141ms and registers when the response is finally released.Rather than enumerate the timeout APIs, the tests collapse all of them —
setTimeout,setInterval,Socket.prototype.setTimeout,AbortSignal.timeout— so any deadline either call arms expires at once, then assert the request is still open. That catches the two mechanisms which record no socket timeout at all.Why SHUTDOWN-only registration is in this PR
runreads nothing buteventType === 'SHUTDOWN'; the INVOKE subscription was dead. Dropping it takes the extension out of the per-invocation gate. Measured on byte-identical bundles differing only in the events array, extension deliberately stopped after INIT:["INVOKE","SHUTDOWN"]Task timed out["SHUTDOWN"]It is also the only shape Lambda Managed Instances accepts — "Extensions for Lambda Managed Instances functions can only register for the
SHUTDOWNevent" — and today the published layer turns that 403 intoprocess.exit(1), failing the whole function's init. Confirmed in MI mode:["SHUTDOWN"]accepted,["INVOKE","SHUTDOWN"]refused403 {"errorType":"Extension.InvalidEventType"}. That makes this a correctness fix there, not only hardening.The honest caveat. The doc says the Invoke phase ends when "the runtime and all extensions signal that they are done", with no subscription qualifier. Read literally, that contradicts this. What supports the change: the RIE gates INVOKE on
GetSubscribedExternalAgents(core.InvokeEvent)while gating INIT onGetRegisteredAgentsSize(), andawslabs/aws-lambda-web-adapter— an AWS first-party external extension in the request path of one of the most widely deployed layers — registers{"events": []}and parks forever on/event/next, with a source comment saying it was verified on a deployed function. If the gate counted registrations, every LWA function would time out on every invocation.Why the only exits are inside the init phase
Leaving the invocation gate is what makes the rest safe, which is why the two changes ship together. Measured under
["SHUTDOWN"], extension acting during invocation 2 of a 3s handler:process.exit(1)Extension.Crashat 0.016sprocess.exit(0)Extension.Crashat 0.019s/exit/errorthen exitExtension.ExitErrorat 0.020sThe exit code is irrelevant and reporting first is irrelevant — the process ending is the act that fails the invocation.
But "never exit" is too strong, and that is the part I had wrong until I measured it. Giving up while the init phase is still waiting on this extension leaves it holding every invocation:
Task timed out,Billed Duration: 30000 msREPORTline at all — zero billed durationSo
runreports whether a poll was ever answered andmainexits on the init side of that line, parks on the other. Two caveats on that, both measured. The gate actually releases when a poll reaches the API rather than when one is answered, and a client cannot observe the former once the transport dies — sopollAcceptedunder-reports, and an extension whose first poll is accepted and then cut will exit where parking would have been free. And under["SHUTDOWN"]the API holds that first poll for the environment's life, sonext()normally resolves only at shutdown: the park branch is reached when the API answers a poll with something that is not a shutdown event and then starts failing, not on the common transport failure. Erring this way is the deliberate direction — exiting when the gate was open costs one invocation, parking when it was not costs every invocation for the life of the environment.registercarries the same 16-minute ceiling the poll loop does — without it, an Extensions API unreachable for 60s on a 30s function billed 30,000ms per invocation with the handler never running.pollAcceptedis set whennext()resolves, not from elapsed time. Deriving it from "the poll was held 5s" is lossy in both directions, and the two errors are not symmetric: exiting when we should have parked costs one invocation, parking when we should have exited bills every one of them for the life of the environment.This is where the PR argues with the docs, which say "exit promptly" on a 500. Happy to be overruled — it is one branch.
Shutdown
Previously the process lingered and Lambda SIGKILLed it at 2,000ms, billed to the function. Worse, the tunnel fired
fetch(...).catch(...)without tracking anything, so an envelope in flight at teardown died with the process regardless.Uploads now go through
makePromiseBufferfrom@sentry/coreand are awaited against the event's deadline, then the process exits 0. Measured on the extension's own clock, from its shutdown event to its exit: 311–318ms with nothing pending, and a clean exit code every time. On the platform's clock — which starts ~610ms earlier, when the runtime gets SIGTERM — that is a 920–930ms shutdown window against the 2,002–2,005ms a never-exiting extension burns before the SIGKILL, so the saving is about 1.08s per teardown rather than the 1.7s the two figures invite you to subtract.Two things the drain has to get right. AWS's own documented example payload carries
deadlineMs: 676051, which is not an epoch value — read as one it grants a negative budget, measured destroying an 8MB in-flight envelope entirely where a guarded version delivered all 8,388,678 bytes. And returning the moment the pending set is empty is too early: the runtime receives SIGTERM ~605ms before the extension is released, and its handlers post through this tunnel. Measured on this branch's build, the runtime's posts at t+20/100/400 after the shutdown event all land, while a build that returns as soon as the set is empty delivers none of them. A post at t+900 never goes out — Lambda has killed the runtime by then — so it is lost either way. Hence a 300ms idle grace, re-armed by tunnel activity, inside the deadline less a 200ms margin.Envelopes over 32KiB were being dropped
Found while validating the rest, and not introduced here — the logic predates this PR.
makeNodeTransportgzips any body pastGZIP_THRESHOLD(32,768 bytes) and setscontent-encoding: gzip. The tunnel read the envelope header by decoding the raw request body and splitting on the first newline, which on gzip magic bytes throws — answered 500, dropped the envelope, and reported it throughdebug, which is never enabled in this process.Measured with the real layer and the real SDK: a 30,000-byte payload is delivered; a 31,500-byte one produces
Sentry responded with status code 500 to sent eventand zero bytes at the ingest stub. Clean flip at the threshold. The regression case is in the layer e2e app alongside the tunnel's other branches, and it fails against a layer built without the fix — a rejected DSN answers 500 rather than 403, because the allowlist is never reached.Three things came out of doing it:
Extension.Crash. Only the first line is ever needed; a header saturating the baggage cap core enforces measures 8,085 bytes, so the read gives up well above that and well below the body.GZIPandgzip, identityboth have to work; each dropped the envelope before. Node gives this header as one string — duplicates arrive joined, unlikeset-cookie— so there is one value and one place that normalises it.debug; silent data loss is the subject of this whole PR, so they go to the console, capped the way the poll loop caps its own reporting.Also in here
startSentryTunnel's listen error calledprocess.exit(1)from inside the class, which registered the extension and then killed it — Lambda extension stops polling after a 300s invocation, hanging every later invocation on that execution environment #24218's exact shape, manufactured by this file. It logs now.{}included, used to read as an event: counters reset, no backoff, immediate re-poll. Measured at ~11,000 polls/s once the extension is out of the invocation gate.SENTRY_DSNunset, the envelope header'sdsnreachedmakeDsn, whose failure path is an ungatedconsole.errorof the caller's text — newlines included, which forges log lines. It is validated before it can be logged.error()is gone. It sentLambda-Extension-Function-Errorwhere the API requiresLambda-Extension-Function-Error-Type, so Lambda rejected it in every run.Extension init cost, for the record: +37.4ms median over 8 fresh containers each way.
Deliberately not in here
scheduleIdleSocketValidation; undici 6, on Node 20 and 22, does not. Fixing it well means adding retry.packages/node/src/transports/http.tscreates an Agent withtimeout: 2000and no'timeout'listener anywhere in the file — the exact mirror of the surface fixed here, armed and inert. Different package; named so the two are fixed together rather than rediscovered one at a time.buffer(req)itself is not.Fixes #24218