fix: keep a crank's store work inside one transaction

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]

packages/kernel-browser-runtime/src/kernel-worker/kernel-worker.ts

@@ -44,7 +44,10 @@ async function main(): Promise<void> {
         isJsonRpcMessage,
       ),
       PlatformServicesClient.make(globalThis as PostMessageTarget),
-      makeSQLKernelDatabase({ dbFilename: DB_FILENAME }),
+      makeSQLKernelDatabase({
+        dbFilename: DB_FILENAME,
+        logger: logger.subLogger({ tags: ['kernel-store'] }),
+      }),
     ]);
 
   setupConsoleForwarding({

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]

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) }),
+    );
+  });
 });

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, {

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]
 

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');

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();

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');

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();