Skip to content

Commit 428dd6c

Browse files
rkistnerrkistner
committed
More logging; working tests.
1 parent f3b5709 commit 428dd6c

File tree

6 files changed

+233
-48
lines changed

6 files changed

+233
-48
lines changed

‎packages/wa-sqlite-driver/package.json‎

Lines changed: 6 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -17,17 +17,18 @@
1717
"dependencies": {
1818
"@journeyapps/wa-sqlite": "^1.3.2",
1919
"@sqlite-js/driver": "workspace:^",
20-
"async-mutex": "^0.5.0"
20+
"async-mutex": "^0.5.0",
21+
"wa-sqlite": "^1.0.0"
2122
},
2223
"devDependencies": {
23-
"vite-plugin-top-level-await": "^1.4.2",
24-
"vite-plugin-wasm": "^3.3.0",
2524
"@sqlite-js/driver-tests": "workspace:^",
2625
"@types/node": "^24.9.1",
27-
"typescript": "^5.9.3",
2826
"@vitest/browser": "^2.0.5",
29-
"vitest": "^2.0.5",
3027
"playwright": "^1.45.3",
28+
"typescript": "^5.9.3",
29+
"vite-plugin-top-level-await": "^1.4.2",
30+
"vite-plugin-wasm": "^3.3.0",
31+
"vitest": "^2.0.5",
3132
"webdriverio": "^8.39.1"
3233
}
3334
}

‎packages/wa-sqlite-driver/src/pool.ts‎

Lines changed: 8 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -12,13 +12,17 @@ import { WorkerDriverConnection } from './worker_threads';
1212

