diff --git a/cpp/src/odbc/odbc_statement_legacy.cpp b/cpp/src/odbc/odbc_statement_legacy.cpp index 7ddd41af..071be572 100644 --- a/cpp/src/odbc/odbc_statement_legacy.cpp +++ b/cpp/src/odbc/odbc_statement_legacy.cpp @@ -1042,6 +1042,13 @@ bool OdbcStatementLegacy::bind_fetch(const shared_ptr& param_set) if (!_statement) return false; const auto& statement = *_statement; + // each execution starts clean: the errors of the last one are not this one's, and a + // cursor it left open (it failed part way through its rows, say) is closed - else this + // execute fails with 24000 invalid cursor state. with no cursor open, SQLCloseCursor + // fails harmlessly (24000), and SQLExecute clears its diagnostics. + _errors->clear(); + _errorHandler->ClearErrors(); + _odbcApi->SQLCloseCursor(statement.get_handle()); const bool polling_mode = get_polling(); const auto bound = bind_params(param_set); if (!bound) { diff --git a/lib/prepared-statement.js b/lib/prepared-statement.js index 48a1f3be..9e7c024b 100755 --- a/lib/prepared-statement.js +++ b/lib/prepared-statement.js @@ -46,13 +46,31 @@ class PreparedStatement { return this.notify.getQueryId() } + // once freed, the native statement is gone: every use is refused, with no native call + freedError () { + const err = new Error(`[msnodesql] prepared statement ${this.getId()} has been freed`) + err.sqlstate = 'HY010' // function sequence error + err.code = 0 + return err + } + + // each execution is submitted ... done. there is no free per execution: 'free' is raised + // once, by free(), when the native statement is released. preparedQuery (paramsOrCallback, callback) { + const chunky = this.notifier.getChunkyArgs(paramsOrCallback, callback) if (!this.active) { - if (callback) { - callback(new Error('error; prepared statement has been Debugd.')) - } + // refused as a query is: its error, then done. never submitted, and nothing to free + const err = this.freedError() + setImmediate(() => { + if (chunky.callback) { + chunky.callback(err, null, false) + } else if (this.notify.listenerCount('error') > 0) { + this.notify.emit('error', err, false) + } + setImmediate(() => this.notify.emit('done', this.getId())) + }) + return this.notify } - const chunky = this.notifier.getChunkyArgs(paramsOrCallback, callback) const onPreparedQuery = (err, results, more) => { this.errors = err @@ -77,9 +95,17 @@ class PreparedStatement { return this.notify } + // releases the native statement, then raises 'free'. inactive at once, so an execution + // asked for after free() is refused even before the release has happened. a second free + // is refused in its callback. free (callback) { + if (!this.active) { + const err = this.freedError() + setImmediate(() => { if (callback) callback(err, null) }) + return + } + this.active = false this.driverMgr.freeStatement(this.notify, err => { - this.active = false if (callback) { callback(err, null) } diff --git a/test/contract/HANDOVER.md b/test/contract/HANDOVER.md index d9a55ed7..2491cd4f 100644 --- a/test/contract/HANDOVER.md +++ b/test/contract/HANDOVER.md @@ -1,8 +1,38 @@ -# Handover: 5.6.0 event regressions (#478 – #481) — 2026-10-15 +# Handover: the v6 event contract (from the 5.6.0 regressions, #478 – #481) -Where the investigation of dhensby's reports stands, and where to pick it up. +Started 2026-10-15 from dhensby's reports. Last updated 2026-10-18. The newest state is +first; the dated Progress sections below have the detail, and the older sections are history. -## Summary +## Where we are — end of 2026-10-18 + +**All four issues are fixed on master** (PRs #482, #484 – #491). #492, the prepared statement +lifecycle, was open at the end of the day. Nothing is released yet: it ships as **v6**. + +| Issue | State | +|---|---| +| #481 work queue after a failure | fixed, closed | +| #480 pause on the last row skipped a result set (and the pause crash) | fixed; closing comment posted | +| #479 `done` on cancel: early, doubled or missing | fixed; closing comment posted | +| #478 info before its error (3621 before 2627) | fixed (#491) | +| #483 Linux: rest of the batch lost after an error at execute | open, native, pinned `known-bug` | + +**Guarding against regressions**, all run on every PR into master: +- the corpus against a live server, on Windows and Linux; +- the replay of every native recording over the fake driver, on Windows, Linux and macOS; +- jittered replays of the timing-sensitive groups. + +The tools are `capture.js`, `replay.js`, `explore.js` and `npm run record-corpus`, and the +script helpers `t.watch` and `t.next` for prepared statements. Corpus status at the end of the day: +64 `agreed`, 6 `known-bug` (the Linux pins for #483) and 36 `unreviewed`. The unreviewed ones +are all of `read/`, `pause/two-by-51-*`, `errors/{bind-failure.events,raiserror-then-result.*, +two-raiserrors-then-result.*}` and `scripts/issue-480`. + +**Before releasing v6:** release notes on the GitHub release, listing every behaviour change in +the contract below. Workarounds for a missing or doubled `done` (node-mssql 12.7.8+) may +break. Then decide the node-mssql guard: an RC on `next` for dhensby, node-mssql-shaped +scenarios, or their suite as a canary job. + +## Summary at first handover (2026-10-15) 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 @@ -65,17 +95,25 @@ deterministic. No more "Connection is busy"; `paused-before-execute` frees once. 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. - -Since 2026-10-18 (see below) every query raises `done` once, after its error and callback, -and `free` waits for it. Prepared executions still never raise `free` (there is no free item -for them). +## The contract (owner, 2026-10-17 – 18), to ship as v6 + +- **`done`**: no more results. Raised on every query, exactly once, whatever happened: + success, error, bind failure, cancel, refusal. It comes after the query's errors and after + its callback. +- **`free`**: the native statement has been released. It always comes after `done`. Nothing + comes after `done` but `free`. +- **Pause:** a paused query emits nothing until it is resumed, including what a native call in + flight brings back. It holds the connection: new work is refused with HY010. Work queued + before the pause waits its turn. +- **Cancel:** an accepted cancel gives `cancel-cb ok` → `error HY008` → `done` → `free`. A + cancel that is not accepted (too late, refused by the driver, or a repeat: one cancel per + query) gives only an error in its own callback, a tick later. It is never thrown and never + touches the query's events. Every cancel's callback is called. +- **Diagnostics** are routed in driver order. `more` is counted over errors only. +- **Prepared statements:** each execution is `submitted` … `done`, with no `free`. `ps.free()` + raises `free` once, when the native statement is released. After that, an execution is + refused with HY010 (its error or callback, then `done`), and a second `free()` with an error + in its callback. ## Linux: results after an error at execute are lost (5.6.0, not this branch) @@ -160,13 +198,73 @@ Found while there, not fixed: info from some DDL is mostly lost, on master too. on master and 1 of 20 here, while PRINT info always comes. It is probably native: the diagnostics are not read when the driver returns plain `SQL_SUCCESS`. +## Progress — 2026-10-18: the prepared statement lifecycle + +The owner's rule: a prepared statement's executions are each `submitted` … `done`, with no +`free`. `free` is raised once, by `ps.free()`, when the native statement is released. After +that, any use of the statement is an error. Corpus: `scripts/prepared` (agreed), recorded +through the new `t.watch` and `t.next` script helpers. Executions share one query object and +raise no free, so `t.query` does not fit them. + +- Native (`bind_fetch`): each execution clears the last one's diagnostics and closes the + cursor it left open. After an execution failed part way (divide by zero), the next one + failed with 24000 invalid cursor state and then reported the old error again, and stale + errors were reported even after free. +- `PreparedStatement` (`lib/prepared-statement.js`): once `free()` is called, an execution is + refused with HY010, "prepared statement N has been freed". That is the error or callback, + then `done`, with no native call. Before, it ran natively on the released handle, with two + callbacks and a garbled message. A second `free()` is refused in its callback. Before, it + threw "Invalid statement handle" and the connection could not close. A `free()` asked for + while an execution runs waits for it: the execution's `done`, then `free`. + +Found, not fixed: a prepared select with no table behind it (`select 10 / ? as n`) is +described with no columns at prepare, so its executions return no rows (`rowcount 1`, no +`meta`). + ## Next -1. Info lost from DDL (above): pin it with a scenario, then look at the native diagnostics reads. -2. Hold an error *at execute* while paused. `free` now waits for `done`, which removes the - reason it was not held (below). -3. Prepared executions: `free` per execution, or document that only `free()` raises it. -4. #483 (Linux, native), on WSL. +### 1. Nothing the driver sends is dropped (the next session's theme) + +Any information the driver sends should reach the caller. Today some is silently lost: +- Info from some DDL is mostly lost, on master too: 1756 "Skipping FOREIGN KEY constraint … + for temporary table", from `create table #fk (id int constraint fk_x references + no_such_table(id))`, came 0 of 20 times on master. PRINT info always comes. It is probably + native: the diagnostics are not read when a call returns plain `SQL_SUCCESS`, or are read + only on some paths. Check every ODBC call that can carry diagnostics: `SQLExecDirect`, + `SQLExecute`, `SQLFetch`, `SQLMoreResults` (SQL_NO_DATA included), `SQLRowCount`, and the + cancel path. +- A prepared select with no table behind it (`select 10 / ? as n`) is described with no + columns at prepare, so its executions return no rows: `rowcount 1`, no `meta`. + +Plan: a new corpus group, `info/`, before any fix: +- PRINT in each position: first, between results, last, after an error, inside a proc; +- RAISERROR severity 0 – 10 (info) next to 11+ (error), and `with nowait`; +- DDL warnings (1756 and others), `set` warnings (ANSI_WARNINGS, arithmetic overflow at + warning level), a truncation warning (01004), and the 3621 that follows a failed statement; +- many messages in one batch, more than one packet, to check that none are lost or reordered; +- each of these through a stored procedure, a prepared statement and a polling query. + +Then agree the transcripts, watch them fail, and fix (mostly native). Record native logs so +that replay covers them. + +### 2. Smaller items + +- Hold an error *at execute* while paused. `free` now waits for `done`, which removes the + reason it was not held (see Settled, below). +- #483 (Linux, native) on WSL. When it is fixed, the `known-bug` Linux pins show as diffs: + `errors/{raiserror-then-result,dup-key-d}.*.linux.txt`, `scripts/issue-478.linux.txt`, + `cancel/after-error-mid-batch.events.linux.txt`. +- A race in accepted cancels: the cancel's own callback (`cancel-cb ok`) and the HY008 from the + fetch in flight are two native completions on different threads, so either can reach JS + first. CI showed it on `cancel/twice-streaming-at-100`, which now has an `--- or` + alternative (the first in the corpus). `cancel/again-after-confirm-at-100` failed once + locally, probably the same race, but its transcript was not kept. Other accepted cancels + of a statement in flight can show it too: add the alternative when one does. Or tighten the + contract: hold the HY008 in JS until the cancel callback has run, so that `cancel-cb ok` + always comes first. That is the owner's call. Note that `capture.js --update` rewrites a file + from what it saw, so it drops an alternative it did not see. +- The 36 `unreviewed` transcripts (listed under Where we are): read them against the + contract and agree them. `read/print-*` belong with the `info/` work above. Settled (2026-10-17): a paused query emits nothing until resumed, including what a native call that was in flight when the pause landed brings back: the `meta` after execute or after @@ -231,7 +329,7 @@ junctioned in as `node_modules/msnodesqlv8`: So their suite is worth adding to CI, but it would not reliably have caught these. The corpus is our guard. -## Suggested order +## Suggested order (2026-10-15; all done) 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 @@ -251,7 +349,7 @@ corpus is our guard. 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 +## Decisions made while reviewing the corpus (all settled; see The contract) - 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? @@ -263,9 +361,9 @@ watch them fail, then fix. ## 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 +git fetch && git checkout master +npx node-gyp rebuild # native changes are not in a prebuild until v6 ships +npx mocha test/contract/contract.test.js test/contract/replay.test.js # ~4 min 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 diff --git a/test/contract/corpus/cancel/twice-streaming-at-100.events.txt b/test/contract/corpus/cancel/twice-streaming-at-100.events.txt index 65436215..20722168 100644 --- a/test/contract/corpus/cancel/twice-streaming-at-100.events.txt +++ b/test/contract/corpus/cancel/twice-streaming-at-100.events.txt @@ -2,6 +2,8 @@ # status: agreed # sql: select top 5000 a.name from sys.all_objects a cross join sys.all_objects b # at: {"row":{"100":["cancel","cancel"]}} +# the cancel callback and the HY008 from the fetch in flight are two native completions, +# on different threads: either can come first (seen on CI, 2026-10-18) submitted meta name row x100 @@ -12,3 +14,14 @@ error HY008 0 Operation canceled more=false done free check ok +--- or +submitted +meta name +row x100 +action cancel x2 +cancel-cb error cannot cancel query (cancel already requested) id 0 +error HY008 0 Operation canceled more=false +cancel-cb ok +done +free +check ok diff --git a/test/contract/corpus/scripts/prepared.txt b/test/contract/corpus/scripts/prepared.txt new file mode 100644 index 00000000..5c271dd7 --- /dev/null +++ b/test/contract/corpus/scripts/prepared.txt @@ -0,0 +1,63 @@ +# scenario: scripts/prepared +# status: agreed +# script: test/contract/scripts/prepared.js +setup: submitted +setup: rowcount 3 +setup: cb ok rows=0 more=false +setup: done +setup: free +== A an execution +ps: submitted +ps: meta r +ps: row +ps: column 0 10 +ps: done +== B a second execution +ps: submitted +ps: meta r +ps: row +ps: column 0 5 +ps: done +== C an execution with a callback +ps: submitted +ps: meta r +ps: row +ps: column 0 10 +C: cb ok rows=1 more=false +ps: done +== D an execution that fails at execute (divide by zero) +ps: submitted +ps: meta r +ps: error 22012 8134 Divide by zero error encountered. more=false +ps: done +== E it still runs after a failure +ps: submitted +ps: meta r +ps: row +ps: column 0 5 +ps: done +== F free +ps: free-cb ok +ps: free +== G executions after free +G: cb error prepared statement 1 has been freed more=false +ps: done +ps: error HY010 0 prepared statement 1 has been freed more=false +ps: done +== H free again +ps: free-cb error prepared statement 1 has been freed +== J free asked for while an execution runs: the execution ends, then free +ps2: submitted +ps2: meta n +ps2: row x2 +ps2: done +ps2: free-cb ok +ps2: free +== I the connection still works +I: submitted +I: meta n +I: row +I: cb ok rows=1 more=false +I: done +I: free +check ok diff --git a/test/contract/native/scripts/prepared.win32.json b/test/contract/native/scripts/prepared.win32.json new file mode 100644 index 00000000..c9e659f7 --- /dev/null +++ b/test/contract/native/scripts/prepared.win32.json @@ -0,0 +1 @@ +{"scenario":"scripts/prepared","transcript":["setup: submitted","setup: rowcount 3","setup: cb ok rows=0 more=false","setup: done","setup: free","== A an execution","ps: submitted","ps: meta r","ps: row","ps: column 0 10","ps: done","== B a second execution","ps: submitted","ps: meta r","ps: row","ps: column 0 5","ps: done","== C an execution with a callback","ps: submitted","ps: meta r","ps: row","ps: column 0 10","C: cb ok rows=1 more=false","ps: done","== D an execution that fails at execute (divide by zero)","ps: submitted","ps: meta r","ps: error 22012 8134 Divide by zero error encountered. more=false","ps: done","== E it still runs after a failure","ps: submitted","ps: meta r","ps: row","ps: column 0 5","ps: done","== F free","ps: free-cb ok","ps: free","== G executions after free","G: cb error prepared statement 1 has been freed more=false","ps: done","ps: error HY010 0 prepared statement 1 has been freed more=false","ps: done","== H free again","ps: free-cb error prepared statement 1 has been freed","== J free asked for while an execution runs: the execution ends, then free","ps2: submitted","ps2: meta n","ps2: row x2","ps2: done","ps2: free-cb ok","ps2: free","== I the connection still works","I: submitted","I: meta n","I: row","I: cb ok rows=1 more=false","I: done","I: free","check ok"],"log":[{"ev":"call","id":0,"t":11.5,"name":"open","args":["",0]},{"ev":"return","of":0,"t":32.2,"result":[null,{"success":true}]},{"ev":"call","id":2,"t":33.7,"name":"query","args":[0,{"query_str":"create table #p (n int); insert #p values (1), (2), (0)","query_timeout":0,"query_polling":false,"query_tz_adjustment":0,"numeric_string":false,"bigint_as_native":false,"stateChangeCallback":{"$":"function"}},[]]},{"ev":"state","of":2,"t":33.9,"change":{"handle":{"connectionId":0,"statementId":0},"oldState":"STATEMENT_CREATED","newState":"STATEMENT_BINDING"}},{"ev":"state","of":2,"t":34.1,"change":{"handle":{"connectionId":0,"statementId":0},"oldState":"STATEMENT_BINDING","newState":"STATEMENT_SUBMITTED"}},{"ev":"state","of":2,"t":35.4,"change":{"handle":{"connectionId":0,"statementId":0},"oldState":"STATEMENT_SUBMITTED","newState":"STATEMENT_READING"}},{"ev":"return","of":2,"t":35.4,"result":[null,{"meta":[],"handle":{"connectionId":0,"statementId":0},"endOfRows":true,"endOfResults":false,"rowCount":3},true]},{"ev":"call","id":7,"t":35.6,"name":"nextResultSet","args":[0,{"connectionId":0,"statementId":0}]},{"ev":"return","of":7,"t":35.7,"result":[null,{"meta":[],"handle":{"connectionId":0,"statementId":0},"endOfRows":true,"endOfResults":true,"rowCount":3}]},{"ev":"call","id":9,"t":36,"name":"releaseStatement","args":[0,{"connectionId":0,"statementId":0}]},{"ev":"state","of":2,"t":36,"change":{"handle":{"connectionId":0,"statementId":0},"oldState":"STATEMENT_READING","newState":"STATEMENT_CLOSED"}},{"ev":"return","of":9,"t":36.1,"result":[null,true]},{"ev":"call","id":12,"t":188.1,"name":"prepare","args":[1,{"query_str":"select 10 / n as r from #p where n = ?","query_timeout":0,"query_polling":false,"query_tz_adjustment":0,"numeric_string":false,"bigint_as_native":false,"stateChangeCallback":{"$":"function"}}]},{"ev":"state","of":12,"t":189.9,"change":{"handle":{"connectionId":0,"statementId":1},"oldState":"STATEMENT_CREATED","newState":"STATEMENT_PREPARED"}},{"ev":"return","of":12,"t":189.9,"result":[null,{"meta":[{"name":"r","nullable":true,"type":"number","sqlType":"int","size":10}],"handle":{"connectionId":0,"statementId":1},"endOfRows":true,"endOfResults":false,"rowCount":0}]},{"ev":"call","id":15,"t":190.1,"name":"bindQuery","args":[1,[1]]},{"ev":"state","of":12,"t":190.2,"change":{"handle":{"connectionId":0,"statementId":1},"oldState":"STATEMENT_PREPARED","newState":"STATEMENT_SUBMITTED"}},{"ev":"return","of":15,"t":193.8,"result":[null,{"meta":[{"name":"r","nullable":true,"type":"number","sqlType":"int","size":10}],"handle":{"connectionId":0,"statementId":1},"endOfRows":true,"endOfResults":false,"rowCount":0}]},{"ev":"call","id":18,"t":193.9,"name":"fetchRows","args":[1,{"connectionId":0,"statementId":1},{"asArrays":true,"batchSize":50,"asObjects":false}]},{"ev":"return","of":18,"t":194.6,"result":[null,{"endOfRows":false,"endOfResults":false,"rowCount":1,"data":{"$":"rows","n":1,"first":[10]}}]},{"ev":"call","id":20,"t":194.8,"name":"fetchRows","args":[1,{"connectionId":0,"statementId":1},{"asArrays":true,"batchSize":50,"asObjects":false}]},{"ev":"return","of":20,"t":194.8,"result":[null,{"endOfRows":true,"endOfResults":false,"rowCount":0,"data":[]}]},{"ev":"call","id":22,"t":194.8,"name":"nextResultSet","args":[1,{"connectionId":0,"statementId":1}]},{"ev":"return","of":22,"t":194.9,"result":[null,{"meta":[{"name":"r","nullable":true,"type":"number","sqlType":"int","size":10}],"handle":{"connectionId":0,"statementId":1},"endOfRows":true,"endOfResults":true,"rowCount":0}]},{"ev":"call","id":24,"t":195,"name":"bindQuery","args":[1,[2]]},{"ev":"return","of":24,"t":196.1,"result":[null,{"meta":[{"name":"r","nullable":true,"type":"number","sqlType":"int","size":10}],"handle":{"connectionId":0,"statementId":1},"endOfRows":true,"endOfResults":true,"rowCount":0}]},{"ev":"call","id":26,"t":196.2,"name":"fetchRows","args":[1,{"connectionId":0,"statementId":1},{"asArrays":true,"batchSize":50,"asObjects":false}]},{"ev":"return","of":26,"t":196.7,"result":[null,{"endOfRows":false,"endOfResults":false,"rowCount":1,"data":{"$":"rows","n":1,"first":[5]}}]},{"ev":"call","id":28,"t":196.7,"name":"fetchRows","args":[1,{"connectionId":0,"statementId":1},{"asArrays":true,"batchSize":50,"asObjects":false}]},{"ev":"return","of":28,"t":196.8,"result":[null,{"endOfRows":true,"endOfResults":false,"rowCount":0,"data":[]}]},{"ev":"call","id":30,"t":196.8,"name":"nextResultSet","args":[1,{"connectionId":0,"statementId":1}]},{"ev":"return","of":30,"t":196.8,"result":[null,{"meta":[{"name":"r","nullable":true,"type":"number","sqlType":"int","size":10}],"handle":{"connectionId":0,"statementId":1},"endOfRows":true,"endOfResults":true,"rowCount":0}]},{"ev":"call","id":32,"t":196.9,"name":"bindQuery","args":[1,[1]]},{"ev":"return","of":32,"t":198,"result":[null,{"meta":[{"name":"r","nullable":true,"type":"number","sqlType":"int","size":10}],"handle":{"connectionId":0,"statementId":1},"endOfRows":true,"endOfResults":true,"rowCount":0}]},{"ev":"call","id":34,"t":198,"name":"fetchRows","args":[1,{"connectionId":0,"statementId":1},{"asArrays":true,"batchSize":50,"asObjects":false}]},{"ev":"return","of":34,"t":198.5,"result":[null,{"endOfRows":false,"endOfResults":false,"rowCount":1,"data":{"$":"rows","n":1,"first":[10]}}]},{"ev":"call","id":36,"t":198.6,"name":"fetchRows","args":[1,{"connectionId":0,"statementId":1},{"asArrays":true,"batchSize":50,"asObjects":false}]},{"ev":"return","of":36,"t":198.6,"result":[null,{"endOfRows":true,"endOfResults":false,"rowCount":0,"data":[]}]},{"ev":"call","id":38,"t":198.6,"name":"nextResultSet","args":[1,{"connectionId":0,"statementId":1}]},{"ev":"return","of":38,"t":198.7,"result":[null,{"meta":[{"name":"r","nullable":true,"type":"number","sqlType":"int","size":10}],"handle":{"connectionId":0,"statementId":1},"endOfRows":true,"endOfResults":true,"rowCount":0}]},{"ev":"call","id":40,"t":198.8,"name":"bindQuery","args":[1,[0]]},{"ev":"return","of":40,"t":199.9,"result":[null,{"meta":[{"name":"r","nullable":true,"type":"number","sqlType":"int","size":10}],"handle":{"connectionId":0,"statementId":1},"endOfRows":true,"endOfResults":true,"rowCount":0}]},{"ev":"call","id":42,"t":200,"name":"fetchRows","args":[1,{"connectionId":0,"statementId":1},{"asArrays":true,"batchSize":50,"asObjects":false}]},{"ev":"state","of":12,"t":200.6,"change":{"handle":{"connectionId":0,"statementId":1},"oldState":"STATEMENT_SUBMITTED","newState":"STATEMENT_ERROR"}},{"ev":"return","of":42,"t":200.7,"result":[[{"$":"error","message":"[Microsoft][ODBC Driver 18 for SQL Server][SQL Server]Divide by zero error encountered.","sqlstate":"22012","code":8134,"severity":16,"serverName":"","procName":"","lineNumber":1}],{"meta":[{"name":"r","nullable":true,"type":"number","sqlType":"int","size":10}],"handle":{"connectionId":0,"statementId":1},"endOfRows":false,"endOfResults":false,"rowCount":0},true]},{"ev":"call","id":45,"t":200.9,"name":"bindQuery","args":[1,[2]]},{"ev":"state","of":12,"t":201.4,"change":{"handle":{"connectionId":0,"statementId":1},"oldState":"STATEMENT_ERROR","newState":"STATEMENT_SUBMITTED"}},{"ev":"return","of":45,"t":202.4,"result":[null,{"meta":[{"name":"r","nullable":true,"type":"number","sqlType":"int","size":10}],"handle":{"connectionId":0,"statementId":1},"endOfRows":false,"endOfResults":false,"rowCount":0}]},{"ev":"call","id":48,"t":202.5,"name":"fetchRows","args":[1,{"connectionId":0,"statementId":1},{"asArrays":true,"batchSize":50,"asObjects":false}]},{"ev":"return","of":48,"t":203,"result":[null,{"endOfRows":false,"endOfResults":false,"rowCount":1,"data":{"$":"rows","n":1,"first":[5]}}]},{"ev":"call","id":50,"t":203.1,"name":"fetchRows","args":[1,{"connectionId":0,"statementId":1},{"asArrays":true,"batchSize":50,"asObjects":false}]},{"ev":"return","of":50,"t":203.1,"result":[null,{"endOfRows":true,"endOfResults":false,"rowCount":0,"data":[]}]},{"ev":"call","id":52,"t":203.1,"name":"nextResultSet","args":[1,{"connectionId":0,"statementId":1}]},{"ev":"return","of":52,"t":203.2,"result":[null,{"meta":[{"name":"r","nullable":true,"type":"number","sqlType":"int","size":10}],"handle":{"connectionId":0,"statementId":1},"endOfRows":true,"endOfResults":true,"rowCount":0}]},{"ev":"call","id":54,"t":203.3,"name":"releaseStatement","args":[1,{"connectionId":0,"statementId":1}]},{"ev":"state","of":12,"t":203.3,"change":{"handle":{"connectionId":0,"statementId":1},"oldState":"STATEMENT_SUBMITTED","newState":"STATEMENT_CLOSED"}},{"ev":"return","of":54,"t":203.8,"result":[null,true]},{"ev":"call","id":57,"t":722.2,"name":"prepare","args":[2,{"query_str":"select n from #p where n > ?","query_timeout":0,"query_polling":false,"query_tz_adjustment":0,"numeric_string":false,"bigint_as_native":false,"stateChangeCallback":{"$":"function"}}]},{"ev":"state","of":57,"t":724.3,"change":{"handle":{"connectionId":0,"statementId":2},"oldState":"STATEMENT_CREATED","newState":"STATEMENT_PREPARED"}},{"ev":"return","of":57,"t":724.3,"result":[null,{"meta":[{"name":"n","nullable":true,"type":"number","sqlType":"int","size":10}],"handle":{"connectionId":0,"statementId":2},"endOfRows":true,"endOfResults":false,"rowCount":0}]},{"ev":"call","id":60,"t":724.5,"name":"bindQuery","args":[2,[0]]},{"ev":"state","of":57,"t":724.5,"change":{"handle":{"connectionId":0,"statementId":2},"oldState":"STATEMENT_PREPARED","newState":"STATEMENT_SUBMITTED"}},{"ev":"return","of":60,"t":726.5,"result":[null,{"meta":[{"name":"n","nullable":true,"type":"number","sqlType":"int","size":10}],"handle":{"connectionId":0,"statementId":2},"endOfRows":true,"endOfResults":false,"rowCount":0}]},{"ev":"call","id":63,"t":726.6,"name":"fetchRows","args":[2,{"connectionId":0,"statementId":2},{"asArrays":true,"batchSize":50,"asObjects":false}]},{"ev":"return","of":63,"t":727.3,"result":[null,{"endOfRows":false,"endOfResults":false,"rowCount":2,"data":{"$":"rows","n":2,"first":[1]}}]},{"ev":"call","id":65,"t":727.4,"name":"fetchRows","args":[2,{"connectionId":0,"statementId":2},{"asArrays":true,"batchSize":50,"asObjects":false}]},{"ev":"return","of":65,"t":727.4,"result":[null,{"endOfRows":true,"endOfResults":false,"rowCount":0,"data":[]}]},{"ev":"call","id":67,"t":727.5,"name":"nextResultSet","args":[2,{"connectionId":0,"statementId":2}]},{"ev":"return","of":67,"t":727.5,"result":[null,{"meta":[{"name":"n","nullable":true,"type":"number","sqlType":"int","size":10}],"handle":{"connectionId":0,"statementId":2},"endOfRows":true,"endOfResults":true,"rowCount":0}]},{"ev":"call","id":69,"t":727.5,"name":"releaseStatement","args":[2,{"connectionId":0,"statementId":2}]},{"ev":"state","of":57,"t":727.5,"change":{"handle":{"connectionId":0,"statementId":2},"oldState":"STATEMENT_SUBMITTED","newState":"STATEMENT_CLOSED"}},{"ev":"return","of":69,"t":728,"result":[null,true]},{"ev":"call","id":72,"t":831.9,"name":"query","args":[3,{"query_str":"select 1 as n","query_timeout":0,"query_polling":false,"query_tz_adjustment":0,"numeric_string":false,"bigint_as_native":false,"stateChangeCallback":{"$":"function"}},[]]},{"ev":"state","of":72,"t":832,"change":{"handle":{"connectionId":0,"statementId":3},"oldState":"STATEMENT_CREATED","newState":"STATEMENT_BINDING"}},{"ev":"state","of":72,"t":832.1,"change":{"handle":{"connectionId":0,"statementId":3},"oldState":"STATEMENT_BINDING","newState":"STATEMENT_SUBMITTED"}},{"ev":"state","of":72,"t":833,"change":{"handle":{"connectionId":0,"statementId":3},"oldState":"STATEMENT_SUBMITTED","newState":"STATEMENT_READING"}},{"ev":"return","of":72,"t":833,"result":[null,{"meta":[{"name":"n","nullable":false,"type":"number","sqlType":"int","size":10}],"handle":{"connectionId":0,"statementId":3},"endOfRows":true,"endOfResults":false,"rowCount":0},true]},{"ev":"call","id":77,"t":833.1,"name":"fetchRows","args":[3,{"connectionId":0,"statementId":3},{"asArrays":true,"batchSize":50,"asObjects":false}]},{"ev":"return","of":77,"t":833.2,"result":[null,{"endOfRows":true,"endOfResults":false,"rowCount":0,"data":{"$":"rows","n":1,"first":[1]}}]},{"ev":"call","id":79,"t":833.2,"name":"nextResultSet","args":[3,{"connectionId":0,"statementId":3}]},{"ev":"return","of":79,"t":833.2,"result":[null,{"meta":[{"name":"n","nullable":false,"type":"number","sqlType":"int","size":10}],"handle":{"connectionId":0,"statementId":3},"endOfRows":true,"endOfResults":true,"rowCount":0}]},{"ev":"call","id":81,"t":833.2,"name":"releaseStatement","args":[3,{"connectionId":0,"statementId":3}]},{"ev":"state","of":72,"t":833.3,"change":{"handle":{"connectionId":0,"statementId":3},"oldState":"STATEMENT_READING","newState":"STATEMENT_CLOSED"}},{"ev":"return","of":81,"t":833.3,"result":[null,true]},{"ev":"call","id":84,"t":1145.1,"name":"query","args":[4,{"query_str":"select 1 as n","query_timeout":0,"query_polling":false,"query_tz_adjustment":0,"numeric_string":false,"bigint_as_native":false,"stateChangeCallback":{"$":"function"}},[]]},{"ev":"state","of":84,"t":1145.3,"change":{"handle":{"connectionId":0,"statementId":4},"oldState":"STATEMENT_CREATED","newState":"STATEMENT_BINDING"}},{"ev":"state","of":84,"t":1145.3,"change":{"handle":{"connectionId":0,"statementId":4},"oldState":"STATEMENT_BINDING","newState":"STATEMENT_SUBMITTED"}},{"ev":"state","of":84,"t":1146.2,"change":{"handle":{"connectionId":0,"statementId":4},"oldState":"STATEMENT_SUBMITTED","newState":"STATEMENT_READING"}},{"ev":"return","of":84,"t":1146.2,"result":[null,{"meta":[{"name":"n","nullable":false,"type":"number","sqlType":"int","size":10}],"handle":{"connectionId":0,"statementId":4},"endOfRows":true,"endOfResults":false,"rowCount":0},true]},{"ev":"call","id":89,"t":1146.3,"name":"fetchRows","args":[4,{"connectionId":0,"statementId":4},{"asArrays":true,"batchSize":50,"asObjects":false}]},{"ev":"return","of":89,"t":1146.3,"result":[null,{"endOfRows":true,"endOfResults":false,"rowCount":0,"data":{"$":"rows","n":1,"first":[1]}}]},{"ev":"call","id":91,"t":1146.4,"name":"nextResultSet","args":[4,{"connectionId":0,"statementId":4}]},{"ev":"return","of":91,"t":1146.4,"result":[null,{"meta":[{"name":"n","nullable":false,"type":"number","sqlType":"int","size":10}],"handle":{"connectionId":0,"statementId":4},"endOfRows":true,"endOfResults":true,"rowCount":0}]},{"ev":"call","id":93,"t":1146.5,"name":"releaseStatement","args":[4,{"connectionId":0,"statementId":4}]},{"ev":"state","of":84,"t":1146.5,"change":{"handle":{"connectionId":0,"statementId":4},"oldState":"STATEMENT_READING","newState":"STATEMENT_CLOSED"}},{"ev":"return","of":93,"t":1146.5,"result":[null,true]},{"ev":"call","id":96,"t":1146.7,"name":"close","args":[]},{"ev":"return","of":96,"t":1146.7,"result":[null,true]}]} \ No newline at end of file diff --git a/test/contract/recorder.js b/test/contract/recorder.js index 5a7ffea6..271ae785 100644 --- a/test/contract/recorder.js +++ b/test/contract/recorder.js @@ -111,6 +111,8 @@ class Run { conn: this.conn, query: (label, sql, params, options = {}) => this.start(label, { sql, params, ...options }), act: (label, actions) => this.act(label, this.queries.get(label), actions), + watch: (label, q, options) => this.watch(label, q, options), + next: (label, event) => new Promise(resolve => this.queries.get(label).once(event, resolve)), freed: label => this.pending.get(label), // freed, and the time after it in which late events still belong to the transcript settled: label => this.pending.get(label).then(() => delay(SETTLE_MS)), @@ -134,6 +136,15 @@ class Run { }) } const q = this.conn.query(...args) + this.watch(label, q, def) + q.on('free', () => resolveFree()) + return q + } + + // log a query's events as label: . a prepared statement's executions share one + // query object, and raise no free of their own, so a script watches it once. + watch (label, q, def = {}) { + const log = line => this.log(label, line) this.queries.set(label, q) const at = def.at ?? {} let rows = 0 @@ -157,7 +168,7 @@ class Run { }) q.on('output', () => log('output')) q.on('done', () => log('done')) - q.on('free', () => { log('free'); resolveFree() }) + q.on('free', () => log('free')) q.once('free', () => { if (label === 'q1') this.startFollowUps('free') // actions on a query that has already freed, e.g. a late cancel diff --git a/test/contract/scripts/README.md b/test/contract/scripts/README.md index 08725543..e9443677 100644 --- a/test/contract/scripts/README.md +++ b/test/contract/scripts/README.md @@ -34,6 +34,8 @@ module.exports = async t => { |---|---| | `t.query(label, sql, params, options)` | runs a query on the connection and logs its events as `label: `. Returns the query (its event emitter). `options`: `callback` (also pass a callback and log it), `columns` (log column values), `at` (actions, as in `scenarios.js`: `start`, `row: { n: [...] }`, `later: { ms: [...] }`, `free`) | | `t.act(label, actions)` | do `pause`, `resume`, `resume:` or `cancel` to that query now | +| `t.watch(label, q, options)` | log the events of a query made some other way, e.g. a prepared statement (`conn.prepare`), whose executions share one query object. It is not waited for: use `t.next` | +| `t.next(label, event)` | resolves on that query's next `event`, e.g. `'done'` | | `t.freed(label)` | resolves on the query's `free` | | `t.settled(label)` | its `free`, plus the time in which late events still belong to the transcript (a cancel callback after `free`, say) | | `t.section(title)` | a `== title` line, to divide cases | diff --git a/test/contract/scripts/prepared.js b/test/contract/scripts/prepared.js new file mode 100644 index 00000000..b02cd846 --- /dev/null +++ b/test/contract/scripts/prepared.js @@ -0,0 +1,78 @@ +'use strict' + +// a prepared statement's lifecycle. its executions share one query object (ps.preparedQuery +// returns it each time), so it is watched once, as 'ps'. each execution is submitted and +// done; free comes only from ps.free(), when the native statement is released. after +// that, any use of the statement is an error. +// +// on a table: a select with no table behind it (select 10 / ? as n) is described with no +// columns when prepared, so its executions return no rows - a separate bug. + +// the driver's [vendor][driver] prefixes vary by driver and version +const strip = m => m.replace(/^(\[[^\]]*\]\s*)+/, '') + +module.exports = async t => { + const cb = label => (err, rows, more) => { + if (err) t.log(label, `cb error ${strip(err.message)} more=${more}`) + else t.log(label, `cb ok rows=${rows ? rows.length : 'null'} more=${more}`) + } + t.query('setup', 'create table #p (n int); insert #p values (1), (2), (0)', null, { callback: true }) + await t.settled('setup') + const ps = await new Promise((resolve, reject) => { + t.conn.prepare('select 10 / n as r from #p where n = ?', (err, p) => err ? reject(err) : resolve(p)) + }) + t.section('A an execution') + t.watch('ps', ps.preparedQuery([1]), { columns: true }) + await t.next('ps', 'done') + + t.section('B a second execution') + ps.preparedQuery([2]) + await t.next('ps', 'done') + + t.section('C an execution with a callback') + ps.preparedQuery([1], cb('C')) + await t.next('ps', 'done') + + t.section('D an execution that fails at execute (divide by zero)') + ps.preparedQuery([0]) + await t.next('ps', 'done') + + t.section('E it still runs after a failure') + ps.preparedQuery([2]) + await t.next('ps', 'done') + + t.section('F free') + await new Promise(resolve => ps.free(err => { + t.log('ps', err ? `free-cb error ${strip(err.message)}` : 'free-cb ok') + resolve() + })) + await t.delay(100) + + t.section('G executions after free') + ps.preparedQuery([1], cb('G')) + await t.delay(200) + ps.preparedQuery([1]) + await t.delay(200) + + t.section('H free again') + await new Promise(resolve => { + ps.free(err => { + t.log('ps', err ? `free-cb error ${strip(err.message)}` : 'free-cb ok') + resolve() + }) + setTimeout(() => { t.log('ps', 'no free callback after 1 s'); resolve() }, 1000) + }) + + t.section('J free asked for while an execution runs: the execution ends, then free') + const ps2 = await new Promise((resolve, reject) => { + t.conn.prepare('select n from #p where n > ?', (err, p) => err ? reject(err) : resolve(p)) + }) + t.watch('ps2', ps2.preparedQuery([0])) + ps2.free(err => t.log('ps2', err ? `free-cb error ${strip(err.message)}` : 'free-cb ok')) + await t.next('ps2', 'free') + await t.delay(100) + + t.section('I the connection still works') + t.query('I', 'select 1 as n', null, { callback: true }) + await t.settled('I') +}