fix: observe request timeout failures
The sanitized operational line promised for a header/request timeout was never actually emitted. Driving a real slow-header and slow-body connection through a real socket against the pinned Node 24 runtime shows the general server 'timeout' event never fires for headersTimeout/requestTimeout — that event belongs to server.setTimeout()'s idle-socket timer, which this server never arms. Both surface as 'clientError' carrying err.code === "ERR_HTTP_REQUEST_TIMEOUT". bindServer now observes 'clientError'. Because registering any such listener suppresses Node's own default response entirely, the handler reproduces that default byte-for-byte — 408 for a timeout, 431 for a header overflow, 400 otherwise — writing it only when the socket is still writable and no response has already begun, then destroying the socket exactly as Node would. Exactly one fixed sanitized line is logged per event, never the caught error's own message, which for a parse failure derives from attacker-controlled input. Proof moves to the real transport boundary: raw-socket scenarios assert the exact response bytes, exactly one status line, socket closure, handler non-invocation, and exactly one sanitized log for a slow-header connection, a slow-body connection, a malformed request line, and an oversized header block. The prior unit test, which manually emitted 'timeout', is removed as misleading. Co-Authored-By: Claude Opus 5 <[email protected]>
This commit is contained in:
co-authored by
Claude Opus 5
parent
1161f5a076
commit
3d6c85b0f8
@@ -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,
|
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
|
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
|
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),
|
[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
|
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
|
does not add distributed rate limiting, durable public-signup abuse control, or any deployment/TLS
|
||||||
|
|||||||
+55
-7
@@ -1,3 +1,4 @@
|
|||||||
|
import type { Socket } from "node:net";
|
||||||
import path from "node:path";
|
import path from "node:path";
|
||||||
import { pathToFileURL } from "node:url";
|
import { pathToFileURL } from "node:url";
|
||||||
import type { ModuleRuntimeServices } from "@ekklesia/contracts";
|
import type { ModuleRuntimeServices } from "@ekklesia/contracts";
|
||||||
@@ -64,9 +65,48 @@ const PRODUCTION_NODE_SERVER_TIMEOUTS: NodeServerTimeouts = Object.freeze({
|
|||||||
requestTimeoutMs: 30_000,
|
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 =
|
const NODE_SERVER_TIMEOUT_LOG_MESSAGE =
|
||||||
"[server] A connection was closed for exceeding a configured header/request timeout.";
|
"[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<Record<string, string>> = 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 {
|
export interface RunningApi {
|
||||||
readonly app: Hono;
|
readonly app: Hono;
|
||||||
@@ -150,12 +190,20 @@ function bindServer(
|
|||||||
}
|
}
|
||||||
},
|
},
|
||||||
);
|
);
|
||||||
// A sanitized operational observation only — Node's own headersTimeout/requestTimeout
|
// `headersTimeout`/`requestTimeout` do NOT surface as the server's general `'timeout'` event —
|
||||||
// enforcement already closes the connection (and, for requestTimeout, sends a 408) regardless
|
// that event only fires for `server.setTimeout()`'s idle-socket timer, which this server never
|
||||||
// of whether anything is listening here; this never carries the remote address, headers, or any
|
// arms. Verified directly against the pinned Node 24 runtime by driving a real slow-header and
|
||||||
// other request detail.
|
// slow-body connection through a real socket: the only server-level event either produces is
|
||||||
server.on("timeout", () => {
|
// `'clientError'`, carrying `err.code === "ERR_HTTP_REQUEST_TIMEOUT"`. Observing the failure
|
||||||
console.error(NODE_SERVER_TIMEOUT_LOG_MESSAGE);
|
// 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", () => {
|
server.once("error", () => {
|
||||||
if (!settled) {
|
if (!settled) {
|
||||||
|
|||||||
@@ -1948,69 +1948,29 @@ describe.sequential("live API — client-address resolution and auth rate-limit
|
|||||||
});
|
});
|
||||||
});
|
});
|
||||||
|
|
||||||
describe.sequential("live API — Node header/request timeouts", () => {
|
describe.sequential("live API — Node header/request timeouts and client errors", () => {
|
||||||
it("closes a connection whose headers never complete within the configured headersTimeout, never invoking a handler", async () => {
|
/**
|
||||||
const database = await createDisposableDatabase("node_timeouts");
|
* Drives one raw, deliberately-malformed or deliberately-slow byte sequence through a real
|
||||||
await applyCoreMigrations(database.url);
|
* listening API and returns everything observable at the transport boundary, plus everything the
|
||||||
const config = createApiRuntimeConfig(
|
* *real* production logging seam (`console.error`, which `apps/api/src/server.ts` writes its
|
||||||
{
|
* sanitized operational line through) actually emitted while it happened.
|
||||||
databaseUrl: database.url,
|
*
|
||||||
host: "127.0.0.1",
|
* This is the only shape of proof that counts for the timeout-observability claim: no event is
|
||||||
identity: {
|
* manually emitted, no logger is called directly, and nothing asserts merely that a listener was
|
||||||
baseUrl: identityBaseUrl,
|
* registered — a real socket is opened against a real server, real bytes are written, and the
|
||||||
publicSignupEnabled: false,
|
* real Node transport is left to do whatever it genuinely does.
|
||||||
secret: "integration-test-secret-0123456789abcdefgh",
|
*/
|
||||||
trustedOrigins: [identityBaseUrl],
|
async function driveRawConnection(
|
||||||
},
|
label: string,
|
||||||
port: 0,
|
write: (socket: net.Socket) => void,
|
||||||
},
|
timeouts: Partial<NodeServerTimeouts> = {
|
||||||
{ 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,
|
connectionsCheckingIntervalMs: 100,
|
||||||
headersTimeoutMs: 200,
|
headersTimeoutMs: 200,
|
||||||
keepAliveTimeoutMs: 200,
|
keepAliveTimeoutMs: 200,
|
||||||
requestTimeoutMs: 300,
|
requestTimeoutMs: 300,
|
||||||
},
|
},
|
||||||
});
|
): Promise<{ destroyed: boolean; logs: string[]; received: string }> {
|
||||||
try {
|
const database = await createDisposableDatabase(label);
|
||||||
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<void>((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<void>((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");
|
|
||||||
await applyCoreMigrations(database.url);
|
await applyCoreMigrations(database.url);
|
||||||
const config = createApiRuntimeConfig(
|
const config = createApiRuntimeConfig(
|
||||||
{
|
{
|
||||||
@@ -2026,14 +1986,11 @@ describe.sequential("live API — Node header/request timeouts", () => {
|
|||||||
},
|
},
|
||||||
{ environment: "production" },
|
{ environment: "production" },
|
||||||
);
|
);
|
||||||
const running = await startApi(config, {
|
// Deliberately tiny, test-only timeouts — production composition (server.ts's `main`) never
|
||||||
nodeServerTimeoutOverride: {
|
// sets this override — so a real timeout is observed deterministically in well under a second
|
||||||
connectionsCheckingIntervalMs: 100,
|
// rather than by waiting out the production values.
|
||||||
headersTimeoutMs: 300,
|
const running = await startApi(config, { nodeServerTimeoutOverride: timeouts });
|
||||||
keepAliveTimeoutMs: 200,
|
const errorSpy = vi.spyOn(console, "error").mockImplementation(() => undefined);
|
||||||
requestTimeoutMs: 400,
|
|
||||||
},
|
|
||||||
});
|
|
||||||
try {
|
try {
|
||||||
const address = running.server.address();
|
const address = running.server.address();
|
||||||
if (!address || typeof address !== "object") {
|
if (!address || typeof address !== "object") {
|
||||||
@@ -2046,10 +2003,82 @@ describe.sequential("live API — Node header/request timeouts", () => {
|
|||||||
socket.once("error", reject);
|
socket.once("error", reject);
|
||||||
});
|
});
|
||||||
const receivedChunks: Buffer[] = [];
|
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("data", (chunk) => receivedChunks.push(chunk as Buffer));
|
||||||
|
socket.on("error", () => undefined);
|
||||||
const closed = new Promise<void>((resolve) => socket.once("close", resolve));
|
const closed = new Promise<void>((resolve) => socket.once("close", resolve));
|
||||||
|
|
||||||
|
write(socket);
|
||||||
|
await closed;
|
||||||
|
|
||||||
|
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.
|
// Complete, well-formed headers declaring a body that never actually arrives.
|
||||||
|
(socket) =>
|
||||||
socket.write(
|
socket.write(
|
||||||
"POST /api/auth/sign-in/email HTTP/1.1\r\n" +
|
"POST /api/auth/sign-in/email HTTP/1.1\r\n" +
|
||||||
"Host: 127.0.0.1\r\n" +
|
"Host: 127.0.0.1\r\n" +
|
||||||
@@ -2057,18 +2086,51 @@ describe.sequential("live API — Node header/request timeouts", () => {
|
|||||||
"Content-Length: 1000\r\n" +
|
"Content-Length: 1000\r\n" +
|
||||||
"\r\n" +
|
"\r\n" +
|
||||||
'{"partial":',
|
'{"partial":',
|
||||||
|
),
|
||||||
|
{
|
||||||
|
connectionsCheckingIntervalMs: 100,
|
||||||
|
headersTimeoutMs: 300,
|
||||||
|
keepAliveTimeoutMs: 200,
|
||||||
|
requestTimeoutMs: 400,
|
||||||
|
},
|
||||||
);
|
);
|
||||||
|
|
||||||
await closed;
|
expect(received).toBe("HTTP/1.1 408 Request Timeout\r\nConnection: close\r\n\r\n");
|
||||||
const received = Buffer.concat(receivedChunks).toString("utf8");
|
expect(statusLines(received)).toHaveLength(1);
|
||||||
// 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).not.toContain("Set-Cookie");
|
||||||
expect(received.match(/^HTTP\/1\.1 \d{3}/gmu)?.length ?? 0).toBeLessThanOrEqual(1);
|
expect(destroyed).toBe(true);
|
||||||
} finally {
|
expectSanitizedTransportLog(logs);
|
||||||
await running.shutdown().catch(() => undefined);
|
});
|
||||||
await dropDatabase(database.name);
|
|
||||||
}
|
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");
|
||||||
});
|
});
|
||||||
});
|
});
|
||||||
|
|||||||
@@ -213,9 +213,11 @@ function fakeDiscoveredModule(
|
|||||||
/** A minimal fake `ServerType`: enough of Node's `http.Server` shape for `bindServer`/`shutdown`
|
/** 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;
|
* 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). */
|
* `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() {
|
function fakeServer() {
|
||||||
let errorHandler: ((error: Error) => void) | undefined;
|
let errorHandler: ((error: Error) => void) | undefined;
|
||||||
let timeoutHandler: (() => void) | undefined;
|
let clientErrorHandler: ClientErrorHandler | undefined;
|
||||||
const server = {
|
const server = {
|
||||||
address: () => ({ address: "127.0.0.1", family: "IPv4", port: 4_000 }),
|
address: () => ({ address: "127.0.0.1", family: "IPv4", port: 4_000 }),
|
||||||
close: vi.fn((callback?: () => void) => {
|
close: vi.fn((callback?: () => void) => {
|
||||||
@@ -223,9 +225,9 @@ function fakeServer() {
|
|||||||
return server;
|
return server;
|
||||||
}),
|
}),
|
||||||
listening: true,
|
listening: true,
|
||||||
on: vi.fn((event: string, handler: () => void) => {
|
on: vi.fn((event: string, handler: ClientErrorHandler) => {
|
||||||
if (event === "timeout") {
|
if (event === "clientError") {
|
||||||
timeoutHandler = handler;
|
clientErrorHandler = handler;
|
||||||
}
|
}
|
||||||
return server;
|
return server;
|
||||||
}),
|
}),
|
||||||
@@ -237,9 +239,11 @@ function fakeServer() {
|
|||||||
}),
|
}),
|
||||||
};
|
};
|
||||||
return {
|
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,
|
server,
|
||||||
triggerError: (error: Error) => errorHandler?.(error),
|
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
|
* resolving synchronously would reference `bindServer`'s own `server` const before it is
|
||||||
* initialized. */
|
* initialized. */
|
||||||
function mockSuccessfulServe() {
|
function mockSuccessfulServe() {
|
||||||
const { server, triggerError, triggerTimeout } = fakeServer();
|
const { clientErrorHandler, server, triggerError } = fakeServer();
|
||||||
serveMock.mockImplementation((_options: unknown, listeningListener?: () => void) => {
|
serveMock.mockImplementation((_options: unknown, listeningListener?: () => void) => {
|
||||||
queueMicrotask(() => listeningListener?.());
|
queueMicrotask(() => listeningListener?.());
|
||||||
return server;
|
return server;
|
||||||
});
|
});
|
||||||
return { server, triggerError, triggerTimeout };
|
return { clientErrorHandler, server, triggerError };
|
||||||
}
|
}
|
||||||
|
|
||||||
function mockFailingServe(error: Error) {
|
function mockFailingServe(error: Error) {
|
||||||
@@ -586,23 +590,117 @@ describe("Ekklesia API Node server timeouts", () => {
|
|||||||
await running.shutdown();
|
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<typeof vi.fn>;
|
||||||
|
write: ReturnType<typeof vi.fn>;
|
||||||
|
};
|
||||||
|
}
|
||||||
|
|
||||||
|
async function startAndCaptureClientErrorHandler() {
|
||||||
const poolEnd = vi.fn().mockResolvedValue(undefined);
|
const poolEnd = vi.fn().mockResolvedValue(undefined);
|
||||||
poolConstructor.mockImplementation(function fakePool() {
|
poolConstructor.mockImplementation(function fakePool() {
|
||||||
return { end: poolEnd, on: vi.fn() };
|
return { end: poolEnd, on: vi.fn() };
|
||||||
});
|
});
|
||||||
betterAuthMock.mockReturnValue({ api: { getSession: vi.fn() }, handler: 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);
|
const errorSpy = vi.spyOn(console, "error").mockImplementation(() => undefined);
|
||||||
|
|
||||||
try {
|
try {
|
||||||
const running = await startApi(validConfig());
|
for (const [code, expected] of [
|
||||||
triggerTimeout();
|
["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);
|
expect(errorSpy).toHaveBeenCalledTimes(1);
|
||||||
const [message] = errorSpy.mock.calls[0] as [string];
|
const emitted = errorSpy.mock.calls.flat().map(String).join("\n");
|
||||||
expect(message).toContain("timeout");
|
expect(emitted).not.toContain("secret-path");
|
||||||
expect(message).not.toMatch(/\d{1,3}\.\d{1,3}\.\d{1,3}\.\d{1,3}/u);
|
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();
|
await running.shutdown();
|
||||||
} finally {
|
} finally {
|
||||||
|
|||||||
@@ -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
|
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).
|
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
|
`apps/api/src/server.ts` configures `@hono/node-server`'s `serverOptions` (passed straight through
|
||||||
to `http.createServer`) with `headersTimeout: 20s`, `requestTimeout: 30s`, and
|
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
|
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.
|
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 second detail concerns *observing* those timeouts, and corrects a claim this ADR originally
|
||||||
the remote address, headers, or request path — purely for observability; it does not participate
|
made. Node's general server `'timeout'` event belongs to `server.setTimeout()`'s idle-socket timer,
|
||||||
in, and cannot suppress, Node's own `408`/close behavior for `headersTimeout`/`requestTimeout`
|
which this server never arms — it does **not** fire for `headersTimeout`/`requestTimeout`. Driving
|
||||||
(confirmed directly: only overriding the low-level `'clientError'` event, which this pass does
|
a real slow-header and a real slow-body connection through a real socket against the pinned runtime
|
||||||
not touch, would do that).
|
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,
|
Bounded graceful-shutdown deadlines for module `stop()` hooks are a related but distinct concern,
|
||||||
explicitly deferred to pass 4 and not touched here.
|
explicitly deferred to pass 4 and not touched here.
|
||||||
|
|||||||
+30
-9
@@ -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
|
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.
|
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:
|
Two non-obvious details, both found only by reproducing them directly against the pinned Node 24
|
||||||
Node's `http.Server` only *checks* for a timeout violation when its periodic
|
runtime through a real socket:
|
||||||
`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
|
1. **Detection latency.** Node's `http.Server` only *checks* for a timeout violation when its
|
||||||
configured timeout. `connectionsCheckingIntervalMs` is therefore also set explicitly (5s). A
|
periodic `connectionsCheckingInterval` fires, and that option's own default is 30 seconds —
|
||||||
sanitized, fixed operational log line (never the remote address, headers, or request path) is
|
leaving it unset would silently let a violating connection sit for up to a further 30 seconds
|
||||||
emitted on a server-level `'timeout'` event purely for observability; it does not participate in,
|
past its configured timeout. `connectionsCheckingIntervalMs` is therefore also set explicitly
|
||||||
and cannot suppress, Node's own `408`/close behavior. See
|
(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
|
[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
|
## Module discovery, permission composition, and module runtime startup
|
||||||
|
|
||||||
|
|||||||
Reference in New Issue
Block a user