From 1637d38c56c21b4dc69f96eea54be6d0d879e9a0 Mon Sep 17 00:00:00 2001 From: Dustin Healy <54083382+dustinhealy@users.noreply.github.com> Date: Thu, 30 Jul 2026 07:47:25 -0700 Subject: [PATCH 1/5] feat: request tombstones, memory watermarks, and error logging in the 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. --- server.ts | 59 +++++++++++++++++++- src/server/logging.test.ts | 110 +++++++++++++++++++++++++++++++++++++ src/server/logging.ts | 95 ++++++++++++++++++++++++++++++++ 3 files changed, 261 insertions(+), 3 deletions(-) create mode 100644 src/server/logging.test.ts create mode 100644 src/server/logging.ts diff --git a/server.ts b/server.ts index 2c175ecc..8dfd1758 100644 --- a/server.ts +++ b/server.ts @@ -1,5 +1,12 @@ import { Glob } from 'bun'; import { join } from 'node:path'; +import { + isProbeRequest, + createFloodGuard, + formatLoggedPath, + createMemoryWatermark, + parseMemoryThresholdsMb, +} from './src/server/logging'; import { metricsResponse, httpRequestsTotal, @@ -97,17 +104,44 @@ type Handler = { default: { fetch: (req: Request) => Promise } }; const { default: handler } = (await import(SERVER_ENTRY.href)) as Handler; -async function withHttpMetrics( +const REQUEST_LOG = process.env.ADMIN_PANEL_REQUEST_LOG !== 'false'; +const floodGuard = createFloodGuard(); + +async function withHttpObservability( req: Request, pathname: string, getResponse: () => Response | Promise, ): Promise { const path = normalizeMetricsPath(pathname); const end = httpRequestDurationSeconds.startTimer({ method: req.method, path }); + + // The arrival line is logged before the handler runs so that a request that + // kills the process still leaves its method and path as the last log line. + let logCompletion = false; + let startedAt = 0; + let loggedPath = ''; + if (REQUEST_LOG && !isProbeRequest(req.headers.get('user-agent'))) { + const { admitted, suppressedInPriorWindow } = floodGuard.admit(Date.now()); + if (suppressedInPriorWindow > 0) { + console.log(`[req] suppressed ${suppressedInPriorWindow} requests in prior window`); + } + if (admitted) { + loggedPath = formatLoggedPath(new URL(req.url).pathname); + startedAt = performance.now(); + console.log(`[req] ${req.method} ${loggedPath}`); + logCompletion = true; + } + } + const res = await getResponse(); const statusCode = String(res.status); httpRequestsTotal.inc({ method: req.method, path, status_code: statusCode }); end({ status_code: statusCode }); + if (logCompletion) { + console.log( + `[req] ${req.method} ${loggedPath} ${statusCode} ${Math.round(performance.now() - startedAt)}ms`, + ); + } return res; } @@ -118,7 +152,7 @@ async function buildStaticRoutes(): Promise Pro const cache = getCacheHeaders(path); const routePath = `${BASE_PATH}/${path}`; routes[routePath] = (req) => - withHttpMetrics(req, routePath, () => { + withHttpObservability(req, routePath, () => { const res = new Response(file, { headers: { 'Content-Type': file.type, ...cache } }); applySecurityHeaders(res.headers); return res; @@ -139,7 +173,7 @@ const server = Bun.serve({ const metricsPath = BASE_PATH && url.pathname.startsWith(BASE_PATH) ? url.pathname.slice(BASE_PATH.length) || '/' : url.pathname; - const res = await withHttpMetrics(req, metricsPath, () => handler.fetch(req)); + const res = await withHttpObservability(req, metricsPath, () => handler.fetch(req)); const patched = new Response(res.body, res); for (const [k, v] of Object.entries(NO_CACHE)) { patched.headers.set(k, v); @@ -148,8 +182,27 @@ const server = Bun.serve({ return patched; }, }, + error(error: Error): Response { + console.error(`[error] unhandled server error: ${error.message}`, error.stack ?? ''); + return new Response('Internal Server Error', { status: 500 }); + }, }); +const memoryWatermark = createMemoryWatermark( + parseMemoryThresholdsMb(env.ADMIN_PANEL_MEMORY_LOG_THRESHOLDS_MB), +); +const MEMORY_CHECK_INTERVAL_MS = 10_000; +setInterval(() => { + const { rss, heapUsed } = process.memoryUsage(); + const crossedMb = memoryWatermark.check(rss); + if (crossedMb !== null) { + const mib = 1024 * 1024; + console.log( + `[mem] rss=${Math.round(rss / mib)}Mi heapUsed=${Math.round(heapUsed / mib)}Mi (crossed ${crossedMb}Mi)`, + ); + } +}, MEMORY_CHECK_INTERVAL_MS); + console.log(`Admin panel listening on http://localhost:${server.port}${BASE_PATH}/`); if (!process.env.ADMIN_PANEL_METRICS_SECRET) { diff --git a/src/server/logging.test.ts b/src/server/logging.test.ts new file mode 100644 index 00000000..19277f5d --- /dev/null +++ b/src/server/logging.test.ts @@ -0,0 +1,110 @@ +import { describe, it, expect } from 'vitest'; +import { + isProbeRequest, + createFloodGuard, + formatLoggedPath, + createMemoryWatermark, + parseMemoryThresholdsMb, +} from './logging'; + +const MIB = 1024 * 1024; + +describe('isProbeRequest', () => { + it.each([ + ['kube-probe/1.29', true], + ['kube-probe/1.31+', true], + ['Mozilla/5.0 (Macintosh)', false], + ['curl/8.7.1', false], + ['', false], + [null, false], + ])('user-agent %s -> %s', (userAgent, expected) => { + expect(isProbeRequest(userAgent)).toBe(expected); + }); +}); + +describe('formatLoggedPath', () => { + it('passes short paths through unchanged', () => { + expect(formatLoggedPath('/auth/openid/callback')).toBe('/auth/openid/callback'); + }); + + it('truncates paths beyond 200 characters', () => { + const long = `/${'a'.repeat(500)}`; + const formatted = formatLoggedPath(long); + expect(formatted).toBe(`${long.slice(0, 200)}...(truncated)`); + }); + + it('keeps a path of exactly 200 characters intact', () => { + const exact = `/${'a'.repeat(199)}`; + expect(formatLoggedPath(exact)).toBe(exact); + }); +}); + +describe('createFloodGuard', () => { + it('admits requests up to the cap within one window', () => { + const guard = createFloodGuard(3, 10_000); + expect(guard.admit(1_000).admitted).toBe(true); + expect(guard.admit(2_000).admitted).toBe(true); + expect(guard.admit(3_000).admitted).toBe(true); + expect(guard.admit(4_000).admitted).toBe(false); + expect(guard.admit(5_000).admitted).toBe(false); + }); + + it('reports the suppressed count once when a new window opens', () => { + const guard = createFloodGuard(2, 10_000); + guard.admit(1_000); + guard.admit(2_000); + guard.admit(3_000); + guard.admit(4_000); + const next = guard.admit(12_000); + expect(next.admitted).toBe(true); + expect(next.suppressedInPriorWindow).toBe(2); + expect(guard.admit(13_000).suppressedInPriorWindow).toBe(0); + }); + + it('resets the admission budget each window', () => { + const guard = createFloodGuard(1, 10_000); + expect(guard.admit(0).admitted).toBe(true); + expect(guard.admit(1).admitted).toBe(false); + expect(guard.admit(10_000).admitted).toBe(true); + expect(guard.admit(10_001).admitted).toBe(false); + }); +}); + +describe('parseMemoryThresholdsMb', () => { + it.each([ + [undefined, [256, 384, 448]], + ['', [256, 384, 448]], + ['100,200,300', [100, 200, 300]], + ['300, 100, 200', [100, 200, 300]], + ['512', [512]], + ['abc,-5,0', [256, 384, 448]], + ['abc,128', [128]], + ])('parses %s -> %s', (raw, expected) => { + expect(parseMemoryThresholdsMb(raw)).toEqual(expected); + }); +}); + +describe('createMemoryWatermark', () => { + it('fires once per upward crossing and reports the highest threshold crossed', () => { + const watermark = createMemoryWatermark([256, 384, 448]); + expect(watermark.check(100 * MIB)).toBeNull(); + expect(watermark.check(260 * MIB)).toBe(256); + expect(watermark.check(270 * MIB)).toBeNull(); + expect(watermark.check(460 * MIB)).toBe(448); + }); + + it('re-arms a threshold after memory drops back below it', () => { + const watermark = createMemoryWatermark([256]); + expect(watermark.check(300 * MIB)).toBe(256); + expect(watermark.check(310 * MIB)).toBeNull(); + expect(watermark.check(200 * MIB)).toBeNull(); + expect(watermark.check(300 * MIB)).toBe(256); + }); + + it('stays silent while memory remains flat below every threshold', () => { + const watermark = createMemoryWatermark([256, 384, 448]); + expect(watermark.check(101 * MIB)).toBeNull(); + expect(watermark.check(102 * MIB)).toBeNull(); + expect(watermark.check(101 * MIB)).toBeNull(); + }); +}); diff --git a/src/server/logging.ts b/src/server/logging.ts new file mode 100644 index 00000000..ce467d9f --- /dev/null +++ b/src/server/logging.ts @@ -0,0 +1,95 @@ +const MAX_LOGGED_PATH_LENGTH = 200; +const DEFAULT_MEMORY_THRESHOLDS_MB = [256, 384, 448]; + +export const FLOOD_WINDOW_MS = 10_000; +export const FLOOD_MAX_REQUESTS = 200; + +/** Kubelet health probes identify themselves via User-Agent; logging them would drown real traffic. */ +export function isProbeRequest(userAgent: string | null): boolean { + return userAgent !== null && userAgent.startsWith('kube-probe/'); +} + +/** Never logs query strings (they can carry OAuth exchange codes); caps length against scanner URLs. */ +export function formatLoggedPath(pathname: string): string { + if (pathname.length <= MAX_LOGGED_PATH_LENGTH) return pathname; + return `${pathname.slice(0, MAX_LOGGED_PATH_LENGTH)}...(truncated)`; +} + +export interface FloodGuardDecision { + admitted: boolean; + suppressedInPriorWindow: number; +} + +export interface FloodGuard { + admit: (nowMs: number) => FloodGuardDecision; +} + +/** + * Caps logged requests per fixed window so a request flood can't amplify into + * a log flood; the count of suppressed requests is surfaced once when the + * next window opens, so the flood itself stays visible. + */ +export function createFloodGuard( + maxRequests: number = FLOOD_MAX_REQUESTS, + windowMs: number = FLOOD_WINDOW_MS, +): FloodGuard { + let windowStart = 0; + let admittedInWindow = 0; + let suppressedInWindow = 0; + + return { + admit(nowMs: number): FloodGuardDecision { + let suppressedInPriorWindow = 0; + if (nowMs - windowStart >= windowMs) { + suppressedInPriorWindow = suppressedInWindow; + windowStart = nowMs; + admittedInWindow = 0; + suppressedInWindow = 0; + } + if (admittedInWindow < maxRequests) { + admittedInWindow += 1; + return { admitted: true, suppressedInPriorWindow }; + } + suppressedInWindow += 1; + return { admitted: false, suppressedInPriorWindow }; + }, + }; +} + +export function parseMemoryThresholdsMb(raw: string | undefined): number[] { + if (!raw) return DEFAULT_MEMORY_THRESHOLDS_MB; + const parsed = raw + .split(',') + .map((value) => Number(value.trim())) + .filter((value) => Number.isFinite(value) && value > 0); + if (parsed.length === 0) return DEFAULT_MEMORY_THRESHOLDS_MB; + return [...parsed].sort((a, b) => a - b); +} + +export interface MemoryWatermark { + /** Returns the highest threshold (in MiB) newly crossed upward, or null. */ + check: (rssBytes: number) => number | null; +} + +const BYTES_PER_MIB = 1024 * 1024; + +/** + * Fires once per upward crossing of each threshold; a threshold re-arms when + * RSS drops back below it, so a sawtooth pattern logs each climb without + * repeating on every tick spent above a threshold. + */ +export function createMemoryWatermark(thresholdsMb: number[]): MemoryWatermark { + let lastRssMb = 0; + + return { + check(rssBytes: number): number | null { + const rssMb = rssBytes / BYTES_PER_MIB; + let crossed: number | null = null; + for (const threshold of thresholdsMb) { + if (lastRssMb < threshold && rssMb >= threshold) crossed = threshold; + } + lastRssMb = rssMb; + return crossed; + }, + }; +} From 13662ef0fc86c964546445b5eec9994f49a177d6 Mon Sep 17 00:00:00 2001 From: Dustin Healy <54083382+dustinhealy@users.noreply.github.com> Date: Sun, 9 Aug 2026 15:43:24 -0700 Subject: [PATCH 2/5] =?UTF-8?q?=F0=9F=9B=82=20fix:=20Stop=20Trusting=20Use?= =?UTF-8?q?r-Agent=20For=20Log=20Suppression,=20Report=20Streams=20On=20Dr?= =?UTF-8?q?ain?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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. --- .env.example | 4 ++ server.ts | 16 ++++---- src/server/logging.test.ts | 68 +++++++++++++++++++++++++++++++- src/server/logging.ts | 80 ++++++++++++++++++++++++++++---------- src/types/server.ts | 14 +++++++ 5 files changed, 153 insertions(+), 29 deletions(-) diff --git a/.env.example b/.env.example index a62d10f4..43fee13d 100644 --- a/.env.example +++ b/.env.example @@ -55,3 +55,7 @@ SESSION_SECRET= # ADMIN_PANEL_INDEX_CACHE_CONTROL= # overrides INDEX_CACHE_CONTROL for admin panel # ADMIN_PANEL_INDEX_PRAGMA= # overrides INDEX_PRAGMA for admin panel # ADMIN_PANEL_INDEX_EXPIRES= # overrides INDEX_EXPIRES for admin panel + +# Request and memory observability +# ADMIN_PANEL_REQUEST_LOG=false # disables request arrival/completion logging (default: enabled) +# ADMIN_PANEL_MEMORY_LOG_THRESHOLDS_MB=256,384,448 # RSS thresholds in MiB, each logged once per upward crossing diff --git a/server.ts b/server.ts index 8dfd1758..fe960e9b 100644 --- a/server.ts +++ b/server.ts @@ -2,6 +2,7 @@ import { Glob } from 'bun'; import { join } from 'node:path'; import { isProbeRequest, + reportOnBodyComplete, createFloodGuard, formatLoggedPath, createMemoryWatermark, @@ -120,7 +121,7 @@ async function withHttpObservability( let logCompletion = false; let startedAt = 0; let loggedPath = ''; - if (REQUEST_LOG && !isProbeRequest(req.headers.get('user-agent'))) { + if (REQUEST_LOG && !isProbeRequest(req.headers.get('user-agent'), new URL(req.url).pathname)) { const { admitted, suppressedInPriorWindow } = floodGuard.admit(Date.now()); if (suppressedInPriorWindow > 0) { console.log(`[req] suppressed ${suppressedInPriorWindow} requests in prior window`); @@ -137,12 +138,13 @@ async function withHttpObservability( const statusCode = String(res.status); httpRequestsTotal.inc({ method: req.method, path, status_code: statusCode }); end({ status_code: statusCode }); - if (logCompletion) { - console.log( - `[req] ${req.method} ${loggedPath} ${statusCode} ${Math.round(performance.now() - startedAt)}ms`, - ); - } - return res; + if (!logCompletion) return res; + + return reportOnBodyComplete(res, (outcome) => { + const elapsed = Math.round(performance.now() - startedAt); + const suffix = outcome === 'stream-error' ? ' stream-error' : ''; + console.log(`[req] ${req.method} ${loggedPath} ${statusCode} ${elapsed}ms${suffix}`); + }); } async function buildStaticRoutes(): Promise Promise>> { diff --git a/src/server/logging.test.ts b/src/server/logging.test.ts index 19277f5d..0bc9c6a4 100644 --- a/src/server/logging.test.ts +++ b/src/server/logging.test.ts @@ -4,6 +4,7 @@ import { createFloodGuard, formatLoggedPath, createMemoryWatermark, + reportOnBodyComplete, parseMemoryThresholdsMb, } from './logging'; @@ -17,9 +18,16 @@ describe('isProbeRequest', () => { ['curl/8.7.1', false], ['', false], [null, false], - ])('user-agent %s -> %s', (userAgent, expected) => { - expect(isProbeRequest(userAgent)).toBe(expected); + ])('user-agent %s on the probe path -> %s', (userAgent, expected) => { + expect(isProbeRequest(userAgent, '/health')).toBe(expected); }); + + it.each(['/', '/api/config', '/admin/users'])( + 'refuses to suppress %s even for a probe user-agent', + (pathname) => { + expect(isProbeRequest('kube-probe/1.29', pathname)).toBe(false); + }, + ); }); describe('formatLoggedPath', () => { @@ -85,6 +93,12 @@ describe('parseMemoryThresholdsMb', () => { }); describe('createMemoryWatermark', () => { + it('reports the highest crossed threshold regardless of caller ordering', () => { + const watermark = createMemoryWatermark([448, 256, 384]); + + expect(watermark.check(500 * MIB)).toBe(448); + }); + it('fires once per upward crossing and reports the highest threshold crossed', () => { const watermark = createMemoryWatermark([256, 384, 448]); expect(watermark.check(100 * MIB)).toBeNull(); @@ -108,3 +122,53 @@ describe('createMemoryWatermark', () => { expect(watermark.check(101 * MIB)).toBeNull(); }); }); + +describe('reportOnBodyComplete', () => { + it('reports immediately for a bodyless response', () => { + const outcomes: string[] = []; + const res = reportOnBodyComplete(new Response(null, { status: 204 }), (o) => outcomes.push(o)); + + expect(outcomes).toEqual(['ok']); + expect(res.status).toBe(204); + }); + + it('waits for the stream to drain before reporting success', async () => { + const outcomes: string[] = []; + const body = new ReadableStream({ + start(controller) { + controller.enqueue(new TextEncoder().encode('chunk')); + controller.close(); + }, + }); + + const res = reportOnBodyComplete(new Response(body, { status: 200 }), (o) => outcomes.push(o)); + expect(outcomes).toEqual([]); + + await res.text(); + expect(outcomes).toEqual(['ok']); + }); + + it('reports a stream error when the upstream body fails mid-transfer', async () => { + const outcomes: string[] = []; + const body = new ReadableStream({ + start(controller) { + controller.enqueue(new TextEncoder().encode('partial')); + controller.error(new Error('upstream died')); + }, + }); + + const res = reportOnBodyComplete(new Response(body, { status: 200 }), (o) => outcomes.push(o)); + await expect(res.text()).rejects.toThrow(); + expect(outcomes).toEqual(['stream-error']); + }); + + it('preserves status and headers', () => { + const res = reportOnBodyComplete( + new Response('csv', { status: 200, headers: { 'content-type': 'text/csv' } }), + () => {}, + ); + + expect(res.status).toBe(200); + expect(res.headers.get('content-type')).toBe('text/csv'); + }); +}); diff --git a/src/server/logging.ts b/src/server/logging.ts index ce467d9f..4ff6dd74 100644 --- a/src/server/logging.ts +++ b/src/server/logging.ts @@ -1,11 +1,20 @@ +import type * as t from '@/types'; const MAX_LOGGED_PATH_LENGTH = 200; const DEFAULT_MEMORY_THRESHOLDS_MB = [256, 384, 448]; export const FLOOD_WINDOW_MS = 10_000; export const FLOOD_MAX_REQUESTS = 200; -/** Kubelet health probes identify themselves via User-Agent; logging them would drown real traffic. */ -export function isProbeRequest(userAgent: string | null): boolean { +/** Paths a kubelet probe is allowed to reach; anything else must stay loggable. */ +const PROBE_PATHS = new Set(['/health']); + +/** + * Kubelet health probes identify themselves via User-Agent, but that header is + * client-controlled, so the path is required too. Without it any request could + * claim to be a probe and suppress its own arrival and completion lines. + */ +export function isProbeRequest(userAgent: string | null, pathname: string): boolean { + if (!PROBE_PATHS.has(pathname)) return false; return userAgent !== null && userAgent.startsWith('kube-probe/'); } @@ -15,15 +24,6 @@ export function formatLoggedPath(pathname: string): string { return `${pathname.slice(0, MAX_LOGGED_PATH_LENGTH)}...(truncated)`; } -export interface FloodGuardDecision { - admitted: boolean; - suppressedInPriorWindow: number; -} - -export interface FloodGuard { - admit: (nowMs: number) => FloodGuardDecision; -} - /** * Caps logged requests per fixed window so a request flood can't amplify into * a log flood; the count of suppressed requests is surfaced once when the @@ -32,13 +32,13 @@ export interface FloodGuard { export function createFloodGuard( maxRequests: number = FLOOD_MAX_REQUESTS, windowMs: number = FLOOD_WINDOW_MS, -): FloodGuard { +): t.FloodGuard { let windowStart = 0; let admittedInWindow = 0; let suppressedInWindow = 0; return { - admit(nowMs: number): FloodGuardDecision { + admit(nowMs: number): t.FloodGuardDecision { let suppressedInPriorWindow = 0; if (nowMs - windowStart >= windowMs) { suppressedInPriorWindow = suppressedInWindow; @@ -66,11 +66,6 @@ export function parseMemoryThresholdsMb(raw: string | undefined): number[] { return [...parsed].sort((a, b) => a - b); } -export interface MemoryWatermark { - /** Returns the highest threshold (in MiB) newly crossed upward, or null. */ - check: (rssBytes: number) => number | null; -} - const BYTES_PER_MIB = 1024 * 1024; /** @@ -78,7 +73,7 @@ const BYTES_PER_MIB = 1024 * 1024; * RSS drops back below it, so a sawtooth pattern logs each climb without * repeating on every tick spent above a threshold. */ -export function createMemoryWatermark(thresholdsMb: number[]): MemoryWatermark { +export function createMemoryWatermark(thresholdsMb: number[]): t.MemoryWatermark { let lastRssMb = 0; return { @@ -86,10 +81,55 @@ export function createMemoryWatermark(thresholdsMb: number[]): MemoryWatermark { const rssMb = rssBytes / BYTES_PER_MIB; let crossed: number | null = null; for (const threshold of thresholdsMb) { - if (lastRssMb < threshold && rssMb >= threshold) crossed = threshold; + if (lastRssMb >= threshold || rssMb < threshold) continue; + if (crossed === null || threshold > crossed) crossed = threshold; } lastRssMb = rssMb; return crossed; }, }; } + +/** + * Wraps a streaming body so completion is reported once the bytes are actually + * delivered. A handler that returns a `Response` built from an upstream stream + * resolves before transfer, so logging at that point would claim success for a + * transfer that can still fail mid-flight. + */ +export function reportOnBodyComplete( + res: Response, + report: (outcome: 'ok' | 'stream-error') => void, +): Response { + if (res.body === null) { + report('ok'); + return res; + } + + const source = res.body.getReader(); + const monitored = new ReadableStream({ + async pull(controller) { + try { + const { done, value } = await source.read(); + if (done) { + controller.close(); + report('ok'); + return; + } + controller.enqueue(value); + } catch (err) { + controller.error(err); + report('stream-error'); + } + }, + cancel(reason) { + report('stream-error'); + return source.cancel(reason); + }, + }); + + return new Response(monitored, { + status: res.status, + statusText: res.statusText, + headers: res.headers, + }); +} diff --git a/src/types/server.ts b/src/types/server.ts index 52cbd117..61edeaf5 100644 --- a/src/types/server.ts +++ b/src/types/server.ts @@ -36,3 +36,17 @@ export interface OAuthExchangeResponse { user: SerializableUser; expiresAt?: number; } + +export interface FloodGuardDecision { + admitted: boolean; + suppressedInPriorWindow: number; +} + +export interface FloodGuard { + admit: (nowMs: number) => FloodGuardDecision; +} + +export interface MemoryWatermark { + /** Returns the highest threshold (in MiB) newly crossed upward, or null. */ + check: (rssBytes: number) => number | null; +} From 5654482b90e05f9df4960fa8b8d185cc52aa3f22 Mon Sep 17 00:00:00 2001 From: Dustin Healy <54083382+dustinhealy@users.noreply.github.com> Date: Sun, 9 Aug 2026 15:54:15 -0700 Subject: [PATCH 3/5] =?UTF-8?q?=F0=9F=9B=82=20fix:=20State=20The=20Report-?= =?UTF-8?q?Once=20Invariant=20For=20Streamed=20Completion=20Lines?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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. --- src/server/logging.test.ts | 15 +++++++++++++++ src/server/logging.ts | 14 +++++++++++--- 2 files changed, 26 insertions(+), 3 deletions(-) diff --git a/src/server/logging.test.ts b/src/server/logging.test.ts index 0bc9c6a4..0708590b 100644 --- a/src/server/logging.test.ts +++ b/src/server/logging.test.ts @@ -162,6 +162,21 @@ describe('reportOnBodyComplete', () => { expect(outcomes).toEqual(['stream-error']); }); + it('reports once when a cancel races a pending read', async () => { + const outcomes: string[] = []; + /** Never enqueues, so the wrapper's read is still pending when the cancel lands. */ + const body = new ReadableStream({ start() {} }); + + const res = reportOnBodyComplete(new Response(body, { status: 200 }), (o) => outcomes.push(o)); + const reader = res.body!.getReader(); + const pending = reader.read(); + await reader.cancel('client gone'); + await pending.catch(() => {}); + await new Promise((resolve) => setTimeout(resolve, 0)); + + expect(outcomes).toEqual(['stream-error']); + }); + it('preserves status and headers', () => { const res = reportOnBodyComplete( new Response('csv', { status: 200, headers: { 'content-type': 'text/csv' } }), diff --git a/src/server/logging.ts b/src/server/logging.ts index 4ff6dd74..0ab44965 100644 --- a/src/server/logging.ts +++ b/src/server/logging.ts @@ -105,6 +105,13 @@ export function reportOnBodyComplete( return res; } + let reported = false; + const reportOnce = (outcome: 'ok' | 'stream-error'): void => { + if (reported) return; + reported = true; + report(outcome); + }; + const source = res.body.getReader(); const monitored = new ReadableStream({ async pull(controller) { @@ -112,17 +119,18 @@ export function reportOnBodyComplete( const { done, value } = await source.read(); if (done) { controller.close(); - report('ok'); + reportOnce('ok'); return; } controller.enqueue(value); } catch (err) { controller.error(err); - report('stream-error'); + reportOnce('stream-error'); } }, cancel(reason) { - report('stream-error'); + /** A cancel races any in-flight read, whose rejection would otherwise report a second time. */ + reportOnce('stream-error'); return source.cancel(reason); }, }); From dcd3ffeb607470e30deb024cfa157679bf5994fe Mon Sep 17 00:00:00 2001 From: Dustin Healy <54083382+dustinhealy@users.noreply.github.com> Date: Sun, 9 Aug 2026 16:03:54 -0700 Subject: [PATCH 4/5] =?UTF-8?q?=F0=9F=AA=A6=20fix:=20Close=20The=20Arrival?= =?UTF-8?q?=20Tombstone=20On=20Handler=20Throws=20And=20HEAD=20Requests?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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. --- server.ts | 33 +++++++++++++++++++++++++++------ 1 file changed, 27 insertions(+), 6 deletions(-) diff --git a/server.ts b/server.ts index fe960e9b..9e32ce81 100644 --- a/server.ts +++ b/server.ts @@ -134,17 +134,38 @@ async function withHttpObservability( } } - const res = await getResponse(); + const logDone = (status: string, note = ''): void => { + const elapsed = Math.round(performance.now() - startedAt); + console.log(`[req] ${req.method} ${loggedPath} ${status} ${elapsed}ms${note}`); + }; + + let res: Response; + try { + res = await getResponse(); + } catch (err) { + // Bun's error callback turns this into a 500, but that line carries no method or + // path, so the arrival tombstone would otherwise never be closed out. + httpRequestsTotal.inc({ method: req.method, path, status_code: '500' }); + end({ status_code: '500' }); + if (logCompletion) logDone('500', ' handler-error'); + throw err; + } + const statusCode = String(res.status); httpRequestsTotal.inc({ method: req.method, path, status_code: statusCode }); end({ status_code: statusCode }); if (!logCompletion) return res; - return reportOnBodyComplete(res, (outcome) => { - const elapsed = Math.round(performance.now() - startedAt); - const suffix = outcome === 'stream-error' ? ' stream-error' : ''; - console.log(`[req] ${req.method} ${loggedPath} ${statusCode} ${elapsed}ms${suffix}`); - }); + // Bun discards a HEAD body without reading or cancelling it, so a monitored + // stream would never settle and the completion line would never be emitted. + if (req.method === 'HEAD') { + logDone(statusCode); + return res; + } + + return reportOnBodyComplete(res, (outcome) => + logDone(statusCode, outcome === 'stream-error' ? ' stream-error' : ''), + ); } async function buildStaticRoutes(): Promise Promise>> { From fa7c82c8f9b0188d9415b3b7b9ade5f72219dd2e Mon Sep 17 00:00:00 2001 From: Dustin Healy <54083382+dustinhealy@users.noreply.github.com> Date: Sun, 9 Aug 2026 16:46:18 -0700 Subject: [PATCH 5/5] =?UTF-8?q?=E2=9A=A1=20fix:=20Leave=20Native=20File=20?= =?UTF-8?q?Bodies=20Unwrapped=20For=20Static=20Assets?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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. --- server.ts | 21 +++++++++++++++------ 1 file changed, 15 insertions(+), 6 deletions(-) diff --git a/server.ts b/server.ts index 9e32ce81..53b9e4c4 100644 --- a/server.ts +++ b/server.ts @@ -112,6 +112,7 @@ async function withHttpObservability( req: Request, pathname: string, getResponse: () => Response | Promise, + options?: { monitorBody?: boolean }, ): Promise { const path = normalizeMetricsPath(pathname); const end = httpRequestDurationSeconds.startTimer({ method: req.method, path }); @@ -158,7 +159,10 @@ async function withHttpObservability( // Bun discards a HEAD body without reading or cancelling it, so a monitored // stream would never settle and the completion line would never be emitted. - if (req.method === 'HEAD') { + // A native file body must also be left intact: replacing it with a JavaScript + // stream costs Bun's sendfile path and the Content-Length it derives from the + // file, turning every static asset into a chunked transfer. + if (req.method === 'HEAD' || options?.monitorBody === false) { logDone(statusCode); return res; } @@ -175,11 +179,16 @@ async function buildStaticRoutes(): Promise Pro const cache = getCacheHeaders(path); const routePath = `${BASE_PATH}/${path}`; routes[routePath] = (req) => - withHttpObservability(req, routePath, () => { - const res = new Response(file, { headers: { 'Content-Type': file.type, ...cache } }); - applySecurityHeaders(res.headers); - return res; - }); + withHttpObservability( + req, + routePath, + () => { + const res = new Response(file, { headers: { 'Content-Type': file.type, ...cache } }); + applySecurityHeaders(res.headers); + return res; + }, + { monitorBody: false }, + ); } return routes; }