diff --git a/packages/nuxt-cli/src/commands/dev.ts b/packages/nuxt-cli/src/commands/dev.ts index f4fdb8199..4963e477b 100644 --- a/packages/nuxt-cli/src/commands/dev.ts +++ b/packages/nuxt-cli/src/commands/dev.ts @@ -19,14 +19,16 @@ import { isReusePortSupported } from '../dev/listen' import { ForkPool } from '../dev/pool' import { formatRestartReason } from '../dev/reason' import { setupShortcuts } from '../dev/shortcuts' +import { SUPERVISOR_SHUTDOWN_TIMEOUT_MS } from '../dev/shutdown' import { formatTakeoverRefusal, takeOverDevServer } from '../dev/takeover' +import { summariseActiveResources } from '../utils/hang' import { debug, logger } from '../utils/logger' import { resolveRootDir } from '../utils/paths' import { dotEnvArgs, envNameArgs, extendsArgs, logLevelArgs, profileArgs, rootDirArgs } from './_shared' const startTime: number | undefined = Date.now() -const SHUTDOWN_TIMEOUT_MS = 3000 +const SHUTDOWN_NOTICE_MS = 1500 const forkSupported = !isTest && (!isBun || isBunForkSupported()) const command = defineCommand({ @@ -356,19 +358,39 @@ type ArgsT = Exclude< * Registering any listener for these signals (the fork pool and the CPU * profiler both do) suppresses Node's default exit behaviour, so Ctrl-C would * otherwise leave the server, its forks and any tunnel running. + * + * Shutdown is given enough time for `close` hooks (nitro plugins closing database + * connections, and so on) to finish; a second Ctrl-C skips the wait. */ function setupSignalHandlers(close: () => Promise): void { + let closing = false for (const signal of ['SIGINT', 'SIGTERM'] as const) { - process.once(signal, () => { + process.on(signal, () => { + if (closing) { + process.exit(130) + } + closing = true + + const notice = setTimeout(() => { + logger.info('Shutting down... press Ctrl-C again to exit immediately.') + }, SHUTDOWN_NOTICE_MS) + notice.unref?.() + // Ctrl-C should always give the terminal back, even if a watcher or an // open connection stops the graceful shutdown from settling. - const deadline = setTimeout(() => process.exit(), SHUTDOWN_TIMEOUT_MS) + const deadline = setTimeout(() => { + const summary = summariseActiveResources() + logger.warn(`The dev server did not shut down within ${SUPERVISOR_SHUTDOWN_TIMEOUT_MS / 1000}s${summary ? `: ${summary}` : ''}. Exiting anyway.`) + process.exit() + }, SUPERVISOR_SHUTDOWN_TIMEOUT_MS) + close() .catch((error) => { console.error(error) process.exitCode = 1 }) .finally(() => { + clearTimeout(notice) clearTimeout(deadline) process.exit() }) diff --git a/packages/nuxt-cli/src/dev/index.ts b/packages/nuxt-cli/src/dev/index.ts index 86f5085a6..7b8f0f756 100644 --- a/packages/nuxt-cli/src/dev/index.ts +++ b/packages/nuxt-cli/src/dev/index.ts @@ -45,13 +45,24 @@ interface InitializeOptions { // IPC Hooks class IPC { enabled = !!process.send && !process.title?.includes('vitest') && process.env.__NUXT__FORK + #shutdown?: () => Promise + #closing?: Promise + constructor() { // only kill process if it is a fork if (this.enabled) { + // The terminal delivers Ctrl-C to the whole process group, so this fork has to + // run its own shutdown rather than being terminated mid-request. + for (const signal of ['SIGINT', 'SIGTERM'] as const) { + process.once(signal, () => void this.close()) + } // Without a parent there is nobody to reap this process, and it may be - // holding the dev server port or the inspector port. + // holding the dev server port or the inspector port. A shutdown that is + // already running exits on its own once the `close` hooks have finished. process.once('disconnect', () => { - process.exit(0) + if (!this.#closing) { + process.exit(0) + } }) process.on('unhandledRejection', createRejectionHandler( message => this.send({ type: 'nuxt:internal:dev:rejection', message }), @@ -65,10 +76,37 @@ class IPC { } await initialize(message.context, { listenOverrides: message.listenOverrides }) } + else if (message.type === 'nuxt:internal:dev:shutdown') { + await this.close() + } }) this.send({ type: 'nuxt:internal:dev:fork-ready' }) } + /** Register the shutdown routine to run before this fork exits. */ + onShutdown(handler: () => Promise): void { + this.#shutdown = handler + } + + /** + * Run the dev server's `close` hooks to completion before exiting, so user code + * (nitro plugins, database connections) can tear itself down. + */ + close(): Promise { + this.#closing ??= (async () => { + try { + await this.#shutdown?.() + } + catch (error) { + debug('Could not shut the dev server down cleanly:', error) + } + finally { + process.exit(0) + } + })() + return this.#closing + } + send(message: T) { if (this.enabled) { process.send?.(message) @@ -171,24 +209,28 @@ export async function initialize(devContext: NuxtDevContext, ctx: InitializeOpti const armRestart = createRestartHook(devServer) + const close = () => { + closePromise ??= (async () => { + devServer.closeWatchers() + try { + await Promise.all([ + devServer.listener.close(), + devServer.close(), + ]) + } + finally { + devServer.releaseLock() + } + })() + return closePromise + } + + ipc.onShutdown(close) + return { listener: devServer.listener, reload: (reason?: DevRestartReason) => devServer.load(true, reason), - close: () => { - closePromise ??= (async () => { - devServer.closeWatchers() - try { - await Promise.all([ - devServer.listener.close(), - devServer.close(), - ]) - } - finally { - devServer.releaseLock() - } - })() - return closePromise - }, + close, onReady: (callback: (address: string) => void) => { if (address) { callback(address) diff --git a/packages/nuxt-cli/src/dev/pool.ts b/packages/nuxt-cli/src/dev/pool.ts index c1b7bd78f..d5ad0a438 100644 --- a/packages/nuxt-cli/src/dev/pool.ts +++ b/packages/nuxt-cli/src/dev/pool.ts @@ -1,11 +1,12 @@ import type { ChildProcess } from 'node:child_process' import type { InspectOptions } from './inspect' import type { DevListenOverrides } from './listen' -import type { NuxtDevContext, NuxtDevIPCMessage } from './utils' +import type { NuxtDevContext, NuxtDevIPCMessage, NuxtParentIPCMessage } from './utils' import { fork } from 'node:child_process' import process from 'node:process' -import { debug } from '../utils/logger' +import { debug, logger } from '../utils/logger' +import { DEV_SHUTDOWN_TIMEOUT_MS, FORCE_KILL_TIMEOUT_MS } from './shutdown' interface ForkPoolOptions { rawArgs: string[] @@ -54,13 +55,9 @@ export class ForkPool { this.listenOverrides = options.listenOverrides this.inspect = options.inspect - // Graceful shutdown - for (const signal of [ - 'exit', - 'SIGTERM' /* Graceful shutdown */, - 'SIGINT' /* Ctrl-C */, - 'SIGQUIT' /* Ctrl-\ */, - ] as const) { + // last-resort for forks that outlive this process. nuxt closes forks gracefully + // on `SIGINT`/`SIGTERM`, so we skip them. + for (const signal of ['exit', 'SIGQUIT'] as const) { process.once(signal, () => { this.killAll(signal === 'exit' ? 0 : signal) }) @@ -116,7 +113,7 @@ export class ForkPool { promote: () => { fork.serving = true }, - close: () => this.killFork(fork), + close: () => this.closeFork(fork), } } @@ -223,6 +220,9 @@ export class ForkPool { // entry, or a kill), which would leave `ready` pending forever. readyReject(new Error('Dev server fork exited before it finished starting.')) if (pooledFork.serving && errorCode) { + // Ending the session on the crash of the process that holds the listener is + // silent otherwise, leaving no clue as to what stopped the dev server. + logger.error(`The dev server process (PID ${childProc.pid}) exited with code ${errorCode}.`) // Active fork crashed process.exit(errorCode) } @@ -241,6 +241,42 @@ export class ForkPool { }) } + /** + * Ask a fork to shut down and wait for its `close` hooks to run, so nitro plugins + * and anything else the app opened get to tear down before the process goes away. + * A fork that takes too long is signalled instead. + */ + private async closeFork(fork: PooledFork): Promise { + if (fork.state === 'dead' || fork.process.exitCode !== null || !fork.process.connected) { + return this.killFork(fork) + } + + fork.state = 'dead' + // A fork we are shutting down on purpose must not end the session. + fork.serving = false + this.removeFork(fork) + + const exited = waitForExit(fork.process) + fork.process.send({ type: 'nuxt:internal:dev:shutdown' } satisfies NuxtParentIPCMessage, (error) => { + if (error) { + fork.process.kill('SIGTERM') + } + }) + + if (await settlesWithin(exited, DEV_SHUTDOWN_TIMEOUT_MS)) { + return + } + + debug(`Dev server fork ${fork.process.pid} did not shut down in time, terminating it`) + fork.process.kill('SIGTERM') + if (await settlesWithin(exited, FORCE_KILL_TIMEOUT_MS)) { + return + } + + fork.process.kill('SIGKILL') + await settlesWithin(exited, FORCE_KILL_TIMEOUT_MS) + } + private killFork(fork: PooledFork, signal: NodeJS.Signals | number = 'SIGTERM'): Promise { const wasAlive = fork.state !== 'dead' && !!fork.process && fork.process.exitCode === null fork.state = 'dead' @@ -292,3 +328,22 @@ export class ForkPool { } } } + +function waitForExit(child: ChildProcess): Promise { + return new Promise((resolve) => { + child.once('exit', () => resolve()) + child.once('close', () => resolve()) + }) +} + +/** Resolves `true` if the promise settles before the timeout, `false` otherwise. */ +function settlesWithin(promise: Promise, timeout: number): Promise { + return new Promise((resolve) => { + const timer = setTimeout(resolve, timeout, false) + timer.unref?.() + void promise.then(() => { + clearTimeout(timer) + resolve(true) + }) + }) +} diff --git a/packages/nuxt-cli/src/dev/shutdown.ts b/packages/nuxt-cli/src/dev/shutdown.ts new file mode 100644 index 000000000..5f6412942 --- /dev/null +++ b/packages/nuxt-cli/src/dev/shutdown.ts @@ -0,0 +1,15 @@ +/** + * How long a dev server process is given to run its `close` hooks. Nitro plugins + * use these to close database connections and the like, so anything that signals + * a dev server has to allow for them before escalating. + */ +export const DEV_SHUTDOWN_TIMEOUT_MS = 10_000 + +/** + * How long the process supervising a dev server waits for it to go away. Longer + * than the budget above, since the fork spends that budget before exiting. + */ +export const SUPERVISOR_SHUTDOWN_TIMEOUT_MS = 15_000 + +/** How long a signalled process has to disappear before we give up on it. */ +export const FORCE_KILL_TIMEOUT_MS = 2000 diff --git a/packages/nuxt-cli/src/dev/takeover.ts b/packages/nuxt-cli/src/dev/takeover.ts index c5a084fe2..e7d17a0d1 100644 --- a/packages/nuxt-cli/src/dev/takeover.ts +++ b/packages/nuxt-cli/src/dev/takeover.ts @@ -10,9 +10,8 @@ import { isCI } from 'std-env' import { restoreRawMode, withDirectStdout } from '../utils/console' import { clearStaleLock, clearTakeover, isInteractiveSession, isLockEnabled, isProcessAlive, markTakenOver, readLock } from '../utils/lockfile' import { logger } from '../utils/logger' +import { DEV_SHUTDOWN_TIMEOUT_MS } from './shutdown' -/** How long the outgoing dev server has to exit and release its port. */ -const TAKEOVER_TIMEOUT_MS = 5000 /** How long a `SIGKILL`ed process has to disappear before we give up. */ const TAKEOVER_KILL_TIMEOUT_MS = 1000 const TAKEOVER_POLL_INTERVAL_MS = 100 @@ -154,7 +153,7 @@ async function performTakeover(buildDir: string, existing: LockInfo, timeouts: T // On Windows `SIGTERM` is not delivered as a signal and terminates the process // outright, so the graceful window below simply passes quickly there. signalAll(pids, 'SIGTERM') - if (await waitForRelease(pids, port, existing.hostname, timeouts.graceful ?? TAKEOVER_TIMEOUT_MS)) { + if (await waitForRelease(pids, port, existing.hostname, timeouts.graceful ?? DEV_SHUTDOWN_TIMEOUT_MS)) { progress.stop(`Stopped the dev server on port ${port} (PID ${existing.pid})`) return { action: 'taken', port, pid: existing.pid } } diff --git a/packages/nuxt-cli/src/dev/utils.ts b/packages/nuxt-cli/src/dev/utils.ts index b728ef9d3..f65468f7f 100644 --- a/packages/nuxt-cli/src/dev/utils.ts +++ b/packages/nuxt-cli/src/dev/utils.ts @@ -36,6 +36,7 @@ import { formatChangedKeys, formatRestartReason, formatSkippedReload, mergeResta export type NuxtParentIPCMessage = | { type: 'nuxt:internal:dev:context', context: NuxtDevContext, listenOverrides: DevListenOverrides, inspect?: InspectOptions } + | { type: 'nuxt:internal:dev:shutdown' } export type NuxtDevIPCMessage = | { type: 'nuxt:internal:dev:fork-ready' } diff --git a/packages/nuxt-cli/src/main.ts b/packages/nuxt-cli/src/main.ts index 5fcb7c613..e5d11ff8e 100644 --- a/packages/nuxt-cli/src/main.ts +++ b/packages/nuxt-cli/src/main.ts @@ -11,7 +11,7 @@ import { provider } from 'std-env' import { description, name, version } from '../package.json' import { commands } from './commands' import { cwdArgs } from './commands/_shared' -import { runCommand } from './run' +import { runCommand, setCurrentCommand } from './run' import { normaliseCwdArg } from './utils/args' import { setupGlobalConsole } from './utils/console' import { checkEngines } from './utils/engines' @@ -44,6 +44,7 @@ const _main = defineCommand({ normaliseCwdArg(ctx.rawArgs) const command = ctx.args._[0] + setCurrentCommand(command) setupGlobalConsole({ dev: command === 'dev' }) if (command !== '_dev' && provider !== 'stackblitz') { diff --git a/packages/nuxt-cli/src/run.ts b/packages/nuxt-cli/src/run.ts index 583baeb01..22182105f 100644 --- a/packages/nuxt-cli/src/run.ts +++ b/packages/nuxt-cli/src/run.ts @@ -6,6 +6,7 @@ import { runCommand as _runCommand, runMain as _runMain } from 'citty' import { commands } from './commands' import { main } from './main' import { normaliseCwdArg } from './utils/args' +import { warnOnHang } from './utils/hang' globalThis.__nuxt_cli__ = globalThis.__nuxt_cli__ || { // Programmatic usage fallback @@ -18,12 +19,26 @@ globalThis.__nuxt_cli__ = globalThis.__nuxt_cli__ || { ), } +// Commands that keep serving after their `run` resolves, so an alive process is expected. +const LONG_RUNNING_COMMANDS = new Set(['dev', '_dev', 'analyze', 'test']) + +let currentCommand: string | undefined + +/** Record the command being run, so `runMain` knows whether the process is expected to exit. */ +export function setCurrentCommand(command: string | undefined): void { + currentCommand = command +} + export async function runMain(): Promise { if (process.argv[2] === 'complete') { const { initCompletions } = await import('./completions') await initCompletions(main) } - return _runMain(main) + await _runMain(main) + + if (!currentCommand || !LONG_RUNNING_COMMANDS.has(currentCommand)) { + warnOnHang({ action: currentCommand ? `\`nuxt ${currentCommand}\`` : 'command' }) + } } export async function runCommand( diff --git a/packages/nuxt-cli/src/utils/hang.ts b/packages/nuxt-cli/src/utils/hang.ts new file mode 100644 index 000000000..b5fd83744 --- /dev/null +++ b/packages/nuxt-cli/src/utils/hang.ts @@ -0,0 +1,80 @@ +import process from 'node:process' + +import { logger } from './logger' + +/** Handles that are present in every process (stdio, signal listeners) and never the reason a command hangs. */ +const IGNORED_RESOURCES = new Set(['TTYWrap', 'PipeWrap', 'FileHandle', 'SignalWrap']) + +const RESOURCE_LABELS: Record = { + ChildProcess: 'child process', + FSEventWrap: 'file watcher', + FSReqCallback: 'file system operation', + FSReqPromise: 'file system operation', + Immediate: 'timer', + MessagePort: 'worker thread', + Process: 'child process', + StatWatcher: 'file watcher', + TCPServerWrap: 'server', + TCPSocketWrap: 'open connection', + TCPWrap: 'open connection', + Timeout: 'timer', + TLSWrap: 'open connection', + UDPWrap: 'open connection', + Worker: 'worker thread', +} + +/** + * Describe what is currently keeping the event loop alive, as a human-readable list + * such as `2 timers, 1 file watcher`. Returns `undefined` when nothing but the + * process's own stdio is left, which points at an unsettled promise instead. + */ +export function summariseActiveResources(resources: string[] = process.getActiveResourcesInfo()): string | undefined { + const counts = new Map() + for (const resource of resources) { + if (IGNORED_RESOURCES.has(resource)) { + continue + } + const label = RESOURCE_LABELS[resource] || resource + counts.set(label, (counts.get(label) ?? 0) + 1) + } + + if (counts.size === 0) { + return undefined + } + + return [...counts] + .map(([label, count]) => count === 1 ? `1 ${label}` : `${count} ${label}s`) + .join(', ') +} + +export interface HangWarningOptions { + /** How long to wait after the work is done before warning. Defaults to 5s. */ + timeout?: number + /** What has just finished, used in the warning. Defaults to `command`. */ + action?: string + warn?: (message: string) => void +} + +/** + * Warn if the process is still running some time after its work is done. + * + * The timer is unref'd, so it only ever fires when something else is holding the + * event loop open, and it never delays an exit that would otherwise happen. + * Returns a function to disarm it. + */ +export function warnOnHang(options: HangWarningOptions = {}): () => void { + const { timeout = 5000, action = 'command', warn = (message: string) => logger.warn(message) } = options + + const timer = setTimeout(() => { + const summary = summariseActiveResources() + warn([ + `The ${action} is complete but the process is still running${summary ? `: ${summary}` : ''}.`, + summary + ? 'A module, plugin or dependency is likely holding these open. Nuxt will exit once they are closed.' + : 'Nothing is registered on the event loop, so a pending promise is likely never settling.', + ].join('\n')) + }, timeout) + timer.unref?.() + + return () => clearTimeout(timer) +} diff --git a/packages/nuxt-cli/test/unit/hang.spec.ts b/packages/nuxt-cli/test/unit/hang.spec.ts new file mode 100644 index 000000000..de01b273a --- /dev/null +++ b/packages/nuxt-cli/test/unit/hang.spec.ts @@ -0,0 +1,52 @@ +import { describe, expect, it, vi } from 'vitest' + +import { summariseActiveResources, warnOnHang } from '../../src/utils/hang' + +describe('summariseActiveResources', () => { + it('should ignore the handles every process has', () => { + expect(summariseActiveResources(['TTYWrap', 'PipeWrap', 'SignalWrap', 'FileHandle'])).toBeUndefined() + }) + + it('should group resources by what they mean to a user', () => { + expect(summariseActiveResources(['Timeout', 'Timeout', 'Immediate', 'FSEventWrap', 'TCPWrap'])).toBe('3 timers, 1 file watcher, 1 open connection') + }) + + it('should fall back to the internal name for unknown resources', () => { + expect(summariseActiveResources(['SomeAddonHandle'])).toBe('1 SomeAddonHandle') + }) +}) + +describe('warnOnHang', () => { + it('should report what is keeping the process alive', async () => { + vi.useFakeTimers() + try { + const warn = vi.fn() + const interval = setInterval(() => {}, 1000) + warnOnHang({ timeout: 10, action: '`nuxt build`', warn }) + + await vi.advanceTimersByTimeAsync(10) + + clearInterval(interval) + expect(warn).toHaveBeenCalledOnce() + expect(warn.mock.calls[0]![0]).toContain('The `nuxt build` is complete but the process is still running') + } + finally { + vi.useRealTimers() + } + }) + + it('should not warn once disarmed', async () => { + vi.useFakeTimers() + try { + const warn = vi.fn() + warnOnHang({ timeout: 10, warn })() + + await vi.advanceTimersByTimeAsync(100) + + expect(warn).not.toHaveBeenCalled() + } + finally { + vi.useRealTimers() + } + }) +}) diff --git a/packages/nuxt-cli/test/unit/pool.spec.ts b/packages/nuxt-cli/test/unit/pool.spec.ts index 6b50af947..4c5051675 100644 --- a/packages/nuxt-cli/test/unit/pool.spec.ts +++ b/packages/nuxt-cli/test/unit/pool.spec.ts @@ -6,14 +6,19 @@ import process from 'node:process' import { beforeEach, describe, expect, it, vi } from 'vitest' import { ForkPool } from '../../src/dev/pool' +import { logger } from '../../src/utils/logger' let nextPid = 1000 class FakeFork extends EventEmitter { pid = nextPid++ exitCode: number | null = null + connected = true sent: any[] = [] killed?: NodeJS.Signals | number + signals: Array = [] + /** Whether a `kill` should be honoured, so a fork can be made to ignore signals. */ + exitsOnKill = true send(message: unknown) { this.sent.push(message) @@ -21,12 +26,22 @@ class FakeFork extends EventEmitter { } kill(signal: NodeJS.Signals | number) { + this.signals.push(signal) this.killed = signal + if (!this.exitsOnKill) { + return true + } this.exitCode = 0 this.emit('exit', 0, null) return true } + exit() { + this.exitCode = 0 + this.connected = false + this.emit('exit', 0, null) + } + ready() { this.emit('message', { type: 'nuxt:internal:dev:fork-ready' }) } @@ -91,6 +106,29 @@ describe('fork pool', () => { exit.mockRestore() }) + it('should say why the session ended when the serving fork crashes', async () => { + const exit = vi.spyOn(process, 'exit').mockImplementation(() => undefined as never) + const error = vi.spyOn(logger, 'error').mockImplementation(() => {}) + + const active = await createPool().getFork(context) + active.promote() + forks.find(f => f.pid === active.pid)!.emit('close', 1, null) + + expect(error).toHaveBeenCalledWith(expect.stringContaining(`PID ${active.pid}`)) + expect(error).toHaveBeenCalledWith(expect.stringContaining('exited with code 1')) + + error.mockRestore() + exit.mockRestore() + }) + + it('should leave `SIGINT` and `SIGTERM` to the graceful shutdown path', () => { + const before = ['SIGINT', 'SIGTERM'].map(signal => process.listenerCount(signal)) + + createPool() + + expect(['SIGINT', 'SIGTERM'].map(signal => process.listenerCount(signal))).toEqual(before) + }) + it('should not end the session when the serving fork is closed deliberately', async () => { const exit = vi.spyOn(process, 'exit').mockImplementation(() => undefined as never) const active = await createPool().getFork(context) @@ -125,6 +163,51 @@ describe('fork pool', () => { }) }) + it('should let a fork run its close hooks before it exits', async () => { + const active = await createPool().getFork(context) + const child = forks.find(f => f.pid === active.pid)! + + const closing = active.close() + expect(child.sent.at(-1)).toMatchObject({ type: 'nuxt:internal:dev:shutdown' }) + expect(child.killed).toBeUndefined() + + child.exit() + await closing + }) + + it('should terminate a fork that does not shut down in time', async () => { + vi.useFakeTimers() + try { + const active = await createPool().getFork(context) + const child = forks.find(f => f.pid === active.pid)! + child.exitsOnKill = false + + const closing = active.close() + await vi.advanceTimersByTimeAsync(10_000) + expect(child.signals).toEqual(['SIGTERM']) + + await vi.advanceTimersByTimeAsync(2000) + expect(child.signals).toEqual(['SIGTERM', 'SIGKILL']) + + await vi.advanceTimersByTimeAsync(2000) + await closing + } + finally { + vi.useRealTimers() + } + }) + + it('should signal a fork whose IPC channel is already gone', async () => { + const active = await createPool().getFork(context) + const child = forks.find(f => f.pid === active.pid)! + child.connected = false + + await active.close() + + expect(child.sent.some(m => m.type === 'nuxt:internal:dev:shutdown')).toBe(false) + expect(child.killed).toBe('SIGTERM') + }) + it('should forward messages other than fork readiness', async () => { const onMessage = vi.fn() await createPool().getFork(context, { onMessage })