From d66d9cb0ad66a0a399f253d0538b95f5ed920825 Mon Sep 17 00:00:00 2001 From: TimelordUK Date: Sun, 18 Oct 2026 15:31:08 +0100 Subject: [PATCH 1/3] fix: the prepared statement lifecycle - free once, refused after Each execution of a prepared statement is submitted ... done, with no free; free is raised once, by ps.free(), when the native statement is released. After that, any use is an error. - native (bind_fetch): each execution clears the last one's diagnostics and closes the cursor it left open. after an execution failed part way, the next failed with 24000 and reported the old error again - an execution after free() is refused with HY010 (the error or callback, then done), with no native call; it ran on the released handle before, with two callbacks and a garbled message - a second free() is refused in its callback; it threw and left the connection unable to close - free() asked for while an execution runs waits for its done Corpus: scripts/prepared (agreed), with t.watch / t.next script helpers. Co-Authored-By: Claude Opus 5.5 (1M context) --- cpp/src/odbc/odbc_statement_legacy.cpp | 7 ++ lib/prepared-statement.js | 36 +++++++-- test/contract/HANDOVER.md | 25 +++++- test/contract/corpus/scripts/prepared.txt | 63 +++++++++++++++ .../native/scripts/prepared.win32.json | 1 + test/contract/recorder.js | 13 +++- test/contract/scripts/README.md | 2 + test/contract/scripts/prepared.js | 78 +++++++++++++++++++ 8 files changed, 218 insertions(+), 7 deletions(-) create mode 100644 test/contract/corpus/scripts/prepared.txt create mode 100644 test/contract/native/scripts/prepared.win32.json create mode 100644 test/contract/scripts/prepared.js 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..8fc24294 100644 --- a/test/contract/HANDOVER.md +++ b/test/contract/HANDOVER.md @@ -160,12 +160,35 @@ 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. +3. A prepared select with no table returns no rows (above). 4. #483 (Linux, native), on WSL. Settled (2026-10-17): a paused query emits nothing until resumed, including what a native 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') +} From 36f262934de011f4185609adf117380a71b6cd78 Mon Sep 17 00:00:00 2001 From: TimelordUK Date: Sun, 18 Oct 2026 15:33:45 +0100 Subject: [PATCH 2/3] docs: handover - where the v6 event contract stands, and the plan for diagnostics A current state at the top (the four issues, what guards them, the corpus status, what is left before v6), the contract as it now stands in full, and a Next plan led by never dropping what the driver sends (a new info/ corpus group first). The older sections are marked as history. Co-Authored-By: Claude Opus 5.5 (1M context) --- test/contract/HANDOVER.md | 117 ++++++++++++++++++++++++++++++-------- 1 file changed, 93 insertions(+), 24 deletions(-) diff --git a/test/contract/HANDOVER.md b/test/contract/HANDOVER.md index 8fc24294..de49f382 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) @@ -185,11 +223,42 @@ described with no columns at prepare, so its executions return no rows (`rowcoun ## 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. A prepared select with no table returns no rows (above). -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`. +- `cancel/again-after-confirm-at-100` failed once in about 50 local runs (2026-10-18), and the + transcript was not kept. If it shows again, read the variant. If it is only the refusal + and the HY008 swapping places, both meet the contract: add it as an `--- or` alternative. +- 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 @@ -254,7 +323,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 @@ -274,7 +343,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? @@ -286,9 +355,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 From f03f97dd66926241e637703b2a379c8adf7faa29 Mon Sep 17 00:00:00 2001 From: TimelordUK Date: Sun, 18 Oct 2026 16:39:41 +0100 Subject: [PATCH 3/3] test: cancel/twice-streaming-at-100 may give HY008 before cancel-cb ok The cancel callback and the HY008 from the fetch in flight are two native completions on different threads; CI saw the other order. Both meet the contract, so the transcript lists both (--- or). Co-Authored-By: Claude Opus 5.5 (1M context) --- test/contract/HANDOVER.md | 12 +++++++++--- .../corpus/cancel/twice-streaming-at-100.events.txt | 13 +++++++++++++ 2 files changed, 22 insertions(+), 3 deletions(-) diff --git a/test/contract/HANDOVER.md b/test/contract/HANDOVER.md index de49f382..2491cd4f 100644 --- a/test/contract/HANDOVER.md +++ b/test/contract/HANDOVER.md @@ -254,9 +254,15 @@ that replay covers them. - #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`. -- `cancel/again-after-confirm-at-100` failed once in about 50 local runs (2026-10-18), and the - transcript was not kept. If it shows again, read the variant. If it is only the refusal - and the HY008 swapping places, both meet the contract: add it as an `--- or` alternative. +- 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. 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