diff --git a/README.md b/README.md index 9f4873a..b3cb468 100644 --- a/README.md +++ b/README.md @@ -108,7 +108,8 @@ doctor` as a blocking failure) — the durable abuse-control prerequisites do no development/test composition may enable it. Every public body-consuming route — Better Auth, Core's grant-mutation endpoint, and every module route (via a new, required `maxBodyBytes` field on the executable route contract) — now has an explicit, platform-enforced byte ceiling with one -sanitized `413` contract. The Node HTTP server now has finite header/request timeouts. See +sanitized `413` contract. The Node HTTP server now has finite header/request timeouts, whose real +transport-level failures are observed and logged in sanitized form. See [API](docs/development/api.md), [Module development](docs/module-development/README.md#http-routes), and [ADR 0017](docs/architecture/decisions/0017-public-request-perimeter-hardening.md). **This pass does not add distributed rate limiting, durable public-signup abuse control, or any deployment/TLS diff --git a/apps/api/src/server.ts b/apps/api/src/server.ts index 3141ab6..9c85247 100644 --- a/apps/api/src/server.ts +++ b/apps/api/src/server.ts @@ -1,3 +1,4 @@ +import type { Socket } from "node:net"; import path from "node:path"; import { pathToFileURL } from "node:url"; import type { ModuleRuntimeServices } from "@ekklesia/contracts"; @@ -64,9 +65,48 @@ const PRODUCTION_NODE_SERVER_TIMEOUTS: NodeServerTimeouts = Object.freeze({ requestTimeoutMs: 30_000, }); -/** Never carries the remote address, request path, headers, or any other connection detail. */ +/** + * The two fixed operational lines a transport-level client failure may produce. Neither ever + * carries the remote address, request path, query, headers, cookies, body, forwarding chain, the + * caught error's own message, or the malformed bytes that caused it — an attacker controls all of + * those, and a parse failure's message in particular is derived directly from the rejected input. + */ const NODE_SERVER_TIMEOUT_LOG_MESSAGE = "[server] A connection was closed for exceeding a configured header/request timeout."; +const NODE_SERVER_CLIENT_ERROR_LOG_MESSAGE = + "[server] A connection was closed after a malformed or oversized client request."; + +/** + * Node's own documented default `clientError` responses, reproduced byte-for-byte (verified + * directly against the pinned Node 24 runtime by driving each case through a real socket with no + * listener attached). Registering *any* `clientError` listener suppresses that default entirely — + * `_http_server.js` only falls back when `server.emit("clientError", ...)` returns `false` — so a + * listener that merely observes would silently turn every 408/400/431 into a bare connection reset. + * Reproducing the exact bytes is what lets the platform log the event without changing what a + * caller actually receives. + */ +const NODE_CLIENT_ERROR_RESPONSES: Readonly> = Object.freeze({ + ERR_HTTP_REQUEST_TIMEOUT: "HTTP/1.1 408 Request Timeout\r\nConnection: close\r\n\r\n", + HPE_HEADER_OVERFLOW: "HTTP/1.1 431 Request Header Fields Too Large\r\nConnection: close\r\n\r\n", +}); +const NODE_CLIENT_ERROR_DEFAULT_RESPONSE = "HTTP/1.1 400 Bad Request\r\nConnection: close\r\n\r\n"; + +/** + * Mirrors Node's own `socketOnError` fallback exactly: write the code-appropriate response only + * when the socket is still writable *and* no response has already begun for the in-flight request, + * then destroy the socket. The `_httpMessage` guard is what prevents a second, corrupting status + * line when a handler already responded and only the (unread) request body subsequently timed out. + */ +function writeNodeClientErrorResponse(error: NodeJS.ErrnoException, socket: Socket): void { + const inFlightResponse = (socket as Socket & { _httpMessage?: { headersSent?: boolean } }) + ._httpMessage; + const alreadyResponding = inFlightResponse?.headersSent === true; + if (socket.writable && !alreadyResponding) { + const code = typeof error.code === "string" ? error.code : ""; + socket.write(NODE_CLIENT_ERROR_RESPONSES[code] ?? NODE_CLIENT_ERROR_DEFAULT_RESPONSE); + } + socket.destroy(); +} export interface RunningApi { readonly app: Hono; @@ -150,12 +190,20 @@ function bindServer( } }, ); - // A sanitized operational observation only — Node's own headersTimeout/requestTimeout - // enforcement already closes the connection (and, for requestTimeout, sends a 408) regardless - // of whether anything is listening here; this never carries the remote address, headers, or any - // other request detail. - server.on("timeout", () => { - console.error(NODE_SERVER_TIMEOUT_LOG_MESSAGE); + // `headersTimeout`/`requestTimeout` do NOT surface as the server's general `'timeout'` event — + // that event only fires for `server.setTimeout()`'s idle-socket timer, which this server never + // arms. Verified directly against the pinned Node 24 runtime by driving a real slow-header and + // slow-body connection through a real socket: the only server-level event either produces is + // `'clientError'`, carrying `err.code === "ERR_HTTP_REQUEST_TIMEOUT"`. Observing the failure + // therefore has to happen here, and — because registering a listener suppresses Node's own + // default response — this handler must reproduce that default itself. + server.on("clientError", (error: NodeJS.ErrnoException, socket: Socket) => { + console.error( + error.code === "ERR_HTTP_REQUEST_TIMEOUT" + ? NODE_SERVER_TIMEOUT_LOG_MESSAGE + : NODE_SERVER_CLIENT_ERROR_LOG_MESSAGE, + ); + writeNodeClientErrorResponse(error, socket); }); server.once("error", () => { if (!settled) { diff --git a/apps/api/tests/api-http.integration.ts b/apps/api/tests/api-http.integration.ts index 0bbf2ef..28c1231 100644 --- a/apps/api/tests/api-http.integration.ts +++ b/apps/api/tests/api-http.integration.ts @@ -1948,69 +1948,29 @@ describe.sequential("live API — client-address resolution and auth rate-limit }); }); -describe.sequential("live API — Node header/request timeouts", () => { - it("closes a connection whose headers never complete within the configured headersTimeout, never invoking a handler", async () => { - const database = await createDisposableDatabase("node_timeouts"); - await applyCoreMigrations(database.url); - const config = createApiRuntimeConfig( - { - databaseUrl: database.url, - host: "127.0.0.1", - identity: { - baseUrl: identityBaseUrl, - publicSignupEnabled: false, - secret: "integration-test-secret-0123456789abcdefgh", - trustedOrigins: [identityBaseUrl], - }, - port: 0, - }, - { environment: "production" }, - ); - // Deliberately tiny, test-only timeouts — production composition (server.ts's `main`) never - // sets this override — so this test observes the real transport-event close deterministically, - // in well under a second, rather than waiting out the production values. - const running = await startApi(config, { - nodeServerTimeoutOverride: { - connectionsCheckingIntervalMs: 100, - headersTimeoutMs: 200, - keepAliveTimeoutMs: 200, - requestTimeoutMs: 300, - }, - }); - try { - const address = running.server.address(); - if (!address || typeof address !== "object") { - throw harnessError("The API integration server has no bound address."); - } - - const socket = net.connect({ host: "127.0.0.1", port: address.port }); - await new Promise((resolve, reject) => { - socket.once("connect", () => resolve()); - socket.once("error", reject); - }); - const receivedChunks: Buffer[] = []; - // A `net.Socket` stays paused (and never surfaces the peer's eventual FIN as `close`) until - // something actively consumes its readable side — attaching this listener is what makes the - // socket start flowing, not merely a way to capture the response for the assertion below. - socket.on("data", (chunk) => receivedChunks.push(chunk as Buffer)); - const closed = new Promise((resolve) => socket.once("close", resolve)); - - // An incomplete request: a request line and one header, deliberately never terminated by the - // blank line that would mark the end of the headers, and no further data ever sent. - socket.write("GET /api/v1/principal HTTP/1.1\r\nHost: 127.0.0.1\r\n"); - - await closed; - expect(socket.destroyed).toBe(true); - const received = Buffer.concat(receivedChunks).toString("utf8"); - expect(received).toContain("408"); - } finally { - await running.shutdown().catch(() => undefined); - await dropDatabase(database.name); - } - }); - - it("closes a connection whose body never completes within the configured requestTimeout, never invoking a handler or writing a second response", async () => { - const database = await createDisposableDatabase("node_timeouts_body"); +describe.sequential("live API — Node header/request timeouts and client errors", () => { + /** + * Drives one raw, deliberately-malformed or deliberately-slow byte sequence through a real + * listening API and returns everything observable at the transport boundary, plus everything the + * *real* production logging seam (`console.error`, which `apps/api/src/server.ts` writes its + * sanitized operational line through) actually emitted while it happened. + * + * This is the only shape of proof that counts for the timeout-observability claim: no event is + * manually emitted, no logger is called directly, and nothing asserts merely that a listener was + * registered — a real socket is opened against a real server, real bytes are written, and the + * real Node transport is left to do whatever it genuinely does. + */ + async function driveRawConnection( + label: string, + write: (socket: net.Socket) => void, + timeouts: Partial = { + connectionsCheckingIntervalMs: 100, + headersTimeoutMs: 200, + keepAliveTimeoutMs: 200, + requestTimeoutMs: 300, + }, + ): Promise<{ destroyed: boolean; logs: string[]; received: string }> { + const database = await createDisposableDatabase(label); await applyCoreMigrations(database.url); const config = createApiRuntimeConfig( { @@ -2026,14 +1986,11 @@ describe.sequential("live API — Node header/request timeouts", () => { }, { environment: "production" }, ); - const running = await startApi(config, { - nodeServerTimeoutOverride: { - connectionsCheckingIntervalMs: 100, - headersTimeoutMs: 300, - keepAliveTimeoutMs: 200, - requestTimeoutMs: 400, - }, - }); + // Deliberately tiny, test-only timeouts — production composition (server.ts's `main`) never + // sets this override — so a real timeout is observed deterministically in well under a second + // rather than by waiting out the production values. + const running = await startApi(config, { nodeServerTimeoutOverride: timeouts }); + const errorSpy = vi.spyOn(console, "error").mockImplementation(() => undefined); try { const address = running.server.address(); if (!address || typeof address !== "object") { @@ -2046,29 +2003,134 @@ describe.sequential("live API — Node header/request timeouts", () => { socket.once("error", reject); }); const receivedChunks: Buffer[] = []; + // A `net.Socket` stays paused (and never surfaces the peer's eventual FIN as `close`) until + // something actively consumes its readable side — attaching this listener is what makes the + // socket start flowing, not merely a way to capture the response for the assertions below. socket.on("data", (chunk) => receivedChunks.push(chunk as Buffer)); + socket.on("error", () => undefined); const closed = new Promise((resolve) => socket.once("close", resolve)); - // Complete, well-formed headers declaring a body that never actually arrives. - socket.write( - "POST /api/auth/sign-in/email HTTP/1.1\r\n" + - "Host: 127.0.0.1\r\n" + - "Content-Type: application/json\r\n" + - "Content-Length: 1000\r\n" + - "\r\n" + - '{"partial":', - ); - + write(socket); await closed; - const received = Buffer.concat(receivedChunks).toString("utf8"); - // Node's own documented requestTimeout behavior: a 408, never a real sign-in attempt (which - // would need the complete body to ever reach Better Auth), and never a second response. - expect(received).toContain("408"); - expect(received).not.toContain("Set-Cookie"); - expect(received.match(/^HTTP\/1\.1 \d{3}/gmu)?.length ?? 0).toBeLessThanOrEqual(1); + + const logs = errorSpy.mock.calls.flat().map((value) => String(value)); + return { + destroyed: socket.destroyed, + logs, + received: Buffer.concat(receivedChunks).toString("utf8"), + }; } finally { + errorSpy.mockRestore(); await running.shutdown().catch(() => undefined); await dropDatabase(database.name); } + } + + /** Every status line in a response stream — more than one would mean the platform corrupted the + * connection by writing a second response after Node (or a handler) already wrote one. */ + function statusLines(received: string): readonly string[] { + return received.match(/^HTTP\/1\.1 \d{3}[^\r\n]*/gmu) ?? []; + } + + /** The exact operational line `apps/api/src/server.ts` promises for a transport-level client + * failure — no request path, query, body, cookie, authorization value, client-address header, + * forwarding chain, raw peer address, stack, or parser payload may appear anywhere in the logs. */ + function expectSanitizedTransportLog(logs: readonly string[]): void { + expect(logs).toHaveLength(1); + const emitted = logs.join("\n"); + for (const forbidden of [ + "/api/v1/principal", + "/api/auth", + "127.0.0.1", + "Cookie", + "cookie", + "Authorization", + "authorization", + "x-forwarded-for", + "x-ekklesia-client-address", + "partial", + "Parse Error", + "HPE_", + "ERR_HTTP_REQUEST_TIMEOUT", + "at ", + ]) { + expect(emitted).not.toContain(forbidden); + } + } + + it("answers a never-completed header sequence with exactly one 408, closes the socket, invokes no handler, and emits exactly one sanitized operational log", async () => { + const { destroyed, logs, received } = await driveRawConnection( + "node_timeouts", + // An incomplete request: a request line and one header, deliberately never terminated by the + // blank line that would mark the end of the headers, and no further data ever sent. + (socket) => socket.write("GET /api/v1/principal HTTP/1.1\r\nHost: 127.0.0.1\r\n"), + ); + + expect(received).toBe("HTTP/1.1 408 Request Timeout\r\nConnection: close\r\n\r\n"); + expect(statusLines(received)).toHaveLength(1); + // A handler would have produced a JSON principal body; Node answered before routing. + expect(received).not.toContain("anonymous"); + expect(destroyed).toBe(true); + expectSanitizedTransportLog(logs); + }); + + it("answers a never-completed body with exactly one 408, closes the socket, invokes no auth logic, and emits exactly one sanitized operational log", async () => { + const { destroyed, logs, received } = await driveRawConnection( + "node_timeouts_body", + // Complete, well-formed headers declaring a body that never actually arrives. + (socket) => + socket.write( + "POST /api/auth/sign-in/email HTTP/1.1\r\n" + + "Host: 127.0.0.1\r\n" + + "Content-Type: application/json\r\n" + + "Content-Length: 1000\r\n" + + "\r\n" + + '{"partial":', + ), + { + connectionsCheckingIntervalMs: 100, + headersTimeoutMs: 300, + keepAliveTimeoutMs: 200, + requestTimeoutMs: 400, + }, + ); + + expect(received).toBe("HTTP/1.1 408 Request Timeout\r\nConnection: close\r\n\r\n"); + expect(statusLines(received)).toHaveLength(1); + expect(received).not.toContain("Set-Cookie"); + expect(destroyed).toBe(true); + expectSanitizedTransportLog(logs); + }); + + it("preserves Node's own 400 for a malformed request line, without logging the malformed bytes", async () => { + const { destroyed, logs, received } = await driveRawConnection("node_bad_request", (socket) => + socket.write("!!!!NOT-HTTP-AT-ALL!!!! /secret-path\r\n\r\n"), + ); + + expect(received).toBe("HTTP/1.1 400 Bad Request\r\nConnection: close\r\n\r\n"); + expect(statusLines(received)).toHaveLength(1); + expect(destroyed).toBe(true); + expectSanitizedTransportLog(logs); + // The attacker-controlled bytes must never reach the log. + expect(logs.join("\n")).not.toContain("NOT-HTTP-AT-ALL"); + expect(logs.join("\n")).not.toContain("secret-path"); + }); + + it("preserves Node's own 431 for an oversized header block, without logging the header contents", async () => { + const { destroyed, logs, received } = await driveRawConnection( + "node_header_overflow", + (socket) => + socket.write( + `GET /api/v1/principal HTTP/1.1\r\nHost: 127.0.0.1\r\nX-Overflow: ${"z".repeat(20_000)}\r\n\r\n`, + ), + ); + + expect(received).toBe( + "HTTP/1.1 431 Request Header Fields Too Large\r\nConnection: close\r\n\r\n", + ); + expect(statusLines(received)).toHaveLength(1); + expect(destroyed).toBe(true); + expectSanitizedTransportLog(logs); + expect(logs.join("\n")).not.toContain("zzz"); }); }); diff --git a/apps/api/tests/lifecycle.test.ts b/apps/api/tests/lifecycle.test.ts index fc5d71c..f4b14e2 100644 --- a/apps/api/tests/lifecycle.test.ts +++ b/apps/api/tests/lifecycle.test.ts @@ -213,9 +213,11 @@ function fakeDiscoveredModule( /** A minimal fake `ServerType`: enough of Node's `http.Server` shape for `bindServer`/`shutdown` * to drive without a real socket. `close` and `once` are spies so tests can assert call counts; * `triggerError` simulates the server's own `'error'` event (e.g. a bind failure). */ +type ClientErrorHandler = (error: NodeJS.ErrnoException, socket: import("node:net").Socket) => void; + function fakeServer() { let errorHandler: ((error: Error) => void) | undefined; - let timeoutHandler: (() => void) | undefined; + let clientErrorHandler: ClientErrorHandler | undefined; const server = { address: () => ({ address: "127.0.0.1", family: "IPv4", port: 4_000 }), close: vi.fn((callback?: () => void) => { @@ -223,9 +225,9 @@ function fakeServer() { return server; }), listening: true, - on: vi.fn((event: string, handler: () => void) => { - if (event === "timeout") { - timeoutHandler = handler; + on: vi.fn((event: string, handler: ClientErrorHandler) => { + if (event === "clientError") { + clientErrorHandler = handler; } return server; }), @@ -237,9 +239,11 @@ function fakeServer() { }), }; return { + /** The `clientError` handler `bindServer` registered — the real event path Node uses for a + * header/request timeout, a parse failure, and a header overflow alike. */ + clientErrorHandler: () => clientErrorHandler, server, triggerError: (error: Error) => errorHandler?.(error), - triggerTimeout: () => timeoutHandler?.(), }; } @@ -248,12 +252,12 @@ function fakeServer() { * resolving synchronously would reference `bindServer`'s own `server` const before it is * initialized. */ function mockSuccessfulServe() { - const { server, triggerError, triggerTimeout } = fakeServer(); + const { clientErrorHandler, server, triggerError } = fakeServer(); serveMock.mockImplementation((_options: unknown, listeningListener?: () => void) => { queueMicrotask(() => listeningListener?.()); return server; }); - return { server, triggerError, triggerTimeout }; + return { clientErrorHandler, server, triggerError }; } function mockFailingServe(error: Error) { @@ -586,23 +590,117 @@ describe("Ekklesia API Node server timeouts", () => { await running.shutdown(); }); - it("logs a sanitized operational event, and nothing else, when the underlying server reports a timeout", async () => { + // Whether Node actually *emits* anything for a real header/request timeout — and that exactly one + // 408 is written, the socket closes, and no handler runs — is proven only at the real transport + // boundary, by the raw-socket scenarios in `apps/api/tests/api-http.integration.ts`. Node's + // general `'timeout'` event is NOT that path (it belongs to `server.setTimeout()`, which this + // server never arms); `'clientError'` is. The tests below therefore deliberately do not claim to + // prove the event path at all — they cover only the response-reproduction logic that Node's own + // default would otherwise have performed, including the duplicate-response guard, which is + // impractical to drive from a real socket. + function fakeErrorSocket(overrides: { headersSent?: boolean; writable?: boolean } = {}) { + const socket = { + _httpMessage: + overrides.headersSent === undefined ? undefined : { headersSent: overrides.headersSent }, + destroy: vi.fn(), + destroyed: false, + writable: overrides.writable ?? true, + write: vi.fn(), + }; + return socket as unknown as import("node:net").Socket & { + destroy: ReturnType; + write: ReturnType; + }; + } + + async function startAndCaptureClientErrorHandler() { const poolEnd = vi.fn().mockResolvedValue(undefined); poolConstructor.mockImplementation(function fakePool() { return { end: poolEnd, on: vi.fn() }; }); betterAuthMock.mockReturnValue({ api: { getSession: vi.fn() }, handler: vi.fn() }); - const { triggerTimeout } = mockSuccessfulServe(); + const { clientErrorHandler } = mockSuccessfulServe(); + const running = await startApi(validConfig()); + const handler = clientErrorHandler(); + if (!handler) { + throw new Error("Expected startApi to register a clientError handler."); + } + return { handler, running }; + } + + it("reproduces Node's own client-error responses byte-for-byte, since registering a listener suppresses them", async () => { + const { handler, running } = await startAndCaptureClientErrorHandler(); const errorSpy = vi.spyOn(console, "error").mockImplementation(() => undefined); try { - const running = await startApi(validConfig()); - triggerTimeout(); + for (const [code, expected] of [ + ["ERR_HTTP_REQUEST_TIMEOUT", "HTTP/1.1 408 Request Timeout\r\nConnection: close\r\n\r\n"], + [ + "HPE_HEADER_OVERFLOW", + "HTTP/1.1 431 Request Header Fields Too Large\r\nConnection: close\r\n\r\n", + ], + ["HPE_INVALID_METHOD", "HTTP/1.1 400 Bad Request\r\nConnection: close\r\n\r\n"], + [undefined, "HTTP/1.1 400 Bad Request\r\nConnection: close\r\n\r\n"], + ] as const) { + const socket = fakeErrorSocket(); + const error = Object.assign(new Error("parser detail that must never be logged"), { code }); + handler(error, socket); + + expect(socket.write).toHaveBeenCalledTimes(1); + expect(socket.write).toHaveBeenCalledWith(expected); + expect(socket.destroy).toHaveBeenCalledTimes(1); + } + await running.shutdown(); + } finally { + errorSpy.mockRestore(); + } + }); + + it("never writes a second response when a handler already began responding, but still closes the socket", async () => { + const { handler, running } = await startAndCaptureClientErrorHandler(); + const errorSpy = vi.spyOn(console, "error").mockImplementation(() => undefined); + + try { + const socket = fakeErrorSocket({ headersSent: true }); + handler(Object.assign(new Error("timeout"), { code: "ERR_HTTP_REQUEST_TIMEOUT" }), socket); + + expect(socket.write).not.toHaveBeenCalled(); + expect(socket.destroy).toHaveBeenCalledTimes(1); + + // An unwritable socket is likewise never written to, only destroyed. + const closedSocket = fakeErrorSocket({ writable: false }); + handler( + Object.assign(new Error("timeout"), { code: "ERR_HTTP_REQUEST_TIMEOUT" }), + closedSocket, + ); + expect(closedSocket.write).not.toHaveBeenCalled(); + expect(closedSocket.destroy).toHaveBeenCalledTimes(1); + + await running.shutdown(); + } finally { + errorSpy.mockRestore(); + } + }); + + it("logs one fixed sanitized line per client error, never the caught error's own message", async () => { + const { handler, running } = await startAndCaptureClientErrorHandler(); + const errorSpy = vi.spyOn(console, "error").mockImplementation(() => undefined); + + try { + handler( + Object.assign(new Error("Parse Error: /secret-path?token=abc123"), { + code: "HPE_INVALID_METHOD", + }), + fakeErrorSocket(), + ); expect(errorSpy).toHaveBeenCalledTimes(1); - const [message] = errorSpy.mock.calls[0] as [string]; - expect(message).toContain("timeout"); - expect(message).not.toMatch(/\d{1,3}\.\d{1,3}\.\d{1,3}\.\d{1,3}/u); + const emitted = errorSpy.mock.calls.flat().map(String).join("\n"); + expect(emitted).not.toContain("secret-path"); + expect(emitted).not.toContain("abc123"); + expect(emitted).not.toContain("Parse Error"); + expect(emitted).not.toContain("HPE_"); + expect(emitted).not.toMatch(/\d{1,3}\.\d{1,3}\.\d{1,3}\.\d{1,3}/u); await running.shutdown(); } finally { diff --git a/docs/architecture/decisions/0017-public-request-perimeter-hardening.md b/docs/architecture/decisions/0017-public-request-perimeter-hardening.md index a4c0e26..6ac0043 100644 --- a/docs/architecture/decisions/0017-public-request-perimeter-hardening.md +++ b/docs/architecture/decisions/0017-public-request-perimeter-hardening.md @@ -159,7 +159,7 @@ manifest): every existing module fixture, test, and the template (`templates/mod index.ts`) are updated in this same pass to declare it explicitly, per module-authoring convention documented in [Module development](../../module-development/README.md#http-routes). -### Finite Node header/request timeouts, and a non-obvious operational detail +### Finite Node header/request timeouts, and two non-obvious operational details `apps/api/src/server.ts` configures `@hono/node-server`'s `serverOptions` (passed straight through to `http.createServer`) with `headersTimeout: 20s`, `requestTimeout: 30s`, and @@ -177,11 +177,35 @@ configured timeout before Node ever closes it, on top of the configured value. ` therefore also sets `connectionsCheckingIntervalMs: 5s` explicitly, so a violation is detected promptly after it actually elapses rather than after an unrelated, much longer default interval. -A sanitized `server.on("timeout", ...)` listener logs a fixed, generic operational message — never -the remote address, headers, or request path — purely for observability; it does not participate -in, and cannot suppress, Node's own `408`/close behavior for `headersTimeout`/`requestTimeout` -(confirmed directly: only overriding the low-level `'clientError'` event, which this pass does -not touch, would do that). +The second detail concerns *observing* those timeouts, and corrects a claim this ADR originally +made. Node's general server `'timeout'` event belongs to `server.setTimeout()`'s idle-socket timer, +which this server never arms — it does **not** fire for `headersTimeout`/`requestTimeout`. Driving +a real slow-header and a real slow-body connection through a real socket against the pinned runtime +shows the only server-level event either produces is `'clientError'`, carrying +`err.code === "ERR_HTTP_REQUEST_TIMEOUT"`. A `server.on("timeout", ...)` listener therefore never +fires in production, and the sanitized operational line it was meant to emit was never actually +emitted. + +`apps/api/src/server.ts` consequently observes `'clientError'` instead. That carries an obligation: +registering *any* `'clientError'` listener suppresses Node's own default response entirely +(`_http_server.js` falls back only when `server.emit("clientError", ...)` returns `false`), so a +listener that merely watched would silently turn every `408`/`400`/`431` into a bare connection +reset. The handler therefore reproduces Node's default byte-for-byte — `408 Request Timeout` for +`ERR_HTTP_REQUEST_TIMEOUT`, `431 Request Header Fields Too Large` for `HPE_HEADER_OVERFLOW`, `400 +Bad Request` otherwise — writing it only when the socket is still writable and no response has +already begun for the in-flight request (mirroring Node's own `_httpMessage`/`headersSent` guard, so +a handler that already responded before an unread body timed out never receives a second, corrupting +status line), then destroys the socket exactly as Node would. + +Exactly one fixed, sanitized line is logged per event — one message for a timeout, one for any other +malformed or oversized request. Neither ever contains the request path, query, body, cookies, +authorization value, client-address header, forwarding chain, raw peer address, stack, or the caught +error's own message, since a parse failure's message is derived directly from attacker-controlled +input. This is proven at the real transport boundary rather than by manual event emission: raw-socket +scenarios in `apps/api/tests/api-http.integration.ts` drive a genuine slow-header connection, a +genuine slow-body connection, a malformed request line, and an oversized header block, each +asserting the exact response bytes, exactly one status line, socket closure, non-invocation of any +handler, and exactly one sanitized log. Bounded graceful-shutdown deadlines for module `stop()` hooks are a related but distinct concern, explicitly deferred to pass 4 and not touched here. diff --git a/docs/development/api.md b/docs/development/api.md index 1bdd805..574ce9a 100644 --- a/docs/development/api.md +++ b/docs/development/api.md @@ -324,16 +324,37 @@ made explicit). Node's own documented behavior responds `408` and closes the con ever invoking a request listener when either timeout is exceeded, so a timed-out connection cannot invoke a handler or receive a second response by construction. -One non-obvious detail, found only by reproducing it directly against the pinned Node runtime: -Node's `http.Server` only *checks* for a timeout violation when its periodic -`connectionsCheckingInterval` fires, and that option's own default is 30 seconds — leaving it -unset would silently let a violating connection sit for up to a further 30 seconds past its -configured timeout. `connectionsCheckingIntervalMs` is therefore also set explicitly (5s). A -sanitized, fixed operational log line (never the remote address, headers, or request path) is -emitted on a server-level `'timeout'` event purely for observability; it does not participate in, -and cannot suppress, Node's own `408`/close behavior. See +Two non-obvious details, both found only by reproducing them directly against the pinned Node 24 +runtime through a real socket: + +1. **Detection latency.** Node's `http.Server` only *checks* for a timeout violation when its + periodic `connectionsCheckingInterval` fires, and that option's own default is 30 seconds — + leaving it unset would silently let a violating connection sit for up to a further 30 seconds + past its configured timeout. `connectionsCheckingIntervalMs` is therefore also set explicitly + (5s). +2. **The observable event is `'clientError'`, not `'timeout'`.** Node's general server `'timeout'` + event belongs to `server.setTimeout()`'s idle-socket timer, which this server never arms; it + does **not** fire for `headersTimeout`/`requestTimeout`. Those surface as `'clientError'` with + `err.code === "ERR_HTTP_REQUEST_TIMEOUT"`. `apps/api/src/server.ts` therefore observes + `'clientError'`, and — because registering any `'clientError'` listener *suppresses* Node's own + default response entirely (`_http_server.js` only falls back when the emit returns `false`) — + that handler reproduces Node's default byte-for-byte rather than merely watching: `408 Request + Timeout` for a timeout, `431 Request Header Fields Too Large` for a header overflow, and `400 + Bad Request` otherwise, each followed by destroying the socket, and each written only when the + socket is still writable and no response has already begun (so a handler that already responded + before an unread body timed out never receives a second, corrupting status line). + +Exactly one fixed, sanitized operational line is logged per transport-level client failure — one +message for a timeout, one for any other malformed/oversized request. Neither ever contains the +request path, query, body, cookies, authorization value, client-address header, forwarding chain, +raw peer address, stack, or the caught error's own message (a parse failure's message is derived +from attacker-controlled input). This is proven at the real transport boundary by raw-socket +scenarios in `apps/api/tests/api-http.integration.ts` — a real slow-header connection, a real +slow-body connection, a malformed request line, and an oversized header block — each asserting the +exact response bytes, exactly one status line, socket closure, no handler invocation, and exactly +one sanitized log. See [ADR 0017](../architecture/decisions/0017-public-request-perimeter-hardening.md) for the full -account, including the standalone reproduction that found the `connectionsCheckingInterval` gap. +account. ## Module discovery, permission composition, and module runtime startup