From 0078734644e51c3c84962619189affc64b0340bd Mon Sep 17 00:00:00 2001 From: TimelordUK Date: Thu, 15 Oct 2026 18:25:25 +0100 Subject: [PATCH 1/4] test: event contract corpus, and handover of the 5.6.0 event regressions Adds test/contract: scenarios whose exact sequence of events (submitted, meta, row, column, info, error, done, free, callbacks, cancel callbacks) is pinned in corpus/ as reviewable transcripts, with capture.js to record and compare them (including against another build) and contract.test.js to enforce them. Each run is in its own process, so hangs, runaways and crashes stay contained. The corpus currently pins what 5.6.0 does, bugs included (status: unreviewed), covering #478 - #481 plus a crash found on pause/resume every row. The issue repros are in test/contract/repro and the findings in test/contract/HANDOVER.md. Co-Authored-By: Claude Opus 5.5 --- test/contract/HANDOVER.md | 111 ++++++++ test/contract/README.md | 52 ++++ test/contract/capture.js | 77 ++++++ test/contract/contract.test.js | 32 +++ test/contract/corpus.js | 105 +++++++ .../corpus/cancel/before-execute.events.txt | 11 + .../corpus/cancel/during-execute.callback.txt | 11 + .../corpus/cancel/during-execute.events.txt | 11 + .../corpus/cancel/last-row.events.txt | 13 + .../corpus/cancel/late-after-free.events.txt | 13 + .../cancel/paused-before-execute.events.txt | 23 ++ .../cancel/paused-streaming-at-100.events.txt | 13 + .../streaming-after-print-at-100.events.txt | 16 ++ .../corpus/cancel/streaming-at-100.events.txt | 13 + .../corpus/errors/bind-failure.callback.txt | 9 + .../corpus/errors/bind-failure.events.txt | 9 + .../corpus/errors/dup-key-a.callback.txt | 9 + .../corpus/errors/dup-key-a.events.txt | 9 + .../corpus/errors/dup-key-b.callback.txt | 12 + .../corpus/errors/dup-key-b.events.txt | 12 + .../corpus/errors/dup-key-c.callback.txt | 20 ++ .../corpus/errors/dup-key-c.events.txt | 17 ++ .../corpus/errors/dup-key-d.callback.txt | 16 ++ .../corpus/errors/dup-key-d.events.txt | 14 + .../errors/print-then-raiserror.callback.txt | 8 + .../errors/print-then-raiserror.events.txt | 8 + .../raiserror-after-result.callback.txt | 10 + .../errors/raiserror-after-result.events.txt | 10 + .../errors/raiserror-at-execute.callback.txt | 7 + .../errors/raiserror-at-execute.events.txt | 7 + .../errors/raiserror-then-result.callback.txt | 14 + .../errors/raiserror-then-result.events.txt | 12 + .../corpus/errors/syntax.callback.txt | 7 + test/contract/corpus/errors/syntax.events.txt | 7 + .../errors/throw-ends-batch.callback.txt | 10 + .../corpus/errors/throw-ends-batch.events.txt | 10 + .../two-raiserrors-then-result.callback.txt | 23 ++ .../two-raiserrors-then-result.events.txt | 17 ++ .../corpus/pause/before-execute.events.txt | 12 + .../corpus/pause/every-row.events.txt | 166 +++++++++++ .../corpus/pause/two-by-51-at-1.events.txt | 15 + .../corpus/pause/two-by-51-at-101.events.txt | 15 + .../corpus/pause/two-by-51-at-102.events.txt | 15 + .../corpus/pause/two-by-51-at-49.events.txt | 15 + .../corpus/pause/two-by-51-at-50.events.txt | 15 + .../corpus/pause/two-by-51-at-51.events.txt | 13 + .../corpus/pause/two-by-51-at-52.events.txt | 15 + ...bind-failure-then-two-on-free.callback.txt | 23 ++ ...ind-failure-then-two-on-start.callback.txt | 36 +++ ...after-result-then-two-on-free.callback.txt | 20 ++ ...fter-result-then-two-on-start.callback.txt | 23 ++ ...execute-then-cancel-follow-up.callback.txt | 17 ++ ...r-at-execute-then-two-on-free.callback.txt | 18 ++ ...-at-execute-then-two-on-start.callback.txt | 21 ++ .../ok-then-cancel-follow-up.callback.txt | 17 ++ .../queue/ok-then-two-on-free.callback.txt | 25 ++ .../queue/ok-then-two-on-start.callback.txt | 25 ++ .../corpus/read/insert-rowcount.callback.txt | 10 + .../corpus/read/insert-rowcount.events.txt | 9 + .../read/insert-then-select.callback.txt | 14 + .../corpus/read/insert-then-select.events.txt | 12 + .../contract/corpus/read/no-rows.callback.txt | 9 + test/contract/corpus/read/no-rows.events.txt | 8 + .../contract/corpus/read/one-row.callback.txt | 11 + test/contract/corpus/read/one-row.events.txt | 10 + test/contract/corpus/read/param.callback.txt | 12 + test/contract/corpus/read/param.events.txt | 11 + .../corpus/read/print-only.callback.txt | 10 + .../corpus/read/print-only.events.txt | 9 + .../read/print-then-select.callback.txt | 14 + .../corpus/read/print-then-select.events.txt | 12 + test/contract/corpus/read/rows-50.events.txt | 9 + test/contract/corpus/read/rows-51.events.txt | 9 + .../read/select-then-print.callback.txt | 14 + .../corpus/read/select-then-print.events.txt | 12 + .../contract/corpus/read/two-by-51.events.txt | 11 + .../corpus/read/two-result-sets.callback.txt | 15 + .../corpus/read/two-result-sets.events.txt | 13 + .../read/two-rows-two-columns.callback.txt | 15 + .../read/two-rows-two-columns.events.txt | 14 + test/contract/corpus/read/types.callback.txt | 17 ++ test/contract/corpus/read/types.events.txt | 16 ++ test/contract/recorder.js | 261 ++++++++++++++++++ test/contract/repro/common.js | 9 + test/contract/repro/i478.js | 27 ++ test/contract/repro/i479.js | 45 +++ test/contract/repro/i479b.js | 40 +++ test/contract/repro/i480.js | 28 ++ test/contract/repro/i481.js | 65 +++++ test/contract/run-one.js | 24 ++ test/contract/scenarios.js | 120 ++++++++ 91 files changed, 2199 insertions(+) create mode 100644 test/contract/HANDOVER.md create mode 100644 test/contract/README.md create mode 100644 test/contract/capture.js create mode 100644 test/contract/contract.test.js create mode 100644 test/contract/corpus.js create mode 100644 test/contract/corpus/cancel/before-execute.events.txt create mode 100644 test/contract/corpus/cancel/during-execute.callback.txt create mode 100644 test/contract/corpus/cancel/during-execute.events.txt create mode 100644 test/contract/corpus/cancel/last-row.events.txt create mode 100644 test/contract/corpus/cancel/late-after-free.events.txt create mode 100644 test/contract/corpus/cancel/paused-before-execute.events.txt create mode 100644 test/contract/corpus/cancel/paused-streaming-at-100.events.txt create mode 100644 test/contract/corpus/cancel/streaming-after-print-at-100.events.txt create mode 100644 test/contract/corpus/cancel/streaming-at-100.events.txt create mode 100644 test/contract/corpus/errors/bind-failure.callback.txt create mode 100644 test/contract/corpus/errors/bind-failure.events.txt create mode 100644 test/contract/corpus/errors/dup-key-a.callback.txt create mode 100644 test/contract/corpus/errors/dup-key-a.events.txt create mode 100644 test/contract/corpus/errors/dup-key-b.callback.txt create mode 100644 test/contract/corpus/errors/dup-key-b.events.txt create mode 100644 test/contract/corpus/errors/dup-key-c.callback.txt create mode 100644 test/contract/corpus/errors/dup-key-c.events.txt create mode 100644 test/contract/corpus/errors/dup-key-d.callback.txt create mode 100644 test/contract/corpus/errors/dup-key-d.events.txt create mode 100644 test/contract/corpus/errors/print-then-raiserror.callback.txt create mode 100644 test/contract/corpus/errors/print-then-raiserror.events.txt create mode 100644 test/contract/corpus/errors/raiserror-after-result.callback.txt create mode 100644 test/contract/corpus/errors/raiserror-after-result.events.txt create mode 100644 test/contract/corpus/errors/raiserror-at-execute.callback.txt create mode 100644 test/contract/corpus/errors/raiserror-at-execute.events.txt create mode 100644 test/contract/corpus/errors/raiserror-then-result.callback.txt create mode 100644 test/contract/corpus/errors/raiserror-then-result.events.txt create mode 100644 test/contract/corpus/errors/syntax.callback.txt create mode 100644 test/contract/corpus/errors/syntax.events.txt create mode 100644 test/contract/corpus/errors/throw-ends-batch.callback.txt create mode 100644 test/contract/corpus/errors/throw-ends-batch.events.txt create mode 100644 test/contract/corpus/errors/two-raiserrors-then-result.callback.txt create mode 100644 test/contract/corpus/errors/two-raiserrors-then-result.events.txt create mode 100644 test/contract/corpus/pause/before-execute.events.txt create mode 100644 test/contract/corpus/pause/every-row.events.txt create mode 100644 test/contract/corpus/pause/two-by-51-at-1.events.txt create mode 100644 test/contract/corpus/pause/two-by-51-at-101.events.txt create mode 100644 test/contract/corpus/pause/two-by-51-at-102.events.txt create mode 100644 test/contract/corpus/pause/two-by-51-at-49.events.txt create mode 100644 test/contract/corpus/pause/two-by-51-at-50.events.txt create mode 100644 test/contract/corpus/pause/two-by-51-at-51.events.txt create mode 100644 test/contract/corpus/pause/two-by-51-at-52.events.txt create mode 100644 test/contract/corpus/queue/bind-failure-then-two-on-free.callback.txt create mode 100644 test/contract/corpus/queue/bind-failure-then-two-on-start.callback.txt create mode 100644 test/contract/corpus/queue/error-after-result-then-two-on-free.callback.txt create mode 100644 test/contract/corpus/queue/error-after-result-then-two-on-start.callback.txt create mode 100644 test/contract/corpus/queue/error-at-execute-then-cancel-follow-up.callback.txt create mode 100644 test/contract/corpus/queue/error-at-execute-then-two-on-free.callback.txt create mode 100644 test/contract/corpus/queue/error-at-execute-then-two-on-start.callback.txt create mode 100644 test/contract/corpus/queue/ok-then-cancel-follow-up.callback.txt create mode 100644 test/contract/corpus/queue/ok-then-two-on-free.callback.txt create mode 100644 test/contract/corpus/queue/ok-then-two-on-start.callback.txt create mode 100644 test/contract/corpus/read/insert-rowcount.callback.txt create mode 100644 test/contract/corpus/read/insert-rowcount.events.txt create mode 100644 test/contract/corpus/read/insert-then-select.callback.txt create mode 100644 test/contract/corpus/read/insert-then-select.events.txt create mode 100644 test/contract/corpus/read/no-rows.callback.txt create mode 100644 test/contract/corpus/read/no-rows.events.txt create mode 100644 test/contract/corpus/read/one-row.callback.txt create mode 100644 test/contract/corpus/read/one-row.events.txt create mode 100644 test/contract/corpus/read/param.callback.txt create mode 100644 test/contract/corpus/read/param.events.txt create mode 100644 test/contract/corpus/read/print-only.callback.txt create mode 100644 test/contract/corpus/read/print-only.events.txt create mode 100644 test/contract/corpus/read/print-then-select.callback.txt create mode 100644 test/contract/corpus/read/print-then-select.events.txt create mode 100644 test/contract/corpus/read/rows-50.events.txt create mode 100644 test/contract/corpus/read/rows-51.events.txt create mode 100644 test/contract/corpus/read/select-then-print.callback.txt create mode 100644 test/contract/corpus/read/select-then-print.events.txt create mode 100644 test/contract/corpus/read/two-by-51.events.txt create mode 100644 test/contract/corpus/read/two-result-sets.callback.txt create mode 100644 test/contract/corpus/read/two-result-sets.events.txt create mode 100644 test/contract/corpus/read/two-rows-two-columns.callback.txt create mode 100644 test/contract/corpus/read/two-rows-two-columns.events.txt create mode 100644 test/contract/corpus/read/types.callback.txt create mode 100644 test/contract/corpus/read/types.events.txt create mode 100644 test/contract/recorder.js create mode 100644 test/contract/repro/common.js create mode 100644 test/contract/repro/i478.js create mode 100644 test/contract/repro/i479.js create mode 100644 test/contract/repro/i479b.js create mode 100644 test/contract/repro/i480.js create mode 100644 test/contract/repro/i481.js create mode 100644 test/contract/run-one.js create mode 100644 test/contract/scenarios.js diff --git a/test/contract/HANDOVER.md b/test/contract/HANDOVER.md new file mode 100644 index 00000000..8572dbef --- /dev/null +++ b/test/contract/HANDOVER.md @@ -0,0 +1,111 @@ +# Handover: 5.6.0 event regressions (#478 – #481) — 2026-10-15 + +Where the investigation of dhensby's reports stands, and where to pick it up. + +## Summary + +The normal streaming path is fine: plain reads, multiple result sets, and pause/resume part +way through a batch. The **event contract at the edges** is broken: the order of errors and +infos, cancel, pausing at a batch boundary, and the work queue after a failure. node-mssql +drives all of those. Every point in the four issues reproduced on localdb (ODBC 18, Windows). + +No fixes have been made yet. This branch adds: +- `test/contract/`: the event-contract corpus (see `README.md`), 77 scenarios, every one + pinned to what **5.6.0 does today**, bugs included (`# status: unreviewed`); +- `test/contract/repro/`: dhensby's repro scripts from the issues, runnable as they are + (`node test/contract/repro/i480.js`). + +## Issues, as reproduced + +| Issue | Seen on 5.6.0 | 5.5.1 | Corpus scenarios | +|---|---|---|---| +| #478 error/info order | `info 3621` before `error 2627` (A–C); D comes out in driver order | 3621 dropped | `errors/dup-key-*` | +| #479 A running cancel | `done` → cancel-cb → `error HY008` → `free` (`done` too early) | cancel refused | `cancel/streaming-at-100` | +| #479 B late cancel | an extra `done`, then cancel-cb error `empty queue` | refused | `cancel/late-after-free` | +| #479 C cancel after PRINT | cancel-cb **ok**, then all remaining rows stream and a 2nd `done` follows: nothing was cancelled | refused | `cancel/streaming-after-print-at-100` | +| #479 comment, point 4: pause + cancel a polling query | hangs: no `free`, connection stuck | works | polling, so out of the corpus (repro: `i479b.js 4`) | +| #479 comment, point 5: pause + cancel before execute | `free` x2; with polling, an endless `free`/`rowcount 0` loop and a busy connection | `free` x2 | `cancel/paused-before-execute` (repro: `i479b.js 5`) | +| #480 pause on the last row of a batch | the next result set is lost (`[51, 0]`) | same | `pause/two-by-51-at-51` | +| #481 queue advances once too often | follow-ups overlap: `HY000 Connection is busy with results for another command`; B2 cannot cancel | same (since 5.1.0) | `queue/*` | + +Found by the corpus, beyond the issues: +- **Pausing and resuming on every row** (how Node stream back-pressure behaves) **crashes the + process with 0xC0000005 (access violation) in about 1 run in 3** (`pause/every-row`). This is + the worst finding. +- Pausing on the very last row and then resuming: `done`, `free`, then an endless `rowcount 0` + loop (`pause/two-by-51-at-102`). 5.5.1 does the same. This is the open question at the end + of #480. +- Polling, cancel mid-stream: cancel-cb ok, ~1000 more rows, then the connection is busy. + Polling is out of scope for the contract. +- Callback mode: result set 2's `meta` arrives before result set 1's callback + (`read/two-result-sets.callback`), because the callback is deferred with setImmediate in + `connection.query`. + +Against 5.5.1, `capture.js --root <5.5.1>` reports 23 of the 77 scenarios as different: +exactly the error, cancel and pause-on-last-row groups. Reads, the queue and pausing mid-batch +behave the same, so those bugs are older than 5.6.0. + +## node-mssql's own suite + +The tediousjs/node-mssql `test-msnodesqlv8` suite was run against localdb, with this repo +junctioned in as `node_modules/msnodesqlv8`: +- Both master and 12.7.7 fail the **same 6 tests on 5.5.1 and 5.6.0**. Those come from the + environment: ODBC 18 message prefixes, and login/config tests that don't fit localdb. +- On 12.7.7 + 5.6.0, "a cancelled stream emits done event" failed once with + `done() called multiple times` (#479) and passed on a rerun: it depends on timing. +- node-mssql 12.7.8 and later (released 2026-10-15) include their workarounds + (tediousjs/node-mssql#1917). Users on ≤ 12.7.7 with 5.6.0 get the raw behaviour. +- Their test DB has to allow snapshot isolation (their CI uses `master`, which does). + Otherwise their isolation-level test leaves SNAPSHOT on a pooled session and later tests + fail in a cascade. + +So their suite is worth adding to CI, but it would not reliably have caught these. The +corpus is our guard. + +## Suggested order + +1. **The crash on pause/resume on every row.** An untested hypothesis: `resume()` calls + `dispatch()` (or `nextResult()`) while the previous `nativeGetRows` / `nextResultSet` is + still in flight, so two native calls run on one statement at once. Nothing in `reader.js` + stops a second fetch while one is outstanding. #480 is the same family: `dispatch()` and + `resume()` both move to the next result. A first step is an "operation in flight" guard in + `Query`, with `dispatch` / `nextResult` / `resume` going through it, then + `capture.js --repeat 20 every-row`. +2. **#481 queue.** Make finishing an item specific to that item and idempotent + (`WorkQueue.finish(op)`, as in dhensby's option 2). +3. **#480 and the last-row loop.** Likely solved together with 1. +4. **#479 cancel.** `done` only for a cancel that worked, and after the HY008. Report a + refused native cancel (`CancelWorker::OnOK` passes `(null, false)`). The `STATEMENT_ERROR` + that info-only diagnostics set makes a cancel after a PRINT a silent no-op. +5. **#478.** Route each set of diagnostics in driver order. Count `more` over errors only. + +For each one: edit the corpus transcripts to the agreed behaviour first (`# status: agreed`), +watch them fail, then fix. + +## Decisions to make while reviewing the corpus + +- Callback before the next result set's `meta`? (recommended: yes) +- On cancel: `cancel-cb` → `error HY008` → `done` → `free`, or no `done` at all on cancel? + node-mssql asked for `done` on cancel back in #120. +- A cancel that finds nothing to cancel (late, or refused): an error in the cancel callback, + and no other events. +- Should anything ever come after `free`? (recommended: no) + +## Picking up on another machine + +```sh +git fetch && git checkout test/event-contract-corpus +npm run fetch-prebuild # or build +npx mocha test/contract/contract.test.js # ~40 s, expect 77 passing +node test/contract/capture.js pause/ # compare a group, 3 runs each +``` +- The connection comes from `.env-cmdrc` (`CONNECTION_KEY`) as for the other tests. The corpus + was captured with ODBC Driver 18 against `(localdb)\node`, database `scratch`. Another + driver may phrase messages differently; use `..txt` for genuine differences. +- To compare with 5.5.1: `npm i msnodesqlv8@5.5.1` in a scratch folder, then + `capture.js --root /node_modules/msnodesqlv8`. +- node-mssql: clone tediousjs/node-mssql, `npm i`, replace `node_modules/msnodesqlv8` with a + junction to this repo, write `test/.mssql.json` + (`{"connectionString": "...;Database=mssqltest;...", "options": {"trustedConnection": true, "trustServerCertificate": true}}`), + create the DB with `alter database mssqltest set allow_snapshot_isolation on`, then + `npx mocha --exit -t 30000 test/msnodesqlv8`. diff --git a/test/contract/README.md b/test/contract/README.md new file mode 100644 index 00000000..b5978a7c --- /dev/null +++ b/test/contract/README.md @@ -0,0 +1,52 @@ +# Event contract corpus + +Most tests check what a query returns. These check **the exact sequence of events** it +raises — `submitted`, `meta`, `row`, `info`, `error`, `done`, `free`, callbacks, cancel +callbacks — for a growing set of scenarios, including the edge cases (errors part way +through a batch, pause at a batch boundary, cancel at every stage, work queued behind a +failed query). + +Each scenario's expected transcript is a text file in `corpus/`, so a change to the +event order shows up as a diff in review, and the contract can be discussed line by line. + +| File | What it is | +|---|---| +| `scenarios.js` | the scenarios: query, setup, actions (pause / resume / cancel at row n, at start, after n ms, after free), follow-up queries | +| `recorder.js` | runs a scenario and records the transcript; line format documented at the top | +| `corpus.js` | reads / writes / diffs corpus files | +| `capture.js` | CLI to record and compare | +| `contract.test.js` | mocha: every scenario must match its corpus file | +| `run-one.js` | runs one scenario in a child process, so a hang or runaway can't affect the next | + +## Workflow + +```sh +# compare what happens now with the corpus (each scenario 3 times, to catch nondeterminism) +node test/contract/capture.js cancel/ + +# record what happens now (new scenarios, or after an intended change) +node test/contract/capture.js --update dup-key + +# see how another build behaves against the same corpus, e.g. an older release +node test/contract/capture.js --root ../some-dir/node_modules/msnodesqlv8 + +# run as a test +npx mocha test/contract/contract.test.js +``` + +## Status of a transcript + +Each file has `# status: unreviewed` or `# status: agreed`. + +- **unreviewed** — captured from what the driver does today. It pins current behaviour, + bugs included, so that any change is visible. +- **agreed** — someone has read it and it is the contract. To change the contract, edit + the transcript to what it should be and mark it agreed; the test fails until the + driver does that. + +A file may list several accepted transcripts separated by `--- or`, and `capture.js` +marks a scenario `NOT DETERMINISTIC` when runs differ. Treat both as something to fix: +the aim is a predictable API. + +A platform or ODBC driver that legitimately behaves differently can have its own file, +`..txt`. diff --git a/test/contract/capture.js b/test/contract/capture.js new file mode 100644 index 00000000..b3bcb9ee --- /dev/null +++ b/test/contract/capture.js @@ -0,0 +1,77 @@ +'use strict' + +// runs corpus scenarios and shows how each one compares with its expected transcript. +// +// node test/contract/capture.js [filter...] compare, print differences +// node test/contract/capture.js --update [filter] write what happens now into the corpus +// node test/contract/capture.js --print [filter] print each transcript in full +// node test/contract/capture.js --repeat 10 [filter] run each scenario 10 times (default 3) +// node test/contract/capture.js --root use the msnodesqlv8 in , e.g. an +// older release, to see how it differs +// +// a filter matches any part of a scenario name, e.g. 'cancel/' or 'dup-key'. +// the connection string comes from the test environment, as for the mocha tests. + +const path = require('path') +const { TestEnv } = require('../env/test-env') +const { scenarios } = require('./scenarios') +const { captureScenario } = require('./recorder') +const corpus = require('./corpus') + +function parseArgs (argv) { + const opts = { update: false, print: false, repeat: 3, root: path.join(__dirname, '../..'), filters: [] } + for (let i = 0; i < argv.length; i++) { + const a = argv[i] + if (a === '--update') opts.update = true + else if (a === '--print') opts.print = true + else if (a === '--repeat') opts.repeat = Number(argv[++i]) + else if (a === '--root') opts.root = path.resolve(argv[++i]) + else opts.filters.push(a) + } + return opts +} + +async function main () { + const opts = parseArgs(process.argv.slice(2)) + const version = require(path.join(opts.root, 'package.json')).version + const connectionString = new TestEnv().connectionString + const selected = scenarios.filter(s => opts.filters.length === 0 || opts.filters.some(f => s.name.includes(f))) + console.log(`msnodesqlv8 ${version} (${opts.root}) - ${selected.length} scenarios, ${opts.repeat} runs each`) + + const summary = { same: 0, different: 0, missing: 0, nondeterministic: [] } + for (const scenario of selected) { + const variants = await captureScenario(opts.root, connectionString, scenario, opts.repeat) + const expected = corpus.read(scenario.name) + if (variants.length > 1) summary.nondeterministic.push(`${scenario.name} (${variants.map(v => v.count).join('/')})`) + const allMatch = expected && variants.every(v => corpus.matches(expected, v.lines)) + const mark = !expected ? 'NEW ' : allMatch ? 'same' : 'DIFF' + if (!expected) summary.missing++ + else if (allMatch) summary.same++ + else summary.different++ + console.log(`${mark} ${scenario.name}${variants.length > 1 ? ` [${variants.length} different outcomes]` : ''}${expected ? ` (${expected.status})` : ''}`) + + if (opts.print || (expected && !allMatch && !opts.update)) { + for (const v of variants) { + const indent = s => s.split('\n').map(l => ` ${l}`).join('\n') + console.log(` -- seen ${v.count}x`) + if (expected && !corpus.matches(expected, v.lines)) console.log(indent(corpus.diff(expected.variants[0], v.lines))) + else console.log(indent(v.lines.join('\n'))) + } + } + if (opts.update && !allMatch) { + console.log(` wrote ${path.relative(process.cwd(), corpus.write(scenario, variants))}`) + } + } + + console.log(`\n${summary.same} same, ${summary.different} different, ${summary.missing} new`) + if (summary.nondeterministic.length > 0) { + console.log(`not deterministic (runs per outcome):\n ${summary.nondeterministic.join('\n ')}`) + } + // a hung query can leave native work outstanding, so don't wait for the event loop + process.exit(0) +} + +main().catch(e => { + console.error(e) + process.exit(1) +}) diff --git a/test/contract/contract.test.js b/test/contract/contract.test.js new file mode 100644 index 00000000..1ee16163 --- /dev/null +++ b/test/contract/contract.test.js @@ -0,0 +1,32 @@ +'use strict' + +// the event contract: every scenario in scenarios.js must raise exactly the events its +// transcript in corpus/ lists, in that order. see corpus.js for the file format and +// capture.js for recording and comparing transcripts. + +import { createRequire } from 'module' +const require = createRequire(import.meta.url) +const path = require('path') +const assert = require('chai').assert +const { TestEnv } = require('../env/test-env') +const { scenarios } = require('./scenarios') +const { runIsolated } = require('./recorder') +const corpus = require('./corpus') + +const root = path.join(path.dirname(require.resolve('./scenarios')), '../..') +const connectionString = new TestEnv().connectionString + +describe('event contract', function () { + this.timeout(40000) + + for (const scenario of scenarios) { + it(scenario.name, async function handler () { + const expected = corpus.read(scenario.name) + assert.isNotNull(expected, `no transcript for ${scenario.name} - record one with: node test/contract/capture.js --update ${scenario.name}`) + const lines = await runIsolated(root, connectionString, scenario) + if (!corpus.matches(expected, lines)) { + assert.fail(`${scenario.name} (${expected.status}) differs from ${path.basename(expected.file)}:\n${corpus.diff(expected.variants[0], lines)}`) + } + }) + } +}) diff --git a/test/contract/corpus.js b/test/contract/corpus.js new file mode 100644 index 00000000..2727dcb4 --- /dev/null +++ b/test/contract/corpus.js @@ -0,0 +1,105 @@ +'use strict' + +// reads and writes the expected transcripts in corpus/. +// +// a corpus file is the scenario as '#' comment lines (for whoever reads it - they are +// not compared), then the transcript. a scenario that is allowed more than one outcome +// lists each one, separated by a line '--- or'. that should be rare: an outcome that +// depends on timing is usually something to fix, not to accept. +// +// # status: unreviewed | agreed +// +// 'unreviewed' is what capture.js writes: the transcript is what the driver does today, +// pinned so that a change shows up. 'agreed' means the transcript has been read and is +// the contract. to change the contract, edit the transcript and mark it agreed - the +// test then fails until the driver does what it says. +// +// a driver or platform that legitimately differs can have its own file, +// ..txt (e.g. errors/dup-key-d.events.direct.linux.txt), which is used +// instead of .txt on that platform. + +const fs = require('fs') +const path = require('path') + +const CORPUS_DIR = path.join(__dirname, 'corpus') +const ALTERNATIVE = '--- or' + +function fileFor (name, platform = process.platform) { + const specific = path.join(CORPUS_DIR, `${name}.${platform}.txt`) + if (fs.existsSync(specific)) return specific + return path.join(CORPUS_DIR, `${name}.txt`) +} + +function read (name) { + const file = fileFor(name) + if (!fs.existsSync(file)) return null + const text = fs.readFileSync(file, 'utf8').replace(/\r\n/g, '\n') + const status = /^# status: (\S+)/m.exec(text)?.[1] ?? 'unreviewed' + const variants = [[]] + for (const line of text.split('\n')) { + if (line === ALTERNATIVE) variants.push([]) + else if (line !== '' && !line.startsWith('#')) variants[variants.length - 1].push(line) + } + return { file, status, variants } +} + +function header (scenario, status) { + const lines = [`# scenario: ${scenario.name}`, `# status: ${status}`] + for (const statement of scenario.setup ?? []) lines.push(`# setup: ${statement}`) + lines.push(`# sql: ${scenario.sql}`) + if (scenario.params) lines.push(`# params: ${JSON.stringify(scenario.params, (k, v) => typeof v === 'number' && !isFinite(v) ? String(v) : v)}`) + if (scenario.at) lines.push(`# at: ${JSON.stringify(scenario.at)}`) + for (const f of scenario.followUps ?? []) { + lines.push(`# follow-up ${f.label} on ${f.when ?? 'start'}: ${f.sql}${f.at ? ` at ${JSON.stringify(f.at)}` : ''}`) + } + return lines +} + +// variants: [{ lines, count }] as captureScenario returns them +function write (scenario, variants) { + const existing = read(scenario.name) + const file = existing?.file ?? fileFor(scenario.name) + const out = header(scenario, existing?.status ?? 'unreviewed') + if (variants.length > 1) { + out.push(`# NOT DETERMINISTIC: ${variants.length} different transcripts in ${variants.reduce((n, v) => n + v.count, 0)} runs`) + } + variants.forEach((v, i) => { + if (i > 0) out.push(ALTERNATIVE) + out.push(...v.lines) + }) + fs.mkdirSync(path.dirname(file), { recursive: true }) + fs.writeFileSync(file, out.join('\n') + '\n') + return file +} + +function matches (expected, lines) { + const text = lines.join('\n') + return expected.variants.some(v => v.join('\n') === text) +} + +// a minimal line diff (longest common subsequence) - transcripts are short +function diff (expected, actual) { + const n = expected.length + const m = actual.length + const lcs = Array.from({ length: n + 1 }, () => new Array(m + 1).fill(0)) + for (let i = n - 1; i >= 0; i--) { + for (let j = m - 1; j >= 0; j--) { + lcs[i][j] = expected[i] === actual[j] ? lcs[i + 1][j + 1] + 1 : Math.max(lcs[i + 1][j], lcs[i][j + 1]) + } + } + const out = [] + let i = 0 + let j = 0 + while (i < n || j < m) { + if (i < n && j < m && expected[i] === actual[j]) { + out.push(` ${expected[i]}`); i++; j++ + } else if (j < m && (i >= n || lcs[i][j + 1] >= lcs[i + 1][j])) { + out.push(`+ ${actual[j]}`); j++ + } else { + out.push(`- ${expected[i]}`); i++ + } + } + return out.join('\n') +} + +module.exports = { read, write, matches, diff, CORPUS_DIR } diff --git a/test/contract/corpus/cancel/before-execute.events.txt b/test/contract/corpus/cancel/before-execute.events.txt new file mode 100644 index 00000000..6adb851c --- /dev/null +++ b/test/contract/corpus/cancel/before-execute.events.txt @@ -0,0 +1,11 @@ +# scenario: cancel/before-execute.events +# status: unreviewed +# sql: waitfor delay '00:00:01'; select 2 as n +# at: {"start":["cancel"]} +action cancel +submitted +done +cancel-cb ok +error HY008 0 Operation canceled more=false +free +check ok diff --git a/test/contract/corpus/cancel/during-execute.callback.txt b/test/contract/corpus/cancel/during-execute.callback.txt new file mode 100644 index 00000000..f247821f --- /dev/null +++ b/test/contract/corpus/cancel/during-execute.callback.txt @@ -0,0 +1,11 @@ +# scenario: cancel/during-execute.callback +# status: unreviewed +# sql: waitfor delay '00:00:01'; select 2 as n +# at: {"later":{"300":["cancel"]}} +submitted +action cancel +done +cancel-cb ok +free +cb error HY008 0 Operation canceled more=false +check ok diff --git a/test/contract/corpus/cancel/during-execute.events.txt b/test/contract/corpus/cancel/during-execute.events.txt new file mode 100644 index 00000000..7ecfe54c --- /dev/null +++ b/test/contract/corpus/cancel/during-execute.events.txt @@ -0,0 +1,11 @@ +# scenario: cancel/during-execute.events +# status: unreviewed +# sql: waitfor delay '00:00:01'; select 2 as n +# at: {"later":{"300":["cancel"]}} +submitted +action cancel +done +cancel-cb ok +error HY008 0 Operation canceled more=false +free +check ok diff --git a/test/contract/corpus/cancel/last-row.events.txt b/test/contract/corpus/cancel/last-row.events.txt new file mode 100644 index 00000000..78cca5a2 --- /dev/null +++ b/test/contract/corpus/cancel/last-row.events.txt @@ -0,0 +1,13 @@ +# scenario: cancel/last-row.events +# status: unreviewed +# sql: select top 5 object_id as a from sys.all_objects +# at: {"row":{"5":["cancel"]}} +submitted +meta a +row x5 +action cancel +done +cancel-cb ok +done +free +check ok diff --git a/test/contract/corpus/cancel/late-after-free.events.txt b/test/contract/corpus/cancel/late-after-free.events.txt new file mode 100644 index 00000000..827524d5 --- /dev/null +++ b/test/contract/corpus/cancel/late-after-free.events.txt @@ -0,0 +1,13 @@ +# scenario: cancel/late-after-free.events +# status: unreviewed +# sql: select 1 as n +# at: {"free":["cancel"]} +submitted +meta n +row +done +free +action cancel +done +cancel-cb error Error: [msnodesql] cannot cancel query (empty queue) id 0 +check ok diff --git a/test/contract/corpus/cancel/paused-before-execute.events.txt b/test/contract/corpus/cancel/paused-before-execute.events.txt new file mode 100644 index 00000000..11008ef4 --- /dev/null +++ b/test/contract/corpus/cancel/paused-before-execute.events.txt @@ -0,0 +1,23 @@ +# scenario: cancel/paused-before-execute.events +# status: unreviewed +# sql: waitfor delay '00:00:01'; select 2 as n +# at: {"start":["pause","cancel"]} +# NOT DETERMINISTIC: 2 different transcripts in 3 runs +action pause +action cancel +submitted +done +cancel-cb ok +error HY008 0 Operation canceled more=false +free x2 +check ok +--- or +action pause +action cancel +submitted +done +cancel-cb ok +free +error HY008 0 Operation canceled more=false +free +check ok diff --git a/test/contract/corpus/cancel/paused-streaming-at-100.events.txt b/test/contract/corpus/cancel/paused-streaming-at-100.events.txt new file mode 100644 index 00000000..7dee6f90 --- /dev/null +++ b/test/contract/corpus/cancel/paused-streaming-at-100.events.txt @@ -0,0 +1,13 @@ +# scenario: cancel/paused-streaming-at-100.events +# status: unreviewed +# sql: select top 5000 a.name from sys.all_objects a cross join sys.all_objects b +# at: {"row":{"100":["pause","cancel"]}} +submitted +meta name +row x100 +action pause +action cancel +done +cancel-cb ok +free +check ok diff --git a/test/contract/corpus/cancel/streaming-after-print-at-100.events.txt b/test/contract/corpus/cancel/streaming-after-print-at-100.events.txt new file mode 100644 index 00000000..a0b871fb --- /dev/null +++ b/test/contract/corpus/cancel/streaming-after-print-at-100.events.txt @@ -0,0 +1,16 @@ +# scenario: cancel/streaming-after-print-at-100.events +# status: unreviewed +# sql: print 'start'; select top 5000 a.name from sys.all_objects a cross join sys.all_objects b +# at: {"row":{"100":["cancel"]}} +submitted +info 01000 0 start +rowcount 0 +meta name +row x100 +action cancel +done +cancel-cb ok +row x4900 +done +free +check ok diff --git a/test/contract/corpus/cancel/streaming-at-100.events.txt b/test/contract/corpus/cancel/streaming-at-100.events.txt new file mode 100644 index 00000000..e1f28be1 --- /dev/null +++ b/test/contract/corpus/cancel/streaming-at-100.events.txt @@ -0,0 +1,13 @@ +# scenario: cancel/streaming-at-100.events +# status: unreviewed +# sql: select top 5000 a.name from sys.all_objects a cross join sys.all_objects b +# at: {"row":{"100":["cancel"]}} +submitted +meta name +row x100 +action cancel +done +cancel-cb ok +error HY008 0 Operation canceled more=false +free +check ok diff --git a/test/contract/corpus/errors/bind-failure.callback.txt b/test/contract/corpus/errors/bind-failure.callback.txt new file mode 100644 index 00000000..7a3819a7 --- /dev/null +++ b/test/contract/corpus/errors/bind-failure.callback.txt @@ -0,0 +1,9 @@ +# scenario: errors/bind-failure.callback +# status: unreviewed +# sql: select ? as v +# params: ["Infinity"] +submitted +done +free +cb error - - IMNOD: [msnodesql] Parameter 1: Invalid number parameter more=false +check ok diff --git a/test/contract/corpus/errors/bind-failure.events.txt b/test/contract/corpus/errors/bind-failure.events.txt new file mode 100644 index 00000000..0d7235e4 --- /dev/null +++ b/test/contract/corpus/errors/bind-failure.events.txt @@ -0,0 +1,9 @@ +# scenario: errors/bind-failure.events +# status: unreviewed +# sql: select ? as v +# params: ["Infinity"] +submitted +error - - IMNOD: [msnodesql] Parameter 1: Invalid number parameter more=false +done +free +check ok diff --git a/test/contract/corpus/errors/dup-key-a.callback.txt b/test/contract/corpus/errors/dup-key-a.callback.txt new file mode 100644 index 00000000..c7415878 --- /dev/null +++ b/test/contract/corpus/errors/dup-key-a.callback.txt @@ -0,0 +1,9 @@ +# scenario: errors/dup-key-a.callback +# status: unreviewed +# setup: create table #t (id int constraint pk_t primary key); insert #t values (1) +# sql: insert #t values (1) +submitted +info 01000 3621 The statement has been terminated. +free +cb error 23000 2627 Violation of PRIMARY KEY constraint 'pk_t'. Cannot insert duplicate key in object 'dbo.#t'. The duplicate key value is (1). more=false +check ok diff --git a/test/contract/corpus/errors/dup-key-a.events.txt b/test/contract/corpus/errors/dup-key-a.events.txt new file mode 100644 index 00000000..65f3b3b7 --- /dev/null +++ b/test/contract/corpus/errors/dup-key-a.events.txt @@ -0,0 +1,9 @@ +# scenario: errors/dup-key-a.events +# status: unreviewed +# setup: create table #t (id int constraint pk_t primary key); insert #t values (1) +# sql: insert #t values (1) +submitted +info 01000 3621 The statement has been terminated. +error 23000 2627 Violation of PRIMARY KEY constraint 'pk_t'. Cannot insert duplicate key in object 'dbo.#t'. The duplicate key value is (1). more=false +free +check ok diff --git a/test/contract/corpus/errors/dup-key-b.callback.txt b/test/contract/corpus/errors/dup-key-b.callback.txt new file mode 100644 index 00000000..b19c44f1 --- /dev/null +++ b/test/contract/corpus/errors/dup-key-b.callback.txt @@ -0,0 +1,12 @@ +# scenario: errors/dup-key-b.callback +# status: unreviewed +# setup: create table #t (id int constraint pk_t primary key); insert #t values (1) +# sql: select 1 as n; insert #t values (1) +submitted +meta n +row +column 0 1 +info 01000 3621 The statement has been terminated. +cb error 23000 2627 Violation of PRIMARY KEY constraint 'pk_t'. Cannot insert duplicate key in object 'dbo.#t'. The duplicate key value is (1). more=false +free +check ok diff --git a/test/contract/corpus/errors/dup-key-b.events.txt b/test/contract/corpus/errors/dup-key-b.events.txt new file mode 100644 index 00000000..2fe9de64 --- /dev/null +++ b/test/contract/corpus/errors/dup-key-b.events.txt @@ -0,0 +1,12 @@ +# scenario: errors/dup-key-b.events +# status: unreviewed +# setup: create table #t (id int constraint pk_t primary key); insert #t values (1) +# sql: select 1 as n; insert #t values (1) +submitted +meta n +row +column 0 1 +info 01000 3621 The statement has been terminated. +error 23000 2627 Violation of PRIMARY KEY constraint 'pk_t'. Cannot insert duplicate key in object 'dbo.#t'. The duplicate key value is (1). more=false +free +check ok diff --git a/test/contract/corpus/errors/dup-key-c.callback.txt b/test/contract/corpus/errors/dup-key-c.callback.txt new file mode 100644 index 00000000..2c239b40 --- /dev/null +++ b/test/contract/corpus/errors/dup-key-c.callback.txt @@ -0,0 +1,20 @@ +# scenario: errors/dup-key-c.callback +# status: unreviewed +# setup: create table #t (id int constraint pk_t primary key); insert #t values (1) +# sql: select 1 as n; insert #t values (1); select 2 as m +submitted +meta n +row +column 0 1 +info 01000 3621 The statement has been terminated. +cb error 23000 2627 Violation of PRIMARY KEY constraint 'pk_t'. Cannot insert duplicate key in object 'dbo.#t'. The duplicate key value is (1). more=true +cb ok rows=1 more=true +rowcount 0 +meta m +cb ok rows=0 more=true +row +column 0 2 +cb ok rows=1 more=false +done +free +check ok diff --git a/test/contract/corpus/errors/dup-key-c.events.txt b/test/contract/corpus/errors/dup-key-c.events.txt new file mode 100644 index 00000000..db307cdc --- /dev/null +++ b/test/contract/corpus/errors/dup-key-c.events.txt @@ -0,0 +1,17 @@ +# scenario: errors/dup-key-c.events +# status: unreviewed +# setup: create table #t (id int constraint pk_t primary key); insert #t values (1) +# sql: select 1 as n; insert #t values (1); select 2 as m +submitted +meta n +row +column 0 1 +info 01000 3621 The statement has been terminated. +error 23000 2627 Violation of PRIMARY KEY constraint 'pk_t'. Cannot insert duplicate key in object 'dbo.#t'. The duplicate key value is (1). more=true +rowcount 0 +meta m +row +column 0 2 +done +free +check ok diff --git a/test/contract/corpus/errors/dup-key-d.callback.txt b/test/contract/corpus/errors/dup-key-d.callback.txt new file mode 100644 index 00000000..a97f884b --- /dev/null +++ b/test/contract/corpus/errors/dup-key-d.callback.txt @@ -0,0 +1,16 @@ +# scenario: errors/dup-key-d.callback +# status: unreviewed +# setup: create table #t (id int constraint pk_t primary key); insert #t values (1) +# sql: insert #t values (1); select 2 as m +submitted +info 01000 3621 The statement has been terminated. +cb error 23000 2627 Violation of PRIMARY KEY constraint 'pk_t'. Cannot insert duplicate key in object 'dbo.#t'. The duplicate key value is (1). more=true +rowcount 0 +meta m +cb ok rows=0 more=true +row +column 0 2 +cb ok rows=1 more=false +done +free +check ok diff --git a/test/contract/corpus/errors/dup-key-d.events.txt b/test/contract/corpus/errors/dup-key-d.events.txt new file mode 100644 index 00000000..5c581468 --- /dev/null +++ b/test/contract/corpus/errors/dup-key-d.events.txt @@ -0,0 +1,14 @@ +# scenario: errors/dup-key-d.events +# status: unreviewed +# setup: create table #t (id int constraint pk_t primary key); insert #t values (1) +# sql: insert #t values (1); select 2 as m +submitted +error 23000 2627 Violation of PRIMARY KEY constraint 'pk_t'. Cannot insert duplicate key in object 'dbo.#t'. The duplicate key value is (1). more=true +info 01000 3621 The statement has been terminated. +rowcount 0 +meta m +row +column 0 2 +done +free +check ok diff --git a/test/contract/corpus/errors/print-then-raiserror.callback.txt b/test/contract/corpus/errors/print-then-raiserror.callback.txt new file mode 100644 index 00000000..454ac45a --- /dev/null +++ b/test/contract/corpus/errors/print-then-raiserror.callback.txt @@ -0,0 +1,8 @@ +# scenario: errors/print-then-raiserror.callback +# status: unreviewed +# sql: print 'p1'; raiserror('boom', 16, 1) +submitted +info 01000 0 p1 +cb error 42000 50000 boom more=false +free +check ok diff --git a/test/contract/corpus/errors/print-then-raiserror.events.txt b/test/contract/corpus/errors/print-then-raiserror.events.txt new file mode 100644 index 00000000..674d3e7a --- /dev/null +++ b/test/contract/corpus/errors/print-then-raiserror.events.txt @@ -0,0 +1,8 @@ +# scenario: errors/print-then-raiserror.events +# status: unreviewed +# sql: print 'p1'; raiserror('boom', 16, 1) +submitted +info 01000 0 p1 +error 42000 50000 boom more=false +free +check ok diff --git a/test/contract/corpus/errors/raiserror-after-result.callback.txt b/test/contract/corpus/errors/raiserror-after-result.callback.txt new file mode 100644 index 00000000..a56e76b5 --- /dev/null +++ b/test/contract/corpus/errors/raiserror-after-result.callback.txt @@ -0,0 +1,10 @@ +# scenario: errors/raiserror-after-result.callback +# status: unreviewed +# sql: select 1 as n; raiserror('boom', 16, 1) +submitted +meta n +row +column 0 1 +cb error 42000 50000 boom more=false +free +check ok diff --git a/test/contract/corpus/errors/raiserror-after-result.events.txt b/test/contract/corpus/errors/raiserror-after-result.events.txt new file mode 100644 index 00000000..4ebead55 --- /dev/null +++ b/test/contract/corpus/errors/raiserror-after-result.events.txt @@ -0,0 +1,10 @@ +# scenario: errors/raiserror-after-result.events +# status: unreviewed +# sql: select 1 as n; raiserror('boom', 16, 1) +submitted +meta n +row +column 0 1 +error 42000 50000 boom more=false +free +check ok diff --git a/test/contract/corpus/errors/raiserror-at-execute.callback.txt b/test/contract/corpus/errors/raiserror-at-execute.callback.txt new file mode 100644 index 00000000..bc2b18f6 --- /dev/null +++ b/test/contract/corpus/errors/raiserror-at-execute.callback.txt @@ -0,0 +1,7 @@ +# scenario: errors/raiserror-at-execute.callback +# status: unreviewed +# sql: raiserror('boom', 16, 1) +submitted +free +cb error 42000 50000 boom more=false +check ok diff --git a/test/contract/corpus/errors/raiserror-at-execute.events.txt b/test/contract/corpus/errors/raiserror-at-execute.events.txt new file mode 100644 index 00000000..90eb7f84 --- /dev/null +++ b/test/contract/corpus/errors/raiserror-at-execute.events.txt @@ -0,0 +1,7 @@ +# scenario: errors/raiserror-at-execute.events +# status: unreviewed +# sql: raiserror('boom', 16, 1) +submitted +error 42000 50000 boom more=false +free +check ok diff --git a/test/contract/corpus/errors/raiserror-then-result.callback.txt b/test/contract/corpus/errors/raiserror-then-result.callback.txt new file mode 100644 index 00000000..df4b7d8f --- /dev/null +++ b/test/contract/corpus/errors/raiserror-then-result.callback.txt @@ -0,0 +1,14 @@ +# scenario: errors/raiserror-then-result.callback +# status: unreviewed +# sql: raiserror('boom', 16, 1); select 2 as m +submitted +cb error 42000 50000 boom more=true +rowcount 0 +meta m +cb ok rows=0 more=true +row +column 0 2 +cb ok rows=1 more=false +done +free +check ok diff --git a/test/contract/corpus/errors/raiserror-then-result.events.txt b/test/contract/corpus/errors/raiserror-then-result.events.txt new file mode 100644 index 00000000..eb9ff904 --- /dev/null +++ b/test/contract/corpus/errors/raiserror-then-result.events.txt @@ -0,0 +1,12 @@ +# scenario: errors/raiserror-then-result.events +# status: unreviewed +# sql: raiserror('boom', 16, 1); select 2 as m +submitted +error 42000 50000 boom more=true +rowcount 0 +meta m +row +column 0 2 +done +free +check ok diff --git a/test/contract/corpus/errors/syntax.callback.txt b/test/contract/corpus/errors/syntax.callback.txt new file mode 100644 index 00000000..c95ada8b --- /dev/null +++ b/test/contract/corpus/errors/syntax.callback.txt @@ -0,0 +1,7 @@ +# scenario: errors/syntax.callback +# status: unreviewed +# sql: select from where +submitted +free +cb error 42000 156 Incorrect syntax near the keyword 'from'. more=false +check ok diff --git a/test/contract/corpus/errors/syntax.events.txt b/test/contract/corpus/errors/syntax.events.txt new file mode 100644 index 00000000..82fd5b10 --- /dev/null +++ b/test/contract/corpus/errors/syntax.events.txt @@ -0,0 +1,7 @@ +# scenario: errors/syntax.events +# status: unreviewed +# sql: select from where +submitted +error 42000 156 Incorrect syntax near the keyword 'from'. more=false +free +check ok diff --git a/test/contract/corpus/errors/throw-ends-batch.callback.txt b/test/contract/corpus/errors/throw-ends-batch.callback.txt new file mode 100644 index 00000000..229e2dd1 --- /dev/null +++ b/test/contract/corpus/errors/throw-ends-batch.callback.txt @@ -0,0 +1,10 @@ +# scenario: errors/throw-ends-batch.callback +# status: unreviewed +# sql: select 1 as n; throw 50001, 'thrown', 1; select 2 as m +submitted +meta n +row +column 0 1 +cb error 42000 50001 thrown more=false +free +check ok diff --git a/test/contract/corpus/errors/throw-ends-batch.events.txt b/test/contract/corpus/errors/throw-ends-batch.events.txt new file mode 100644 index 00000000..ab39e54a --- /dev/null +++ b/test/contract/corpus/errors/throw-ends-batch.events.txt @@ -0,0 +1,10 @@ +# scenario: errors/throw-ends-batch.events +# status: unreviewed +# sql: select 1 as n; throw 50001, 'thrown', 1; select 2 as m +submitted +meta n +row +column 0 1 +error 42000 50001 thrown more=false +free +check ok diff --git a/test/contract/corpus/errors/two-raiserrors-then-result.callback.txt b/test/contract/corpus/errors/two-raiserrors-then-result.callback.txt new file mode 100644 index 00000000..f7bda7bc --- /dev/null +++ b/test/contract/corpus/errors/two-raiserrors-then-result.callback.txt @@ -0,0 +1,23 @@ +# scenario: errors/two-raiserrors-then-result.callback +# status: unreviewed +# sql: print 'p1'; raiserror('e1', 16, 1); print 'p2'; raiserror('e2', 16, 1); select 1 as n +submitted +info 01000 0 p1 +cb error 42000 50000 e1 more=true +rowcount 0 +cb ok rows=0 more=true +info 01000 0 p2 +rowcount 0 +cb ok rows=0 more=true +cb error 42000 50000 e2 more=true +rowcount 0 +cb ok rows=0 more=true +rowcount 0 +meta n +cb ok rows=0 more=true +row +column 0 1 +cb ok rows=1 more=false +done +free +check ok diff --git a/test/contract/corpus/errors/two-raiserrors-then-result.events.txt b/test/contract/corpus/errors/two-raiserrors-then-result.events.txt new file mode 100644 index 00000000..9e46a24f --- /dev/null +++ b/test/contract/corpus/errors/two-raiserrors-then-result.events.txt @@ -0,0 +1,17 @@ +# scenario: errors/two-raiserrors-then-result.events +# status: unreviewed +# sql: print 'p1'; raiserror('e1', 16, 1); print 'p2'; raiserror('e2', 16, 1); select 1 as n +submitted +info 01000 0 p1 +error 42000 50000 e1 more=true +rowcount 0 +info 01000 0 p2 +rowcount 0 +error 42000 50000 e2 more=true +rowcount 0 x2 +meta n +row +column 0 1 +done +free +check ok diff --git a/test/contract/corpus/pause/before-execute.events.txt b/test/contract/corpus/pause/before-execute.events.txt new file mode 100644 index 00000000..ab2d03eb --- /dev/null +++ b/test/contract/corpus/pause/before-execute.events.txt @@ -0,0 +1,12 @@ +# scenario: pause/before-execute.events +# status: unreviewed +# sql: select 1 as n +# at: {"start":["pause","resume:50"]} +action pause +submitted +meta n +action resume +row +done +free +check ok diff --git a/test/contract/corpus/pause/every-row.events.txt b/test/contract/corpus/pause/every-row.events.txt new file mode 100644 index 00000000..01cb1630 --- /dev/null +++ b/test/contract/corpus/pause/every-row.events.txt @@ -0,0 +1,166 @@ +# scenario: pause/every-row.events +# status: unreviewed +# sql: select top 51 object_id as a from sys.all_objects; select top 51 object_id as b from sys.all_objects +# at: {"row":{"1":["pause","resume:1"],"2":["pause","resume:1"],"3":["pause","resume:1"],"4":["pause","resume:1"],"5":["pause","resume:1"],"6":["pause","resume:1"],"7":["pause","resume:1"],"8":["pause","resume:1"],"9":["pause","resume:1"],"10":["pause","resume:1"],"11":["pause","resume:1"],"12":["pause","resume:1"],"13":["pause","resume:1"],"14":["pause","resume:1"],"15":["pause","resume:1"],"16":["pause","resume:1"],"17":["pause","resume:1"],"18":["pause","resume:1"],"19":["pause","resume:1"],"20":["pause","resume:1"],"21":["pause","resume:1"],"22":["pause","resume:1"],"23":["pause","resume:1"],"24":["pause","resume:1"],"25":["pause","resume:1"],"26":["pause","resume:1"],"27":["pause","resume:1"],"28":["pause","resume:1"],"29":["pause","resume:1"],"30":["pause","resume:1"],"31":["pause","resume:1"],"32":["pause","resume:1"],"33":["pause","resume:1"],"34":["pause","resume:1"],"35":["pause","resume:1"],"36":["pause","resume:1"],"37":["pause","resume:1"],"38":["pause","resume:1"],"39":["pause","resume:1"],"40":["pause","resume:1"],"41":["pause","resume:1"],"42":["pause","resume:1"],"43":["pause","resume:1"],"44":["pause","resume:1"],"45":["pause","resume:1"],"46":["pause","resume:1"],"47":["pause","resume:1"],"48":["pause","resume:1"],"49":["pause","resume:1"],"50":["pause","resume:1"],"51":["pause","resume:1"],"52":["pause","resume:1"],"53":["pause","resume:1"],"54":["pause","resume:1"],"55":["pause","resume:1"],"56":["pause","resume:1"],"57":["pause","resume:1"],"58":["pause","resume:1"],"59":["pause","resume:1"],"60":["pause","resume:1"],"61":["pause","resume:1"],"62":["pause","resume:1"],"63":["pause","resume:1"],"64":["pause","resume:1"],"65":["pause","resume:1"],"66":["pause","resume:1"],"67":["pause","resume:1"],"68":["pause","resume:1"],"69":["pause","resume:1"],"70":["pause","resume:1"],"71":["pause","resume:1"],"72":["pause","resume:1"],"73":["pause","resume:1"],"74":["pause","resume:1"],"75":["pause","resume:1"],"76":["pause","resume:1"],"77":["pause","resume:1"],"78":["pause","resume:1"],"79":["pause","resume:1"],"80":["pause","resume:1"],"81":["pause","resume:1"],"82":["pause","resume:1"],"83":["pause","resume:1"],"84":["pause","resume:1"],"85":["pause","resume:1"],"86":["pause","resume:1"],"87":["pause","resume:1"],"88":["pause","resume:1"],"89":["pause","resume:1"],"90":["pause","resume:1"],"91":["pause","resume:1"],"92":["pause","resume:1"],"93":["pause","resume:1"],"94":["pause","resume:1"],"95":["pause","resume:1"],"96":["pause","resume:1"],"97":["pause","resume:1"],"98":["pause","resume:1"],"99":["pause","resume:1"],"100":["pause","resume:1"],"101":["pause","resume:1"],"102":["pause","resume:1"]}} +# NOT DETERMINISTIC: 2 different transcripts in 3 runs +PROCESS FAILED 3221225477 +--- or +submitted +meta a +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +meta b +action resume +done +free +check ok diff --git a/test/contract/corpus/pause/two-by-51-at-1.events.txt b/test/contract/corpus/pause/two-by-51-at-1.events.txt new file mode 100644 index 00000000..3b587433 --- /dev/null +++ b/test/contract/corpus/pause/two-by-51-at-1.events.txt @@ -0,0 +1,15 @@ +# scenario: pause/two-by-51-at-1.events +# status: unreviewed +# sql: select top 51 object_id as a from sys.all_objects; select top 51 object_id as b from sys.all_objects +# at: {"row":{"1":["pause","resume:50"]}} +submitted +meta a +row +action pause +action resume +row x50 +meta b +row x51 +done +free +check ok diff --git a/test/contract/corpus/pause/two-by-51-at-101.events.txt b/test/contract/corpus/pause/two-by-51-at-101.events.txt new file mode 100644 index 00000000..b98825ea --- /dev/null +++ b/test/contract/corpus/pause/two-by-51-at-101.events.txt @@ -0,0 +1,15 @@ +# scenario: pause/two-by-51-at-101.events +# status: unreviewed +# sql: select top 51 object_id as a from sys.all_objects; select top 51 object_id as b from sys.all_objects +# at: {"row":{"101":["pause","resume:50"]}} +submitted +meta a +row x51 +meta b +row x50 +action pause +action resume +row +done +free +check ok diff --git a/test/contract/corpus/pause/two-by-51-at-102.events.txt b/test/contract/corpus/pause/two-by-51-at-102.events.txt new file mode 100644 index 00000000..64825fdc --- /dev/null +++ b/test/contract/corpus/pause/two-by-51-at-102.events.txt @@ -0,0 +1,15 @@ +# scenario: pause/two-by-51-at-102.events +# status: unreviewed +# sql: select top 51 object_id as a from sys.all_objects; select top 51 object_id as b from sys.all_objects +# at: {"row":{"102":["pause","resume:50"]}} +submitted +meta a +row x51 +meta b +row x51 +action pause +done +free +action resume +rowcount 0 (repeating) +RUNAWAY more than 2000 events diff --git a/test/contract/corpus/pause/two-by-51-at-49.events.txt b/test/contract/corpus/pause/two-by-51-at-49.events.txt new file mode 100644 index 00000000..8fc9bf1b --- /dev/null +++ b/test/contract/corpus/pause/two-by-51-at-49.events.txt @@ -0,0 +1,15 @@ +# scenario: pause/two-by-51-at-49.events +# status: unreviewed +# sql: select top 51 object_id as a from sys.all_objects; select top 51 object_id as b from sys.all_objects +# at: {"row":{"49":["pause","resume:50"]}} +submitted +meta a +row x49 +action pause +action resume +row x2 +meta b +row x51 +done +free +check ok diff --git a/test/contract/corpus/pause/two-by-51-at-50.events.txt b/test/contract/corpus/pause/two-by-51-at-50.events.txt new file mode 100644 index 00000000..69a79852 --- /dev/null +++ b/test/contract/corpus/pause/two-by-51-at-50.events.txt @@ -0,0 +1,15 @@ +# scenario: pause/two-by-51-at-50.events +# status: unreviewed +# sql: select top 51 object_id as a from sys.all_objects; select top 51 object_id as b from sys.all_objects +# at: {"row":{"50":["pause","resume:50"]}} +submitted +meta a +row x50 +action pause +action resume +row +meta b +row x51 +done +free +check ok diff --git a/test/contract/corpus/pause/two-by-51-at-51.events.txt b/test/contract/corpus/pause/two-by-51-at-51.events.txt new file mode 100644 index 00000000..7eff8a0c --- /dev/null +++ b/test/contract/corpus/pause/two-by-51-at-51.events.txt @@ -0,0 +1,13 @@ +# scenario: pause/two-by-51-at-51.events +# status: unreviewed +# sql: select top 51 object_id as a from sys.all_objects; select top 51 object_id as b from sys.all_objects +# at: {"row":{"51":["pause","resume:50"]}} +submitted +meta a +row x51 +action pause +meta b +action resume +done +free +check ok diff --git a/test/contract/corpus/pause/two-by-51-at-52.events.txt b/test/contract/corpus/pause/two-by-51-at-52.events.txt new file mode 100644 index 00000000..1fd5dcde --- /dev/null +++ b/test/contract/corpus/pause/two-by-51-at-52.events.txt @@ -0,0 +1,15 @@ +# scenario: pause/two-by-51-at-52.events +# status: unreviewed +# sql: select top 51 object_id as a from sys.all_objects; select top 51 object_id as b from sys.all_objects +# at: {"row":{"52":["pause","resume:50"]}} +submitted +meta a +row x51 +meta b +row +action pause +action resume +row x50 +done +free +check ok diff --git a/test/contract/corpus/queue/bind-failure-then-two-on-free.callback.txt b/test/contract/corpus/queue/bind-failure-then-two-on-free.callback.txt new file mode 100644 index 00000000..a2818f39 --- /dev/null +++ b/test/contract/corpus/queue/bind-failure-then-two-on-free.callback.txt @@ -0,0 +1,23 @@ +# scenario: queue/bind-failure-then-two-on-free.callback +# status: unreviewed +# sql: select ? as v +# params: ["Infinity"] +# follow-up q2 on free: waitfor delay '00:00:01'; select 2 as n +# follow-up q3 on free: select 3 as n +submitted +done +free +cb error - - IMNOD: [msnodesql] Parameter 1: Invalid number parameter more=false +q2: submitted +q2: meta n +q2: row +q3: submitted +q3: meta n +q3: row +q2: cb ok rows=1 more=false +q2: done +q2: free +q3: cb ok rows=1 more=false +q3: done +q3: free +check ok diff --git a/test/contract/corpus/queue/bind-failure-then-two-on-start.callback.txt b/test/contract/corpus/queue/bind-failure-then-two-on-start.callback.txt new file mode 100644 index 00000000..9215e611 --- /dev/null +++ b/test/contract/corpus/queue/bind-failure-then-two-on-start.callback.txt @@ -0,0 +1,36 @@ +# scenario: queue/bind-failure-then-two-on-start.callback +# status: unreviewed +# sql: select ? as v +# params: ["Infinity"] +# follow-up q2 on start: waitfor delay '00:00:01'; select 2 as n +# follow-up q3 on start: select 3 as n +# NOT DETERMINISTIC: 2 different transcripts in 3 runs +submitted +done +free +q2: submitted +q3: submitted +cb error - - IMNOD: [msnodesql] Parameter 1: Invalid number parameter more=false +q3: free +q3: cb error HY000 0 Connection is busy with results for another command more=false +q2: meta n +q2: row +q2: cb ok rows=1 more=false +q2: done +q2: free +check ok +--- or +submitted +done +free +q2: submitted +q3: submitted +cb error - - IMNOD: [msnodesql] Parameter 1: Invalid number parameter more=false +q3: meta n +q2: free +q2: cb error HY000 0 Connection is busy with results for another command more=false +q3: row +q3: cb ok rows=1 more=false +q3: done +q3: free +check ok diff --git a/test/contract/corpus/queue/error-after-result-then-two-on-free.callback.txt b/test/contract/corpus/queue/error-after-result-then-two-on-free.callback.txt new file mode 100644 index 00000000..da116207 --- /dev/null +++ b/test/contract/corpus/queue/error-after-result-then-two-on-free.callback.txt @@ -0,0 +1,20 @@ +# scenario: queue/error-after-result-then-two-on-free.callback +# status: unreviewed +# sql: select 1 as n; raiserror('boom', 16, 1) +# follow-up q2 on free: waitfor delay '00:00:01'; select 2 as n +# follow-up q3 on free: select 3 as n +submitted +meta n +row +cb error 42000 50000 boom more=false +free +q2: submitted +q3: submitted +q3: free +q3: cb error HY000 0 Connection is busy with results for another command more=false +q2: meta n +q2: row +q2: cb ok rows=1 more=false +q2: done +q2: free +check ok diff --git a/test/contract/corpus/queue/error-after-result-then-two-on-start.callback.txt b/test/contract/corpus/queue/error-after-result-then-two-on-start.callback.txt new file mode 100644 index 00000000..b8625d01 --- /dev/null +++ b/test/contract/corpus/queue/error-after-result-then-two-on-start.callback.txt @@ -0,0 +1,23 @@ +# scenario: queue/error-after-result-then-two-on-start.callback +# status: unreviewed +# sql: select 1 as n; raiserror('boom', 16, 1) +# follow-up q2 on start: waitfor delay '00:00:01'; select 2 as n +# follow-up q3 on start: select 3 as n +submitted +meta n +row +cb error 42000 50000 boom more=false +q2: submitted +q2: meta n +q2: row +q3: submitted +q3: meta n +q3: row +free +q2: cb ok rows=1 more=false +q2: done +q2: free +q3: cb ok rows=1 more=false +q3: done +q3: free +check ok diff --git a/test/contract/corpus/queue/error-at-execute-then-cancel-follow-up.callback.txt b/test/contract/corpus/queue/error-at-execute-then-cancel-follow-up.callback.txt new file mode 100644 index 00000000..5fba6be5 --- /dev/null +++ b/test/contract/corpus/queue/error-at-execute-then-cancel-follow-up.callback.txt @@ -0,0 +1,17 @@ +# scenario: queue/error-at-execute-then-cancel-follow-up.callback +# status: unreviewed +# sql: raiserror('boom', 16, 1) +# follow-up q2 on free: waitfor delay '00:00:01'; select 2 as n at {"later":{"300":["cancel"]}} +submitted +free +cb error 42000 50000 boom more=false +q2: submitted +q2: action cancel +q2: done +q2: cancel-cb error Error: [msnodesql] cannot cancel query (empty queue) id 1 +q2: meta n +q2: row +q2: cb ok rows=1 more=false +q2: done +q2: free +check ok diff --git a/test/contract/corpus/queue/error-at-execute-then-two-on-free.callback.txt b/test/contract/corpus/queue/error-at-execute-then-two-on-free.callback.txt new file mode 100644 index 00000000..01596b1f --- /dev/null +++ b/test/contract/corpus/queue/error-at-execute-then-two-on-free.callback.txt @@ -0,0 +1,18 @@ +# scenario: queue/error-at-execute-then-two-on-free.callback +# status: unreviewed +# sql: raiserror('boom', 16, 1) +# follow-up q2 on free: waitfor delay '00:00:01'; select 2 as n +# follow-up q3 on free: select 3 as n +submitted +free +cb error 42000 50000 boom more=false +q2: submitted +q3: submitted +q3: free +q3: cb error HY000 0 Connection is busy with results for another command more=false +q2: meta n +q2: row +q2: cb ok rows=1 more=false +q2: done +q2: free +check ok diff --git a/test/contract/corpus/queue/error-at-execute-then-two-on-start.callback.txt b/test/contract/corpus/queue/error-at-execute-then-two-on-start.callback.txt new file mode 100644 index 00000000..4389887d --- /dev/null +++ b/test/contract/corpus/queue/error-at-execute-then-two-on-start.callback.txt @@ -0,0 +1,21 @@ +# scenario: queue/error-at-execute-then-two-on-start.callback +# status: unreviewed +# sql: raiserror('boom', 16, 1) +# follow-up q2 on start: waitfor delay '00:00:01'; select 2 as n +# follow-up q3 on start: select 3 as n +submitted +q2: submitted +q2: meta n +q2: row +q3: submitted +q3: meta n +q3: row +free +cb error 42000 50000 boom more=false +q2: cb ok rows=1 more=false +q2: done +q2: free +q3: cb ok rows=1 more=false +q3: done +q3: free +check ok diff --git a/test/contract/corpus/queue/ok-then-cancel-follow-up.callback.txt b/test/contract/corpus/queue/ok-then-cancel-follow-up.callback.txt new file mode 100644 index 00000000..bdc8c46c --- /dev/null +++ b/test/contract/corpus/queue/ok-then-cancel-follow-up.callback.txt @@ -0,0 +1,17 @@ +# scenario: queue/ok-then-cancel-follow-up.callback +# status: unreviewed +# sql: select 1 as n +# follow-up q2 on free: waitfor delay '00:00:01'; select 2 as n at {"later":{"300":["cancel"]}} +submitted +meta n +row +cb ok rows=1 more=false +done +free +q2: submitted +q2: action cancel +q2: done +q2: cancel-cb ok +q2: free +q2: cb error HY008 0 Operation canceled more=false +check ok diff --git a/test/contract/corpus/queue/ok-then-two-on-free.callback.txt b/test/contract/corpus/queue/ok-then-two-on-free.callback.txt new file mode 100644 index 00000000..b0f3a82d --- /dev/null +++ b/test/contract/corpus/queue/ok-then-two-on-free.callback.txt @@ -0,0 +1,25 @@ +# scenario: queue/ok-then-two-on-free.callback +# status: unreviewed +# sql: select ? as v +# params: [1] +# follow-up q2 on free: waitfor delay '00:00:01'; select 2 as n +# follow-up q3 on free: select 3 as n +submitted +meta v +row +cb ok rows=1 more=false +done +free +q2: submitted +q2: meta n +q2: row +q3: submitted +q3: meta n +q3: row +q2: cb ok rows=1 more=false +q2: done +q2: free +q3: cb ok rows=1 more=false +q3: done +q3: free +check ok diff --git a/test/contract/corpus/queue/ok-then-two-on-start.callback.txt b/test/contract/corpus/queue/ok-then-two-on-start.callback.txt new file mode 100644 index 00000000..ed99f6cb --- /dev/null +++ b/test/contract/corpus/queue/ok-then-two-on-start.callback.txt @@ -0,0 +1,25 @@ +# scenario: queue/ok-then-two-on-start.callback +# status: unreviewed +# sql: select ? as v +# params: [1] +# follow-up q2 on start: waitfor delay '00:00:01'; select 2 as n +# follow-up q3 on start: select 3 as n +submitted +meta v +row +q2: submitted +q2: meta n +q2: row +q3: submitted +q3: meta n +q3: row +cb ok rows=1 more=false +done +free +q2: cb ok rows=1 more=false +q2: done +q2: free +q3: cb ok rows=1 more=false +q3: done +q3: free +check ok diff --git a/test/contract/corpus/read/insert-rowcount.callback.txt b/test/contract/corpus/read/insert-rowcount.callback.txt new file mode 100644 index 00000000..1df82f76 --- /dev/null +++ b/test/contract/corpus/read/insert-rowcount.callback.txt @@ -0,0 +1,10 @@ +# scenario: read/insert-rowcount.callback +# status: unreviewed +# setup: create table #r (id int) +# sql: insert #r values (1) +submitted +rowcount 1 +cb ok rows=0 more=false +done +free +check ok diff --git a/test/contract/corpus/read/insert-rowcount.events.txt b/test/contract/corpus/read/insert-rowcount.events.txt new file mode 100644 index 00000000..a7435106 --- /dev/null +++ b/test/contract/corpus/read/insert-rowcount.events.txt @@ -0,0 +1,9 @@ +# scenario: read/insert-rowcount.events +# status: unreviewed +# setup: create table #r (id int) +# sql: insert #r values (1) +submitted +rowcount 1 +done +free +check ok diff --git a/test/contract/corpus/read/insert-then-select.callback.txt b/test/contract/corpus/read/insert-then-select.callback.txt new file mode 100644 index 00000000..4abadd60 --- /dev/null +++ b/test/contract/corpus/read/insert-then-select.callback.txt @@ -0,0 +1,14 @@ +# scenario: read/insert-then-select.callback +# status: unreviewed +# setup: create table #r (id int) +# sql: insert #r values (1); select id from #r +submitted +rowcount 1 +meta id +cb ok rows=0 more=true +row +column 0 1 +cb ok rows=1 more=false +done +free +check ok diff --git a/test/contract/corpus/read/insert-then-select.events.txt b/test/contract/corpus/read/insert-then-select.events.txt new file mode 100644 index 00000000..98d00ee8 --- /dev/null +++ b/test/contract/corpus/read/insert-then-select.events.txt @@ -0,0 +1,12 @@ +# scenario: read/insert-then-select.events +# status: unreviewed +# setup: create table #r (id int) +# sql: insert #r values (1); select id from #r +submitted +rowcount 1 +meta id +row +column 0 1 +done +free +check ok diff --git a/test/contract/corpus/read/no-rows.callback.txt b/test/contract/corpus/read/no-rows.callback.txt new file mode 100644 index 00000000..2c8f2928 --- /dev/null +++ b/test/contract/corpus/read/no-rows.callback.txt @@ -0,0 +1,9 @@ +# scenario: read/no-rows.callback +# status: unreviewed +# sql: select top 0 1 as n +submitted +meta n +cb ok rows=0 more=false +done +free +check ok diff --git a/test/contract/corpus/read/no-rows.events.txt b/test/contract/corpus/read/no-rows.events.txt new file mode 100644 index 00000000..698c9476 --- /dev/null +++ b/test/contract/corpus/read/no-rows.events.txt @@ -0,0 +1,8 @@ +# scenario: read/no-rows.events +# status: unreviewed +# sql: select top 0 1 as n +submitted +meta n +done +free +check ok diff --git a/test/contract/corpus/read/one-row.callback.txt b/test/contract/corpus/read/one-row.callback.txt new file mode 100644 index 00000000..8dc6e185 --- /dev/null +++ b/test/contract/corpus/read/one-row.callback.txt @@ -0,0 +1,11 @@ +# scenario: read/one-row.callback +# status: unreviewed +# sql: select 1 as n +submitted +meta n +row +column 0 1 +cb ok rows=1 more=false +done +free +check ok diff --git a/test/contract/corpus/read/one-row.events.txt b/test/contract/corpus/read/one-row.events.txt new file mode 100644 index 00000000..0acc1f98 --- /dev/null +++ b/test/contract/corpus/read/one-row.events.txt @@ -0,0 +1,10 @@ +# scenario: read/one-row.events +# status: unreviewed +# sql: select 1 as n +submitted +meta n +row +column 0 1 +done +free +check ok diff --git a/test/contract/corpus/read/param.callback.txt b/test/contract/corpus/read/param.callback.txt new file mode 100644 index 00000000..448aa9b2 --- /dev/null +++ b/test/contract/corpus/read/param.callback.txt @@ -0,0 +1,12 @@ +# scenario: read/param.callback +# status: unreviewed +# sql: select ? as v +# params: [1] +submitted +meta v +row +column 0 1 +cb ok rows=1 more=false +done +free +check ok diff --git a/test/contract/corpus/read/param.events.txt b/test/contract/corpus/read/param.events.txt new file mode 100644 index 00000000..9c6fa74b --- /dev/null +++ b/test/contract/corpus/read/param.events.txt @@ -0,0 +1,11 @@ +# scenario: read/param.events +# status: unreviewed +# sql: select ? as v +# params: [1] +submitted +meta v +row +column 0 1 +done +free +check ok diff --git a/test/contract/corpus/read/print-only.callback.txt b/test/contract/corpus/read/print-only.callback.txt new file mode 100644 index 00000000..8321bb57 --- /dev/null +++ b/test/contract/corpus/read/print-only.callback.txt @@ -0,0 +1,10 @@ +# scenario: read/print-only.callback +# status: unreviewed +# sql: print 'p1' +submitted +info 01000 0 p1 +rowcount 0 +cb ok rows=0 more=false +done +free +check ok diff --git a/test/contract/corpus/read/print-only.events.txt b/test/contract/corpus/read/print-only.events.txt new file mode 100644 index 00000000..5fcc8e2a --- /dev/null +++ b/test/contract/corpus/read/print-only.events.txt @@ -0,0 +1,9 @@ +# scenario: read/print-only.events +# status: unreviewed +# sql: print 'p1' +submitted +info 01000 0 p1 +rowcount 0 +done +free +check ok diff --git a/test/contract/corpus/read/print-then-select.callback.txt b/test/contract/corpus/read/print-then-select.callback.txt new file mode 100644 index 00000000..5ebb90e7 --- /dev/null +++ b/test/contract/corpus/read/print-then-select.callback.txt @@ -0,0 +1,14 @@ +# scenario: read/print-then-select.callback +# status: unreviewed +# sql: print 'p1'; select 1 as n +submitted +info 01000 0 p1 +rowcount 0 +meta n +cb ok rows=0 more=true +row +column 0 1 +cb ok rows=1 more=false +done +free +check ok diff --git a/test/contract/corpus/read/print-then-select.events.txt b/test/contract/corpus/read/print-then-select.events.txt new file mode 100644 index 00000000..0cf3d596 --- /dev/null +++ b/test/contract/corpus/read/print-then-select.events.txt @@ -0,0 +1,12 @@ +# scenario: read/print-then-select.events +# status: unreviewed +# sql: print 'p1'; select 1 as n +submitted +info 01000 0 p1 +rowcount 0 +meta n +row +column 0 1 +done +free +check ok diff --git a/test/contract/corpus/read/rows-50.events.txt b/test/contract/corpus/read/rows-50.events.txt new file mode 100644 index 00000000..514be115 --- /dev/null +++ b/test/contract/corpus/read/rows-50.events.txt @@ -0,0 +1,9 @@ +# scenario: read/rows-50.events +# status: unreviewed +# sql: select top 50 object_id as a from sys.all_objects +submitted +meta a +row x50 +done +free +check ok diff --git a/test/contract/corpus/read/rows-51.events.txt b/test/contract/corpus/read/rows-51.events.txt new file mode 100644 index 00000000..7dcb2cbc --- /dev/null +++ b/test/contract/corpus/read/rows-51.events.txt @@ -0,0 +1,9 @@ +# scenario: read/rows-51.events +# status: unreviewed +# sql: select top 51 object_id as a from sys.all_objects +submitted +meta a +row x51 +done +free +check ok diff --git a/test/contract/corpus/read/select-then-print.callback.txt b/test/contract/corpus/read/select-then-print.callback.txt new file mode 100644 index 00000000..eb684cbd --- /dev/null +++ b/test/contract/corpus/read/select-then-print.callback.txt @@ -0,0 +1,14 @@ +# scenario: read/select-then-print.callback +# status: unreviewed +# sql: select 1 as n; print 'p1' +submitted +meta n +row +column 0 1 +info 01000 0 p1 +rowcount 0 +cb ok rows=0 more=true +cb ok rows=1 more=false +done +free +check ok diff --git a/test/contract/corpus/read/select-then-print.events.txt b/test/contract/corpus/read/select-then-print.events.txt new file mode 100644 index 00000000..936815ea --- /dev/null +++ b/test/contract/corpus/read/select-then-print.events.txt @@ -0,0 +1,12 @@ +# scenario: read/select-then-print.events +# status: unreviewed +# sql: select 1 as n; print 'p1' +submitted +meta n +row +column 0 1 +info 01000 0 p1 +rowcount 0 +done +free +check ok diff --git a/test/contract/corpus/read/two-by-51.events.txt b/test/contract/corpus/read/two-by-51.events.txt new file mode 100644 index 00000000..38393847 --- /dev/null +++ b/test/contract/corpus/read/two-by-51.events.txt @@ -0,0 +1,11 @@ +# scenario: read/two-by-51.events +# status: unreviewed +# sql: select top 51 object_id as a from sys.all_objects; select top 51 object_id as b from sys.all_objects +submitted +meta a +row x51 +meta b +row x51 +done +free +check ok diff --git a/test/contract/corpus/read/two-result-sets.callback.txt b/test/contract/corpus/read/two-result-sets.callback.txt new file mode 100644 index 00000000..04177211 --- /dev/null +++ b/test/contract/corpus/read/two-result-sets.callback.txt @@ -0,0 +1,15 @@ +# scenario: read/two-result-sets.callback +# status: unreviewed +# sql: select 1 as a; select 2 as b +submitted +meta a +row +column 0 1 +meta b +cb ok rows=1 more=true +row +column 0 2 +cb ok rows=1 more=false +done +free +check ok diff --git a/test/contract/corpus/read/two-result-sets.events.txt b/test/contract/corpus/read/two-result-sets.events.txt new file mode 100644 index 00000000..09398f9b --- /dev/null +++ b/test/contract/corpus/read/two-result-sets.events.txt @@ -0,0 +1,13 @@ +# scenario: read/two-result-sets.events +# status: unreviewed +# sql: select 1 as a; select 2 as b +submitted +meta a +row +column 0 1 +meta b +row +column 0 2 +done +free +check ok diff --git a/test/contract/corpus/read/two-rows-two-columns.callback.txt b/test/contract/corpus/read/two-rows-two-columns.callback.txt new file mode 100644 index 00000000..eb73767c --- /dev/null +++ b/test/contract/corpus/read/two-rows-two-columns.callback.txt @@ -0,0 +1,15 @@ +# scenario: read/two-rows-two-columns.callback +# status: unreviewed +# sql: select 1 as a, 'x' as b union all select 2, 'y' +submitted +meta a,b +row +column 0 1 +column 1 "x" +row +column 0 2 +column 1 "y" +cb ok rows=2 more=false +done +free +check ok diff --git a/test/contract/corpus/read/two-rows-two-columns.events.txt b/test/contract/corpus/read/two-rows-two-columns.events.txt new file mode 100644 index 00000000..03c65d1c --- /dev/null +++ b/test/contract/corpus/read/two-rows-two-columns.events.txt @@ -0,0 +1,14 @@ +# scenario: read/two-rows-two-columns.events +# status: unreviewed +# sql: select 1 as a, 'x' as b union all select 2, 'y' +submitted +meta a,b +row +column 0 1 +column 1 "x" +row +column 0 2 +column 1 "y" +done +free +check ok diff --git a/test/contract/corpus/read/types.callback.txt b/test/contract/corpus/read/types.callback.txt new file mode 100644 index 00000000..bbdda23b --- /dev/null +++ b/test/contract/corpus/read/types.callback.txt @@ -0,0 +1,17 @@ +# scenario: read/types.callback +# status: unreviewed +# sql: select 1 as i, N'x' as s, cast(1.5 as decimal(5, 2)) as d, cast('2020-01-02T03:04:05' as datetime2(0)) as dt, cast(null as int) as nul, 0x0102 as b, cast(1 as bit) as bt +submitted +meta i,s,d,dt,nul,b,bt +row +column 0 1 +column 1 "x" +column 2 1.5 +column 3 2020-01-02T03:04:05.000Z +column 4 null +column 5 0x0102 +column 6 true +cb ok rows=1 more=false +done +free +check ok diff --git a/test/contract/corpus/read/types.events.txt b/test/contract/corpus/read/types.events.txt new file mode 100644 index 00000000..b528633a --- /dev/null +++ b/test/contract/corpus/read/types.events.txt @@ -0,0 +1,16 @@ +# scenario: read/types.events +# status: unreviewed +# sql: select 1 as i, N'x' as s, cast(1.5 as decimal(5, 2)) as d, cast('2020-01-02T03:04:05' as datetime2(0)) as dt, cast(null as int) as nul, 0x0102 as b, cast(1 as bit) as bt +submitted +meta i,s,d,dt,nul,b,bt +row +column 0 1 +column 1 "x" +column 2 1.5 +column 3 2020-01-02T03:04:05.000Z +column 4 null +column 5 0x0102 +column 6 true +done +free +check ok diff --git a/test/contract/recorder.js b/test/contract/recorder.js new file mode 100644 index 00000000..e05708a8 --- /dev/null +++ b/test/contract/recorder.js @@ -0,0 +1,261 @@ +'use strict' + +// runs a scenario from scenarios.js and records everything the query does as a +// transcript: one line per event, callback, cancel callback and action, in the order +// they happen. the transcript is compared with the one the corpus expects, so the +// exact sequence of events is part of the contract, not just the results. +// +// line format (the main query is unprefixed, other queries are prefixed 'q2: ' etc.) +// submitted +// meta a,b column names +// column 0 "abc" only for scenarios with columns: true +// row x51 consecutive identical lines are collapsed: 'free x2' +// rowcount 1 +// info 01000 3621 sqlstate, code, message without the [driver] prefix +// error 23000 2627 more=false +// output procedure output parameters +// done +// free +// cb ok rows=1 more=false the query callback +// cb error 42000 50000 more=false +// action pause|resume|cancel something the scenario did, at that point +// cancel-cb ok|error +// TIMEOUT ... the query never freed, or the connection hung +// check ok|error ...|TIMEOUT a query run on the connection after the scenario + +const { execFile } = require('child_process') +const path = require('path') + +const MAX_LINES = 400 +const MAX_EVENTS = 2000 // beyond this the query is looping; stop so the transcript is stable +const SETTLE_MS = 150 +const PROCESS_TIMEOUT_MS = 30000 + +const strip = m => String(m ?? '').replace(/^(\[[^\]]*\])+/, '').replace(/\s+/g, ' ').trim() + +const describeError = e => { + if (!e) return 'null' + const state = e.sqlstate ?? '-' + const code = e.code ?? '-' + return `${state} ${code} ${strip(e.message)}` +} + +const formatValue = v => { + if (v === null || v === undefined) return String(v) + if (Buffer.isBuffer(v)) return `0x${v.toString('hex')}` + if (v instanceof Date) return v.toISOString() + return JSON.stringify(v) +} + +class Transcript { + constructor () { + this.lines = [] + this.counts = [] + this.total = 0 + } + + push (line) { + // rows are bounded by the query itself; only other events count towards a runaway + if (!line.endsWith('row') && ++this.total > MAX_EVENTS) return + const last = this.lines.length - 1 + if (last >= 0 && this.lines[last] === line) { + this.counts[last]++ + return + } + if (this.lines.length >= MAX_LINES) return + this.lines.push(line) + this.counts.push(1) + } + + toLines () { + const out = this.lines.map((l, i) => this.counts[i] > 1 ? `${l} x${this.counts[i]}` : l) + if (this.total > MAX_EVENTS) { + // how far a loop gets before the cap varies run to run, so leave the count off + out[out.length - 1] = `${this.lines[this.lines.length - 1]} (repeating)` + out.push(`RUNAWAY more than ${MAX_EVENTS} events`) + } + else if (this.lines.length >= MAX_LINES) out.push(`... truncated after ${MAX_LINES} distinct lines`) + return out + } +} + +const delay = ms => new Promise(resolve => setTimeout(resolve, ms)) + +function withTimeout (promise, ms) { + let h + return Promise.race([ + promise.then(v => { clearTimeout(h); return { ok: true, value: v } }, e => { clearTimeout(h); return { ok: false, error: e } }), + new Promise(resolve => { h = setTimeout(() => resolve({ timeout: true }), ms) }) + ]) +} + +class Run { + constructor (sql, conn, scenario, transcript) { + this.sql = sql + this.conn = conn + this.scenario = scenario + this.t = transcript + this.pending = new Map() + this.queries = new Map() + } + + log (label, line) { + this.t.push(label === 'q1' ? line : `${label}: ${line}`) + } + + start (label, def) { + const log = line => this.log(label, line) + let resolveFree + this.pending.set(label, new Promise(resolve => { resolveFree = resolve })) + const args = [def.sql] + if (def.params) args.push(def.params) + if (def.callback) { + args.push((err, rows, more) => { + if (err) log(`cb error ${describeError(err)} more=${more}`) + else log(`cb ok rows=${rows ? rows.length : 'null'} more=${more}`) + }) + } + const q = this.conn.query(...args) + this.queries.set(label, q) + const at = def.at ?? {} + let rows = 0 + q.on('submitted', () => log('submitted')) + q.on('meta', m => log(`meta ${m.map(c => c.name).join(',')}`)) + q.on('row', () => { + log('row') + const actions = at.row?.[++rows] + if (actions) this.act(label, q, actions) + }) + if (def.columns) { + q.on('column', (index, value, more) => log(`column ${index} ${formatValue(value)}${more ? ' more=true' : ''}`)) + } + q.on('rowcount', n => log(`rowcount ${n}`)) + q.on('info', m => log(`info ${describeError(m)}`)) + q.on('error', (e, more) => log(`error ${describeError(e)} more=${more}`)) + q.on('output', () => log('output')) + q.on('done', () => log('done')) + q.on('free', () => { log('free'); resolveFree() }) + q.once('free', () => { + if (label === 'q1') this.startFollowUps('free') + // actions on a query that has already freed, e.g. a late cancel + if (at.free) setTimeout(() => this.act(label, q, at.free), 20) + }) + if (at.start) this.act(label, q, at.start) + for (const [ms, actions] of Object.entries(at.later ?? {})) { + setTimeout(() => this.act(label, q, actions), Number(ms)) + } + return q + } + + act (label, q, actions) { + for (const action of actions) { + const [name, arg] = action.split(':') + if (name === 'pause') { + this.log(label, 'action pause') + q.pauseQuery() + } else if (name === 'resume') { + const resume = () => { this.log(label, 'action resume'); q.resumeQuery() } + if (arg) setTimeout(resume, Number(arg)) + else resume() + } else if (name === 'cancel') { + this.log(label, 'action cancel') + q.cancelQuery(e => this.log(label, e ? `cancel-cb error ${strip(e.message)}` : 'cancel-cb ok')) + } else if (name === 'queue') { + // start the follow-up queries now, while this query is still on the connection + this.startFollowUps(arg) + } else { + throw new Error(`unknown action ${action}`) + } + } + } + + startFollowUps (when) { + for (const f of this.scenario.followUps ?? []) { + if ((f.when ?? 'start') === when) this.start(f.label, f) + } + } + + async execute () { + const s = this.scenario + for (const statement of s.setup ?? []) { + await this.conn.promises.query(statement) + } + this.start('q1', s) + this.startFollowUps('start') + + const timeoutMs = s.timeoutMs ?? 6000 + const deadline = Date.now() + timeoutMs + // follow-ups can be added while waiting, so wait until every known query has freed + for (;;) { + const labels = [...this.pending.keys()] + const res = await withTimeout(Promise.all(labels.map(l => this.pending.get(l))), Math.max(1, deadline - Date.now())) + if (res.timeout) { + const stuck = [] + for (const l of labels) { + if (!(await withTimeout(this.pending.get(l), 1)).ok) stuck.push(l) + } + this.t.push(`TIMEOUT no free from ${stuck.join(',')} after ${timeoutMs}ms`) + return false + } + await delay(SETTLE_MS) // late events after free are part of the transcript + if (this.pending.size === labels.length) return true + } + } + + async check () { + const res = await withTimeout(this.conn.promises.query('select 1 as n'), 3000) + if (res.timeout) this.t.push('check TIMEOUT') + else if (!res.ok) this.t.push(`check error ${describeError(res.error)}`) + else this.t.push(res.value.first?.[0]?.n === 1 ? 'check ok' : 'check wrong result') + } +} + +// returns the transcript of one run of the scenario as an array of lines +async function runScenario (sql, connectionString, scenario) { + const t = new Transcript() + const conn = await sql.promises.open(connectionString) + const run = new Run(sql, conn, scenario, t) + try { + const freed = await run.execute() + if (freed) await run.check() + } catch (e) { + t.push(`EXCEPTION ${strip(e.message)}`) + } + const closed = await withTimeout(conn.promises.close(), 3000) + if (closed.timeout) t.push('close TIMEOUT') + return t.toLines() +} + +// runs the scenario in a child process (see run-one.js) and returns its transcript +function runIsolated (root, connectionString, scenario) { + return new Promise(resolve => { + execFile(process.execPath, [path.join(__dirname, 'run-one.js'), root, scenario.name], { + env: { ...process.env, MSSQL_CONTRACT_CS: connectionString }, + timeout: PROCESS_TIMEOUT_MS, + maxBuffer: 16 * 1024 * 1024, + windowsHide: true + }, (err, stdout, stderr) => { + try { + resolve(JSON.parse(stdout)) + } catch { + resolve([err?.killed ? `PROCESS TIMEOUT after ${PROCESS_TIMEOUT_MS}ms` : `PROCESS FAILED ${err?.code ?? ''} ${strip(stderr).slice(0, 200)}`]) + } + }) + }) +} + +// runs the scenario several times: a contract has to be deterministic, so every +// distinct transcript is returned, most frequent first. +async function captureScenario (root, connectionString, scenario, repeat = 3) { + const seen = new Map() + for (let i = 0; i < repeat; i++) { + const lines = await runIsolated(root, connectionString, scenario) + const key = lines.join('\n') + seen.set(key, (seen.get(key) ?? 0) + 1) + } + return [...seen.entries()] + .sort((a, b) => b[1] - a[1]) + .map(([text, count]) => ({ lines: text.split('\n'), count })) +} + +module.exports = { runScenario, runIsolated, captureScenario } diff --git a/test/contract/repro/common.js b/test/contract/repro/common.js new file mode 100644 index 00000000..3be6d82e --- /dev/null +++ b/test/contract/repro/common.js @@ -0,0 +1,9 @@ +'use strict' +// shared by the issue repros. MSNODESQLV8_ROOT picks another build (e.g. an older +// release installed elsewhere); MSSQL_CS overrides the connection string. +const path = require('path') +const { TestEnv } = require('../../env/test-env') +const root = process.env.MSNODESQLV8_ROOT || path.join(__dirname, '../../..') +const sql = require(root) +const cs = process.env.MSSQL_CS || new TestEnv().connectionString +module.exports = { sql, cs, version: require(path.join(root, 'package.json')).version } diff --git a/test/contract/repro/i478.js b/test/contract/repro/i478.js new file mode 100644 index 00000000..e3eba87a --- /dev/null +++ b/test/contract/repro/i478.js @@ -0,0 +1,27 @@ +'use strict' +const { sql, cs, version } = require('./common') +const events = (conn, text) => new Promise(resolve => { + const ev = [] + const q = conn.query(text) + q.on('meta', () => ev.push('meta')) + q.on('info', m => ev.push(`info ${m.code}`)) + q.on('error', (e, more) => ev.push(`error ${e.code} more=${more}`)) + q.on('done', () => ev.push('done')) + q.on('free', () => { ev.push('free'); resolve(ev) }) +}) +const run = (conn, text) => new Promise((resolve, reject) => + conn.query(text, (e, rows, more) => { if (e) reject(e); else if (!more) resolve() })) +sql.open(cs, async (err, conn) => { + if (err) throw err + await run(conn, 'create table #t (id int primary key); insert #t values (1)') + const cases = { + A: 'insert #t values (1)', + B: 'select 1 as n; insert #t values (1)', + C: 'select 1 as n; insert #t values (1); select 2 as m', + D: 'insert #t values (1); select 2 as m' + } + for (const [k, text] of Object.entries(cases)) { + console.log(version, process.platform, k, (await events(conn, text)).join(' > ')) + } + conn.close(() => {}) +}) diff --git a/test/contract/repro/i479.js b/test/contract/repro/i479.js new file mode 100644 index 00000000..32b03d78 --- /dev/null +++ b/test/contract/repro/i479.js @@ -0,0 +1,45 @@ +'use strict' +const { sql, cs, version } = require('./common') +const big = 'select top 5000 a.name from sys.all_objects a cross join sys.all_objects b' +function trace (q, log) { + q.on('error', (e, more) => log(`error ${e.sqlstate} ${e.message} more=${more}`)) + q.on('done', () => log('done')) + q.on('free', () => log('free')) +} +function runningCancel (conn, text) { + return new Promise(resolve => { + const out = [] + let rows = 0 + const q = conn.query(text) + q.on('row', () => { + if (++rows === 100) { + out.push('cancelQuery()') + q.cancelQuery(e => out.push(`cancel cb: ${e ? e.message : 'no error'}`)) + } + }) + trace(q, m => out.push(`${m} [rows=${rows}]`)) + q.on('free', () => setTimeout(() => resolve(out), 200)) + }) +} +function lateCancel (conn) { + return new Promise(resolve => { + const out = [] + const q = conn.query('select 1 as n') + trace(q, m => out.push(m)) + q.on('free', () => setTimeout(() => { + out.push('cancelQuery()') + q.cancelQuery(e => { + out.push(`cancel cb: ${e ? e.message : 'no error'}`) + setTimeout(() => resolve(out), 200) + }) + }, 50)) + }) +} +sql.open(cs, async (err, conn) => { + if (err) throw err + console.log(`msnodesqlv8 ${version} ${process.platform} node ${process.version}`) + console.log('A running cancel\n ' + (await runningCancel(conn, big)).join('\n ')) + console.log('B late cancel\n ' + (await lateCancel(conn)).join('\n ')) + console.log('C running cancel after a print\n ' + (await runningCancel(conn, `print 'start'; ${big}`)).join('\n ')) + conn.close(() => {}) +}) diff --git a/test/contract/repro/i479b.js b/test/contract/repro/i479b.js new file mode 100644 index 00000000..16adf1ff --- /dev/null +++ b/test/contract/repro/i479b.js @@ -0,0 +1,40 @@ +'use strict' +// comment on #479: point 4 (paused polling query cancelled) and point 5 (pause + cancel before first state change) +const { sql, cs } = require('./common') +const big = 'select top 5000 a.name from sys.all_objects a cross join sys.all_objects b' +const which = process.argv[2] +const t0 = Date.now() +const log = m => console.log(`+${String(Date.now() - t0).padStart(5)}ms ${m}`) +function trace (q) { + q.on('error', (e, more) => log(`error ${e.sqlstate} ${e.message} more=${more}`)) + q.on('done', () => log('done')) + q.on('free', () => log('free')) +} +const followUp = conn => conn.query('select 1 as n', (err, res) => { + log(`follow-up ${err ? err.message : JSON.stringify(res)}`) + conn.close(() => process.exit(0)) +}) +sql.open(cs, (err, conn) => { + if (err) throw err + setTimeout(() => { log('TIMEOUT - hung'); process.exit(2) }, 10000) + if (which === '4') { + const q = conn.query(sql.PollingQuery(big)) + let rows = 0 + q.on('row', () => { + if (++rows === 100) { + q.pauseQuery() + q.cancelQuery(e => { + log(`cancel cb ${e ? e.message : 'no error'}`) + followUp(conn) + }) + } + }) + trace(q) + } else { + const q = conn.query("waitfor delay '00:00:05'; select 1 as n") + q.pauseQuery() + q.cancelQuery(e => log(`cancel cb ${e ? e.message : 'no error'}`)) + trace(q) + setTimeout(() => followUp(conn), 6000) + } +}) diff --git a/test/contract/repro/i480.js b/test/contract/repro/i480.js new file mode 100644 index 00000000..c7e0347e --- /dev/null +++ b/test/contract/repro/i480.js @@ -0,0 +1,28 @@ +'use strict' +const { sql, cs } = require('./common') +const QUERY = 'select top 51 object_id as a from sys.all_objects; select top 51 object_id as b from sys.all_objects' +function run (conn, pauseAtRow) { + return new Promise((resolve, reject) => { + const q = conn.query(QUERY) + const meta = [] + const rowsPerResultSet = [] + let rows = 0 + q.on('meta', m => { meta.push(m.map(c => c.name).join()); rowsPerResultSet.push(0) }) + q.on('error', reject) + q.on('row', () => { + rowsPerResultSet[rowsPerResultSet.length - 1]++ + if (++rows === pauseAtRow) { + q.pauseQuery() + setTimeout(() => q.resumeQuery(), 50) + } + }) + q.on('free', () => resolve({ meta, rows, rowsPerResultSet })) + }) +} +sql.open(cs, async (err, conn) => { + if (err) throw err + for (const pauseAtRow of [50, 51, 52]) { + console.log(`pause at row ${pauseAtRow}:`, JSON.stringify(await run(conn, pauseAtRow))) + } + conn.close(() => {}) +}) diff --git a/test/contract/repro/i481.js b/test/contract/repro/i481.js new file mode 100644 index 00000000..1490a284 --- /dev/null +++ b/test/contract/repro/i481.js @@ -0,0 +1,65 @@ +'use strict' +const { sql, cs, version } = require('./common') +const OK = 'select 1 as n' +const EXEC_ERROR = "raiserror('boom', 16, 1)" +const LATE_ERROR = "select 1 as n; raiserror('boom', 16, 1)" +const SLOW = "waitfor delay '00:00:02'; select 2 as n" +const show = (err, rows) => err ? `${err.sqlstate || ''} ${err.message}` : JSON.stringify(rows) +function recorder (resolve) { + const t0 = Date.now() + const out = [] + const giveUp = setTimeout(() => resolve([...out, '(gave up after 8 s)']), 8000) + return { + log: m => out.push(`+${String(Date.now() - t0).padStart(4)}ms ${m}`), + finish: () => { clearTimeout(giveUp); setTimeout(() => resolve(out), 100) } + } +} +function overlap (conn, q1Text, q1Params, when) { + return new Promise(resolve => { + const { log, finish } = recorder(resolve) + let open = 2 + const follow = () => { + for (const [name, text] of [['q2', SLOW], ['q3', 'select 3 as n']]) { + const q = conn.query(text, (err, rows) => log(`${name} cb ${show(err, rows)}`)) + q.on('submitted', () => log(`${name} submitted`)) + q.on('free', () => { log(`${name} free`); if (--open === 0) finish() }) + } + } + const q1 = conn.query(q1Text, q1Params, err => log(`q1 cb ${err ? show(err) : 'ok'}`)) + q1.on('free', () => { log('q1 free'); if (when === 'on free') follow() }) + if (when === 'now') follow() + }) +} +function cancelLater (conn, q1Text) { + return new Promise(resolve => { + const { log, finish } = recorder(resolve) + const q1 = conn.query(q1Text, err => log(`q1 cb ${err ? show(err) : 'ok'}`)) + q1.on('free', () => { + log('q1 free') + const q2 = conn.query(SLOW, (err, rows) => log(`q2 cb ${show(err, rows)}`)) + q2.on('submitted', () => setTimeout(() => { + log('q2.cancelQuery()') + q2.cancelQuery(e => log(`q2 cancel cb ${e ? e.message : 'no error'}`)) + }, 300)) + q2.on('done', () => log('q2 done')) + q2.on('free', () => { log('q2 free'); finish() }) + }) + }) +} +sql.open(cs, async (err, conn) => { + if (err) throw err + console.log(`msnodesqlv8 ${version} ${process.platform} node ${process.version}`) + const runs = [ + ['A1 ok, q2/q3 queued at once', () => overlap(conn, 'select ? as v', [1], 'now')], + ['A2 parameter fails to bind, q2/q3 queued at once', () => overlap(conn, 'select ? as v', [Infinity], 'now')], + ['A3 ok, q2/q3 from q1 free', () => overlap(conn, OK, [], 'on free')], + ['A4 error at execute, q2/q3 from q1 free', () => overlap(conn, EXEC_ERROR, [], 'on free')], + ['A5 error after a result, q2/q3 from q1 free', () => overlap(conn, LATE_ERROR, [], 'on free')], + ['B1 ok, cancel q2', () => cancelLater(conn, OK)], + ['B2 error at execute, cancel q2', () => cancelLater(conn, EXEC_ERROR)] + ] + for (const [title, run] of runs) { + console.log(`${title}\n ${(await run()).join('\n ')}`) + } + conn.close(() => {}) +}) diff --git a/test/contract/run-one.js b/test/contract/run-one.js new file mode 100644 index 00000000..c05cf50a --- /dev/null +++ b/test/contract/run-one.js @@ -0,0 +1,24 @@ +'use strict' + +// runs one scenario in this process and writes its transcript to stdout as JSON. +// recorder.js starts this as a child process for every run, so that a query that +// hangs, floods events or leaves native work behind cannot affect the next run. +// node run-one.js (connection string in MSSQL_CONTRACT_CS) + +const { scenarios } = require('./scenarios') +const { runScenario } = require('./recorder') + +const [root, name] = process.argv.slice(2) +const scenario = scenarios.find(s => s.name === name) +if (!scenario) { + console.error(`no scenario ${name}`) + process.exit(2) +} + +runScenario(require(root), process.env.MSSQL_CONTRACT_CS, scenario) + .then(lines => { + process.stdout.write(JSON.stringify(lines), () => process.exit(0)) + }) + .catch(e => { + process.stdout.write(JSON.stringify([`EXCEPTION ${e.message}`]), () => process.exit(0)) + }) diff --git a/test/contract/scenarios.js b/test/contract/scenarios.js new file mode 100644 index 00000000..dbccc8cc --- /dev/null +++ b/test/contract/scenarios.js @@ -0,0 +1,120 @@ +'use strict' + +// the event contract corpus: each scenario is a query plus what is done to it while it +// runs. its expected transcript lives in corpus/.txt (see recorder.js for the +// line format). to add an edge case, add a scenario here and capture it: +// node test/contract/capture.js --update +// then read the transcript it wrote and edit it to what the contract should be. +// +// a scenario: +// name group/name - the corpus file, without the mode suffix +// sql the query text; params optional +// setup statements run first on the same connection +// columns also record each 'column' event with its value - only for small queries +// whose values are the same on every server +// at actions while it runs: +// start: [...] straight after query() +// row: { 51: [...] } on the nth row (1 based, counted across result sets) +// later: { 300: [...] } ms after query() +// free: [...] just after 'free' +// a follow-up can have its own 'at' as well. +// actions: 'pause', 'resume', 'resume:50' (after 50 ms), 'cancel', +// 'queue:' (start followUps with that when, now) +// followUps queries put on the same connection: { label, sql, when: 'start' | 'free' } +// modes which variants to generate, each a separate corpus file: +// events listen to events only (how streaming consumers such as node-mssql read) +// callback also pass a callback +// +// polling queries (sql.PollingQuery) are not covered: the contract is for ordinary queries. + +const BIG = 'select top 5000 a.name from sys.all_objects a cross join sys.all_objects b' +const SLOW = "waitfor delay '00:00:01'; select 2 as n" +const DUP_TABLE = ['create table #t (id int constraint pk_t primary key); insert #t values (1)'] +const TWO_51 = 'select top 51 object_id as a from sys.all_objects; select top 51 object_id as b from sys.all_objects' +const TYPES = "select 1 as i, N'x' as s, cast(1.5 as decimal(5, 2)) as d, cast('2020-01-02T03:04:05' as datetime2(0)) as dt, cast(null as int) as nul, 0x0102 as b, cast(1 as bit) as bt" + +const BOTH = ['events', 'callback'] +const EVENTS = ['events'] + +const base = [ + // ----- plain reads: the shapes every other group builds on + { name: 'read/one-row', sql: 'select 1 as n', columns: true, modes: BOTH }, + { name: 'read/types', sql: TYPES, columns: true, modes: BOTH }, + { name: 'read/no-rows', sql: 'select top 0 1 as n', modes: BOTH }, + { name: 'read/two-result-sets', sql: 'select 1 as a; select 2 as b', columns: true, modes: BOTH }, + { name: 'read/two-rows-two-columns', sql: "select 1 as a, 'x' as b union all select 2, 'y'", columns: true, modes: BOTH }, + { name: 'read/rows-50', sql: 'select top 50 object_id as a from sys.all_objects', modes: EVENTS }, + { name: 'read/rows-51', sql: 'select top 51 object_id as a from sys.all_objects', modes: EVENTS }, + { name: 'read/two-by-51', sql: TWO_51, modes: EVENTS }, + { name: 'read/param', sql: 'select ? as v', params: [1], columns: true, modes: BOTH }, + { name: 'read/insert-rowcount', setup: ['create table #r (id int)'], sql: 'insert #r values (1)', modes: BOTH }, + { name: 'read/insert-then-select', setup: ['create table #r (id int)'], sql: 'insert #r values (1); select id from #r', columns: true, modes: BOTH }, + { name: 'read/print-then-select', sql: "print 'p1'; select 1 as n", columns: true, modes: BOTH }, + { name: 'read/select-then-print', sql: "select 1 as n; print 'p1'", columns: true, modes: BOTH }, + { name: 'read/print-only', sql: "print 'p1'", modes: BOTH }, + + // ----- errors (#478, #475): the order of errors and infos, and 'more' + { name: 'errors/raiserror-at-execute', sql: "raiserror('boom', 16, 1)", modes: BOTH }, + { name: 'errors/raiserror-after-result', sql: "select 1 as n; raiserror('boom', 16, 1)", columns: true, modes: BOTH }, + { name: 'errors/raiserror-then-result', sql: "raiserror('boom', 16, 1); select 2 as m", columns: true, modes: BOTH }, + { name: 'errors/print-then-raiserror', sql: "print 'p1'; raiserror('boom', 16, 1)", modes: BOTH }, + { name: 'errors/two-raiserrors-then-result', sql: "print 'p1'; raiserror('e1', 16, 1); print 'p2'; raiserror('e2', 16, 1); select 1 as n", columns: true, modes: BOTH }, + { name: 'errors/throw-ends-batch', sql: "select 1 as n; throw 50001, 'thrown', 1; select 2 as m", columns: true, modes: BOTH }, + { name: 'errors/syntax', sql: 'select from where', modes: BOTH }, + { name: 'errors/bind-failure', sql: 'select ? as v', params: [Infinity], modes: BOTH }, + { name: 'errors/dup-key-a', setup: DUP_TABLE, sql: 'insert #t values (1)', modes: BOTH }, + { name: 'errors/dup-key-b', setup: DUP_TABLE, sql: 'select 1 as n; insert #t values (1)', columns: true, modes: BOTH }, + { name: 'errors/dup-key-c', setup: DUP_TABLE, sql: 'select 1 as n; insert #t values (1); select 2 as m', columns: true, modes: BOTH }, + { name: 'errors/dup-key-d', setup: DUP_TABLE, sql: 'insert #t values (1); select 2 as m', columns: true, modes: BOTH }, + + // ----- pause / resume (#480, #470): 51 rows is one full batch of 50 plus one + ...[1, 49, 50, 51, 52, 101, 102].map(n => ({ + name: `pause/two-by-51-at-${n}`, sql: TWO_51, at: { row: { [n]: ['pause', 'resume:50'] } }, modes: EVENTS + })), + { name: 'pause/before-execute', sql: 'select 1 as n', at: { start: ['pause', 'resume:50'] }, modes: EVENTS }, + // back pressure as node streams apply it: pause on every row, resume shortly after + { name: 'pause/every-row', sql: TWO_51, at: { row: Object.fromEntries(Array.from({ length: 102 }, (_, i) => [i + 1, ['pause', 'resume:1']])) }, modes: EVENTS }, + + // ----- cancel (#479) + { name: 'cancel/streaming-at-100', sql: BIG, at: { row: { 100: ['cancel'] } }, modes: EVENTS }, + { name: 'cancel/streaming-after-print-at-100', sql: `print 'start'; ${BIG}`, at: { row: { 100: ['cancel'] } }, modes: EVENTS }, + { name: 'cancel/paused-streaming-at-100', sql: BIG, at: { row: { 100: ['pause', 'cancel'] } }, modes: EVENTS }, + { name: 'cancel/before-execute', sql: SLOW, at: { start: ['cancel'] }, modes: EVENTS }, + { name: 'cancel/paused-before-execute', sql: SLOW, at: { start: ['pause', 'cancel'] }, modes: EVENTS }, + { name: 'cancel/during-execute', sql: SLOW, at: { later: { 300: ['cancel'] } }, modes: BOTH }, + { name: 'cancel/last-row', sql: 'select top 5 object_id as a from sys.all_objects', at: { row: { 5: ['cancel'] } }, modes: EVENTS }, + { name: 'cancel/late-after-free', sql: 'select 1 as n', at: { free: ['cancel'] }, modes: EVENTS }, + + // ----- the connection's work queue (#481): a follow-up must not run until the + // query before it has freed, whatever way that query ended + ...[ + ['ok', 'select ? as v', [1]], + ['bind-failure', 'select ? as v', [Infinity]], + ['error-at-execute', "raiserror('boom', 16, 1)"], + ['error-after-result', "select 1 as n; raiserror('boom', 16, 1)"] + ].flatMap(([label, sql, params]) => ['start', 'free'].map(when => ({ + name: `queue/${label}-then-two-on-${when}`, + sql, + params, + followUps: [{ label: 'q2', sql: SLOW, when, callback: true }, { label: 'q3', sql: 'select 3 as n', when, callback: true }], + modes: ['callback'] + }))), + ...[['ok', 'select 1 as n'], ['error-at-execute', "raiserror('boom', 16, 1)"]].map(([label, sql]) => ({ + name: `queue/${label}-then-cancel-follow-up`, + sql, + followUps: [{ label: 'q2', sql: SLOW, when: 'free', callback: true, at: { later: { 300: ['cancel'] } } }], + modes: ['callback'] + })) +] + +function expand (s) { + return (s.modes ?? EVENTS).map(listen => ({ + ...s, + name: `${s.name}.${listen}`, + callback: listen === 'callback' + })) +} + +const scenarios = base.flatMap(expand) + +module.exports = { scenarios } From b45a83aaa3872adf4bede14340516ec5a17d5a72 Mon Sep 17 00:00:00 2001 From: TimelordUK Date: Sat, 17 Oct 2026 12:03:01 +0100 Subject: [PATCH 2/4] fix: pausing on the last row of a batch could run two native calls at once A pause on the last row of a batch was ignored: dispatch() went on to the next result set (or ended the query) while paused, and resume() then did the same step again from the stale batch. Two nextResultSet calls in flight on one statement crashed the process (0xC0000005, pause/every-row about 1 run in 3). Otherwise the second call skipped a result set (#480), or after the last row done/free came twice followed by an endless rowcount 0 loop. A query now has one next step at a time: running, or parked by a pause. resume() runs the parked step and never starts another. Nothing, done included, is emitted while paused. The three pause transcripts are now agreed; the pause test that expected done while still paused now resumes first. Co-Authored-By: Claude Opus 5.5 (1M context) --- lib/reader.js | 72 ++++---- test/contract/HANDOVER.md | 35 +++- .../corpus/pause/every-row.events.txt | 158 +++++++++++++++++- .../corpus/pause/two-by-51-at-102.events.txt | 7 +- .../corpus/pause/two-by-51-at-51.events.txt | 5 +- test/pause.test.js | 2 + 6 files changed, 230 insertions(+), 49 deletions(-) diff --git a/lib/reader.js b/lib/reader.js index 2b1fac55..3f85587e 100755 --- a/lib/reader.js +++ b/lib/reader.js @@ -54,6 +54,10 @@ class Query extends BasePromises { this.batchData = null this.running = true this.paused = false + // the one next step of the read, held while paused: resume() runs it. a read only ever + // has one step going (a native call, or what runs when it returns), so resume must never + // start another - two native calls on one statement at once crash the process. + this.parked = null this.done = false this.infoFromNextResult = false this.rowBatchSize = 50 /* ignored for prepared statements */ @@ -384,42 +388,52 @@ class Query extends BasePromises { }) } + // park a step to run on resume, if paused. true when parked. + park (step) { + if (!this.paused) return false + logger.debugLazy(() => `paused, park next step for queryId ${this.queryId}`, this.context) + this.parked = step + return true + } + dispatch () { if (!this.running) { logger.debugLazy(() => `dispatch called but not running for queryId ${this.queryId}`, this.context) return } - if (this.paused) { - logger.debugLazy(() => `dispatch called but paused for queryId ${this.queryId}`, this.context) - return // will come back at some later stage - } + if (this.park(() => this.dispatch())) return logger.traceLazy(() => `dispatch fetching rows for queryId ${this.queryId}, rowBatchSize=${this.rowBatchSize}`, this.context) this.nativeGetRows(this.queryId, this.rowBatchSize).then(d => { logger.traceLazy(() => `dispatch received ${d?.data?.length || 0} rows for queryId ${this.queryId}, endOfRows=${d?.endOfRows} endOfResults=${d?.endOfResults}`, this.context) this.batchRowIndex = 0 this.batchData = d - this.dispatchRows(d) - if (this.paused && this.batchRowIndex < (d.data ? d.data.length : 0)) { - // paused part way through this batch - resume() dispatches the rest of it and - // then fetches or ends, so going on here would raise 'done' too early. - return - } - if (!d.endOfRows) { - this.dispatch() - } else if (!d.endOfResults) { - this.nextResult() - } else { - d.meta = [] - this.moveToNextResult(d) - } + this.continueBatch() }).catch(err => { logger.debugLazy(() => `dispatch error for queryId ${this.queryId}: ${err}`, 'DriverRead.dispatch', this.context) this.end(err) }) } + // emit what is left of the current batch, then fetch more, or move to the next result. + // a pause, mid batch or on its last row, parks here until resume. + continueBatch () { + if (this.park(() => this.continueBatch())) return + const d = this.batchData + this.dispatchRows(d) + if (this.park(() => this.continueBatch())) return + if (!d.endOfRows) { + this.dispatch() + } else if (!d.endOfResults) { + this.nextResult() + } else { + d.meta = [] + this.moveToNextResult(d) + } + } + nextResult () { + if (this.park(() => this.nextResult())) return this.infoFromNextResult = false this.nativeNextResult(this.queryId) .then(nextResultSetInfo => { @@ -483,24 +497,10 @@ class Query extends BasePromises { logger.debugLazy(() => `DriverRead.resume() called for queryId ${this.queryId}`, this.context) this.queue.resume(this.notify.getOperation()) this.paused = false - this.dispatchRows(this.batchData) - if (this.paused) { - // dispatchRows paused again mid-batch, don't fetch more - logger.debugLazy(() => `DriverRead.resume() re-paused during dispatchRows for queryId ${this.queryId}`, this.context) - } else if (this.batchData && this.batchData.endOfRows && - this.batchRowIndex >= (this.batchData.data ? this.batchData.data.length : 0)) { - // all rows from this batch were dispatched and the native result set is exhausted - // do not call nativeGetRows again or the ODBC driver will return a function sequence error - logger.debugLazy(() => `DriverRead.resume() endOfRows reached, batch fully dispatched for queryId ${this.queryId}`, this.context) - if (!this.batchData.endOfResults) { - this.nextResult() - } else { - this.batchData.meta = [] - this.moveToNextResult(this.batchData) - } - } else { - this.dispatch() - } + // nothing parked: the read's step is still running, and carries on when it returns + const step = this.parked + this.parked = null + if (step) step() logger.debugLazy(() => `DriverRead.resume() resumed operation for queryId ${this.queryId}`, this.context) } diff --git a/test/contract/HANDOVER.md b/test/contract/HANDOVER.md index 8572dbef..fd79b1cd 100644 --- a/test/contract/HANDOVER.md +++ b/test/contract/HANDOVER.md @@ -9,7 +9,36 @@ way through a batch. The **event contract at the edges** is broken: the order of infos, cancel, pausing at a batch boundary, and the work queue after a failure. node-mssql drives all of those. Every point in the four issues reproduced on localdb (ODBC 18, Windows). -No fixes have been made yet. This branch adds: +## Progress — 2026-10-17 + +**Fixed: the pause/resume crash, #480, and the loop after pausing on the last row.** All +three had one cause. A pause on the *last* row of a batch was ignored: `dispatch()` went on to +`nextResult()` (or ended the query) while paused, and `resume()` then did the same step again +from the stale `batchData`. If the first `nextResultSet` was still in flight, two native calls +ran on one statement at once (0xC0000005). If it had finished, the second one skipped a +whole result set (#480). Or, at the end of the last set, `done`/`free` came out twice and +then the endless `rowcount 0` loop. + +The fix in `lib/reader.js`: a query has exactly one next step at any time. Either it is +running, or it is *parked* by a pause (`park()`, `continueBatch()`). `resume()` runs the +parked step and never starts another. Nothing that a step would emit, `done` included, +comes out while paused, except what a native call already in flight brings back. +- `pause/every-row`, `pause/two-by-51-at-51`, `pause/two-by-51-at-102` are now + `# status: agreed`. every-row: 23 runs the same, no crash. +- `test/pause.test.js` "should handle multiple pause calls" expected `done` while still + paused. It now resumes, then expects `done`. +- Full mocha suite: 897 passing; the only failures were the three transcripts above, before + they were updated. + +Still open, not this change: `queue/bind-failure-then-two-on-start` is non-deterministic +(#481, overlapping follow-ups), and so is `cancel/paused-before-execute` (#479, `free` x2). + +Open decision: a pause that lands while a native call is in flight still lets that call's +events out, e.g. the next result set's `meta`. Should paused mean no events at all? + +## State at first handover + +No fixes had been made. This branch adds: - `test/contract/`: the event-contract corpus (see `README.md`), 77 scenarios, every one pinned to what **5.6.0 does today**, bugs included (`# status: unreviewed`); - `test/contract/repro/`: dhensby's repro scripts from the issues, runnable as they are @@ -64,7 +93,7 @@ corpus is our guard. ## Suggested order -1. **The crash on pause/resume on every row.** An untested hypothesis: `resume()` calls +1. ~~**The crash on pause/resume on every row.**~~ Fixed, see Progress. The hypothesis was right:: `resume()` calls `dispatch()` (or `nextResult()`) while the previous `nativeGetRows` / `nextResultSet` is still in flight, so two native calls run on one statement at once. Nothing in `reader.js` stops a second fetch while one is outstanding. #480 is the same family: `dispatch()` and @@ -73,7 +102,7 @@ corpus is our guard. `capture.js --repeat 20 every-row`. 2. **#481 queue.** Make finishing an item specific to that item and idempotent (`WorkQueue.finish(op)`, as in dhensby's option 2). -3. **#480 and the last-row loop.** Likely solved together with 1. +3. ~~**#480 and the last-row loop.**~~ Fixed together with 1. 4. **#479 cancel.** `done` only for a cancel that worked, and after the HY008. Report a refused native cancel (`CancelWorker::OnOK` passes `(null, false)`). The `STATEMENT_ERROR` that info-only diagnostics set makes a cancel after a PRINT a silent no-op. diff --git a/test/contract/corpus/pause/every-row.events.txt b/test/contract/corpus/pause/every-row.events.txt index 01cb1630..e366df00 100644 --- a/test/contract/corpus/pause/every-row.events.txt +++ b/test/contract/corpus/pause/every-row.events.txt @@ -1,10 +1,7 @@ # scenario: pause/every-row.events -# status: unreviewed +# status: agreed # sql: select top 51 object_id as a from sys.all_objects; select top 51 object_id as b from sys.all_objects # at: {"row":{"1":["pause","resume:1"],"2":["pause","resume:1"],"3":["pause","resume:1"],"4":["pause","resume:1"],"5":["pause","resume:1"],"6":["pause","resume:1"],"7":["pause","resume:1"],"8":["pause","resume:1"],"9":["pause","resume:1"],"10":["pause","resume:1"],"11":["pause","resume:1"],"12":["pause","resume:1"],"13":["pause","resume:1"],"14":["pause","resume:1"],"15":["pause","resume:1"],"16":["pause","resume:1"],"17":["pause","resume:1"],"18":["pause","resume:1"],"19":["pause","resume:1"],"20":["pause","resume:1"],"21":["pause","resume:1"],"22":["pause","resume:1"],"23":["pause","resume:1"],"24":["pause","resume:1"],"25":["pause","resume:1"],"26":["pause","resume:1"],"27":["pause","resume:1"],"28":["pause","resume:1"],"29":["pause","resume:1"],"30":["pause","resume:1"],"31":["pause","resume:1"],"32":["pause","resume:1"],"33":["pause","resume:1"],"34":["pause","resume:1"],"35":["pause","resume:1"],"36":["pause","resume:1"],"37":["pause","resume:1"],"38":["pause","resume:1"],"39":["pause","resume:1"],"40":["pause","resume:1"],"41":["pause","resume:1"],"42":["pause","resume:1"],"43":["pause","resume:1"],"44":["pause","resume:1"],"45":["pause","resume:1"],"46":["pause","resume:1"],"47":["pause","resume:1"],"48":["pause","resume:1"],"49":["pause","resume:1"],"50":["pause","resume:1"],"51":["pause","resume:1"],"52":["pause","resume:1"],"53":["pause","resume:1"],"54":["pause","resume:1"],"55":["pause","resume:1"],"56":["pause","resume:1"],"57":["pause","resume:1"],"58":["pause","resume:1"],"59":["pause","resume:1"],"60":["pause","resume:1"],"61":["pause","resume:1"],"62":["pause","resume:1"],"63":["pause","resume:1"],"64":["pause","resume:1"],"65":["pause","resume:1"],"66":["pause","resume:1"],"67":["pause","resume:1"],"68":["pause","resume:1"],"69":["pause","resume:1"],"70":["pause","resume:1"],"71":["pause","resume:1"],"72":["pause","resume:1"],"73":["pause","resume:1"],"74":["pause","resume:1"],"75":["pause","resume:1"],"76":["pause","resume:1"],"77":["pause","resume:1"],"78":["pause","resume:1"],"79":["pause","resume:1"],"80":["pause","resume:1"],"81":["pause","resume:1"],"82":["pause","resume:1"],"83":["pause","resume:1"],"84":["pause","resume:1"],"85":["pause","resume:1"],"86":["pause","resume:1"],"87":["pause","resume:1"],"88":["pause","resume:1"],"89":["pause","resume:1"],"90":["pause","resume:1"],"91":["pause","resume:1"],"92":["pause","resume:1"],"93":["pause","resume:1"],"94":["pause","resume:1"],"95":["pause","resume:1"],"96":["pause","resume:1"],"97":["pause","resume:1"],"98":["pause","resume:1"],"99":["pause","resume:1"],"100":["pause","resume:1"],"101":["pause","resume:1"],"102":["pause","resume:1"]}} -# NOT DETERMINISTIC: 2 different transcripts in 3 runs -PROCESS FAILED 3221225477 ---- or submitted meta a row @@ -159,7 +156,160 @@ action pause action resume row action pause +action resume meta b +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause +action resume +row +action pause action resume done free diff --git a/test/contract/corpus/pause/two-by-51-at-102.events.txt b/test/contract/corpus/pause/two-by-51-at-102.events.txt index 64825fdc..1230be1e 100644 --- a/test/contract/corpus/pause/two-by-51-at-102.events.txt +++ b/test/contract/corpus/pause/two-by-51-at-102.events.txt @@ -1,5 +1,5 @@ # scenario: pause/two-by-51-at-102.events -# status: unreviewed +# status: agreed # sql: select top 51 object_id as a from sys.all_objects; select top 51 object_id as b from sys.all_objects # at: {"row":{"102":["pause","resume:50"]}} submitted @@ -8,8 +8,7 @@ row x51 meta b row x51 action pause +action resume done free -action resume -rowcount 0 (repeating) -RUNAWAY more than 2000 events +check ok diff --git a/test/contract/corpus/pause/two-by-51-at-51.events.txt b/test/contract/corpus/pause/two-by-51-at-51.events.txt index 7eff8a0c..d64938ad 100644 --- a/test/contract/corpus/pause/two-by-51-at-51.events.txt +++ b/test/contract/corpus/pause/two-by-51-at-51.events.txt @@ -1,13 +1,14 @@ # scenario: pause/two-by-51-at-51.events -# status: unreviewed +# status: agreed # sql: select top 51 object_id as a from sys.all_objects; select top 51 object_id as b from sys.all_objects # at: {"row":{"51":["pause","resume:50"]}} submitted meta a row x51 action pause -meta b action resume +meta b +row x51 done free check ok diff --git a/test/pause.test.js b/test/pause.test.js index d82e9324..8116e5e3 100755 --- a/test/pause.test.js +++ b/test/pause.test.js @@ -183,6 +183,8 @@ describe('pause', function () { onRow: () => { queryHelper.query.pauseQuery() queryHelper.query.pauseQuery() // Double pause + // nothing more, not even done, until resumed - and one resume is enough + setTimeout(() => queryHelper.query.resumeQuery(), PAUSE_CHECK_DELAY) }, onDone: (rowCount) => { assert.strictEqual(rowCount, 1) From ca8e2222f121a9339c1e1dd3dfb28a581408ec17 Mon Sep 17 00:00:00 2001 From: TimelordUK Date: Sat, 17 Oct 2026 12:43:14 +0100 Subject: [PATCH 3/4] fix: the work queue finishes each item exactly once, and a paused query holds the connection (#481) The queue advanced by removing whatever was at its head, so a query that failed advanced once too often: work queued behind it was removed just after it started, two statements overlapped ("Connection is busy with results for another command"), and a later query could no longer be cancelled. - WorkQueue.finish(op) removes that item only, by identity, starts the next only if it was the head, and is a no-op the second time. nextOp() is gone. - Each query keeps its own queue item. A prepared statement shares one notify across its executions, so the notify's operation was only the latest one. - A statement's unbind and free run straight after their query, before work already waiting (enqueueFollowUp), so 'free' is no longer delayed behind it. - close() always finishes its item: the cancelled branch of moveToNextResult cleared 'running' first, which is what the extra advance in end() covered. - dropItem matches by identity, not priority. A paused query now holds the connection. It keeps its place at the head, rather than moving to the back and removing the item waiting behind it without running it (that query was never submitted, and its callback never fired). A query submitted while another is paused waits for it, rather than freeing it. Cancelling a paused query ends it as any cancel does (HY008, then free), rather than freeing it silently, and close() cancels a paused query first. Corpus: the queue and paused-cancel transcripts are re-recorded and now deterministic; queue/ok-then-two-on-* are agreed. pause.test.js and querycancel.test.js are changed to the new rules. Co-Authored-By: Claude Opus 5.5 (1M context) --- lib/driver.js | 105 +++++++----------- lib/query-handler.js | 12 +- lib/queue.js | 57 +++++++--- lib/reader.js | 55 ++++++--- test/contract/HANDOVER.md | 55 ++++++++- .../cancel/paused-before-execute.events.txt | 11 -- .../cancel/paused-streaming-at-100.events.txt | 1 + ...bind-failure-then-two-on-free.callback.txt | 6 +- ...ind-failure-then-two-on-start.callback.txt | 13 --- ...after-result-then-two-on-free.callback.txt | 9 +- ...fter-result-then-two-on-start.callback.txt | 8 +- ...execute-then-cancel-follow-up.callback.txt | 7 +- ...r-at-execute-then-two-on-free.callback.txt | 9 +- ...-at-execute-then-two-on-start.callback.txt | 10 +- .../queue/ok-then-two-on-free.callback.txt | 8 +- .../queue/ok-then-two-on-start.callback.txt | 14 +-- test/pause.test.js | 53 ++++++--- test/querycancel.test.js | 3 +- 18 files changed, 261 insertions(+), 175 deletions(-) diff --git a/lib/driver.js b/lib/driver.js index 120792ef..ff250463 100755 --- a/lib/driver.js +++ b/lib/driver.js @@ -18,7 +18,6 @@ const driverModule = ((() => { CLOSE: 17, UNBIND: 18 } - const executingStates = new Set(['STATEMENT_SUBMITTED', 'STATEMENT_POLLING']) class DriverMgr { constructor (sql, version) { @@ -37,6 +36,13 @@ const driverModule = ((() => { } close (callback) { + // a paused query holds the connection, and would hold it forever: cancel it, so it + // ends as cancelled and frees its statement before the close runs. + const head = this.workQueue.peek() + if (head?.paused && head.commandType === driverCommandEnum.QUERY) { + logger.debugLazy(() => 'close: cancel the paused query at the head of the queue', 'DriverMgr.close') + this.cancel(head.args[0], () => {}) + } this.workQueue.enqueue(driverCommandEnum.CLOSE, () => { logger.debugLazy(() => 'cppDriver.close ', 'DriverMgr.close') this.cppDriver.close(() => { @@ -66,7 +72,7 @@ const driverModule = ((() => { const qid = notify.getQueryId() const handle = notify.getHandle() - if (queueItem.operationId === peek.operationId) { + if (queueItem === peek) { logger.debugLazy(() => `send ${queueItem.operationId} cancel to the driver`) this.cppDriver.cancelQuery(qid, handle, (e) => { this.forwardCancel(e, callback) @@ -97,32 +103,16 @@ const driverModule = ((() => { return qid === currentQueryId } - // the native statement is still running (SQLExecute not yet returned) - for a - // polling statement a cancel only flags the poll loop, so the statement is busy - // for a while after the cancel request has returned. - isExecuting (notify) { - const state = notify.getLastStateChange() - return state ? executingStates.has(state.newState) : false - } - drop (qid, first, notify, callback) { - const executing = this.isExecuting(notify) - logger.debugLazy(() => `drop called for query id ${qid}, paused: ${first.paused}, executing: ${executing}`, 'DriverMgr.drop') - if (first.paused && executing) { - // paused before execution finished: the statement must not be freed here while - // the native side still uses it. un-park it and cancel it as the active query - - // the reader then ends and frees the statement as normal. - logger.debugLazy(() => `un-park executing query id ${qid} to cancel`, 'DriverMgr.drop') - this.workQueue.resume(first) - this.execCancel(notify, first, callback) - } else if (first.paused) { - logger.debugLazy(() => `executing cancel for paused query id ${qid}`, 'DriverMgr.drop') - this.execCancel(notify, first, () => { - this.freeStatement(notify, () => { - logger.debugLazy(() => `freed statement and dropped paused query id ${qid}`, 'DriverMgr.drop') - this.workQueue.dropItem(first) - callback(null) - }) + logger.debugLazy(() => `drop called for query id ${qid}, paused: ${first.paused}`, 'DriverMgr.drop') + if (first.paused) { + // a paused query still owns its statement and the head of the queue. cancel the + // native statement, then the reader ends the query as cancelled and frees the + // statement as any other query does. + logger.debugLazy(() => `cancel paused query id ${qid}`, 'DriverMgr.drop') + this.execCancel(notify, first, (e) => { + callback(e) + if (!e && notify.queryWorker) notify.queryWorker.cancelPaused() }) } else { logger.debugLazy(() => `executing cancel for active query id ${qid}`, 'DriverMgr.drop') @@ -196,12 +186,14 @@ const driverModule = ((() => { : [] } - raiseFree (queryId, notify, callback) { + // op: the free statement's own queue item, finished once 'free' is raised (none + // when there was no statement to free) + raiseFree (queryId, notify, callback, op) { setImmediate(() => { callback(null, queryId) setImmediate(() => { notify.emit('free', queryId) - this.workQueue.nextOp() + this.workQueue.finish(op) }) }) } @@ -210,16 +202,16 @@ const driverModule = ((() => { const handle = notify.getHandle() const queryId = notify.getQueryId() if (handle) { - this.workQueue.enqueue(driverCommandEnum.FREE_STATEMENT, () => { + const op = this.workQueue.enqueueFollowUp(driverCommandEnum.FREE_STATEMENT, () => { logger.debugLazy(() => `free statement ${queryId}`, 'DriverMgr.freeStatement') this.cppDriver.releaseStatement(queryId, handle, () => { logger.debugLazy(() => `statement ${queryId} free - raise event`, 'DriverMgr.freeStatement') - this.raiseFree(queryId, notify, callback) + this.raiseFree(queryId, notify, callback, op) }) }, []) } else { - this.raiseFree(queryId, notify, callback) + this.raiseFree(queryId, notify, callback, null) } } @@ -241,51 +233,55 @@ const driverModule = ((() => { // only be unbound when rest of query completes. The output params // will now be ready to fetch out of the statement. - next (callback, err) { + next (callback, err, op) { setImmediate(() => { callback(err || null, false) setImmediate(() => { - this.workQueue.nextOp() + this.workQueue.finish(op) }) }) } + // the native calls below always complete asynchronously, so op is assigned by then beginTransaction (callback) { - this.workQueue.enqueue(driverCommandEnum.BEGIN_TRANSACTION, () => { - this.cppDriver.beginTransaction(err => { this.next(callback, err) }) + const op = this.workQueue.enqueue(driverCommandEnum.BEGIN_TRANSACTION, () => { + this.cppDriver.beginTransaction(err => { this.next(callback, err, op) }) }, []) } rollback (callback) { - this.workQueue.enqueue(driverCommandEnum.ROLLBACK, () => { - this.cppDriver.rollback(err => { this.next(callback, err) }) + const op = this.workQueue.enqueue(driverCommandEnum.ROLLBACK, () => { + this.cppDriver.rollback(err => { this.next(callback, err, op) }) }, []) } commit (callback) { - this.workQueue.enqueue(driverCommandEnum.COMMIT, () => { - this.cppDriver.commit(err => { this.next(callback, err) }) + const op = this.workQueue.enqueue(driverCommandEnum.COMMIT, () => { + this.cppDriver.commit(err => { this.next(callback, err, op) }) }, []) } prepare (notify, queryOrObj, callback) { - this.workQueue.enqueue(driverCommandEnum.PREPARE, () => { + const op = this.workQueue.enqueue(driverCommandEnum.PREPARE, () => { this.cppDriver.prepare(notify.getQueryId(), queryOrObj, (err, meta) => { callback(err, meta) - this.workQueue.nextOp() + this.workQueue.finish(op) }) }, []) } + // the query keeps its own queue item: a prepared statement shares one notify across + // its executions, so the notify's operation is only ever the latest one queued readOperation (notify, queryObj, params, factory, cb) { - notify.setOperation(this.workQueue.enqueue(driverCommandEnum.QUERY, + const op = this.workQueue.enqueue(driverCommandEnum.QUERY, (notify, query, params, callback) => { setImmediate(() => { - const q = this.reader.getQuery(notify, query, params, factory(), callback) + const q = this.reader.getQuery(notify, query, params, factory(), callback, op) notify.setQueryWorker(q) q.begin() }) - }, [notify, queryObj, params, cb])) + }, [notify, queryObj, params, cb]) + notify.setOperation(op) } readAllPrepared (notify, queryObj, params, cb) { @@ -303,24 +299,9 @@ const driverModule = ((() => { () => new NativeQueryHandler(this.cppDriver, this), cb) } - headPaused (notify, queryObj, params, cb) { - const peek = this.workQueue.peek() - const paused = peek?.paused - if (paused) { - const pausedNotify = peek.args[0] - this.freeStatement(pausedNotify, () => { - this.workQueue.dropItem(peek) - this.read(notify, queryObj, params, cb) - }) - } - return paused - } - + // a paused query holds the connection: a new query waits behind it like any other readAllQuery (notify, queryObj, params, cb) { - // if paused at head of q then kill this statement to allow driver to set up this one - if (!this.headPaused(notify, queryObj, params, cb)) { - this.read(notify, queryObj, params, cb) - } + this.read(notify, queryObj, params, cb) } } diff --git a/lib/query-handler.js b/lib/query-handler.js index 35bab128..bacb57b1 100755 --- a/lib/query-handler.js +++ b/lib/query-handler.js @@ -65,13 +65,13 @@ class NativeProcedureQueryHandler extends QueryHandler { // for a stored procedure with multiple statements, only unbind after all // statements are completed - unbind (more, not, qid, results, callback) { + unbind (more, not, qid, results, callback, op) { // Check if the query was cancelled before attempting unbind if (not.getCancelSent && not.getCancelSent()) { logger.debugLazy(() => `Skipping parameter unbind for cancelled statement ${qid}`, 'NativeProcedureQueryHandler.unbind') this.onStatementCompleteHandler.onStatementComplete(not, null, callback, results, more) if (!more) { - this.workQueue.nextOp() + this.workQueue.finish(op) } return } @@ -81,7 +81,7 @@ class NativeProcedureQueryHandler extends QueryHandler { logger.debugLazy(() => `Skipping parameter unbind for cancelled query worker ${qid}`, 'NativeProcedureQueryHandler.unbind') this.onStatementCompleteHandler.onStatementComplete(not, null, callback, results, more) if (!more) { - this.workQueue.nextOp() + this.workQueue.finish(op) } return } @@ -93,7 +93,7 @@ class NativeProcedureQueryHandler extends QueryHandler { not.emit('output', outputVector) this.onStatementCompleteHandler.onStatementComplete(not, outputVector, callback, results, more) if (!more) { - this.workQueue.nextOp() + this.workQueue.finish(op) } }) } @@ -101,8 +101,8 @@ class NativeProcedureQueryHandler extends QueryHandler { end (not, outputParams, callback, results, endMore) { if (!endMore) { const qid = not.getQueryId() - this.workQueue.enqueue(this.unbindEnum, (a) => - setImmediate(() => { this.unbind(a, not, qid, results, callback) }), [endMore]) + const op = this.workQueue.enqueueFollowUp(this.unbindEnum, (a) => + setImmediate(() => { this.unbind(a, not, qid, results, callback, op) }), [endMore]) } else { this.onStatementCompleteHandler.onStatementComplete(not, null, callback, results, endMore) } diff --git a/lib/queue.js b/lib/queue.js index 2d0dbfec..0f56ac31 100755 --- a/lib/queue.js +++ b/lib/queue.js @@ -2,6 +2,9 @@ const queueModule = ((() => { const priorityQueue = require('./data-struture/priority-queue/PriorityQueue') + const { Comparator } = require('./data-struture/utils/comparator/Comparator') + // items are compared by identity, never by priority + const byIdentity = new Comparator((a, b) => a === b ? 0 : 1) class WorkItem { constructor (commandType, fn, args, operationId) { this.paused = false @@ -9,6 +12,7 @@ const queueModule = ((() => { this.fn = fn this.args = args this.operationId = operationId + this.priority = operationId } run () { @@ -20,6 +24,7 @@ const queueModule = ((() => { constructor () { this.workQueue = new priorityQueue.PriorityQueue() this.operationId = 0 + this.followUps = 0 } emptyQueue () { @@ -28,10 +33,11 @@ const queueModule = ((() => { } } + // one item at a time: a new item starts now only if nothing else is queued execQueueOp (op) { const peek = this.workQueue.peek() - this.workQueue.add(op, op.operationId) - if (peek == null || peek.paused) { + this.workQueue.add(op, op.priority) + if (peek == null) { op.run() } } @@ -44,36 +50,55 @@ const queueModule = ((() => { return op } + // work that finishes off the item at the head (its statement's unbind and free) runs + // straight after it, before anything that was already waiting behind it. + enqueueFollowUp (commandType, fn, args) { + const head = this.workQueue.peek() + if (!head) return this.enqueue(commandType, fn, args) + const op = new WorkItem(commandType, fn, args, this.operationId++) + op.priority = head.priority + (++this.followUps) / 1e6 + this.execQueueOp(op) + return op + } + + // a paused query holds the connection: it keeps its place at the head, and work + // queued behind it waits until it is resumed and finished, or cancelled. park (item) { - this.workQueue.changePriority(item, Number.MAX_SAFE_INTEGER) item.paused = true - const peek = this.workQueue.peek() - if (!peek.paused) { - this.nextOp() - } } resume (item) { - this.workQueue.changePriority(item, item.operationId) item.paused = false } + has (item) { + return item != null && this.workQueue.find(item, byIdentity).length > 0 + } + dropItem (item) { - return this.workQueue.remove(item) + if (this.has(item)) this.workQueue.remove(item, byIdentity) + } + + // the owner of an item says it is finished: remove that item, and if it was the + // head, start the next. finishing an item twice, or one already gone, does nothing - + // it must never remove, or start, someone else's work. + finish (item) { + if (!this.has(item)) return + const wasHead = this.workQueue.peek() === item + this.workQueue.remove(item, byIdentity) + if (wasHead) { + this.followUps = 0 + this.exec() + } } exec () { const op = this.workQueue.peek() - if (op && !op.paused) { + if (op) { op.run() } } - nextOp () { - this.workQueue.remove(this.workQueue.peek()) - this.exec() - } - length () { return this.workQueue.length() } @@ -81,7 +106,7 @@ const queueModule = ((() => { pushRange (ops) { while (ops.length > 0) { const op = ops.pop() - this.workQueue.add(op, op.operationId) + this.workQueue.add(op, op.priority) } } diff --git a/lib/reader.js b/lib/reader.js index 3f85587e..0a1a2d50 100755 --- a/lib/reader.js +++ b/lib/reader.js @@ -25,16 +25,17 @@ class DriverRead { // invokeObject.begin(queryId, query, params, onInvoke) - getQuery (notify, query, params, invokeObject, callback) { - const q = new Query(this.native, this.version, this.useUTC, notify, this.workQueue, query, params, invokeObject, callback) + getQuery (notify, query, params, invokeObject, callback, operation) { + const q = new Query(this.native, this.version, this.useUTC, notify, this.workQueue, query, params, invokeObject, callback, operation) notify.setQueryWorker(q) return q } } class Query extends BasePromises { - constructor (native, version, useUTC, notify, queue, query, params, queryHandler, callback) { + constructor (native, version, useUTC, notify, queue, query, params, queryHandler, callback, operation) { super() + this.operation = operation // this query's own item on the connection's work queue this.version = version this.native = native this.useUTC = useUTC @@ -58,6 +59,7 @@ class Query extends BasePromises { // has one step going (a native call, or what runs when it returns), so resume must never // start another - two native calls on one statement at once crash the process. this.parked = null + this.pausedCancelled = false this.done = false this.infoFromNextResult = false this.rowBatchSize = 50 /* ignored for prepared statements */ @@ -118,12 +120,14 @@ class Query extends BasePromises { } close () { - if (!this.running) return // Already closed - this.running = false - // Clear any active timeout to prevent late-firing timeouts - this.notify.clearTimeout() - // Don't call nextOp here - it should be called after statement is freed - this.queue.nextOp() + if (this.running) { + this.running = false + // Clear any active timeout to prevent late-firing timeouts + this.notify.clearTimeout() + } + // the query's own item is finished; its free statement is a separate item. finish is + // idempotent, so this holds however the query stopped running + this.queue.finish(this.operation) } emitDone () { @@ -204,7 +208,7 @@ class Query extends BasePromises { } else { reject(msgs) } - this.queue.nextOp() + this.close() } else if (e) { // Error but more results available - just pass through resolve({ @@ -309,9 +313,7 @@ class Query extends BasePromises { if (!this.cancelled) { this.routeStatementError(err, this.callback, this.notify) } - this.queryHandler.end(this.notify, this.outputParams, () => { - this.queue.nextOp() - }, null, false) + this.queryHandler.end(this.notify, this.outputParams, null, null, false) this.close() } @@ -388,14 +390,35 @@ class Query extends BasePromises { }) } - // park a step to run on resume, if paused. true when parked. + // park a step to run on resume, if paused. true when parked - or, for a paused query + // that has been cancelled, when the query has ended instead. park (step) { if (!this.paused) return false + if (this.pausedCancelled) { + this.endPausedCancel() + return true + } logger.debugLazy(() => `paused, park next step for queryId ${this.queryId}`, this.context) this.parked = step return true } + // the native statement of this paused query has been cancelled. what is parked will + // not run, and nothing more is emitted but the end: a step still in flight ends the + // query when it returns. + cancelPaused () { + this.pausedCancelled = true + if (this.parked) this.endPausedCancel() + } + + endPausedCancel () { + this.parked = null + const cancelled = new Error('[msnodesql] Operation canceled') + cancelled.sqlstate = 'HY008' + cancelled.code = 0 + this.end([cancelled]) + } + dispatch () { if (!this.running) { logger.debugLazy(() => `dispatch called but not running for queryId ${this.queryId}`, this.context) @@ -488,14 +511,14 @@ class Query extends BasePromises { if (this.paused) return logger.debugLazy(() => `DriverRead.pause() called for queryId ${this.queryId}`, this.context) this.paused = true - this.queue.park(this.notify.getOperation()) + this.queue.park(this.operation) logger.debugLazy(() => `DriverRead.pause() parked operation for queryId ${this.queryId}`, this.context) } resume () { if (!this.paused) return logger.debugLazy(() => `DriverRead.resume() called for queryId ${this.queryId}`, this.context) - this.queue.resume(this.notify.getOperation()) + this.queue.resume(this.operation) this.paused = false // nothing parked: the read's step is still running, and carries on when it returns const step = this.parked diff --git a/test/contract/HANDOVER.md b/test/contract/HANDOVER.md index fd79b1cd..26e3324e 100644 --- a/test/contract/HANDOVER.md +++ b/test/contract/HANDOVER.md @@ -30,8 +30,59 @@ comes out while paused, except what a native call already in flight brings back. - Full mocha suite: 897 passing; the only failures were the three transcripts above, before they were updated. -Still open, not this change: `queue/bind-failure-then-two-on-start` is non-deterministic -(#481, overlapping follow-ups), and so is `cancel/paused-before-execute` (#479, `free` x2). +**Fixed: #481, the work queue.** Every item on the queue is now finished by its owner: +`WorkQueue.finish(op)` removes that item only (by identity), starts the next only if it was +the head, and does nothing the second time. The blind `nextOp()` is gone. +- Each query keeps its own queue item (`Query.operation`). A prepared statement shares one + notify across its executions, so `notify.getOperation()` is only the latest one queued. +- A statement's unbind and free are *follow-ups* (`enqueueFollowUp`). They run straight after + their query, before anything that was already waiting. Before, q2 (or `close()`) could run + ahead of q1's free. +- `close()` always finishes its item. The cancelled branch of `moveToNextResult` had cleared + `running` first, so `close()` returned early. That is what the extra advance in `end()` + (93f1590f) was covering. +- `dropItem` matches by identity. It used to drop every item with the same priority. + +**Fixed: a paused query holds the connection.** Owner's rule: once paused, no other operation +runs on the connection. +- A paused query keeps its place at the head. Before, it moved to the back, and `park()` then + removed the item that was waiting behind it **without running it**. On 5.6.0 such a query was + never submitted and its callback never fired. +- A query submitted while another is paused waits behind it (`headPaused`, which freed the + paused query, is gone). +- Cancelling a paused query sends the native cancel, then ends the query as cancelled + (`Query.cancelPaused`): `error HY008` → `free`, the same as cancelling one that is not paused. + Before, it was freed silently. +- `close()` cancels a paused query at the head first, so the close cannot wait forever. + +Corpus: all 11 changed `queue/*` and `cancel/paused-*` transcripts re-recorded, now +deterministic. No more "Connection is busy"; `paused-before-execute` frees once. +`queue/ok-then-two-on-*` are agreed. The rest still show #479/#478 behaviour, so they stay +unreviewed. Tests changed to the new rules: `pause.test.js` (a new query waits; close and +cancel give HY008) and `querycancel.test.js` (HY008 on a paused cancel). + +## The contract (owner, 2026-10-17), to ship as v6 + +- `done`: no more results. Raised on **every** query, exactly once: errors, cancels and bind + failures included. +- `free`: the native statement has been released. It comes after `done`. +- Nothing after `done` but `free`; an in-flight error may be unavoidable. +- A paused query emits nothing until resumed, and holds the connection. + +`done` is not raised by any `errors/*` scenario today. On cancel it comes before the HY008. +Prepared executions never raise `free` (there is no free item for them). + +## Next + +1. A fake native connection (`test/common/fake-native.js`) that holds every callback until + the test releases it, and asserts the invariants (one native call in flight per + connection, nothing after `releaseStatement` or `free`, one `done` then `free`). Then + scripted tests and an interleaving explorer for queue and reader. +2. Cases to pin with it: pause then cancel a compound query with another queued; pause and + submit a fresh query without cancelling (it waits; is that what we want?); an error coming + back from a fetch in flight when the pause lands (today it is emitted while paused, but the + rows are held). +3. `done` on every path (#479, the errors), then #478. Open decision: a pause that lands while a native call is in flight still lets that call's events out, e.g. the next result set's `meta`. Should paused mean no events at all? diff --git a/test/contract/corpus/cancel/paused-before-execute.events.txt b/test/contract/corpus/cancel/paused-before-execute.events.txt index 11008ef4..4a074ba7 100644 --- a/test/contract/corpus/cancel/paused-before-execute.events.txt +++ b/test/contract/corpus/cancel/paused-before-execute.events.txt @@ -2,22 +2,11 @@ # status: unreviewed # sql: waitfor delay '00:00:01'; select 2 as n # at: {"start":["pause","cancel"]} -# NOT DETERMINISTIC: 2 different transcripts in 3 runs action pause action cancel submitted done cancel-cb ok error HY008 0 Operation canceled more=false -free x2 -check ok ---- or -action pause -action cancel -submitted -done -cancel-cb ok -free -error HY008 0 Operation canceled more=false free check ok diff --git a/test/contract/corpus/cancel/paused-streaming-at-100.events.txt b/test/contract/corpus/cancel/paused-streaming-at-100.events.txt index 7dee6f90..c556d70f 100644 --- a/test/contract/corpus/cancel/paused-streaming-at-100.events.txt +++ b/test/contract/corpus/cancel/paused-streaming-at-100.events.txt @@ -9,5 +9,6 @@ action pause action cancel done cancel-cb ok +error HY008 0 Operation canceled more=false free check ok diff --git a/test/contract/corpus/queue/bind-failure-then-two-on-free.callback.txt b/test/contract/corpus/queue/bind-failure-then-two-on-free.callback.txt index a2818f39..c9a4bc58 100644 --- a/test/contract/corpus/queue/bind-failure-then-two-on-free.callback.txt +++ b/test/contract/corpus/queue/bind-failure-then-two-on-free.callback.txt @@ -11,12 +11,12 @@ cb error - - IMNOD: [msnodesql] Parameter 1: Invalid number parameter more=false q2: submitted q2: meta n q2: row -q3: submitted -q3: meta n -q3: row q2: cb ok rows=1 more=false q2: done q2: free +q3: submitted +q3: meta n +q3: row q3: cb ok rows=1 more=false q3: done q3: free diff --git a/test/contract/corpus/queue/bind-failure-then-two-on-start.callback.txt b/test/contract/corpus/queue/bind-failure-then-two-on-start.callback.txt index 9215e611..a4ffa31e 100644 --- a/test/contract/corpus/queue/bind-failure-then-two-on-start.callback.txt +++ b/test/contract/corpus/queue/bind-failure-then-two-on-start.callback.txt @@ -4,31 +4,18 @@ # params: ["Infinity"] # follow-up q2 on start: waitfor delay '00:00:01'; select 2 as n # follow-up q3 on start: select 3 as n -# NOT DETERMINISTIC: 2 different transcripts in 3 runs submitted done free q2: submitted -q3: submitted cb error - - IMNOD: [msnodesql] Parameter 1: Invalid number parameter more=false -q3: free -q3: cb error HY000 0 Connection is busy with results for another command more=false q2: meta n q2: row q2: cb ok rows=1 more=false q2: done q2: free -check ok ---- or -submitted -done -free -q2: submitted q3: submitted -cb error - - IMNOD: [msnodesql] Parameter 1: Invalid number parameter more=false q3: meta n -q2: free -q2: cb error HY000 0 Connection is busy with results for another command more=false q3: row q3: cb ok rows=1 more=false q3: done diff --git a/test/contract/corpus/queue/error-after-result-then-two-on-free.callback.txt b/test/contract/corpus/queue/error-after-result-then-two-on-free.callback.txt index da116207..fffc5680 100644 --- a/test/contract/corpus/queue/error-after-result-then-two-on-free.callback.txt +++ b/test/contract/corpus/queue/error-after-result-then-two-on-free.callback.txt @@ -9,12 +9,15 @@ row cb error 42000 50000 boom more=false free q2: submitted -q3: submitted -q3: free -q3: cb error HY000 0 Connection is busy with results for another command more=false q2: meta n q2: row q2: cb ok rows=1 more=false q2: done q2: free +q3: submitted +q3: meta n +q3: row +q3: cb ok rows=1 more=false +q3: done +q3: free check ok diff --git a/test/contract/corpus/queue/error-after-result-then-two-on-start.callback.txt b/test/contract/corpus/queue/error-after-result-then-two-on-start.callback.txt index b8625d01..80fb0b10 100644 --- a/test/contract/corpus/queue/error-after-result-then-two-on-start.callback.txt +++ b/test/contract/corpus/queue/error-after-result-then-two-on-start.callback.txt @@ -7,16 +7,16 @@ submitted meta n row cb error 42000 50000 boom more=false +free q2: submitted q2: meta n q2: row -q3: submitted -q3: meta n -q3: row -free q2: cb ok rows=1 more=false q2: done q2: free +q3: submitted +q3: meta n +q3: row q3: cb ok rows=1 more=false q3: done q3: free diff --git a/test/contract/corpus/queue/error-at-execute-then-cancel-follow-up.callback.txt b/test/contract/corpus/queue/error-at-execute-then-cancel-follow-up.callback.txt index 5fba6be5..265cc569 100644 --- a/test/contract/corpus/queue/error-at-execute-then-cancel-follow-up.callback.txt +++ b/test/contract/corpus/queue/error-at-execute-then-cancel-follow-up.callback.txt @@ -8,10 +8,7 @@ cb error 42000 50000 boom more=false q2: submitted q2: action cancel q2: done -q2: cancel-cb error Error: [msnodesql] cannot cancel query (empty queue) id 1 -q2: meta n -q2: row -q2: cb ok rows=1 more=false -q2: done +q2: cancel-cb ok q2: free +q2: cb error HY008 0 Operation canceled more=false check ok diff --git a/test/contract/corpus/queue/error-at-execute-then-two-on-free.callback.txt b/test/contract/corpus/queue/error-at-execute-then-two-on-free.callback.txt index 01596b1f..4aa0485a 100644 --- a/test/contract/corpus/queue/error-at-execute-then-two-on-free.callback.txt +++ b/test/contract/corpus/queue/error-at-execute-then-two-on-free.callback.txt @@ -7,12 +7,15 @@ submitted free cb error 42000 50000 boom more=false q2: submitted -q3: submitted -q3: free -q3: cb error HY000 0 Connection is busy with results for another command more=false q2: meta n q2: row q2: cb ok rows=1 more=false q2: done q2: free +q3: submitted +q3: meta n +q3: row +q3: cb ok rows=1 more=false +q3: done +q3: free check ok diff --git a/test/contract/corpus/queue/error-at-execute-then-two-on-start.callback.txt b/test/contract/corpus/queue/error-at-execute-then-two-on-start.callback.txt index 4389887d..0be8a29c 100644 --- a/test/contract/corpus/queue/error-at-execute-then-two-on-start.callback.txt +++ b/test/contract/corpus/queue/error-at-execute-then-two-on-start.callback.txt @@ -4,17 +4,17 @@ # follow-up q2 on start: waitfor delay '00:00:01'; select 2 as n # follow-up q3 on start: select 3 as n submitted +free +cb error 42000 50000 boom more=false q2: submitted q2: meta n q2: row -q3: submitted -q3: meta n -q3: row -free -cb error 42000 50000 boom more=false q2: cb ok rows=1 more=false q2: done q2: free +q3: submitted +q3: meta n +q3: row q3: cb ok rows=1 more=false q3: done q3: free diff --git a/test/contract/corpus/queue/ok-then-two-on-free.callback.txt b/test/contract/corpus/queue/ok-then-two-on-free.callback.txt index b0f3a82d..6ee9cf85 100644 --- a/test/contract/corpus/queue/ok-then-two-on-free.callback.txt +++ b/test/contract/corpus/queue/ok-then-two-on-free.callback.txt @@ -1,5 +1,5 @@ # scenario: queue/ok-then-two-on-free.callback -# status: unreviewed +# status: agreed # sql: select ? as v # params: [1] # follow-up q2 on free: waitfor delay '00:00:01'; select 2 as n @@ -13,12 +13,12 @@ free q2: submitted q2: meta n q2: row -q3: submitted -q3: meta n -q3: row q2: cb ok rows=1 more=false q2: done q2: free +q3: submitted +q3: meta n +q3: row q3: cb ok rows=1 more=false q3: done q3: free diff --git a/test/contract/corpus/queue/ok-then-two-on-start.callback.txt b/test/contract/corpus/queue/ok-then-two-on-start.callback.txt index ed99f6cb..ab24611f 100644 --- a/test/contract/corpus/queue/ok-then-two-on-start.callback.txt +++ b/test/contract/corpus/queue/ok-then-two-on-start.callback.txt @@ -1,5 +1,5 @@ # scenario: queue/ok-then-two-on-start.callback -# status: unreviewed +# status: agreed # sql: select ? as v # params: [1] # follow-up q2 on start: waitfor delay '00:00:01'; select 2 as n @@ -7,18 +7,18 @@ submitted meta v row -q2: submitted -q2: meta n -q2: row -q3: submitted -q3: meta n -q3: row cb ok rows=1 more=false done free +q2: submitted +q2: meta n +q2: row q2: cb ok rows=1 more=false q2: done q2: free +q3: submitted +q3: meta n +q3: row q3: cb ok rows=1 more=false q3: done q3: free diff --git a/test/pause.test.js b/test/pause.test.js index 8116e5e3..a60f9149 100755 --- a/test/pause.test.js +++ b/test/pause.test.js @@ -77,7 +77,8 @@ describe('pause', function () { query: q, getRowCount: () => rows, onRow: options.onRow || (() => {}), - onError: options.onError || ((e) => { assert.ifError(e) }), + // a query a test leaves paused is cancelled when the connection closes (HY008) + onError: options.onError || ((e) => { if (e?.sqlstate !== 'HY008') assert.ifError(e) }), onDone: options.onDone || (() => {}) } @@ -93,15 +94,24 @@ describe('pause', function () { describe('basic pause/resume functionality', () => { it('should pause a large query and cancel without resume', function (done) { + // a paused query ends on cancel as any other: no more rows, an HY008 error, then free + let cancelErr const queryHelper = createRowCountingQuery(env.theConnection, QUERIES.large, { onRow: (rowCount) => { + assert(!cancelErr, 'no rows after a cancel') if (rowCount % PAUSE_INTERVAL === 0) { queryHelper.query.pauseQuery() setTimeout(() => { - queryHelper.query.cancelQuery(done) + queryHelper.query.cancelQuery(e => { assert.ifError(e) }) }, RESUME_DELAY) } - } + }, + onError: e => { cancelErr = e } + }) + queryHelper.query.on('free', () => { + assert(cancelErr, 'expected an error on cancel') + assert.strictEqual(cancelErr.sqlstate, 'HY008') + done() }) }) @@ -136,7 +146,11 @@ describe('pause', function () { setTimeout(() => { assert.strictEqual(rowCount, 0, 'Should not receive any rows when starting paused') - done() + q.on('free', () => { + assert(rowCount > 0, 'rows once resumed') + done() + }) + q.resumeQuery() }, PAUSE_CHECK_DELAY) }) @@ -195,25 +209,30 @@ describe('pause', function () { }) describe('query interaction', () => { - it('should kill paused query when new query is submitted', function (done) { + it('should hold the connection while paused - a new query waits', function (done) { const pauseAt = 10 + let resumed = false + let firstFree = false const queryHelper = createRowCountingQuery(env.theConnection, QUERIES.large, { onRow: (rowCount) => { if (rowCount === pauseAt) { queryHelper.query.pauseQuery() + const q2 = env.theConnection.query(QUERIES.large, (err, res) => { + assert.ifError(err) + assert(firstFree, 'the paused query finishes first') + assert(res.length > 0) + done() + }) + q2.on('submitted', () => assert(resumed, 'not submitted while the first is paused')) setTimeout(() => { assert.strictEqual(queryHelper.getRowCount(), pauseAt) - // New query should kill the paused one - env.theConnection.query(QUERIES.large, (err, res) => { - assert.ifError(err) - assert(Array.isArray(res)) - assert(res.length > 0) - done() - }) + resumed = true + queryHelper.query.resumeQuery() }, PAUSE_CHECK_DELAY) } } }) + queryHelper.query.on('free', () => { firstFree = true }) }) it('should allow new query after cancel', function (done) { @@ -278,14 +297,20 @@ describe('pause', function () { q.pauseQuery() let rowCount = 0 + let cancelErr + let freed = false q.on('row', () => rowCount++) - q.on('error', (e) => { assert.ifError(e) }) + q.on('error', (e) => { cancelErr = e }) + q.on('free', () => { freed = true }) - // Wait a bit to ensure no rows are received, then close + // Wait a bit to ensure no rows are received, then close: the close cancels the + // paused query, which ends and frees its statement before the connection closes setTimeout(() => { assert.strictEqual(rowCount, 0, 'Should not receive rows while paused') newConn.close((err) => { assert.ifError(err) + assert.strictEqual(cancelErr?.sqlstate, 'HY008') + assert(freed, 'the paused query is freed before the close completes') done() }) }, PAUSE_CHECK_DELAY * 5) // Longer wait for this test diff --git a/test/querycancel.test.js b/test/querycancel.test.js index e4795369..4a6c0615 100755 --- a/test/querycancel.test.js +++ b/test/querycancel.test.js @@ -319,8 +319,9 @@ it('cancel a call to proc that waits for delay of input param.', testDone => { it('pause a large query and cancel check done', testDone => { let rows = 0 const q = env.theConnection.query('select top 3000 * from syscolumns') + // a paused query ends on cancel as any other: HY008 q.on('error', (e) => { - assert.ifError(e) + if (e.sqlstate !== 'HY008') assert.ifError(e) }) q.on('row', () => { ++rows From 055711b1f8841e057a5b1846e206d1c00835b9f5 Mon Sep 17 00:00:00 2001 From: TimelordUK Date: Sat, 17 Oct 2026 13:11:56 +0100 Subject: [PATCH 4/4] feat!: refuse new work on a connection while a query is paused A paused query holds the connection. Rather than queue new work behind it indefinitely, a query submitted while another is paused is refused at once: its callback (or 'error') gets an error with sqlstate HY010 (function sequence error), then 'done' and 'free', and no 'submitted'. beginTransaction, commit, rollback and prepare get the error in their callback. Work queued before the pause still waits its turn. Once a cancel of a paused query is accepted, the query no longer holds the connection, so work submitted from the cancel callback queues behind it. Corpus: queue/paused-then-{submit,cancel-queued-before,resume-queued-before}; the submit and resume cases are agreed. The Linux CI runs showed 4 error scenarios that differ from Windows: a batch whose first statement fails at execute loses the rest of the batch on Linux (more=false, no done). The base commit does the same, so it is older than this branch (5.6.0's #475 look-ahead). Pinned as .linux.txt transcripts with status known-bug, captured on WSL Fedora, and described in HANDOVER.md. Co-Authored-By: Claude Opus 5.5 (1M context) --- lib/driver.js | 55 ++++++++++++++++- test/contract/HANDOVER.md | 32 +++++++--- .../errors/dup-key-d.callback.linux.txt | 9 +++ .../corpus/errors/dup-key-d.events.linux.txt | 9 +++ .../raiserror-then-result.callback.linux.txt | 7 +++ .../raiserror-then-result.events.linux.txt | 7 +++ ...aused-then-cancel-queued-before.events.txt | 21 +++++++ ...aused-then-resume-queued-before.events.txt | 22 +++++++ .../queue/paused-then-submit.callback.txt | 18 ++++++ test/contract/scenarios.js | 25 +++++++- test/pause.test.js | 61 ++++++++++++++++--- 11 files changed, 248 insertions(+), 18 deletions(-) create mode 100644 test/contract/corpus/errors/dup-key-d.callback.linux.txt create mode 100644 test/contract/corpus/errors/dup-key-d.events.linux.txt create mode 100644 test/contract/corpus/errors/raiserror-then-result.callback.linux.txt create mode 100644 test/contract/corpus/errors/raiserror-then-result.events.linux.txt create mode 100644 test/contract/corpus/queue/paused-then-cancel-queued-before.events.txt create mode 100644 test/contract/corpus/queue/paused-then-resume-queued-before.events.txt create mode 100644 test/contract/corpus/queue/paused-then-submit.callback.txt diff --git a/lib/driver.js b/lib/driver.js index ff250463..1570c90d 100755 --- a/lib/driver.js +++ b/lib/driver.js @@ -111,6 +111,9 @@ const driverModule = ((() => { // statement as any other query does. logger.debugLazy(() => `cancel paused query id ${qid}`, 'DriverMgr.drop') this.execCancel(notify, first, (e) => { + // once cancelled the query is ending, and no longer holds the connection: work + // submitted from the cancel callback queues behind it + if (!e) this.workQueue.resume(first) callback(e) if (!e && notify.queryWorker) notify.queryWorker.cancelPaused() }) @@ -243,25 +246,75 @@ const driverModule = ((() => { } // the native calls below always complete asynchronously, so op is assigned by then + // a paused query holds the connection: new work is refused until it is resumed and + // finished, or cancelled. work queued before the pause still waits its turn. + pausedQuery () { + const head = this.workQueue.peek() + return head?.paused && head.commandType === driverCommandEnum.QUERY ? head : null + } + + pausedError (head) { + const qid = head.args[0].getQueryId() + const err = new Error(`[msnodesql] query ${qid} on this connection is paused - resume or cancel it before submitting more work`) + err.sqlstate = 'HY010' // function sequence error + err.code = 0 + return err + } + + // true when refused: callback gets the error + refuseWhilePaused (callback) { + const head = this.pausedQuery() + if (!head) return false + const err = this.pausedError(head) + setImmediate(() => callback(err)) + return true + } + + // a refused query ends as any failed query does: the error, then done and free. + // it was never submitted, so there is no 'submitted'. + refuseQueryWhilePaused (notify, cb) { + const head = this.pausedQuery() + if (!head) return false + const err = this.pausedError(head) + logger.debugLazy(() => `refuse query ${notify.getQueryId()}: ${err.message}`, 'DriverMgr.refuseQueryWhilePaused') + setImmediate(() => { + if (cb) { + cb(err, null, false) + } else if (notify.listenerCount('error') > 0) { + notify.emit('error', err, false) + } + // a tick on: the connection defers the user's callback by one + setImmediate(() => { + notify.emit('done', notify.getQueryId()) + notify.emit('free', notify.getQueryId()) + }) + }) + return true + } + beginTransaction (callback) { + if (this.refuseWhilePaused(callback)) return const op = this.workQueue.enqueue(driverCommandEnum.BEGIN_TRANSACTION, () => { this.cppDriver.beginTransaction(err => { this.next(callback, err, op) }) }, []) } rollback (callback) { + if (this.refuseWhilePaused(callback)) return const op = this.workQueue.enqueue(driverCommandEnum.ROLLBACK, () => { this.cppDriver.rollback(err => { this.next(callback, err, op) }) }, []) } commit (callback) { + if (this.refuseWhilePaused(callback)) return const op = this.workQueue.enqueue(driverCommandEnum.COMMIT, () => { this.cppDriver.commit(err => { this.next(callback, err, op) }) }, []) } prepare (notify, queryOrObj, callback) { + if (this.refuseWhilePaused(callback)) return const op = this.workQueue.enqueue(driverCommandEnum.PREPARE, () => { this.cppDriver.prepare(notify.getQueryId(), queryOrObj, (err, meta) => { callback(err, meta) @@ -273,6 +326,7 @@ const driverModule = ((() => { // the query keeps its own queue item: a prepared statement shares one notify across // its executions, so the notify's operation is only ever the latest one queued readOperation (notify, queryObj, params, factory, cb) { + if (this.refuseQueryWhilePaused(notify, cb)) return const op = this.workQueue.enqueue(driverCommandEnum.QUERY, (notify, query, params, callback) => { setImmediate(() => { @@ -299,7 +353,6 @@ const driverModule = ((() => { () => new NativeQueryHandler(this.cppDriver, this), cb) } - // a paused query holds the connection: a new query waits behind it like any other readAllQuery (notify, queryObj, params, cb) { this.read(notify, queryObj, params, cb) } diff --git a/test/contract/HANDOVER.md b/test/contract/HANDOVER.md index 26e3324e..1e13b2b0 100644 --- a/test/contract/HANDOVER.md +++ b/test/contract/HANDOVER.md @@ -48,11 +48,15 @@ runs on the connection. - A paused query keeps its place at the head. Before, it moved to the back, and `park()` then removed the item that was waiting behind it **without running it**. On 5.6.0 such a query was never submitted and its callback never fired. -- A query submitted while another is paused waits behind it (`headPaused`, which freed the - paused query, is gone). +- Work submitted while a query is paused is **refused** (owner's decision): a query gets an + error with sqlstate `HY010` (function sequence error), then `done` and `free`, and no + `submitted`. `beginTransaction`, `commit`, `rollback` and `prepare` get the error in their + callback. Work queued *before* the pause waits its turn. (`headPaused`, which freed the paused + query when a new one came, is gone.) Corpus: `queue/paused-then-*`. - Cancelling a paused query sends the native cancel, then ends the query as cancelled (`Query.cancelPaused`): `error HY008` → `free`, the same as cancelling one that is not paused. - Before, it was freed silently. + Before, it was freed silently. Once the cancel is accepted the query no longer holds the + connection, so work submitted from the cancel callback queues behind it. - `close()` cancels a paused query at the head first, so the close cannot wait forever. Corpus: all 11 changed `queue/*` and `cancel/paused-*` transcripts re-recorded, now @@ -72,16 +76,30 @@ cancel give HY008) and `querycancel.test.js` (HY008 on a paused cancel). `done` is not raised by any `errors/*` scenario today. On cancel it comes before the HY008. Prepared executions never raise `free` (there is no free item for them). +## Linux: results after an error at execute are lost (5.6.0, not this branch) + +On Linux (msodbcsql18, CI's Ubuntu and WSL Fedora), when the first statement of a batch fails +at execute, the error comes with `more=false` and the rest of the batch is lost: no +`rowcount`, no following result set, no `done`. Windows gives `more=true`, then the rest. So +the #475 fix in 5.6.0 (`odbc_statement_legacy.cpp`, the look-ahead after a failed execute) +does not hold on Linux. The same 4 scenarios differ with the base commit's `lib/`, so it is +older than the queue work. Pinned as `errors/{raiserror-then-result,dup-key-d}.*.linux.txt`, +`# status: known-bug`, so that CI is green and the fix shows up as a diff. + +To run the corpus on WSL: a `git worktree` under `/tmp//node_modules/msnodesqlv8` (the +tests `require('msnodesqlv8')`), `npx node-gyp rebuild`, copy `.env-cmdrc`, symlink +`node_modules` from an existing checkout. + ## Next 1. A fake native connection (`test/common/fake-native.js`) that holds every callback until the test releases it, and asserts the invariants (one native call in flight per connection, nothing after `releaseStatement` or `free`, one `done` then `free`). Then scripted tests and an interleaving explorer for queue and reader. -2. Cases to pin with it: pause then cancel a compound query with another queued; pause and - submit a fresh query without cancelling (it waits; is that what we want?); an error coming - back from a fetch in flight when the pause lands (today it is emitted while paused, but the - rows are held). +2. Cases to pin with it: an error coming back from a fetch in flight when the pause lands + (today it is emitted while paused, but the rows are held). Already in the corpus against a + real server: pause then cancel a compound query with another queued + (`queue/paused-then-cancel-queued-before`), and submit while paused (`queue/paused-then-submit`). 3. `done` on every path (#479, the errors), then #478. Open decision: a pause that lands while a native call is in flight still lets that call's diff --git a/test/contract/corpus/errors/dup-key-d.callback.linux.txt b/test/contract/corpus/errors/dup-key-d.callback.linux.txt new file mode 100644 index 00000000..767e7b2d --- /dev/null +++ b/test/contract/corpus/errors/dup-key-d.callback.linux.txt @@ -0,0 +1,9 @@ +# scenario: errors/dup-key-d.callback +# status: known-bug +# setup: create table #t (id int constraint pk_t primary key); insert #t values (1) +# sql: insert #t values (1); select 2 as m +submitted +info 01000 3621 The statement has been terminated. +free +cb error 23000 2627 Violation of PRIMARY KEY constraint 'pk_t'. Cannot insert duplicate key in object 'dbo.#t'. The duplicate key value is (1). more=false +check ok diff --git a/test/contract/corpus/errors/dup-key-d.events.linux.txt b/test/contract/corpus/errors/dup-key-d.events.linux.txt new file mode 100644 index 00000000..21c63331 --- /dev/null +++ b/test/contract/corpus/errors/dup-key-d.events.linux.txt @@ -0,0 +1,9 @@ +# scenario: errors/dup-key-d.events +# status: known-bug +# setup: create table #t (id int constraint pk_t primary key); insert #t values (1) +# sql: insert #t values (1); select 2 as m +submitted +info 01000 3621 The statement has been terminated. +error 23000 2627 Violation of PRIMARY KEY constraint 'pk_t'. Cannot insert duplicate key in object 'dbo.#t'. The duplicate key value is (1). more=false +free +check ok diff --git a/test/contract/corpus/errors/raiserror-then-result.callback.linux.txt b/test/contract/corpus/errors/raiserror-then-result.callback.linux.txt new file mode 100644 index 00000000..b660c7b4 --- /dev/null +++ b/test/contract/corpus/errors/raiserror-then-result.callback.linux.txt @@ -0,0 +1,7 @@ +# scenario: errors/raiserror-then-result.callback +# status: known-bug +# sql: raiserror('boom', 16, 1); select 2 as m +submitted +free +cb error 42000 50000 boom more=false +check ok diff --git a/test/contract/corpus/errors/raiserror-then-result.events.linux.txt b/test/contract/corpus/errors/raiserror-then-result.events.linux.txt new file mode 100644 index 00000000..9e3a186e --- /dev/null +++ b/test/contract/corpus/errors/raiserror-then-result.events.linux.txt @@ -0,0 +1,7 @@ +# scenario: errors/raiserror-then-result.events +# status: known-bug +# sql: raiserror('boom', 16, 1); select 2 as m +submitted +error 42000 50000 boom more=false +free +check ok diff --git a/test/contract/corpus/queue/paused-then-cancel-queued-before.events.txt b/test/contract/corpus/queue/paused-then-cancel-queued-before.events.txt new file mode 100644 index 00000000..f2328499 --- /dev/null +++ b/test/contract/corpus/queue/paused-then-cancel-queued-before.events.txt @@ -0,0 +1,21 @@ +# scenario: queue/paused-then-cancel-queued-before.events +# status: unreviewed +# sql: select top 51 object_id as a from sys.all_objects; select top 51 object_id as b from sys.all_objects +# at: {"row":{"3":["pause"]},"later":{"300":["cancel"]}} +# follow-up q2 on start: select 2 as n +submitted +meta a +row x3 +action pause +action cancel +done +cancel-cb ok +error HY008 0 Operation canceled more=false +free +q2: submitted +q2: meta n +q2: row +q2: cb ok rows=1 more=false +q2: done +q2: free +check ok diff --git a/test/contract/corpus/queue/paused-then-resume-queued-before.events.txt b/test/contract/corpus/queue/paused-then-resume-queued-before.events.txt new file mode 100644 index 00000000..823e3728 --- /dev/null +++ b/test/contract/corpus/queue/paused-then-resume-queued-before.events.txt @@ -0,0 +1,22 @@ +# scenario: queue/paused-then-resume-queued-before.events +# status: agreed +# sql: select top 51 object_id as a from sys.all_objects; select top 51 object_id as b from sys.all_objects +# at: {"row":{"3":["pause","resume:100"]}} +# follow-up q2 on start: select 2 as n +submitted +meta a +row x3 +action pause +action resume +row x48 +meta b +row x51 +done +free +q2: submitted +q2: meta n +q2: row +q2: cb ok rows=1 more=false +q2: done +q2: free +check ok diff --git a/test/contract/corpus/queue/paused-then-submit.callback.txt b/test/contract/corpus/queue/paused-then-submit.callback.txt new file mode 100644 index 00000000..558d5178 --- /dev/null +++ b/test/contract/corpus/queue/paused-then-submit.callback.txt @@ -0,0 +1,18 @@ +# scenario: queue/paused-then-submit.callback +# status: agreed +# sql: select top 20 object_id as a from sys.all_objects +# at: {"row":{"10":["pause","queue:paused","resume:100"]}} +# follow-up q2 on paused: select 2 as n +submitted +meta a +row x10 +action pause +q2: cb error HY010 0 query 0 on this connection is paused - resume or cancel it before submitting more work more=false +q2: done +q2: free +action resume +row x10 +cb ok rows=20 more=false +done +free +check ok diff --git a/test/contract/scenarios.js b/test/contract/scenarios.js index dbccc8cc..08db513f 100644 --- a/test/contract/scenarios.js +++ b/test/contract/scenarios.js @@ -104,7 +104,30 @@ const base = [ sql, followUps: [{ label: 'q2', sql: SLOW, when: 'free', callback: true, at: { later: { 300: ['cancel'] } } }], modes: ['callback'] - })) + })), + // a paused query holds the connection: work submitted while it is paused is refused + // (HY010), work queued before the pause waits its turn - after a resume or a cancel + { + name: 'queue/paused-then-submit', + sql: 'select top 20 object_id as a from sys.all_objects', + at: { row: { 10: ['pause', 'queue:paused', 'resume:100'] } }, + followUps: [{ label: 'q2', sql: 'select 2 as n', when: 'paused', callback: true }], + modes: ['callback'] + }, + { + name: 'queue/paused-then-cancel-queued-before', + sql: TWO_51, + at: { row: { 3: ['pause'] }, later: { 300: ['cancel'] } }, + followUps: [{ label: 'q2', sql: 'select 2 as n', when: 'start', callback: true }], + modes: ['events'] + }, + { + name: 'queue/paused-then-resume-queued-before', + sql: TWO_51, + at: { row: { 3: ['pause', 'resume:100'] } }, + followUps: [{ label: 'q2', sql: 'select 2 as n', when: 'start', callback: true }], + modes: ['events'] + } ] function expand (s) { diff --git a/test/pause.test.js b/test/pause.test.js index a60f9149..0b409852 100755 --- a/test/pause.test.js +++ b/test/pause.test.js @@ -209,7 +209,37 @@ describe('pause', function () { }) describe('query interaction', () => { - it('should hold the connection while paused - a new query waits', function (done) { + it('should refuse a new query while paused - HY010, done, free', function (done) { + const pauseAt = 10 + const queryHelper = createRowCountingQuery(env.theConnection, QUERIES.large, { + onRow: (rowCount) => { + if (rowCount !== pauseAt) return + queryHelper.query.pauseQuery() + const events = [] + const q2 = env.theConnection.query(QUERIES.large, (err, res) => { + events.push('cb') + assert(err, 'refused while the first query is paused') + assert.strictEqual(err.sqlstate, 'HY010') + assert.strictEqual(res, null) + }) + q2.on('submitted', () => events.push('submitted')) + q2.on('done', () => events.push('done')) + q2.on('free', () => { + events.push('free') + assert.deepStrictEqual(events, ['cb', 'done', 'free']) + assert.strictEqual(queryHelper.getRowCount(), pauseAt) + // the paused query is untouched: resume it and it completes + queryHelper.query.resumeQuery() + }) + }, + onDone: rowCount => { + assert(rowCount > pauseAt) + done() + } + }) + }) + + it('should run a query queued before the pause once the paused one completes', function (done) { const pauseAt = 10 let resumed = false let firstFree = false @@ -217,15 +247,7 @@ describe('pause', function () { onRow: (rowCount) => { if (rowCount === pauseAt) { queryHelper.query.pauseQuery() - const q2 = env.theConnection.query(QUERIES.large, (err, res) => { - assert.ifError(err) - assert(firstFree, 'the paused query finishes first') - assert(res.length > 0) - done() - }) - q2.on('submitted', () => assert(resumed, 'not submitted while the first is paused')) setTimeout(() => { - assert.strictEqual(queryHelper.getRowCount(), pauseAt) resumed = true queryHelper.query.resumeQuery() }, PAUSE_CHECK_DELAY) @@ -233,6 +255,27 @@ describe('pause', function () { } }) queryHelper.query.on('free', () => { firstFree = true }) + // queued while the first query runs, before it is paused: waits its turn + const q2 = env.theConnection.query(QUERIES.large, (err, res) => { + assert.ifError(err) + assert(firstFree, 'the paused query finishes first') + assert(res.length > 0) + done() + }) + q2.on('submitted', () => assert(resumed, 'not submitted while the first is paused')) + }) + + it('should refuse a transaction while a query is paused', function (done) { + const q = env.theConnection.query(QUERIES.large) + q.pauseQuery() + setTimeout(() => { + env.theConnection.beginTransaction(err => { + assert(err) + assert.strictEqual(err.sqlstate, 'HY010') + q.on('done', () => done()) + q.resumeQuery() + }) + }, PAUSE_CHECK_DELAY) }) it('should allow new query after cancel', function (done) {