fix(plugins): report a plugin SQL call done once its last statement has run

The time budget for an exec script was read after every statement, the
last one included. A single statement without args, or a script whose
closing COMMIT crossed the budget, had already run and committed, yet the
call threw a time budget error. A plugin that retries on error then wrote
the same rows a second time.

The script now reads the clock before each statement after the first, so
it still stops before the next statement once the time is up and rolls
back a transaction it opened, but a script whose statements have all run
is reported as done. query() likewise reads the clock only once another
row has come back, so a result read to its end is returned.

The ctx.db doc in the SDK said a single statement was not timed, which
contradicted the query budget. It now names what is really untimed: an
exec with bound args and migrate. README and wiki describe the script
stopping before its next statement.

plugin-sdk/README.md

@@ -252,7 +252,7 @@ for a legitimate plugin and only bite a runaway or abusive one — build against
 | `ctx.ai` | 200 calls/day per plugin (UTC midnight rollover); past it throws `"daily AI budget exhausted (resets at UTC midnight)"` |
 | `ctx.notify` | 100 calls/day per plugin (UTC midnight rollover); past it throws `"daily notification budget exhausted (resets at UTC midnight)"` |
 | RPC (every `ctx.*` call) | burst 60, sustained 20/s, 16 in-flight per plugin; a throttled call is refused with `HOST_ERROR: rate limit exceeded — slow down ctx.* calls` |
-| `ctx.db` (your own sqlite) | 256 MB per plugin; a `query` or `tx` returns at most 100,000 rows (a whole `tx` batch shares one count). A `query`, a whole `tx` batch and an `exec` script without bound args each have 2 s of wall-clock time, checked between the rows a statement reads and between the statements of a batch or script; past either limit the call throws (`query exceeded its 2000 ms time budget`), a `tx` rolls back, and an `exec` script stops after the statement that ran out of time (the statements before it stay applied, as they always did, and a transaction the script opened itself is rolled back). Split a longer script over several calls, or batch it with `tx`. `migrate` has no time budget, since a migration stopped part of the way would fail again on every start. `ATTACH`, `DETACH`, `VACUUM`, `PRAGMA`, `WITH RECURSIVE` and `load_extension` are refused. The budget cannot stop a single statement, because SQLite runs it on TREK's main thread in one step: a write runs to its end (an `INSERT ... SELECT` over a cross join of large tables), and a read runs until its first row (an aggregate over one). Keep your statements indexed and bounded |
+| `ctx.db` (your own sqlite) | 256 MB per plugin; a `query` or `tx` returns at most 100,000 rows (a whole `tx` batch shares one count). A `query`, a whole `tx` batch and an `exec` script without bound args each have 2 s of wall-clock time, checked between the rows a statement reads and between the statements of a batch or script; past either limit the call throws (`query exceeded its 2000 ms time budget`), a `tx` rolls back, and an `exec` script stops before its next statement once the time is up (the statements that ran stay applied, as they always did, and a transaction the script opened itself is rolled back; a script whose last statement has run counts as done, however long it took). Split a longer script over several calls, or batch it with `tx`. `migrate` has no time budget, since a migration stopped part of the way would fail again on every start. `ATTACH`, `DETACH`, `VACUUM`, `PRAGMA`, `WITH RECURSIVE` and `load_extension` are refused. The budget cannot stop a single statement, because SQLite runs it on TREK's main thread in one step: a write runs to its end (an `INSERT ... SELECT` over a cross join of large tables), and a read runs until its first row (an aggregate over one). Keep your statements indexed and bounded |
 | `ctx.meta` | 64 KB per value, 256 chars per key, 100 keys per (plugin, entity) |
 | Plugin process | 300 MB RSS ceiling; auto-disabled after 5 crashes in 5 minutes |
 | Event redelivery buffer | 200 events held per plugin, dropped unreplayed after 15 minutes |

plugin-sdk/src/index.ts