1313
export function waSqliteSingleWorker(path: string): SqliteDriverConnectionPool {
1414
return new LazyConnectionPool(async () => {
15-
const connection = new WorkerDriverConnection(
16-
new Worker(new URL('./wa-sqlite-worker.js', import.meta.url), {
15+
const worker = new Worker(
16+
new URL('./wa-sqlite-worker.js', import.meta.url),
17+
{
1718
type: 'module'
18-
}),
19-
{ path }
19+
}
2020
);
21+
const connection = new WorkerDriverConnection(worker, { path });
2122
await connection.open();
23+
(connection as any).terminate = () => {
24+
worker.terminate();
25+
};
2226
return connection;
2327
});
2428
}

‎packages/wa-sqlite-driver/src/wa-sqlite-worker.ts‎

Lines changed: 28 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -1,22 +1,42 @@
11
import { OPFSCoopSyncVFS2 } from './OPFSCoopSyncVFS2';
22
import { sqlite3, module, WaSqliteConnection } from './wa-sqlite-driver';
33
import { setupDriverWorker } from './worker_threads';
4-
5-
let vfs: OPFSCoopSyncVFS2 | null = null;
4+
import { IDBBatchAtomicVFS } from '@journeyapps/wa-sqlite/src/examples/IDBBatchAtomicVFS.js';
5+
import { OPFSAdaptiveVFS } from '@journeyapps/wa-sqlite/src/examples/OPFSAdaptiveVFS.js';
6+
import { OPFSPermutedVFS } from '@journeyapps/wa-sqlite/src/examples/OPFSPermutedVFS.js';
7+
let vfs: any | null = null;
68
setupDriverWorker({
79
async openConnection(options) {
810
// Register a custom file system.
911
if (vfs != null) {
1012
throw new Error('Can only open one connection');
1113
}
12-
vfs = await OPFSCoopSyncVFS2.create(
13-
'test.db',
14-
module,
15-
options.readonly ?? false
16-
);
14+
// vfs = await OPFSCoopSyncVFS2.create(
15+
// 'test.db',
16+
// module,
17+
// options.readonly ?? false
18+
// );
19+
// IDBBatchAtomicVFS - breaks hard (database disk image is malformed)
20+
// vfs = await (IDBBatchAtomicVFS as any).create('test.db', module);
21+
// OPFSAdaptiveVFS - works great
22+
// vfs = await (OPFSAdaptiveVFS as any).create('test.db', module, {
23+
// ifAvailable: true,
24+
// mode: 'shared'
25+
// });
26+
// vfs = await (OPFSAdaptiveVFS as any).create('test.db', module, {
27+
// ifAvailable: true,
28+
// mode: 'shared'
29+
// });
30+
31+
// database disk image is malformed
32+
vfs = await (OPFSPermutedVFS as any).create('test.db', module);
33+
1734
// @ts-ignore
1835
sqlite3.vfs_register(vfs as any, true);
1936

20-
return await WaSqliteConnection.open(options.path, vfs);
37+
const con = await WaSqliteConnection.open(options.path, vfs);
38+
using stmt = await con.prepare('PRAGMA busy_timeout = 10000');
39+
await stmt.step();
40+
return con;
2141
}
2242
});

‎packages/wa-sqlite-driver/test/src/mptest-runner.test.ts‎

Lines changed: 161 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -203,6 +203,7 @@ class MptestRunner {
203203
if (taskControl.isResolved()) {
204204
return;
205205
}
206+
this.logError(`task failure client=${clientId}`, err);
206207
taskControl.reject(err);
207208
throw err;
208209
});
@@ -236,13 +237,15 @@ class MptestRunner {
236237
}
237238
const waitPromise = Promise.all(promises).then(() => undefined);
238239
if (timeoutMs <= 0) {
239-
await waitPromise;
240+
await this.withProgress(waitPromise, label);
240241
return;
241242
}
242243
let handle: ReturnType<typeof setTimeout> | undefined;
244+
let progressHandle: ReturnType<typeof setInterval> | undefined;
243245
try {
246+
progressHandle = this.createProgressLogger(label, timeoutMs);
244247
await Promise.race([
245-
waitPromise,
248+
this.withProgress(waitPromise, label, progressHandle),
246249
new Promise((_, reject) => {
247250
handle = setTimeout(
248251
() =>
@@ -257,9 +260,57 @@ class MptestRunner {
257260
if (handle) {
258261
clearTimeout(handle);
259262
}
263+
if (progressHandle) {
264+
clearInterval(progressHandle);
265+
}
266+
}
267+
}
268+
269+
private createProgressLogger(
270+
label: string,
271+
timeoutMs: number
272+
): ReturnType<typeof setInterval> {
273+
const start = Date.now();
274+
return setInterval(
275+
() => {
276+
const elapsed = Date.now() - start;
277+
const pending = this.describePending();
278+
console.log(
279+
`[wait] ${label} elapsed=${elapsed}ms timeout=${timeoutMs}ms pending=${pending}`
280+
);
281+
},
282+
Math.min(1000, Math.max(250, timeoutMs / 10))
283+
);
284+
}
285+
286+
private async withProgress(
287+
promise: Promise<unknown>,
288+
label: string,
289+
progressHandle?: ReturnType<typeof setInterval>
290+
): Promise<void> {
291+
try {
292+
await promise;
293+
} finally {
294+
if (progressHandle) {
295+
clearInterval(progressHandle);
296+
}
260297
}
261298
}
262299

300+
private describePending(): string {
301+
const entries: string[] = [];
302+
for (const [clientId, client] of this.clients.entries()) {
303+
const size = client.pending.size;
304+
if (size > 0) {
305+
entries.push(`client${clientId}:${size}`);
306+
}
307+
}
308+
if (entries.length === 0) {
309+
return 'none';
310+
}
311+
return entries.join(',');
312+
}
313+
263314
private async runScriptInternal(
264315
context: ScriptContext,
265316
script: string,
@@ -292,10 +343,12 @@ class MptestRunner {
292343
}
293344
if (index > begin) {
294345
const sqlChunk = script.slice(begin, index);
346+
this.logSqlChunk(context, prevLine, sqlChunk);
295347
await this.executeSql(context, sqlChunk, result);
296348
}
297349
let consumed = token.length;
298350
const command = parseCommand(script, index, token.length);
351+
this.logCommand(context, prevLine, command.name, command.payload);
299352
switch (command.name) {
300353
case 'sleep':
301354
await sleepMs(Number(command.args[0] ?? '0'));
@@ -308,14 +361,17 @@ class MptestRunner {
308361
throw new Error(
309362
`${context.displayName}:${prevLine} expected [${expectedRaw}] but got [${result.toString()}]`
310363
);
311-
} else {
312-
console.log(
313-
`${context.displayName}:${prevLine} expected [${expectedRaw}] matched [${result.toString()}]`
314-
);
315364
}
316365
result.reset();
317366
break;
318367
}
368+
case 'print': {
369+
const message = command.payload.replace(/^\s*/, '');
370+
if (message.length > 0) {
371+
this.logMessage(context, message);
372+
}
373+
break;
374+
}
319375
case 'task': {
320376
const clientId = Number(command.args[0]);
321377
if (!Number.isInteger(clientId) || clientId < 0) {
@@ -346,9 +402,15 @@ class MptestRunner {
346402
taskControl?.resolve();
347403
break;
348404
}
405+
case 'exit': {
406+
const code = Number(command.args[0] ?? '0');
407+
taskControl?.resolve();
408+
await this.terminateClient(context, code);
409+
return;
410+
}
349411
case 'wait': {
350412
const target = command.args[0] ?? 'all';
351-
const timeout = command.args[1] ? Number(command.args[1]) : 10000;
413+
const timeout = command.args[1] ? Number(command.args[1]) : 30_000;
352414
if (target === 'all') {
353415
await this.waitForAll(timeout);
354416
} else {
@@ -411,6 +473,7 @@ class MptestRunner {
411473
}
412474
if (begin < script.length) {
413475
const remainder = script.slice(begin);
476+
this.logSqlChunk(context, line, remainder);
414477
await this.executeSql(context, remainder, result);
415478
}
416479
}
@@ -464,6 +527,7 @@ class MptestRunner {
464527
const { rows } = await statement.step();
465528
if (rows) {
466529
const rawRows = rows as SqliteRowRaw[];
530+
this.logSqlExecution(context, sql, rawRows);
467531
for (const row of rawRows) {
468532
for (const value of row) {
469533
result.append(value);
@@ -472,20 +536,108 @@ class MptestRunner {
472536
}
473537
} catch (err) {
474538
if (isSqliteError(err)) {
539+
this.logError('sqlite error', err);
475540
result.appendError(err);
476541
} else {
542+
this.logError('sql execution error', err);
477543
throw err;
478544
}
479545
} finally {
480546
statement.finalize();
481547
}
482548
}
483549
}
550+
551+
private logMessage(context: ScriptContext, message: string): void {
552+
const trimmed = message.replace(/\s+$/, '');
553+
if (!trimmed) {
554+
return;
555+
}
556+
console.log(`${context.displayName} ${trimmed}`);
557+
}
558+
559+
private logCommand(
560+
context: ScriptContext,
561+
line: number,
562+
command: string,
563+
payload: string
564+
): void {
565+
const detail = payload ? ` ${payload.trim()}` : '';
566+
console.log(`${context.displayName}:${line} --${command}${detail}`);
567+
}
568+
569+
private logSqlChunk(
570+
context: ScriptContext,
571+
line: number,
572+
chunk: string
573+
): void {
574+
const summary = chunk.trim().replace(/\s+/g, ' ');
575+
if (!summary) {
576+
return;
577+
}
578+
console.log(`${context.displayName}:${line} SQL ${summary}`);
579+
}
580+
581+
private logError(prefix: string, err: unknown): void {
582+
if (err instanceof Error) {
583+
console.error(`[error] ${prefix}: ${err.message}\n${err.stack}`);
584+
} else {
585+
console.error(`[error] ${prefix}: ${String(err)}`);
586+
}
587+
}
588+
589+
private logSqlExecution(
590+
context: ScriptContext,
591+
placeholder: string,
592+
values: SqliteRowRaw[]
593+
): void {
594+
console.log(
595+
`${context.displayName} SQL values ${placeholder} => ${JSON.stringify(values)}`
596+
);
597+
}
598+
599+
private async terminateClient(
600+
context: ScriptContext,
601+
exitCode: number
602+
): Promise<void> {
603+
const { clientId, displayName } = context;
604+
const client = this.clients.get(clientId);
605+
if (!client) {
606+
return;
607+
}
608+
this.clients.delete(clientId);
609+
try {
610+
await client.reserved.release();
611+
} catch (err) {
612+
this.logError(`release error client=${clientId}`, err);
613+
if (exitCode === 0) {
614+
throw err;
615+
}
616+
}
617+
try {
618+
await client.pool.close();
619+
} catch (err) {
620+
this.logError(`close error client=${clientId}`, err);
621+
if (exitCode === 0) {
622+
throw err;
623+
}
624+
}
625+
if (exitCode !== 0) {
626+
console.log(`${displayName} exited with code ${exitCode}`);
627+
}
628+
}
484629
}
485630

486-
describe('mptest scripts', () => {
631+
describe('mptest scripts', { timeout: 60_000 }, () => {
487632
// const scripts = topLevelScripts;
488-
const scripts = ['mptest/multiwrite01.test'];
633+
// const scripts = ['mptest/multiwrite01.test'];
634+
// const scripts = ['mptest/config02.test'];
635+
// const scripts = ['mptest/crash01.test'];
636+
const scripts = [
637+
// 'mptest/multiwrite01.test',
638+
'mptest/config02.test'
639+
// 'mptest/crash01.test'
640+
];
489641
for (const script of scripts) {
490642
test(script, async () => {
491643
const dbPath = `mptest-${sanitizeForFilename(script)}-${Math.random()

0 commit comments

Comments
 (0)