|
| 1 | +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. |
| 2 | + |
| 3 | +/** |
| 4 | + * #7842 — executes the ambient-vs-bare split that `MetadataManager`'s |
| 5 | + * `listCache` policy comment asserts. |
| 6 | + * |
| 7 | + * PR #7840 (#7708) re-anchored that comment onto a fresh measurement instead of |
| 8 | + * a retired witness, and the measurement NARROWED the hazard rather than |
| 9 | + * retiring it: on a real `ObjectQL` + real `SqlDriver` (better-sqlite3, |
| 10 | + * `:memory:`, knex pool max 1), a metadata read issued while a transaction is |
| 11 | + * open stalls out `acquireConnectionTimeout` — but ONLY when the transaction was |
| 12 | + * opened somewhere the engine's ambient `txStore` (ADR-0034) cannot see it. A |
| 13 | + * transaction opened through `engine.transaction()` is published into that store, |
| 14 | + * `buildDriverOptions` threads it onto the loader's read, and the read returns at |
| 15 | + * once on the connection the transaction already holds. |
| 16 | + * |
| 17 | + * That split lived only in a code comment and in PR prose, so nothing noticed if |
| 18 | + * `buildDriverOptions`' ambient fallback, `DatabaseLoader._find()`'s option |
| 19 | + * forwarding, or the SQLite pool config changed underneath it — at which point |
| 20 | + * the comment silently becomes the next stale witness, which is the defect #7708 |
| 21 | + * existed to repair. This file is the executable half. It PINS current behaviour |
| 22 | + * and changes none of it. |
| 23 | + * |
| 24 | + * ## The 60-second problem, and what this fixture does about it |
| 25 | + * |
| 26 | + * The negative direction is an acquire timeout, and knex's default is 60s — a |
| 27 | + * 60-second test in the shared suite is worse than the gap it closes. The |
| 28 | + * fixture's driver therefore declares its own short `acquireConnectionTimeout` |
| 29 | + * ({@link ACQUIRE_MS}); `SqlDriverConfig` is `Knex.Config &` extras and the |
| 30 | + * constructor forwards everything it does not itself consume, so the knob |
| 31 | + * arrives at knex untouched. That shortens the WAIT, not the SHAPE: the read |
| 32 | + * still fails on connection acquisition, with knex's own message, exactly as it |
| 33 | + * does in production at 60s. `assertEffectiveTimeout` re-reads the value off the |
| 34 | + * live knex client so a driver that stopped forwarding it cannot leave this test |
| 35 | + * quietly measuring the default. |
| 36 | + * |
| 37 | + * ## Why the positive case asserts three things and not one |
| 38 | + * |
| 39 | + * "The read completed" passes trivially if no transaction was ever open — the |
| 40 | + * test would then guard nothing while appearing to guard the whole hazard. So |
| 41 | + * inside the callback all three of PR #7840's own false-negative checks are |
| 42 | + * asserted: the driver counts one open transaction, the ambient store carries a |
| 43 | + * handle, and — the load-bearing one — the `sys_metadata` read is observed |
| 44 | + * ARRIVING AT THE DRIVER with that handle in its options. Only the third |
| 45 | + * distinguishes "the ambient store was threaded onto the loader's read" from |
| 46 | + * "the read happened to succeed on its own". |
| 47 | + * |
| 48 | + * Worked precedent: `sql-driver-sqlite-tx-guard.test.ts`, which keeps the |
| 49 | + * driver's own `parentTrx` contract honest the same way. This lives in |
| 50 | + * `packages/runtime` because it is the only package carrying `objectql` + |
| 51 | + * `driver-sql` + `metadata` in one dependency closure. |
| 52 | + */ |
| 53 | + |
| 54 | +import { describe, it, expect, afterEach, vi } from 'vitest'; |
| 55 | +import { ObjectQL } from '@objectstack/objectql'; |
| 56 | +import { SqlDriver } from '@objectstack/driver-sql'; |
| 57 | +import { DatabaseLoader } from '@objectstack/metadata'; |
| 58 | +import { SysMetadataObject } from '@objectstack/metadata-core'; |
| 59 | + |
| 60 | +/** |
| 61 | + * The fixture's acquire bound, replacing knex's 60s default. |
| 62 | + * |
| 63 | + * Long enough that a loaded CI box cannot mistake scheduling jitter for a |
| 64 | + * timeout, short enough that the negative case costs well under a second. |
| 65 | + */ |
| 66 | +const ACQUIRE_MS = 400; |
| 67 | + |
| 68 | +/** Upper bound for the negative case — an order of magnitude under knex's 60s default. */ |
| 69 | +const STALL_CEILING_MS = 20_000; |
| 70 | + |
| 71 | +/** The seeded row `list('object')` must come back with. */ |
| 72 | +const SEEDED_NAME = 'thing'; |
| 73 | + |
| 74 | +interface Fixture { |
| 75 | + engine: ObjectQL; |
| 76 | + driver: SqlDriver; |
| 77 | + loader: DatabaseLoader; |
| 78 | + /** Every `driver.find` the fixture has observed, and whether it carried a transaction. */ |
| 79 | + reads: () => Array<{ object: string; hasTx: boolean }>; |
| 80 | +} |
| 81 | + |
| 82 | +let fixture: Fixture | null = null; |
| 83 | + |
| 84 | +afterEach(async () => { |
| 85 | + vi.restoreAllMocks(); |
| 86 | + try { |
| 87 | + await fixture?.engine.destroy(); |
| 88 | + } catch { |
| 89 | + /* teardown is best-effort — a stalled pool must not mask the assertion */ |
| 90 | + } |
| 91 | + fixture = null; |
| 92 | +}); |
| 93 | + |
| 94 | +async function boot(): Promise<Fixture> { |
| 95 | + const driver = new SqlDriver({ |
| 96 | + client: 'better-sqlite3', |
| 97 | + connection: { filename: ':memory:' }, |
| 98 | + useNullAsDefault: true, |
| 99 | + // See the header: shortens the wait, not the shape. |
| 100 | + acquireConnectionTimeout: ACQUIRE_MS, |
| 101 | + }); |
| 102 | + await driver.initObjects([SysMetadataObject as any]); |
| 103 | + |
| 104 | + // Seeded through the driver rather than the engine: `sys_metadata` is |
| 105 | + // `managedBy: 'engine-owned'`, and this row is fixture state, not a write |
| 106 | + // whose path is under test. |
| 107 | + await driver.create('sys_metadata', { |
| 108 | + id: 'md_fixture_1', |
| 109 | + type: 'object', |
| 110 | + name: SEEDED_NAME, |
| 111 | + scope: 'platform', |
| 112 | + metadata: JSON.stringify({ name: SEEDED_NAME }), |
| 113 | + }); |
| 114 | + |
| 115 | + const engine = new ObjectQL(); |
| 116 | + engine.registerDriver(driver, true); |
| 117 | + await engine.init(); |
| 118 | + // The engine's own proxy, not `engine.registry.registerObject` — the registry |
| 119 | + // method requires a `packageId` and the proxy supplies one, so this keeps the |
| 120 | + // fixture out of the package's TEST_DEBT ledger (`check:type-check-debt`). |
| 121 | + engine.registerObject(SysMetadataObject as any); |
| 122 | + |
| 123 | + // `cache: { enabled: false }` is what makes every `list()` below a real |
| 124 | + // database read; with the loader's own read-through cache on, the second call |
| 125 | + // would be answered from memory and would never reach the pool at all. |
| 126 | + const loader = new DatabaseLoader({ |
| 127 | + engine: engine as any, |
| 128 | + cache: { enabled: false }, |
| 129 | + }); |
| 130 | + |
| 131 | + // Flush `ensureSchema()` OUTSIDE any transaction. On the engine path it runs |
| 132 | + // the `project_id` → `environment_id` forward migration on a bare connection |
| 133 | + // and swallows its own failure, so leaving it to the measured call would put |
| 134 | + // one extra acquire timeout inside the number the negative case reports. |
| 135 | + // Doubles as the issue's `control` row: no transaction open, read returns. |
| 136 | + const control = await loader.list('object'); |
| 137 | + expect(control).toEqual([SEEDED_NAME]); |
| 138 | + |
| 139 | + const spy = vi.spyOn(driver, 'find'); |
| 140 | + fixture = { |
| 141 | + engine, |
| 142 | + driver, |
| 143 | + loader, |
| 144 | + reads: () => |
| 145 | + spy.mock.calls.map((call) => ({ |
| 146 | + object: call[0] as string, |
| 147 | + hasTx: (call[2] as { transaction?: unknown } | undefined)?.transaction !== undefined, |
| 148 | + })), |
| 149 | + }; |
| 150 | + return fixture; |
| 151 | +} |
| 152 | + |
| 153 | +/** |
| 154 | + * The two facts the hazard is made of, re-read off the LIVE knex client. |
| 155 | + * |
| 156 | + * `pool.max === 1` is why a second connection is unobtainable; the acquire bound |
| 157 | + * is why this test costs 0.4s instead of 60s. Asserting both here means a change |
| 158 | + * to the SQLite pool config, or a driver that stops forwarding the knob, fails |
| 159 | + * with the reason named rather than as a mysterious green (nothing to stall) or |
| 160 | + * a mysterious hang (back at the default). |
| 161 | + */ |
| 162 | +function assertEffectiveTimeout(driver: SqlDriver): void { |
| 163 | + const client = (driver as any).knex.client; |
| 164 | + expect(client.pool.max).toBe(1); |
| 165 | + expect(client.config.acquireConnectionTimeout).toBe(ACQUIRE_MS); |
| 166 | +} |
| 167 | + |
| 168 | +describe('#7842 metadata list under an open transaction: ambient vs bare (real ObjectQL + real SqlDriver)', () => { |
| 169 | + it('AMBIENT — a transaction opened via engine.transaction() is threaded onto the loader read, which completes', async () => { |
| 170 | + const { engine, driver, loader, reads } = await boot(); |
| 171 | + assertEffectiveTimeout(driver); |
| 172 | + |
| 173 | + const before = reads().length; |
| 174 | + let names: string[] = []; |
| 175 | + |
| 176 | + const started = Date.now(); |
| 177 | + await engine.transaction(async () => { |
| 178 | + // ── False-negative guard 1: a transaction really is open on the driver. |
| 179 | + // Without this, "the read completed" also passes when `engine.transaction` |
| 180 | + // silently degraded to a no-transaction path and there was never a |
| 181 | + // single-connection hazard to survive. |
| 182 | + expect((driver as any).activeTransactions).toBe(1); |
| 183 | + |
| 184 | + // ── False-negative guard 2: it is published into the engine's ambient |
| 185 | + // store (ADR-0034), which is the only thing `buildDriverOptions` can find |
| 186 | + // when the caller passes no explicit handle — as the loader does not. |
| 187 | + const ambient = (engine as any).txStore.getStore(); |
| 188 | + expect(ambient?.transaction).toBeDefined(); |
| 189 | + |
| 190 | + names = await loader.list('object'); |
| 191 | + }); |
| 192 | + const elapsed = Date.now() - started; |
| 193 | + |
| 194 | + // The read returned real rows — not an empty degradation that would also |
| 195 | + // satisfy "it completed". |
| 196 | + expect(names).toEqual([SEEDED_NAME]); |
| 197 | + |
| 198 | + // ── False-negative guard 3, the load-bearing one. The other two prove a |
| 199 | + // transaction existed; only this proves the ambient store was THREADED onto |
| 200 | + // the loader's read. Everything else here stays green if |
| 201 | + // `buildDriverOptions` stops consulting `txStore` and the read merely runs |
| 202 | + // on some other connection. |
| 203 | + const inTx = reads().slice(before).filter((r) => r.object === 'sys_metadata'); |
| 204 | + expect(inTx.length).toBeGreaterThan(0); |
| 205 | + expect(inTx.every((r) => r.hasTx)).toBe(true); |
| 206 | + |
| 207 | + // And it did not stall on the way: the whole ambient case finishes inside |
| 208 | + // the acquire bound the bare case exhausts. |
| 209 | + expect(elapsed).toBeLessThan(STALL_CEILING_MS); |
| 210 | + }); |
| 211 | + |
| 212 | + it('BARE — a transaction opened directly on the driver is invisible to the ambient store, and the loader read stalls out connection acquisition', async () => { |
| 213 | + const { engine, driver, loader, reads } = await boot(); |
| 214 | + assertEffectiveTimeout(driver); |
| 215 | + |
| 216 | + const before = reads().length; |
| 217 | + const trx = await driver.beginTransaction(); |
| 218 | + try { |
| 219 | + // Same first guard as above: the transaction is genuinely open and |
| 220 | + // genuinely holding the pool's only connection. |
| 221 | + expect((driver as any).activeTransactions).toBe(1); |
| 222 | + // ...and nothing published it into the engine's ambient store, which is |
| 223 | + // the entire difference between the two cases. |
| 224 | + expect((engine as any).txStore.getStore()).toBeUndefined(); |
| 225 | + |
| 226 | + const started = Date.now(); |
| 227 | + await expect(loader.list('object')).rejects.toThrow(/Timeout acquiring a connection/i); |
| 228 | + const elapsed = Date.now() - started; |
| 229 | + |
| 230 | + // It failed by WAITING on the pool, not instantly for some other reason... |
| 231 | + expect(elapsed).toBeGreaterThanOrEqual(ACQUIRE_MS / 2); |
| 232 | + // ...and the fixture's bound, not knex's 60s default, is what ended the wait. |
| 233 | + expect(elapsed).toBeLessThan(STALL_CEILING_MS); |
| 234 | + |
| 235 | + // The negative direction's own false-negative guard: the read really was |
| 236 | + // attempted and really did reach the driver — WITHOUT a transaction |
| 237 | + // handle. A rejection alone cannot tell "nothing threaded the caller's |
| 238 | + // transaction" apart from "the read never went out". |
| 239 | + const bare = reads().slice(before).filter((r) => r.object === 'sys_metadata'); |
| 240 | + expect(bare.length).toBeGreaterThan(0); |
| 241 | + expect(bare.every((r) => !r.hasTx)).toBe(true); |
| 242 | + } finally { |
| 243 | + await driver.rollback(trx); |
| 244 | + } |
| 245 | + }); |
| 246 | +}); |
0 commit comments