diff --git a/packages/kernel-browser-runtime/CHANGELOG.md b/packages/kernel-browser-runtime/CHANGELOG.md index e101fdcb3..31e6f07c5 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 — including the transaction aborts it reports on the kernel's dying path — reach the log rather than nowhere ([#1021](https://github.com/MetaMask/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 5a75a4578..54296e31c 100644 --- a/packages/kernel-node-runtime/CHANGELOG.md +++ b/packages/kernel-node-runtime/CHANGELOG.md @@ -19,6 +19,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 — including the transaction aborts it reports on the kernel's dying path — reach the log rather than nowhere ([#1021](https://github.com/MetaMask/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..672313a02 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,9 @@ vi.mock('@metamask/kernel-store/sqlite/nodejs', async () => { '../../../ocap-kernel/test/storage.ts' ); return { - makeSQLKernelDatabase: makeMapKernelDatabase, + // Wrapped so that a test can see what the database was constructed with, + // while still getting a real store back. + makeSQLKernelDatabase: vi.fn(makeMapKernelDatabase), }; }); @@ -18,4 +22,19 @@ describe('makeKernel', () => { expect(kernel).toBeInstanceOf(Kernel); }); + + // FAILING REPRO. + // + // The kernel store is the only collaborator `makeKernel` builds without + // handing it a logger, so every `logger?.` call inside the SQLite driver is + // dead code in production — including the four abort failures #1012 added + // logging for. `kernel-worker.ts` omits it too, which keeps the wasm driver's + // pair dead even once this passes. + 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 5cfe39eb5..df9b23b67 100644 --- a/packages/kernel-store/CHANGELOG.md +++ b/packages/kernel-store/CHANGELOG.md @@ -12,6 +12,11 @@ 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` ([#1021](https://github.com/MetaMask/ocap-kernel/pull/1021)) + - Otherwise the savepoint stayed on the stack and the transaction open with nothing left to commit or abort it. The release failure is still what gets thrown +- The wasm driver clears `_inTx` when aborting or committing a transaction throws, instead of believing it is still in one ([#1021](https://github.com/MetaMask/ocap-kernel/pull/1021)) + - Left true, `beginIfNeeded` became a permanent no-op and later writes autocommitted — including the next savepoint, which was then created bare, where its `RELEASE` commits and no rollback could undo the delivery. The nodejs driver reads `db.inTransaction` and was never affected +- An abort that fails while recovering from a failed savepoint operation is now logged in both drivers ([#1021](https://github.com/MetaMask/ocap-kernel/pull/1021)) ## [0.6.0] diff --git a/packages/kernel-store/src/sqlite/nodejs.test.ts b/packages/kernel-store/src/sqlite/nodejs.test.ts index a62392fe1..270f018ae 100644 --- a/packages/kernel-store/src/sqlite/nodejs.test.ts +++ b/packages/kernel-store/src/sqlite/nodejs.test.ts @@ -360,6 +360,45 @@ describe('makeSQLKernelDatabase', () => { expect(mockDb._spStack).toStrictEqual([]); }); + // The hazard `rollbackSavepoint` guards against, by the other door. + 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.ts b/packages/kernel-store/src/sqlite/nodejs.ts index ec863edc7..fa754bb88 100644 --- a/packages/kernel-store/src/sqlite/nodejs.ts +++ b/packages/kernel-store/src/sqlite/nodejs.ts @@ -298,8 +298,14 @@ export async function makeSQLKernelDatabase({ db._spStack.length = 0; try { rollbackIfNeeded(); - } catch { - // The rollback failure below is the one worth reporting. + } catch (abortError) { + // The rollback failure below is the one worth reporting, but a failed + // abort leaves SQLite holding a transaction the next crank would + // silently write into. Nothing here can repair that. + logger?.error( + 'failed to discard transaction after rollback', + abortError, + ); } throw error; } @@ -321,7 +327,28 @@ export async function makeSQLKernelDatabase({ 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: left as + // it was, the savepoint stays on the stack and the transaction open with + // nothing to ever commit or abort it, so every later write on this + // connection joins it, reports success, and vanishes on close. There is no + // committing this transaction now, so discard it. + db._spStack.length = 0; + try { + rollbackIfNeeded(); + } catch (abortError) { + // The release failure below is the one worth reporting, but a failed + // abort leaves SQLite holding a transaction the next crank would + // silently write into. Nothing here can repair that. + logger?.error( + 'failed to discard transaction after release', + abortError, + ); + } + throw error; + } db._spStack.splice(idx); if (db._spStack.length === 0) { commitIfNeeded(); diff --git a/packages/kernel-store/src/sqlite/wasm.test.ts b/packages/kernel-store/src/sqlite/wasm.test.ts index 2cbc96d65..1cf496dc9 100644 --- a/packages/kernel-store/src/sqlite/wasm.test.ts +++ b/packages/kernel-store/src/sqlite/wasm.test.ts @@ -488,7 +488,6 @@ describe('makeSQLKernelDatabase', () => { ); expect(mockDb._spStack).toStrictEqual([]); - mockDb._inTx = false; }); it('releaseSavepoint validates savepoint exists', async () => { @@ -518,6 +517,126 @@ describe('makeSQLKernelDatabase', () => { expect(mockDb._inTx).toBe(false); }); + // The hazard `rollbackSavepoint` guards against, by the other door. + it('releaseSavepoint discards the transaction when the release fails', async () => { + const db = await makeSQLKernelDatabase({}); + mockDb._inTx = true; + mockDb._spStack = ['point1']; + mockDb.exec.mockImplementationOnce(() => { + throw new Error('disk I/O error'); + }); + + expect(() => db.releaseSavepoint('point1')).toThrowError( + 'disk I/O error', + ); + + expect(mockDb._spStack).toStrictEqual([]); + expect(mockDb._inTx).toBe(false); + }); + + it('releaseSavepoint reports the release 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.releaseSavepoint('point1')).toThrowError( + 'disk I/O error', + ); + + expect(mockDb._inTx).toBe(false); + }); + + // A failed abort is the one case that can leave `_inTx` disagreeing with the + // database. Left true, `beginIfNeeded` is a no-op forever after. + it('stops believing it is in a transaction when 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._inTx).toBe(false); + }); + + // Why that matters: a savepoint created outside a transaction commits when + // released (Agoric/agoric-sdk#8423), so an aborted crank would keep its + // writes. + it('begins a transaction for the next savepoint after a failed abort', 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', + ); + + mockDb.exec.mockClear(); + mockStatement.step.mockClear(); + db.createSavepoint('next'); + + // BEGIN is the only prepared statement `createSavepoint` runs; the + // SAVEPOINT itself goes through `exec`. + expect(mockStatement.step).toHaveBeenCalledOnce(); + expect(mockDb.exec).toHaveBeenCalledWith('SAVEPOINT next'); + }); + + // FAILING REPRO. + // + // `commitIfNeeded` still steps the COMMIT before clearing `_inTx`, the exact + // ordering `rollbackIfNeeded` was corrected to avoid. A COMMIT that throws + // therefore leaves `_inTx` true against a database that may hold no + // transaction, `beginIfNeeded` is a no-op forever after, and the next + // savepoint is created outside a transaction — which commits when released + // (Agoric/agoric-sdk#8423). This is the crank's commit point, so the writes + // that leak are a whole crank's. + // + // A failed abort is therefore not, as the abort case above claims, the one + // case that can leave `_inTx` disagreeing with the database. This is the + // second. + it('stops believing it is in a transaction when the commit fails', async () => { + const db = await makeSQLKernelDatabase({}); + mockDb._inTx = true; + mockDb._spStack = ['point1']; + // The RELEASE goes through `exec` and succeeds; COMMIT is the first + // prepared statement this path steps, and it is what fails. + mockStatement.step.mockImplementationOnce(() => { + throw new Error('disk I/O error'); + }); + + expect(() => db.releaseSavepoint('point1')).toThrowError( + 'disk I/O error', + ); + + expect(mockDb._inTx).toBe(false); + + // And so the next savepoint gets a transaction of its own rather than + // being created bare. + mockDb.exec.mockClear(); + mockStatement.step.mockClear(); + db.createSavepoint('next'); + expect(mockStatement.step).toHaveBeenCalledOnce(); + expect(mockDb.exec).toHaveBeenCalledWith('SAVEPOINT next'); + }); + it('supports nested savepoints', async () => { const db = await makeSQLKernelDatabase({}); db.createSavepoint('outer'); diff --git a/packages/kernel-store/src/sqlite/wasm.ts b/packages/kernel-store/src/sqlite/wasm.ts index c0c32b8a7..a047d6cbc 100644 --- a/packages/kernel-store/src/sqlite/wasm.ts +++ b/packages/kernel-store/src/sqlite/wasm.ts @@ -199,9 +199,13 @@ export async function makeSQLKernelDatabase({ */ function commitIfNeeded(): void { if (db._inTx && db._spStack.length === 0) { + // Cleared before the commit is attempted, for the reason `rollbackIfNeeded` + // gives: a throwing COMMIT would otherwise wedge `_inTx` true, and every + // later savepoint would be created bare — where its RELEASE commits + // (Agoric/agoric-sdk#8423) and no rollback can undo the delivery. + db._inTx = false; sqlCommitTransaction.step(); sqlCommitTransaction.reset(); - db._inTx = false; } } @@ -210,10 +214,16 @@ export async function makeSQLKernelDatabase({ */ function rollbackIfNeeded(): void { if (db._inTx) { - sqlAbortTransaction.step(); - sqlAbortTransaction.reset(); + // Cleared before the abort is attempted, because the abort can throw and + // `_inTx` is tracked here rather than read from SQLite as the nodejs driver + // does. Left true, `beginIfNeeded` is a no-op forever after and writes + // autocommit one statement at a time (see `createSavepoint`). Cleared, a + // still-open transaction surfaces as a failed `BEGIN` — the louder + // failure. db._inTx = false; db._spStack.length = 0; + sqlAbortTransaction.step(); + sqlAbortTransaction.reset(); } } @@ -380,8 +390,14 @@ export async function makeSQLKernelDatabase({ db._spStack.length = 0; try { rollbackIfNeeded(); - } catch { - // The rollback failure below is the one worth reporting. + } catch (abortError) { + // The rollback failure below is the one worth reporting. The next + // `BEGIN` will fail if SQLite really is still in a transaction, but that + // is a crank away and this is where the evidence is. + logger?.error( + 'failed to discard transaction after rollback', + abortError, + ); } throw error; } @@ -403,7 +419,28 @@ export async function makeSQLKernelDatabase({ 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: left as + // it was, the savepoint stays on the stack and the transaction open with + // nothing to ever commit or abort it, so every later write on this + // connection joins it, reports success, and vanishes on close. There is no + // committing this transaction now, so discard it. + db._spStack.length = 0; + try { + rollbackIfNeeded(); + } catch (abortError) { + // The release failure below is the one worth reporting. The next + // `BEGIN` will fail if SQLite really is still in a transaction, but that + // is a crank away and this is where the evidence is. + logger?.error( + 'failed to discard transaction after release', + abortError, + ); + } + 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..36131a8a1 100644 --- a/packages/kernel-test/src/crank-rollback.test.ts +++ b/packages/kernel-test/src/crank-rollback.test.ts @@ -138,6 +138,106 @@ describe('crank rollback against a real database', () => { expect(kdb.kernelKVStore.get('second')).toBe('yes'); }); + // An aborted crank still owes work after the rollback — terminating the vat, + // collecting garbage — whose writes have to survive it. + 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'); + }); + + // And survive it *inside the crank's transaction*, not as autocommitted + // statements. Rolling back `crank` is the only way to observe that 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(); + }); + + // Every `provideCachedStoredValue` keeps its value in a closure and writes + // through to kv, so a rollback that only reverts the database leaves the cache + // holding the abandoned crank's value — and the next `set` persists it. The GC + // action set is the case that matters: `processGCActionSet` consumes an action + // before delivering it, so losing the rollback loses the action outright. + 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', + ]); + }); + + // Same closure, same failure: a reap scheduled and then consumed by a crank + // that rolls back must still be pending afterwards. + 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(); + }); + + // `maybeFreeKrefs` is RAM-only, so nothing rolls it back. Left populated, the + // next crank's `collectGarbage` visits krefs whose decrements were undone — + // and `getKernelPromise` throws outright for one the rollback deleted, which + // kills the run loop. + 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` + // while the rollback removes the promise record it names. + 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(); + }); + // `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. diff --git a/packages/kernel-test/src/garbage-collection.test.ts b/packages/kernel-test/src/garbage-collection.test.ts index 67055414f..2fc1dc160 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); diff --git a/packages/ocap-kernel/CHANGELOG.md b/packages/ocap-kernel/CHANGELOG.md index 1cab9b17e..4c363fd23 100644 --- a/packages/ocap-kernel/CHANGELOG.md +++ b/packages/ocap-kernel/CHANGELOG.md @@ -66,6 +66,19 @@ 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 ([#1021](https://github.com/MetaMask/ocap-kernel/pull/1021)) + - A crank now takes two savepoints, `crank` and `delivery`, and rolls back only `delivery`. Rolling back the outermost one ends the transaction, so terminating the vat and collecting garbage — which follow the rollback and must survive it — were autocommitting a statement at a time + - Buffered vat outputs are flushed after that work rather than before it, so a later failure can no longer roll the crank back underneath an answer already given. Termination still settles the dying vat's own promises immediately +- A failing `endCrank` no longer replaces the error that killed the run loop; it is reported with that error as its `cause`, as the rollback path already did ([#1021](https://github.com/MetaMask/ocap-kernel/pull/1021)) + - Now that the delivery rollback spares the `crank` savepoint, `endCrank`'s release is a real RELEASE and COMMIT on the dying path where it used to be a no-op — and the run loop called it from a bare `finally` +- 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/MetaMask/ocap-kernel/pull/1021)) + - Both release inside the `try` and roll back in the `catch`, so once a failed RELEASE discarded the whole savepoint stack, the rollback reported a savepoint that no longer existed in place of the real error. The rollback is still attempted: a release that failed for a reason of its own may well have left the savepoint standing +- Forget a crank's savepoints when the store call that ends them fails, in both `rollbackCrank` and `endCrank` ([#1021](https://github.com/MetaMask/ocap-kernel/pull/1021)) + - A failed rollback or release discards the whole transaction, savepoints included. Keeping them listed had `endCrank` throw `No such savepoint: t0` from the run loop's `finally`, over whatever really killed the kernel +- `rollbackCrank` now also reverts the two pieces of state a database rollback cannot reach, whether or not the rollback itself succeeded: every cached stored value is re-read, and the crank's accumulated garbage-collection candidates are discarded ([#1021](https://github.com/MetaMask/ocap-kernel/pull/1021)) + - A cached stored value answers reads from a closure and only writes through to the database, so reverting the database left it holding the abandoned crank's value and the next write persisted that. `processGCActionSet` takes an action out of the set before delivering it, so an aborted delivery lost the action outright instead of retrying it + - `maybeFreeKrefs` lives in RAM, so nothing reverted it either. Its entries are collection candidates only because of decrements the rollback undid, and a later `collectGarbage` threw outright on a promise the rollback had deleted, killing the run loop + - A failed rollback discards the whole transaction, moving the database back at least as far as a successful rollback would have — so reverting only on success left exactly the state that is least able to tolerate it - 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/KernelQueue.test.ts b/packages/ocap-kernel/src/KernelQueue.test.ts index 1b3bd4a35..9e4de322e 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; @@ -92,6 +110,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 +163,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 +192,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 +231,170 @@ describe('KernelQueue', () => { expect(kernelStore.collectGarbage).toHaveBeenCalled(); expect(kernelStore.endCrank).toHaveBeenCalled(); }); + + // Why the flush comes after the crank's fallible work: see + // `#processCrankResult`. Here the terminate is what fails. + 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(); + // Told the result will never come, rather than left waiting on a crank the + // store no longer has any record of. + expect(reject).toHaveBeenCalledWith( + expect.objectContaining({ cause: terminationError }), + ); + }); + + // The same invariant inside the flush: `#enqueueRun` is store work and can + // fail part-way, so no caller may be answered until all of it lands. + 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(); + }); + + // Why two savepoints: see `#runLoop`. This pins that the rollback spares the + // transaction, so the work an aborted crank still owes stays inside it. + 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 +487,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 +558,43 @@ describe('KernelQueue', () => { }); }); + // FAILING REPRO. + // + // The companion of the case above, at the other end of the crank. Since the + // delivery rollback now spares `crank`, `endCrank`'s release is a real + // RELEASE + COMMIT on the dying path where it used to be a no-op, and + // `#runLoop` calls it from a bare `finally` — so when it throws it replaces + // the error that killed the kernel instead of being reported alongside it. + 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); + + // However the release failure is named, the error that actually killed the + // kernel has to stay reachable — as the rollback path already manages. + 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, @@ -839,7 +1076,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); }); @@ -875,7 +1112,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); @@ -945,11 +1182,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(); @@ -984,11 +1217,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 afda8139c..f4e1eff9f 100644 --- a/packages/ocap-kernel/src/KernelQueue.ts +++ b/packages/ocap-kernel/src/KernelQueue.ts @@ -56,14 +56,10 @@ 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 a second + * attempt could only report "no such savepoint" over the real error. Recorded + * at the attempt rather than returned, because `#processCrankResult` can throw + * after rolling back. */ #crankRollbackAttempted: boolean = false; @@ -126,17 +122,25 @@ export class KernelQueue { ): Promise { for (;;) { let wakeUpPromise: Promise | undefined; + // Boxed rather than left `undefined`, so that a crank which threw + // `undefined` is still distinguishable from one that did not throw. + let crankFailure: { error: unknown } | undefined; 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. + // `releaseAllSavepoints` names it by ordinal, so `crank` must stay first. + 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) { @@ -153,15 +157,14 @@ 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. + // The original failure stays the `cause`; 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,8 +173,11 @@ export class KernelQueue { } throw error; } + } catch (error) { + crankFailure = { error }; + throw error; } finally { - this.#kernelStore.endCrank(); + this.#endCrank(crankFailure); if (wakeUpPromise) { await wakeUpPromise; } @@ -179,6 +185,31 @@ export class KernelQueue { } } + /** + * End the crank without losing the error that is already unwinding. Since the + * delivery rollback now spares `crank`, `endCrank`'s release is a real RELEASE + * and COMMIT on the dying path, where it used to be a no-op — and from a bare + * `finally` a failing one would silently replace whatever killed the kernel. + * + * @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; + } + // The original failure stays the `cause`, as on the rollback path; the + // release failure is named here. + throw new Error( + `Run loop died and its crank could not be ended: ${String(endCrankError)}`, + { cause: crankFailure.error }, + ); + } + } + /** * Record the death of the run loop and fail the kernel's own message-result * subscriptions, which would otherwise hang forever. Kernel promises in the @@ -304,13 +335,11 @@ 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, so + // a second attempt would report a missing savepoint as the reason the + // kernel died, burying the error that actually killed it. this.#crankRollbackAttempted = true; } // Discard kernel subscriptions that were queued for invocation @@ -333,17 +362,29 @@ 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 call kills the worker, so its writes must outlive the rollback above: + // a store that still believed the vat was alive would relaunch it after a + // restart and redeliver what killed it. if (crankResult?.terminate) { const { vatId, info } = crankResult.terminate; await this.#terminateVat(vatId, info); } this.#kernelStore.collectGarbage(); + if (!crankResult?.abort) { + // After the fallible work above, not before it. The flush settles the + // promise `enqueueMessage` gave an external caller, so a later rollback + // would discard the state that answer was computed from. + // + // Not airtight: `#terminateVat` resolves the dying vat's promises through + // `resolvePromises`, which defaults to `immediate` and invokes their + // subscriptions before `collectGarbage`. Deferring those too would change + // termination semantics, not crank ordering. + this.#flushCrankBuffer(); + } + // After the flush, because the audit reads the run queue as ground truth + // while a buffered item's references were already counted when it was + // enqueued: audited mid-flush, every buffered item reads as a leak. this.#kernelStore.assertRefCountsIfAuditing(); } @@ -371,21 +412,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..90f4ef3bc 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,34 @@ describe('RemoteHandle', () => { }); }); + // `handleRemoteMessage` releases its savepoint inside the `try` and rolls + // back in the `catch`. #1012 made a failed `RELEASE` discard the whole + // savepoint stack, so that rollback reports a savepoint that no longer + // exists, and left unguarded it throws out of the `catch` in place of the + // failure that brought it there. + 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'], + }); + + // The error an operator needs is the one the database gave, not the + // bookkeeping artefact of trying to clean up after it. + await expect(remote.handleRemoteMessage(delivery)).rejects.toBe( + releaseFailure, + ); + // Still attempted, so that abandoning the rollback is not a way to pass + // this test: a release that failed for a reason of its own may well have + // left the savepoint standing. + expect(rollbackSavepoint).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..34181df66 100644 --- a/packages/ocap-kernel/src/remotes/kernel/RemoteHandle.ts +++ b/packages/ocap-kernel/src/remotes/kernel/RemoteHandle.ts @@ -1032,7 +1032,19 @@ export class RemoteHandle implements EndpointHandle { 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); + try { + this.#kernelStore.rollbackSavepoint(savepointName); + } catch (rollbackError) { + // The release above is inside the `try`, and a failed RELEASE discards + // the whole savepoint stack — so this rollback reports a savepoint that + // is already gone, over the database failure an operator actually needs. + // Still attempted, because a release that failed for a reason of its own + // may well have left the savepoint standing. + this.#logger.error( + `${this.#peerId.slice(0, 8)}:: rollback of ${savepointName} failed`, + rollbackError, + ); + } throw error; } diff --git a/packages/ocap-kernel/src/remotes/kernel/RemoteManager.test.ts b/packages/ocap-kernel/src/remotes/kernel/RemoteManager.test.ts index 29ca0b2da..c3257d85d 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'; @@ -948,5 +949,44 @@ describe('RemoteManager', () => { // mutations would otherwise drift from the rolled-back kv view. expect(finalizeSpy).not.toHaveBeenCalled(); }); + + // The same shape `RemoteHandle.handleRemoteMessage` has: the release sits + // inside the `try` and the rollback in the `catch`, so a failed RELEASE — + // which discards the whole savepoint stack — leaves the rollback naming a + // savepoint that is gone. + 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; + + // The error an operator needs is the one the database gave, not the + // bookkeeping artefact of trying to clean up after it. + await expect(onIncarnationChange(peerId, 'incarnation-A')).rejects.toBe( + releaseFailure, + ); + // Still attempted, so that abandoning the rollback is not a way to pass: + // a release that failed for a reason of its own may well have left the + // savepoint standing. + 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..9a477cf39 100644 --- a/packages/ocap-kernel/src/remotes/kernel/RemoteManager.ts +++ b/packages/ocap-kernel/src/remotes/kernel/RemoteManager.ts @@ -261,7 +261,16 @@ export class RemoteManager { this.#kernelStore.setPeerIncarnation(peerId, observedIncarnation); this.#kernelStore.releaseSavepoint(savepoint); } catch (error) { - this.#kernelStore.rollbackSavepoint(savepoint); + try { + this.#kernelStore.rollbackSavepoint(savepoint); + } catch (rollbackError) { + // The release above is inside the `try`, and a failed RELEASE discards + // the whole savepoint stack — so this rollback reports a savepoint that + // is already gone, over the database failure an operator actually needs. + // Still attempted, because a release that failed for a reason of its own + // may well have left the savepoint standing. + this.#logger?.error(`Rollback of ${savepoint} failed`, rollbackError); + } throw error; } diff --git a/packages/ocap-kernel/src/store/index.ts b/packages/ocap-kernel/src/store/index.ts index 8e082aa8b..436a21cc8 100644 --- a/packages/ocap-kernel/src/store/index.ts +++ b/packages/ocap-kernel/src/store/index.ts @@ -89,7 +89,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'; /** * Create a new KernelStore object wrapped around a raw kernel database. The @@ -115,6 +115,48 @@ export function makeKernelStore(kdb: KernelDatabase, logger?: Logger) { const { 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: adding one here does both. + */ + 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}, reading its + * current setting out of the database. + * + * @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. */ @@ -125,14 +167,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 one closes over + * the last value written through it (see `provideCachedStoredValue`), so + * reverting the database alone is not enough: the closure would 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 @@ -144,17 +188,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'] }), @@ -214,23 +250,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 }) => { diff --git a/packages/ocap-kernel/src/store/methods/crank.test.ts b/packages/ocap-kernel/src/store/methods/crank.test.ts index db3de8645..426890d20 100644 --- a/packages/ocap-kernel/src/store/methods/crank.test.ts +++ b/packages/ocap-kernel/src/store/methods/crank.test.ts @@ -17,6 +17,8 @@ describe('crank methods', () => { savepoints: [], crankBuffer: mockCrankBuffer, refreshRunQueue: vi.fn(), + refreshCachedValues: vi.fn(), + maybeFreeKrefs: new Set(), } as unknown as StoreContext; kdb = { @@ -153,6 +155,69 @@ describe('crank methods', () => { expect(mockCrankBuffer).toHaveLength(0); }); + + // A failed rollback discards every savepoint, not just this one. Truncating + // to the ordinal would have `endCrank` release a `t0` the database lacks and + // throw over whatever really killed the kernel. + 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([]); + // The release `endCrank` would otherwise attempt, and throw over. + crankMethods.endCrank(); + expect(kdb.releaseSavepoint).not.toHaveBeenCalled(); + }); + + // The two halves of this function compose the wrong way round if the + // failure path simply rethrows: 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 the caches it left behind are + // at least as stale. + it('reverts the caches the database cannot reach even when the rollback fails', () => { + context.inCrank = true; + context.maybeFreeKrefs.add('kp1'); + 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.refreshCachedValues).toHaveBeenCalled(); + expect(context.refreshRunQueue).toHaveBeenCalled(); + expect(context.runQueueLengthCache).toBe(-1); + expect([...context.maybeFreeKrefs]).toStrictEqual([]); + }); + + // Reverting must not become a way to lose the database error either. + 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', () => { @@ -206,6 +271,21 @@ describe('crank methods', () => { expect(context.resolveCrank).toBeUndefined(); expect(await waiter).toBeUndefined(); }); + + // As `rollbackCrank` does. Left listed, the next crank numbers its savepoint + // `t1` against a database that has none, and every later release and rollback + // aims one crank past its target. + 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', () => { diff --git a/packages/ocap-kernel/src/store/methods/crank.ts b/packages/ocap-kernel/src/store/methods/crank.ts index 87d2bc65b..a3bba1956 100644 --- a/packages/ocap-kernel/src/store/methods/crank.ts +++ b/packages/ocap-kernel/src/store/methods/crank.ts @@ -51,34 +51,84 @@ export function getCrankMethods(ctx: StoreContext, kdb: KernelDatabase) { if (ctx.savepoints[ordinal] === 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. + // Left listed, `endCrank`'s release would commit the crank we just + // abandoned. ctx.savepoints.length = ordinal; + } catch (error) { + // A failed rollback discards the whole transaction, so every savepoint + // is gone, not just this one. Truncating to `ordinal` would have + // `endCrank` release a `t0` the database lacks and throw over whatever + // really killed the kernel. + 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(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(); 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 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(rollbackError?: unknown): void { + try { + // Recreate the run queue so its cached head/tail are re-read from the + // database, and invalidate the length cache, since the rollback may have + // restored dequeued items. + ctx.refreshRunQueue(); + ctx.runQueueLengthCache = -1; + // Same staleness, worse consequence: a cached value reads from its + // closure and only writes through to kv, so one this crank consumed stays + // consumed and the next `set` persists that. `processGCActionSet` takes an + // action out of the set before delivering it, so an action not restored + // here is lost rather than retried. + ctx.refreshCachedValues(); + // Nothing rolls back RAM. These krefs are collection candidates only + // because this crank decremented them, and that is precisely what was 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. Correct only while every rollback discards the whole delivery, + // which is all any caller asks for. + ctx.maybeFreeKrefs.clear(); + } 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 { + // A failed release discards the transaction too, so the database has no + // savepoints left either. Left listed, the next crank would number its + // savepoint `t1` and aim every later release and rollback one crank past + // the one it meant to end. + ctx.savepoints.length = 0; + } } } diff --git a/packages/ocap-kernel/src/store/types.ts b/packages/ocap-kernel/src/store/types.ts index 3bf54862f..b9886c174 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 diff --git a/packages/ocap-kernel/test/savepoint-stack.ts b/packages/ocap-kernel/test/savepoint-stack.ts new file mode 100644 index 000000000..c4b7e587f --- /dev/null +++ b/packages/ocap-kernel/test/savepoint-stack.ts @@ -0,0 +1,53 @@ +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 #1012 and verified against both: a + * failed RELEASE clears the savepoint stack, and rolling back 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 rollbackSavepoint = vi.fn((name: string) => { + if (!savepoints.includes(name)) { + throw new Error(`No such savepoint: ${name}`); + } + }); + return { + kernelStore: { + ...kernelStore, + createSavepoint: (name: string) => { + savepoints.push(name); + }, + releaseSavepoint: () => { + savepoints.length = 0; + throw releaseFailure; + }, + rollbackSavepoint, + }, + releaseFailure, + rollbackSavepoint, + }; +}