diff --git a/packages/kernel-browser-runtime/CHANGELOG.md b/packages/kernel-browser-runtime/CHANGELOG.md index b63734215d..e101fdcb30 100644 --- a/packages/kernel-browser-runtime/CHANGELOG.md +++ b/packages/kernel-browser-runtime/CHANGELOG.md @@ -7,6 +7,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +### Added + +- Log a fatal message when the kernel's run loop dies, since the worker outlives the kernel and has no exit to take ([#1005](https://github.com/MetaMask/ocap-kernel/pull/1005)) + ### Fixed - Process platform-services RPC request handlers in the background so a request handler that fires a reentrant outbound RPC (e.g. transport handshake calling back into the kernel) cannot deadlock waiting for its response ([#948](https://github.com/MetaMask/ocap-kernel/pull/948)) diff --git a/packages/kernel-browser-runtime/src/kernel-worker/kernel-worker.ts b/packages/kernel-browser-runtime/src/kernel-worker/kernel-worker.ts index b5e33df321..832a57a906 100644 --- a/packages/kernel-browser-runtime/src/kernel-worker/kernel-worker.ts +++ b/packages/kernel-browser-runtime/src/kernel-worker/kernel-worker.ts @@ -64,6 +64,20 @@ async function main(): Promise { const kernelP = Kernel.make(platformServicesClient, kernelDatabase, { resetStorage, systemSubclusters, + // Log and stay up, deliberately. `self.close()` would match what the daemon + // does, but here it would remove the only diagnostic without buying any + // recovery: nothing respawns this worker, the vat iframes belong to the + // offscreen document and would outlive it as orphans, and the panel keeps + // its last successful status when polling fails — so it would go on showing + // a healthy kernel forever. Staying up is what lets `getStatus` report + // `runLoop: failed` and the panel say so. Reviving the browser kernel means + // teardown and respawn driven from the offscreen document. + onRunLoopFailure: (error) => { + logger.error( + 'Kernel run loop died; this worker must be reloaded.', + error, + ); + }, }); const handlerP = kernelP.then((kernel) => { diff --git a/packages/kernel-cli/CHANGELOG.md b/packages/kernel-cli/CHANGELOG.md index 6d2f044716..e09095da01 100644 --- a/packages/kernel-cli/CHANGELOG.md +++ b/packages/kernel-cli/CHANGELOG.md @@ -23,6 +23,11 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 - `kernel daemon start` refuses to start when another daemon is already listening on the same Unix socket, instead of unlinking the socket and orphaning the running process ([#952](https://github.com/MetaMask/ocap-kernel/pull/952)) - Daemon fatal-path visibility: `daemon-entry` now installs handlers for `uncaughtException`, `unhandledRejection`, `SIGHUP`, and `exit` that append a synchronous fingerprint line to `daemon.log` before terminating ([#966](https://github.com/MetaMask/ocap-kernel/pull/966)) - Without these, silent daemon deaths under `stdio: 'ignore'` (the CLI's default spawn mode) left no trace in the log; the operator saw only that the daemon was gone. Every terminating path now leaves at least one line. +- The daemon logs the failure and shuts down with a non-zero exit code when the kernel's run loop dies, instead of staying up with a socket that answers RPCs for a kernel that processes nothing ([#1005](https://github.com/MetaMask/ocap-kernel/pull/1005)) + - A death during startup aborts `daemon start` instead of publishing a socket and pid file for a dead kernel + - Shutdown is bounded at 10 seconds and terminates the process either way, removing the pid file first. Live vat worker threads hold the event loop open, so an exit code alone never took effect, leaving an orphan on `kernel.sqlite` that neither start-time interlock could see + - Failures carry their `cause` chain, so a death reported through a failed crank rollback still names the error that killed the kernel + - Logging in front of a shutdown or `process.exit` is best-effort, the fatal handlers included: the transport is `appendFileSync`, so a full disk would otherwise take the termination with it ## [0.1.0] diff --git a/packages/kernel-cli/src/commands/daemon-entry.ts b/packages/kernel-cli/src/commands/daemon-entry.ts index 77d96b00ea..b4c8d69406 100644 --- a/packages/kernel-cli/src/commands/daemon-entry.ts +++ b/packages/kernel-cli/src/commands/daemon-entry.ts @@ -2,12 +2,18 @@ import '@metamask/kernel-shims/endoify-node'; import { makeKernel } from '@metamask/kernel-node-runtime'; import { startDaemon } from '@metamask/kernel-node-runtime/daemon'; import type { DaemonHandle } from '@metamask/kernel-node-runtime/daemon'; +import { stringify } from '@metamask/kernel-utils'; import type { LogEntry } from '@metamask/logger'; import { Logger } from '@metamask/logger'; -import { appendFileSync } from 'node:fs'; +import { appendFileSync, rmSync } from 'node:fs'; import { mkdir, readFile, rm, writeFile } from 'node:fs/promises'; import { join } from 'node:path'; +import { + cleanUpFailedStartup, + logBestEffort, + makeDaemonRunLoopWiring, +} from './run-loop-failure.ts'; import { getOcapHome } from '../ocap-home.ts'; import { isProcessAlive } from '../utils.ts'; @@ -60,8 +66,25 @@ const logger = new Logger({ installFatalHandlers(); main().catch((error) => { - process.stderr.write(`Daemon fatal: ${String(error)}\n`); - process.exitCode = 1; + // Best-effort, because the exit below is downstream of it: a throwing + // transport would otherwise escape to `unhandledRejection`, whose handler logs + // too and so throws again, leaving the process to die only because Node aborts + // when its own exception handler fails — code 7, and not even the `exit` + // fingerprint survives that. + // stderr is `ignore` under the CLI spawner, so the log file is the only place + // this can be read; `stringify` keeps the `cause` chain that `String` drops. + logBestEffort(logger, 'error', 'Daemon fatal', stringify(error, 0)); + try { + process.stderr.write(`Daemon fatal: ${String(error)}\n`); + } catch { + // A closed stderr must not preempt the exit either. + } + // Not `process.exitCode`: a kernel that got as far as launching vats holds + // live worker threads, and those keep the event loop running, so a code alone + // would leave the daemon up with no socket and no pid file — an orphan + // neither interlock can see. + // eslint-disable-next-line n/no-process-exit -- a daemon that cannot start must not linger + process.exit(1); }); /** @@ -74,14 +97,32 @@ async function main(): Promise { process.env.OCAP_SOCKET_PATH ?? join(ocapDir, 'daemon.sock'); const dbFilename = join(ocapDir, 'kernel.sqlite'); + const pidPath = join(ocapDir, 'daemon.pid'); + + // Declared before `makeKernel` so the failure wiring can close over it: the + // kernel may report a death before `startDaemon` has returned. + let shutdownPromise: Promise | undefined; + + const runLoop = makeDaemonRunLoopWiring({ + logger, + shutdown: async (reason) => shutdown(reason), + isShuttingDown: () => shutdownPromise !== undefined, + // eslint-disable-next-line n/no-sync -- must finish before process.exit + removePidFile: () => rmSync(pidPath, { force: true }), + setExitCode: (code) => { + process.exitCode = code; + }, + // eslint-disable-next-line n/no-process-exit -- a broken shutdown must still terminate + exit: (code) => process.exit(code), + }); + const { kernel, kernelDatabase } = await makeKernel({ resetStorage: false, dbFilename, logger, + onRunLoopFailure: runLoop.onRunLoopFailure, }); - const pidPath = join(ocapDir, 'daemon.pid'); - // Interlock: refuse to start a second daemon under the same OCAP_HOME. // The socket-binding interlock in startDaemon handles the live-socket // case; this catches the rarer case where an orphan still holds the @@ -101,6 +142,7 @@ async function main(): Promise { let handle: DaemonHandle; try { await kernel.initIdentity(); + runLoop.assertSurvivedStartup(); await writeFile(pidPath, String(process.pid)); handle = await startDaemon({ @@ -110,19 +152,18 @@ async function main(): Promise { onShutdown: async () => shutdown('RPC shutdown'), }); } catch (error) { - try { - kernel.stop().catch(() => undefined); - kernelDatabase.close(); - } catch { - // Best-effort cleanup. - } - rm(pidPath, { force: true }).catch(() => undefined); + await cleanUpFailedStartup({ + logger, + stopKernel: async () => kernel.stop(), + closeDatabase: () => kernelDatabase.close(), + // eslint-disable-next-line n/no-sync -- must finish before process.exit + removePidFile: () => rmSync(pidPath, { force: true }), + }); throw error; } logger.info(`Daemon started. Socket: ${handle.socketPath}`); - let shutdownPromise: Promise | undefined; /** * Shut down the daemon idempotently. Concurrent calls coalesce. * @@ -139,6 +180,10 @@ async function main(): Promise { return shutdownPromise; } + // Must follow `shutdown`, which a replayed failure calls and which needs + // `handle`. + runLoop.daemonStarted(); + process.on('SIGTERM', () => { shutdown('SIGTERM').catch(() => (process.exitCode = 1)); }); @@ -197,7 +242,11 @@ function makeFileTransport(logFilePath: string, minLevel: LogLevelName) { * file transport we're using here is `appendFileSync` under the * hood, so `logger.error(...)` from inside a fatal handler flushes * to disk before the process exits — no separate sync-write path - * is required. + * is required. That same `appendFileSync` throws on a full disk, + * though, and here the log runs *before* the `process.exit` that + * terminates the vat workers holding the event loop open, so every + * one of these logs best-effort: the line is worth less than the + * exit it would otherwise block. * * Handlers registered: * @@ -219,25 +268,19 @@ function makeFileTransport(logFilePath: string, minLevel: LogLevelName) { function installFatalHandlers(): void { /* eslint-disable n/no-process-exit -- fatal handlers must terminate deterministically */ process.on('uncaughtException', (error: unknown) => { - const detail = - error instanceof Error ? (error.stack ?? error.message) : String(error); - logger.error('Uncaught exception', detail); + logBestEffort(logger, 'error', 'Uncaught exception', stringify(error, 0)); process.exit(1); }); process.on('unhandledRejection', (reason: unknown) => { - const detail = - reason instanceof Error - ? (reason.stack ?? reason.message) - : String(reason); - logger.error('Unhandled rejection', detail); + logBestEffort(logger, 'error', 'Unhandled rejection', stringify(reason, 0)); process.exit(1); }); process.on('SIGHUP', () => { - logger.error('SIGHUP received; exiting.'); + logBestEffort(logger, 'error', 'SIGHUP received; exiting.'); process.exit(0); }); process.on('exit', (code) => { - logger.error(`Process exiting (code=${code}).`); + logBestEffort(logger, 'error', `Process exiting (code=${code}).`); }); /* eslint-enable n/no-process-exit */ } diff --git a/packages/kernel-cli/src/commands/run-loop-failure.test.ts b/packages/kernel-cli/src/commands/run-loop-failure.test.ts new file mode 100644 index 0000000000..31f5b1e56d --- /dev/null +++ b/packages/kernel-cli/src/commands/run-loop-failure.test.ts @@ -0,0 +1,627 @@ +// The mock shim rather than real lockdown: `vi.useFakeTimers()` cannot install +// its clock over a hardened `Date`, and this module's watchdog is the thing +// under test. +import '@ocap/repo-tools/test-utils/mock-endoify'; + +import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest'; + +import { + cleanUpFailedStartup, + logBestEffort, + makeDaemonRunLoopWiring, + makeRunLoopFailureHandler, + SHUTDOWN_TIMEOUT_MS, +} from './run-loop-failure.ts'; +import type { + DaemonRunLoopWiring, + DaemonRunLoopWiringOptions, + FailedStartupCleanupOptions, + RunLoopFailureHandlerOptions, +} from './run-loop-failure.ts'; + +/** + * Make a handler over spies, defaulting to "the daemon is up and not shutting + * down" so each test overrides only what it is about. + * + * @param overrides - Options to replace. + * @returns The handler and the spies it was built from. + */ +const makeHandler = ( + overrides: Partial = {}, +): { + handle: (failure: Error) => void; + logger: { error: ReturnType; info: ReturnType }; + shutdown: ReturnType; + recordFailure: ReturnType; + removePidFile: ReturnType; + setExitCode: ReturnType; + exit: ReturnType; +} => { + const logger = { error: vi.fn(), info: vi.fn() }; + const shutdown = vi.fn().mockResolvedValue(undefined); + const recordFailure = vi.fn(); + const removePidFile = vi.fn(); + const setExitCode = vi.fn(); + const exit = vi.fn(); + const handle = makeRunLoopFailureHandler({ + logger, + shutdown, + isStarted: () => true, + isShuttingDown: () => false, + recordFailure, + removePidFile, + setExitCode, + exit, + ...overrides, + }); + return { + handle, + logger, + shutdown, + recordFailure, + removePidFile, + setExitCode, + exit, + }; +}; + +// `daemon-entry` calls this in front of every `process.exit` it owns, and that +// exit is the only thing that terminates live vat workers. +describe('logBestEffort', () => { + it('records the message', () => { + const logger = { error: vi.fn(), info: vi.fn() }; + + logBestEffort(logger, 'error', 'Daemon fatal', 'the detail'); + + expect(logger.error).toHaveBeenCalledWith('Daemon fatal', 'the detail'); + }); + + it.each(['error', 'info'] as const)( + 'swallows a %s transport that throws', + (level) => { + const logger = { + error: vi.fn().mockImplementation(() => { + throw new Error('ENOSPC'); + }), + info: vi.fn().mockImplementation(() => { + throw new Error('ENOSPC'); + }), + }; + + expect(() => logBestEffort(logger, level, 'Daemon fatal')).not.toThrow(); + }, + ); +}); + +describe('makeRunLoopFailureHandler', () => { + beforeEach(() => { + vi.useFakeTimers(); + }); + + afterEach(() => { + vi.useRealTimers(); + }); + + it('shuts the daemon down and marks the exit non-zero', async () => { + const { handle, shutdown, setExitCode, logger, exit } = makeHandler(); + + handle(new Error('crank exploded')); + await vi.runAllTimersAsync(); + + expect(shutdown).toHaveBeenCalledWith('run loop failure'); + expect(setExitCode).toHaveBeenCalledWith(1); + expect(logger.error).toHaveBeenCalledWith( + 'Kernel run loop died; shutting down the daemon.', + expect.stringContaining('crank exploded'), + ); + // A shutdown that worked leaves the process to wind down on its own. + expect(exit).not.toHaveBeenCalled(); + }); + + // `stringify` is what carries the chain; `error.stack` would drop it, and when + // a crank's rollback fails the rollback is the outer error and the failure that + // actually killed the kernel is only reachable through `cause`. + it('logs the cause chain, not just the outermost error', () => { + const { handle, logger } = makeHandler(); + + handle( + new Error('could not be rolled back', { + cause: new Error('database is gone'), + }), + ); + + expect(logger.error).toHaveBeenCalledWith( + 'Kernel run loop died; shutting down the daemon.', + expect.stringContaining('database is gone'), + ); + }); + + it('records the failure before doing anything else', () => { + const failure = new Error('crank exploded'); + const { handle, recordFailure } = makeHandler({ isStarted: () => false }); + + handle(failure); + + expect(recordFailure).toHaveBeenCalledWith(failure); + }); + + it('only records the first failure', () => { + let recorded: Error | undefined; + const { handle } = makeHandler({ + recordFailure: (failure) => { + recorded ??= failure; + }, + isStarted: () => false, + }); + + handle(new Error('first')); + handle(new Error('second')); + + expect(recorded?.message).toBe('first'); + }); + + it('does not shut down before the daemon has started', () => { + const { handle, shutdown, setExitCode, logger } = makeHandler({ + isStarted: () => false, + }); + + handle(new Error('died during startup')); + + expect(shutdown).not.toHaveBeenCalled(); + expect(setExitCode).not.toHaveBeenCalled(); + expect(logger.error).toHaveBeenCalledWith( + 'Kernel run loop died before the daemon started.', + expect.stringContaining('died during startup'), + ); + }); + + // A loop stopping because someone asked the daemon to stop is not an outage, + // and must not turn a deliberate `ocap daemon stop` into a non-zero exit. + it('does not fail a shutdown already under way', () => { + const { handle, shutdown, setExitCode, exit, logger } = makeHandler({ + isShuttingDown: () => true, + }); + + handle(new Error('loop stopped')); + + expect(shutdown).not.toHaveBeenCalled(); + expect(setExitCode).not.toHaveBeenCalled(); + expect(exit).not.toHaveBeenCalled(); + expect(logger.info).toHaveBeenCalledWith( + 'Kernel run loop stopped during shutdown.', + expect.stringContaining('loop stopped'), + ); + }); + + // Live vat workers hold the event loop open, so `setExitCode` alone would leave + // an orphan on kernel.sqlite with its socket already gone. + it('kills the process when the shutdown stalls', async () => { + const { handle, removePidFile, exit, logger } = makeHandler({ + shutdown: vi.fn().mockReturnValue(new Promise(() => undefined)), + }); + + handle(new Error('crank exploded')); + expect(exit).not.toHaveBeenCalled(); + + await vi.advanceTimersByTimeAsync(SHUTDOWN_TIMEOUT_MS); + + expect(logger.error).toHaveBeenCalledWith( + `Shutdown stalled for ${SHUTDOWN_TIMEOUT_MS} ms after run loop failure; exiting now.`, + ); + // Removed before exiting, so the next `ocap daemon start` isn't blocked by a + // pid file whose owner is gone. + expect(removePidFile).toHaveBeenCalled(); + expect(exit).toHaveBeenCalledWith(1); + }); + + it('waits the full timeout before killing the process', async () => { + const { handle, exit } = makeHandler({ + shutdown: vi.fn().mockReturnValue(new Promise(() => undefined)), + timeoutMs: 5_000, + }); + + handle(new Error('crank exploded')); + await vi.advanceTimersByTimeAsync(4_999); + expect(exit).not.toHaveBeenCalled(); + + await vi.advanceTimersByTimeAsync(1); + expect(exit).toHaveBeenCalledWith(1); + }); + + it('kills the process when the shutdown throws', async () => { + const { handle, removePidFile, exit, logger } = makeHandler({ + shutdown: vi.fn().mockRejectedValue(new Error('close failed')), + }); + + handle(new Error('crank exploded')); + await vi.runAllTimersAsync(); + + expect(logger.error).toHaveBeenCalledWith( + 'Shutdown after run loop failure failed; exiting now.', + expect.stringContaining('close failed'), + ); + expect(removePidFile).toHaveBeenCalled(); + expect(exit).toHaveBeenCalledWith(1); + }); + + // The watchdog must not fire after the process is already on its way out, or a + // second `exit` lands during teardown. + it('disarms the watchdog once the shutdown settles', async () => { + const { handle, exit } = makeHandler({ + shutdown: vi.fn().mockRejectedValue(new Error('close failed')), + }); + + handle(new Error('crank exploded')); + await vi.runAllTimersAsync(); + expect(exit).toHaveBeenCalledOnce(); + + await vi.advanceTimersByTimeAsync(SHUTDOWN_TIMEOUT_MS * 2); + + expect(exit).toHaveBeenCalledOnce(); + }); + + it('still exits when removing the pid file fails', async () => { + const { handle, exit, logger } = makeHandler({ + shutdown: vi.fn().mockRejectedValue(new Error('close failed')), + removePidFile: () => { + throw new Error('EPERM'); + }, + }); + + handle(new Error('crank exploded')); + await vi.runAllTimersAsync(); + + expect(logger.error).toHaveBeenCalledWith( + 'Could not remove the pid file before exiting.', + expect.stringContaining('EPERM'), + ); + expect(exit).toHaveBeenCalledWith(1); + }); + + // The daemon logs with `appendFileSync`, and the kernel swallows what this + // handler throws, so a failed log would leave a daemon serving a dead kernel. + it('shuts down even when the log transport throws', async () => { + const { handle, shutdown, setExitCode, exit } = makeHandler({ + logger: { + error: vi.fn().mockImplementation(() => { + throw new Error('ENOSPC'); + }), + info: vi.fn(), + }, + }); + + expect(() => handle(new Error('crank exploded'))).not.toThrow(); + await vi.runAllTimersAsync(); + + expect(setExitCode).toHaveBeenCalledWith(1); + expect(shutdown).toHaveBeenCalledWith('run loop failure'); + expect(exit).not.toHaveBeenCalled(); + }); + + // The disk can fill up between the first log and the last. + it('kills the process when a later log transport throws', async () => { + let calls = 0; + const { handle, removePidFile, exit } = makeHandler({ + logger: { + error: vi.fn().mockImplementation(() => { + calls += 1; + if (calls > 1) { + throw new Error('ENOSPC'); + } + }), + info: vi.fn(), + }, + shutdown: vi.fn().mockReturnValue(new Promise(() => undefined)), + }); + + handle(new Error('crank exploded')); + await vi.advanceTimersByTimeAsync(SHUTDOWN_TIMEOUT_MS); + + expect(removePidFile).toHaveBeenCalled(); + expect(exit).toHaveBeenCalledWith(1); + }); + + // An unhandled rejection here would be reported as the cause of death instead + // of the run loop failure that actually killed the kernel. + it('does not reject when exiting throws', async () => { + const onUnhandled = vi.fn(); + process.once('unhandledRejection', onUnhandled); + + const { handle } = makeHandler({ + shutdown: vi.fn().mockRejectedValue(new Error('close failed')), + exit: vi.fn().mockImplementation(() => { + throw new Error('exit refused'); + }), + }); + + handle(new Error('crank exploded')); + await vi.runAllTimersAsync(); + await Promise.resolve(); + + expect(onUnhandled).not.toHaveBeenCalled(); + process.off('unhandledRejection', onUnhandled); + }); +}); + +/** + * Make the cleanup's options over spies, defaulting to a kernel that stops + * cleanly, so each test overrides only what it is about. + * + * @param overrides - Options to replace. + * @returns The options, with their spies reachable. + */ +const makeCleanupOptions = ( + overrides: Partial = {}, +): FailedStartupCleanupOptions & { + logger: { error: ReturnType; info: ReturnType }; +} => ({ + logger: { error: vi.fn(), info: vi.fn() }, + stopKernel: vi.fn().mockResolvedValue(undefined), + closeDatabase: vi.fn(), + removePidFile: vi.fn(), + ...overrides, +}); + +describe('cleanUpFailedStartup', () => { + beforeEach(() => { + vi.useFakeTimers(); + }); + + afterEach(() => { + vi.useRealTimers(); + }); + + // `stop` terminates the vat workers only after writing the last-active + // timestamp, so a database closed first makes that write throw and the worker + // threads that hold the event loop open survive. + it('waits for the kernel to stop before closing the database', async () => { + const order: string[] = []; + const options = makeCleanupOptions({ + stopKernel: async () => { + await Promise.resolve(); + order.push('stop'); + }, + closeDatabase: () => order.push('close'), + removePidFile: () => order.push('removePid'), + }); + + await cleanUpFailedStartup(options); + + expect(order).toStrictEqual(['stop', 'close', 'removePid']); + }); + + it('gives up on a kernel that never stops', async () => { + const options = makeCleanupOptions({ + stopKernel: vi.fn().mockReturnValue(new Promise(() => undefined)), + }); + + const cleanup = cleanUpFailedStartup(options); + await vi.advanceTimersByTimeAsync(SHUTDOWN_TIMEOUT_MS); + await cleanup; + + expect(options.logger.error).toHaveBeenCalledWith( + `Kernel did not stop within ${SHUTDOWN_TIMEOUT_MS} ms during startup cleanup.`, + ); + expect(options.closeDatabase).toHaveBeenCalled(); + expect(options.removePidFile).toHaveBeenCalled(); + }); + + it('waits the full timeout before giving up on the kernel', async () => { + const options = makeCleanupOptions({ + stopKernel: vi.fn().mockReturnValue(new Promise(() => undefined)), + timeoutMs: 5_000, + }); + + const cleanup = cleanUpFailedStartup(options); + await vi.advanceTimersByTimeAsync(4_999); + expect(options.closeDatabase).not.toHaveBeenCalled(); + + await vi.advanceTimersByTimeAsync(1); + await cleanup; + + expect(options.closeDatabase).toHaveBeenCalled(); + }); + + it('closes the database when the kernel could not be stopped', async () => { + const options = makeCleanupOptions({ + stopKernel: vi.fn().mockRejectedValue(new Error('crank never ended')), + }); + + await cleanUpFailedStartup(options); + + expect(options.logger.error).toHaveBeenCalledWith( + 'Could not stop the kernel during startup cleanup.', + expect.stringContaining('crank never ended'), + ); + expect(options.closeDatabase).toHaveBeenCalled(); + expect(options.removePidFile).toHaveBeenCalled(); + }); + + // A `stop` that ran to completion closed the database itself, so the second + // close throwing is the expected case and must not strand the pid file. + it('removes the pid file when closing the database throws', async () => { + const options = makeCleanupOptions({ + closeDatabase: () => { + throw new Error('database is not open'); + }, + }); + + await cleanUpFailedStartup(options); + + expect(options.removePidFile).toHaveBeenCalled(); + }); + + it('logs a pid file that could not be removed', async () => { + const options = makeCleanupOptions({ + removePidFile: () => { + throw new Error('EPERM'); + }, + }); + + // Rejecting here would take the startup error with it, replacing the reason + // the daemon could not start with the reason its cleanup could not finish. + await cleanUpFailedStartup(options); + + expect(options.logger.error).toHaveBeenCalledWith( + 'Could not remove the pid file during startup cleanup.', + expect.stringContaining('EPERM'), + ); + }); + + // Only `cause` carries the reason the kernel would not stop. + it('logs the cause chain of a stop that failed', async () => { + const options = makeCleanupOptions({ + stopKernel: vi + .fn() + .mockRejectedValue( + new Error('could not stop', { cause: new Error('database is gone') }), + ), + }); + + await cleanUpFailedStartup(options); + + expect(options.logger.error).toHaveBeenCalledWith( + 'Could not stop the kernel during startup cleanup.', + expect.stringContaining('database is gone'), + ); + }); + + // The daemon logs with `appendFileSync`, so a full disk throws, and cleanup is + // the last thing standing between a failed startup and an orphan. + it('cleans up even when the log transport throws', async () => { + const options = makeCleanupOptions({ + logger: { + error: vi.fn().mockImplementation(() => { + throw new Error('ENOSPC'); + }), + info: vi.fn(), + }, + stopKernel: vi.fn().mockRejectedValue(new Error('crank never ended')), + }); + + await cleanUpFailedStartup(options); + + expect(options.closeDatabase).toHaveBeenCalled(); + expect(options.removePidFile).toHaveBeenCalled(); + }); +}); + +/** + * Make the daemon wiring over spies. + * + * @param overrides - Options to replace. + * @returns The wiring and the spies it was built from. + */ +const makeWiring = ( + overrides: Partial = {}, +): { + wiring: DaemonRunLoopWiring; + shutdown: ReturnType; + setExitCode: ReturnType; +} => { + const shutdown = vi.fn().mockResolvedValue(undefined); + const setExitCode = vi.fn(); + const wiring = makeDaemonRunLoopWiring({ + logger: { error: vi.fn(), info: vi.fn() }, + shutdown, + isShuttingDown: () => false, + removePidFile: vi.fn(), + setExitCode, + exit: vi.fn(), + ...overrides, + }); + return { wiring, shutdown, setExitCode }; +}; + +describe('makeDaemonRunLoopWiring', () => { + beforeEach(() => { + vi.useFakeTimers(); + }); + + afterEach(() => { + vi.useRealTimers(); + }); + + it('shuts the daemon down when the run loop dies after startup', async () => { + const { wiring, shutdown } = makeWiring(); + wiring.daemonStarted(); + + wiring.onRunLoopFailure(new Error('crank exploded')); + await vi.runAllTimersAsync(); + + expect(shutdown).toHaveBeenCalledWith('run loop failure'); + }); + + // The kernel can report a death before `startDaemon` has returned. + it('holds a failure that arrives before the daemon has started', () => { + const { wiring, shutdown, setExitCode } = makeWiring(); + + wiring.onRunLoopFailure(new Error('died during startup')); + + expect(shutdown).not.toHaveBeenCalled(); + expect(setExitCode).not.toHaveBeenCalled(); + }); + + it('unwinds startup when the run loop died on the way up', () => { + const { wiring } = makeWiring(); + const failure = new Error('died during startup'); + + wiring.onRunLoopFailure(failure); + + // Only `cause` carries the reason it died. + expect(() => wiring.assertSurvivedStartup()).toThrow( + expect.objectContaining({ + message: 'Kernel run loop died during startup', + cause: failure, + }), + ); + }); + + it('lets startup proceed while the run loop is alive', () => { + const { wiring } = makeWiring(); + + expect(() => wiring.assertSurvivedStartup()).not.toThrow(); + }); + + // A loop that died between startup's check and the daemon coming up would + // otherwise leave it serving RPCs for a dead kernel forever. + it('replays a held failure once there is a daemon to close', async () => { + const { wiring, shutdown, setExitCode } = makeWiring(); + wiring.onRunLoopFailure(new Error('died during startup')); + + wiring.daemonStarted(); + await vi.runAllTimersAsync(); + + expect(shutdown).toHaveBeenCalledWith('run loop failure'); + expect(setExitCode).toHaveBeenCalledWith(1); + }); + + it('does not shut down a daemon whose run loop is alive', async () => { + const { wiring, shutdown } = makeWiring(); + + wiring.daemonStarted(); + await vi.runAllTimersAsync(); + + expect(shutdown).not.toHaveBeenCalled(); + }); + + // Whatever the loop reports afterwards is fallout from the first failure. + it('replays the first failure when several arrive before the daemon starts', async () => { + const logger = { error: vi.fn(), info: vi.fn() }; + const { wiring } = makeWiring({ logger }); + wiring.onRunLoopFailure(new Error('first')); + wiring.onRunLoopFailure(new Error('second')); + + wiring.daemonStarted(); + await vi.runAllTimersAsync(); + + expect(logger.error).toHaveBeenCalledWith( + 'Kernel run loop died; shutting down the daemon.', + expect.stringContaining('first'), + ); + expect(logger.error).not.toHaveBeenCalledWith( + 'Kernel run loop died; shutting down the daemon.', + expect.stringContaining('second'), + ); + }); +}); diff --git a/packages/kernel-cli/src/commands/run-loop-failure.ts b/packages/kernel-cli/src/commands/run-loop-failure.ts new file mode 100644 index 0000000000..bbd352bc87 --- /dev/null +++ b/packages/kernel-cli/src/commands/run-loop-failure.ts @@ -0,0 +1,348 @@ +import { stringify } from '@metamask/kernel-utils'; +import type { Logger } from '@metamask/logger'; + +/** How long a post-failure shutdown may take before the process is killed. */ +export const SHUTDOWN_TIMEOUT_MS = 10_000; + +/** The subset of `Logger` this handler needs. */ +type FailureLogger = Pick; + +/** + * Log without letting the transport's own failure escape. + * + * The daemon's transport is `appendFileSync`, so a full disk throws. Every + * caller is on a path where that throw would cost more than the lost line: the + * kernel swallows what the failure handler throws, so a daemon serving a dead + * kernel would stay up, and in the fatal handlers the log sits in front of the + * `process.exit` that is the only thing terminating live vat workers. + * + * @param logger - Where to record the message. + * @param level - The severity to record it at. + * @param message - The message. + * @param data - Additional detail, already stringified. + */ +export function logBestEffort( + logger: FailureLogger, + level: 'error' | 'info', + message: string, + ...data: string[] +): void { + try { + logger[level](message, ...data); + } catch { + // No transport left to report the transport with. + } +} + +export type RunLoopFailureHandlerOptions = { + logger: FailureLogger; + /** Shut the daemon down. Idempotent; concurrent calls coalesce. */ + shutdown: (reason: string) => Promise; + /** Whether there is a daemon to shut down yet. */ + isStarted: () => boolean; + /** Whether a shutdown is already under way. */ + isShuttingDown: () => boolean; + /** Record the failure so startup can consult it. */ + recordFailure: (failure: Error) => void; + /** Remove the pid file. Must complete before the process exits. */ + removePidFile: () => void; + setExitCode: (code: number) => void; + exit: (code: number) => void; + timeoutMs?: number; +}; + +/** + * Build the daemon's run loop failure handler. + * + * Left alone, a dead run loop leaves the daemon answering RPCs for a kernel that + * processes nothing — an outage only a client that reads `runLoop` in + * `getStatus` can spot. Terminate instead, non-zero, so the failure is visible + * and `ocap daemon start` can recover. + * + * Extracted from `daemon-entry` because that module shuts the process down as a + * side effect of being imported, which leaves this logic untestable in place. + * + * @param options - Options bag. + * @param options.logger - Where to record the failure. + * @param options.shutdown - Shut the daemon down. Idempotent; calls coalesce. + * @param options.isStarted - Whether there is a daemon to shut down yet. + * @param options.isShuttingDown - Whether a shutdown is already under way. + * @param options.recordFailure - Record the failure so startup can consult it. + * @param options.removePidFile - Remove the pid file, synchronously. + * @param options.setExitCode - Set the code the process will exit with. + * @param options.exit - Terminate the process now. + * @param options.timeoutMs - How long the shutdown may take before the process + * is killed. Defaults to {@link SHUTDOWN_TIMEOUT_MS}. + * @returns A handler suitable for `makeKernel`'s `onRunLoopFailure`. + */ +export function makeRunLoopFailureHandler({ + logger, + shutdown, + isStarted, + isShuttingDown, + recordFailure, + removePidFile, + setExitCode, + exit, + timeoutMs = SHUTDOWN_TIMEOUT_MS, +}: RunLoopFailureHandlerOptions): (failure: Error) => void { + return (failure: Error): void => { + recordFailure(failure); + + if (!isStarted()) { + // No daemon to close yet. Startup either unwinds at its own check or + // replays this failure once there is something to shut down. + logBestEffort( + logger, + 'error', + 'Kernel run loop died before the daemon started.', + stringify(failure, 0), + ); + return; + } + + if (isShuttingDown()) { + // Expected teardown, not an outage: don't fail a deliberate stop. + logBestEffort( + logger, + 'info', + 'Kernel run loop stopped during shutdown.', + stringify(failure, 0), + ); + return; + } + + setExitCode(1); + + // `stringify` rather than `failure.stack`, which omits the cause chain. When + // a crank dies and its rollback then fails, the rollback failure is the + // outermost message and the error that actually killed the kernel is only + // reachable through `cause`. + logBestEffort( + logger, + 'error', + 'Kernel run loop died; shutting down the daemon.', + stringify(failure, 0), + ); + + // A shutdown that throws would leave the socket gone and the pid file + // removed by `shutdown`'s own cleanup, while live vat workers keep the event + // loop alive — an orphan holding kernel.sqlite that neither interlock can + // see, so the next `ocap daemon start` succeeds and two kernels contend for + // the database. A shutdown that *hangs* never reaches that cleanup, so the + // pid file survives and the pid interlock does still see the orphan — but it + // is an orphan either way. Terminate in both cases. `setExitCode` is not + // enough precisely because those worker handles keep the process running. + const exitNow = (): void => { + try { + removePidFile(); + } catch (rmError) { + logBestEffort( + logger, + 'error', + 'Could not remove the pid file before exiting.', + stringify(rmError, 0), + ); + } + exit(1); + }; + + const killTimer = setTimeout(() => { + logBestEffort( + logger, + 'error', + `Shutdown stalled for ${timeoutMs} ms after run loop failure; exiting now.`, + ); + exitNow(); + }, timeoutMs); + + shutdown('run loop failure') + .then( + () => clearTimeout(killTimer), + (shutdownError: unknown) => { + clearTimeout(killTimer); + logBestEffort( + logger, + 'error', + 'Shutdown after run loop failure failed; exiting now.', + stringify(shutdownError, 0), + ); + exitNow(); + }, + ) + // Reached only if a handler above throws, and an unhandled rejection here + // would be reported as the cause of death instead of the run loop. + .catch(() => undefined); + }; +} + +export type FailedStartupCleanupOptions = { + logger: FailureLogger; + /** Stop the kernel, terminating the vat workers it launched. */ + stopKernel: () => Promise; + /** Close the kernel database. */ + closeDatabase: () => void; + /** Remove the pid file. Must complete before the process exits. */ + removePidFile: () => void; + /** How long the kernel may take to stop. Defaults to {@link SHUTDOWN_TIMEOUT_MS}. */ + timeoutMs?: number; +}; + +/** + * Tear down a kernel that startup could not finish bringing up. + * + * `Kernel.make` launches a worker thread per persisted vat before the run loop + * starts, so by the time startup can fail there are usually live workers, and a + * worker thread keeps the parent's event loop running. Nothing here can be + * fired and forgotten: `stop` is what terminates those workers, and it only + * reaches them after writing the last-active timestamp, so closing the database + * first makes that write throw and the workers survive. The caller is expected + * to terminate the process afterwards. + * + * @param options - Options bag. + * @param options.logger - Where to record what could not be cleaned up. + * @param options.stopKernel - Stop the kernel, terminating its vat workers. + * @param options.closeDatabase - Close the kernel database. + * @param options.removePidFile - Remove the pid file, synchronously. + * @param options.timeoutMs - How long the kernel may take to stop. + */ +export async function cleanUpFailedStartup({ + logger, + stopKernel, + closeDatabase, + removePidFile, + timeoutMs = SHUTDOWN_TIMEOUT_MS, +}: FailedStartupCleanupOptions): Promise { + // Bounded: `stop` waits for the current crank first, and a run loop that died + // mid-crank may never end it. + let giveUpTimer: ReturnType | undefined; + try { + await Promise.race([ + stopKernel(), + new Promise((resolve) => { + giveUpTimer = setTimeout(() => { + logBestEffort( + logger, + 'error', + `Kernel did not stop within ${timeoutMs} ms during startup cleanup.`, + ); + resolve(); + }, timeoutMs); + }), + ]); + } catch (stopError) { + logBestEffort( + logger, + 'error', + 'Could not stop the kernel during startup cleanup.', + stringify(stopError, 0), + ); + } finally { + clearTimeout(giveUpTimer); + } + + try { + closeDatabase(); + } catch { + // A `stop` that ran to completion closed the database itself, which is the + // expected case rather than a fault. Nothing to salvage either way: the + // process exits next, which releases the file lock regardless. + } + + try { + removePidFile(); + } catch (rmError) { + logBestEffort( + logger, + 'error', + 'Could not remove the pid file during startup cleanup.', + stringify(rmError, 0), + ); + } +} + +export type DaemonRunLoopWiringOptions = { + logger: FailureLogger; + /** Shut the daemon down. Idempotent; concurrent calls coalesce. */ + shutdown: (reason: string) => Promise; + isShuttingDown: () => boolean; + /** Remove the pid file. Must complete before the process exits. */ + removePidFile: () => void; + setExitCode: (code: number) => void; + exit: (code: number) => void; + timeoutMs?: number; +}; + +export type DaemonRunLoopWiring = { + /** Pass to `makeKernel` as `onRunLoopFailure`. */ + onRunLoopFailure: (failure: Error) => void; + /** @throws If the run loop has already died, to unwind startup. */ + assertSurvivedStartup: () => void; + /** Replays a failure that arrived before there was a daemon to shut down. */ + daemonStarted: () => void; +}; + +/** + * Wire the run loop failure handler to the daemon's lifecycle. + * + * A failure can land before there is a daemon to shut down, so it is held for + * startup's own check and replayed once there is one. Extracted from + * `daemon-entry` because that module shuts the process down as a side effect of + * being imported, which leaves this untestable in place. + * + * @param options - Options bag, forwarded to {@link makeRunLoopFailureHandler} + * apart from the lifecycle state this owns. + * @param options.logger - Where to record the failure. + * @param options.shutdown - Shut the daemon down. Idempotent; calls coalesce. + * @param options.isShuttingDown - Whether a shutdown is already under way. + * @param options.removePidFile - Remove the pid file, synchronously. + * @param options.setExitCode - Set the code the process will exit with. + * @param options.exit - Terminate the process now. + * @param options.timeoutMs - How long the shutdown may take before the process + * is killed. + * @returns The wiring `daemon-entry` hangs off the kernel and its own startup. + */ +export function makeDaemonRunLoopWiring({ + logger, + shutdown, + isShuttingDown, + removePidFile, + setExitCode, + exit, + timeoutMs = SHUTDOWN_TIMEOUT_MS, +}: DaemonRunLoopWiringOptions): DaemonRunLoopWiring { + let failure: Error | undefined; + let started = false; + + const onRunLoopFailure = makeRunLoopFailureHandler({ + logger, + shutdown, + isStarted: () => started, + isShuttingDown, + // Whatever the loop reports next is fallout, including the replay below. + recordFailure: (first) => { + failure ??= first; + }, + removePidFile, + setExitCode, + exit, + timeoutMs, + }); + + return harden({ + onRunLoopFailure, + assertSurvivedStartup: () => { + if (failure) { + throw new Error('Kernel run loop died during startup', { + cause: failure, + }); + } + }, + daemonStarted: () => { + started = true; + if (failure) { + onRunLoopFailure(failure); + } + }, + }); +} diff --git a/packages/kernel-cli/test/e2e/daemon.test.ts b/packages/kernel-cli/test/e2e/daemon.test.ts index aae6aa7aca..1531eff7fe 100644 --- a/packages/kernel-cli/test/e2e/daemon.test.ts +++ b/packages/kernel-cli/test/e2e/daemon.test.ts @@ -34,6 +34,11 @@ describe('Daemon CLI e2e', { timeout: 60_000 }, () => { const result = response.result as Record; expect(result).toHaveProperty('vats'); expect(result).toHaveProperty('subclusters'); + // `runLoop` is required by `KernelStatusStruct`, and `sendCommand` doesn't + // validate results — so without this assertion a kernel that stopped + // emitting it would break every `RpcClient` consumer (the UI panel) while + // this test stayed green. A live daemon reports the loop running. + expect(result).toHaveProperty('runLoop', { state: 'running' }); }); it('returns error for unknown method', async () => { diff --git a/packages/kernel-node-runtime/CHANGELOG.md b/packages/kernel-node-runtime/CHANGELOG.md index 67ae0c9adc..934b2c4f7d 100644 --- a/packages/kernel-node-runtime/CHANGELOG.md +++ b/packages/kernel-node-runtime/CHANGELOG.md @@ -7,6 +7,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +### Added + +- Add `onRunLoopFailure` to `makeKernel`, forwarded to `Kernel.make` and called with the error that killed the kernel's run loop ([#1005](https://github.com/MetaMask/ocap-kernel/pull/1005)) + ### Changed - **BREAKING:** Drop `platformOptions.fetch` from `makeNodeJsVatSupervisor` ([#942](https://github.com/MetaMask/ocap-kernel/pull/942)) diff --git a/packages/kernel-node-runtime/src/kernel/make-kernel-options.test.ts b/packages/kernel-node-runtime/src/kernel/make-kernel-options.test.ts new file mode 100644 index 0000000000..0c031b1c23 --- /dev/null +++ b/packages/kernel-node-runtime/src/kernel/make-kernel-options.test.ts @@ -0,0 +1,41 @@ +import { Kernel } from '@metamask/ocap-kernel'; +import { describe, expect, it, vi } from 'vitest'; + +import { makeKernel } from './make-kernel.ts'; + +vi.mock('@metamask/kernel-store/sqlite/nodejs', async () => { + const { makeMapKernelDatabase } = await import( + '../../../ocap-kernel/test/storage.ts' + ); + return { + makeSQLKernelDatabase: makeMapKernelDatabase, + }; +}); + +// `harden(Kernel)` freezes the class, so `vi.spyOn(Kernel, 'make')` throws +// "Cannot redefine property". Replacing the module binding sidesteps that. +vi.mock('@metamask/ocap-kernel', async (importOriginal) => ({ + ...(await importOriginal()), + Kernel: { make: vi.fn().mockResolvedValue({}) }, +})); + +const makeMock = vi.mocked(Kernel.make); + +describe('makeKernel options', () => { + it('forwards onRunLoopFailure to the kernel', async () => { + const onRunLoopFailure = vi.fn(); + + await makeKernel({ onRunLoopFailure }); + + expect(makeMock.mock.calls[0]?.[2]).toMatchObject({ onRunLoopFailure }); + }); + + // The conditional spread that forwards the option is the shape that silently + // drops it, which would reinstate the outage the option exists to report. + it('omits onRunLoopFailure when none is given', async () => { + await makeKernel({}); + + expect(makeMock).toHaveBeenCalledOnce(); + expect(makeMock.mock.calls[0]?.[2]).not.toHaveProperty('onRunLoopFailure'); + }); +}); diff --git a/packages/kernel-node-runtime/src/kernel/make-kernel.ts b/packages/kernel-node-runtime/src/kernel/make-kernel.ts index 81e4a37e43..4cbda735b3 100644 --- a/packages/kernel-node-runtime/src/kernel/make-kernel.ts +++ b/packages/kernel-node-runtime/src/kernel/make-kernel.ts @@ -4,6 +4,7 @@ import { Logger } from '@metamask/logger'; import { Kernel } from '@metamask/ocap-kernel'; import type { IOChannelFactory, + OnRunLoopFailure, SystemSubclusterConfig, } from '@metamask/ocap-kernel'; @@ -29,6 +30,8 @@ export type MakeKernelResult = { * @param options.keySeed - Optional seed for libp2p key generation. * @param options.ioChannelFactory - Optional factory for creating IO channels. * @param options.systemSubclusters - Optional system subcluster configurations. + * @param options.onRunLoopFailure - Optional handler called if the kernel's run + * loop dies, after which the kernel must be restarted. * @returns The kernel and its database. */ export async function makeKernel({ @@ -39,6 +42,7 @@ export async function makeKernel({ keySeed, ioChannelFactory, systemSubclusters, + onRunLoopFailure, }: { workerFilePath?: string; resetStorage?: boolean; @@ -47,6 +51,7 @@ export async function makeKernel({ keySeed?: string | undefined; ioChannelFactory?: IOChannelFactory; systemSubclusters?: SystemSubclusterConfig[]; + onRunLoopFailure?: OnRunLoopFailure; }): Promise { const rootLogger = logger ?? new Logger('kernel-worker'); const platformServicesClient = new NodejsPlatformServices({ @@ -64,6 +69,7 @@ export async function makeKernel({ keySeed, ioChannelFactory: ioChannelFactory ?? makeIOChannelFactory(), ...(systemSubclusters ? { systemSubclusters } : {}), + ...(onRunLoopFailure ? { onRunLoopFailure } : {}), }); return { kernel, kernelDatabase }; diff --git a/packages/kernel-node-runtime/test/e2e/daemon-stack.test.ts b/packages/kernel-node-runtime/test/e2e/daemon-stack.test.ts index fb30696199..237d260c81 100644 --- a/packages/kernel-node-runtime/test/e2e/daemon-stack.test.ts +++ b/packages/kernel-node-runtime/test/e2e/daemon-stack.test.ts @@ -125,6 +125,10 @@ describe('Daemon Stack (JSON-RPC socket protocol)', { timeout: 30_000 }, () => { const result = response.result as Record; expect(result).toHaveProperty('vats'); expect(result).toHaveProperty('subclusters'); + // `runLoop` is required by `KernelStatusStruct`, and this transport doesn't + // validate results — so without this assertion a kernel that stopped emitting + // it would break every `RpcClient` consumer while this test stayed green. + expect(result).toHaveProperty('runLoop', { state: 'running' }); }); it('returns error for unknown method', async () => { diff --git a/packages/kernel-rpc-methods/CHANGELOG.md b/packages/kernel-rpc-methods/CHANGELOG.md index 3e6b845604..2c606b0344 100644 --- a/packages/kernel-rpc-methods/CHANGELOG.md +++ b/packages/kernel-rpc-methods/CHANGELOG.md @@ -7,6 +7,11 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +### Changed + +- `RpcClient` result-validation errors now include the individual struct failures, not just the top-level message ([#1005](https://github.com/MetaMask/ocap-kernel/pull/1005)) + - A union's own message names only the union, so a reply from a peer built against an older schema was indistinguishable from an ordinary bad value; the failures name the branch and the key + ## [0.6.0] ### Changed diff --git a/packages/kernel-rpc-methods/src/RpcClient.test.ts b/packages/kernel-rpc-methods/src/RpcClient.test.ts index c60cd8085e..2fa63f85d3 100644 --- a/packages/kernel-rpc-methods/src/RpcClient.test.ts +++ b/packages/kernel-rpc-methods/src/RpcClient.test.ts @@ -1,4 +1,5 @@ import type { Logger } from '@metamask/logger'; +import { literal, string, tuple, type, union } from '@metamask/superstruct'; import { jsonrpc2 } from '@metamask/utils'; import { describe, it, vi, expect } from 'vitest'; @@ -61,6 +62,30 @@ describe('RpcClient', () => { ); }); + // A union's own message names only the union, so without the branch failures + // a peer built against an older schema reads as an ordinary bad value. + it('names the mismatched key when a union result fails validation', async () => { + const methods = { + method1: { + method: 'method1', + params: tuple([string()]), + result: union([ + type({ state: literal('running') }), + type({ state: literal('failed'), error: string() }), + ]), + }, + } as unknown as ReturnType; + const client = new RpcClient(methods, vi.fn(), 'test'); + const resultP = client.call('method1', ['test']); + client.handleResponse('test1', { + jsonrpc: jsonrpc2, + id: 'test1', + result: { state: 'failed' }, + }); + + await expect(resultP).rejects.toThrow('error: Expected a string'); + }); + it('should throw an error for invalid responses', async () => { const client = new RpcClient(getMethods(), vi.fn(), 'test'); const resultP = client.call('method1', ['test']); diff --git a/packages/kernel-rpc-methods/src/RpcClient.ts b/packages/kernel-rpc-methods/src/RpcClient.ts index 186b1791e5..6d2f3cb292 100644 --- a/packages/kernel-rpc-methods/src/RpcClient.ts +++ b/packages/kernel-rpc-methods/src/RpcClient.ts @@ -3,6 +3,7 @@ import { makeCounter, stringify } from '@metamask/kernel-utils'; import type { PromiseCallbacks } from '@metamask/kernel-utils'; import { Logger } from '@metamask/logger'; import { assert as assertStruct } from '@metamask/superstruct'; +import type { StructError } from '@metamask/superstruct'; import { isJsonRpcFailure, isJsonRpcSuccess } from '@metamask/utils'; import type { JsonRpcNotification, @@ -152,7 +153,22 @@ export class RpcClient< // `Method` must be a key of `this.#methods`. assertStruct(result, this.#methods[method].result); } catch (error) { - throw new Error(`Invalid result: ${(error as Error).message}`); + // A union's own message names only the union, so which branch mismatched + // and at which key is reachable only through `failures()` — the detail that + // distinguishes a bad value from a peer built against an older schema. + const { message, failures } = error as StructError; + const detail = + typeof failures === 'function' + ? failures() + .map(({ path, message: why }) => + path.length > 0 ? `${path.join('.')}: ${why}` : why, + ) + .filter((why) => why !== message) + .join('; ') + : ''; + throw new Error( + `Invalid result: ${message}${detail ? ` (${detail})` : ''}`, + ); } } diff --git a/packages/kernel-store/CHANGELOG.md b/packages/kernel-store/CHANGELOG.md index 40c550d2c6..5cfe39eb5e 100644 --- a/packages/kernel-store/CHANGELOG.md +++ b/packages/kernel-store/CHANGELOG.md @@ -7,6 +7,12 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +### Fixed + +- `rollbackSavepoint` discards the enclosing transaction when `ROLLBACK TO` itself fails, instead of leaving the savepoint on its stack and the transaction open ([#1005](https://github.com/MetaMask/ocap-kernel/pull/1005)) + - Nothing would ever commit or abort that transaction, so every later write on the connection silently joined it, reported success, and vanished on close. Discarding it is no wider than the caller asked for: the transaction begins with the outermost savepoint, so it holds only the work the rollback was abandoning + - The rollback failure is still what gets thrown, even if aborting the transaction fails too + ## [0.6.0] ### Changed diff --git a/packages/kernel-store/src/sqlite/nodejs.test.ts b/packages/kernel-store/src/sqlite/nodejs.test.ts index 36b342401a..a62392fe19 100644 --- a/packages/kernel-store/src/sqlite/nodejs.test.ts +++ b/packages/kernel-store/src/sqlite/nodejs.test.ts @@ -292,6 +292,48 @@ describe('makeSQLKernelDatabase', () => { expect(mockDb._spStack).toStrictEqual([]); }); + // Otherwise every later write on this connection joins a transaction nothing + // will ever commit, reports success, and vanishes on close. + it('rollbackSavepoint discards the transaction when the rollback fails', async () => { + const db = await makeSQLKernelDatabase({}); + mockDb.inTransaction = true; + mockDb._spStack = ['point1']; + mockStatement.run.mockClear(); + mockDb.exec.mockImplementationOnce(() => { + throw new Error('disk I/O error'); + }); + + expect(() => db.rollbackSavepoint('point1')).toThrowError( + 'disk I/O error', + ); + + expect(mockDb._spStack).toStrictEqual([]); + // The abort is the only prepared statement this path runs. + expect(mockStatement.run).toHaveBeenCalledOnce(); + mockDb.inTransaction = false; + }); + + // The rollback failure is the diagnosis; a failed abort on top of it only + // repeats that the same connection is broken. + it('rollbackSavepoint reports the rollback failure even if the abort fails too', async () => { + const db = await makeSQLKernelDatabase({}); + mockDb.inTransaction = true; + mockDb._spStack = ['point1']; + mockDb.exec.mockImplementationOnce(() => { + throw new Error('disk I/O error'); + }); + mockStatement.run.mockImplementationOnce(() => { + throw new Error('cannot rollback'); + }); + + expect(() => db.rollbackSavepoint('point1')).toThrowError( + 'disk I/O error', + ); + + expect(mockDb._spStack).toStrictEqual([]); + mockDb.inTransaction = false; + }); + it('releaseSavepoint validates savepoint exists', async () => { const db = await makeSQLKernelDatabase({}); mockDb.inTransaction = true; diff --git a/packages/kernel-store/src/sqlite/nodejs.ts b/packages/kernel-store/src/sqlite/nodejs.ts index 0dc7c7d460..ec863edc7c 100644 --- a/packages/kernel-store/src/sqlite/nodejs.ts +++ b/packages/kernel-store/src/sqlite/nodejs.ts @@ -287,7 +287,22 @@ export async function makeSQLKernelDatabase({ throw new Error(`No such savepoint: ${name}`); } const query = SQL_QUERIES.ROLLBACK_SAVEPOINT.replace('%NAME%', name); - db.exec(query); + try { + db.exec(query); + } catch (error) { + // Left as it was, the savepoint stays on the stack and the transaction open + // with nothing to ever commit or abort it, so every later write on this + // connection joins it, reports success, and vanishes on close. Discarding + // the whole transaction is safe: it begins with the outermost savepoint, so + // it holds only what this rollback was abandoning anyway. + db._spStack.length = 0; + try { + rollbackIfNeeded(); + } catch { + // The rollback failure below is the one worth reporting. + } + throw error; + } db._spStack.splice(idx); if (db._spStack.length === 0) { rollbackIfNeeded(); diff --git a/packages/kernel-store/src/sqlite/wasm.test.ts b/packages/kernel-store/src/sqlite/wasm.test.ts index 5e17138021..2cbc96d658 100644 --- a/packages/kernel-store/src/sqlite/wasm.test.ts +++ b/packages/kernel-store/src/sqlite/wasm.test.ts @@ -452,6 +452,45 @@ describe('makeSQLKernelDatabase', () => { expect(mockDb._inTx).toBe(false); }); + // Otherwise every later write on this connection joins a transaction nothing + // will ever commit, reports success, and vanishes on close. + it('rollbackSavepoint discards the transaction when the rollback fails', async () => { + const db = await makeSQLKernelDatabase({}); + mockDb._inTx = true; + mockDb._spStack = ['point1']; + mockDb.exec.mockImplementationOnce(() => { + throw new Error('disk I/O error'); + }); + + expect(() => db.rollbackSavepoint('point1')).toThrowError( + 'disk I/O error', + ); + + expect(mockDb._spStack).toStrictEqual([]); + expect(mockDb._inTx).toBe(false); + }); + + // The rollback failure is the diagnosis; a failed abort on top of it only + // repeats that the same connection is broken. + it('rollbackSavepoint reports the rollback failure even if the abort fails too', async () => { + const db = await makeSQLKernelDatabase({}); + mockDb._inTx = true; + mockDb._spStack = ['point1']; + mockDb.exec.mockImplementationOnce(() => { + throw new Error('disk I/O error'); + }); + mockStatement.step.mockImplementationOnce(() => { + throw new Error('cannot rollback'); + }); + + expect(() => db.rollbackSavepoint('point1')).toThrowError( + 'disk I/O error', + ); + + expect(mockDb._spStack).toStrictEqual([]); + mockDb._inTx = false; + }); + it('releaseSavepoint validates savepoint exists', async () => { const db = await makeSQLKernelDatabase({}); mockDb._inTx = true; diff --git a/packages/kernel-store/src/sqlite/wasm.ts b/packages/kernel-store/src/sqlite/wasm.ts index 6278f98957..c0c32b8a72 100644 --- a/packages/kernel-store/src/sqlite/wasm.ts +++ b/packages/kernel-store/src/sqlite/wasm.ts @@ -369,7 +369,22 @@ export async function makeSQLKernelDatabase({ throw new Error(`No such savepoint: ${name}`); } const query = SQL_QUERIES.ROLLBACK_SAVEPOINT.replace('%NAME%', name); - db.exec(query); + try { + db.exec(query); + } catch (error) { + // Left as it was, the savepoint stays on the stack and the transaction open + // with nothing to ever commit or abort it, so every later write on this + // connection joins it, reports success, and vanishes on close. Discarding + // the whole transaction is safe: it begins with the outermost savepoint, so + // it holds only what this rollback was abandoning anyway. + db._spStack.length = 0; + try { + rollbackIfNeeded(); + } catch { + // The rollback failure below is the one worth reporting. + } + throw error; + } db._spStack.splice(idx); if (db._spStack.length === 0) { rollbackIfNeeded(); diff --git a/packages/kernel-test/src/crank-rollback.test.ts b/packages/kernel-test/src/crank-rollback.test.ts new file mode 100644 index 0000000000..cd2a708aa0 --- /dev/null +++ b/packages/kernel-test/src/crank-rollback.test.ts @@ -0,0 +1,154 @@ +import type { KernelDatabase } from '@metamask/kernel-store'; +import { makeSQLKernelDatabase } from '@metamask/kernel-store/sqlite/nodejs'; +import { makeKernelStore } from '@metamask/ocap-kernel'; +import type { RunQueueItem } from '@metamask/ocap-kernel'; +import { describe, it, expect } from 'vitest'; + +/** + * The run loop rolls back the crank it died in, so that a restart resumes from a + * consistent boundary rather than from a half-finished crank. `KernelQueue`'s own + * tests mock the store, so they prove only that `rollbackCrank` is *called* + * correctly. These exercise what it actually does against real SQLite: the + * savepoint, the run queue and its length cache, and the release that `endCrank` + * performs afterwards. + */ + +/** + * Make a kernel store over a fresh in-memory database. + * + * @returns The store and the database beneath it. + */ +const makeStore = async (): Promise<{ + kernelStore: ReturnType; + kdb: KernelDatabase; +}> => { + const kdb = await makeSQLKernelDatabase({ dbFilename: ':memory:' }); + return { kernelStore: makeKernelStore(kdb), kdb }; +}; + +const makeItem = (target: string): RunQueueItem => + ({ + type: 'send', + target, + message: { methargs: { body: '#[]', slots: [] } }, + }) as unknown as RunQueueItem; + +describe('crank rollback against a real database', () => { + // The claim the changelog makes: because the killing crank is rolled back, the + // item it dequeued is still there to be re-dequeued after a restart. With the + // store mocked this is unobservable. + it('returns the dequeued item to the run queue', async () => { + const { kernelStore } = await makeStore(); + kernelStore.enqueueRun(makeItem('ko1')); + + kernelStore.startCrank(); + kernelStore.createCrankSavepoint('start'); + const dequeued = kernelStore.dequeueRun(); + expect(dequeued).toBeDefined(); + expect(kernelStore.runQueueLength()).toBe(0); + + kernelStore.rollbackCrank('start'); + kernelStore.endCrank(); + + expect(kernelStore.runQueueLength()).toBe(1); + expect(kernelStore.dequeueRun()).toStrictEqual(dequeued); + }); + + // `rollbackCrank` invalidates the length cache precisely because the rollback + // restored rows the cache no longer knows about. Reading the length *before* + // the rollback primes that cache, which is what makes the invalidation matter. + it('recomputes the run queue length after a rollback', async () => { + const { kernelStore } = await makeStore(); + kernelStore.enqueueRun(makeItem('ko1')); + kernelStore.enqueueRun(makeItem('ko2')); + + kernelStore.startCrank(); + kernelStore.createCrankSavepoint('start'); + kernelStore.dequeueRun(); + kernelStore.dequeueRun(); + // Prime the cache at 0 so a stale read would be visible below. + expect(kernelStore.runQueueLength()).toBe(0); + + kernelStore.rollbackCrank('start'); + kernelStore.endCrank(); + + expect(kernelStore.runQueueLength()).toBe(2); + }); + + // `endCrank` releases savepoints unconditionally, and releasing the savepoint a + // rollback abandoned would commit the crank being discarded. It cannot, because + // `rollbackCrank` forgets the savepoint — but that reasoning is about SQLite's + // savepoint stack, so it is worth pinning against a real one. + it('does not commit the abandoned crank when endCrank releases afterwards', async () => { + const { kernelStore, kdb } = await makeStore(); + kdb.kernelKVStore.set('before', 'yes'); + + kernelStore.startCrank(); + kernelStore.createCrankSavepoint('start'); + kdb.kernelKVStore.set('during', 'yes'); + kdb.kernelKVStore.delete('before'); + + kernelStore.rollbackCrank('start'); + kernelStore.endCrank(); + + expect(kdb.kernelKVStore.get('during')).toBeUndefined(); + expect(kdb.kernelKVStore.get('before')).toBe('yes'); + }); + + // A rollback that left the transaction open would swallow every later write on + // the connection, including the ones `Kernel.stop()` makes on the way out. + it('leaves the database writable after a rolled-back crank', async () => { + const { kernelStore, kdb } = await makeStore(); + + kernelStore.startCrank(); + kernelStore.createCrankSavepoint('start'); + kdb.kernelKVStore.set('discarded', 'yes'); + kernelStore.rollbackCrank('start'); + kernelStore.endCrank(); + + kdb.kernelKVStore.set('after', 'yes'); + expect(kdb.kernelKVStore.get('after')).toBe('yes'); + + // Survives the commit boundary a subsequent crank draws, so the write really + // landed rather than sitting in a transaction that never resolves. + kernelStore.startCrank(); + kernelStore.createCrankSavepoint('start'); + kernelStore.endCrank(); + expect(kdb.kernelKVStore.get('after')).toBe('yes'); + expect(kdb.kernelKVStore.get('discarded')).toBeUndefined(); + }); + + // The abort path rolls back mid-crank and the run loop then keeps going, so the + // next crank has to be able to create its own savepoint and commit normally. + it('commits a later crank after an earlier one rolled back', async () => { + const { kernelStore, kdb } = await makeStore(); + + kernelStore.startCrank(); + kernelStore.createCrankSavepoint('start'); + kdb.kernelKVStore.set('first', 'yes'); + kernelStore.rollbackCrank('start'); + kernelStore.endCrank(); + + kernelStore.startCrank(); + kernelStore.createCrankSavepoint('start'); + kdb.kernelKVStore.set('second', 'yes'); + kernelStore.endCrank(); + + expect(kdb.kernelKVStore.get('first')).toBeUndefined(); + expect(kdb.kernelKVStore.get('second')).toBe('yes'); + }); + + // `createCrankSavepoint` records the name only once the database has the + // savepoint. Asking to roll back one that was never created must therefore say + // so, rather than releasing someone else's savepoint. + it('refuses to roll back a savepoint that was never created', async () => { + const { kernelStore } = await makeStore(); + + kernelStore.startCrank(); + + expect(() => kernelStore.rollbackCrank('start')).toThrow( + 'no such savepoint', + ); + kernelStore.endCrank(); + }); +}); diff --git a/packages/kernel-ui/CHANGELOG.md b/packages/kernel-ui/CHANGELOG.md index 30e1a149e6..69ae0f2266 100644 --- a/packages/kernel-ui/CHANGELOG.md +++ b/packages/kernel-ui/CHANGELOG.md @@ -7,6 +7,11 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +### Added + +- Show a banner when `getStatus` reports the kernel's run loop as failed; the vat and subcluster tables keep rendering their last known contents, so a dead kernel otherwise looks like a healthy idle one ([#1005](https://github.com/MetaMask/ocap-kernel/pull/1005)) + - The banner's details section shows `runLoop.detail`, the whole cause chain: when a crank dies and its rollback then fails, the headline names the rollback and only the chain names what killed the kernel + ## [0.5.0] ### Changed diff --git a/packages/kernel-ui/src/App.test.tsx b/packages/kernel-ui/src/App.test.tsx index 33c8bbf3b2..83a6e0c75b 100644 --- a/packages/kernel-ui/src/App.test.tsx +++ b/packages/kernel-ui/src/App.test.tsx @@ -14,6 +14,10 @@ vi.mock('./hooks/useDarkMode.ts', () => ({ useDarkMode: vi.fn(), })); +vi.mock('./hooks/useStatusPolling.ts', () => ({ + useStatusPolling: vi.fn(), +})); + describe('App', () => { beforeEach(() => { cleanup(); @@ -57,6 +61,33 @@ describe('App', () => { expect(screen.getByText('Control Panel')).toBeInTheDocument(); }); + // Without this, deleting the banner from App leaves every test green, and the + // panel is the only remediation signal the browser worker has — it cannot exit. + it('surfaces a failed run loop above the tabs', async () => { + const { useStream } = await import('./hooks/useStream.ts'); + vi.mocked(useStream).mockReturnValue({ + callKernelMethod: vi.fn(), + error: undefined, + } as unknown as StreamState); + const { useStatusPolling } = await import('./hooks/useStatusPolling.ts'); + vi.mocked(useStatusPolling).mockReturnValue({ + vats: [], + subclusters: [], + runLoop: { + state: 'failed', + error: 'crank exploded', + detail: '{"message":"crank exploded"}', + }, + }); + const { App } = await import('./App.tsx'); + render(); + + expect(screen.getByTestId('run-loop-failure')).toBeInTheDocument(); + expect(screen.getByTestId('run-loop-failure-error')).toHaveTextContent( + 'crank exploded', + ); + }); + it('renders all tab labels including the new Remote Comms tab', async () => { const { useStream } = await import('./hooks/useStream.ts'); vi.mocked(useStream).mockReturnValue({ diff --git a/packages/kernel-ui/src/App.tsx b/packages/kernel-ui/src/App.tsx index c0a7c1fcac..46bfe5dfbc 100644 --- a/packages/kernel-ui/src/App.tsx +++ b/packages/kernel-ui/src/App.tsx @@ -11,6 +11,7 @@ import { DatabaseInspector } from './components/DatabaseInspector.tsx'; import { MessagePanel } from './components/MessagePanel.tsx'; import { ObjectRegistry } from './components/ObjectRegistry.tsx'; import { RemoteComms } from './components/RemoteComms.tsx'; +import { RunLoopBanner } from './components/RunLoopBanner.tsx'; import { Tabs } from './components/shared/Tabs.tsx'; import { PanelProvider } from './context/PanelContext.tsx'; import { useDarkMode } from './hooks/useDarkMode.ts'; @@ -70,6 +71,7 @@ export const App: React.FC = () => { + {tabs.find((tab) => tab.value === activeTab)?.component} diff --git a/packages/kernel-ui/src/components/RunLoopBanner.test.tsx b/packages/kernel-ui/src/components/RunLoopBanner.test.tsx new file mode 100644 index 0000000000..0aee16c885 --- /dev/null +++ b/packages/kernel-ui/src/components/RunLoopBanner.test.tsx @@ -0,0 +1,107 @@ +import type { KernelStatus } from '@metamask/ocap-kernel'; +import { render, screen, cleanup } from '@testing-library/react'; +import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest'; + +import { RunLoopBanner } from './RunLoopBanner.tsx'; +import { usePanelContext } from '../context/PanelContext.tsx'; +import type { PanelContextType } from '../context/PanelContext.tsx'; + +vi.mock('../context/PanelContext.tsx', () => ({ + usePanelContext: vi.fn(), +})); + +const mockUsePanelContext = vi.mocked(usePanelContext); + +const makeMockPanelContext = ( + status: KernelStatus | undefined, +): PanelContextType => ({ + status, + callKernelMethod: vi.fn(), + logMessage: vi.fn(), + messageContent: '', + setMessageContent: vi.fn(), + panelLogs: [], + clearLogs: vi.fn(), + isLoading: false, + objectRegistry: null, + setObjectRegistry: vi.fn(), +}); + +const makeMockStatus = (runLoop: KernelStatus['runLoop']): KernelStatus => ({ + vats: [], + subclusters: [], + runLoop, +}); + +describe('RunLoopBanner', () => { + beforeEach(() => { + vi.clearAllMocks(); + }); + + afterEach(() => { + cleanup(); + }); + + it('announces a dead run loop with the reason it died', () => { + mockUsePanelContext.mockReturnValue( + makeMockPanelContext( + makeMockStatus({ + state: 'failed', + error: 'crank exploded', + detail: '{"message":"crank exploded"}', + }), + ), + ); + + render(); + + expect(screen.getByTestId('run-loop-failure')).toHaveTextContent( + 'Kernel run loop has died', + ); + expect(screen.getByTestId('run-loop-failure-error')).toHaveTextContent( + 'crank exploded', + ); + }); + + // When a crank dies and its rollback then fails, the headline names the + // rollback and only the chain names what killed the kernel. + it('shows the cause chain behind the headline', () => { + mockUsePanelContext.mockReturnValue( + makeMockPanelContext( + makeMockStatus({ + state: 'failed', + error: 'Run loop died and its crank could not be rolled back', + detail: + '{"message":"rollback failed","cause":{"message":"disk gone"}}', + }), + ), + ); + + render(); + + expect(screen.getByTestId('run-loop-failure-detail')).toHaveTextContent( + 'disk gone', + ); + }); + + it.each([ + { name: 'running', runLoop: { state: 'running' } as const }, + { name: 'idle', runLoop: { state: 'idle' } as const }, + ])('renders nothing when the run loop is $name', ({ runLoop }) => { + mockUsePanelContext.mockReturnValue( + makeMockPanelContext(makeMockStatus(runLoop)), + ); + + render(); + + expect(screen.queryByTestId('run-loop-failure')).toBeNull(); + }); + + it('renders nothing before the first status arrives', () => { + mockUsePanelContext.mockReturnValue(makeMockPanelContext(undefined)); + + render(); + + expect(screen.queryByTestId('run-loop-failure')).toBeNull(); + }); +}); diff --git a/packages/kernel-ui/src/components/RunLoopBanner.tsx b/packages/kernel-ui/src/components/RunLoopBanner.tsx new file mode 100644 index 0000000000..e7567e5915 --- /dev/null +++ b/packages/kernel-ui/src/components/RunLoopBanner.tsx @@ -0,0 +1,63 @@ +import { + Box, + Text as TextComponent, + TextColor, + TextVariant, + FontWeight, +} from '@metamask/design-system-react'; + +import { usePanelContext } from '../context/PanelContext.tsx'; + +// Announces that the kernel's run loop has died. Worth saying loudly because +// every other panel keeps rendering its last known contents, so a dead kernel +// looks identical to a healthy idle one. +export const RunLoopBanner: React.FC = () => { + const { status } = usePanelContext(); + const runLoop = status?.runLoop; + + if (runLoop?.state !== 'failed') { + return null; + } + + return ( + + + Kernel run loop has died. Nothing shown below is live and no message + will be processed until the kernel is restarted. + + + {runLoop.error} + + {/* When a crank dies and its rollback then fails, the headline above names + the rollback and only the chain below names what killed the kernel. */} +
+ + + Details + + + 
+          {runLoop.detail}
+
+
+ + ); +}; diff --git a/packages/ocap-kernel/CHANGELOG.md b/packages/ocap-kernel/CHANGELOG.md index ed8da249c2..87dcabb833 100644 --- a/packages/ocap-kernel/CHANGELOG.md +++ b/packages/ocap-kernel/CHANGELOG.md @@ -9,6 +9,11 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Added +- Report run loop health in `KernelStatus.runLoop` (`{ state: 'idle' | 'running' }` or `{ state: 'failed', error, detail }`), exporting `RunLoopStatus`, `RunLoopStatusStruct`, and `OnRunLoopFailure` ([#1005](https://github.com/MetaMask/ocap-kernel/pull/1005)) + - `idle` means never started; a loop parked on an empty queue reports `running` + - `error` is the failure's message and `detail` its whole cause chain, because only strings cross the wire: when a crank dies and its rollback then fails, the message names the rollback and only the chain names what killed the kernel + - **BREAKING:** `runLoop` is required, so `KernelStatus` gains a mandatory property and a `getStatus` reply from a kernel built before this field fails result validation outright. It cannot be made optional: `exactOptional` would leave the type and the validator disagreeing inside a `type()`, and `optional` widens the property to `| undefined`, which an RPC result may not be +- Add `onRunLoopFailure` to `Kernel.make` options, called with the error that killed the run loop so an embedder that outlives the kernel can exit or restart ([#1005](https://github.com/MetaMask/ocap-kernel/pull/1005)) - Add `fetch`, `Request`, `Headers`, and `Response` to available vat endowments ([#942](https://github.com/MetaMask/ocap-kernel/pull/942)) - Add `VatConfig.network: { allowedHosts: string[] }`; requesting `'fetch'` without it rejects `initVat` - Integrate Snaps attenuated endowment factories into vat globals ([#937](https://github.com/MetaMask/ocap-kernel/pull/937)) @@ -38,6 +43,19 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Fixed +- Stop reporting a healthy kernel after the run loop dies ([#1005](https://github.com/MetaMask/ocap-kernel/pull/1005)) + - The error was logged and swallowed, so `getStatus` kept returning its healthy-looking record while nothing on the run queue was processed and every `queueMessage` hung forever. Results in flight now reject with the killing error as their `cause`, later calls reject immediately, and `getStatus` answers without waiting on a crank that may never end +- Roll back the crank the run loop died in instead of committing it, so a restart resumes from a consistent boundary ([#1005](https://github.com/MetaMask/ocap-kernel/pull/1005)) + - Because the killing item is no longer consumed, a restart re-dequeues it; an item that reliably kills a crank needs `clearState`/`reset` rather than a restart + - Store state only — a crank that had already flushed its buffer settled JS-side subscriptions irreversibly +- Refuse inbound remote deliveries once the run loop is dead, rolling back without acknowledging them, so the peer retries and gives up instead of waiting on a kernel that will never deliver ([#1005](https://github.com/MetaMask/ocap-kernel/pull/1005)) + - Covers `bringOutYourDead` as well as `message` and `notify`: a reap is queue work too, consumed only by the run loop. The remaining GC arms need no guard, since they only touch refcounts +- Refuse `launchSubcluster` once the run loop is dead ([#1005](https://github.com/MetaMask/ocap-kernel/pull/1005)) + - The bootstrap message can't be queued either way, but the launch reached that point having already spawned a vat worker per entry in the config, none of which its cleanup path tears down +- Keep crank bookkeeping consistent when the database misbehaves: `endCrank` settles its `waitForCrank` waiters even if releasing savepoints throws (previously stranding `getStatus`, `stop`, `reset`, `clearStorage`, and the `VatManager`/`SubclusterManager` waiters), `rollbackCrank` forgets its savepoint even if the rollback throws (which otherwise had `endCrank` commit the crank being abandoned), and `createCrankSavepoint` records a name only once the database created it ([#1005](https://github.com/MetaMask/ocap-kernel/pull/1005)) +- Report the database error when an aborted crank cannot be rolled back, instead of a spurious "no such savepoint" ([#1005](https://github.com/MetaMask/ocap-kernel/pull/1005)) + - The abort path recorded the rollback only after it succeeded, so a throwing rollback had the run loop try again against the savepoint `rollbackCrank` had already discarded. The second attempt's "no such savepoint" then became the reported cause of death — and since only `error.message` crosses the wire, the real failure reached neither `getStatus` nor the daemon log +- Reject the run loop's promise with the same `Error` its status reports, rather than re-throwing a non-`Error` for the embedder to normalize a second time ([#1005](https://github.com/MetaMask/ocap-kernel/pull/1005)) - Deserialize CapData rejections in `Kernel.queueMessage` so vat errors surface as plain `Error` objects to all callers ([#928](https://github.com/MetaMask/ocap-kernel/pull/928)) - Detect peer restart across receiver state loss so the receiving kernel no longer silently drops a restarted peer's `seq=1` messages ([#948](https://github.com/MetaMask/ocap-kernel/pull/948)) - Persist the peer's last-observed incarnation and compare it on every successful handshake; on a detected restart, clear the peer's c-list contributions and reject the promises it was deciding before the new incarnation reuses any erefs diff --git a/packages/ocap-kernel/src/Kernel.test.ts b/packages/ocap-kernel/src/Kernel.test.ts index ca1dde78b8..670da38c04 100644 --- a/packages/ocap-kernel/src/Kernel.test.ts +++ b/packages/ocap-kernel/src/Kernel.test.ts @@ -1,6 +1,7 @@ import { VatNotFoundError } from '@metamask/kernel-errors'; import type { KernelDatabase } from '@metamask/kernel-store'; import type { JsonRpcMessage } from '@metamask/kernel-utils'; +import { waitUntilQuiescent } from '@metamask/kernel-utils'; import { Logger } from '@metamask/logger'; import type { DuplexStream } from '@metamask/streams'; import type { Mocked, MockInstance } from 'vitest'; @@ -11,6 +12,7 @@ import { kser } from './liveslots/kernel-marshal.ts'; import type { VatId, VatConfig, + OnRunLoopFailure, PlatformServices, ClusterConfig, } from './types.ts'; @@ -25,7 +27,47 @@ const mocks = vi.hoisted(() => { .fn() .mockResolvedValue({ body: '{"result":"ok"}', slots: [] }); - run = vi.fn().mockResolvedValue(undefined); + #runLoopFailure: Error | undefined; + + #rejectRunLoop: ((error: Error) => void) | undefined; + + // Like the real run loop, this settles only if the kernel dies. + run = vi.fn( + async () => + new Promise((_resolve, reject) => { + this.#rejectRunLoop = reject; + }), + ); + + /** + * Fail the run loop, in the order the real `KernelQueue.run` does: the + * status flips before the rejection is observable. Does not reproduce + * `#failRunLoop`'s rejection of in-flight subscriptions. + * + * @param error - The error that killed the run loop. + */ + killRunLoop(error: Error): void { + this.#runLoopFailure = error; + this.#rejectRunLoop?.(error); + } + + getRunLoopStatus = vi.fn(() => + this.#runLoopFailure + ? { + state: 'failed', + error: this.#runLoopFailure.message, + detail: `{"message":"${this.#runLoopFailure.message}"}`, + } + : { state: 'running' }, + ); + + assertRunLoopAlive = vi.fn((what: string) => { + if (this.#runLoopFailure) { + throw new Error(`Kernel run loop died; cannot ${what}`, { + cause: this.#runLoopFailure, + }); + } + }); stop = vi.fn(); @@ -505,10 +547,74 @@ describe('Kernel', () => { expect(status).toStrictEqual({ vats: [], subclusters: [], + runLoop: { state: 'running' }, remoteComms: { state: 'disconnected', }, }); + // A healthy status must not race an in-flight crank. + expect( + mocks.KernelQueue.lastInstance.waitForCrank, + ).toHaveBeenCalledOnce(); + }); + + it('reports a run loop that dies while waiting for the crank', async () => { + const kernel = await Kernel.make( + mockPlatformServices, + mockKernelDatabase, + ); + const queue = mocks.KernelQueue.lastInstance; + // An in-flight crank is exactly when the loop is most likely to die. + queue.waitForCrank.mockImplementationOnce(async () => { + queue.killRunLoop(new Error('died mid-crank')); + }); + + expect((await kernel.getStatus()).runLoop).toStrictEqual({ + state: 'failed', + error: 'died mid-crank', + detail: expect.stringContaining('died mid-crank'), + }); + }); + + it('reports the kernel as failed once the run loop dies', async () => { + const kernel = await Kernel.make( + mockPlatformServices, + mockKernelDatabase, + ); + await kernel.launchSubcluster(makeSingleVatClusterConfig()); + expect((await kernel.getStatus()).runLoop).toStrictEqual({ + state: 'running', + }); + + mocks.KernelQueue.lastInstance.killRunLoop(new Error('run loop boom')); + await waitUntilQuiescent(); + + const status = await kernel.getStatus(); + expect(status.runLoop).toStrictEqual({ + state: 'failed', + error: 'run loop boom', + detail: expect.stringContaining('run loop boom'), + }); + // The vats are still in the store, but nothing is delivering to them. + expect(status.vats).toHaveLength(1); + }); + + it('reports a failed run loop without waiting for the crank to finish', async () => { + const kernel = await Kernel.make( + mockPlatformServices, + mockKernelDatabase, + ); + const { waitForCrank } = mocks.KernelQueue.lastInstance; + // A crank that never finishes, as when the run loop died mid-crank. + waitForCrank.mockReturnValue(new Promise(() => undefined)); + mocks.KernelQueue.lastInstance.killRunLoop(new Error('run loop boom')); + await waitUntilQuiescent(); + + expect((await kernel.getStatus()).runLoop).toStrictEqual({ + state: 'failed', + error: 'run loop boom', + detail: expect.stringContaining('run loop boom'), + }); }); it('includes vats and subclusters in status', async () => { @@ -872,6 +978,117 @@ describe('Kernel', () => { }); }); + describe('run loop failure', () => { + it('logs and notifies the embedder when the run loop dies', async () => { + const logger = new Logger('test'); + const logErrorSpy = vi.spyOn(logger, 'error'); + const onRunLoopFailure = vi.fn(); + await Kernel.make(mockPlatformServices, mockKernelDatabase, { + logger, + onRunLoopFailure, + }); + const failure = new Error('run loop boom'); + + mocks.KernelQueue.lastInstance.killRunLoop(failure); + await waitUntilQuiescent(); + + expect(logErrorSpy).toHaveBeenCalledWith( + 'Run loop died; the kernel can no longer process messages and must be restarted:', + failure, + ); + expect(onRunLoopFailure).toHaveBeenCalledWith(failure); + }); + + it('does not hand the kernel to the failure handler as its receiver', async () => { + let gotAReceiver = true; + await Kernel.make(mockPlatformServices, mockKernelDatabase, { + onRunLoopFailure: function onRunLoopFailure(this: unknown): void { + gotAReceiver = this !== undefined; + }, + }); + + mocks.KernelQueue.lastInstance.killRunLoop(new Error('run loop boom')); + await waitUntilQuiescent(); + + expect(gotAReceiver).toBe(false); + }); + + // `run` rejects with the same object its status reports, so re-wrapping here + // would leave the embedder and `getStatus` describing two different errors. + it('hands the embedder the error the run loop died with, unwrapped', async () => { + const onRunLoopFailure = vi.fn(); + await Kernel.make(mockPlatformServices, mockKernelDatabase, { + onRunLoopFailure, + }); + const failure = new Error('run loop boom'); + + mocks.KernelQueue.lastInstance.killRunLoop(failure); + await waitUntilQuiescent(); + + expect(onRunLoopFailure).toHaveBeenCalledOnce(); + expect(onRunLoopFailure.mock.calls[0]?.[0]).toBe(failure); + }); + + // The handler slot returns void, but TypeScript admits anything thenable + // there, and an escaping rejection is what the containment exists to stop. + it.each([ + { + kind: 'an async handler', + makeHandler: (handlerError: Error) => async (): Promise => { + throw handlerError; + }, + }, + { + kind: 'a non-native thenable', + makeHandler: (handlerError: Error) => (): PromiseLike => ({ + then: (_onFulfilled, onRejected) => + onRejected?.(handlerError) as PromiseLike, + }), + }, + ])( + 'logs a failure handler that rejects, given $kind', + async ({ makeHandler }) => { + const logger = new Logger('test'); + const logErrorSpy = vi.spyOn(logger, 'error'); + const handlerError = new Error('handler boom'); + await Kernel.make(mockPlatformServices, mockKernelDatabase, { + logger, + onRunLoopFailure: makeHandler( + handlerError, + ) as unknown as OnRunLoopFailure, + }); + + mocks.KernelQueue.lastInstance.killRunLoop(new Error('run loop boom')); + await waitUntilQuiescent(); + + expect(logErrorSpy).toHaveBeenCalledWith( + 'Run loop failure handler rejected:', + handlerError, + ); + }, + ); + + it('logs a failure handler that throws', async () => { + const logger = new Logger('test'); + const logErrorSpy = vi.spyOn(logger, 'error'); + const handlerError = new Error('handler boom'); + await Kernel.make(mockPlatformServices, mockKernelDatabase, { + logger, + onRunLoopFailure: () => { + throw handlerError; + }, + }); + + mocks.KernelQueue.lastInstance.killRunLoop(new Error('run loop boom')); + await waitUntilQuiescent(); + + expect(logErrorSpy).toHaveBeenCalledWith( + 'Run loop failure handler threw:', + handlerError, + ); + }); + }); + describe('system subcluster cleanup', () => { it('deletes orphaned system subclusters without starting their vats', async () => { const db = makeMapKernelDatabase(); diff --git a/packages/ocap-kernel/src/Kernel.ts b/packages/ocap-kernel/src/Kernel.ts index 6cff649624..912c1f6929 100644 --- a/packages/ocap-kernel/src/Kernel.ts +++ b/packages/ocap-kernel/src/Kernel.ts @@ -29,6 +29,7 @@ import type { ClusterConfig, VatConfig, KernelStatus, + OnRunLoopFailure, Subcluster, SubclusterLaunchResult, EndpointHandle, @@ -93,6 +94,8 @@ export class Kernel { /** Manages IO channel lifecycle (optional, requires factory injection) */ readonly #ioManager: IOManager | undefined; + readonly #onRunLoopFailure: OnRunLoopFailure | undefined; + /** * Construct a new kernel instance. * @@ -105,6 +108,7 @@ export class Kernel { * @param options.mnemonic - Optional BIP39 mnemonic for deriving the kernel identity. * @param options.ioChannelFactory - Optional factory for creating IO channels. * @param options.allowedGlobalNames - Optional list of allowed global names for vat endowments. + * @param options.onRunLoopFailure - Optional handler called if the run loop dies. */ // eslint-disable-next-line no-restricted-syntax private constructor( @@ -117,10 +121,12 @@ export class Kernel { mnemonic?: string | undefined; ioChannelFactory?: IOChannelFactory; allowedGlobalNames?: AllowedGlobalName[]; + onRunLoopFailure?: OnRunLoopFailure; } = {}, ) { this.#platformServices = platformServices; this.#kernelDatabase = kernelDatabase; + this.#onRunLoopFailure = options.onRunLoopFailure; this.#logger = options.logger ?? new Logger('ocap-kernel'); this.#kernelStore = makeKernelStore(kernelDatabase, this.#logger); if (!this.#kernelStore.isInitialized()) { @@ -234,6 +240,7 @@ export class Kernel { * @param options.ioChannelFactory - Optional factory for creating IO channels. * @param options.systemSubclusters - Optional array of system subcluster configurations. * @param options.allowedGlobalNames - Optional list of allowed global names for vat endowments. When set, only these names from the `VatSupervisor`'s configured endowments (see `createDefaultEndowments`) are available to vats. + * @param options.onRunLoopFailure - Optional handler called if the run loop dies. The kernel must be restarted after that, so an embedder that outlives it (e.g. a daemon) should use this to terminate or restart. * @returns A promise for the new kernel instance. */ static async make( @@ -247,6 +254,7 @@ export class Kernel { ioChannelFactory?: IOChannelFactory; systemSubclusters?: SystemSubclusterConfig[]; allowedGlobalNames?: AllowedGlobalName[]; + onRunLoopFailure?: OnRunLoopFailure; } = {}, ): Promise { const kernel = new Kernel(platformServices, kernelDatabase, options); @@ -296,18 +304,47 @@ export class Kernel { // This runs for the entire lifetime of the kernel this.#kernelQueue .run(this.#kernelRouter.deliver.bind(this.#kernelRouter)) - .catch((error) => { - this.#logger.error( - 'Run loop error (kernel may be non-functional):', - error, - ); - // Don't re-throw to avoid unhandled rejection in this long-running task - }); + .catch((error) => this.#handleRunLoopFailure(error)); // Launch new system subclusters (requires queue to be running) await this.#subclusterManager.launchNewSystemSubclusters(configs); } + /** + * Tell the embedder the kernel is finished, since it owns the decision to + * exit or restart. Deliberately not re-thrown: an unhandled rejection would + * take the process down without giving it that chance. + * + * @param failure - The error that killed the run loop, normalized by + * `KernelQueue.run`, which reports this same object in `getStatus`. + */ + #handleRunLoopFailure(failure: Error): void { + this.#logger.error( + 'Run loop died; the kernel can no longer process messages and must be restarted:', + failure, + ); + // Called off a local, not off `this`: `this.#onRunLoopFailure(...)` is a + // member call, so a non-arrow handler would receive the whole kernel as its + // receiver. The handler's business here is one `Error`. + const notify = this.#onRunLoopFailure; + try { + // `OnRunLoopFailure` returns void, but TypeScript admits an async + // function there, whose rejection would become the very unhandled + // rejection this method exists to avoid. Contain it either way. + const handled = notify?.(failure) as unknown; + if (typeof (handled as PromiseLike)?.then === 'function') { + Promise.resolve(handled).catch((handlerError: unknown) => { + this.#logger.error( + 'Run loop failure handler rejected:', + handlerError, + ); + }); + } + } catch (handlerError) { + this.#logger.error('Run loop failure handler threw:', handlerError); + } + } + /** * Provide the kernel facet, creating and registering it as a kernel service * if it doesn't already exist. @@ -628,15 +665,25 @@ export class Kernel { } /** - * Get the current kernel status, defined as the current cluster configuration - * and a list of all running vats. + * Get the current kernel status: run loop health, the current cluster + * configuration, and a list of all running vats. * - * @returns A promise for the current kernel status containing vats, subclusters, and remote comms information. + * @returns A promise for the current kernel status containing run loop health, + * vats, subclusters, and remote comms information. */ async getStatus(): Promise { - await this.#kernelQueue.waitForCrank(); + // A dead kernel must still be able to report that it's dead. `endCrank` + // runs in a `finally` and settles its waiters even when it throws, so this + // is belt-and-braces against a future crank that can't be waited out. + if (this.#kernelQueue.getRunLoopStatus().state !== 'failed') { + await this.#kernelQueue.waitForCrank(); + } + // Read after the wait: an in-flight crank is exactly when the loop is most + // likely to die, and a status sampled before it would report `running`. + const runLoop = this.#kernelQueue.getRunLoopStatus(); const status: KernelStatus = { + runLoop, vats: this.getVats(), subclusters: this.#subclusterManager.getSubclusters(), }; @@ -742,6 +789,10 @@ export class Kernel { /** * Stop all running vats and reset the kernel state. * This is for debugging purposes only. + * + * Does not revive a kernel whose run loop has died: this clears state, it does + * not restart the loop, so `getStatus` still reports `failed` afterwards and + * the queue still refuses new work. */ async reset(): Promise { await this.#kernelQueue.waitForCrank(); diff --git a/packages/ocap-kernel/src/KernelQueue.test.ts b/packages/ocap-kernel/src/KernelQueue.test.ts index 1c7101d496..d7beb0e2f1 100644 --- a/packages/ocap-kernel/src/KernelQueue.test.ts +++ b/packages/ocap-kernel/src/KernelQueue.test.ts @@ -66,6 +66,49 @@ describe('KernelQueue', () => { kernelQueue = new KernelQueue(kernelStore, terminateVat); }); + /** + * Make a promise kit whose `resolve`/`reject` actually settle its promise, + * for tests where the module-level `makePromiseKit` mock's bare `vi.fn()` + * settlers won't do. + * + * @returns A promise and its settlement functions. + */ + const makeRealPromiseKit = (): { + promise: Promise>; + resolve: (value: CapData) => void; + reject: (reason: unknown) => void; + } => { + let settleWithValue!: (value: CapData) => void; + let settleWithReason!: (reason: unknown) => void; + const promise = new Promise>((resolve, reject) => { + settleWithValue = resolve; + settleWithReason = reject; + }); + return { + promise, + resolve: settleWithValue, + reject: settleWithReason, + }; + }; + + /** + * Run a single crank whose delivery blows up, killing the run loop. + * + * @param error - The error the delivery fails with. + */ + const killRunLoop = async (error: Error): Promise => { + (kernelStore.runQueueLength as unknown as MockInstance).mockReturnValueOnce( + 1, + ); + (kernelStore.dequeueRun as unknown as MockInstance).mockReturnValueOnce({ + type: 'send', + target: 'ko123', + message: {} as KernelMessage, + }); + const deliver = vi.fn().mockRejectedValue(error); + await expect(kernelQueue.run(deliver)).rejects.toBe(error); + }; + describe('run', () => { it('processes items from the run queue and performs cleanup', async () => { const mockItem: RunQueueItem = { @@ -153,6 +196,321 @@ describe('KernelQueue', () => { }); }); + describe('getRunLoopStatus', () => { + it('reports idle before the run loop starts', () => { + expect(kernelQueue.getRunLoopStatus()).toStrictEqual({ state: 'idle' }); + }); + + it('reports running while the run loop is processing', async () => { + ( + kernelStore.runQueueLength as unknown as MockInstance + ).mockReturnValueOnce(1); + (kernelStore.dequeueRun as unknown as MockInstance).mockReturnValueOnce({ + type: 'send', + target: 'ko123', + message: {} as KernelMessage, + }); + // A delivery that never settles parks the loop mid-crank. + const deliver = vi.fn().mockReturnValue(new Promise(() => undefined)); + kernelQueue.run(deliver).catch(() => undefined); + await Promise.resolve(); + expect(deliver).toHaveBeenCalled(); + expect(kernelQueue.getRunLoopStatus()).toStrictEqual({ + state: 'running', + }); + }); + + it('reports failed once the run loop dies', async () => { + await killRunLoop(new Error('crank exploded')); + expect(kernelQueue.getRunLoopStatus()).toStrictEqual({ + state: 'failed', + error: 'crank exploded', + detail: expect.stringContaining('crank exploded'), + }); + }); + + // One normalization, so what `run` rejects with and what the status reports + // are the same object rather than two wrappers that happen to agree. + it('reports failed for a non-Error run loop failure', async () => { + ( + kernelStore.runQueueLength as unknown as MockInstance + ).mockReturnValueOnce(1); + (kernelStore.dequeueRun as unknown as MockInstance).mockReturnValueOnce({ + type: 'send', + target: 'ko123', + message: {} as KernelMessage, + }); + const deliver = vi.fn().mockRejectedValue('not an error'); + + const failure = await kernelQueue.run(deliver).catch((error) => error); + + expect(failure).toBeInstanceOf(Error); + expect(failure.message).toBe('not an error'); + // The thrown value survives, so it isn't lost to the normalization. + expect(failure.cause).toBe('not an error'); + expect(kernelQueue.getRunLoopStatus()).toStrictEqual({ + state: 'failed', + error: 'not an error', + detail: expect.stringContaining('not an error'), + }); + }); + }); + + describe('run loop death', () => { + it('rejects in-flight message results', async () => { + const kit = makeRealPromiseKit(); + (makePromiseKit as unknown as MockInstance).mockReturnValueOnce(kit); + const resultPromise = kernelQueue.enqueueMessage('ko123', 'test', []); + expect(kernelQueue.subscriptions.has('kp1')).toBe(true); + + const failure = new Error('crank exploded'); + await killRunLoop(failure); + + await expect(resultPromise).rejects.toThrow( + 'Kernel run loop died; this message result will never be delivered', + ); + await expect(resultPromise).rejects.toHaveProperty('cause', failure); + expect(kernelQueue.subscriptions.size).toBe(0); + }); + + it('rejects messages queued after the run loop dies', async () => { + const failure = new Error('crank exploded'); + await killRunLoop(failure); + await expect( + kernelQueue.enqueueMessage('ko123', 'test', []), + ).rejects.toThrow('Kernel run loop died; cannot queue a message'); + expect(kernelStore.enqueueRun).not.toHaveBeenCalled(); + }); + + it('rolls back the crank it died in', async () => { + await killRunLoop(new Error('crank exploded')); + // Without this, endCrank's savepoint release commits the half-finished + // crank and the dequeued item is lost. + expect(kernelStore.rollbackCrank).toHaveBeenCalledWith('start'); + }); + + it('does not roll back when the savepoint was never created', async () => { + ( + kernelStore.createCrankSavepoint as unknown as MockInstance + ).mockImplementationOnce(() => { + throw new Error('database is gone'); + }); + await expect(kernelQueue.run(vi.fn())).rejects.toThrow( + 'database is gone', + ); + expect(kernelStore.rollbackCrank).not.toHaveBeenCalled(); + }); + + it('does not roll back twice when an aborted crank then throws', async () => { + (kernelStore.runQueueLength as unknown as MockInstance) + .mockReturnValueOnce(1) + .mockReturnValue(0); + (kernelStore.dequeueRun as unknown as MockInstance).mockReturnValueOnce({ + type: 'send', + target: 'ko123', + message: { result: 'kp99' } as KernelMessage, + }); + const deliver = vi.fn().mockResolvedValue({ abort: true }); + ( + kernelStore.collectGarbage as unknown as MockInstance + ).mockImplementation(() => { + throw new Error(STOP_RUN_LOOP); + }); + + // A second rollback would throw "no such savepoint" over this error. + await expect(kernelQueue.run(deliver)).rejects.toThrow(STOP_RUN_LOOP); + expect(kernelStore.rollbackCrank).toHaveBeenCalledOnce(); + }); + + it('reports both failures when the rollback also fails', async () => { + ( + kernelStore.runQueueLength as unknown as MockInstance + ).mockReturnValueOnce(1); + (kernelStore.dequeueRun as unknown as MockInstance).mockReturnValueOnce({ + type: 'send', + target: 'ko123', + message: {} as KernelMessage, + }); + const rollbackError = new Error('database is gone'); + ( + kernelStore.rollbackCrank as unknown as MockInstance + ).mockImplementationOnce(() => { + throw rollbackError; + }); + const crankError = new Error('crank exploded'); + const deliver = vi.fn().mockRejectedValue(crankError); + + // The rollback failure names itself; the original stays the `cause`, since + // that is the root cause an operator needs. + await expect(kernelQueue.run(deliver)).rejects.toMatchObject({ + message: + 'Run loop died and its crank could not be rolled back: Error: database is gone', + cause: crankError, + }); + expect(kernelQueue.getRunLoopStatus()).toStrictEqual({ + state: 'failed', + error: + 'Run loop died and its crank could not be rolled back: Error: database is gone', + // The headline names the rollback, so only `detail` can carry the error + // that actually killed the kernel to the one consumer that reports it. + detail: expect.stringContaining('crank exploded'), + }); + }); + + // `rollbackCrank` discards the savepoint even when its database call throws, + // so a second attempt could only report a missing savepoint. Without the + // `finally` that records the attempt, the abort path leaves the flag unset, + // the catch asks again, and "no such savepoint" becomes the reason the + // kernel reports for its own death — the database error reaching nobody, + // since only `error.message` crosses the wire. + it('reports the database failure when an aborted crank cannot roll back', async () => { + (kernelStore.runQueueLength as unknown as MockInstance) + .mockReturnValueOnce(1) + .mockReturnValue(0); + (kernelStore.dequeueRun as unknown as MockInstance).mockReturnValueOnce({ + type: 'send', + target: 'ko123', + message: { result: 'kp99' } as KernelMessage, + }); + const rollbackError = new Error('database is gone'); + ( + kernelStore.rollbackCrank as unknown as MockInstance + ).mockImplementationOnce(() => { + throw rollbackError; + }); + const deliver = vi.fn().mockResolvedValue({ abort: true }); + + await expect(kernelQueue.run(deliver)).rejects.toBe(rollbackError); + expect(kernelStore.rollbackCrank).toHaveBeenCalledOnce(); + expect(kernelQueue.getRunLoopStatus()).toStrictEqual({ + state: 'failed', + error: 'database is gone', + detail: expect.stringContaining('database is gone'), + }); + }); + + // The rollback flag is per-crank. If an earlier abort could latch it, every + // later crank that died would skip its rollback and commit half its work. + it('rolls back a later crank after an earlier one aborted', async () => { + const items: RunQueueItem[] = [ + { type: 'send', target: 'ko1', message: {} as KernelMessage }, + { type: 'send', target: 'ko2', message: {} as KernelMessage }, + ]; + let dequeued = 0; + ( + kernelStore.runQueueLength as unknown as MockInstance + ).mockImplementation(() => (dequeued < items.length ? 1 : 0)); + (kernelStore.dequeueRun as unknown as MockInstance).mockImplementation( + () => { + const item = items[dequeued]; + dequeued += 1; + return item; + }, + ); + const secondError = new Error('second crank exploded'); + const deliver = vi + .fn() + .mockResolvedValueOnce({ abort: true }) + .mockRejectedValueOnce(secondError); + + await expect(kernelQueue.run(deliver)).rejects.toBe(secondError); + + expect(kernelStore.rollbackCrank).toHaveBeenCalledTimes(2); + expect(kernelQueue.getRunLoopStatus()).toStrictEqual({ + state: 'failed', + error: 'second crank exploded', + detail: expect.stringContaining('second crank exploded'), + }); + }); + + it('refuses ingress via assertRunLoopAlive', async () => { + const failure = new Error('crank exploded'); + expect(() => kernelQueue.assertRunLoopAlive('accept work')).not.toThrow(); + + await killRunLoop(failure); + + expect(() => kernelQueue.assertRunLoopAlive('accept work')).toThrow( + 'Kernel run loop died; cannot accept work', + ); + // The failure that killed the loop is the root cause. + await expect(async () => + kernelQueue.assertRunLoopAlive('accept work'), + ).rejects.toHaveProperty('cause', failure); + }); + + // Teardown enqueues too, so the guard cannot sit on these mutators: it must + // keep working after the loop dies, because `VatHandle.terminate` and + // `RemoteManager` reject the promises a dead endpoint was deciding, and + // refusing that would break `terminateAllVats` and `reset`. + it.each([ + { + teardown: 'resolvePromises', + call: (queue: KernelQueue) => + queue.resolvePromises('v1', [ + ['kp1', true, { body: 'x', slots: [] }], + ]), + didWork: () => kernelStore.resolveKernelPromise, + }, + { + teardown: 'enqueueNotify', + call: (queue: KernelQueue) => queue.enqueueNotify('v1', 'kp1'), + didWork: () => kernelStore.enqueueRun, + }, + { + teardown: 'enqueueSend', + call: (queue: KernelQueue) => + queue.enqueueSend('ko123', { + methargs: { body: 'x', slots: [] }, + result: null, + }), + didWork: () => kernelStore.enqueueRun, + }, + ])( + 'still allows $teardown after the run loop dies', + async ({ call, didWork }) => { + ( + kernelStore.getKernelPromise as unknown as MockInstance + ).mockReturnValue({ + state: 'unresolved', + decider: 'v1', + subscribers: [], + }); + await killRunLoop(new Error('crank exploded')); + + expect(() => call(kernelQueue)).not.toThrow(); + // "Allows" has to mean the work happened, not merely that nothing threw. + expect(didWork()).toHaveBeenCalled(); + }, + ); + + // The guard sits outside `run`'s try, so the refusal must not be mistaken + // for the loop dying: were it inside, a stray second call would mark a + // healthy kernel failed and reject every in-flight result. + it('refuses to start the run loop twice without killing the running one', async () => { + ( + kernelStore.runQueueLength as unknown as MockInstance + ).mockReturnValueOnce(1); + (kernelStore.dequeueRun as unknown as MockInstance).mockReturnValueOnce({ + type: 'send', + target: 'ko123', + message: {} as KernelMessage, + }); + const deliver = vi.fn().mockReturnValue(new Promise(() => undefined)); + kernelQueue.run(deliver).catch(() => undefined); + await kernelQueue.enqueueMessage('ko123', 'method', []); + expect(kernelQueue.subscriptions.has('kp1')).toBe(true); + + await expect(kernelQueue.run(deliver)).rejects.toThrow( + 'run loop already started', + ); + + expect(kernelQueue.getRunLoopStatus()).toStrictEqual({ + state: 'running', + }); + expect(kernelQueue.subscriptions.has('kp1')).toBe(true); + }); + }); + describe('enqueueMessage', () => { it('creates a message, enqueues it, and returns a promise for the result', async () => { const target = 'ko123'; @@ -512,16 +870,22 @@ describe('KernelQueue', () => { mockItem, ); const deliver = vi.fn().mockResolvedValue({ abort: true }); + // Sample at the end of the aborted crank: the sentinel error below kills + // the run loop, which discards every subscription still waiting. + let subscribedAfterAbort: boolean | undefined; + let rejectedAfterAbort: boolean | undefined; ( kernelStore.collectGarbage as unknown as MockInstance ).mockImplementation(() => { + subscribedAfterAbort = kernelQueue.subscriptions.has('kp99'); + rejectedAfterAbort = rejectSpy.mock.calls.length > 0; throw new Error(STOP_RUN_LOOP); }); await expect(kernelQueue.run(deliver)).rejects.toThrow(STOP_RUN_LOOP); expect(kernelStore.rollbackCrank).toHaveBeenCalledWith('start'); - expect(rejectSpy).not.toHaveBeenCalled(); + expect(rejectedAfterAbort).toBe(false); expect(resolveSpy).not.toHaveBeenCalled(); - expect(kernelQueue.subscriptions.has('kp99')).toBe(true); + expect(subscribedAfterAbort).toBe(true); }); }); diff --git a/packages/ocap-kernel/src/KernelQueue.ts b/packages/ocap-kernel/src/KernelQueue.ts index f0cba6d132..4148300ff7 100644 --- a/packages/ocap-kernel/src/KernelQueue.ts +++ b/packages/ocap-kernel/src/KernelQueue.ts @@ -1,5 +1,6 @@ import type { CapData } from '@endo/marshal'; import { makePromiseKit } from '@endo/promise-kit'; +import { stringify } from '@metamask/kernel-utils'; import { processGCActionSet } from './garbage-collection/garbage-collection.ts'; import { kser } from './liveslots/kernel-marshal.ts'; @@ -10,6 +11,7 @@ import type { KRef, KernelMessage, KernelOneResolution, + RunLoopStatus, RunQueueItem, RunQueueItemNotify, RunQueueItemSend, @@ -17,6 +19,10 @@ import type { } from './types.ts'; import { Fail } from './utils/assert.ts'; +type RunLoopState = + | Exclude + | { state: 'failed'; error: Error }; + /** * The kernel's run queue. * @@ -48,6 +54,30 @@ export class KernelQueue { /** Thunk to signal run queue transition from empty to non-empty */ #wakeUpTheRunQueue: (() => void) | null; + /** + * Whether this crank's savepoint has already been handed to `rollbackCrank`. + * Attempted, not necessarily succeeded: `rollbackCrank` forgets the savepoint + * whether or not the database call throws, so after either outcome a second + * attempt can only report "no such savepoint" over the real error. + * + * This has to be recorded at the moment of the attempt rather than returned + * from `#processCrankResult`, because that method can throw after rolling back + * (`#terminateVat`, `collectGarbage`), and the catch below must still know not + * to ask twice. + */ + #crankRollbackAttempted: boolean = false; + + /** + * The run loop's state, as one value so that a failure recorded for a loop + * that never started can't be represented. Once failed, nothing drains the + * queue again; for which ingress points refuse work and why teardown does not, + * see {@link assertRunLoopAlive}. + * + * Derived from the wire type so that a field added to its `failed` arm fails to + * compile until `getRunLoopStatus` produces it. + */ + #runLoopState: RunLoopState = { state: 'idle' }; + /** * Construct a new KernelQueue instance. * @@ -66,32 +96,79 @@ export class KernelQueue { /** * The kernel's run loop: take an item off the run queue, deliver it, * repeat. Note that this loops forever: the returned promise never resolves. + * If it rejects with anything but `run loop already started`, the kernel is + * dead — see {@link getRunLoopStatus}. * * @param deliver - A function that delivers an item to the kernel. + * @returns A promise that rejects with the `Error` that killed the run loop. */ async run( deliver: (item: RunQueueItem) => Promise, + ): Promise { + this.#runLoopState.state === 'idle' || Fail`run loop already started`; + this.#runLoopState = { state: 'running' }; + try { + return await this.#runLoop(deliver); + } catch (error) { + // The recorded failure rather than the raw throw, so that the embedder's + // handler and `getRunLoopStatus` describe one object rather than two. + throw this.#failRunLoop(error); + } + } + + /** + * Take an item off the run queue, deliver it, repeat. + * + * @param deliver - A function that delivers an item to the kernel. + */ + async #runLoop( + deliver: (item: RunQueueItem) => Promise, ): Promise { for (;;) { let wakeUpPromise: Promise | undefined; this.#kernelStore.startCrank(); + this.#crankRollbackAttempted = false; try { this.#kernelStore.createCrankSavepoint('start'); - const queueItem = this.#getNextRunQueueItem(); - if (queueItem) { - this.#kernelStore.nextTerminatedVatCleanup(); - const crankResult = await deliver(queueItem); - await this.#processCrankResult(crankResult, queueItem); - } else { - if (this.#wakeUpTheRunQueue !== null) { - Fail`run queue already waiting to be woken; cannot sleep again before the previous wake handler is consumed`; - } + // The savepoint exists from here on, so a throw can be undone. Without + // this, `endCrank`'s savepoint release commits the half-finished crank: + // the item this crank dequeued is gone for good, refcount increments + // stick, and promises resolved during it stay resolved while their + // notifies die unflushed. A restart would resume from that. + try { + const queueItem = this.#getNextRunQueueItem(); + if (queueItem) { + this.#kernelStore.nextTerminatedVatCleanup(); + const crankResult = await deliver(queueItem); + await this.#processCrankResult(crankResult, queueItem); + } else { + if (this.#wakeUpTheRunQueue !== null) { + Fail`run queue already waiting to be woken; cannot sleep again before the previous wake handler is consumed`; + } - const { promise, resolve } = makePromiseKit(); - this.#wakeUpTheRunQueue = resolve; - wakeUpPromise = promise; + const { promise, resolve } = makePromiseKit(); + this.#wakeUpTheRunQueue = resolve; + wakeUpPromise = promise; + } + } catch (error) { + // An aborted crank already asked, and `rollbackCrank` discards the + // savepoint either way; asking again could only throw "no such + // savepoint" over the real error. + if (!this.#crankRollbackAttempted) { + try { + this.#kernelStore.rollbackCrank('start'); + } catch (rollbackError) { + // The original failure stays the `cause`, since that is the root + // cause an operator needs; the rollback failure is named here. + throw new Error( + `Run loop died and its crank could not be rolled back: ${String(rollbackError)}`, + { cause: error }, + ); + } + } + throw error; } } finally { this.#kernelStore.endCrank(); @@ -102,6 +179,90 @@ export class KernelQueue { } } + /** + * Record the death of the run loop and fail the kernel's own message-result + * subscriptions, which would otherwise hang forever. Kernel promises in the + * store stay unresolved, so vats awaiting a notify the dead loop owed them + * are not rescued by this. + * + * @param error - The error that killed the run loop. + * @returns The failure, as an `Error` whatever was thrown. + */ + #failRunLoop(error: unknown): Error { + const failure = + error instanceof Error + ? error + : new Error(String(error), { cause: error }); + this.#runLoopState = { state: 'failed', error: failure }; + + const orphaned = [...this.subscriptions.values()]; + this.subscriptions.clear(); + this.#resolvedWithKernelSubscription = []; + for (const { reject } of orphaned) { + reject( + this.#makeDeadRunLoopError( + 'Kernel run loop died; this message result will never be delivered', + ), + ); + } + return failure; + } + + /** + * @param message - The message for the caller. + * @returns An error whose cause is the failure that killed the run loop. + */ + #makeDeadRunLoopError(message: string): Error { + return new Error(message, { + cause: + this.#runLoopState.state === 'failed' + ? this.#runLoopState.error + : undefined, + }); + } + + /** + * Refuse work that would otherwise sit in a queue nobody drains. + * + * For callers at an ingress boundary only. Teardown must not be refused even + * though it also enqueues: `VatHandle.terminate` and `RemoteManager` reject the + * promises a dying endpoint was deciding, via `resolvePromises`, which enqueues + * notifies for their subscribers. Those notifies are never delivered, but that + * is acceptable — the endpoint is going away — whereas refusing them would + * break `terminateAllVats` and `reset`. Note that those are cleanup, not + * recovery: nothing clears a `failed` state and `run` refuses to be called + * twice, so a kernel that has failed stays failed for the life of the + * instance. Recovery means a new kernel, which in practice means a new + * process. + * + * @param what - What is being refused, completing "cannot ...". + * @throws If the run loop has died. + */ + assertRunLoopAlive(what: string): void { + if (this.#runLoopState.state === 'failed') { + throw this.#makeDeadRunLoopError(`Kernel run loop died; cannot ${what}`); + } + } + + /** + * Report whether the kernel is able to process its run queue at all. + * + * @returns The current run loop status. + */ + getRunLoopStatus(): RunLoopStatus { + return harden( + this.#runLoopState.state === 'failed' + ? { + state: 'failed', + error: this.#runLoopState.error.message, + // The message drops the cause chain, and in a double failure it names + // the failed rollback rather than what killed the kernel. + detail: stringify(this.#runLoopState.error, 0), + } + : { state: this.#runLoopState.state }, + ); + } + /** * Get the next item from the kernel run queue. * **ATTN:** Mutates the kernel store if the queue is not empty. @@ -142,7 +303,16 @@ export class KernelQueue { // Rollback the kernel state to before the failed delivery attempt. // For active vats, this allows the message to be retried in a future crank. // For terminated vats, the message will just go splat. - this.#kernelStore.rollbackCrank('start'); + try { + this.#kernelStore.rollbackCrank('start'); + } finally { + // Set even when the rollback threw. `rollbackCrank` forgets the + // savepoint in its own `finally`, so "attempted" and "the savepoint is + // gone" now coincide exactly — and a second attempt from the run loop's + // catch would report a missing savepoint as the reason the kernel died, + // burying the database error that actually killed it. + this.#crankRollbackAttempted = true; + } // Discard kernel subscriptions that were queued for invocation this.#resolvedWithKernelSubscription = []; @@ -245,6 +415,8 @@ export class KernelQueue { method: string, args: unknown[], ): Promise> { + // Nothing is draining the run queue, so a returned promise could never settle. + this.assertRunLoopAlive('queue a message'); // TODO(#562): Use logger instead. // eslint-disable-next-line no-console console.debug('enqueueMessage', target, method, args); diff --git a/packages/ocap-kernel/src/index.test.ts b/packages/ocap-kernel/src/index.test.ts index b1bffc5be6..d0614cc21a 100644 --- a/packages/ocap-kernel/src/index.test.ts +++ b/packages/ocap-kernel/src/index.test.ts @@ -10,6 +10,7 @@ describe('index', () => { 'ClusterConfigStruct', 'Kernel', 'KernelStatusStruct', + 'RunLoopStatusStruct', 'SubclusterStruct', 'VatConfigStruct', 'VatHandle', diff --git a/packages/ocap-kernel/src/index.ts b/packages/ocap-kernel/src/index.ts index 33bbbcab84..41a7e4c831 100644 --- a/packages/ocap-kernel/src/index.ts +++ b/packages/ocap-kernel/src/index.ts @@ -22,6 +22,8 @@ export type { PlatformServices, VatConfig, KernelStatus, + OnRunLoopFailure, + RunLoopStatus, Subcluster, SubclusterId, SubclusterLaunchResult, @@ -52,6 +54,7 @@ export { ClusterConfigStruct, CapDataStruct, KernelStatusStruct, + RunLoopStatusStruct, SubclusterStruct, } from './types.ts'; export { AllowedGlobalNameStruct } from './vats/endowments.ts'; diff --git a/packages/ocap-kernel/src/remotes/kernel/RemoteHandle.test.ts b/packages/ocap-kernel/src/remotes/kernel/RemoteHandle.test.ts index e114834029..c14539bc6c 100644 --- a/packages/ocap-kernel/src/remotes/kernel/RemoteHandle.test.ts +++ b/packages/ocap-kernel/src/remotes/kernel/RemoteHandle.test.ts @@ -191,6 +191,78 @@ describe('RemoteHandle', () => { }); }); + // Only the run loop consumes `nextReapAction`, so a dead loop would leave the + // peer's request acknowledged and never performed. + it('refuses an incoming bringOutYourDead when the run loop is dead', async () => { + const remote = makeRemote(); + const delivery = JSON.stringify({ + seq: 1, + method: 'deliver', + params: ['bringOutYourDead'], + }); + const failure = new Error('Kernel run loop died; cannot accept it'); + vi.mocked(mockKernelQueue.assertRunLoopAlive).mockImplementation(() => { + throw failure; + }); + + await expect(remote.handleRemoteMessage(delivery)).rejects.toBe(failure); + expect(mockKernelStore.nextReapAction()).toBeUndefined(); + + // The refusal must not advance the received sequence number, or the peer's + // retry would be discarded as a duplicate. + vi.mocked(mockKernelQueue.assertRunLoopAlive).mockImplementation( + () => undefined, + ); + await remote.handleRemoteMessage(delivery); + expect(mockKernelStore.nextReapAction()).toStrictEqual({ + type: 'bringOutYourDead', + endpointId: remote.remoteId, + }); + }); + + // A dead run loop will never deliver the message, and `handleRemoteMessage` + // rolls back without advancing the received sequence number, so the peer + // retries and gives up rather than being acknowledged by a black hole. + it.each([ + { + kind: 'message', + params: [ + 'message', + 'ro+1', + { methargs: { body: '["method",[]]', slots: [] }, result: 'rp+2' }, + ], + handedToQueue: () => mockKernelQueue.enqueueSend, + }, + { + kind: 'notify', + params: ['notify', [['rp+1', false, { body: '"x"', slots: [] }]]], + handedToQueue: () => mockKernelQueue.resolvePromises, + }, + ])( + 'refuses an incoming $kind when the run loop is dead', + async ({ params, handedToQueue }) => { + const remote = makeRemote(); + const delivery = JSON.stringify({ seq: 1, method: 'deliver', params }); + const failure = new Error('Kernel run loop died; cannot accept it'); + vi.mocked(mockKernelQueue.assertRunLoopAlive).mockImplementation(() => { + throw failure; + }); + + await expect(remote.handleRemoteMessage(delivery)).rejects.toBe( + failure, + ); + expect(handedToQueue()).not.toHaveBeenCalled(); + + // The refusal must not advance the received sequence number, or the + // peer's retry would be discarded as a duplicate. + vi.mocked(mockKernelQueue.assertRunLoopAlive).mockImplementation( + () => undefined, + ); + await remote.handleRemoteMessage(delivery); + expect(handedToQueue()).toHaveBeenCalledOnce(); + }, + ); + it('does not send BOYD back when remotely triggered (ping-pong prevention)', async () => { const remote = makeRemote(); diff --git a/packages/ocap-kernel/src/remotes/kernel/RemoteHandle.ts b/packages/ocap-kernel/src/remotes/kernel/RemoteHandle.ts index 9a619789d6..d92359b5c0 100644 --- a/packages/ocap-kernel/src/remotes/kernel/RemoteHandle.ts +++ b/packages/ocap-kernel/src/remotes/kernel/RemoteHandle.ts @@ -807,6 +807,11 @@ export class RemoteHandle implements EndpointHandle { const [method] = params; switch (method) { case 'message': { + // Refuse rather than queue work for a loop that will never drain it. + // The caller rolls this delivery back without advancing the received + // sequence number, so the peer retries and then gives up instead of + // believing a black hole accepted its message. + this.#kernelQueue.assertRunLoopAlive('accept a remote message'); const [, target, message] = params; this.#kernelQueue.enqueueSend( this.#kernelStore.translateRefEtoK(this.remoteId, target), @@ -815,6 +820,7 @@ export class RemoteHandle implements EndpointHandle { break; } case 'notify': { + this.#kernelQueue.assertRunLoopAlive('accept a remote notify'); const [, resolutions] = params; const kResolutions: KernelOneResolution[] = resolutions.map( (resolution) => { @@ -849,6 +855,10 @@ export class RemoteHandle implements EndpointHandle { break; } case 'bringOutYourDead': { + // Queue work like the arms above: `scheduleReap` is consumed only by the + // run loop, via `nextReapAction`. The other GC arms need no guard — they + // only touch refcounts, which the caller's crank commits by itself. + this.#kernelQueue.assertRunLoopAlive('accept a remote reap request'); this.#kernelStore.scheduleReap(this.remoteId); break; } diff --git a/packages/ocap-kernel/src/rpc/kernel-control/get-status.test.ts b/packages/ocap-kernel/src/rpc/kernel-control/get-status.test.ts index 57fb559f71..6440b1401b 100644 --- a/packages/ocap-kernel/src/rpc/kernel-control/get-status.test.ts +++ b/packages/ocap-kernel/src/rpc/kernel-control/get-status.test.ts @@ -1,7 +1,11 @@ +import { is } from '@metamask/superstruct'; import { describe, it, expect, vi, beforeEach } from 'vitest'; import { getStatusHandler } from './get-status.ts'; import type { Kernel } from '../../Kernel.ts'; +import { KernelQueue } from '../../KernelQueue.ts'; +import type { KernelStore } from '../../store/index.ts'; +import { KernelStatusStruct } from '../../types.ts'; describe('getStatusHandler', () => { let mockKernel: Kernel; @@ -37,6 +41,107 @@ describe('getStatusHandler', () => { }); }); + // `RpcClient` validates every result against `KernelStatusStruct`, so a + // `runLoop` shape the struct rejects fails the whole getStatus call for every + // client — the outage class this field exists to report. + describe('runLoop passes result validation', () => { + const makeStatus = (runLoop: unknown) => ({ + vats: [], + subclusters: [], + remoteComms: { state: 'disconnected' }, + runLoop, + }); + + /** + * @returns A queue whose store does nothing, for reading its run loop status. + */ + const makeKernelQueue = (): { queue: KernelQueue; store: KernelStore } => { + const store = { + startCrank: vi.fn(), + endCrank: vi.fn(), + createCrankSavepoint: vi.fn(), + rollbackCrank: vi.fn(), + collectGarbage: vi.fn(), + nextReapAction: vi.fn().mockReturnValue(null), + getGCActions: vi.fn().mockReturnValue([]), + runQueueLength: vi.fn().mockReturnValue(0), + nextTerminatedVatCleanup: vi.fn(), + dequeueRun: vi.fn(), + flushCrankBuffer: vi.fn().mockReturnValue([]), + } as unknown as KernelStore; + return { queue: new KernelQueue(store, vi.fn()), store }; + }; + + it.each([ + { name: 'idle', runLoop: { state: 'idle' } }, + { name: 'running', runLoop: { state: 'running' } }, + { + name: 'failed', + runLoop: { state: 'failed', error: 'boom', detail: '{}' }, + }, + ])('accepts $name', ({ runLoop }) => { + expect(is(makeStatus(runLoop), KernelStatusStruct)).toBe(true); + }); + + it.each([ + { name: 'an unknown state', runLoop: { state: 'wedged' } }, + { name: 'failed without an error', runLoop: { state: 'failed' } }, + { + name: 'failed without a detail', + runLoop: { state: 'failed', error: 'boom' }, + }, + { + name: 'a non-string error', + runLoop: { state: 'failed', error: 1, detail: '{}' }, + }, + { name: 'a bare string', runLoop: 'failed' }, + ])('rejects $name', ({ runLoop }) => { + expect(is(makeStatus(runLoop), KernelStatusStruct)).toBe(false); + }); + + // `runLoop` is required, so `RpcClient`'s result validation fails the whole + // `getStatus` call for a reply from a kernel built before this field, rather + // than quietly losing it. Pinned because the alternatives don't typecheck + // here: `optional` widens the property to `| undefined` and `KernelStatus` + // must satisfy `Json`. + it('rejects a status with no runLoop at all', () => { + // Everything else present and valid, so only the missing `runLoop` can be + // what fails: `remoteComms: undefined` would fail on its own account. + expect( + is( + { + vats: [], + subclusters: [], + remoteComms: { state: 'disconnected' }, + }, + KernelStatusStruct, + ), + ).toBe(false); + }); + + // Ties the struct to what the queue actually emits, which are otherwise two + // independent declarations of one shape. + it('accepts what getRunLoopStatus returns before the run loop starts', () => { + const { queue } = makeKernelQueue(); + expect(is(makeStatus(queue.getRunLoopStatus()), KernelStatusStruct)).toBe( + true, + ); + }); + + it('accepts what getRunLoopStatus returns after the run loop dies', async () => { + const { queue, store } = makeKernelQueue(); + vi.mocked(store.createCrankSavepoint).mockImplementationOnce(() => { + throw new Error('boom'); + }); + + await expect(queue.run(vi.fn())).rejects.toThrow('boom'); + + expect(is(makeStatus(queue.getRunLoopStatus()), KernelStatusStruct)).toBe( + true, + ); + }); + }); + it('should propagate errors from getVats', async () => { const error = new Error('Status check failed'); vi.mocked(mockKernel.getStatus).mockRejectedValueOnce(error); diff --git a/packages/ocap-kernel/src/store/methods/crank.test.ts b/packages/ocap-kernel/src/store/methods/crank.test.ts index 421a64e8e2..db3de86450 100644 --- a/packages/ocap-kernel/src/store/methods/crank.test.ts +++ b/packages/ocap-kernel/src/store/methods/crank.test.ts @@ -65,6 +65,23 @@ describe('crank methods', () => { expect(kdb.createSavepoint).toHaveBeenCalledWith('t1'); }); + it('does not record a savepoint the database refused', () => { + context.inCrank = true; + vi.mocked(kdb.createSavepoint).mockImplementationOnce(() => { + throw new Error('database is gone'); + }); + + expect(() => crankMethods.createCrankSavepoint('start')).toThrow( + 'database is gone', + ); + + expect(context.savepoints).toStrictEqual([]); + // Otherwise `endCrank` releases a savepoint that never existed, and that + // error replaces whatever really went wrong. + crankMethods.endCrank(); + expect(kdb.releaseSavepoint).not.toHaveBeenCalled(); + }); + it('should throw when not in a crank', () => { expect(() => crankMethods.createCrankSavepoint('test')).toThrow( 'createCrankSavepoint outside of crank', @@ -73,6 +90,24 @@ describe('crank methods', () => { }); describe('rollbackCrank', () => { + it('forgets the savepoint even if the database rollback fails', () => { + context.inCrank = true; + context.savepoints = ['start']; + vi.mocked(kdb.rollbackSavepoint).mockImplementationOnce(() => { + throw new Error('database is gone'); + }); + + expect(() => crankMethods.rollbackCrank('start')).toThrow( + 'database is gone', + ); + + // Still listed, `endCrank` would release it — committing the crank this + // rollback was abandoning. + expect(context.savepoints).toStrictEqual([]); + crankMethods.endCrank(); + expect(kdb.releaseSavepoint).not.toHaveBeenCalled(); + }); + it('should rollback to specified savepoint', () => { context.inCrank = true; context.savepoints = ['first', 'second', 'third']; @@ -158,6 +193,19 @@ describe('crank methods', () => { 'endCrank outside of crank', ); }); + + it('settles the crank even if releasing savepoints fails', async () => { + crankMethods.startCrank(); + context.savepoints = ['test']; + const waiter = crankMethods.waitForCrank(); + vi.mocked(kdb.releaseSavepoint).mockImplementationOnce(() => { + throw new Error('database is gone'); + }); + expect(() => crankMethods.endCrank()).toThrow('database is gone'); + expect(context.inCrank).toBe(false); + expect(context.resolveCrank).toBeUndefined(); + expect(await waiter).toBeUndefined(); + }); }); describe('releaseAllSavepoints', () => { diff --git a/packages/ocap-kernel/src/store/methods/crank.ts b/packages/ocap-kernel/src/store/methods/crank.ts index 4cc88d8778..87d2bc65b8 100644 --- a/packages/ocap-kernel/src/store/methods/crank.ts +++ b/packages/ocap-kernel/src/store/methods/crank.ts @@ -32,8 +32,11 @@ export function getCrankMethods(ctx: StoreContext, kdb: KernelDatabase) { function createCrankSavepoint(name: string): void { ctx.inCrank || Fail`createCrankSavepoint outside of crank`; const ordinal = ctx.savepoints.length; - ctx.savepoints.push(name); + // Record the name only once the database has the savepoint. Recording it + // first would leave `endCrank` trying to release a savepoint that was never + // created, and that error would replace whatever really went wrong. kdb.createSavepoint(`t${ordinal}`); + ctx.savepoints.push(name); } /** @@ -46,8 +49,16 @@ export function getCrankMethods(ctx: StoreContext, kdb: KernelDatabase) { ctx.crankBuffer.length = 0; // Discard buffered outputs for (const ordinal of ctx.savepoints.keys()) { if (ctx.savepoints[ordinal] === savepoint) { - kdb.rollbackSavepoint(`t${ordinal}`); - ctx.savepoints.length = ordinal; + try { + kdb.rollbackSavepoint(`t${ordinal}`); + } finally { + // Forget the savepoint even if the rollback failed. Leaving it listed + // would have `endCrank`'s release commit the crank we just abandoned — + // the half-finished state this rollback exists to discard. A failed + // rollback discards the whole transaction instead (see + // `rollbackSavepoint`), which for a crank is the same boundary. + ctx.savepoints.length = ordinal; + } // The rollback reverted DB state but in-memory caches are stale. // Recreate the run queue so its cached head/tail are re-read from DB. ctx.refreshRunQueue(); @@ -72,14 +83,18 @@ export function getCrankMethods(ctx: StoreContext, kdb: KernelDatabase) { } /** - * End a crank. + * End a crank. Settles even if releasing the savepoints fails, so that a + * database error can't strand every `waitForCrank()` waiter forever. */ function endCrank(): void { ctx.inCrank || Fail`endCrank outside of crank`; - releaseAllSavepoints(); - ctx.inCrank = false; - ctx.resolveCrank?.(); - ctx.resolveCrank = undefined; + try { + releaseAllSavepoints(); + } finally { + ctx.inCrank = false; + ctx.resolveCrank?.(); + ctx.resolveCrank = undefined; + } } /** diff --git a/packages/ocap-kernel/src/types.ts b/packages/ocap-kernel/src/types.ts index e5ea314b01..aeefa76800 100644 --- a/packages/ocap-kernel/src/types.ts +++ b/packages/ocap-kernel/src/types.ts @@ -763,6 +763,34 @@ const RemoteCommsConnectedStruct = object({ listenAddresses: array(string()), }); +/** + * Whether the kernel is capable of processing its run queue. `idle` means the + * run loop was never started, not that it has nothing to do — a loop parked on + * an empty queue reports `running`. `failed` means nothing will ever be + * processed again and the kernel must be restarted. + */ +// The arms are `type()`, not `object()`, so a client shipped against them +// tolerates a newer kernel adding a field to an arm. Note the limit of that: +// a newer kernel adding a whole new *state* is rejected by the union either +// way, so adding an arm here is a breaking wire change for older clients. +export const RunLoopStatusStruct = union([ + type({ state: literal('idle') }), + type({ state: literal('running') }), + // Two strings because one cannot be both: `error` is the message, `detail` the + // cause chain. When a crank dies and its rollback then fails, the message names + // the rollback and only the chain names what killed the kernel. + type({ state: literal('failed'), error: string(), detail: string() }), +]); + +export type RunLoopStatus = Infer; + +/** + * Notified when the kernel's run loop dies. Should not be async: the kernel is + * reporting a failure it cannot recover from, so there is nothing to await. An + * async handler's rejection is logged rather than awaited. + */ +export type OnRunLoopFailure = (error: Error) => void; + export const KernelStatusStruct = type({ subclusters: array(SubclusterStruct), vats: array( @@ -772,6 +800,15 @@ export const KernelStatusStruct = type({ subclusterId: SubclusterIdStruct, }), ), + // Required, in the type as well as on the wire. `exactOptional` would make the + // type say "may be absent" while validation still demanded the key, since + // `exactOptional` only permits an absent key inside `object()` and this is a + // `type()`. `optional` would agree with the type but cannot be used: it widens + // the inferred property to `| undefined`, and `KernelStatus` is an RPC result, + // so it must satisfy `Json`. Required is the only self-consistent option — at + // the cost that a reply from a kernel predating this field fails validation + // outright, which `remoteComms` already implies for older kernels too. + runLoop: RunLoopStatusStruct, remoteComms: exactOptional( union([ RemoteCommsDisconnectedStruct, diff --git a/packages/ocap-kernel/src/vats/SubclusterManager.test.ts b/packages/ocap-kernel/src/vats/SubclusterManager.test.ts index 43c15657cf..f46a7bd499 100644 --- a/packages/ocap-kernel/src/vats/SubclusterManager.test.ts +++ b/packages/ocap-kernel/src/vats/SubclusterManager.test.ts @@ -69,6 +69,7 @@ describe('SubclusterManager', () => { mockKernelQueue = { waitForCrank: vi.fn().mockResolvedValue(undefined), + assertRunLoopAlive: vi.fn(), } as unknown as Mocked; mockVatManager = { @@ -127,6 +128,21 @@ describe('SubclusterManager', () => { }); }); + // The launch fails at the bootstrap message either way; only refusing up + // front keeps it from leaking a spawned worker per vat in the config. + it('refuses to launch when the run loop has died', async () => { + vi.mocked(mockKernelQueue.assertRunLoopAlive).mockImplementation(() => { + throw new Error('Kernel run loop died; cannot launch a subcluster'); + }); + + await expect( + subclusterManager.launchSubcluster(createMockClusterConfig()), + ).rejects.toThrow('Kernel run loop died; cannot launch a subcluster'); + + expect(mockVatManager.launchVat).not.toHaveBeenCalled(); + expect(mockKernelStore.addSubcluster).not.toHaveBeenCalled(); + }); + it('launches subcluster with multiple vats', async () => { const config: ClusterConfig = { bootstrap: 'alice', diff --git a/packages/ocap-kernel/src/vats/SubclusterManager.ts b/packages/ocap-kernel/src/vats/SubclusterManager.ts index a32ac7a5d4..ebbcc384e1 100644 --- a/packages/ocap-kernel/src/vats/SubclusterManager.ts +++ b/packages/ocap-kernel/src/vats/SubclusterManager.ts @@ -116,6 +116,9 @@ export class SubclusterManager { { isSystem = false }: { isSystem?: boolean } = {}, ): Promise { await this.#kernelQueue.waitForCrank(); + // It would fail at the bootstrap message anyway, but only refusing here fails + // before spawning a worker per vat, which the catch below leaks. + this.#kernelQueue.assertRunLoopAlive('launch a subcluster'); isClusterConfig(config) || Fail`invalid cluster config`; if (!config.vats[config.bootstrap]) { Fail`invalid bootstrap vat name ${config.bootstrap}`; diff --git a/packages/ocap-kernel/test/remotes-mocks.ts b/packages/ocap-kernel/test/remotes-mocks.ts index c7a4b4e7e0..0e37b4a77c 100644 --- a/packages/ocap-kernel/test/remotes-mocks.ts +++ b/packages/ocap-kernel/test/remotes-mocks.ts @@ -77,6 +77,7 @@ export class MockRemotesFactory { enqueueSend: vi.fn(), enqueueNotify: vi.fn(), resolvePromises: vi.fn(), + assertRunLoopAlive: vi.fn(), waitForCrank: vi.fn(), run: vi.fn(), } as unknown as KernelQueue; diff --git a/packages/repo-tools/src/test-utils/env/mock-kernel.ts b/packages/repo-tools/src/test-utils/env/mock-kernel.ts index d38ec0c253..1744c09ab0 100644 --- a/packages/repo-tools/src/test-utils/env/mock-kernel.ts +++ b/packages/repo-tools/src/test-utils/env/mock-kernel.ts @@ -8,6 +8,7 @@ import { exactOptional, array, type, + union, } from '@metamask/superstruct'; import { vi } from 'vitest'; @@ -44,6 +45,12 @@ export const setupOcapKernelMock = (): { const KRefStruct = define('KRef', () => isKRefMock); + const RunLoopStatusStruct = union([ + type({ state: literal('idle') }), + type({ state: literal('running') }), + type({ state: literal('failed'), error: string(), detail: string() }), + ]); + return { isVatId: () => isVatIdMock, isVatConfig: () => isVatConfigMock, @@ -63,6 +70,7 @@ export const setupOcapKernelMock = (): { slots: array(string()), }), ClusterConfigStruct, + RunLoopStatusStruct, KernelStatusStruct: type({ subclusters: array(SubclusterStruct), vats: array( @@ -72,6 +80,7 @@ export const setupOcapKernelMock = (): { subclusterId: SubclusterIdStruct, }), ), + runLoop: RunLoopStatusStruct, }), KernelSendMessageStruct: object({ id: literal('v0'),