diff --git a/apps/api/src/server.ts b/apps/api/src/server.ts index ad19d58..1a1d831 100644 --- a/apps/api/src/server.ts +++ b/apps/api/src/server.ts @@ -130,6 +130,13 @@ export interface StartApiOptions { * test can prove real timeout behavior deterministically without waiting out the production * values. Never set by the executable entry point. */ readonly nodeServerTimeoutOverride?: Partial; + /** Test-only escape hatch: narrows the graceful HTTP drain deadline + * (`HTTP_DRAIN_TIMEOUT_MS`) so a forced close can be proven in milliseconds. Never set by the + * executable entry point. */ + readonly drainTimeoutMsOverride?: number; + /** Test-only escape hatch: narrows the per-module stop/rollback hook deadline + * (`MODULE_STOP_HOOK_TIMEOUT_MS`). Never set by the executable entry point. */ + readonly moduleHookTimeoutMsOverride?: number; } async function safeCloseDatabase(handle: ApiDatabaseHandle): Promise { @@ -152,6 +159,94 @@ async function safeStopModuleRuntime(moduleRuntime: StartedModuleRuntime): Promi } } +/** + * The platform's fixed graceful-drain deadline. In-flight HTTP work has this long to finish after + * the listener stops accepting new connections; after it, connections are closed so process + * shutdown stays bounded. Not configurable in this slice. + */ +export const HTTP_DRAIN_TIMEOUT_MS = 30_000; + +/** + * A shutdown that did not complete cleanly. Carries only fixed booleans and the already-sanitized + * module-runtime error — never a request, socket, URL, credential, SQL, or stack detail — so an + * operator can see *which* stages failed without any of it becoming a disclosure channel. + */ +export class ApiShutdownError extends Error { + readonly drainTimedOut: boolean; + readonly moduleStopFailed: boolean; + readonly moduleStopError: unknown; + + constructor(drainTimedOut: boolean, moduleStopError: unknown) { + super("The API did not shut down cleanly."); + this.name = "ApiShutdownError"; + this.drainTimedOut = drainTimedOut; + this.moduleStopFailed = moduleStopError !== undefined; + this.moduleStopError = moduleStopError; + this.stack = `${this.name}: ${this.message}`; + Object.freeze(this); + } +} + +/** + * Stops accepting new connections, then waits up to `timeoutMs` for existing HTTP work to finish. + * + * At the deadline it closes idle and then still-active connections using Node's own supported + * public `Server` APIs (`closeIdleConnections`/`closeAllConnections`, both called only after + * `server.close()`), and stops waiting for the close callback. No private socket or server field is + * touched. + * + * Force-closing a connection ends the transport. It does **not** prove that arbitrary in-process + * handler JavaScript was canceled — a handler promise may still be running and may still settle. + * What is guaranteed is that shutdown no longer waits for it, and that the pool closes afterwards, + * so its late database work fails. + */ +/** `ServerType` is a union that also covers HTTP/2 servers, which do not expose these two methods. + * `serve()` here always creates a plain `http.Server`, which does; narrowing with a real capability + * check keeps that honest instead of asserting a cast. */ +interface ConnectionClosingServer { + closeAllConnections(): void; + closeIdleConnections(): void; +} + +function supportsConnectionClosing( + server: ServerType, +): server is ServerType & ConnectionClosingServer { + const candidate = server as Partial; + return ( + typeof candidate.closeIdleConnections === "function" && + typeof candidate.closeAllConnections === "function" + ); +} + +async function drainHttpServer( + server: ServerType, + timeoutMs: number, +): Promise<"drained" | "forced"> { + let timer: ReturnType | undefined; + const closed = new Promise((resolve) => { + server.close(() => resolve()); + }); + try { + const outcome = await Promise.race([ + closed.then(() => "drained" as const), + new Promise<"forced">((resolve) => { + timer = setTimeout(() => resolve("forced"), timeoutMs); + }), + ]); + if (outcome === "drained") { + return "drained"; + } + if (supportsConnectionClosing(server)) { + server.closeIdleConnections(); + server.closeAllConnections(); + } + return "forced"; + } finally { + clearTimeout(timer); + // The close callback may still fire later; nothing awaits it, and it carries no rejection. + } +} + /** * Binds the Node HTTP server. Two platform-owned transport concerns are applied at this exact * boundary, below Hono entirely: `wrapFetchWithClientAddress` resolves and sanitizes the caller's @@ -292,7 +387,11 @@ export async function startApi( // handle to stop here, only the pool this failure leaves open. let moduleRuntime: StartedModuleRuntime; try { - moduleRuntime = await startDiscoveredModuleRuntime(inventory.modules, services); + moduleRuntime = await startDiscoveredModuleRuntime(inventory.modules, services, { + ...(options.moduleHookTimeoutMsOverride === undefined + ? {} + : { hookTimeoutMs: options.moduleHookTimeoutMsOverride }), + }); } catch (error) { await safeCloseDatabase(databaseHandle); throw error; @@ -345,13 +444,12 @@ export async function startApi( // code can run against it afterward. Unlike the startup-cleanup paths above, a module-stop // failure here is not swallowed — it is a genuine shutdown result a caller should observe — but // database cleanup still always runs first, so a stop failure never leaves the pool open. + const drainTimeoutMs = options.drainTimeoutMsOverride ?? HTTP_DRAIN_TIMEOUT_MS; let shutdownPromise: Promise | undefined; const shutdown = (): Promise => { if (!shutdownPromise) { shutdownPromise = (async () => { - await new Promise((resolve) => { - server.close(() => resolve()); - }); + const drainOutcome = await drainHttpServer(server, drainTimeoutMs); let moduleStopError: unknown; try { await moduleRuntime.stop(); @@ -359,8 +457,14 @@ export async function startApi( moduleStopError = error; } await safeCloseDatabase(databaseHandle); - if (moduleStopError) { - throw moduleStopError; + // Every stage above ran regardless of what the earlier ones did, so a drain timeout or a + // module-stop failure can never leave the pool open. Both failures are reported together, + // as fixed metadata: a forced drain is a genuine shutdown failure, not a success. + if (drainOutcome === "forced" || moduleStopError) { + throw new ApiShutdownError( + drainOutcome === "forced", + moduleStopError === undefined ? undefined : moduleStopError, + ); } })(); } diff --git a/apps/api/tests/api-http.integration.ts b/apps/api/tests/api-http.integration.ts index 12754dc..bef43b3 100644 --- a/apps/api/tests/api-http.integration.ts +++ b/apps/api/tests/api-http.integration.ts @@ -336,6 +336,8 @@ function apiOrigin(running: RunningApi): string { interface StartConfiguredApiOptions { readonly clientAddress?: ClientAddressConfigInput; + /** Test-only narrowing of the platform's 30-second graceful HTTP drain deadline. */ + readonly drainTimeoutMsOverride?: number; readonly modulesDirectoryOverride?: string; readonly nodeServerTimeoutOverride?: Partial; /** Defaults to `true`: almost every existing scenario in this suite signs accounts up over HTTP @@ -391,6 +393,9 @@ async function startConfiguredApi( ...(options.nodeServerTimeoutOverride === undefined ? {} : { nodeServerTimeoutOverride: options.nodeServerTimeoutOverride }), + ...(options.drainTimeoutMsOverride === undefined + ? {} + : { drainTimeoutMsOverride: options.drainTimeoutMsOverride }), }); } @@ -2725,3 +2730,114 @@ describe.sequential("live API — Node header/request timeouts and client errors expect(logs.join("\n")).not.toContain("zzz"); }); }); + +/** + * Pass 4: shutdown is finite even when HTTP work does not settle. + * + * These drive a real bound listener and a real socket rather than a mock, because the behavior + * under test is what Node's own `server.close()` does and does not do. Every socket, server, and + * disposable database is closed in `finally`, and each scenario carries its own outer deadline so + * a regression fails rather than hangs. + */ +describe.sequential("live API — bounded HTTP drain and shutdown", () => { + async function withDeadline(operation: Promise, timeoutMs: number): Promise { + let timer: ReturnType | undefined; + try { + return await Promise.race([ + operation, + new Promise((_resolve, reject) => { + timer = setTimeout( + () => reject(harnessError("shutdown did not settle in time")), + timeoutMs, + ); + }), + ]); + } finally { + clearTimeout(timer); + } + } + + it("serves a real request and then drains cleanly, well inside the deadline", async () => { + const database = await createDisposableDatabase("drain_ok"); + await applyCoreMigrations(database.url); + const running = await startConfiguredApi(database.url, { drainTimeoutMsOverride: 5_000 }); + try { + const origin = apiOrigin(running); + const response = await fetch(`${origin}/api/v1/principal`); + expect(response.status).toBe(200); + expect(await response.json()).toEqual({ kind: "anonymous" }); + + // Nothing is stalled, so the graceful path completes and shutdown reports success — the + // drain deadline is never reached and no connection is force-closed. + await expect(withDeadline(running.shutdown(), 20_000)).resolves.toBeUndefined(); + + // The listener really is closed afterwards. + await expect(fetch(`${origin}/api/v1/principal`)).rejects.toBeTruthy(); + } finally { + await running.shutdown().catch(() => undefined); + await dropDatabase(database.name); + } + }); + + it("force-closes a stalled connection at the drain deadline and still reaches pool closure", async () => { + const database = await createDisposableDatabase("drain_forced"); + await applyCoreMigrations(database.url); + // A short, test-only drain deadline; production keeps HTTP_DRAIN_TIMEOUT_MS unchanged. + const running = await startConfiguredApi(database.url, { drainTimeoutMsOverride: 250 }); + 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 }); + try { + // A real, deliberately incomplete request: headers are never finished, so Node keeps the + // connection open and `server.close()` alone would wait indefinitely. + await new Promise((resolve, reject) => { + socket.once("error", reject); + socket.on("data", () => undefined); + socket.write("GET /api/v1/principal HTTP/1.1\r\nHost: 127.0.0.1\r\n", () => resolve()); + }); + + const closed = new Promise((resolve) => { + socket.once("close", () => resolve()); + }); + + let captured: unknown; + try { + await withDeadline(running.shutdown(), 20_000); + } catch (error) { + captured = error; + } + + // A forced drain is a genuine shutdown failure, never reported as success. + expect(captured).toMatchObject({ drainTimedOut: true, name: "ApiShutdownError" }); + // ...and it still carries nothing about the request, socket, or database. + const publicText = `${String(captured)}\n${(captured as Error).stack ?? ""}`; + expect(publicText).not.toContain("127.0.0.1"); + expect(publicText).not.toContain(database.name); + // The connection was actually closed by the platform, not left dangling. + await withDeadline(closed, 10_000); + } finally { + socket.destroy(); + await running.shutdown().catch(() => undefined); + await dropDatabase(database.name); + } + }); + + it("shares one memoized shutdown across concurrent callers", async () => { + const database = await createDisposableDatabase("drain_once"); + await applyCoreMigrations(database.url); + const running = await startConfiguredApi(database.url, { drainTimeoutMsOverride: 5_000 }); + try { + const [first, second, third] = await withDeadline( + Promise.all([running.shutdown(), running.shutdown(), running.shutdown()]), + 20_000, + ); + expect([first, second, third]).toEqual([undefined, undefined, undefined]); + // A later caller observes the same completed result rather than restarting cleanup. + await expect(running.shutdown()).resolves.toBeUndefined(); + } finally { + await dropDatabase(database.name); + } + }); +}); diff --git a/apps/api/tests/lifecycle.test.ts b/apps/api/tests/lifecycle.test.ts index 19c0727..02fb776 100644 --- a/apps/api/tests/lifecycle.test.ts +++ b/apps/api/tests/lifecycle.test.ts @@ -1067,11 +1067,14 @@ describe("Ekklesia API module runtime startup and shutdown", () => { issues: [expect.objectContaining({ code: "MODULE_START_FAILED" })], }); + // The module whose start hook failed is rolled back first through its own stop hook, then the + // module that had already started, in reverse order. expect(recorder.events).toEqual([ "one:register", "two:register", "one:start", "two:start", + "two:stop", "one:stop", ]); expect(poolConstructor).toHaveBeenCalledTimes(1); @@ -1177,8 +1180,14 @@ describe("Ekklesia API module runtime startup and shutdown", () => { const running = await startApi(validConfig(), { modulesDirectoryOverride: modulesDirectory }); + // Shutdown now aggregates which stages failed; the module-runtime error is carried intact. await expect(running.shutdown()).rejects.toMatchObject({ - issues: [expect.objectContaining({ code: "MODULE_STOP_FAILED", moduleId: "stop-fails" })], + drainTimedOut: false, + moduleStopError: { + issues: [expect.objectContaining({ code: "MODULE_STOP_FAILED", moduleId: "stop-fails" })], + }, + moduleStopFailed: true, + name: "ApiShutdownError", }); expect(poolEnd).toHaveBeenCalledTimes(1); }); diff --git a/apps/api/tests/module-database.integration.ts b/apps/api/tests/module-database.integration.ts index 864b3c8..6956817 100644 --- a/apps/api/tests/module-database.integration.ts +++ b/apps/api/tests/module-database.integration.ts @@ -450,8 +450,15 @@ describe.sequential("live API — module database explicit migration ownership", await applyCoreMigrations(database.url); resetRecorder(); + // The module whose `start` failed is now rolled back through its own `stop` hook first. That + // hook also writes to the table its missing migration would have created, so it fails too — + // which is exactly the documented reason a `stop` hook must tolerate partial initialization. + // Both outcomes are reported, in order, and neither is swallowed. await expect(startMigratedApi(database.url, fixtureModulesDirectory)).rejects.toMatchObject({ - issues: [expect.objectContaining({ code: "MODULE_START_FAILED", moduleId: "db-facade" })], + issues: [ + expect.objectContaining({ code: "MODULE_START_FAILED", moduleId: "db-facade" }), + expect.objectContaining({ code: "MODULE_ROLLBACK_FAILED", moduleId: "db-facade" }), + ], }); // No schema inference, no automatic table creation as a side effect of the failed attempt. diff --git a/core/src/modules/runtime.ts b/core/src/modules/runtime.ts index 9395b65..168a192 100644 --- a/core/src/modules/runtime.ts +++ b/core/src/modules/runtime.ts @@ -34,6 +34,7 @@ export type ModuleRuntimeIssueCode = | "MODULE_CAPABILITY_UNREGISTERED" | "MODULE_REGISTER_FAILED" | "MODULE_ROLLBACK_FAILED" + | "MODULE_ROLLBACK_TIMEOUT" | "MODULE_ROUTE_DEFINITION_INVALID" | "MODULE_ROUTE_DUPLICATE" | "MODULE_ROUTE_MAX_BODY_BYTES_INVALID" @@ -47,7 +48,8 @@ export type ModuleRuntimeIssueCode = | "MODULE_RUNTIME_IMPORT_FAILED" | "MODULE_RUNTIME_VERSION_MISMATCH" | "MODULE_START_FAILED" - | "MODULE_STOP_FAILED"; + | "MODULE_STOP_FAILED" + | "MODULE_STOP_TIMEOUT"; export interface ModuleRuntimeIssue { readonly code: ModuleRuntimeIssueCode; @@ -74,7 +76,16 @@ export interface StartedModuleRuntime { stop(): Promise; } -export interface StartModuleRuntimeOptions extends ModuleDiscoveryOptions { +export interface ModuleRuntimeTimeoutOptions { + /** Test-only narrowing of `MODULE_STOP_HOOK_TIMEOUT_MS`, applied to both normal stop and startup + * rollback, so a deadline can be proven in milliseconds instead of ten seconds. Production + * composition never sets this. */ + readonly hookTimeoutMs?: number; +} + +export interface StartModuleRuntimeOptions + extends ModuleDiscoveryOptions, + ModuleRuntimeTimeoutOptions { /** The same frozen services object every started module's `start`/`stop` hooks and (once * `apps/api` mounts routes) HTTP handlers receive for this runtime — a required production * dependency, never an optional test-only global. See `ModuleRuntimeServices`. */ @@ -489,18 +500,93 @@ async function registerModules( } } +/** + * The platform's fixed wait for one module's `stop` hook, during either a normal stop or a startup + * rollback. Not configurable in this slice — no environment variable, manifest field, or runtime + * service — so every deployment bounds cleanup identically. + * + * This bounds *waiting*, not execution. An in-process promise cannot be canceled: a hook that + * exceeds this deadline keeps running and may settle later, but it no longer delays the rest of + * shutdown, and the pool closes after the bounded sequence, so its late database work fails. The + * platform does not sandbox, terminate, or undo a trusted module's JavaScript. + */ +export const MODULE_STOP_HOOK_TIMEOUT_MS = 10_000; + +interface StopModulesOptions { + /** Test-only narrowing of `MODULE_STOP_HOOK_TIMEOUT_MS` so a deadline can be proven without + * waiting out the production value. Production composition never sets this. */ + readonly hookTimeoutMs?: number; +} + +/** + * Awaits one hook under a deadline. The losing branch is always handled: the timer is cleared when + * the hook wins, and a hook that loses gets a permanent no-op rejection handler attached so a late + * throw can never surface as an unhandled rejection. A timed-out hook is never awaited again. + */ +async function awaitHookWithinDeadline( + hook: Promise, + timeoutMs: number, +): Promise<"completed" | "timed-out"> { + let timer: ReturnType | undefined; + // Attached before the race so the rejection is considered handled even if the timeout wins. + const observed = hook.then( + () => "completed" as const, + (error: unknown) => { + throw error; + }, + ); + observed.catch(() => undefined); + try { + return await Promise.race([ + observed, + new Promise<"timed-out">((resolve) => { + timer = setTimeout(() => resolve("timed-out"), timeoutMs); + }), + ]); + } finally { + clearTimeout(timer); + } +} + +/** + * Stops modules in reverse order, giving each hook a bounded slice of time and continuing to the + * next module whatever the previous one did. Every applicable hook is invoked at most once. + * + * The whole sequence is finite because the module count is finite and fixed at discovery: its + * worst case is `startedModuleCount * MODULE_STOP_HOOK_TIMEOUT_MS`, not one global ten-second + * bound. + */ async function stopModules( modules: readonly LoadedModule[], registry: StagedCapabilityRegistry, phase: "rollback" | "stop", services: ModuleRuntimeServices, + options: StopModulesOptions = {}, ): Promise { + const timeoutMs = options.hookTimeoutMs ?? MODULE_STOP_HOOK_TIMEOUT_MS; const issues: ModuleRuntimeIssue[] = []; for (const module of [...modules].reverse()) { + const moduleId = module.discovered.manifest.id; + const stop = module.definition.stop; + if (!stop) { + // No synthetic callback and no timer for a module that declares no stop hook. + continue; + } try { - await module.definition.stop?.( - registry.createRuntimeContext(module.discovered, phase, services), + const outcome = await awaitHookWithinDeadline( + Promise.resolve(stop(registry.createRuntimeContext(module.discovered, phase, services))), + timeoutMs, ); + if (outcome === "timed-out") { + issues.push( + runtimeIssue( + phase === "rollback" ? "MODULE_ROLLBACK_TIMEOUT" : "MODULE_STOP_TIMEOUT", + phase, + moduleId, + `Module ${moduleId} ${phase} did not complete within the platform deadline.`, + ), + ); + } } catch (error) { if (error instanceof ModuleRuntimeSignal) { issues.push(error.issue); @@ -509,8 +595,8 @@ async function stopModules( runtimeIssue( phase === "rollback" ? "MODULE_ROLLBACK_FAILED" : "MODULE_STOP_FAILED", phase, - module.discovered.manifest.id, - `Module ${module.discovered.manifest.id} ${phase} failed.`, + moduleId, + `Module ${moduleId} ${phase} failed.`, ), ); } @@ -523,14 +609,21 @@ async function startModules( modules: readonly LoadedModule[], registry: StagedCapabilityRegistry, services: ModuleRuntimeServices, + options: StopModulesOptions = {}, ): Promise { - const started: LoadedModule[] = []; + // A module joins the rollback set the moment its `start` hook is *invoked*, not when it + // completes. A hook that acquired a connection, registered a listener, or recorded partial + // initialization before throwing still has cleanup to do, and previously only the modules that + // had already finished were rolled back — leaving the failing module's own resources behind. Its + // `stop` hook therefore runs first, ahead of the earlier modules in reverse order, which is why + // module authors must make `stop` safe after a partially completed `start`. + const rollbackCandidates: LoadedModule[] = []; for (const module of modules) { + rollbackCandidates.push(module); try { await module.definition.start?.( registry.createRuntimeContext(module.discovered, "start", services), ); - started.push(module); } catch (error) { const startIssue = error instanceof ModuleRuntimeSignal @@ -541,7 +634,13 @@ async function startModules( module.discovered.manifest.id, `Module ${module.discovered.manifest.id} startup failed.`, ); - const rollbackIssues = await stopModules(started, registry, "rollback", services); + const rollbackIssues = await stopModules( + rollbackCandidates, + registry, + "rollback", + services, + options, + ); throw new ModuleRuntimeError([startIssue, ...rollbackIssues]); } } @@ -558,12 +657,13 @@ async function startModules( export async function startDiscoveredModuleRuntime( discoveredModules: readonly DiscoveredModule[], services: ModuleRuntimeServices, + timeouts: ModuleRuntimeTimeoutOptions = {}, ): Promise { const modules = await loadRuntimeDefinitions(discoveredModules); const capabilityRegistry = new StagedCapabilityRegistry(); const httpRoutes = new StagedModuleHttpRoutes(); await registerModules(modules, capabilityRegistry, httpRoutes); - await startModules(modules, capabilityRegistry, services); + await startModules(modules, capabilityRegistry, services, timeouts); const capabilities = capabilityRegistry.publish(); const routes = httpRoutes.publish(); @@ -583,7 +683,7 @@ export async function startDiscoveredModuleRuntime( routes, stop: (): Promise => { stopPromise ??= (async () => { - const issues = await stopModules(modules, capabilityRegistry, "stop", services); + const issues = await stopModules(modules, capabilityRegistry, "stop", services, timeouts); if (issues.length > 0) { throw new ModuleRuntimeError(issues); } @@ -597,5 +697,7 @@ export async function startModuleRuntime( options: StartModuleRuntimeOptions, ): Promise { const discovered = await discoverModules(options); - return startDiscoveredModuleRuntime(discovered, options.services); + return startDiscoveredModuleRuntime(discovered, options.services, { + ...(options.hookTimeoutMs === undefined ? {} : { hookTimeoutMs: options.hookTimeoutMs }), + }); } diff --git a/core/tests/module-runtime.test.ts b/core/tests/module-runtime.test.ts index 048e837..5b0a28c 100644 --- a/core/tests/module-runtime.test.ts +++ b/core/tests/module-runtime.test.ts @@ -369,10 +369,13 @@ describe("module runtime", () => { const error = await captureRuntimeError(modulesDirectory); expect(runtimeIssueCodes(error)).toEqual(["MODULE_START_FAILED", "MODULE_ROLLBACK_FAILED"]); + // The module whose `start` threw is rolled back *first*, then the previously started modules in + // reverse order — its own hook may have partial initialization to release before it threw. expect(recorder.events).toEqual([ "one:start", "two:start", "three:start", + "three:stop", "two:stop", "one:stop", ]); @@ -1151,3 +1154,200 @@ describe("module runtime services", () => { expect(vi.mocked(services.database.transaction)).not.toHaveBeenCalled(); }); }); + +/** + * Pass 4: a module whose `start` hook fails owns cleanup of whatever it managed to acquire, and + * every stop/rollback hook runs under a finite platform deadline. + */ +describe("module startup rollback and bounded stop hooks", () => { + it("releases a partially initialized resource through the failing module's own stop hook", async () => { + const modulesDirectory = await createModulesDirectory(); + const recorder = createEventRecorder(); + await createRuntimeModule(modulesDirectory, "partial", { + serverSource: `let acquired = false; + export default { + id: "partial", version: "0.1.0", + start() { + acquired = true; + ${recorder.expression}.push("partial:acquired"); + throw new Error("secret-token at /private/path"); + }, + stop() { + if (acquired) { acquired = false; ${recorder.expression}.push("partial:released"); } + } + };`, + }); + + const error = await captureRuntimeError(modulesDirectory); + + expect(runtimeIssueCodes(error)).toEqual(["MODULE_START_FAILED"]); + expect(recorder.events).toEqual(["partial:acquired", "partial:released"]); + expect(JSON.stringify(error.issues)).not.toContain("secret-token"); + expect(JSON.stringify(error.issues)).not.toContain("/private/path"); + }); + + it("reports the failing module's own rollback failure and still rolls back earlier modules", async () => { + const modulesDirectory = await createModulesDirectory(); + const recorder = createEventRecorder(); + await createRuntimeModule(modulesDirectory, "earlier", { + serverSource: `export default { + id: "earlier", version: "0.1.0", + stop() { ${recorder.expression}.push("earlier:stop"); } + };`, + }); + await createRuntimeModule(modulesDirectory, "failing", { + manifest: manifestFor("failing", { + dependencies: { modules: { required: { earlier: "^0.1.0" } } }, + }), + serverSource: `export default { + id: "failing", version: "0.1.0", + start() { throw new Error("start blew up"); }, + stop() { ${recorder.expression}.push("failing:stop"); throw new Error("rollback blew up"); } + };`, + }); + + const error = await captureRuntimeError(modulesDirectory); + + expect(runtimeIssueCodes(error)).toEqual(["MODULE_START_FAILED", "MODULE_ROLLBACK_FAILED"]); + expect(recorder.events).toEqual(["failing:stop", "earlier:stop"]); + }); + + it("gives a ModuleRuntimeSignal thrown during start the same rollback treatment", async () => { + const modulesDirectory = await createModulesDirectory(); + const recorder = createEventRecorder(); + // `capabilities.require` for a capability this module never declared throws a + // `ModuleRuntimeSignal` from inside `start`, rather than an ordinary Error. + await createRuntimeModule(modulesDirectory, "signal", { + serverSource: `export default { + id: "signal", version: "0.1.0", + start({ capabilities }) { capabilities.require("undeclared.thing"); }, + stop() { ${recorder.expression}.push("signal:stop"); } + };`, + }); + + const error = await captureRuntimeError(modulesDirectory); + + expect(error.issues[0]?.phase).toBe("start"); + expect(recorder.events).toEqual(["signal:stop"]); + }); + + it("invokes each stop hook at most once across rollback", async () => { + const modulesDirectory = await createModulesDirectory(); + const recorder = createEventRecorder(); + await createRuntimeModule(modulesDirectory, "counted", { + serverSource: `export default { + id: "counted", version: "0.1.0", + start() { throw new Error("nope"); }, + stop() { ${recorder.expression}.push("counted:stop"); } + };`, + }); + + await captureRuntimeError(modulesDirectory); + + expect(recorder.events.filter((event) => event === "counted:stop")).toHaveLength(1); + }); + + it("bounds a never-settling rollback hook and continues with the earlier module", async () => { + const modulesDirectory = await createModulesDirectory(); + const recorder = createEventRecorder(); + await createRuntimeModule(modulesDirectory, "earlier", { + serverSource: `export default { + id: "earlier", version: "0.1.0", + stop() { ${recorder.expression}.push("earlier:stop"); } + };`, + }); + await createRuntimeModule(modulesDirectory, "hanging", { + manifest: manifestFor("hanging", { + dependencies: { modules: { required: { earlier: "^0.1.0" } } }, + }), + serverSource: `export default { + id: "hanging", version: "0.1.0", + start() { throw new Error("nope"); }, + stop() { ${recorder.expression}.push("hanging:stop"); return new Promise(() => {}); } + };`, + }); + + // A short test-only deadline; production uses MODULE_STOP_HOOK_TIMEOUT_MS unchanged. + let captured: ModuleRuntimeError | undefined; + try { + await startModuleRuntime({ ...runtimeOptions(modulesDirectory), hookTimeoutMs: 25 }); + } catch (error) { + captured = error as ModuleRuntimeError; + } + + expect(captured).toBeInstanceOf(ModuleRuntimeError); + expect(runtimeIssueCodes(captured as ModuleRuntimeError)).toEqual([ + "MODULE_START_FAILED", + "MODULE_ROLLBACK_TIMEOUT", + ]); + // The timed-out hook did not block the earlier module's rollback. + expect(recorder.events).toEqual(["hanging:stop", "earlier:stop"]); + }); + + it("bounds a never-settling normal stop hook and continues with the earlier module", async () => { + const modulesDirectory = await createModulesDirectory(); + const recorder = createEventRecorder(); + await createRuntimeModule(modulesDirectory, "earlier", { + serverSource: `export default { + id: "earlier", version: "0.1.0", + stop() { ${recorder.expression}.push("earlier:stop"); } + };`, + }); + await createRuntimeModule(modulesDirectory, "hanging", { + manifest: manifestFor("hanging", { + dependencies: { modules: { required: { earlier: "^0.1.0" } } }, + }), + serverSource: `export default { + id: "hanging", version: "0.1.0", + stop() { ${recorder.expression}.push("hanging:stop"); return new Promise(() => {}); } + };`, + }); + + const runtime = await startModuleRuntime({ + ...runtimeOptions(modulesDirectory), + hookTimeoutMs: 25, + }); + let captured: ModuleRuntimeError | undefined; + try { + await runtime.stop(); + } catch (error) { + captured = error as ModuleRuntimeError; + } + + expect(runtimeIssueCodes(captured as ModuleRuntimeError)).toEqual(["MODULE_STOP_TIMEOUT"]); + expect(recorder.events).toEqual(["hanging:stop", "earlier:stop"]); + // Repeated and concurrent callers share the memoized promise and never restart cleanup. + const [first, second] = await Promise.allSettled([runtime.stop(), runtime.stop()]); + expect(first.status).toBe("rejected"); + expect(second.status).toBe("rejected"); + expect(recorder.events.filter((event) => event === "hanging:stop")).toHaveLength(1); + }); + + it("never lets a hook that rejects after its deadline become an unhandled rejection", async () => { + const modulesDirectory = await createModulesDirectory(); + await createRuntimeModule(modulesDirectory, "late", { + serverSource: `export default { + id: "late", version: "0.1.0", + stop() { return new Promise((_resolve, reject) => { setTimeout(() => reject(new Error("late")), 40); }); } + };`, + }); + + const unhandled: unknown[] = []; + const onUnhandled = (reason: unknown): void => { + unhandled.push(reason); + }; + process.on("unhandledRejection", onUnhandled); + try { + const runtime = await startModuleRuntime({ + ...runtimeOptions(modulesDirectory), + hookTimeoutMs: 10, + }); + await expect(runtime.stop()).rejects.toBeInstanceOf(ModuleRuntimeError); + // Give the late rejection time to fire, then confirm nothing escaped. + await new Promise((resolve) => setTimeout(resolve, 80)); + expect(unhandled).toEqual([]); + } finally { + process.off("unhandledRejection", onUnhandled); + } + }); +}); diff --git a/docs/development/api.md b/docs/development/api.md index 32da520..83e33a7 100644 --- a/docs/development/api.md +++ b/docs/development/api.md @@ -585,8 +585,9 @@ failure propagates: module-services/identity/authorization construction failing was started yet — the frozen `ModuleRuntimeServices` object is built in the same step, from the same pool); the server failing to bind its listen address; or an app-construction failure, both of which also stop the module runtime first, since it may have already started successfully. A module -load/register/start failure uses Core's own existing rollback (already-started modules stop, in -reverse order, before the failure propagates) and then closes the pool — there is no separate +load/register/start failure uses Core's own rollback — the module whose `start` hook failed is +stopped first, through its own `stop` hook, then already-started modules in reverse order, each +under the same bounded per-hook deadline — before the failure propagates, and then closes the pool — there is no separate runtime handle to stop in that case, since `startDiscoveredModuleRuntime` never returned one. ## A real signup → sign-in → principal → sign-out transcript diff --git a/docs/development/testing.md b/docs/development/testing.md index 7e7296f..bf334cd 100644 --- a/docs/development/testing.md +++ b/docs/development/testing.md @@ -152,6 +152,20 @@ key material is ever committed to this repository** — and the disposable conta `afterAll` even when an assertion fails. See [ADR 0018](../architecture/decisions/0018-identity-session-resolution-and-database-transport.md). +### Which kind of timing proof lives where + +Pass 4 introduced several deadlines, and their tests deliberately differ in kind: + +- **Unit deadline tests** (`core/tests/module-runtime.test.ts`) drive module stop and rollback + hooks through a short, test-only `hookTimeoutMs` override with manually controlled + never-settling promises — no real waiting, no sleeps, and an explicit `unhandledRejection` check + proving a hook that rejects after its deadline stays handled. +- **Real raw-HTTP force-close** (`apps/api/tests/api-http.integration.ts`) binds the real listener, + opens a real socket, writes a deliberately incomplete request, and proves shutdown force-closes + it at a short `drainTimeoutMsOverride` and still reaches pool closure. +Both use a short **test-only override**; the production defaults (10 s per module hook, 30 s HTTP +drain) are asserted separately as constants and are never waited out. + CI runs the same command in the dedicated `migration-smoke` job. After this change is merged, add the following pull-request status context to `main` branch protection: diff --git a/docs/module-development/README.md b/docs/module-development/README.md index 4ff5f8b..126fdf0 100644 --- a/docs/module-development/README.md +++ b/docs/module-development/README.md @@ -180,6 +180,21 @@ Entrypoint imports must have no top-level side effects. Modules are trusted back evaluation cannot be rolled back. Keep registration declarative; open resources in `start` and close them in `stop`. +### `stop()` may run after a partially completed `start()` + +If your `start` hook throws, **your own `stop` hook runs first**, ahead of the previously started +modules being rolled back in reverse order. That is deliberate: a hook that opened a connection, +registered a listener, or recorded partial initialization before failing is the only code that knows +how to release it. Write `stop` so it is safe and idempotent about resources it may or may not have +acquired — guard on what you actually took, and never assume `start` completed. + +Stop and rollback hooks have finite time: the platform waits at most **10 seconds** per module hook, +then records a timeout and continues with the next module in reverse order. Settle promptly. A hook +that exceeds its deadline is not killed — the platform simply stops waiting for it — but the shared +PostgreSQL pool closes after the bounded stop sequence, so **a timed-out hook cannot rely on +database availability afterwards**, and any late query will fail. The platform cannot undo side +effects your module performed outside its stop hook. + ## HTTP routes A module registers plain Fetch (`Request` in, `Response` out) route handlers during `register`,