Skip to content

🪦 feat: Request Tombstones, Memory Watermarks & Server Error Logging - #102

Open
dustinhealy wants to merge 5 commits into
mainfrom
request-observability
Open

🪦 feat: Request Tombstones, Memory Watermarks & Server Error Logging#102
dustinhealy wants to merge 5 commits into
mainfrom
request-observability

Conversation

@dustinhealy

Copy link
Copy Markdown
Contributor

Summary

The bun server's only log output is its two startup lines, which leaves crashes and OOMKills undiagnosable: the HTTP metrics increment on completion, so a request that kills the process mid-flight is invisible to them, an uncaught handler throw produces no output at all, and nothing captures memory growth between metric scrapes.

Adds three narrow instruments to the serve path (server.ts, pure helpers in src/server/logging.ts):

  • Request tombstones[req] GET /path at arrival (before the handler runs, so a fatal request leaves its method and path as the process's last words) plus [req] GET /path 200 12ms on completion. An arrival line with no matching completion identifies the request a process died holding. Paths log without query strings (they can carry OAuth exchange codes) and truncate at 200 chars. Kubelet probes (kube-probe/ user-agent) are skipped so steady-state logs stay near-silent. A per-window cap (200 requests / 10s) stops a request flood from amplifying into a log flood, surfacing [req] suppressed N requests in prior window instead.
  • Memory watermarks — a 10s tick logs [mem] rss=391Mi heapUsed=213Mi (crossed 384Mi) on each upward threshold crossing (defaults 256/384/448 MiB, configurable via ADMIN_PANEL_MEMORY_LOG_THRESHOLDS_MB), re-arming when memory drops back below a threshold. This timestamps allocation bursts even when no request is in flight — the deciding evidence between a pathological request and runtime GC behavior.
  • Error hookBun.serve had no error() handler, so an uncaught throw in the SSR handler produced no log line at all. It now logs the message and stack and returns a plain 500.

On by default; disable with ADMIN_PANEL_REQUEST_LOG=false. Prometheus metrics, /metrics, and /health behavior unchanged.

Change Type

  • New feature (non-breaking change which adds functionality)

Testing

22 new unit tests (probe detection, truncation, flood-guard windows, watermark hysteresis); full suite (821 tests) passing; tsc --noEmit, eslint, and a from-scratch production build clean.

Verified live against the production build (bun run build + bun run start):

  • GET /login?redirect=/... logs as [req] GET /login — query string never appears
  • kube-probe/1.29 requests produce zero lines
  • a 300-char path truncates at 200 with a ...(truncated) marker
  • a 230-request burst logs exactly 200 requests, then [req] suppressed 30 requests in prior window when the next window opens
  • watermark fires on threshold crossing with env-configured thresholds and reports the highest threshold crossed
  • ADMIN_PANEL_REQUEST_LOG=false produces zero request lines under real traffic

Test Configuration:

  • Bun 1.3.11, production build served locally with SESSION_SECRET set
  • Watermark exercised via ADMIN_PANEL_MEMORY_LOG_THRESHOLDS_MB=50,80 so thresholds sit below the server's baseline RSS

Checklist

  • My code adheres to this project's style guidelines
  • I have performed a self-review of my own code
  • I have commented in any complex areas of my code
  • My changes do not introduce new warnings
  • I have written tests demonstrating that my changes are effective or that my feature works
  • Local unit tests pass with my changes

… bun server

The server's only log output is its two startup lines. The HTTP metrics
increment on completion, so a request that kills the process mid-flight
is invisible to them, an uncaught handler throw produces no output at
all, and there is no signal for memory growth between metric scrapes.
Diagnosing a crash or an OOMKill from this is guesswork.

Adds three narrow instruments to the serve path. Request lines log at
arrival (before the handler) and completion, so a fatal request leaves
its method and path as the process's last words; paths are logged
without query strings, truncated, kubelet probes are skipped, and a
per-window cap stops a request flood from amplifying into a log flood
while still surfacing the suppressed count. A memory watermark logs RSS
threshold crossings on a 10s tick to timestamp allocation bursts even
when no request is in flight. An error hook on Bun.serve logs unhandled
handler throws.

On by default; disable with ADMIN_PANEL_REQUEST_LOG=false. Thresholds
configurable via ADMIN_PANEL_MEMORY_LOG_THRESHOLDS_MB.
Comment thread src/server/logging.ts
@dustinhealy

Copy link
Copy Markdown
Contributor Author

@codex review

@chatgpt-codex-connector chatgpt-codex-connector Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

💡 Codex Review

Here are some automated review suggestions for this pull request.

Reviewed commit: 1637d38c56

ℹ️ About Codex in GitHub

Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you

  • Open a pull request for review
  • Mark a draft as ready
  • Comment "@codex review".

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".

Comment thread src/server/logging.ts Outdated
Comment thread server.ts Outdated
Comment thread server.ts Outdated
Comment thread src/server/logging.ts Outdated
Comment thread server.ts
…n Drain

A request could claim to be a kubelet probe and suppress both its arrival and
completion lines, so a failing or hostile request evaded the new diagnostics
entirely. The real probe path already bypasses this wrapper, so the header was
buying nothing; suppression now also requires the request to target /health.

Completion was reported when the handler returned, which for a streamed body
such as the audit-log CSV export happens before any bytes are delivered. That
logged a 200 for transfers that could still fail. Report once the body drains,
and mark the line when the upstream stream errors instead.

Also return the highest crossed memory threshold rather than the last one the
caller happened to list, move the exported logging interfaces into the types
barrel, and document both new environment variables.

@cursor cursor Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Cursor Bugbot has reviewed your changes using high effort and found 1 potential issue.

Fix All in Cursor

❌ Bugbot Autofix is OFF. To automatically fix reported issues with cloud agents, have a team admin enable autofix in the Cursor dashboard.

Reviewed by Cursor Bugbot for commit 13662ef. Configure here.

Comment thread src/server/logging.ts
@dustinhealy

Copy link
Copy Markdown
Contributor Author

@codex re-review

reportOnBodyComplete has three exits that each report an outcome, and the
cancel path races whatever read is in flight. Make the single-report invariant
explicit rather than resting on the stream machinery happening to suppress the
loser of that race, since a duplicated completion line is exactly what muddies
triage on the path this logging exists to serve.

@chatgpt-codex-connector chatgpt-codex-connector Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

💡 Codex Review

Here are some automated review suggestions for this pull request.

Reviewed commit: 13662ef0fc

ℹ️ About Codex in GitHub

Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you

  • Open a pull request for review
  • Mark a draft as ready
  • Comment "@codex review".

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".

Comment thread src/server/logging.ts
Comment thread server.ts Outdated
Comment thread server.ts Outdated
A rejecting handler left only an arrival line: the await exited before a status
was recorded, so the request never got a completion tombstone and Bun's error
line carries no method or path. Catch it in the wrapper, log the 500 with the
request identity, record the metric, and rethrow so the error response is
unchanged.

A HEAD response whose handler still produced a body never completed either, as
Bun discards that body without reading or cancelling it, leaving the monitored
stream unsettled. Report HEAD status immediately instead of waiting on a stream
the server will not consume.
@dustinhealy

Copy link
Copy Markdown
Contributor Author

@codex re-review

@chatgpt-codex-connector chatgpt-codex-connector Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

💡 Codex Review

Here are some automated review suggestions for this pull request.

Reviewed commit: dcd3ffeb60

ℹ️ About Codex in GitHub

Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you

  • Open a pull request for review
  • Mark a draft as ready
  • Comment "@codex review".

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".

Comment thread server.ts
Monitoring a response body replaces it with a JavaScript stream, which for a
Bun.file body costs the sendfile path and the Content-Length Bun derives from the
file. A Bun.file response carries no eager content-length header, so the wrapped
copy had none either and every JS, CSS, font, and image turned into a chunked
transfer, on by default with request logging.

Static routes now report completion as soon as the status is known and hand back
the untouched response. That trades exact delivery timing on assets Bun serves
natively for keeping that native path, and leaves body monitoring where it was
added for: the proxied streams on the dynamic route.
@dustinhealy

Copy link
Copy Markdown
Contributor Author

@codex review

@chatgpt-codex-connector

Copy link
Copy Markdown

Codex Review: Didn't find any major issues. Breezy!

Reviewed commit: fa7c82c8f9

ℹ️ About Codex in GitHub

Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you

  • Open a pull request for review
  • Mark a draft as ready
  • Comment "@codex review".

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".

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant