Repository navigation
🪦 feat: Log Request Tombstones and Memory Watermarks, Closing Out Abandoned Requests as 499 - #197
Open
danny-avila wants to merge 1 commit into
Open
danny-avila wants to merge 1 commit into
danny-avila wants to merge 1 commit into
Conversation
…ndoned Requests as 499 The Bun server logged nothing per request and nothing about memory, so a crash or OOMKill left no trace of the request in flight or of the climb that preceded it. Each request now logs "[req] METHOD /path" on arrival, before the handler runs, and "[req] METHOD /path STATUS Nms" once it is answered, so an arrival without a completion names a request the process died holding. Paths are logged without query strings and cut at 200 characters, and at most 200 requests are logged per 10 seconds, with the number held back reported when the next window opens. ADMIN_PANEL_REQUEST_LOG=false turns the log off. The log and the HTTP metrics record one status: 499 when the client abandoned the request before it was answered, else the response's own. Bun neither reads nor cancels the body of an abandoned request, so such a request is closed out at once instead of waiting on its body, and a streamed body settles on the first of drain, error, or the request's abort signal, once. HEAD responses and the Bun.file static routes are logged at once and their bodies left untouched. Every other body passes through a stream Bun cannot size, so server-function responses now go out chunked instead of with a Content-Length. A 10-second check logs "[mem] rss=... heapUsed=... (crossed ...)" each time RSS climbs past one of ADMIN_PANEL_MEMORY_LOG_THRESHOLDS_MB (default 256,384,448 MiB); a threshold re-arms once RSS drops back below it. The wrapper and its helpers live in src/server/logging.ts, where tsc, eslint and vitest cover them; server.ts only wires them up. Both variables are documented in .env.example. Builds on the request tombstones and memory watermarks proposed in #102.
Contributor
Author
Codex Review SummaryThis comment shows the latest Codex review activity on this pull request.
ℹ️ About Codex in GitHubYour team has set up Codex to review pull requests in this repo. Reviews are triggered when you
Codex reacts with 👀 while any review is running, comments if it has suggestions, and reacts with 👍 once all reviews finish with no findings. |
|
Codex Review: Didn't find any major issues. Another round soon, please! Reviewed commit: ℹ️ About Codex in GitHubYour team has set up Codex to review pull requests in this repo. Reviews are triggered when you
If Codex has suggestions, it will comment; otherwise it will react with 👍. Codex can also answer questions or update the PR. Try commenting "@codex address that feedback". |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Pull Request Template
Summary
The panel's Bun server logs its two startup lines and nothing else: no line per request and no memory readings. Memory only shows up when Prometheus scrapes
/metrics. When the process crashes or is OOMKilled, nothing records which request it was handling or how memory grew before it. This PR supersedes #102 by @dustinhealy. It keeps that PR's request tombstones and memory watermarks, written fresh on today'smain. It also closes out requests the client abandons, which #102 left open on currentmain.Request tombstones. Each request logs
[req] GET /pathwhen it arrives, before the handler runs, and[req] GET /path 200 12msonce it is answered. An arrival line with no completion line names a request the process died holding. Carried over from #102:[req] suppressed N requests in prior window, so a request flood cannot turn into a log flood but is still visible.ADMIN_PANEL_REQUEST_LOG=falseturns the log off. The metrics are recorded either way.Abandoned requests close out as 499. The completion line and the HTTP metrics use one status:
499whenreq.signal.abortedis set by the time the handler returns (the rule #181 added to the metrics), otherwise the response's own status.stream-error), or the request's abort signal fires (client-closed, with the status the response was sent with).#102 waited only on the response body. Bun neither reads nor cancels the body of a request the client abandoned, so on current
mainevery abandoned server function left an arrival line with no completion line, which looks exactly like a crash. #102 also counted those requests as500. In the live check below, #102's approach left 9 of 9 forced aborts open. With this PR, none were left open.Bodies left alone. A HEAD response and the
Bun.filestatic routes are logged at once and returned untouched. Bun sends no body for HEAD: it reads one chunk and then cancels the stream, so a wrapped HEAD body would end in a misleadingclient-closed. Wrapping a file body would lose Bun's sendfile path and theContent-Lengthit derives from the file.Every other body passes through a JavaScript stream, and Bun cannot tell its length. Server-function responses, which
mainsends withContent-Length, now go out withTransfer-Encoding: chunked. Browsers and TanStack's client read both the same way, SSR pages were already chunked, and #102 did the same.Memory watermarks. Every 10 seconds the server compares RSS with
ADMIN_PANEL_MEMORY_LOG_THRESHOLDS_MB(default256,384,448MiB). Each time RSS climbs past a threshold it logs[mem] rss=391Mi heapUsed=213Mi (crossed 384Mi), reporting the highest threshold crossed. A threshold logs again only after RSS drops back below it. This records when memory jumped even if no request was in flight at the time.Where it lives. The wrapper and its helpers are in
src/server/logging.ts, and its types are insrc/types/server.ts.server.tsis excluded fromtscand ESLint, so the code moved intosrc/server, wheretsc, ESLint and Vitest check it.server.tsonly wires the module up, and the Docker image already copiessrc/server. Both variables are documented in.env.example.Not carried over from #102.
Bun.serveerror()hook and the catch/rethrow-500 path. Bun 1.3.11 and later already log an uncaught handler throw with its stack and answer 500. TanStack Start also catches handler errors itself and answers 500, sohandler.fetchdoes not reject to Bun.isProbeRequest./healthis a static route and never reaches the wrapper, and neither does/metrics.Change Type
Testing
Unit tests in
src/server/logging.test.ts(Node environment, realprom-clientcounters,console.logspied):499, and the metrics count499and no500.200 Nms client-closedline, and a later cancel adds nothing. A cancel that lands while a read is pending also reports once.stream-error.monitorBody: false) are returned untouched and closed out at once.[mem]lines until it is stopped.Each behaviour was checked against its own test by removing it. Without the abort listener, the mid-stream test fails. If abandoned bodies are wrapped, or the response status is recorded instead of 499, the 499 test fails. If HEAD or file bodies are wrapped, those tests fail. Without the settle-once guard, the two mid-stream tests fail.
Live check with a production build against a LibreChat backend:
/,/configuration,/access,/usersand/grantscurl --max-time 0.003, with the session cookie)499, 4 were answered within 3 ms (200); no arrival left open after 15 s;/metricsshowsstatus_code="499"32Bun.serverunning the same wrapper over a slow 10-chunk stream: full read, cut mid-stream, client gone before the handler answered, HEAD200 1101ms, one200 350ms client-closed,499 150ms, HEAD closed out at onceBun.serve: a HEAD answered with a raw stream, andResponse.jsonwith and without the wrapperResponse.jsongoes out withContent-Lengthunwrapped andTransfer-Encoding: chunkedwrappedContent-Lengthkept/login?redirect=/grants&code=…[req] GET /login[req] suppressed 30 requests in prior windowADMIN_PANEL_MEMORY_LOG_THRESHOLDS_MB=50,80[mem] rss=118Mi heapUsed=29Mi (crossed 80Mi)on the first tick; at the defaults, RSS (about 120 MiB) logs nothingADMIN_PANEL_REQUEST_LOG=false[req]lines; the metrics still counted the aborts as499No console errors or failed requests while browsing.
Test Configuration:
dev, MongoDB replica set.bun run build+bun server.ts).npx tsc --noEmit,npx eslint src/ e2e/ --max-warnings 0,npx prettier --checkon the changed files,bun run test:lint-rules,npx vitest run(3366 tests),bun run build.Checklist