diff --git a/packages/kernel-browser-runtime/CHANGELOG.md b/packages/kernel-browser-runtime/CHANGELOG.md index 473a868c6..d13c38154 100644 --- a/packages/kernel-browser-runtime/CHANGELOG.md +++ b/packages/kernel-browser-runtime/CHANGELOG.md @@ -13,6 +13,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Fixed +- The kernel worker gives the kernel store a logger, so the wasm SQLite driver's diagnostics reach the log rather than nowhere ([#1021](https://github.com/Consensys-Incorporated/ocap-kernel/pull/1021)) - 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)) ## [0.6.0] 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 832a57a90..afffa24e3 100644 --- a/packages/kernel-browser-runtime/src/kernel-worker/kernel-worker.ts +++ b/packages/kernel-browser-runtime/src/kernel-worker/kernel-worker.ts @@ -44,7 +44,10 @@ async function main(): Promise { isJsonRpcMessage, ), PlatformServicesClient.make(globalThis as PostMessageTarget), - makeSQLKernelDatabase({ dbFilename: DB_FILENAME }), + makeSQLKernelDatabase({ + dbFilename: DB_FILENAME, + logger: logger.subLogger({ tags: ['kernel-store'] }), + }), ]); setupConsoleForwarding({ diff --git a/packages/kernel-node-runtime/CHANGELOG.md b/packages/kernel-node-runtime/CHANGELOG.md index 51b675e9d..fbc3f4dbf 100644 --- a/packages/kernel-node-runtime/CHANGELOG.md +++ b/packages/kernel-node-runtime/CHANGELOG.md @@ -23,6 +23,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Fixed +- `makeKernel` gives the kernel store a logger, so the SQLite driver's diagnostics reach the log rather than nowhere ([#1021](https://github.com/Consensys-Incorporated/ocap-kernel/pull/1021)) - The RPC socket server refuses to bind a Unix socket that has a live listener, rather than unlinking it and orphaning the previous owner; stale socket files with no listener are still cleaned up automatically ([#952](https://github.com/MetaMask/ocap-kernel/pull/952)) ## [0.1.0] diff --git a/packages/kernel-node-runtime/src/kernel/make-kernel.test.ts b/packages/kernel-node-runtime/src/kernel/make-kernel.test.ts index 57b0293d6..eb80137e4 100644 --- a/packages/kernel-node-runtime/src/kernel/make-kernel.test.ts +++ b/packages/kernel-node-runtime/src/kernel/make-kernel.test.ts @@ -1,3 +1,5 @@ +import { makeSQLKernelDatabase } from '@metamask/kernel-store/sqlite/nodejs'; +import { Logger } from '@metamask/logger'; import { Kernel } from '@metamask/ocap-kernel'; import { describe, expect, it, vi } from 'vitest'; @@ -8,7 +10,7 @@ vi.mock('@metamask/kernel-store/sqlite/nodejs', async () => { '../../../ocap-kernel/test/storage.ts' ); return { - makeSQLKernelDatabase: makeMapKernelDatabase, + makeSQLKernelDatabase: vi.fn(makeMapKernelDatabase), }; }); @@ -18,4 +20,12 @@ describe('makeKernel', () => { expect(kernel).toBeInstanceOf(Kernel); }); + + it('gives the kernel store a logger', async () => { + await makeKernel({}); + + expect(vi.mocked(makeSQLKernelDatabase)).toHaveBeenCalledWith( + expect.objectContaining({ logger: expect.any(Logger) }), + ); + }); }); diff --git a/packages/kernel-node-runtime/src/kernel/make-kernel.ts b/packages/kernel-node-runtime/src/kernel/make-kernel.ts index 901e79982..529eb7af2 100644 --- a/packages/kernel-node-runtime/src/kernel/make-kernel.ts +++ b/packages/kernel-node-runtime/src/kernel/make-kernel.ts @@ -60,7 +60,10 @@ export async function makeKernel({ }); // Initialize kernel store. - const kernelDatabase = await makeSQLKernelDatabase({ dbFilename }); + const kernelDatabase = await makeSQLKernelDatabase({ + dbFilename, + logger: rootLogger.subLogger({ tags: ['kernel-store'] }), + }); // Create and start kernel. const kernel = await Kernel.make(platformServicesClient, kernelDatabase, { diff --git a/packages/kernel-store/CHANGELOG.md b/packages/kernel-store/CHANGELOG.md index 51e5eb111..ba26b8ff9 100644 --- a/packages/kernel-store/CHANGELOG.md +++ b/packages/kernel-store/CHANGELOG.md @@ -12,6 +12,19 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 - `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 +- `releaseSavepoint` discards the enclosing transaction when `RELEASE` fails, as `rollbackSavepoint` already did for `ROLLBACK TO`; the release failure is still what gets thrown ([#1021](https://github.com/Consensys-Incorporated/ocap-kernel/pull/1021)) +- The wasm driver asks SQLite whether a transaction is open instead of caching the answer, so an error SQLite recovers from no longer refuses every write for the life of the worker ([#1021](https://github.com/Consensys-Incorporated/ocap-kernel/pull/1021)) + - SQLite ends the transaction itself after `SQLITE_FULL`, `SQLITE_IOERR` and `SQLITE_BUSY`. The driver's `ROLLBACK` was refused as a result, it read that refusal as a transaction it could not end, and latched — on a healthy database, in the browser extension's kernel store. The nodejs driver already read `db.inTransaction`; both now recover once the transaction is gone +- Both drivers discard the transaction a failed `COMMIT` leaves open ([#1021](https://github.com/Consensys-Incorporated/ocap-kernel/pull/1021)) + - `releaseSavepoint` reaches `commitIfNeeded` outside any try of its own, so a throwing `COMMIT` left the transaction open with nothing to end it. Later writes autocommitted — including the next savepoint, created bare, where `RELEASE` commits and no rollback can undo the work +- The nodejs driver no longer logs every SQL statement it executes ([#1021](https://github.com/Consensys-Incorporated/ocap-kernel/pull/1021)) + - Handing it a logger for the error paths above also enabled better-sqlite3's `verbose` option, which fires on every statement with values inlined, at `info`. Kernel store rows carry vat state, c-list entries and capability data +- Neither driver commits a transaction whose discarding abort failed ([#1021](https://github.com/Consensys-Incorporated/ocap-kernel/pull/1021)) + - The savepoint list was emptied while SQLite still held the transaction, so the next `createSavepoint` skipped `BEGIN`, nested inside it, and committed the abandoned crank on release. Both drivers now retry the abort before beginning, and abort rather than commit while one is outstanding +- Every write refuses while a transaction the drivers could not abort is outstanding, not just the ones that pass through `beginIfNeeded` or `commitIfNeeded` ([#1021](https://github.com/Consensys-Incorporated/ocap-kernel/pull/1021)) + - `kernelKVStore.set`, `kernelKVStore.delete`, `clear`, `deleteVatStore`, the savepoint operations, and the nodejs driver's vatstore update joined the abandoned transaction and reported success. Teardown such as `reset` looked like it had landed, and the writes went with the transaction on close + - `executeQuery` stays exempt: its callers are debug surfaces, which would not expect a query to roll anything back +- Both drivers log an abort that fails while recovering from a failed savepoint operation ([#1021](https://github.com/Consensys-Incorporated/ocap-kernel/pull/1021)) ## [0.6.0] diff --git a/packages/kernel-store/src/sqlite/nodejs.savepoint-interleaving.test.ts b/packages/kernel-store/src/sqlite/nodejs.savepoint-interleaving.test.ts new file mode 100644 index 000000000..47087733d --- /dev/null +++ b/packages/kernel-store/src/sqlite/nodejs.savepoint-interleaving.test.ts @@ -0,0 +1,94 @@ +import { describe, it, expect } from 'vitest'; + +import { makeSQLKernelDatabase } from './nodejs.ts'; + +/** + * Why a crank and a savepoint of someone else's must never overlap. + * + * `KernelQueue.#runLoop` calls releasing its `crank` savepoint "this crank's one + * commit point". `releaseAllSavepoints` releases `t0`, which is the outermost + * savepoint only if the crank opened the first one, and `KernelStore`'s own + * `createSavepoint` bypasses `ctx.savepoints` and so is invisible to the ordinal + * numbering. Two production paths use it: `RemoteHandle.handleRemoteMessage` and + * `RemoteManager.handleIncarnationChange`. + * + * Real SQLite through the real driver, one test per interleaving. Each records + * what SQLite actually does, which is the reason the kernel now serializes the + * two: `createSavepoint` refuses inside a crank, `startCrank` refuses while a + * caller holds the store outside one, and callers take their turn through + * `beginOutOfCrank`. See `crank.out-of-crank.test.ts` for the enforcement. + */ +describe('a savepoint the crank does not know about', () => { + it('outside the crank, leaves the crank release with nothing to commit', async () => { + const kdb = await makeSQLKernelDatabase({ dbFilename: ':memory:' }); + const kv = kdb.kernelKVStore; + + // RemoteHandle.handleRemoteMessage, parked on its await. + kdb.createSavepoint('receive_r1_7'); + + // The run loop wakes: startCrank, then the two crank savepoints. + kdb.createSavepoint('t0'); + kdb.createSavepoint('t1'); + kv.set('crankWrite', 'durable'); + + // endCrank -> releaseAllSavepoints -> releaseSavepoint('t0'). `t0` is not the + // outermost savepoint, so this releases into the remote's, not to a commit. + kdb.releaseSavepoint('t0'); + + // The remote message then fails, so RemoteHandle rolls its savepoint back, + // and takes the whole committed-looking crank with it. + kdb.rollbackSavepoint('receive_r1_7'); + + expect(kv.get('crankWrite')).toBeUndefined(); + kdb.close(); + }); + + it('inside the crank, is destroyed by the delivery rollback behind its owner', async () => { + const kdb = await makeSQLKernelDatabase({ dbFilename: ':memory:' }); + const kv = kdb.kernelKVStore; + + // startCrank + kdb.createSavepoint('t0'); + kdb.createSavepoint('t1'); + + // A remote message arrives during `await deliver(queueItem)`. + kdb.createSavepoint('receive_r1_7'); + kv.set('remoteSeq.r1.highestReceivedSeq', '7'); + + // The delivery aborts: rollbackCrank('delivery') issues ROLLBACK TO t1, and + // SQLite cancels every savepoint started after t1 -- including the remote's. + kdb.rollbackSavepoint('t1'); + + // The remote handler, still inside its own try, reaches its release and + // finds the savepoint gone along with everything it wrote. + expect(() => kdb.releaseSavepoint('receive_r1_7')).toThrow( + 'No such savepoint: receive_r1_7', + ); + expect(kv.get('remoteSeq.r1.highestReceivedSeq')).toBeUndefined(); + kdb.close(); + }); + + it('inside a crank that succeeds, is committed under its owner', async () => { + const kdb = await makeSQLKernelDatabase({ dbFilename: ':memory:' }); + const kv = kdb.kernelKVStore; + + // A remote message arrives and gets as far as its await, so the seq row it + // writes "at the end, within the transaction" is not written yet. + kdb.createSavepoint('t0'); + kdb.createSavepoint('t1'); + kdb.createSavepoint('receive_r1_7'); + kv.set('remoteHalfDone', 'yes'); + + // endCrank releases t0, and with it everything stacked above. + kdb.releaseSavepoint('t0'); + + // The remote handler resumes to find its savepoint gone -- and its + // half-finished work durable regardless, so it reports a failure for an + // effect that has landed and the peer retries it. + expect(() => kdb.releaseSavepoint('receive_r1_7')).toThrow( + 'No such savepoint: receive_r1_7', + ); + expect(kv.get('remoteHalfDone')).toBe('yes'); + kdb.close(); + }); +}); diff --git a/packages/kernel-store/src/sqlite/nodejs.test.ts b/packages/kernel-store/src/sqlite/nodejs.test.ts index a62392fe1..189fe0cf1 100644 --- a/packages/kernel-store/src/sqlite/nodejs.test.ts +++ b/packages/kernel-store/src/sqlite/nodejs.test.ts @@ -308,7 +308,6 @@ describe('makeSQLKernelDatabase', () => { ); expect(mockDb._spStack).toStrictEqual([]); - // The abort is the only prepared statement this path runs. expect(mockStatement.run).toHaveBeenCalledOnce(); mockDb.inTransaction = false; }); @@ -360,6 +359,44 @@ describe('makeSQLKernelDatabase', () => { expect(mockDb._spStack).toStrictEqual([]); }); + it('releaseSavepoint discards the transaction when the release 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.releaseSavepoint('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; + }); + + it('releaseSavepoint reports the release 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.releaseSavepoint('point1')).toThrowError( + 'disk I/O error', + ); + + expect(mockDb._spStack).toStrictEqual([]); + mockDb.inTransaction = false; + }); + it('supports nested savepoints', async () => { const db = await makeSQLKernelDatabase({}); db.createSavepoint('outer'); diff --git a/packages/kernel-store/src/sqlite/nodejs.transaction-survival.test.ts b/packages/kernel-store/src/sqlite/nodejs.transaction-survival.test.ts new file mode 100644 index 000000000..27cdd35a0 --- /dev/null +++ b/packages/kernel-store/src/sqlite/nodejs.transaction-survival.test.ts @@ -0,0 +1,247 @@ +import type { Logger } from '@metamask/logger'; +import { describe, it, expect, beforeEach, vi } from 'vitest'; + +import { SQL_QUERIES } from './common.ts'; +import { makeSQLKernelDatabase } from './nodejs.ts'; +import type { KernelDatabase } from '../types.ts'; + +/** + * Two invariants the crank layer relies on: + * + * - a failed `ROLLBACK TO` discards the whole transaction; + * - `commitIfNeeded` leaves no transaction behind. + * + * Both hold only while the abort doing the discarding succeeds. When it does + * not, the driver logs it and refuses every later write rather than let one + * join a transaction nothing will commit; `ctx.savepoints` is truncated to + * zero either way, so it no longer matches the database. + */ + +/** Every statement and exec call, in order. */ +let issued: string[] = []; +/** SQL that throws when next run. */ +let failOnce: Set = new Set(); + +/** What SQLite would report through `db.inTransaction`. */ +let inTransaction = false; + +/** + * Run one statement against the mock, tracking the transaction the way SQLite + * does: a statement that throws changes nothing, and one that succeeds opens or + * closes the transaction. Without the latter the mock can only ever model a + * connection that is wedged, which is the state under test here and so exactly + * the state that must not be assumed. + * + * @param text - The SQL being run. + */ +function runSql(text: string): void { + issued.push(text); + if (failOnce.delete(text)) { + throw new Error(`SQLITE_IOERR: ${text}`); + } + if (text === 'BEGIN TRANSACTION') { + inTransaction = true; + } else if (text === 'COMMIT TRANSACTION' || text === 'ROLLBACK TRANSACTION') { + inTransaction = false; + } +} + +const makeStatement = (text: string): Record => ({ + run: () => { + runSql(text); + return undefined; + }, + get: () => undefined, + all: () => [], + pluck: () => undefined, + iterate: () => [], +}); + +const mockDb = { + prepare: vi.fn((text: string) => makeStatement(text)), + transaction: vi.fn((fn: () => void) => fn), + exec: vi.fn(runSql), + get inTransaction(): boolean { + return inTransaction; + }, + set inTransaction(value: boolean) { + inTransaction = value; + }, + _spStack: [] as string[], + close: vi.fn(), +}; + +vi.mock('better-sqlite3', () => ({ + default: vi.fn(function () { + return mockDb; + }), +})); +vi.mock('node:fs/promises', () => ({ mkdir: vi.fn() })); +vi.mock('node:os', () => ({ tmpdir: vi.fn(() => '/mock-tmpdir') })); + +describe('the nodejs driver after a failure it tolerates', () => { + beforeEach(() => { + issued = []; + failOnce = new Set(); + mockDb.inTransaction = false; + mockDb._spStack = []; + }); + + it('discards the transaction when the rollback fails and the abort fails too', async () => { + const kdb = await makeSQLKernelDatabase({}); + // A crank in progress: SAVEPOINT t0, SAVEPOINT t1. + mockDb.inTransaction = true; + mockDb._spStack = ['t0', 't1']; + issued = []; + + // The disk fills. `ROLLBACK TO SAVEPOINT t1` fails, and so does the + // `ROLLBACK TRANSACTION` meant to discard the transaction instead. The + // driver logs that second failure and rethrows the first, so SQLite is + // still in a transaction with t0 and t1 on its stack. + failOnce.add('ROLLBACK TO SAVEPOINT t1'); + failOnce.add('ROLLBACK TRANSACTION'); + expect(() => kdb.rollbackSavepoint('t1')).toThrow('SQLITE_IOERR'); + expect(mockDb._spStack).toStrictEqual([]); + expect(mockDb.inTransaction).toBe(true); + + // `_spStack` now says "no savepoints, nothing to commit or abort" while + // SQLite says otherwise. Teardown still runs after the run loop dies -- + // `reset`, a peer incarnation change, a remote message -- and takes a + // savepoint. + issued = []; + kdb.createSavepoint('teardown'); + kdb.releaseSavepoint('teardown'); + + // The abandoned transaction is retried and discarded before the new + // savepoint can join it, so what the COMMIT makes durable is `teardown`'s + // own transaction and not the crank that was thrown away. + expect(issued).toStrictEqual([ + 'ROLLBACK TRANSACTION', + 'BEGIN TRANSACTION', + 'SAVEPOINT teardown', + 'RELEASE SAVEPOINT teardown', + 'COMMIT TRANSACTION', + ]); + }); + + // Teardown after the run loop dies reaches the store by many doors, most of + // which never touch `beginIfNeeded`. + it.each([ + { + what: 'a savepoint', + write: (kdb: KernelDatabase) => kdb.createSavepoint('teardown'), + sql: 'SAVEPOINT teardown', + }, + { + what: 'a savepoint rollback', + write: (kdb: KernelDatabase) => kdb.rollbackSavepoint('t0'), + sql: 'ROLLBACK TO SAVEPOINT t0', + }, + { + what: 'a savepoint release', + write: (kdb: KernelDatabase) => kdb.releaseSavepoint('t0'), + sql: 'RELEASE SAVEPOINT t0', + }, + { + what: 'a kv write', + write: (kdb: KernelDatabase) => kdb.kernelKVStore.set('k', 'v'), + sql: SQL_QUERIES.SET, + }, + { + what: 'a kv delete', + write: (kdb: KernelDatabase) => kdb.kernelKVStore.delete('k'), + sql: SQL_QUERIES.DELETE, + }, + { + what: 'a clear', + write: (kdb: KernelDatabase) => kdb.clear(), + sql: SQL_QUERIES.CLEAR, + }, + { + what: 'a vatstore delete', + write: (kdb: KernelDatabase) => kdb.deleteVatStore('v1'), + sql: SQL_QUERIES.DELETE_VS_ALL, + }, + { + what: 'a vatstore update', + write: (kdb: KernelDatabase) => + kdb.makeVatStore('v1').updateKVData([['k', 'v']], []), + sql: SQL_QUERIES.SET_VS, + }, + ])( + 'refuses $what once the transaction cannot be discarded at all', + async ({ write, sql }) => { + const kdb = await makeSQLKernelDatabase({}); + mockDb.inTransaction = true; + mockDb._spStack = ['t0', 't1']; + issued = []; + + failOnce.add('ROLLBACK TO SAVEPOINT t1'); + failOnce.add('ROLLBACK TRANSACTION'); + expect(() => kdb.rollbackSavepoint('t1')).toThrow('SQLITE_IOERR'); + + failOnce.add('ROLLBACK TRANSACTION'); + expect(() => write(kdb)).toThrow('refusing further writes'); + expect(issued).not.toContain(sql); + }, + ); + + it('discards the transaction when the commit fails', async () => { + const kdb = await makeSQLKernelDatabase({}); + mockDb.inTransaction = true; + mockDb._spStack = ['t0']; + issued = []; + + // endCrank: RELEASE SAVEPOINT t0 succeeds, the COMMIT it triggers does not. + failOnce.add('COMMIT TRANSACTION'); + expect(() => kdb.releaseSavepoint('t0')).toThrow('SQLITE_IOERR'); + + // A failed COMMIT can leave the transaction open, and `_spStack` was + // already spliced empty, so nothing else would have ended it. + expect(issued).toContain('ROLLBACK TRANSACTION'); + expect(mockDb.inTransaction).toBe(false); + }); + + // SQLite ending the transaction is the only way out of an abort that keeps + // failing. Refusing writes past that point refuses them forever. + it('writes again once the transaction it could not end is gone', async () => { + const kdb = await makeSQLKernelDatabase({}); + mockDb.inTransaction = true; + mockDb._spStack = ['t0', 't1']; + + failOnce.add('ROLLBACK TO SAVEPOINT t1'); + failOnce.add('ROLLBACK TRANSACTION'); + expect(() => kdb.rollbackSavepoint('t1')).toThrow('SQLITE_IOERR'); + + mockDb.inTransaction = false; + + issued = []; + kdb.kernelKVStore.set('k', 'v'); + expect(issued).toStrictEqual([SQL_QUERIES.SET]); + }); + + it('reports the abort that failed while discarding the transaction', async () => { + const logger = { + debug: vi.fn(), + warn: vi.fn(), + error: vi.fn(), + subLogger: vi.fn(() => logger), + } as unknown as Logger; + const kdb = await makeSQLKernelDatabase({ logger }); + mockDb.inTransaction = true; + mockDb._spStack = ['t0']; + + failOnce.add('COMMIT TRANSACTION'); + failOnce.add('ROLLBACK TRANSACTION'); + expect(() => kdb.releaseSavepoint('t0')).toThrow( + 'SQLITE_IOERR: COMMIT TRANSACTION', + ); + + expect(logger.error).toHaveBeenCalledWith( + 'failed to discard transaction after commit', + expect.objectContaining({ + message: 'SQLITE_IOERR: ROLLBACK TRANSACTION', + }), + ); + }); +}); diff --git a/packages/kernel-store/src/sqlite/nodejs.ts b/packages/kernel-store/src/sqlite/nodejs.ts index ec863edc7..23f4b417e 100644 --- a/packages/kernel-store/src/sqlite/nodejs.ts +++ b/packages/kernel-store/src/sqlite/nodejs.ts @@ -28,11 +28,9 @@ export type Database = SqliteDatabase & { async function initDB(dbFilename: string, logger?: Logger): Promise { const dbPath = await getDBFilename(dbFilename); logger?.debug('dbPath:', dbPath); - const db = new Sqlite(dbPath, { - verbose: (logger ? logger.info.bind(logger) : undefined) as - | ((...args: unknown[]) => void) - | undefined, - }) as Database; + // No `verbose`: it fires on every statement with values inlined, and kernel + // store rows carry vat state and c-list entries. + const db = new Sqlite(dbPath) as Database; db._spStack = []; return db; } @@ -41,9 +39,16 @@ async function initDB(dbFilename: string, logger?: Logger): Promise { * Makes a persistent {@link KVStore} on top of a SQLite database. * * @param db - The (open) database to use. + * @param options - Options for the store. + * @param options.assertWritable - Throws if this connection can no longer + * persist anything, which every write here must ask first: one issued into a + * transaction nothing can end reports success and is lost with it. * @returns A key/value store using the given database. */ -function makeKVStore(db: Database): KVStore { +function makeKVStore( + db: Database, + { assertWritable }: { assertWritable: () => void }, +): KVStore { const sqlKVInit = db.prepare(SQL_QUERIES.CREATE_TABLE); sqlKVInit.run(); @@ -93,6 +98,7 @@ function makeKVStore(db: Database): KVStore { * @param value - The value to assign to it. */ function kvSet(key: string, value: string): void { + assertWritable(); sqlKVSet.run(key, value); } @@ -104,6 +110,7 @@ function makeKVStore(db: Database): KVStore { * @param key - The key to remove. */ function kvDelete(key: string): void { + assertWritable(); sqlKVDelete.run(key); } @@ -135,7 +142,7 @@ export async function makeSQLKernelDatabase({ }): Promise { const db = await initDB(dbFilename ?? DEFAULT_DB_FILENAME, logger); - const kvStore = makeKVStore(db); + const kvStore = makeKVStore(db, { assertWritable: assertNotAbandoned }); const sqlKVInitVS = db.prepare(SQL_QUERIES.CREATE_TABLE_VS); sqlKVInitVS.run(); @@ -150,12 +157,18 @@ export async function makeSQLKernelDatabase({ const sqlCommitTransaction = db.prepare(SQL_QUERIES.COMMIT_TRANSACTION); const sqlAbortTransaction = db.prepare(SQL_QUERIES.ABORT_TRANSACTION); + // Set when an abort meant to discard a transaction fails. The writes of the + // crank we gave up on are still in it, and a savepoint taken inside it would + // be released into it. + let txAbandoned = false; + /** * Begin a transaction if not already in one * * @returns True if a new transaction was started, false if already in one */ function beginIfNeeded(): boolean { + assertNotAbandoned(); if (db.inTransaction) { return false; } @@ -163,12 +176,44 @@ export async function makeSQLKernelDatabase({ return true; } + /** + * Refuse to touch a transaction an earlier abort could not end. A savepoint + * created inside one is released into it, committing the crank that abort was + * discarding, and a COMMIT makes those writes durable outright. Retried once + * first, since the failure may have been transient. + * + * @throws If the transaction is still there afterwards, because reporting + * that this connection can no longer persist anything is the only honest + * answer left — returning normally would tell the caller its write landed. + */ + function assertNotAbandoned(): void { + if (!txAbandoned) { + return; + } + discardTransaction('abandonment'); + if (txAbandoned) { + throw new Error( + 'transaction cannot be ended; refusing further writes on this connection', + ); + } + } + /** * Commit a transaction if one is active and no savepoints remain */ function commitIfNeeded(): void { - if (db.inTransaction && db._spStack.length === 0) { + assertNotAbandoned(); + if (!db.inTransaction || db._spStack.length > 0) { + return; + } + try { sqlCommitTransaction.run(); + } catch (error) { + // A failed COMMIT can leave the transaction open, and `releaseSavepoint` + // reaches here outside any try of its own — the same hazard the savepoint + // paths below discard the transaction to avoid, by a third door. + discardTransaction('commit'); + throw error; } } @@ -176,9 +221,35 @@ export async function makeSQLKernelDatabase({ * Rollback a transaction */ function rollbackIfNeeded(): void { - if (db.inTransaction) { + if (!db.inTransaction) { + txAbandoned = false; + return; + } + try { sqlAbortTransaction.run(); - db._spStack.length = 0; + } catch (error) { + txAbandoned = true; + throw error; + } + db._spStack.length = 0; + // Normally false now. If SQLite still reports a transaction, it is still + // not ours to commit. + txAbandoned = db.inTransaction; + } + + /** + * Discard the transaction after a failure that leaves it unowned, keeping the + * error that got us here rather than the abort's. + * + * @param after - What failed, completing "failed to discard transaction after + * ...". + */ + function discardTransaction(after: string): void { + db._spStack.length = 0; + try { + rollbackIfNeeded(); + } catch (error) { + logger?.error(`failed to discard transaction after ${after}`, error); } } @@ -190,6 +261,17 @@ export async function makeSQLKernelDatabase({ sqlKVClearVS.run(); } + const kvClearInTransaction = db.transaction(kvClear); + + /** + * Delete everything from the database, refusing rather than handing the + * deletes to a transaction that will never commit. + */ + function clear(): void { + assertNotAbandoned(); + kvClearInTransaction(); + } + /** * Execute an arbitrary query and return the results. * @@ -234,6 +316,7 @@ export async function makeSQLKernelDatabase({ * @param deletes - A set of keys that have been deleted. */ function updateKVData(sets: [string, string][], deletes: string[]): void { + assertNotAbandoned(); db.transaction(() => { for (const [key, value] of sets) { sqlVatstoreSet.run(vatID, key, value); @@ -256,6 +339,7 @@ export async function makeSQLKernelDatabase({ * @param vatId - The vat whose store is to be deleted. */ function deleteVatStore(vatId: string): void { + assertNotAbandoned(); sqlVatstoreDeleteAll.run(vatId); } @@ -281,6 +365,7 @@ export async function makeSQLKernelDatabase({ * @param name - The name of the savepoint. */ function rollbackSavepoint(name: string): void { + assertNotAbandoned(); assertSafeIdentifier(name); const idx = db._spStack.lastIndexOf(name); if (idx < 0) { @@ -295,12 +380,7 @@ export async function makeSQLKernelDatabase({ // 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. - } + discardTransaction('rollback'); throw error; } db._spStack.splice(idx); @@ -315,13 +395,21 @@ export async function makeSQLKernelDatabase({ * @param name - The name of the savepoint. */ function releaseSavepoint(name: string): void { + assertNotAbandoned(); assertSafeIdentifier(name); const idx = db._spStack.lastIndexOf(name); if (idx < 0) { throw new Error(`No such savepoint: ${name}`); } const query = SQL_QUERIES.RELEASE_SAVEPOINT.replace('%NAME%', name); - db.exec(query); + try { + db.exec(query); + } catch (error) { + // The hazard `rollbackSavepoint` guards against, by the other door, and + // there is no committing this transaction now. + discardTransaction('release'); + throw error; + } db._spStack.splice(idx); if (db._spStack.length === 0) { commitIfNeeded(); @@ -331,7 +419,7 @@ export async function makeSQLKernelDatabase({ return { kernelKVStore: kvStore, executeQuery: kvExecuteQuery, - clear: db.transaction(kvClear), + clear, makeVatStore, deleteVatStore, createSavepoint, diff --git a/packages/kernel-store/src/sqlite/wasm.test.ts b/packages/kernel-store/src/sqlite/wasm.test.ts index 2cbc96d65..b4a20f99f 100644 --- a/packages/kernel-store/src/sqlite/wasm.test.ts +++ b/packages/kernel-store/src/sqlite/wasm.test.ts @@ -26,11 +26,13 @@ const mockStatement = { columnCount: 2, }; +let txOpen = false; + const mockDb = { exec: vi.fn(), prepare: vi.fn(() => mockStatement), - _inTx: false, + pointer: 1, _spStack: [] as string[], close: vi.fn(), @@ -47,6 +49,7 @@ vi.mock('@sqlite.org/sqlite-wasm', () => ({ OpfsDb: OpfsDbMock, DB: DBMock, }, + capi: { sqlite3_get_autocommit: () => (txOpen ? 0 : 1) }, })), })); @@ -81,6 +84,7 @@ describe('makeSQLKernelDatabase', () => { return mockDb; }), }, + capi: { sqlite3_get_autocommit: () => (txOpen ? 0 : 1) }, }) as unknown as Sqlite3Static, ); const logger = { @@ -368,170 +372,6 @@ describe('makeSQLKernelDatabase', () => { }); }); - describe('savepoint functionality', () => { - beforeEach(() => { - mockDb.exec.mockClear(); - mockDb._inTx = false; - mockDb._spStack = []; - }); - - it('creates a savepoint using sanitized name', async () => { - const db = await makeSQLKernelDatabase({}); - db.createSavepoint('valid_name'); - - expect(mockDb.exec).toHaveBeenCalledWith('SAVEPOINT valid_name'); - }); - - it('rejects invalid savepoint names', async () => { - const db = await makeSQLKernelDatabase({}); - expect(() => db.createSavepoint('invalid-name')).toThrowError( - 'Invalid identifier', - ); - expect(() => db.createSavepoint('123numeric')).toThrowError( - 'Invalid identifier', - ); - expect(() => db.createSavepoint('spaces not allowed')).toThrowError( - 'Invalid identifier', - ); - expect(() => db.createSavepoint("point'; DROP TABLE kv--")).toThrowError( - 'Invalid identifier', - ); - expect(mockDb.exec).not.toHaveBeenCalledWith( - expect.stringContaining('DROP TABLE'), - ); - }); - - it('rolls back to a savepoint', async () => { - const db = await makeSQLKernelDatabase({}); - db.createSavepoint('test_point'); - db.rollbackSavepoint('test_point'); - expect(mockDb.exec).toHaveBeenCalledWith( - 'ROLLBACK TO SAVEPOINT test_point', - ); - }); - - it('releases a savepoint', async () => { - const db = await makeSQLKernelDatabase({}); - db.createSavepoint('test_point'); - db.releaseSavepoint('test_point'); - expect(mockDb.exec).toHaveBeenCalledWith('RELEASE SAVEPOINT test_point'); - }); - - it('createSavepoint begins transaction if needed', async () => { - const db = await makeSQLKernelDatabase({}); - db.createSavepoint('test_point'); - expect(mockDb._inTx).toBe(true); - expect(mockDb._spStack).toContain('test_point'); - expect(mockDb.exec).toHaveBeenCalledWith('SAVEPOINT test_point'); - }); - - it('rollbackSavepoint validates savepoint exists', async () => { - const db = await makeSQLKernelDatabase({}); - mockDb._inTx = true; - mockDb._spStack = ['existing_point']; - expect(() => db.rollbackSavepoint('nonexistent_point')).toThrowError( - 'No such savepoint: nonexistent_point', - ); - }); - - it('rollbackSavepoint removes all points after target', async () => { - const db = await makeSQLKernelDatabase({}); - mockDb._inTx = true; - mockDb._spStack = ['point1', 'point2', 'point3']; - db.rollbackSavepoint('point2'); - expect(mockDb._spStack).toStrictEqual(['point1']); - expect(mockDb.exec).toHaveBeenCalledWith('ROLLBACK TO SAVEPOINT point2'); - }); - - it('rollbackSavepoint closes transaction if no savepoints remain', async () => { - const db = await makeSQLKernelDatabase({}); - mockDb._inTx = true; - mockDb._spStack = ['point1']; - db.rollbackSavepoint('point1'); - expect(mockDb._spStack).toStrictEqual([]); - 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; - mockDb._spStack = ['existing_point']; - expect(() => db.releaseSavepoint('nonexistent_point')).toThrowError( - 'No such savepoint: nonexistent_point', - ); - }); - - it('releaseSavepoint removes all points after target', async () => { - const db = await makeSQLKernelDatabase({}); - mockDb._inTx = true; - mockDb._spStack = ['point1', 'point2', 'point3']; - db.releaseSavepoint('point2'); - expect(mockDb._spStack).toStrictEqual(['point1']); - expect(mockDb.exec).toHaveBeenCalledWith('RELEASE SAVEPOINT point2'); - }); - - it('releaseSavepoint commits transaction if no savepoints remain', async () => { - const db = await makeSQLKernelDatabase({}); - mockDb._inTx = true; - mockDb._spStack = ['point1']; - db.releaseSavepoint('point1'); - expect(mockDb._spStack).toStrictEqual([]); - expect(mockDb._inTx).toBe(false); - }); - - it('supports nested savepoints', async () => { - const db = await makeSQLKernelDatabase({}); - db.createSavepoint('outer'); - db.createSavepoint('inner'); - expect(mockDb._spStack).toStrictEqual(['outer', 'inner']); - db.rollbackSavepoint('inner'); - expect(mockDb._spStack).toStrictEqual(['outer']); - expect(mockDb._inTx).toBe(true); - db.releaseSavepoint('outer'); - expect(mockDb._spStack).toStrictEqual([]); - expect(mockDb._inTx).toBe(false); - }); - }); - it('deleteVatStore removes all data for a given vat', async () => { Object.values(mockStatement).forEach((mock) => { if (typeof mock === 'function' && mock.mockReset) { @@ -606,14 +446,12 @@ describe('transaction management', () => { } }); mockDb.exec.mockReset(); - mockDb._inTx = false; + txOpen = false; mockDb._spStack = []; }); it('safeMutate rollbacks transaction on error', async () => { const db = await makeSQLKernelDatabase({}); - mockDb._inTx = false; - mockDb._spStack = []; mockStatement.step.mockImplementationOnce(() => { throw new Error('Database error'); }); @@ -626,7 +464,7 @@ describe('transaction management', () => { it('safeMutate does not commit if already in transaction', async () => { const db = await makeSQLKernelDatabase({}); - mockDb._inTx = true; + txOpen = true; mockDb._spStack = []; const vatStore = db.makeVatStore('test-vat'); vatStore.updateKVData([['key', 'value']], []); diff --git a/packages/kernel-store/src/sqlite/wasm.transaction-survival.test.ts b/packages/kernel-store/src/sqlite/wasm.transaction-survival.test.ts new file mode 100644 index 000000000..6aadfcd2b --- /dev/null +++ b/packages/kernel-store/src/sqlite/wasm.transaction-survival.test.ts @@ -0,0 +1,285 @@ +import type { Logger } from '@metamask/logger'; +import { describe, it, expect, beforeEach, vi } from 'vitest'; + +import { SQL_QUERIES } from './common.ts'; +import { makeSQLKernelDatabase } from './wasm.ts'; +import type { KernelDatabase } from '../types.ts'; + +/** + * The nodejs sibling of this file states the invariants both drivers owe the + * crank layer. This one exists because the two drivers reach them over + * different plumbing: wasm steps prepared statements rather than running them, + * and its vatstore writes go through `safeMutate` rather than a driver-level + * transaction helper. + */ + +/** Every statement and exec call, in order. */ +let issued: string[] = []; +/** SQL that throws when next run. */ +let failOnce: Set = new Set(); +/** What SQLite would report through `sqlite3_get_autocommit`. */ +let txOpen = false; + +/** + * Run one statement against the mock. A statement that throws changes nothing, + * as in SQLite, so an injected failure leaves the transaction as it was. + * + * @param text - The SQL being run. + */ +function runSql(text: string): void { + issued.push(text); + if (failOnce.delete(text)) { + throw new Error(`SQLITE_IOERR: ${text}`); + } + if (text === 'BEGIN TRANSACTION') { + txOpen = true; + } else if (text === 'COMMIT TRANSACTION' || text === 'ROLLBACK TRANSACTION') { + if (!txOpen) { + throw new Error('cannot rollback - no transaction is active'); + } + txOpen = false; + } +} + +const makeStatement = (text: string): Record => ({ + bind: vi.fn(), + step: () => { + runSql(text); + return false; + }, + reset: vi.fn(), + get: vi.fn(), + getString: vi.fn(), + getColumnName: vi.fn(), + columnCount: 0, +}); + +const mockDb = { + prepare: vi.fn((text: string) => makeStatement(text)), + exec: vi.fn(runSql), + pointer: 1, + _spStack: [] as string[], + close: vi.fn(), +}; + +const DbMock = vi.fn(function () { + return mockDb; +}); + +vi.mock('@sqlite.org/sqlite-wasm', () => ({ + default: vi.fn(async () => ({ + oo1: { OpfsDb: DbMock, DB: DbMock }, + capi: { sqlite3_get_autocommit: () => (txOpen ? 0 : 1) }, + })), +})); +vi.mock('./env.ts', () => ({ getDBFolder: vi.fn(() => 'test-folder') })); + +describe('the wasm driver after a failure it tolerates', () => { + beforeEach(() => { + issued = []; + failOnce = new Set(); + txOpen = false; + mockDb._spStack = []; + }); + + // Teardown after the run loop dies reaches the store by many doors, most of + // which never touch `beginIfNeeded`. + it.each([ + { + what: 'a savepoint', + write: (kdb: KernelDatabase) => kdb.createSavepoint('teardown'), + sql: 'SAVEPOINT teardown', + }, + { + what: 'a savepoint rollback', + write: (kdb: KernelDatabase) => kdb.rollbackSavepoint('t0'), + sql: 'ROLLBACK TO SAVEPOINT t0', + }, + { + what: 'a savepoint release', + write: (kdb: KernelDatabase) => kdb.releaseSavepoint('t0'), + sql: 'RELEASE SAVEPOINT t0', + }, + { + what: 'a kv write', + write: (kdb: KernelDatabase) => kdb.kernelKVStore.set('k', 'v'), + sql: SQL_QUERIES.SET, + }, + { + what: 'a kv delete', + write: (kdb: KernelDatabase) => kdb.kernelKVStore.delete('k'), + sql: SQL_QUERIES.DELETE, + }, + { + what: 'a clear', + write: (kdb: KernelDatabase) => kdb.clear(), + sql: SQL_QUERIES.CLEAR, + }, + { + what: 'a vatstore delete', + write: (kdb: KernelDatabase) => kdb.deleteVatStore('v1'), + sql: SQL_QUERIES.DELETE_VS_ALL, + }, + { + what: 'a vatstore update', + write: (kdb: KernelDatabase) => + kdb.makeVatStore('v1').updateKVData([['k', 'v']], []), + sql: SQL_QUERIES.SET_VS, + }, + ])( + 'refuses $what once the transaction cannot be discarded at all', + async ({ write, sql }) => { + const kdb = await makeSQLKernelDatabase({}); + txOpen = true; + mockDb._spStack = ['t0', 't1']; + issued = []; + + failOnce.add('ROLLBACK TO SAVEPOINT t1'); + failOnce.add('ROLLBACK TRANSACTION'); + expect(() => kdb.rollbackSavepoint('t1')).toThrow('SQLITE_IOERR'); + + failOnce.add('ROLLBACK TRANSACTION'); + expect(() => write(kdb)).toThrow('refusing further writes'); + expect(issued).not.toContain(sql); + }, + ); + + it('discards the transaction and lets the next savepoint begin its own', async () => { + const kdb = await makeSQLKernelDatabase({}); + txOpen = true; + mockDb._spStack = ['t0', 't1']; + issued = []; + + failOnce.add('ROLLBACK TO SAVEPOINT t1'); + failOnce.add('ROLLBACK TRANSACTION'); + expect(() => kdb.rollbackSavepoint('t1')).toThrow('SQLITE_IOERR'); + + issued = []; + kdb.createSavepoint('teardown'); + kdb.releaseSavepoint('teardown'); + + // The abort is retried and succeeds, so what the COMMIT makes durable is + // `teardown`'s own transaction and not the crank that was thrown away. + expect(issued).toStrictEqual([ + 'ROLLBACK TRANSACTION', + 'BEGIN TRANSACTION', + 'SAVEPOINT teardown', + 'RELEASE SAVEPOINT teardown', + 'COMMIT TRANSACTION', + ]); + }); + + // SQLite having ended the transaction leaves the driver's savepoints gone + // and its ROLLBACK refused, which it must not read as a transaction it could + // not end: that refuses every write from here on. + it('keeps writing after SQLite rolls the transaction back itself', async () => { + const kdb = await makeSQLKernelDatabase({}); + txOpen = true; + mockDb._spStack = ['t0', 't1']; + + failOnce.add('ROLLBACK TO SAVEPOINT t1'); + txOpen = false; + expect(() => kdb.rollbackSavepoint('t1')).toThrow('SQLITE_IOERR'); + + issued = []; + kdb.kernelKVStore.set('k', 'v'); + expect(issued).toStrictEqual([SQL_QUERIES.SET]); + }); + + // SQLite ending the transaction is also the only way out of an abort that + // keeps failing. Refusing writes past that point refuses them forever. + it('writes again once the transaction it could not end is gone', async () => { + const kdb = await makeSQLKernelDatabase({}); + txOpen = true; + mockDb._spStack = ['t0', 't1']; + + failOnce.add('ROLLBACK TO SAVEPOINT t1'); + failOnce.add('ROLLBACK TRANSACTION'); + expect(() => kdb.rollbackSavepoint('t1')).toThrow('SQLITE_IOERR'); + + txOpen = false; + + issued = []; + kdb.kernelKVStore.set('k', 'v'); + expect(issued).toStrictEqual([SQL_QUERIES.SET]); + }); + + // A savepoint left on the stack keeps the transaction open with nothing to + // commit or abort it, so every later write joins it and vanishes on close. + it.each([ + { + what: 'a savepoint rollback', + act: (kdb: KernelDatabase) => kdb.rollbackSavepoint('t0'), + failing: 'ROLLBACK TO SAVEPOINT t0', + }, + { + what: 'a savepoint release', + act: (kdb: KernelDatabase) => kdb.releaseSavepoint('t0'), + failing: 'RELEASE SAVEPOINT t0', + }, + { + what: 'a commit', + act: (kdb: KernelDatabase) => kdb.releaseSavepoint('t0'), + failing: 'COMMIT TRANSACTION', + }, + ])('discards the transaction when $what fails', async ({ act, failing }) => { + const kdb = await makeSQLKernelDatabase({}); + txOpen = true; + mockDb._spStack = ['t0']; + issued = []; + + failOnce.add(failing); + expect(() => act(kdb)).toThrow(`SQLITE_IOERR: ${failing}`); + + expect(issued.at(-1)).toBe('ROLLBACK TRANSACTION'); + expect(txOpen).toBe(false); + expect(mockDb._spStack).toStrictEqual([]); + }); + + // The first failure is the diagnosis; a failed abort on top of it only + // repeats that the same connection is broken. + it.each([ + { + what: 'a savepoint rollback', + act: (kdb: KernelDatabase) => kdb.rollbackSavepoint('t0'), + failing: 'ROLLBACK TO SAVEPOINT t0', + after: 'rollback', + }, + { + what: 'a savepoint release', + act: (kdb: KernelDatabase) => kdb.releaseSavepoint('t0'), + failing: 'RELEASE SAVEPOINT t0', + after: 'release', + }, + { + what: 'a commit', + act: (kdb: KernelDatabase) => kdb.releaseSavepoint('t0'), + failing: 'COMMIT TRANSACTION', + after: 'commit', + }, + ])( + 'reports the failure in $what rather than the abort that followed it', + async ({ act, failing, after }) => { + const logger = { + debug: vi.fn(), + warn: vi.fn(), + error: vi.fn(), + subLogger: vi.fn(() => logger), + } as unknown as Logger; + const kdb = await makeSQLKernelDatabase({ logger }); + txOpen = true; + mockDb._spStack = ['t0']; + + failOnce.add(failing); + failOnce.add('ROLLBACK TRANSACTION'); + expect(() => act(kdb)).toThrow(`SQLITE_IOERR: ${failing}`); + + expect(logger.error).toHaveBeenCalledWith( + `failed to discard transaction after ${after}`, + expect.objectContaining({ + message: 'SQLITE_IOERR: ROLLBACK TRANSACTION', + }), + ); + }, + ); +}); diff --git a/packages/kernel-store/src/sqlite/wasm.transactions.test.ts b/packages/kernel-store/src/sqlite/wasm.transactions.test.ts new file mode 100644 index 000000000..c04dbe775 --- /dev/null +++ b/packages/kernel-store/src/sqlite/wasm.transactions.test.ts @@ -0,0 +1,89 @@ +import { describe, it, expect } from 'vitest'; + +import { makeSQLKernelDatabase } from './wasm.ts'; +import type { KernelDatabase } from '../types.ts'; + +/** + * The wasm driver against the real SQLite build. Its siblings mock the database + * to inject I/O failures; this file exists for the savepoint and transaction + * semantics only SQLite itself can state. + */ + +const makeDb = async (): Promise => + makeSQLKernelDatabase({ dbFilename: ':memory:' }); + +describe('the wasm driver on real SQLite', () => { + it('undoes the writes a rolled-back savepoint covers', async () => { + const kdb = await makeDb(); + kdb.kernelKVStore.set('kept', 'before'); + kdb.createSavepoint('t0'); + kdb.kernelKVStore.set('undone', 'during'); + kdb.kernelKVStore.set('kept', 'during'); + kdb.rollbackSavepoint('t0'); + + expect(kdb.kernelKVStore.get('undone')).toBeUndefined(); + expect(kdb.kernelKVStore.get('kept')).toBe('before'); + }); + + it('keeps the writes a released savepoint covers', async () => { + const kdb = await makeDb(); + kdb.createSavepoint('t0'); + kdb.kernelKVStore.set('key', 'value'); + kdb.releaseSavepoint('t0'); + + expect(kdb.kernelKVStore.get('key')).toBe('value'); + }); + + it('rolls the inner savepoint back without disturbing the outer one', async () => { + const kdb = await makeDb(); + kdb.createSavepoint('t0'); + kdb.kernelKVStore.set('outer', 'yes'); + kdb.createSavepoint('t1'); + kdb.kernelKVStore.set('inner', 'yes'); + kdb.rollbackSavepoint('t1'); + kdb.releaseSavepoint('t0'); + + expect(kdb.kernelKVStore.get('outer')).toBe('yes'); + expect(kdb.kernelKVStore.get('inner')).toBeUndefined(); + }); + + // The first savepoint has to open a transaction of its own, or releasing it + // autocommits. See https://github.com/Agoric/agoric-sdk/issues/8423. + it('opens a transaction for the outermost savepoint', async () => { + const kdb = await makeDb(); + kdb.createSavepoint('t0'); + kdb.kernelKVStore.set('key', 'value'); + + // SQLite refuses this unless a transaction is open. + expect(() => kdb.executeQuery('ROLLBACK TRANSACTION')).not.toThrow(); + expect(kdb.kernelKVStore.get('key')).toBeUndefined(); + }); + + // What SQLITE_FULL leaves behind: the transaction and every savepoint in it + // are gone, so the crank's rollback fails. Taking that for a transaction the + // driver cannot end refuses every later write on a healthy database. + it('keeps writing after SQLite ends the transaction itself', async () => { + const kdb = await makeDb(); + kdb.createSavepoint('t0'); + kdb.kernelKVStore.set('lost', 'value'); + kdb.executeQuery('ROLLBACK TRANSACTION'); + + expect(() => kdb.rollbackSavepoint('t0')).toThrow('no such savepoint: t0'); + + kdb.kernelKVStore.set('after', 'value'); + expect(kdb.kernelKVStore.get('after')).toBe('value'); + }); + + it('takes the next crank in a transaction of its own', async () => { + const kdb = await makeDb(); + kdb.createSavepoint('t0'); + kdb.executeQuery('ROLLBACK TRANSACTION'); + expect(() => kdb.rollbackSavepoint('t0')).toThrow('no such savepoint: t0'); + + kdb.createSavepoint('t0'); + kdb.kernelKVStore.set('key', 'value'); + kdb.releaseSavepoint('t0'); + + expect(kdb.kernelKVStore.get('key')).toBe('value'); + }); +}); diff --git a/packages/kernel-store/src/sqlite/wasm.ts b/packages/kernel-store/src/sqlite/wasm.ts index c0c32b8a7..afc8651df 100644 --- a/packages/kernel-store/src/sqlite/wasm.ts +++ b/packages/kernel-store/src/sqlite/wasm.ts @@ -1,5 +1,8 @@ import { Logger } from '@metamask/logger'; -import type { Database as SqliteDatabase } from '@sqlite.org/sqlite-wasm'; +import type { + Database as SqliteDatabase, + Sqlite3Static, +} from '@sqlite.org/sqlite-wasm'; import sqlite3InitModule from '@sqlite.org/sqlite-wasm'; import { @@ -11,11 +14,22 @@ import { getDBFolder } from './env.ts'; import type { KVStore, VatStore, KernelDatabase } from '../types.ts'; export type Database = SqliteDatabase & { - _inTx: boolean; + /** + * Whether SQLite holds a transaction on this connection, as SQLite reports + * it. A cached answer goes stale: SQLite rolls a transaction back on its own + * after SQLITE_FULL, SQLITE_IOERR or SQLITE_BUSY, and a driver that trusted + * its own bookkeeping would issue a ROLLBACK there, read the resulting + * "cannot rollback - no transaction is active" as a transaction it could not + * end, and refuse every later write on a healthy database. + */ + readonly inTransaction: boolean; // stack of active savepoint names _spStack: string[]; }; +/** `sqlite3_get_autocommit` is bound by the wasm build but absent from its types. */ +type AutocommitCapi = { sqlite3_get_autocommit: (pDb: number) => number }; + /** * Ensure that SQLite is initialized. * @@ -40,8 +54,15 @@ export async function initDB( db = new sqlite3.oo1.DB(`:memory:`, 'cw'); } + const { sqlite3_get_autocommit: getAutocommit } = + sqlite3.capi as Sqlite3Static['capi'] & AutocommitCapi; + const dbWithTx = db as Database; - dbWithTx._inTx = false; + Object.defineProperty(dbWithTx, 'inTransaction', { + configurable: true, + get: () => + dbWithTx.pointer !== undefined && getAutocommit(dbWithTx.pointer) === 0, + }); dbWithTx._spStack = []; return dbWithTx; @@ -51,10 +72,20 @@ export async function initDB( * Makes a {@link KVStore} on top of a SQLite database * * @param db - The (open) database to use. - * @param logger - A logger object for recording activity. + * @param options - Options for the store. + * @param options.assertWritable - Throws if this connection can no longer + * persist anything, which every write here must ask first: one issued into a + * transaction nothing can end reports success and is lost with it. + * @param options.logger - A logger object for recording activity. * @returns A key/value store using the given database. */ -function makeKVStore(db: Database, logger?: Logger): KVStore { +function makeKVStore( + db: Database, + { + assertWritable, + logger, + }: { assertWritable: () => void; logger?: Logger | undefined }, +): KVStore { db.exec(SQL_QUERIES.CREATE_TABLE); const sqlKVGet = db.prepare(SQL_QUERIES.GET); @@ -116,6 +147,7 @@ function makeKVStore(db: Database, logger?: Logger): KVStore { * @param value - The value to assign to it. */ function kvSet(key: string, value: string): void { + assertWritable(); logger?.debug(`kv set '${key}' to '${value}'`); sqlKVSet.bind([key, value]); sqlKVSet.step(); @@ -130,6 +162,7 @@ function makeKVStore(db: Database, logger?: Logger): KVStore { * @param key - The key to remove. */ function kvDelete(key: string): void { + assertWritable(); logger?.debug(`kv delete '${key}'`); sqlKVDelete.bind([key]); sqlKVDelete.step(); @@ -165,7 +198,10 @@ export async function makeSQLKernelDatabase({ const db = await initDB(dbFilename ?? DEFAULT_DB_FILENAME, logger); logger?.debug('Initializing kernel store'); - const kvStore = makeKVStore(db, logger?.subLogger({ tags: ['kv'] })); + const kvStore = makeKVStore(db, { + assertWritable: assertNotAbandoned, + logger: logger?.subLogger({ tags: ['kv'] }), + }); db.exec(SQL_QUERIES.CREATE_TABLE_VS); @@ -179,29 +215,64 @@ export async function makeSQLKernelDatabase({ const sqlCommitTransaction = db.prepare(SQL_QUERIES.COMMIT_TRANSACTION); const sqlAbortTransaction = db.prepare(SQL_QUERIES.ABORT_TRANSACTION); + // Set when an abort meant to discard a transaction fails. The writes of the + // crank we gave up on are still in it, and a savepoint taken inside it would + // be released into it. + let txAbandoned = false; + /** * Begin a transaction if not already in one * * @returns True if a new transaction was started, false if already in one */ function beginIfNeeded(): boolean { - if (db._inTx) { + assertNotAbandoned(); + if (db.inTransaction) { return false; } sqlBeginTransaction.step(); sqlBeginTransaction.reset(); - db._inTx = true; return true; } + /** + * Refuse to touch a transaction an earlier abort could not end. A savepoint + * created inside one is released into it, committing the crank that abort was + * discarding, and a COMMIT makes those writes durable outright. Retried once + * first, since the failure may have been transient. + * + * @throws If the transaction is still there afterwards, because reporting + * that this connection can no longer persist anything is the only honest + * answer left — returning normally would tell the caller its write landed. + */ + function assertNotAbandoned(): void { + if (!txAbandoned) { + return; + } + discardTransaction('abandonment'); + if (txAbandoned) { + throw new Error( + 'transaction cannot be ended; refusing further writes on this connection', + ); + } + } + /** * Commit a transaction if one is active and no savepoints remain */ function commitIfNeeded(): void { - if (db._inTx && db._spStack.length === 0) { + assertNotAbandoned(); + if (!db.inTransaction || db._spStack.length > 0) { + return; + } + try { sqlCommitTransaction.step(); sqlCommitTransaction.reset(); - db._inTx = false; + } catch (error) { + // A failed COMMIT can leave the transaction open, and `releaseSavepoint` + // reaches here outside any try of its own. + discardTransaction('commit'); + throw error; } } @@ -209,11 +280,36 @@ export async function makeSQLKernelDatabase({ * Rollback a transaction */ function rollbackIfNeeded(): void { - if (db._inTx) { + if (!db.inTransaction) { + txAbandoned = false; + return; + } + try { sqlAbortTransaction.step(); sqlAbortTransaction.reset(); - db._inTx = false; - db._spStack.length = 0; + } catch (error) { + txAbandoned = true; + throw error; + } + db._spStack.length = 0; + // Normally false now. If SQLite still reports a transaction, it is still + // not ours to commit. + txAbandoned = db.inTransaction; + } + + /** + * Discard the transaction after a failure that leaves it unowned, keeping the + * error that got us here rather than the abort's. + * + * @param after - What failed, completing "failed to discard transaction after + * ...". + */ + function discardTransaction(after: string): void { + db._spStack.length = 0; + try { + rollbackIfNeeded(); + } catch (error) { + logger?.error(`failed to discard transaction after ${after}`, error); } } @@ -241,6 +337,7 @@ export async function makeSQLKernelDatabase({ * Delete everything from the database. */ function kvClear(): void { + assertNotAbandoned(); logger?.debug('clearing all kernel state'); sqlKVClear.step(); sqlKVClear.reset(); @@ -249,7 +346,11 @@ export async function makeSQLKernelDatabase({ } /** - * Execute a SQL query. + * Execute a SQL query. Unlike the other write paths this one does not consult + * `assertNotAbandoned`, whose side effect is a rollback: the debug surfaces + * that call it would not expect a query to end a transaction. `step` will run + * DML given it, where the nodejs driver's `all` refuses a statement that + * returns no rows. * * @param sql - The SQL query to execute. * @returns An array of results. @@ -336,6 +437,7 @@ export async function makeSQLKernelDatabase({ * @param vatId - The vat whose store is to be deleted. */ function deleteVatStore(vatId: string): void { + assertNotAbandoned(); sqlVatstoreDeleteAll.bind([vatId]); sqlVatstoreDeleteAll.step(); sqlVatstoreDeleteAll.reset(); @@ -363,6 +465,7 @@ export async function makeSQLKernelDatabase({ * @param name - The name of the savepoint. */ function rollbackSavepoint(name: string): void { + assertNotAbandoned(); assertSafeIdentifier(name); const idx = db._spStack.lastIndexOf(name); if (idx < 0) { @@ -377,12 +480,7 @@ export async function makeSQLKernelDatabase({ // 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. - } + discardTransaction('rollback'); throw error; } db._spStack.splice(idx); @@ -397,13 +495,21 @@ export async function makeSQLKernelDatabase({ * @param name - The name of the savepoint. */ function releaseSavepoint(name: string): void { + assertNotAbandoned(); assertSafeIdentifier(name); const idx = db._spStack.lastIndexOf(name); if (idx < 0) { throw new Error(`No such savepoint: ${name}`); } const query = SQL_QUERIES.RELEASE_SAVEPOINT.replace('%NAME%', name); - db.exec(query); + try { + db.exec(query); + } catch (error) { + // The hazard `rollbackSavepoint` guards against, by the other door, and + // there is no committing this transaction now. + discardTransaction('release'); + throw error; + } db._spStack.splice(idx); if (db._spStack.length === 0) { commitIfNeeded(); diff --git a/packages/kernel-test/src/crank-rollback.test.ts b/packages/kernel-test/src/crank-rollback.test.ts index cd2a708aa..cc71c5cbc 100644 --- a/packages/kernel-test/src/crank-rollback.test.ts +++ b/packages/kernel-test/src/crank-rollback.test.ts @@ -5,12 +5,9 @@ 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. + * `KernelQueue`'s own tests mock the store, so they prove only that + * `rollbackCrank` is *called* correctly. These exercise what it does against + * real SQLite. */ /** @@ -34,9 +31,6 @@ const makeItem = (target: string): RunQueueItem => }) 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')); @@ -54,9 +48,6 @@ describe('crank rollback against a real database', () => { 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')); @@ -75,10 +66,6 @@ describe('crank rollback against a real database', () => { 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'); @@ -95,8 +82,6 @@ describe('crank rollback against a real database', () => { 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(); @@ -109,8 +94,7 @@ describe('crank rollback against a real database', () => { 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. + // Survives the commit boundary a later crank draws. kernelStore.startCrank(); kernelStore.createCrankSavepoint('start'); kernelStore.endCrank(); @@ -118,8 +102,6 @@ describe('crank rollback against a real database', () => { 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(); @@ -138,9 +120,91 @@ describe('crank rollback against a real database', () => { 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('keeps the writes a crank makes after rolling its delivery back', async () => { + const { kernelStore, kdb } = await makeStore(); + + kernelStore.startCrank(); + kernelStore.createCrankSavepoint('crank'); + kernelStore.createCrankSavepoint('delivery'); + kdb.kernelKVStore.set('delivered', 'yes'); + + kernelStore.rollbackCrank('delivery'); + kdb.kernelKVStore.set('terminated', 'yes'); + kernelStore.endCrank(); + + expect(kdb.kernelKVStore.get('delivered')).toBeUndefined(); + expect(kdb.kernelKVStore.get('terminated')).toBe('yes'); + }); + + // Rolling back `crank` is the only way to observe this from here; the run loop + // never does it. + it('holds those writes in the transaction rather than autocommitting them', async () => { + const { kernelStore, kdb } = await makeStore(); + + kernelStore.startCrank(); + kernelStore.createCrankSavepoint('crank'); + kernelStore.createCrankSavepoint('delivery'); + kernelStore.rollbackCrank('delivery'); + kdb.kernelKVStore.set('terminated', 'yes'); + + kernelStore.rollbackCrank('crank'); + kernelStore.endCrank(); + + expect(kdb.kernelKVStore.get('terminated')).toBeUndefined(); + }); + + it('restores the GC action set consumed by a rolled-back crank', async () => { + const { kernelStore } = await makeStore(); + kernelStore.addGCActions(['v1 dropExport ko1']); + + kernelStore.startCrank(); + kernelStore.createCrankSavepoint('crank'); + kernelStore.createCrankSavepoint('delivery'); + // Consume the action the way `processGCActionSet` does. + kernelStore.setGCActions(new Set()); + + kernelStore.rollbackCrank('delivery'); + kernelStore.endCrank(); + + expect([...kernelStore.getGCActions()]).toStrictEqual([ + 'v1 dropExport ko1', + ]); + }); + + it('restores the reap queue consumed by a rolled-back crank', async () => { + const { kernelStore } = await makeStore(); + kernelStore.scheduleReap('v1'); + + kernelStore.startCrank(); + kernelStore.createCrankSavepoint('crank'); + kernelStore.createCrankSavepoint('delivery'); + expect(kernelStore.nextReapAction()).toBeDefined(); + + kernelStore.rollbackCrank('delivery'); + kernelStore.endCrank(); + + expect(kernelStore.nextReapAction()).toBeDefined(); + }); + + it('discards GC candidates accumulated by a rolled-back crank', async () => { + const { kernelStore } = await makeStore(); + + kernelStore.startCrank(); + kernelStore.createCrankSavepoint('crank'); + kernelStore.createCrankSavepoint('delivery'); + // Born at 1, so this drops it to 0 and leaves `kpid` in `maybeFreeKrefs`. + const kpid = kernelStore.initKernelPromise()[0]; + kernelStore.decrementRefCount(kpid, 'test'); + + kernelStore.rollbackCrank('delivery'); + kernelStore.endCrank(); + + kernelStore.startCrank(); + kernelStore.createCrankSavepoint('crank'); + expect(() => kernelStore.collectGarbage()).not.toThrow(); + kernelStore.endCrank(); + }); + it('refuses to roll back a savepoint that was never created', async () => { const { kernelStore } = await makeStore(); diff --git a/packages/kernel-test/src/garbage-collection.test.ts b/packages/kernel-test/src/garbage-collection.test.ts index 67055414f..fb20462b6 100644 --- a/packages/kernel-test/src/garbage-collection.test.ts +++ b/packages/kernel-test/src/garbage-collection.test.ts @@ -117,6 +117,29 @@ describe('Garbage Collection', () => { expect(parseReplyBody(useResult.body)).toBe(objectId); }); + /** + * Reap the importer vat until the kernel's bookkeeping catches up with the + * vat's own garbage collection, or the attempts run out. + * + * `bringOutYourDead` reports an import as dropped only once the engine has + * collected the vat's presence and run its finalizer, which `gcAndFinalize` + * does not guarantee on the first attempt. Each attempt needs its own reap — + * `nextReapAction` shifts the one scheduled entry off, so cranking again finds + * nothing to do — plus a message to wake the run loop and consume it. + * + * Gives up after five attempts; the caller's assertion reports the failure. + * + * @param settled - Whether the state under test has arrived yet. + */ + async function reapImporterUntil(settled: () => boolean): Promise { + const isImporter = (vatId: VatId): boolean => vatId === importerVatId; + for (let attempt = 0; attempt < 5 && !settled(); attempt += 1) { + kernel.reapVats(isImporter); + await kernel.queueMessage(importerKRef, 'noop', []); + await waitUntilQuiescent(500); + } + } + it('should trigger GC syscalls through bringOutYourDead', async () => { // Create an object in the exporter vat with a known ID const objectId = 'test-object'; @@ -161,14 +184,10 @@ describe('Garbage Collection', () => { await kernel.queueMessage(importerKRef, 'makeWeak', [objectId]); await waitUntilQuiescent(); - // Schedule reap to trigger bringOutYourDead on next crank - kernel.reapVats((vatId) => vatId === importerVatId); - - // Run 3 cranks to allow bringOutYourDead to be processed - for (let i = 0; i < 3; i++) { - await kernel.queueMessage(importerKRef, 'noop', []); - await waitUntilQuiescent(500); - } + // Reap until the importer reports the drop + await reapImporterUntil( + () => kernelStore.getObjectRefCount(createObjectRef).reachable === 1, + ); // Check reference counts after dropImports const afterWeakRefCounts = kernelStore.getObjectRefCount(createObjectRef); @@ -180,13 +199,10 @@ describe('Garbage Collection', () => { await kernel.queueMessage(importerKRef, 'forgetImport', []); await waitUntilQuiescent(); - // Schedule another reap - kernel.reapVats((vatId) => vatId === importerVatId); - - for (let i = 0; i < 3; i++) { - await kernel.queueMessage(importerKRef, 'noop', []); - await waitUntilQuiescent(500); - } + // Reap until the importer reports the retirement + await reapImporterUntil( + () => kernelStore.getObjectRefCount(createObjectRef).recognizable === 1, + ); // Check reference counts after retireImports const afterForgetRefCounts = kernelStore.getObjectRefCount(createObjectRef); @@ -242,10 +258,18 @@ describe('Garbage Collection', () => { * * @param vatId - The vat to reap. * @param rootKRef - That vat's root, to poke with cranks afterwards. + * @param settled - Whether the state under test has arrived yet. */ - async function reapAndSettle(vatId: VatId, rootKRef: KRef): Promise { - kernel.reapVats((id) => id === vatId); - for (let i = 0; i < 3; i++) { + async function reapAndSettle( + vatId: VatId, + rootKRef: KRef, + settled: () => boolean, + ): Promise { + // Reap until the vat's GC is visible rather than a fixed number of times: + // three was enough on an idle machine and not under a loaded one, which + // made this the last flake in the file. + for (let attempt = 0; attempt < 5 && !settled(); attempt += 1) { + kernel.reapVats((id) => id === vatId); await kernel.queueMessage(rootKRef, 'noop', []); await waitUntilQuiescent(500); } @@ -282,7 +306,11 @@ describe('Garbage Collection', () => { await kernel.queueMessage(importerKRef, 'makeWeak', [objectId]); await kernel.queueMessage(importerKRef, 'forgetImport', []); await waitUntilQuiescent(); - await reapAndSettle(importerVatId, importerKRef); + await reapAndSettle(importerVatId, importerKRef, () => + kernelStore + .getImporters(sharedKRef) + .every((vatId) => vatId !== importerVatId), + ); // The exporter must not have been told to drop it: the second importer // legitimately still holds it @@ -315,7 +343,11 @@ describe('Garbage Collection', () => { await kernel.queueMessage(secondImporterKRef, 'makeWeak', [objectId]); await kernel.queueMessage(secondImporterKRef, 'forgetImport', []); await waitUntilQuiescent(); - await reapAndSettle(secondImporterVatId, secondImporterKRef); + await reapAndSettle( + secondImporterVatId, + secondImporterKRef, + () => kernelStore.getImporters(sharedKRef).length === 0, + ); expect(kernelStore.getImporters(sharedKRef)).toStrictEqual([]); // Only the createObject result's stored value still names it diff --git a/packages/ocap-kernel/CHANGELOG.md b/packages/ocap-kernel/CHANGELOG.md index 1393fc21a..138e014eb 100644 --- a/packages/ocap-kernel/CHANGELOG.md +++ b/packages/ocap-kernel/CHANGELOG.md @@ -58,9 +58,13 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 - **BREAKING:** `getPinnedObjects` now names each pinned object once, however many pins it holds; `getPinCount` gives the number of pins ([#1020](https://github.com/MetaMask/ocap-kernel/pull/1020)) - **BREAKING:** `incrementRefCount` now throws on a kref the kernel has already deleted, rather than writing a resurrected row ([#1020](https://github.com/MetaMask/ocap-kernel/pull/1020)) - A missing object row read as `(0, 0)` and was written back as a live-looking object with no owner; a missing promise row read as `NaN`, which no decrement can bring to zero, so the promise could never be collected. `decrementRefCount` still tolerates a missing object row, since releasing a reference to something already gone is ordinary teardown +- **BREAKING:** `KernelStore`'s `beginOutOfCrank` and `endOutOfCrank` are replaced by `withStoreOutOfCrank(work)`, which takes the turn and gives it back however `work` ends ([#1021](https://github.com/Consensys-Incorporated/ocap-kernel/pull/1021)) + - A turn that was never given back left the run loop waiting on a promise nothing resolves: no failure, no log, no timeout. `work` must be synchronous: the type refuses a callback that returns a promise, and one that reaches it through inference anyway is thrown on rather than given the turn back mid-flight ### Fixed +- `Kernel.stop` records the last active time on a best-effort basis, logging rather than throwing when the store refuses the write ([#1021](https://github.com/Consensys-Incorporated/ocap-kernel/pull/1021)) + - A store that can no longer persist anything refuses every write, and this one sits ahead of stopping remote comms, terminating the vat workers, and closing the database. The timestamp is meaningless once the state it dates is unreachable; the worker processes are not - A message delivered to a kernel-owned kref with no registered service now rejects the caller with `ENDPOINT_UNREACHABLE` instead of throwing, which escaped the crank and killed the run loop — turning one unreachable reference into a dead kernel ([#1007](https://github.com/MetaMask/ocap-kernel/pull/1007)) - Reachable without any kernel bug: an anonymous kernel object hosts something that cannot outlive the process, such as an accepted socket connection, so a vat holding one across a restart or a message to one still queued from the previous incarnation lands here. That surviving reference is exactly what stops the init sweep deleting the object, so its `kernel` owner survives with it - Matches what `KernelRouter` already does for a delivery whose endpoint has vanished. A message sent with no result promise has nobody to report to, so it is logged instead @@ -70,6 +74,22 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 - 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 +- Keep a crank's store work inside one transaction, so terminating the vat and collecting garbage after an aborted delivery are committed with the crank instead of autocommitting a statement at a time ([#1021](https://github.com/Consensys-Incorporated/ocap-kernel/pull/1021)) + - Buffered vat outputs are flushed after that work rather than before it, so a delivery rollback can no longer discard the state an answer was computed from. A release or commit that fails while ending the crank still aborts it after the answer has gone out. Termination still settles the dying vat's own promises immediately +- `rollbackCrank` now also reverts the state a database rollback cannot reach, whether or not the rollback itself succeeded: cached stored values are re-read, and the garbage-collection candidate set goes back to what the savepoint held ([#1021](https://github.com/Consensys-Incorporated/ocap-kernel/pull/1021)) + - Otherwise a cache kept the abandoned crank's value and the next write persisted it, a GC action taken out of the set for an aborted delivery was lost rather than retried, and a later `collectGarbage` killed the run loop on a promise the rollback had deleted + - Restored rather than emptied, because only `collectGarbage` empties that set: a candidate produced outside a crank — a peer restart abandoning a remote's exports is the real path — is still owed a collection, and clearing it leaked those objects with nothing left to notice, the reference count audit included +- Cleanup after a dead crank no longer replaces the error that killed the run loop: a failing `endCrank` reports it as `cause`, and neither `endCrank` nor `rollbackCrank` retries a savepoint that a failed rollback or release has already discarded ([#1021](https://github.com/Consensys-Incorporated/ocap-kernel/pull/1021)) +- A failing savepoint rollback in `RemoteHandle.handleRemoteMessage` and `RemoteManager`'s incarnation change is logged rather than thrown, so the failure it was cleaning up after is what reaches the caller ([#1021](https://github.com/Consensys-Incorporated/ocap-kernel/pull/1021)) +- A peer restart now rejects the promises the restarting peer was made decider of during the crank it waited out, not only those it held beforehand ([#1021](https://github.com/Consensys-Incorporated/ocap-kernel/pull/1021)) + - Waiting for the store spans a whole crank, and a promise created in that crank was left with no decider and nothing to settle it, so the vat that sent the message waited forever +- Keep a crank and a savepoint taken through `KernelStore.createSavepoint` from overlapping ([#1021](https://github.com/Consensys-Incorporated/ocap-kernel/pull/1021)) + - Those savepoints bypass `ctx.savepoints` and so are invisible to `createCrankSavepoint`'s ordinal naming. One open across a crank left `releaseAllSavepoints` releasing `t0` into it rather than to a commit, so the caller's later rollback discarded the whole crank; one opened inside a crank was cancelled by a delivery rollback it had nothing to do with, or made durable by a release beneath it, after the peer had already been told the message was committed + - Both directions are now refused, and the two production callers — `RemoteHandle.handleRemoteMessage` and `RemoteManager`'s incarnation change — take their turn through the new `beginOutOfCrank`/`endOutOfCrank`, which the run loop consults via `outOfCrankWorkPending` before starting each crank. Work between the two must be synchronous + - `handleRemoteMessage` now decodes an incoming `redeemURL` before opening its savepoint instead of awaiting inside it; the decode writes nothing, so the message stays atomic + - Consequence: an inbound remote message or a peer's handshake arriving mid-crank waits for that crank to end, so their latency is now bounded by the slowest crank rather than being independent of it. A crank that sends to a remote can be slow. The alternative is to route inbound messages through the run queue as SwingSet's comms vat does, which is a larger change than this one +- The reference count audit runs after the crank is committed rather than inside it, so a violation kills the run loop instead of rolling back a delivery whose caller the crank buffer flush had already answered ([#1021](https://github.com/Consensys-Incorporated/ocap-kernel/pull/1021)) + - It still runs after the flush, which is what kept buffered items from reading as leaks - 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)) diff --git a/packages/ocap-kernel/src/Kernel.test.ts b/packages/ocap-kernel/src/Kernel.test.ts index d85cb0223..6cf889206 100644 --- a/packages/ocap-kernel/src/Kernel.test.ts +++ b/packages/ocap-kernel/src/Kernel.test.ts @@ -787,6 +787,27 @@ describe('Kernel', () => { expect(timestamp).toBeGreaterThanOrEqual(before); expect(timestamp).toBeLessThanOrEqual(after); }); + + it('releases the vat workers even when the store refuses the timestamp', async () => { + const workerTerminateAllMock = vi + .spyOn(mockPlatformServices, 'terminateAll') + .mockResolvedValue(undefined); + const kernel = await Kernel.make( + mockPlatformServices, + mockKernelDatabase, + ); + // What a driver holding a transaction it could not abort does to every + // write, teardown's included. + vi.spyOn(mockKernelDatabase.kernelKVStore, 'set').mockImplementation( + () => { + throw new Error('refusing further writes on this connection'); + }, + ); + + await kernel.stop(); + + expect(workerTerminateAllMock).toHaveBeenCalledOnce(); + }); }); describe('restartVat()', () => { diff --git a/packages/ocap-kernel/src/Kernel.ts b/packages/ocap-kernel/src/Kernel.ts index c041d060b..d44467b88 100644 --- a/packages/ocap-kernel/src/Kernel.ts +++ b/packages/ocap-kernel/src/Kernel.ts @@ -862,7 +862,15 @@ export class Kernel { */ async stop(): Promise { await this.#kernelQueue.waitForCrank(); - this.#kernelStore.recordLastActiveTime(); + try { + this.#kernelStore.recordLastActiveTime(); + } catch (error) { + // A store that can no longer persist anything refuses this write, and + // everything below it releases something: remote comms, the vat workers, + // the database handle. A timestamp is not worth leaking those over, and + // is meaningless anyway once the state it dates is unreachable. + this.#logger.error('could not record last active time', error); + } await this.#platformServices.stopRemoteComms(); this.#remoteManager.cleanup(); await this.#platformServices.terminateAll(); diff --git a/packages/ocap-kernel/src/KernelQueue.audit-ordering.test.ts b/packages/ocap-kernel/src/KernelQueue.audit-ordering.test.ts new file mode 100644 index 000000000..3cd87fbf2 --- /dev/null +++ b/packages/ocap-kernel/src/KernelQueue.audit-ordering.test.ts @@ -0,0 +1,99 @@ +import type { CapData } from '@endo/marshal'; +import { describe, it, expect, vi, beforeEach } from 'vitest'; + +import { KernelQueue } from './KernelQueue.ts'; +import type { KernelStore } from './store/index.ts'; +import type { CrankResult, KRef, RunQueueItem } from './types.ts'; + +vi.mock('./garbage-collection/garbage-collection.ts', () => ({ + processGCActionSet: vi.fn().mockReturnValue(null), +})); + +/** + * `#processCrankResult` flushes the crank buffer last of the crank's own work, + * for the reason the comment there gives. + * + * `assertRefCountsIfAuditing` has to run after that flush too, because a + * buffered item's references were counted at enqueue time and so read as a leak + * if the audit runs mid-flush. Both orderings were individually justified and + * they contradicted each other: the audit is fallible, it ran after the answers + * had gone out, and a crank that throws is rolled back by the run loop's catch. + * + * The audit now runs after `endCrank` instead, outside anything a rollback can + * reach, so a violation kills the run loop rather than retracting a delivery the + * caller was already answered from. + */ +describe('a reference count audit that fails after the flush', () => { + let kernelStore: KernelStore; + let kernelQueue: KernelQueue; + let resolveSubscription: (value: CapData) => void; + + const AUDIT_FAILED = 'reference count invariant violated'; + + beforeEach(() => { + resolveSubscription = vi.fn(); + + kernelStore = { + startCrank: vi.fn(), + endCrank: vi.fn(), + beginOutOfCrank: vi.fn().mockResolvedValue(undefined), + endOutOfCrank: vi.fn(), + outOfCrankWorkPending: vi.fn().mockReturnValue(undefined), + createCrankSavepoint: vi.fn(), + rollbackCrank: vi.fn(), + nextTerminatedVatCleanup: vi.fn(), + nextReapAction: vi.fn().mockReturnValue(null), + runQueueLength: vi.fn().mockReturnValue(0), + dequeueRun: vi.fn(), + enqueueRun: vi.fn(), + incrementRefCount: vi.fn(), + collectGarbage: vi.fn(), + // The buffered notify a successful crank flushes. + flushCrankBuffer: vi + .fn() + .mockReturnValue([{ type: 'notify', endpointId: 'v1', kpid: 'kp1' }]), + getKernelPromise: vi.fn().mockReturnValue({ + state: 'fulfilled', + value: { body: '{}', slots: [] }, + }), + // The audit the `auditRefCounts` option turns on, finding drift. + assertRefCountsIfAuditing: vi.fn(() => { + throw new Error(AUDIT_FAILED); + }), + } as unknown as KernelStore; + + kernelQueue = new KernelQueue( + kernelStore, + vi.fn().mockResolvedValue(undefined), + ); + + // An external caller waiting on `kp1`, as `enqueueMessage` leaves one. + kernelQueue.subscriptions.set('kp1' as KRef, { + resolve: resolveSubscription, + reject: vi.fn(), + }); + }); + + it('keeps the delivery it already answered the caller from', async () => { + const item: RunQueueItem = { + type: 'notify', + endpointId: 'v1', + kpid: 'kp1' as KRef, + } as RunQueueItem; + vi.mocked(kernelStore.runQueueLength).mockReturnValueOnce(1); + vi.mocked(kernelStore.dequeueRun).mockReturnValueOnce(item); + + const deliver = vi + .fn<(queueItem: RunQueueItem) => Promise>() + .mockResolvedValue(undefined); + + await expect(kernelQueue.run(deliver)).rejects.toThrow(AUDIT_FAILED); + + // The flush invoked the subscription, so the caller has its answer... + expect(resolveSubscription).toHaveBeenCalled(); + // ...and the audit's failure takes the run loop down without retracting the + // delivery that answer was computed from. + expect(kernelStore.rollbackCrank).not.toHaveBeenCalledWith('delivery'); + expect(kernelStore.endCrank).toHaveBeenCalled(); + }); +}); diff --git a/packages/ocap-kernel/src/KernelQueue.test.ts b/packages/ocap-kernel/src/KernelQueue.test.ts index 4ff8a8e78..f66e79b05 100644 --- a/packages/ocap-kernel/src/KernelQueue.test.ts +++ b/packages/ocap-kernel/src/KernelQueue.test.ts @@ -25,6 +25,24 @@ vi.mock('@endo/promise-kit', () => ({ */ const STOP_RUN_LOOP = 'test: stop run loop'; +/** + * Collect an error and every error reachable through its `cause` chain, so that + * a test can assert a root cause survived without pinning how its reporter + * chose to wrap it. + * + * @param error - The error to walk. + * @returns The chain, outermost first. + */ +const causeChain = (error: unknown): Error[] => { + const chain: Error[] = []; + let current = error; + while (current instanceof Error) { + chain.push(current); + current = current.cause; + } + return chain; +}; + describe('KernelQueue', () => { let kernelStore: KernelStore; let kernelQueue: KernelQueue; @@ -56,6 +74,9 @@ describe('KernelQueue', () => { getGCActions: vi.fn().mockReturnValue([]), startCrank: vi.fn(), endCrank: vi.fn(), + beginOutOfCrank: vi.fn().mockResolvedValue(undefined), + endOutOfCrank: vi.fn(), + outOfCrankWorkPending: vi.fn().mockReturnValue(undefined), createCrankSavepoint: vi.fn(), rollbackCrank: vi.fn(), waitForCrank: vi.fn(), @@ -92,6 +113,23 @@ describe('KernelQueue', () => { }; }; + /** + * Stop the run loop by failing the *next* crank's start, so that the crank + * under test runs to completion. Throwing from one of a crank's own store calls + * cuts it short, which hides everything the crank does after that call. + */ + const stopAfterOneCrank = (): void => { + let cranks = 0; + (kernelStore.startCrank as unknown as MockInstance).mockImplementation( + () => { + cranks += 1; + if (cranks > 1) { + throw new Error(STOP_RUN_LOOP); + } + }, + ); + }; + /** * Run a single crank whose delivery blows up, killing the run loop. * @@ -128,7 +166,8 @@ describe('KernelQueue', () => { const deliver = vi.fn().mockRejectedValue(deliverError); await expect(kernelQueue.run(deliver)).rejects.toBe(deliverError); expect(kernelStore.startCrank).toHaveBeenCalled(); - expect(kernelStore.createCrankSavepoint).toHaveBeenCalledWith('start'); + expect(kernelStore.createCrankSavepoint).toHaveBeenCalledWith('crank'); + expect(kernelStore.createCrankSavepoint).toHaveBeenCalledWith('delivery'); expect(processGCActionSetSpy).toHaveBeenCalled(); expect(kernelStore.nextReapAction).toHaveBeenCalled(); expect(kernelStore.nextTerminatedVatCleanup).toHaveBeenCalled(); @@ -156,9 +195,9 @@ describe('KernelQueue', () => { }); await expect(kernelQueue.run(deliver)).rejects.toThrow(STOP_RUN_LOOP); expect(kernelStore.startCrank).toHaveBeenCalled(); - expect(kernelStore.createCrankSavepoint).toHaveBeenCalledWith('start'); + expect(kernelStore.createCrankSavepoint).toHaveBeenCalledWith('delivery'); expect(deliver).toHaveBeenCalledWith(mockItem); - expect(kernelStore.rollbackCrank).toHaveBeenCalledWith('start'); + expect(kernelStore.rollbackCrank).toHaveBeenCalledWith('delivery'); expect(kernelStore.collectGarbage).toHaveBeenCalled(); expect(kernelStore.endCrank).toHaveBeenCalled(); }); @@ -195,6 +234,162 @@ describe('KernelQueue', () => { expect(kernelStore.collectGarbage).toHaveBeenCalled(); expect(kernelStore.endCrank).toHaveBeenCalled(); }); + + it('answers no caller from a crank it then rolls back', async () => { + const mockItem: RunQueueItem = { + type: 'send', + target: 'ko123', + message: { result: 'kp1' } as KernelMessage, + }; + (kernelStore.runQueueLength as unknown as MockInstance) + .mockReturnValueOnce(1) + .mockReturnValue(0); + (kernelStore.dequeueRun as unknown as MockInstance).mockReturnValueOnce( + mockItem, + ); + + // A caller is awaiting this message's result. + const resolve = vi.fn(); + const reject = vi.fn(); + kernelQueue.subscriptions.set('kp1', { resolve, reject }); + + // The delivery succeeds and its result is there for the flush to hand over... + ( + kernelStore.flushCrankBuffer as unknown as MockInstance + ).mockReturnValueOnce([ + { type: 'notify', endpointId: 'v1', kpid: 'kp1' }, + ]); + (kernelStore.getKernelPromise as unknown as MockInstance).mockReturnValue( + { + state: 'fulfilled', + value: { body: '"answer"', slots: [] }, + }, + ); + + // ...but the crank still has fallible work left, and it dies there. + const terminationError = new Error('vat worker already gone'); + (terminateVat as unknown as MockInstance).mockRejectedValueOnce( + terminationError, + ); + const deliver = vi.fn().mockResolvedValue({ + terminate: { vatId: 'v1', info: { body: '"exit"', slots: [] } }, + }); + + await expect(kernelQueue.run(deliver)).rejects.toBe(terminationError); + + expect(kernelStore.rollbackCrank).toHaveBeenCalledWith('delivery'); + expect(resolve).not.toHaveBeenCalled(); + expect(reject).toHaveBeenCalledWith( + expect.objectContaining({ cause: terminationError }), + ); + }); + + it('answers no caller until every buffered item is enqueued', async () => { + const mockItem: RunQueueItem = { + type: 'send', + target: 'ko123', + message: { result: 'kp1' } as KernelMessage, + }; + (kernelStore.runQueueLength as unknown as MockInstance) + .mockReturnValueOnce(1) + .mockReturnValue(0); + (kernelStore.dequeueRun as unknown as MockInstance).mockReturnValueOnce( + mockItem, + ); + + const resolve = vi.fn(); + const reject = vi.fn(); + kernelQueue.subscriptions.set('kp1', { resolve, reject }); + + // Two resolutions to hand over, the caller's first. + ( + kernelStore.flushCrankBuffer as unknown as MockInstance + ).mockReturnValueOnce([ + { type: 'notify', endpointId: 'v1', kpid: 'kp1' }, + { type: 'notify', endpointId: 'v2', kpid: 'kp2' }, + ]); + (kernelStore.getKernelPromise as unknown as MockInstance).mockReturnValue( + { state: 'fulfilled', value: { body: '"answer"', slots: [] } }, + ); + + // The second enqueue is the write that fails. + const enqueueError = new Error('database is gone'); + let enqueued = 0; + (kernelStore.enqueueRun as unknown as MockInstance).mockImplementation( + () => { + enqueued += 1; + if (enqueued > 1) { + throw enqueueError; + } + }, + ); + + const deliver = vi.fn().mockResolvedValue(undefined); + await expect(kernelQueue.run(deliver)).rejects.toBe(enqueueError); + + expect(kernelStore.rollbackCrank).toHaveBeenCalledWith('delivery'); + expect(resolve).not.toHaveBeenCalled(); + }); + + it.each([ + { + label: 'an abort', + crankResult: { abort: true }, + storeOrder: ['rollbackCrank', 'collectGarbage'], + }, + { + label: 'an abort that also terminates', + crankResult: { + abort: true, + terminate: { vatId: 'v1', info: { body: '"exit"', slots: [] } }, + }, + storeOrder: ['rollbackCrank', 'terminateVat', 'collectGarbage'], + }, + ])( + 'keeps the crank transactional after rolling back $label', + async ({ crankResult, storeOrder }) => { + const mockItem: RunQueueItem = { + type: 'send', + target: 'ko123', + message: { result: 'kp99' } as KernelMessage, + }; + (kernelStore.runQueueLength as unknown as MockInstance) + .mockReturnValueOnce(1) + .mockReturnValue(0); + (kernelStore.dequeueRun as unknown as MockInstance).mockReturnValueOnce( + mockItem, + ); + + const storeCalls: string[] = []; + ( + kernelStore.rollbackCrank as unknown as MockInstance + ).mockImplementation(() => { + storeCalls.push('rollbackCrank'); + }); + (terminateVat as unknown as MockInstance).mockImplementation( + async () => { + storeCalls.push('terminateVat'); + }, + ); + ( + kernelStore.collectGarbage as unknown as MockInstance + ).mockImplementation(() => { + storeCalls.push('collectGarbage'); + throw new Error(STOP_RUN_LOOP); + }); + + const deliver = vi.fn().mockResolvedValue(crankResult); + await expect(kernelQueue.run(deliver)).rejects.toThrow(STOP_RUN_LOOP); + + expect(storeCalls).toStrictEqual(storeOrder); + expect( + ( + kernelStore.createCrankSavepoint as unknown as MockInstance + ).mock.calls.flat(), + ).toStrictEqual(['crank', 'delivery']); + expect(kernelStore.rollbackCrank).not.toHaveBeenCalledWith('crank'); + }, + ); }); describe('getRunLoopStatus', () => { @@ -287,7 +482,7 @@ describe('KernelQueue', () => { 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'); + expect(kernelStore.rollbackCrank).toHaveBeenCalledWith('delivery'); }); it('does not roll back when the savepoint was never created', async () => { @@ -358,6 +553,34 @@ describe('KernelQueue', () => { }); }); + it('reports both failures when endCrank 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, + }); + (kernelStore.endCrank as unknown as MockInstance).mockImplementation( + () => { + throw new Error('database is gone'); + }, + ); + const crankError = new Error('crank exploded'); + const deliver = vi.fn().mockRejectedValue(crankError); + + const failure = await kernelQueue + .run(deliver) + .catch((error: unknown) => error); + + expect(causeChain(failure)).toContain(crankError); + expect(kernelQueue.getRunLoopStatus()).toMatchObject({ + state: 'failed', + 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, @@ -843,7 +1066,7 @@ describe('KernelQueue', () => { throw new Error(STOP_RUN_LOOP); }); await expect(kernelQueue.run(deliver)).rejects.toThrow(STOP_RUN_LOOP); - expect(kernelStore.rollbackCrank).toHaveBeenCalledWith('start'); + expect(kernelStore.rollbackCrank).toHaveBeenCalledWith('delivery'); expect(rejectSpy).toHaveBeenCalledWith(terminateInfo); expect(kernelQueue.subscriptions.has('kp99')).toBe(false); }); @@ -879,7 +1102,7 @@ describe('KernelQueue', () => { throw new Error(STOP_RUN_LOOP); }); await expect(kernelQueue.run(deliver)).rejects.toThrow(STOP_RUN_LOOP); - expect(kernelStore.rollbackCrank).toHaveBeenCalledWith('start'); + expect(kernelStore.rollbackCrank).toHaveBeenCalledWith('delivery'); expect(rejectedAfterAbort).toBe(false); expect(resolveSpy).not.toHaveBeenCalled(); expect(subscribedAfterAbort).toBe(true); @@ -919,6 +1142,102 @@ describe('KernelQueue', () => { }); }); + describe('out-of-crank work', () => { + it('waits for a caller holding the store before starting a crank', async () => { + let releaseHolder!: () => void; + const held = new Promise((resolve) => { + releaseHolder = resolve; + }); + let cranksWhileHeld = 0; + // Return values rather than an implementation: the contract is that + // nothing waiting is `undefined` and not a resolved promise, and an + // `async` mock cannot express that. + (kernelStore.outOfCrankWorkPending as unknown as MockInstance) + .mockReturnValueOnce(held) + .mockReturnValue(undefined); + (kernelStore.startCrank as unknown as MockInstance).mockImplementation( + () => { + cranksWhileHeld += 1; + throw new Error(STOP_RUN_LOOP); + }, + ); + + const runLoop = kernelQueue.run(vi.fn()); + await Promise.resolve(); + expect(cranksWhileHeld).toBe(0); + + releaseHolder(); + await expect(runLoop).rejects.toThrow(STOP_RUN_LOOP); + expect(cranksWhileHeld).toBe(1); + }); + + it('starts the crank without yielding when nothing is waiting', async () => { + stopAfterOneCrank(); + (kernelStore.runQueueLength as unknown as MockInstance).mockReturnValue( + 0, + ); + + await expect(kernelQueue.run(vi.fn())).rejects.toThrow(STOP_RUN_LOOP); + expect(kernelStore.outOfCrankWorkPending).toHaveBeenCalled(); + }); + + // A caller registers synchronously, so one can arrive in a microtask queued + // ahead of this loop's resumption. Checking once would leave `startCrank` + // refusing, which kills the kernel outright. + it('keeps yielding while callers keep arriving', async () => { + const pending = + kernelStore.outOfCrankWorkPending as unknown as MockInstance; + // Two callers in a row, then nothing. `undefined` rather than a resolved + // promise is the contract; an `async` mock would loop here forever. + pending + .mockReturnValueOnce(Promise.resolve()) + .mockReturnValueOnce(Promise.resolve()) + .mockReturnValue(undefined); + let checksBeforeCrank = -1; + (kernelStore.startCrank as unknown as MockInstance).mockImplementation( + () => { + checksBeforeCrank = pending.mock.calls.length; + throw new Error(STOP_RUN_LOOP); + }, + ); + + await expect(kernelQueue.run(vi.fn())).rejects.toThrow(STOP_RUN_LOOP); + + // Both gates awaited, and the check that found nothing waiting is the one + // immediately before the crank starts. + expect(checksBeforeCrank).toBe(3); + }); + }); + + describe('reference count audit', () => { + it('audits a crank that delivered something', async () => { + stopAfterOneCrank(); + ( + kernelStore.runQueueLength as unknown as MockInstance + ).mockReturnValueOnce(1); + (kernelStore.dequeueRun as unknown as MockInstance).mockReturnValueOnce({ + type: 'send', + target: 'ko123', + message: {} as KernelMessage, + }); + + await expect( + kernelQueue.run(vi.fn().mockResolvedValue(undefined)), + ).rejects.toThrow(STOP_RUN_LOOP); + expect(kernelStore.assertRefCountsIfAuditing).toHaveBeenCalled(); + }); + + it('leaves an idle crank alone', async () => { + stopAfterOneCrank(); + (kernelStore.runQueueLength as unknown as MockInstance).mockReturnValue( + 0, + ); + + await expect(kernelQueue.run(vi.fn())).rejects.toThrow(STOP_RUN_LOOP); + expect(kernelStore.assertRefCountsIfAuditing).not.toHaveBeenCalled(); + }); + }); + describe('invokeKernelSubscription', () => { it('calls reject for rejected promises', async () => { const rejectSpy = vi.fn(); @@ -949,11 +1268,7 @@ describe('KernelQueue', () => { mockItem, ); const deliver = vi.fn().mockResolvedValue(undefined); - ( - kernelStore.collectGarbage as unknown as MockInstance - ).mockImplementation(() => { - throw new Error(STOP_RUN_LOOP); - }); + stopAfterOneCrank(); await expect(kernelQueue.run(deliver)).rejects.toThrow(STOP_RUN_LOOP); expect(rejectSpy).toHaveBeenCalledWith(rejectedValue); expect(resolveSpy).not.toHaveBeenCalled(); @@ -988,11 +1303,7 @@ describe('KernelQueue', () => { mockItem, ); const deliver = vi.fn().mockResolvedValue(undefined); - ( - kernelStore.collectGarbage as unknown as MockInstance - ).mockImplementation(() => { - throw new Error(STOP_RUN_LOOP); - }); + stopAfterOneCrank(); await expect(kernelQueue.run(deliver)).rejects.toThrow(STOP_RUN_LOOP); expect(resolveSpy).toHaveBeenCalledWith(fulfilledValue); expect(rejectSpy).not.toHaveBeenCalled(); diff --git a/packages/ocap-kernel/src/KernelQueue.ts b/packages/ocap-kernel/src/KernelQueue.ts index b4280ec02..8154ae015 100644 --- a/packages/ocap-kernel/src/KernelQueue.ts +++ b/packages/ocap-kernel/src/KernelQueue.ts @@ -56,14 +56,8 @@ export class KernelQueue { /** * 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. + * Attempted, not necessarily succeeded: it is forgotten either way, so asking + * twice could only report "no such savepoint" over the real error. */ #crankRollbackAttempted: boolean = false; @@ -126,20 +120,47 @@ export class KernelQueue { ): Promise { for (;;) { let wakeUpPromise: Promise | undefined; + // Boxed, so a crank that threw `undefined` stays distinguishable from one + // that did not throw. + let crankFailure: { error: unknown } | undefined; + let delivered = false; + + // Work that has to be its own transaction — an inbound remote message, a + // peer restart — can only run while no crank is open, and this loop is + // synchronous from `endCrank` to here. Without this yield its only gap is + // the sleep below, so such work would wait for the queue to drain or, as + // it used to, nest a savepoint inside a crank whose rollback would + // discard it. Undefined on the usual path, which keeps that path + // synchronous. + // Re-checked rather than awaited once: a caller registers synchronously, + // so one arriving in a microtask queued ahead of this loop's resumption + // would otherwise meet `startCrank`'s refusal and kill the kernel over + // ordinary concurrent remote traffic. The last check and `startCrank` + // have no await between them, which is what makes the handoff airtight. + let outOfCrankWork = this.#kernelStore.outOfCrankWorkPending(); + while (outOfCrankWork) { + await outOfCrankWork; + outOfCrankWork = this.#kernelStore.outOfCrankWorkPending(); + } this.#kernelStore.startCrank(); this.#crankRollbackAttempted = false; try { - this.#kernelStore.createCrankSavepoint('start'); + // Two savepoints, because rolling back the outermost one discards the + // enclosing transaction (see `rollbackSavepoint`) and an aborted crank + // still has writes to make. Only `delivery` is ever rolled back; + // releasing `crank` in `endCrank` is this crank's one commit point. + this.#kernelStore.createCrankSavepoint('crank'); + this.#kernelStore.createCrankSavepoint('delivery'); // 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. + // this, `endCrank`'s release commits the half-finished crank: the + // dequeued item is gone for good, refcount increments stick, and + // resolved promises keep their unflushed notifies. try { const queueItem = this.#getNextRunQueueItem(); if (queueItem) { + delivered = true; this.#kernelStore.nextTerminatedVatCleanup(); const crankResult = await deliver(queueItem); await this.#processCrankResult(crankResult, queueItem); @@ -153,15 +174,12 @@ export class KernelQueue { 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. + // An aborted crank already asked; asking again could only throw "no + // such savepoint" over the real error. if (!this.#crankRollbackAttempted) { try { - this.#kernelStore.rollbackCrank('start'); + this.#kernelStore.rollbackCrank('delivery'); } 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 }, @@ -170,12 +188,50 @@ export class KernelQueue { } throw error; } + } catch (error) { + crankFailure = { error }; + throw error; } finally { - this.#kernelStore.endCrank(); + this.#endCrank(crankFailure); if (wakeUpPromise) { await wakeUpPromise; } } + + if (delivered) { + // After the crank has been committed, not inside it. The audit has to + // run after the flush, because a buffered item's references were + // counted when it was enqueued and so read as a leak mid-flush — but + // the flush is also what answers an external caller of + // `enqueueMessage`. Auditing while the delivery savepoint still existed + // put those two together: a violation would roll back the state the + // caller had already been answered from. Out here a violation still + // kills the run loop, which is what an audit failure means, without + // pretending to undo a crank that has landed. + this.#kernelStore.assertRefCountsIfAuditing(); + } + } + } + + /** + * End the crank without losing the error that is already unwinding. Now that + * the delivery rollback spares `crank`, `endCrank` is a real RELEASE and + * COMMIT on the dying path where it used to be a no-op. + * + * @param crankFailure - The error already in flight, if the crank threw. + * @param crankFailure.error - That error. + */ + #endCrank(crankFailure?: { error: unknown }): void { + try { + this.#kernelStore.endCrank(); + } catch (endCrankError) { + if (!crankFailure) { + throw endCrankError; + } + throw new Error( + `Run loop died and its crank could not be ended: ${String(endCrankError)}`, + { cause: crankFailure.error }, + ); } } @@ -304,13 +360,9 @@ export class KernelQueue { // For active vats, this allows the message to be retried in a future crank. // For terminated vats, the message will just go splat. try { - this.#kernelStore.rollbackCrank('start'); + this.#kernelStore.rollbackCrank('delivery'); } 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. + // Set even when the rollback threw: the savepoint is gone either way. this.#crankRollbackAttempted = true; } // Discard kernel subscriptions that were queued for invocation @@ -333,18 +385,24 @@ export class KernelQueue { // TODO: Currently all errors terminate the vat, but instead we could // restart it and terminate the vat only after a certain number of failed // retries. This is probably where we should implement the vat restart logic. - } else { - // Upon on successful crank completion, enqueue buffered vat outputs for delivery. - this.#flushCrankBuffer(); } - // Vat termination during delivery is triggered by an illegal syscall - // or by syscall.exit(). + // This kills the worker, so its writes must outlive the rollback above: a + // store that still believed the vat was alive would relaunch it. They are + // still inside the crank's transaction, so a release or commit that fails + // in `endCrank` discards them along with the rest of it. if (crankResult?.terminate) { const { vatId, info } = crankResult.terminate; await this.#terminateVat(vatId, info); } this.#kernelStore.collectGarbage(); - this.#kernelStore.assertRefCountsIfAuditing(); + if (!crankResult?.abort) { + // After the fallible work above, not before it: the flush settles the + // promise `enqueueMessage` gave an external caller, so a delivery + // rollback would otherwise discard the state that answer was computed + // from. It closes that window only — a release or commit that fails in + // `endCrank` still aborts the crank after the answer has gone out. + this.#flushCrankBuffer(); + } } /** @@ -371,21 +429,23 @@ export class KernelQueue { */ #flushCrankBuffer(): void { const items = this.#kernelStore.flushCrankBuffer(); + const resolved: KRef[] = []; for (const item of items) { this.#enqueueRun(item); if (item.type === 'notify') { - // Invoke kernel subscription callback if any, reading resolution - // data from the (now committed) promise state - this.#invokeKernelSubscription(item.kpid); + resolved.push(item.kpid); } } + // Plus promises with no vat subscriber to notify, which the kernel is + // nonetheless waiting on (e.g. from `enqueueMessage`). + resolved.push(...this.#resolvedWithKernelSubscription); + this.#resolvedWithKernelSubscription = []; - // Invoke kernel subscriptions for promises resolved during this crank - // that don't have kernel-level subscribers (e.g., promises from enqueueMessage) - for (const kpid of this.#resolvedWithKernelSubscription) { + // Callbacks only once every `#enqueueRun` is done: one that threw partway + // would roll the crank back underneath answers already given. + for (const kpid of resolved) { this.#invokeKernelSubscription(kpid); } - this.#resolvedWithKernelSubscription = []; } /** diff --git a/packages/ocap-kernel/src/remotes/kernel/RemoteHandle.test.ts b/packages/ocap-kernel/src/remotes/kernel/RemoteHandle.test.ts index 4f53572c0..e807b17e9 100644 --- a/packages/ocap-kernel/src/remotes/kernel/RemoteHandle.test.ts +++ b/packages/ocap-kernel/src/remotes/kernel/RemoteHandle.test.ts @@ -5,6 +5,7 @@ import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest'; import { RemoteHandle } from './RemoteHandle.ts'; import { createMockRemotesFactory } from '../../../test/remotes-mocks.ts'; +import { withFailingSavepointRelease } from '../../../test/savepoint-stack.ts'; import type { KernelQueue } from '../../KernelQueue.ts'; import type { KernelStore } from '../../store/index.ts'; import { parseRef } from '../../store/utils/parse-ref.ts'; @@ -220,6 +221,77 @@ describe('RemoteHandle', () => { }); }); + it('reports the release failure rather than a missing savepoint', async () => { + const failing = withFailingSavepointRelease(mockKernelStore); + const { releaseFailure, rollbackSavepoint } = failing; + mockKernelStore = failing.kernelStore; + const remote = makeRemote(); + + const delivery = JSON.stringify({ + seq: 1, + method: 'deliver', + params: ['bringOutYourDead'], + }); + + await expect(remote.handleRemoteMessage(delivery)).rejects.toBe( + releaseFailure, + ); + // Still attempted: abandoning the rollback is not a way to pass this. + expect(rollbackSavepoint).toHaveBeenCalledWith('receive_r0_1'); + // And the turn is given back even on the way out. A leaked waiter leaves + // the gate unresolved, and the run loop parks on it for good. + expect(mockKernelStore.outOfCrankWorkPending()).toBeUndefined(); + expect(() => mockKernelStore.startCrank()).not.toThrow(); + }); + + it('gives the run loop its turn back after handling a message', async () => { + const remote = makeRemote(); + const delivery = JSON.stringify({ + seq: 1, + method: 'deliver', + params: ['bringOutYourDead'], + }); + + await remote.handleRemoteMessage(delivery); + + expect(mockKernelStore.outOfCrankWorkPending()).toBeUndefined(); + expect(() => mockKernelStore.startCrank()).not.toThrow(); + }); + + // The savepoint window has to stay synchronous: an await inside it parks the + // run loop for the duration and lets a crank interleave with the savepoint. + it('decodes an incoming redeemURL before opening its savepoint', async () => { + const replyKRef = mockKernelStore.initKernelObject('kernel'); + // Wrapped rather than spied: the store is hardened. + const createSavepoint = vi.fn(mockKernelStore.createSavepoint); + mockKernelStore = { ...mockKernelStore, createSavepoint } as KernelStore; + const remote = makeRemote(); + mockKernelStore.initEndpoint(remote.remoteId); + + let finishDecoding!: (kref: string) => void; + vi.spyOn(mockRemoteComms, 'redeemLocalOcapURL').mockReturnValue( + new Promise((resolve) => { + finishDecoding = resolve; + }), + ); + + const handled = remote.handleRemoteMessage( + JSON.stringify({ + seq: 1, + method: 'redeemURL', + params: ['as if it was a URL', 'replyKey'], + }), + ); + await Promise.resolve(); + + expect(createSavepoint).not.toHaveBeenCalled(); + + finishDecoding(replyKRef); + await handled; + + expect(createSavepoint).toHaveBeenCalledWith('receive_r0_1'); + }); + // 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. diff --git a/packages/ocap-kernel/src/remotes/kernel/RemoteHandle.ts b/packages/ocap-kernel/src/remotes/kernel/RemoteHandle.ts index d92359b5c..95d616ee9 100644 --- a/packages/ocap-kernel/src/remotes/kernel/RemoteHandle.ts +++ b/packages/ocap-kernel/src/remotes/kernel/RemoteHandle.ts @@ -83,6 +83,11 @@ type DeferredRedeemURLRequest = | { type: 'redeemURL'; replyKey: string; ref: ERef } | { type: 'redeemURL'; replyKey: string; error: string }; +/** What a redeemURL's URL decoded to, before anything is written down. */ +type RedeemURLResolution = + | { replyKey: string; kref: KRef } + | { replyKey: string; error: string }; + type DeferredRedeemURLReply = | { type: 'redeemURLReply'; replyKey: string; ref: KRef } | { type: 'redeemURLReply'; replyKey: string; error: string }; @@ -869,29 +874,61 @@ export class RemoteHandle implements EndpointHandle { } /** - * Prepare to handle an incoming redeemURL message. Validates and translates - * but does not send the reply. Returns data needed to complete after commit. + * Decode an incoming redeemURL message's URL. Awaits a decrypt and writes + * nothing, so it runs before the savepoint opens: a savepoint held across an + * await interleaves with the run loop's crank. * * @param url - The ocap URL attempting to be redeemed. * @param replyKey - A sender-provided tag to send with the reply. - * @returns Data needed to complete the operation after commit. + * @returns The kref the URL names, or the reason it names none. */ - async #handleRedeemURLRequest( + async #resolveRedeemURLRequest( url: string, replyKey: string, - ): Promise { + ): Promise { assert.typeof(replyKey, 'string'); - let kref: KRef; try { - kref = await this.#remoteComms.redeemLocalOcapURL(url); + return { + replyKey, + kref: await this.#remoteComms.redeemLocalOcapURL(url), + }; } catch (error) { + // Only the message crosses the wire, so the stack and cause chain stop + // here. This catch is unqualified — a bad URL and a broken decode path + // look the same to the peer — so it is logged locally to tell them apart. + this.#logger.error( + `${this.#peerId.slice(0, 8)}:: redeeming URL for ${replyKey} failed`, + error, + ); return { - type: 'redeemURL', replyKey, - error: `${(error as Error).message}`, + error: error instanceof Error ? error.message : String(error), }; } - const ref = this.#kernelStore.translateRefKtoE(this.remoteId, kref, true); + } + + /** + * Enter a resolved redeemURL request in the c-list. Synchronous, and so safe + * inside the savepoint. Returns data needed to complete after commit. + * + * @param resolution - What {@link #resolveRedeemURLRequest} decoded. + * @returns Data needed to complete the operation after commit. + */ + #recordRedeemURLRequest( + resolution: RedeemURLResolution | undefined, + ): DeferredRedeemURLRequest { + if (!resolution) { + throw Error('redeemURL reached the store without being resolved'); + } + const { replyKey } = resolution; + if ('error' in resolution) { + return { type: 'redeemURL', replyKey, error: resolution.error }; + } + const ref = this.#kernelStore.translateRefKtoE( + this.remoteId, + resolution.kref, + true, + ); return { type: 'redeemURL', replyKey, ref }; } @@ -1001,40 +1038,66 @@ export class RemoteHandle implements EndpointHandle { return null; } + // Decoded before the savepoint opens, because it awaits. It writes nothing, + // so the atomicity below is unaffected. + const redeemURLResolution = + method === 'redeemURL' + ? await this.#resolveRedeemURLRequest(...params) + : undefined; + // Wrap message processing in a transaction for atomicity: Either both (1) // message processing and (2) seq update succeed together, or neither // happens. This ensures crash-safe exactly-once delivery. + // + // The savepoint is the outermost one on the connection and so its own + // commit point, which it can only be while no crank is open — hence the + // turn taken here, and the rule that everything between the two is + // synchronous. const savepointName = `receive_${this.remoteId}_${seq}`; - this.#kernelStore.createSavepoint(savepointName); - let deferredCompletion: DeferredCompletion | undefined; - - try { - switch (method) { - case 'deliver': - this.#handleRemoteDeliver(params); - break; - case 'redeemURL': - deferredCompletion = await this.#handleRedeemURLRequest(...params); - break; - case 'redeemURLReply': - deferredCompletion = this.#handleRedeemURLReply(...params); - break; - default: - // eslint-disable-next-line @typescript-eslint/restrict-template-expressions - throw Error(`unknown remote message type ${method}`); - } + const deferredCompletion = await this.#kernelStore.withStoreOutOfCrank< + DeferredCompletion | undefined + >(() => { + let completion: DeferredCompletion | undefined; + this.#kernelStore.createSavepoint(savepointName); + try { + switch (method) { + case 'deliver': + this.#handleRemoteDeliver(params); + break; + case 'redeemURL': + completion = this.#recordRedeemURLRequest(redeemURLResolution); + break; + case 'redeemURLReply': + completion = this.#handleRedeemURLReply(...params); + break; + default: + // eslint-disable-next-line @typescript-eslint/restrict-template-expressions + throw Error(`unknown remote message type ${method}`); + } - // Persist sequence tracking at the end, within the transaction - this.#kernelStore.setRemoteHighestReceivedSeq(this.remoteId, seq); + // Persist sequence tracking at the end, within the transaction + this.#kernelStore.setRemoteHighestReceivedSeq(this.remoteId, seq); - // Commit the transaction - this.#kernelStore.releaseSavepoint(savepointName); - } catch (error) { - // Rollback on any error - in-memory state unchanged since we didn't update it yet - this.#kernelStore.rollbackSavepoint(savepointName); - throw error; - } + // Commit the transaction + this.#kernelStore.releaseSavepoint(savepointName); + } catch (error) { + // Rollback on any error - in-memory state unchanged since we didn't update it yet + try { + this.#kernelStore.rollbackSavepoint(savepointName); + } catch (rollbackError) { + // Only a failed RELEASE discards the savepoint stack, making this + // rollback report a savepoint already gone; a throw from the delivery + // or the seq write leaves a real rollback failure here. + this.#logger.error( + `${this.#peerId.slice(0, 8)}:: rollback of ${savepointName} failed`, + rollbackError, + ); + } + throw error; + } + return completion; + }); // All in-memory state changes happen after commit diff --git a/packages/ocap-kernel/src/remotes/kernel/RemoteManager.test.ts b/packages/ocap-kernel/src/remotes/kernel/RemoteManager.test.ts index 29ca0b2da..22dcfb0f2 100644 --- a/packages/ocap-kernel/src/remotes/kernel/RemoteManager.test.ts +++ b/packages/ocap-kernel/src/remotes/kernel/RemoteManager.test.ts @@ -4,6 +4,7 @@ import { describe, it, expect, beforeEach, vi } from 'vitest'; import * as remoteComms from './remote-comms.ts'; import { RemoteManager } from './RemoteManager.ts'; import { createMockRemotesFactory } from '../../../test/remotes-mocks.ts'; +import { withFailingSavepointRelease } from '../../../test/savepoint-stack.ts'; import { makeMapKernelDatabase } from '../../../test/storage.ts'; import type { KernelQueue } from '../../KernelQueue.ts'; import { makeKernelStore } from '../../store/index.ts'; @@ -897,6 +898,38 @@ describe('RemoteManager', () => { ]); }); + // The turn waits out whatever crank is open, which is long enough for that + // crank to make the remote decider of a promise. Nothing else would ever + // reject it, so the vat that sent the message waits forever. + it('rejects a promise the remote became decider of while it waited for the crank', async () => { + const peerId = 'peer-with-late-promise'; + const remote = remoteManager.establishRemote(peerId); + const { remoteId } = remote; + kernelStore.setPeerIncarnation(peerId, 'incarnation-A'); + const resolvePromisesSpy = vi.spyOn(mockKernelQueue, 'resolvePromises'); + + kernelStore.startCrank(); + const handled = getOnIncarnationChange()(peerId, 'incarnation-B'); + await Promise.resolve(); + + const [kpid] = kernelStore.initKernelPromise(); + kernelStore.setPromiseDecider(kpid, remoteId); + kernelStore.addCListEntry(remoteId, kpid, 'rp+1'); + kernelStore.endCrank(); + + await handled; + + expect(resolvePromisesSpy).toHaveBeenCalledWith(remoteId, [ + [ + kpid, + true, + expect.objectContaining({ + body: expect.stringContaining('[KERNEL:PEER_RESTARTED]'), + }), + ], + ]); + }); + it('persists the incarnation and reports restart even when no remote handle exists', async () => { const peerId = 'unknown-peer'; const resolvePromisesSpy = vi.spyOn(mockKernelQueue, 'resolvePromises'); @@ -947,6 +980,52 @@ describe('RemoteManager', () => { // finalize must not run if the persisted phase failed: in-memory // mutations would otherwise drift from the rolled-back kv view. expect(finalizeSpy).not.toHaveBeenCalled(); + // And the turn is given back on the way out. A leaked waiter leaves the + // gate unresolved, and the run loop parks on it for good. + expect(kernelStore.outOfCrankWorkPending()).toBeUndefined(); + expect(() => kernelStore.startCrank()).not.toThrow(); + }); + + it('gives the run loop its turn back after advancing the incarnation', async () => { + const peerId = 'peer-that-restarted-cleanly'; + remoteManager.establishRemote(peerId); + kernelStore.setPeerIncarnation(peerId, 'incarnation-A'); + + await getOnIncarnationChange()(peerId, 'incarnation-B'); + + expect(kernelStore.outOfCrankWorkPending()).toBeUndefined(); + expect(() => kernelStore.startCrank()).not.toThrow(); + }); + + it('reports the release failure rather than a missing savepoint', async () => { + const peerId = 'peer-whose-release-fails'; + const { + kernelStore: failingStore, + releaseFailure, + rollbackSavepoint, + } = withFailingSavepointRelease(kernelStore); + remoteManager = new RemoteManager({ + platformServices: mockPlatformServices, + kernelStore: failingStore, + kernelQueue: mockKernelQueue, + logger, + }); + remoteManager.setMessageHandler(vi.fn()); + await remoteManager.initRemoteComms(); + const onIncarnationChange = vi + .mocked(remoteComms.initRemoteComms) + .mock.calls.at(-1)?.[8] as ( + peerId: string, + observedIncarnation: string, + ) => Promise; + + await expect(onIncarnationChange(peerId, 'incarnation-A')).rejects.toBe( + releaseFailure, + ); + // Still attempted: abandoning the rollback is not a way to pass this. + expect(rollbackSavepoint).toHaveBeenCalledWith( + `peerIncarnation_${peerId}`, + ); }); }); }); diff --git a/packages/ocap-kernel/src/remotes/kernel/RemoteManager.ts b/packages/ocap-kernel/src/remotes/kernel/RemoteManager.ts index d9b7c3c94..ca46e5344 100644 --- a/packages/ocap-kernel/src/remotes/kernel/RemoteManager.ts +++ b/packages/ocap-kernel/src/remotes/kernel/RemoteManager.ts @@ -5,7 +5,7 @@ import { RemoteHandle } from './RemoteHandle.ts'; import type { KernelQueue } from '../../KernelQueue.ts'; import { makeKernelError } from '../../liveslots/kernel-marshal.ts'; import type { KernelStore } from '../../store/index.ts'; -import type { PlatformServices, RemoteId } from '../../types.ts'; +import type { KRef, PlatformServices, RemoteId } from '../../types.ts'; import type { RemoteIdentity, RemoteComms, @@ -230,40 +230,54 @@ export class RemoteManager { const isRestart = stored !== undefined; const remote = isRestart ? this.#remotesByPeer.get(peerId) : undefined; - // Snapshot the decider list BEFORE any kv mutation so the c-list lookup - // can still find the promises through the entries forgetEndpointImports - // is about to tear down. We materialize into an array because the - // generator iterates over kv state that we'll mutate. - const promisesToReject = remote - ? Array.from(this.#kernelStore.getPromisesByDecider(remote.remoteId)) - : []; - + // The savepoint is the outermost one on the connection and so its own + // commit point, which it can only be while no crank is open. const savepoint = `peerIncarnation_${peerId}`; - this.#kernelStore.createSavepoint(savepoint); - try { - if (isRestart) { - this.#logger?.log( - `Peer ${peerId.slice(0, 8)} restarted (incarnation ${stored.slice(0, 8)} → ${observedIncarnation.slice(0, 8)})`, - ); - if (remote) { - remote.persistPeerRestart(); - } else { - // No live RemoteHandle for the peer but a persisted incarnation - // exists — usually a transient race during kernel boot before - // initRemoteComms has finished restoring remotes. The persisted - // bookkeeping the missing handle would have cleaned up may leak. - // Surfacing as a warning so operators can correlate. - this.#logger?.warn( - `Peer ${peerId.slice(0, 8)} restart detected but no live RemoteHandle; advancing persisted incarnation without c-list cleanup`, + const promisesToReject = await this.#kernelStore.withStoreOutOfCrank< + KRef[] + >(() => { + // Before any kv mutation, so the c-list lookup can still find the + // promises through the entries `forgetEndpointImports` is about to tear + // down. Inside the turn, because waiting for it spans a whole crank, and + // a promise this peer was made decider of during that crank would never + // be rejected — hanging the vat that sent it. Materialized because the + // generator iterates the kv state we are about to mutate. + const deciding = remote + ? Array.from(this.#kernelStore.getPromisesByDecider(remote.remoteId)) + : []; + + this.#kernelStore.createSavepoint(savepoint); + try { + if (isRestart) { + this.#logger?.log( + `Peer ${peerId.slice(0, 8)} restarted (incarnation ${stored.slice(0, 8)} → ${observedIncarnation.slice(0, 8)})`, ); + if (remote) { + remote.persistPeerRestart(); + } else { + // No live RemoteHandle for the peer but a persisted incarnation + // exists — usually a transient race during kernel boot before + // initRemoteComms has finished restoring remotes. The persisted + // bookkeeping the missing handle would have cleaned up may leak. + // Surfacing as a warning so operators can correlate. + this.#logger?.warn( + `Peer ${peerId.slice(0, 8)} restart detected but no live RemoteHandle; advancing persisted incarnation without c-list cleanup`, + ); + } } + this.#kernelStore.setPeerIncarnation(peerId, observedIncarnation); + this.#kernelStore.releaseSavepoint(savepoint); + } catch (error) { + try { + this.#kernelStore.rollbackSavepoint(savepoint); + } catch (rollbackError) { + // Same reasoning as `RemoteHandle.handleRemoteMessage`. + this.#logger?.error(`Rollback of ${savepoint} failed`, rollbackError); + } + throw error; } - this.#kernelStore.setPeerIncarnation(peerId, observedIncarnation); - this.#kernelStore.releaseSavepoint(savepoint); - } catch (error) { - this.#kernelStore.rollbackSavepoint(savepoint); - throw error; - } + return deciding; + }); // Post-commit fan-out: in-memory state changes and run-queue // mutations are not reversible by a savepoint, so they wait until the 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 6440b1401..2724b1de4 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 @@ -59,6 +59,9 @@ describe('getStatusHandler', () => { const store = { startCrank: vi.fn(), endCrank: vi.fn(), + beginOutOfCrank: vi.fn().mockResolvedValue(undefined), + endOutOfCrank: vi.fn(), + outOfCrankWorkPending: vi.fn().mockReturnValue(undefined), createCrankSavepoint: vi.fn(), rollbackCrank: vi.fn(), collectGarbage: vi.fn(), diff --git a/packages/ocap-kernel/src/store/index.test.ts b/packages/ocap-kernel/src/store/index.test.ts index ab7d8d040..4bebf0f54 100644 --- a/packages/ocap-kernel/src/store/index.test.ts +++ b/packages/ocap-kernel/src/store/index.test.ts @@ -152,6 +152,7 @@ describe('kernel store', () => { 'markVatAsTerminated', 'nextReapAction', 'nextTerminatedVatCleanup', + 'outOfCrankWorkPending', 'pinObject', 'provideIncarnationId', 'recomputeRefCounts', @@ -198,6 +199,7 @@ describe('kernel store', () => { 'undoOcapURLRetention', 'unpinObject', 'waitForCrank', + 'withStoreOutOfCrank', ]); }); }); diff --git a/packages/ocap-kernel/src/store/index.ts b/packages/ocap-kernel/src/store/index.ts index 75f946eed..7186fca95 100644 --- a/packages/ocap-kernel/src/store/index.ts +++ b/packages/ocap-kernel/src/store/index.ts @@ -68,7 +68,7 @@ * kernelService.${serviceName} = ${koid} // kref of kernel service object ${serviceName} */ -import { Fail } from '@endo/errors'; +import { Fail, q } from '@endo/errors'; import type { KernelDatabase, KVStore, VatStore } from '@metamask/kernel-store'; import { Logger } from '@metamask/logger'; @@ -92,7 +92,7 @@ import { getRevocationMethods } from './methods/revocation.ts'; import { getSubclusterMethods } from './methods/subclusters.ts'; import { getTranslators } from './methods/translators.ts'; import { getVatMethods } from './methods/vat.ts'; -import type { StoreContext } from './types.ts'; +import type { StoreContext, StoredValue } from './types.ts'; /** * The prefix shared by the issuance count of every object an ocap URL names, @@ -127,6 +127,47 @@ export function makeKernelStore(kdb: KernelDatabase, logger?: Logger) { const { getPrefixedKeys, provideCachedStoredValue, provideStoredQueue } = getBaseMethods(kv); + /** + * Every cached stored value the context holds, as `field: [key, initial]`. + * Declared once so that initialization and `refreshCachedValues` cannot + * disagree about which values exist. + */ + const CACHED_VALUES = { + /** Counter for allocating kernel object IDs */ + nextObjectId: ['nextObjectId', '1'], + /** Counter for allocating kernel promise IDs */ + nextPromiseId: ['nextPromiseId', '1'], + /** Counter for allocating VatIDs */ + nextVatId: ['nextVatId', '1'], + /** Counter for allocating RemoteIDs */ + nextRemoteId: ['nextRemoteId', '1'], + // Garbage collection + gcActions: ['gcActions', '[]'], + reapQueue: ['reapQueue', '[]'], + terminatedVats: ['vats.terminated', '[]'], + // Subclusters + subclusters: ['subclusters', '[]'], + nextSubclusterId: ['nextSubclusterId', '1'], + vatToSubclusterMap: ['vatToSubclusterMap', '{}'], + } as const satisfies Record; + + /** + * Provide a fresh stored value for each of {@link CACHED_VALUES}. + * + * @returns The stored values, keyed by the context field that holds each. + */ + function provideCachedValues(): Record< + keyof typeof CACHED_VALUES, + StoredValue + > { + return Object.fromEntries( + Object.entries(CACHED_VALUES).map(([field, [key, init]]) => [ + field, + provideCachedStoredValue(key, init), + ]), + ) as Record; + } + const context: StoreContext = { kv, /** The kernel's run queue. */ @@ -137,14 +178,16 @@ export function makeKernelStore(kdb: KernelDatabase, logger?: Logger) { refreshRunQueue: () => { context.runQueue = provideStoredQueue('run', true); }, - /** Counter for allocating kernel object IDs */ - nextObjectId: provideCachedStoredValue('nextObjectId', '1'), - /** Counter for allocating kernel promise IDs */ - nextPromiseId: provideCachedStoredValue('nextPromiseId', '1'), - /** Counter for allocating VatIDs */ - nextVatId: provideCachedStoredValue('nextVatId', '1'), - /** Counter for allocating RemoteIDs */ - nextRemoteId: provideCachedStoredValue('nextRemoteId', '1'), + ...provideCachedValues(), + /** + * Re-read every cached stored value from the database. Each closes over the + * last value written through it (see `provideCachedStoredValue`), so after a + * rollback the closure would otherwise still hold the abandoned value and + * the next `set` would write it straight back. + */ + refreshCachedValues: () => { + Object.assign(context, provideCachedValues()); + }, // As refcounts are decremented, we accumulate a set of krefs for which // action might need to be taken: // * promises which are now resolved and unreferenced can be deleted @@ -156,17 +199,9 @@ export function makeKernelStore(kdb: KernelDatabase, logger?: Logger) { // the change, else removals might be lost (not performed during the next // replay). maybeFreeKrefs: new Set(), - // Garbage collection - gcActions: provideCachedStoredValue('gcActions', '[]'), - reapQueue: provideCachedStoredValue('reapQueue', '[]'), - terminatedVats: provideCachedStoredValue('vats.terminated', '[]'), inCrank: false, savepoints: [], crankBuffer: [], - // Subclusters - subclusters: provideCachedStoredValue('subclusters', '[]'), - nextSubclusterId: provideCachedStoredValue('nextSubclusterId', '1'), - vatToSubclusterMap: provideCachedStoredValue('vatToSubclusterMap', '{}'), auditRefCounts: false, // Logging logger: logger?.subLogger({ tags: ['kernel-store'] }), @@ -226,23 +261,8 @@ export function makeKernelStore(kdb: KernelDatabase, logger?: Logger) { })); kdb.clear(); context.maybeFreeKrefs.clear(); - context.runQueue = provideStoredQueue('run', true); - context.gcActions = provideCachedStoredValue('gcActions', '[]'); - context.reapQueue = provideCachedStoredValue('reapQueue', '[]'); - context.terminatedVats = provideCachedStoredValue('vats.terminated', '[]'); - context.nextObjectId = provideCachedStoredValue('nextObjectId', '1'); - context.nextPromiseId = provideCachedStoredValue('nextPromiseId', '1'); - context.nextVatId = provideCachedStoredValue('nextVatId', '1'); - context.nextRemoteId = provideCachedStoredValue('nextRemoteId', '1'); - context.subclusters = provideCachedStoredValue('subclusters', '[]'); - context.nextSubclusterId = provideCachedStoredValue( - 'nextSubclusterId', - '1', - ); - context.vatToSubclusterMap = provideCachedStoredValue( - 'vatToSubclusterMap', - '{}', - ); + context.refreshRunQueue(); + context.refreshCachedValues(); crank.releaseAllSavepoints(); context.crankBuffer.length = 0; preservedState?.forEach(({ key, value }) => { @@ -280,9 +300,16 @@ export function makeKernelStore(kdb: KernelDatabase, logger?: Logger) { /** * Create a savepoint for atomic operations on persistent storage. * + * These are invisible to `createCrankSavepoint`'s ordinal naming, so one + * opened inside a crank would be rolled back by a delivery that has nothing + * to do with it — after its owner had already reported success to a peer. + * Callers take their turn through `beginOutOfCrank`. + * * @param name - The savepoint name. */ function createSavepoint(name: string): void { + !context.inCrank || + Fail`createSavepoint ${q(name)} inside a crank; use beginOutOfCrank`; kdb.createSavepoint(name); } @@ -413,9 +440,6 @@ export function makeKernelStore(kdb: KernelDatabase, logger?: Logger) { return Number(kv.get(`${OCAP_URL_PREFIX}${kref}`) ?? 0); }, retainForOcapURL(kref: KRef): void { - // Refuse to mint a token for something already collected: the URL would - // name a capability that can never be delivered to. Refusing here names - // what was attempted, and does it before anything has been written. this.kernelRefExists(kref) || Fail`cannot issue an ocap URL for deleted kref ${kref}`; const issuances = this.getOcapURLIssuanceCount(kref); @@ -430,16 +454,12 @@ export function makeKernelStore(kdb: KernelDatabase, logger?: Logger) { kv.set(`${OCAP_URL_PREFIX}${kref}`, `${issuances - 1}`); return; } - // The last issuance, or none at all: either way, what is left of the - // retention is exactly what a release drops. this.releaseOcapURLRetentions(kref); }, releaseOcapURLRetentions(kref: KRef): void { if (this.getOcapURLIssuanceCount(kref) === 0) { return; } - // Spend the pin before forgetting the retention, so a failure to release - // it leaves a ledger that still says the retention is held. this.unpinObject(kref); kv.delete(`${OCAP_URL_PREFIX}${kref}`); }, diff --git a/packages/ocap-kernel/src/store/methods/crank.cross-crank-gc.test.ts b/packages/ocap-kernel/src/store/methods/crank.cross-crank-gc.test.ts new file mode 100644 index 000000000..e503d7981 --- /dev/null +++ b/packages/ocap-kernel/src/store/methods/crank.cross-crank-gc.test.ts @@ -0,0 +1,85 @@ +import { describe, it, expect, beforeEach } from 'vitest'; + +import { makeMapKernelDatabase } from '../../../test/storage.ts'; +import { makeKernelStore } from '../index.ts'; + +/** + * `revertStateBeneathRollback` reverts `maybeFreeKrefs`, which nothing else + * rolls back. The set is not per-crank: only `collectGarbage` empties it, so a + * candidate added while no crank was open is still owed a collection and has to + * survive an unrelated crank's rollback. + * + * `RemoteManager.#handlePeerIncarnation` is one such producer. It runs from a + * network callback with no crank open, under its own `peerIncarnation_` + * savepoint, and `persistPeerRestart` -> `forgetEndpointImports` adds every + * export the restarting peer abandoned. It calls no `collectGarbage` of its own, + * so those krefs wait for the next crank's harvest -- and their kv state is + * already committed by the time it comes. A rollback that discarded them would + * leave the objects orphaned, undeleted, and invisible even to the reference + * count audit, which sees an orphan with no holders and a count of zero as + * consistent. + */ +describe('a GC candidate produced outside a crank', () => { + let kernelStore: ReturnType; + + /** + * Abandon a remote's export the way a peer restart does. + * + * @returns The kref of the now-ownerless object. + */ + function orphanARemoteExport(): string { + const kref = kernelStore.initKernelObject('r1'); + kernelStore.addCListEntry('r1', kref, 'o+1'); + // RemoteManager.#handlePeerIncarnation, inside its own savepoint, no crank. + kernelStore.forgetEndpointImports('r1'); + return kref; + } + + /** + * Run one crank, optionally rolling its delivery back. + * + * @param options - How the crank ends. + * @param options.rollback - Whether the delivery aborts. + */ + function runCrank({ rollback = false }: { rollback?: boolean } = {}): void { + kernelStore.startCrank(); + kernelStore.createCrankSavepoint('crank'); + kernelStore.createCrankSavepoint('delivery'); + if (rollback) { + kernelStore.rollbackCrank('delivery'); + } + kernelStore.collectGarbage(); + kernelStore.endCrank(); + } + + beforeEach(() => { + kernelStore = makeKernelStore(makeMapKernelDatabase()); + }); + + it('is collected by the next crank that succeeds', () => { + const kref = orphanARemoteExport(); + + runCrank(); + + expect(kernelStore.kernelRefExists(kref)).toBe(false); + }); + + it('is collected by the next crank that rolls back', () => { + const kref = orphanARemoteExport(); + + runCrank({ rollback: true }); + + expect(kernelStore.kernelRefExists(kref)).toBe(false); + }); + + it('survives a rollback of a crank that never touched it', () => { + const kref = orphanARemoteExport(); + + runCrank({ rollback: true }); + for (let crank = 0; crank < 5; crank += 1) { + runCrank(); + } + + expect(kernelStore.kernelRefExists(kref)).toBe(false); + }); +}); diff --git a/packages/ocap-kernel/src/store/methods/crank.out-of-crank.test.ts b/packages/ocap-kernel/src/store/methods/crank.out-of-crank.test.ts new file mode 100644 index 000000000..5130b57dd --- /dev/null +++ b/packages/ocap-kernel/src/store/methods/crank.out-of-crank.test.ts @@ -0,0 +1,163 @@ +import { describe, it, expect, beforeEach } from 'vitest'; + +import { makeMapKernelDatabase } from '../../../test/storage.ts'; +import { makeKernelStore } from '../index.ts'; + +/** + * A savepoint taken through `KernelStore.createSavepoint` is invisible to + * `createCrankSavepoint`'s ordinal naming, so overlapping one with a crank + * leaves the crank's release committing into someone else's transaction, or the + * caller's writes discarded by a delivery rollback it had nothing to do with. + * See `kernel-store`'s `nodejs.savepoint-interleaving.test.ts` for what SQLite + * does in each case. + * + * The two are kept apart instead: callers take their turn through + * `withStoreOutOfCrank`, and both directions of the overlap are refused. The + * turn is taken and given back by that one call because a turn never given back + * parks the run loop with nothing to show for it. + */ +describe('store work outside a crank', () => { + let kernelStore: ReturnType; + + beforeEach(() => { + kernelStore = makeKernelStore(makeMapKernelDatabase()); + }); + + it('refuses a savepoint taken inside a crank', () => { + kernelStore.startCrank(); + + expect(() => kernelStore.createSavepoint('receive_r1_7')).toThrow( + 'createSavepoint "receive_r1_7" inside a crank', + ); + }); + + it('refuses a crank started while a caller holds the store', async () => { + await kernelStore.withStoreOutOfCrank(() => { + expect(() => kernelStore.startCrank()).toThrow( + 'startCrank while 1 caller(s) hold the store outside a crank', + ); + }); + }); + + it('lets a caller through once the crank it arrived during has ended', async () => { + kernelStore.startCrank(); + + let held = false; + const turn = kernelStore.withStoreOutOfCrank(() => { + held = true; + }); + + await Promise.resolve(); + expect(held).toBe(false); + + kernelStore.endCrank(); + await turn; + + expect(held).toBe(true); + }); + + it('holds the next crank off while a caller is waiting', async () => { + kernelStore.startCrank(); + const turn = kernelStore.withStoreOutOfCrank(() => undefined); + + // What the run loop consults between `endCrank` and the next `startCrank`. + expect(kernelStore.outOfCrankWorkPending()).toBeDefined(); + + kernelStore.endCrank(); + await turn; + + expect(kernelStore.outOfCrankWorkPending()).toBeUndefined(); + }); + + it('nothing to wait for while no caller is holding', () => { + expect(kernelStore.outOfCrankWorkPending()).toBeUndefined(); + }); + + it('gives the store back when the work throws', async () => { + await expect( + kernelStore.withStoreOutOfCrank(() => { + throw new Error('the delivery failed'); + }), + ).rejects.toThrow('the delivery failed'); + + expect(kernelStore.outOfCrankWorkPending()).toBeUndefined(); + expect(() => kernelStore.startCrank()).not.toThrow(); + }); + + it('returns what the work returned', async () => { + expect(await kernelStore.withStoreOutOfCrank(() => 'committed')).toBe( + 'committed', + ); + }); + + // The turn is given back the moment the work returns, so work that awaits + // resumes with the run loop free to start a crank — and the savepoint both + // callers take inside it would nest in that crank rather than being the + // commit point. The type refuses this; the check is for what inference lets + // through. + it('refuses work that is not synchronous', async () => { + await expect( + kernelStore.withStoreOutOfCrank( + (async () => undefined) as unknown as () => undefined, + ), + ).rejects.toThrow('work that is not synchronous'); + + expect(kernelStore.outOfCrankWorkPending()).toBeUndefined(); + expect(() => kernelStore.startCrank()).not.toThrow(); + }); + + // The run loop's protocol: re-check the gate until nothing is waiting, then + // start the crank with no await in between. Checking once would have it + // resume into `startCrank` with a caller already holding, which is a refusal + // it cannot survive. + it('lets a caller that arrives as the gate clears take its turn too', async () => { + let crankStarted = false; + let second: Promise | undefined; + + const first = kernelStore.withStoreOutOfCrank(() => { + // Registers before the first caller's turn is given back, so the gate + // never reaches zero between the two. + second = kernelStore.withStoreOutOfCrank(() => undefined); + }); + + const runLoopTurn = (async () => { + let pending = kernelStore.outOfCrankWorkPending(); + while (pending) { + await pending; + pending = kernelStore.outOfCrankWorkPending(); + } + kernelStore.startCrank(); + crankStarted = true; + })(); + + await first; + expect(crankStarted).toBe(false); + + await second; + await runLoopTurn; + + expect(crankStarted).toBe(true); + }); + + it('holds the crank off until the last of several callers is done', async () => { + kernelStore.startCrank(); + const order: string[] = []; + const first = kernelStore.withStoreOutOfCrank(() => { + order.push('first'); + }); + const second = kernelStore.withStoreOutOfCrank(() => { + order.push('second'); + // The first caller has had its turn and given it back. The gate is still + // closed, because this one has not. + order.push( + kernelStore.outOfCrankWorkPending() === undefined ? 'open' : 'closed', + ); + }); + + kernelStore.endCrank(); + await Promise.all([first, second]); + + expect(order).toStrictEqual(['first', 'second', 'closed']); + expect(kernelStore.outOfCrankWorkPending()).toBeUndefined(); + }); +}); diff --git a/packages/ocap-kernel/src/store/methods/crank.test.ts b/packages/ocap-kernel/src/store/methods/crank.test.ts index db3de8645..5c0561a8c 100644 --- a/packages/ocap-kernel/src/store/methods/crank.test.ts +++ b/packages/ocap-kernel/src/store/methods/crank.test.ts @@ -2,7 +2,18 @@ import type { KernelDatabase } from '@metamask/kernel-store'; import { expect, describe, it, vi, beforeEach } from 'vitest'; import { getCrankMethods } from './crank.ts'; -import type { StoreContext } from '../types.ts'; +import type { KRef } from '../../types.ts'; +import type { Savepoint, StoreContext } from '../types.ts'; + +/** + * Build savepoint records holding no collection candidates, for tests that only + * care which savepoints are listed. + * + * @param names - The savepoint names, in order. + * @returns The savepoint records. + */ +const savepoints = (...names: string[]): Savepoint[] => + names.map((name) => ({ name, maybeFreeKrefs: new Set() })); describe('crank methods', () => { let context: StoreContext; @@ -10,6 +21,12 @@ describe('crank methods', () => { let crankMethods: ReturnType; let mockCrankBuffer: unknown[]; + /** + * @returns The names of the currently listed savepoints, in order. + */ + const savepointNames = (): string[] => + context.savepoints.map(({ name }) => name); + beforeEach(() => { mockCrankBuffer = []; context = { @@ -17,6 +34,8 @@ describe('crank methods', () => { savepoints: [], crankBuffer: mockCrankBuffer, refreshRunQueue: vi.fn(), + refreshCachedValues: vi.fn(), + maybeFreeKrefs: new Set(), } as unknown as StoreContext; kdb = { @@ -51,7 +70,7 @@ describe('crank methods', () => { context.inCrank = true; crankMethods.createCrankSavepoint('test'); - expect(context.savepoints).toStrictEqual(['test']); + expect(savepointNames()).toStrictEqual(['test']); expect(kdb.createSavepoint).toHaveBeenCalledWith('t0'); }); @@ -60,7 +79,7 @@ describe('crank methods', () => { crankMethods.createCrankSavepoint('first'); crankMethods.createCrankSavepoint('second'); - expect(context.savepoints).toStrictEqual(['first', 'second']); + expect(savepointNames()).toStrictEqual(['first', 'second']); expect(kdb.createSavepoint).toHaveBeenCalledWith('t0'); expect(kdb.createSavepoint).toHaveBeenCalledWith('t1'); }); @@ -92,7 +111,7 @@ describe('crank methods', () => { describe('rollbackCrank', () => { it('forgets the savepoint even if the database rollback fails', () => { context.inCrank = true; - context.savepoints = ['start']; + context.savepoints = savepoints('start'); vi.mocked(kdb.rollbackSavepoint).mockImplementationOnce(() => { throw new Error('database is gone'); }); @@ -110,17 +129,17 @@ describe('crank methods', () => { it('should rollback to specified savepoint', () => { context.inCrank = true; - context.savepoints = ['first', 'second', 'third']; + context.savepoints = savepoints('first', 'second', 'third'); crankMethods.rollbackCrank('second'); expect(kdb.rollbackSavepoint).toHaveBeenCalledWith('t1'); - expect(context.savepoints).toStrictEqual(['first']); + expect(savepointNames()).toStrictEqual(['first']); }); it('should throw when savepoint does not exist', () => { context.inCrank = true; - context.savepoints = ['first', 'second']; + context.savepoints = savepoints('first', 'second'); expect(() => crankMethods.rollbackCrank('nonexistent')).toThrow( 'no such savepoint as ""nonexistent""', @@ -141,18 +160,76 @@ describe('crank methods', () => { crankMethods.rollbackCrank('b'); crankMethods.createCrankSavepoint('b2'); expect(kdb.createSavepoint).toHaveBeenLastCalledWith('t1'); - expect(context.savepoints).toStrictEqual(['a', 'b2']); + expect(savepointNames()).toStrictEqual(['a', 'b2']); }); it('clears the crank buffer', () => { context.inCrank = true; - context.savepoints = ['start']; + context.savepoints = savepoints('start'); mockCrankBuffer.push({ type: 'send' }, { type: 'notify' }); crankMethods.rollbackCrank('start'); expect(mockCrankBuffer).toHaveLength(0); }); + + it('forgets every savepoint when the rollback fails', () => { + context.inCrank = true; + crankMethods.createCrankSavepoint('crank'); + crankMethods.createCrankSavepoint('delivery'); + vi.mocked(kdb.rollbackSavepoint).mockImplementationOnce(() => { + throw new Error('disk I/O error'); + }); + + expect(() => crankMethods.rollbackCrank('delivery')).toThrow( + 'disk I/O error', + ); + + expect(context.savepoints).toStrictEqual([]); + crankMethods.endCrank(); + expect(kdb.releaseSavepoint).not.toHaveBeenCalled(); + }); + + it('reverts the caches the database cannot reach even when the rollback fails', () => { + context.inCrank = true; + // Predates the savepoint, so it survives: only `collectGarbage` empties + // this set, and a candidate owed a collection before this crank began is + // still owed one after it is abandoned. + context.maybeFreeKrefs.add('kp1'); + crankMethods.createCrankSavepoint('crank'); + crankMethods.createCrankSavepoint('delivery'); + // Added by the crank being rolled back, so it goes. + context.maybeFreeKrefs.add('kp2'); + vi.mocked(kdb.rollbackSavepoint).mockImplementationOnce(() => { + throw new Error('disk I/O error'); + }); + + expect(() => crankMethods.rollbackCrank('delivery')).toThrow( + 'disk I/O error', + ); + + expect(context.refreshCachedValues).toHaveBeenCalled(); + expect(context.refreshRunQueue).toHaveBeenCalled(); + expect(context.runQueueLengthCache).toBe(-1); + expect([...context.maybeFreeKrefs]).toStrictEqual(['kp1']); + }); + + it('keeps the rollback failure as the cause when reverting also fails', () => { + context.inCrank = true; + const rollbackFailure = new Error('disk I/O error'); + crankMethods.createCrankSavepoint('crank'); + crankMethods.createCrankSavepoint('delivery'); + vi.mocked(kdb.rollbackSavepoint).mockImplementationOnce(() => { + throw rollbackFailure; + }); + vi.mocked(context.refreshCachedValues).mockImplementationOnce(() => { + throw new Error('database is gone'); + }); + + expect(() => crankMethods.rollbackCrank('delivery')).toThrow( + expect.objectContaining({ cause: rollbackFailure }), + ); + }); }); describe('endCrank', () => { @@ -168,7 +245,7 @@ describe('crank methods', () => { it('should release savepoints if they exist', () => { context.inCrank = true; - context.savepoints = ['test']; + context.savepoints = savepoints('test'); crankMethods.endCrank(); expect(kdb.releaseSavepoint).toHaveBeenCalledWith('t0'); expect(context.savepoints).toStrictEqual([]); @@ -196,7 +273,7 @@ describe('crank methods', () => { it('settles the crank even if releasing savepoints fails', async () => { crankMethods.startCrank(); - context.savepoints = ['test']; + context.savepoints = savepoints('test'); const waiter = crankMethods.waitForCrank(); vi.mocked(kdb.releaseSavepoint).mockImplementationOnce(() => { throw new Error('database is gone'); @@ -206,12 +283,24 @@ describe('crank methods', () => { expect(context.resolveCrank).toBeUndefined(); expect(await waiter).toBeUndefined(); }); + + it('forgets its savepoints even if releasing them fails', () => { + crankMethods.startCrank(); + context.savepoints = ['test']; + vi.mocked(kdb.releaseSavepoint).mockImplementationOnce(() => { + throw new Error('database is gone'); + }); + + expect(() => crankMethods.endCrank()).toThrow('database is gone'); + + expect(context.savepoints).toStrictEqual([]); + }); }); describe('releaseAllSavepoints', () => { it('should release all savepoints', () => { context.inCrank = true; - context.savepoints = ['test']; + context.savepoints = savepoints('test'); crankMethods.releaseAllSavepoints(); expect(kdb.releaseSavepoint).toHaveBeenCalledWith('t0'); expect(context.savepoints).toStrictEqual([]); diff --git a/packages/ocap-kernel/src/store/methods/crank.ts b/packages/ocap-kernel/src/store/methods/crank.ts index 87d2bc65b..db38a24ef 100644 --- a/packages/ocap-kernel/src/store/methods/crank.ts +++ b/packages/ocap-kernel/src/store/methods/crank.ts @@ -2,7 +2,17 @@ import { Fail, q } from '@endo/errors'; import { makePromiseKit } from '@endo/promise-kit'; import type { KernelDatabase } from '@metamask/kernel-store'; -import type { CrankBufferItem, StoreContext } from '../types.ts'; +import type { CrankBufferItem, Savepoint, StoreContext } from '../types.ts'; + +/** + * @param value - Anything. + * @returns Whether it is a thenable, which is what `await` acts on. + */ +function isPromiseLike(value: unknown): boolean { + return ( + typeof (value as PromiseLike | undefined)?.then === 'function' + ); +} /** * Get the crank methods. @@ -13,17 +23,119 @@ import type { CrankBufferItem, StoreContext } from '../types.ts'; */ // eslint-disable-next-line @typescript-eslint/explicit-function-return-type export function getCrankMethods(ctx: StoreContext, kdb: KernelDatabase) { + // Callers waiting to take a savepoint of their own, and a gate the run loop + // holds off on starting a crank for while any of them are. The run loop is + // otherwise synchronous from `endCrank` to the next `startCrank`, so it never + // leaves a gap for them on its own. + let outOfCrankWaiters = 0; + let outOfCrankIdle: ReturnType> | undefined; + /** * Start a crank. */ function startCrank(): void { !ctx.inCrank || Fail`startCrank while already in a crank`; + // A savepoint taken outside a crank is the outermost one on the connection, + // and so the transaction's commit point. Opening a crank underneath it + // would put this crank's writes inside someone else's transaction, to be + // committed or discarded by them. + outOfCrankWaiters === 0 || + Fail`startCrank while ${q(outOfCrankWaiters)} caller(s) hold the store outside a crank`; ctx.inCrank = true; const { promise, resolve } = makePromiseKit(); ctx.crankSettled = promise; ctx.resolveCrank = resolve; } + /** + * Take a turn at the store outside any crank, for work that must be its own + * transaction: an inbound remote message, a peer's restart. Resolves only + * once no crank is open, and holds the run loop off until the matching + * {@link endOutOfCrank}. + * + * Private to this module; callers take their turn through + * {@link withStoreOutOfCrank}. + */ + async function beginOutOfCrank(): Promise { + outOfCrankWaiters += 1; + // Created before the await below, so a run loop that consults + // `outOfCrankWorkPending` in the meantime has something to wait on. The + // count it increments above is what `startCrank` itself refuses on. + outOfCrankIdle ??= makePromiseKit(); + try { + while (ctx.inCrank) { + // Awaiting `undefined` would spin this loop as fast as the microtask + // queue allows, wedging the event loop with nothing to show for it. + ctx.crankSettled !== undefined || + Fail`inCrank with no crankSettled to wait on`; + await ctx.crankSettled; + } + } catch (error) { + // The count is incremented above, before any of this can fail, so the + // caller's `finally` has nothing to release yet. Left as it was, a gate + // that never reaches zero parks the run loop for good. + endOutOfCrank(); + throw error; + } + } + + /** + * Give the run loop the store back. Must be called for every + * {@link beginOutOfCrank}, from a `finally`. + */ + function endOutOfCrank(): void { + // An unmatched call would drive the count negative, and a gate that never + // reaches zero parks the run loop for good. + outOfCrankWaiters > 0 || Fail`endOutOfCrank without beginOutOfCrank`; + outOfCrankWaiters -= 1; + if (outOfCrankWaiters === 0) { + outOfCrankIdle?.resolve(); + outOfCrankIdle = undefined; + } + } + + /** + * Hold the store outside any crank for the duration of `work`, and give it + * back however `work` ends. Paired here rather than by callers because a turn + * never given back leaves the run loop waiting on a promise nothing resolves: + * no failure, no log, no timeout. + * + * `work` must be synchronous. The turn is given back the moment it returns, + * so work that awaits resumes with the run loop free to start a crank — and + * both callers take a savepoint inside it, which would then nest inside that + * crank rather than being the commit point it has to be. The type refuses the + * plain cases and the check below catches the rest; a caller that needs to + * await does it with what `work` hands back. + * + * @param work - The synchronous work to do while holding the store. + * @returns What `work` returned. + */ + async function withStoreOutOfCrank( + work: () => Result & + (Result extends PromiseLike ? never : unknown), + ): Promise { + await beginOutOfCrank(); + try { + const result = work(); + // Thrown from inside the `try`, so the `finally` still gives the turn + // back rather than parking the run loop on top of the mistake. + !isPromiseLike(result) || + Fail`withStoreOutOfCrank given work that is not synchronous`; + return result; + } finally { + endOutOfCrank(); + } + } + + /** + * @returns A promise to await before starting a crank, or undefined if + * nothing is waiting — undefined rather than a resolved promise so that the + * run loop's usual path stays synchronous. + */ + function outOfCrankWorkPending(): Promise | undefined { + return outOfCrankIdle?.promise; + } + /** * Create a savepoint in the crank. * @@ -32,11 +144,13 @@ export function getCrankMethods(ctx: StoreContext, kdb: KernelDatabase) { function createCrankSavepoint(name: string): void { ctx.inCrank || Fail`createCrankSavepoint outside of crank`; const ordinal = ctx.savepoints.length; - // 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); + // Copied, not referenced: `maybeFreeKrefs` is mutated in place from here on, + // and this is the "before" a rollback restores. + ctx.savepoints.push({ + name, + maybeFreeKrefs: new Set(ctx.maybeFreeKrefs), + }); } /** @@ -48,37 +162,81 @@ export function getCrankMethods(ctx: StoreContext, kdb: KernelDatabase) { ctx.inCrank || Fail`rollbackCrank outside of crank`; ctx.crankBuffer.length = 0; // Discard buffered outputs for (const ordinal of ctx.savepoints.keys()) { - if (ctx.savepoints[ordinal] === savepoint) { + const restored = ctx.savepoints[ordinal]; + if (restored?.name === savepoint) { 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; + } catch (error) { + ctx.savepoints.length = 0; + // Before the rethrow, and not only on the path below. A failed + // rollback discards the whole transaction, so the database has moved + // back at least as far as a successful rollback would have taken it + // and these caches are at least as stale. Rethrowing ahead of this + // would leave the dying crank holding the GC action it consumed and + // the freed krefs it was about to collect. + revertStateBeneathRollback(restored, error); + throw error; } - // 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(); - // Invalidate the run queue length cache so it's recalculated from - // the database on next access, since the rollback may have restored - // dequeued items. - ctx.runQueueLengthCache = -1; + revertStateBeneathRollback(restored); return; } } Fail`no such savepoint as "${q(savepoint)}"`; } + /** + * Revert what a database rollback cannot reach: the in-memory caches built + * over the abandoned crank's writes. + * + * @param restored - The savepoint being rolled back to, whose snapshot of + * `maybeFreeKrefs` is the "before" this restores. + * @param rollbackError - The error the rollback threw, if it threw. Kept as + * the `cause` should reverting fail too, since it is the root cause an + * operator needs. + */ + function revertStateBeneathRollback( + restored: Savepoint, + rollbackError?: unknown, + ): void { + try { + ctx.refreshRunQueue(); + ctx.runQueueLengthCache = -1; + ctx.refreshCachedValues(); + // Nothing rolls back RAM. Krefs this crank added are collection + // candidates only because of decrements that were just undone; left in + // place, `collectGarbage` throws on a later crank for any promise this one + // created, killing the run loop over work that no longer exists. + // Restored to the savepoint's snapshot rather than cleared, because the + // set is not per-crank: only `collectGarbage` empties it, so a candidate + // added while the run loop was idle — `terminateVat` unpinning a root is + // the real path — is still owed a collection and must survive an + // unrelated crank's rollback. + ctx.maybeFreeKrefs.clear(); + for (const kref of restored.maybeFreeKrefs) { + ctx.maybeFreeKrefs.add(kref); + } + } catch (revertError) { + if (rollbackError === undefined) { + throw revertError; + } + throw new Error( + `Crank rollback failed and its caches could not be reverted: ${String(revertError)}`, + { cause: rollbackError }, + ); + } + } + /** * Release all savepoints. */ function releaseAllSavepoints(): void { if (ctx.savepoints.length > 0) { - kdb.releaseSavepoint('t0'); - ctx.savepoints.length = 0; + try { + kdb.releaseSavepoint('t0'); + } finally { + ctx.savepoints.length = 0; + } } } @@ -144,6 +302,8 @@ export function getCrankMethods(ctx: StoreContext, kdb: KernelDatabase) { endCrank, releaseAllSavepoints, waitForCrank, + withStoreOutOfCrank, + outOfCrankWorkPending, bufferCrankOutput, flushCrankBuffer, isInCrank, diff --git a/packages/ocap-kernel/src/store/types.ts b/packages/ocap-kernel/src/store/types.ts index 3bf54862f..10bacd658 100644 --- a/packages/ocap-kernel/src/store/types.ts +++ b/packages/ocap-kernel/src/store/types.ts @@ -11,6 +11,7 @@ export type StoreContext = { runQueue: StoredQueue; // Holds RunAction[] runQueueLengthCache: number; // Holds number refreshRunQueue: () => void; + refreshCachedValues: () => void; nextObjectId: StoredValue; // Holds string nextPromiseId: StoredValue; // Holds string nextVatId: StoredValue; // Holds string @@ -22,7 +23,7 @@ export type StoreContext = { inCrank: boolean; crankSettled?: Promise; resolveCrank?: (() => void) | undefined; - savepoints: string[]; + savepoints: Savepoint[]; crankBuffer: CrankBufferItem[]; // Buffer for sends and notifications during crank subclusters: StoredValue; // Holds Subcluster[] nextSubclusterId: StoredValue; // Holds string @@ -31,6 +32,17 @@ export type StoreContext = { logger?: Logger | undefined; }; +/** + * A database savepoint, paired with the RAM state a database rollback cannot + * reach. `maybeFreeKrefs` is the collection-candidate set as it stood when the + * savepoint was taken, so a rollback can put back exactly what the abandoned + * work added and no more. + */ +export type Savepoint = { + name: string; + maybeFreeKrefs: Set; +}; + export type StoredValue = { get(): string | undefined; set(newValue: string): void; diff --git a/packages/ocap-kernel/test/savepoint-stack.ts b/packages/ocap-kernel/test/savepoint-stack.ts new file mode 100644 index 000000000..68c43975f --- /dev/null +++ b/packages/ocap-kernel/test/savepoint-stack.ts @@ -0,0 +1,61 @@ +import type { MockedFunction } from 'vitest'; +import { vi } from 'vitest'; + +import type { KernelStore } from '../src/store/index.ts'; + +export type FailingReleaseStore = { + /** The store to hand the subject under test. */ + kernelStore: KernelStore; + /** The error every `releaseSavepoint` throws. */ + releaseFailure: Error; + /** Exposed so a test can assert the rollback was still attempted. */ + rollbackSavepoint: MockedFunction<(name: string) => void>; +}; + +/** + * Wrap a kernel store so that `releaseSavepoint` fails the way a full disk does, + * modelling the drivers' bookkeeping as of #1021 and verified against both: a + * failed RELEASE clears the savepoint stack, and touching a name that is no + * longer on it throws `No such savepoint`. What is under test is therefore the + * caller's error handling, not an expected outcome baked into the mock. + * + * Replaces the store wholesale rather than assigning over its methods, because + * `makeKernelStore` hardens what it returns. + * + * @param kernelStore - The store to wrap. + * @returns The wrapped store and the handles a test needs to assert against. + */ +export function withFailingSavepointRelease( + kernelStore: KernelStore, +): FailingReleaseStore { + const savepoints: string[] = []; + const releaseFailure = new Error('database or disk is full'); + const assertOnStack = (name: string): void => { + if (!savepoints.includes(name)) { + throw new Error(`No such savepoint: ${name}`); + } + }; + const rollbackSavepoint = vi.fn(assertOnStack); + return { + kernelStore: { + ...kernelStore, + createSavepoint: (name: string) => { + // The refusal `KernelStore.createSavepoint` makes, so a caller that + // took its savepoint inside a crank fails here as it would in + // production rather than passing against a more permissive model. + if (kernelStore.isInCrank()) { + throw new Error(`createSavepoint "${name}" inside a crank`); + } + savepoints.push(name); + }, + releaseSavepoint: (name: string) => { + assertOnStack(name); + savepoints.length = 0; + throw releaseFailure; + }, + rollbackSavepoint, + }, + releaseFailure, + rollbackSavepoint, + }; +}