diff --git a/changelog.d/fixes/10171-instrumentation-hook-boot-fatal-log.md b/changelog.d/fixes/10171-instrumentation-hook-boot-fatal-log.md new file mode 100644 index 0000000000..3f2c0fb028 --- /dev/null +++ b/changelog.d/fixes/10171-instrumentation-hook-boot-fatal-log.md @@ -0,0 +1 @@ +- fix(cli): guarantee a non-empty `[STARTUP] Fatal:` log line for any instrumentation-hook boot throw, not just DB-driver init failures (#10171) diff --git a/src/instrumentation-node.ts b/src/instrumentation-node.ts index b3f885c93f..31fe0b4099 100755 --- a/src/instrumentation-node.ts +++ b/src/instrumentation-node.ts @@ -7,6 +7,7 @@ */ import { markServerReady, markServerStarting } from "@/lib/serverLifecycle"; +import { normalizeBootError } from "@/lib/instrumentationBootError"; function getRandomBytes(byteLength: number): Uint8Array { const bytes = new Uint8Array(byteLength); @@ -37,23 +38,13 @@ export function renameProcessTitle(currentTitle: string): string { return `omniroute${currentTitle.slice("next-server".length)}`; } -/** - * Normalize any thrown/rejected value into a real `Error` instance. - * - * Next.js's own `registerInstrumentation()` wrapper (see - * `node_modules/next/dist/server/lib/router-utils/instrumentation-globals.external.js`) - * unconditionally does `err.message = \`...${err.message}\`` on whatever our - * `register()` export rejects with, assuming it is always an `Error`. If a raw - * non-Error primitive bubbles up instead (e.g. sql.js's WASM adapter throws the - * bare string `"Database closed"` — see `./lib/db/adapters/sqljsAdapter.ts`), - * that assignment throws `TypeError: Cannot create property 'message' on - * string '...'` in strict mode, masking the original error and crashing the - * whole server on every boot (#6560). Normalizing before it leaves our code - * guarantees Next always receives something `.message`-assignable. - */ -export function normalizeBootError(err: unknown): Error { - return err instanceof Error ? err : new Error(String(err)); -} +// `normalizeBootError` now lives in `@/lib/instrumentationBootError` (imported +// above) — shared, dependency-free, and reused by `src/instrumentation.ts`'s +// outermost boot boundary (#10171) so both boot-failure logging sites agree +// on the same normalization instead of maintaining two copies of the same +// one-liner. Re-exported here so existing callers/tests importing it from +// this module keep working unchanged. +export { normalizeBootError }; // Matches sql.js's raw `throw "Database closed"` (and similarly-worded // variants) thrown when a query runs against an already-closed WASM handle — diff --git a/src/instrumentation.ts b/src/instrumentation.ts index 5a92447398..59270c7a2d 100644 --- a/src/instrumentation.ts +++ b/src/instrumentation.ts @@ -8,12 +8,43 @@ * @see https://nextjs.org/docs/app/building-your-application/optimizing/instrumentation */ -export async function register() { +import { normalizeBootError } from "@/lib/instrumentationBootError"; + +/** + * `registerNodejsFn` is only for tests to inject a fake without module-mocking + * (`node:test` does not support `mock.module` reliably here) — mirrors the + * same injection pattern as `ensureDbReadyForBoot` in `./instrumentation-node`. + */ +export async function register(registerNodejsFn?: () => Promise) { if (process.env.NEXT_RUNTIME === "nodejs") { - // Literal path so Webpack emits the chunk (computed string breaks dev: - // MODULE_NOT_FOUND for ./instrumentation-node at runtime). - // Turbopack may still avoid tracing this into Edge when guarded by NEXT_RUNTIME. - const { registerNodejs } = await import("./instrumentation-node"); - await registerNodejs(); + try { + // Literal path so Webpack emits the chunk (computed string breaks dev: + // MODULE_NOT_FOUND for ./instrumentation-node at runtime). + // Turbopack may still avoid tracing this into Edge when guarded by NEXT_RUNTIME. + const registerNodejs = + registerNodejsFn ?? (await import("./instrumentation-node")).registerNodejs; + await registerNodejs(); + } catch (err: unknown) { + // Outermost boot boundary (#10171): any throw during module-load of + // ./instrumentation-node OR anywhere inside registerNodejs() runs + // BEFORE initConsoleInterceptor() is wired up. ensureDbReadyForBoot's + // own #7773 guard already logs one specific failure class (DB driver + // init), but it does not cover a throw that happens before it is even + // reached (e.g. a module-load-time error importing ./instrumentation-node + // itself, as reported on native Windows/WSL2 boots). Without an + // unconditional log line here, the process can keep its HTTP listener + // up while every DB-touching route 500s forever with a permanently + // empty app.log. This guarantees stdout/app.log is never silently + // empty on a failed boot, regardless of platform or which step threw. + // Reuses the same normalizeBootError() helper as ensureDbReadyForBoot + // (./instrumentation-node) — imported from a dependency-free module so + // this file, which also loads under the Edge runtime, never has to pull + // in Node-only code (or risk a second failing dynamic import of + // ./instrumentation-node itself) just to normalize the caught value. + const normalizedError = normalizeBootError(err); + const message = normalizedError.message; + console.error("[STARTUP] Fatal: instrumentation hook failed during boot:", message); + throw normalizedError; + } } } diff --git a/src/lib/instrumentationBootError.ts b/src/lib/instrumentationBootError.ts new file mode 100644 index 0000000000..9cbee2733e --- /dev/null +++ b/src/lib/instrumentationBootError.ts @@ -0,0 +1,26 @@ +/** + * Normalize any thrown/rejected value into a real `Error` instance. + * + * Next.js's own `registerInstrumentation()` wrapper (see + * `node_modules/next/dist/server/lib/router-utils/instrumentation-globals.external.js`) + * unconditionally does `err.message = \`...${err.message}\`` on whatever our + * `register()` export (`src/instrumentation.ts`) rejects with, assuming it is + * always an `Error`. If a raw non-Error primitive bubbles up instead (e.g. + * sql.js's WASM adapter throws the bare string `"Database closed"` — see + * `./db/adapters/sqljsAdapter.ts`), that assignment throws `TypeError: Cannot + * create property 'message' on string '...'` in strict mode, masking the + * original error and crashing the whole server on every boot (#6560). + * Normalizing before it leaves our code guarantees Next always receives + * something `.message`-assignable. + * + * Deliberately dependency-free (no imports) so both `src/instrumentation.ts` + * (the shared Edge+Node instrumentation entry point) and + * `src/instrumentation-node.ts` (the Node-only boot sequence) can import it + * statically without pulling Node-specific modules (fs/path/os/better-sqlite3 + * etc.) into the Edge runtime bundle, and without relying on a dynamic + * `import("./instrumentation-node")` that could itself be the thing that + * failed to load (#10171). + */ +export function normalizeBootError(err: unknown): Error { + return err instanceof Error ? err : new Error(String(err)); +} diff --git a/tests/unit/instrumentation-hook-boot-fatal-log-10171.test.ts b/tests/unit/instrumentation-hook-boot-fatal-log-10171.test.ts new file mode 100644 index 0000000000..6d0f790e3d --- /dev/null +++ b/tests/unit/instrumentation-hook-boot-fatal-log-10171.test.ts @@ -0,0 +1,122 @@ +import { test } from "node:test"; +import assert from "node:assert/strict"; +import { register } from "../../src/instrumentation"; + +// Regression guard for #10171: on native Windows/WSL2 boots, the reported +// symptom is a bare HTTP 500 on every DB-touching route with `app.log` +// staying completely empty, even though the CLI prints "OmniRoute is +// running!". ensureDbReadyForBoot() (#7773/#7828) already guarantees a +// non-empty [STARTUP] Fatal: log line for ONE specific failure class +// (database driver init), but nothing previously guaranteed a fatal throw +// ANYWHERE during instrumentation-hook boot (including a throw before +// ensureDbReadyForBoot is even reached) produces a diagnostic line. This +// test proves register() now catches any such throw at the outermost +// boundary and unconditionally logs a `[STARTUP] Fatal:` line to stdout +// before rethrowing, so app.log is never silently empty on a failed boot. + +function captureConsoleError(): { captured: string[]; restore: () => void } { + const originalError = console.error; + const captured: string[] = []; + console.error = (...args: unknown[]) => { + captured.push(args.map((arg) => String(arg)).join(" ")); + }; + return { + captured, + restore: () => { + console.error = originalError; + }, + }; +} + +test("#10171: any instrumentation-hook boot throw is logged with a non-empty [STARTUP] Fatal: line before rethrow", async () => { + const { captured, restore } = captureConsoleError(); + const previousRuntime = process.env.NEXT_RUNTIME; + process.env.NEXT_RUNTIME = "nodejs"; + + // Simulates a module-load-time failure reaching the instrumentation hook + // BEFORE ensureDbReadyForBoot's own #7773 guard is reached — the class of + // failure the reporter's empty app.log suggests on native Windows/WSL2. + const bootFailureMessage = "Cannot find native binding for platform=win32-x64"; + const fakeRegisterNodejs = async () => { + throw new Error(bootFailureMessage); + }; + + try { + await assert.rejects( + () => register(fakeRegisterNodejs), + (err: Error) => err.message === bootFailureMessage + ); + + const fatalLine = captured.find( + (line) => line.includes("[STARTUP] Fatal:") && line.includes(bootFailureMessage) + ); + assert.ok( + fatalLine, + "Expected a non-empty '[STARTUP] Fatal:' console.error line containing the boot " + + "failure before it propagates, so app.log is never silently empty on a failed " + + "boot (#10171). None was logged." + ); + } finally { + if (previousRuntime === undefined) { + delete process.env.NEXT_RUNTIME; + } else { + process.env.NEXT_RUNTIME = previousRuntime; + } + restore(); + } +}); + +test("#10171: a non-Error throw during instrumentation-hook boot is still logged with a non-empty [STARTUP] Fatal: line", async () => { + const { captured, restore } = captureConsoleError(); + const previousRuntime = process.env.NEXT_RUNTIME; + process.env.NEXT_RUNTIME = "nodejs"; + + // Mirrors real-world non-Error throws (e.g. sql.js's bare `throw "Database closed"`, + // #6560) reaching this outermost boundary before normalization. + const fakeRegisterNodejs = async () => { + throw "raw string boot failure"; + }; + + try { + await assert.rejects( + () => register(fakeRegisterNodejs), + (err: unknown) => { + assert.ok(err instanceof Error, "register() must rethrow a real Error instance"); + err.message += " (augmented by Next)"; + assert.equal(err.message, "raw string boot failure (augmented by Next)"); + return true; + } + ); + + const fatalLine = captured.find( + (line) => line.includes("[STARTUP] Fatal:") && line.includes("raw string boot failure") + ); + assert.ok(fatalLine, "Expected a non-empty '[STARTUP] Fatal:' line for a non-Error throw too."); + } finally { + if (previousRuntime === undefined) { + delete process.env.NEXT_RUNTIME; + } else { + process.env.NEXT_RUNTIME = previousRuntime; + } + restore(); + } +}); + +test("register() does not log anything on a clean successful boot", async () => { + const { captured, restore } = captureConsoleError(); + const previousRuntime = process.env.NEXT_RUNTIME; + process.env.NEXT_RUNTIME = "nodejs"; + const fakeRegisterNodejs = async () => {}; + + try { + await assert.doesNotReject(register(fakeRegisterNodejs)); + assert.equal(captured.length, 0, "a successful boot must not emit any fatal startup log lines"); + } finally { + if (previousRuntime === undefined) { + delete process.env.NEXT_RUNTIME; + } else { + process.env.NEXT_RUNTIME = previousRuntime; + } + restore(); + } +});