@@ -74,8 +74,10 @@ export interface PluginContext {
    * path or connection to directly. Quota: 256 MB per plugin (writes past it fail);
    * result sets are capped at 100,000 rows, and a `query`, a `tx` or an `exec` script
    * without args gets 2 s of wall-clock time, checked between the rows it reads and
-   * the statements it runs (past it, it throws, a `tx` rolls back and a script stops).
-   * A single statement and `migrate` are not timed.
+   * the statements it runs (past it, it throws, a `tx` rolls back and a script stops
+   * before its next statement). An `exec` with bound args (one statement) and
+   * `migrate` are not timed, and no single statement can be stopped midway (a read
+   * only between its rows).
    * See `tx()` below for the atomic-batch cap and README § Runtime limits. */
   db: {
     query<T = unknown>(sql: string, ...args: unknown[]): Promise<T[]>;

server/src/nest/plugins/host/plugin-data.service.ts

@@ -129,12 +129,13 @@ export class PluginDataDb {
     const checkTime = this.startBudget('query');
     // iterate() pulls one row at a time, so a recursive CTE that would yield
     // unboundedly is halted at the cap instead of materializing via all(), and the
-    // clock is read between rows.
+    // clock is read between rows. It is read only once another row has come back, so
+    // a result that has been read to its end is returned, however long that took.
     const rows: unknown[] = [];
     for (const row of this.db.prepare(sql).iterate(...(args as never[]))) {
+      if (rows.length > 0) checkTime();
       rows.push(row);
       if (rows.length > maxRows) throw new Error(`query returned more than ${maxRows} rows`);
-      checkTime();
     }
     return rows;
   }
@@ -142,7 +143,7 @@ export class PluginDataDb {
   /**
    * Write statement(s). With bound args, exec() runs one statement. Without, it runs a
    * script of any number (e.g. a small setup script), one statement at a time and
-   * within the time budget, checked after each statement.
+   * within the time budget, checked before each statement after the first.
    */
   exec(sql: string, args: unknown[] = []): { changes: number } {
     this.guard(sql);
@@ -156,27 +157,33 @@ export class PluginDataDb {
 
   /**
    * Runs a script the way `Database#exec` did (statement after statement, each in
-   * autocommit unless the script opens a transaction), with `checkTime` read after
-   * every statement. A trigger body is gathered until SQLite stops calling it
-   * incomplete. A script that runs out of time inside a transaction it opened itself
-   * has that transaction rolled back, so the connection is not left holding it.
+   * autocommit unless the script opens a transaction), with `checkTime` read before
+   * every statement but the first. The clock is never read after the last one, so a
+   * script whose statements have all run (and committed) is reported as done. A
+   * trigger body is gathered until SQLite stops calling it incomplete. A script that
+   * runs out of time inside a transaction it opened itself has that transaction rolled
+   * back, so the connection is not left holding it.
    */
   private runScript(sql: string, checkTime: () => void): void {
     const openedNoTransaction = !this.db.inTransaction;
     let pending = '';
+    let ranOne = false;
     for (const piece of splitAfterSemicolons(sql)) {
       pending += piece;
       const stmt = this.prepareComplete(pending);
       if (stmt === 'incomplete') continue;
       pending = '';
       if (stmt === 'empty') continue;
-      stmt.run();
-      try {
-        checkTime();
-      } catch (e) {
-        if (openedNoTransaction && this.db.inTransaction) this.db.prepare('ROLLBACK').run();
-        throw e;
+      if (ranOne) {
+        try {
+          checkTime();
+        } catch (e) {
+          if (openedNoTransaction && this.db.inTransaction) this.db.prepare('ROLLBACK').run();
+          throw e;
+        }
       }
+      stmt.run();
+      ranOne = true;
     }
     // A statement still open at the end of the script: prepare it once more for
     // SQLite's own error, as Database#exec reports it.

server/tests/unit/plugins/plugin-data.test.ts

@@ -106,12 +106,24 @@ describe('PluginDataDb', () => {
     return () => (t += step);
   };
 
+  /**
+   * A clock that answers `reads` in order and repeats the last value after that. Set
+   * `reads` right before a call to say what each of its clock reads sees.
+   */
+  const scriptedClock = () => {
+    const clock = {
+      reads: [0] as number[],
+      now: () => (clock.reads.length > 1 ? (clock.reads.shift() as number) : (clock.reads[0] ?? 0)),
+    };
+    return clock;
+  };
+
   it('stops a query at the first row past its time budget', () => {
     const db = new PluginDataDb('budget-query', { timeBudgetMs: 100, now: steppingClock(30) });
     db.exec('CREATE TABLE seq (n INTEGER)');
     db.exec('INSERT INTO seq (n) VALUES ' + Array.from({ length: 50 }, (_, i) => `(${i})`).join(','));
-    // The start reads the clock and each row reads it again, 30 ms later every time:
-    // at the fourth row the call is 120 ms in, past the budget.
+    // The start reads the clock and every row after the first reads it again, 30 ms
+    // later every time: at the fifth row the call is 120 ms in, past the budget.
     expect(() => db.query('SELECT n FROM seq')).toThrow('query exceeded its 100 ms time budget');
     // A query that finishes inside the budget is untouched.
     expect(db.query('SELECT n FROM seq WHERE n < 2 ORDER BY n')).toEqual([{ n: 0 }, { n: 1 }]);
@@ -141,13 +153,14 @@ describe('PluginDataDb', () => {
   it('holds an exec script to the time budget between its statements', () => {
     const db = new PluginDataDb('budget-exec', { timeBudgetMs: 80, now: steppingClock(30) });
     db.exec('CREATE TABLE log (n INTEGER)');
-    // Start, then one read after each statement: 30, 60, then 90 ms after the third
-    // insert. The script stops there and the fourth insert never runs. Each statement
-    // committed on its own, as Database#exec ran them, so the three stay.
+    // Start, then one read before each statement after the first: 30, 60, then 90 ms
+    // before the fourth insert. The script stops there and the fourth insert never
+    // runs. Each statement committed on its own, as Database#exec ran them, so the
+    // three stay.
     expect(() =>
       db.exec('INSERT INTO log VALUES (1); INSERT INTO log VALUES (2); INSERT INTO log VALUES (3); INSERT INTO log VALUES (4);'),
     ).toThrow('exec exceeded its 80 ms time budget');
-    // One row back, so the check itself reads the clock once and stays in budget.
+    // One row back, so the check itself reads the clock only at its start.
     expect(db.query('SELECT group_concat(n) AS ns FROM (SELECT n FROM log ORDER BY n)')).toEqual([{ ns: '1,2,3' }]);
     // A script that opened its own transaction and ran out of time inside it is rolled
     // back, so the connection is not left in that transaction.
@@ -160,6 +173,40 @@ describe('PluginDataDb', () => {
     db.close();
   });
 
+  it('reports a call whose last statement or row ran past the budget as done', () => {
+    const clock = scriptedClock();
+    const db = new PluginDataDb('budget-last', { timeBudgetMs: 100, now: clock.now });
+    db.exec('CREATE TABLE log (n INTEGER)');
+    // A single statement without args: the clock is read at the start only, so a
+    // slow insert that has run and committed is not reported as failed.
+    clock.reads = [0, 1000];
+    expect(db.exec('INSERT INTO log VALUES (1)')).toEqual({ changes: 0 });
+    // A script whose closing COMMIT is what takes the time: the reads before the
+    // INSERT and before the COMMIT are in budget, and nothing is read after it.
+    clock.reads = [0, 0, 0, 1000];
+    expect(db.exec('BEGIN; INSERT INTO log VALUES (2); COMMIT;')).toEqual({ changes: 0 });
+    clock.reads = [0];
+    expect(db.query('SELECT n FROM log ORDER BY n')).toEqual([{ n: 1 }, { n: 2 }]);
+    // The same budget running out before the COMMIT still stops the script and rolls
+    // the transaction back.
+    clock.reads = [0, 0, 1000];
+    expect(() => db.exec('BEGIN; INSERT INTO log VALUES (3); COMMIT;')).toThrow('exec exceeded its 100 ms time budget');
+    clock.reads = [0];
+    expect(db.query('SELECT count(*) AS c FROM log')).toEqual([{ c: 2 }]);
+    // A query read to its end is returned, even when its last row came in late: the
+    // clock is read after the second row only, and not again once the rows run out.
+    clock.reads = [0, 0, 1000];
+    expect(db.query('SELECT n FROM log ORDER BY n')).toEqual([{ n: 1 }, { n: 2 }]);
+    // A query stopped early leaves the connection free for the next call.
+    db.exec('INSERT INTO log VALUES (3)');
+    clock.reads = [0, 1000];
+    expect(() => db.query('SELECT n FROM log ORDER BY n')).toThrow('query exceeded its 100 ms time budget');
+    clock.reads = [0];
+    db.exec('INSERT INTO log VALUES (4)');
+    expect(db.query('SELECT count(*) AS c FROM log')).toEqual([{ c: 4 }]);
+    db.close();
+  });
+
   it('runs an exec script statement by statement with the semantics Database#exec had', () => {
     const db = new PluginDataDb('exec-script');
     db.exec(`

wiki/Plugin-Development.md

@@ -412,7 +412,7 @@ stores blobs in `ctx.db` runs into, so build against them.
 | Area | Limit |
 |---|---|
 | every `ctx.*` call | burst 60, sustained 20/s, 16 in-flight per plugin; a throttled call is refused with `HOST_ERROR: rate limit exceeded — slow down ctx.* calls`. Tunable with `TREK_PLUGIN_RPC_BURST` / `TREK_PLUGIN_RPC_PER_SEC` / `TREK_PLUGIN_RPC_INFLIGHT` (see [Environment-Variables](Environment-Variables#plugins)) |
-| `ctx.db` | 256 MB per plugin; a `query` or a whole `tx` batch returns at most 100,000 rows. A `query`, a whole `tx` batch and an `exec` script without bound args each get 2 s of wall-clock time, checked between the rows a statement reads and between the statements of a batch or script (past it the call throws `query exceeded its 2000 ms time budget`, a `tx` rolls back, and an `exec` script stops after the statement that ran out of time, keeping the ones before it and rolling back a transaction the script opened itself). `migrate` is not timed, since a migration stopped part of the way would fail again on every start. A single statement cannot be stopped midway, because SQLite runs it on TREK's main thread: a write such as `INSERT ... SELECT` over a cross join of large tables runs to its end, and a read that yields nothing until it is finished (an aggregate over one) runs to its first row. Keep your statements indexed and bounded |
+| `ctx.db` | 256 MB per plugin; a `query` or a whole `tx` batch returns at most 100,000 rows. A `query`, a whole `tx` batch and an `exec` script without bound args each get 2 s of wall-clock time, checked between the rows a statement reads and between the statements of a batch or script (past it the call throws `query exceeded its 2000 ms time budget`, a `tx` rolls back, and an `exec` script stops before its next statement once the time is up, keeping the ones that ran and rolling back a transaction the script opened itself; a script whose last statement has run counts as done). `migrate` is not timed, since a migration stopped part of the way would fail again on every start. A single statement cannot be stopped midway, because SQLite runs it on TREK's main thread: a write such as `INSERT ... SELECT` over a cross join of large tables runs to its end, and a read that yields nothing until it is finished (an aggregate over one) runs to its first row. Keep your statements indexed and bounded |
 | event subscriptions | 200 events buffered per plugin while it restarts, dropped unreplayed after 15 minutes |
 | the plugin process | 300 MB RSS (`TREK_PLUGIN_MAX_RSS_MB`) — the child is killed past it; auto-disabled with status `error` after 5 crashes inside a 5-minute window |