After a query fails, the connection's work queue advances once too often, so later queries can overlap (5.1.0 – 5.6.0) #481

Version: 5.1.0 to 5.6.0, and master at 1353ab0 (its lib/ is the same as the 5.6.0 package). I read the npm packages for 5.2.1, 5.5.0, 5.5.1 and 5.6.0, and the tags v5.1.0 to v5.4.0. 2.7.0, 3.1.0 and 4.5.0 look fine.
Platform: any. The problem is in the JS work queue.
Caveat: all of this comes from reading the source. I can't run msnodesqlv8 myself (macOS, no ODBC), so I haven't run the repro below. The output shown is what I expect from the code.

I found this while reviewing node-mssql's msnodesqlv8 adapter for 5.6.0 (tediousjs/node-mssql#1917). It is separate from #478 and #479. It is, though, one way a query that is still running can end up on #479's cannot cancel query (empty queue|not found) path.

What happens

Each connection runs its work through a WorkQueue. A query puts two items on it, the query and then its FREE_STATEMENT, and normally advances the queue twice. When the query ends in an error, it advances three times for those two items. A parameter that fails to bind advances twice for its one item. nextOp() removes whatever is at the head of the queue, without checking which item the caller has finished (lib/queue.js:72-75).

• If nothing else is queued, the extra advance does nothing. That may be why the tests haven't caught it.
• If something was queued in the meantime, the extra advance removes it from the queue, usually just after it has started, and starts the item behind it. Two statements then run on the connection at once. Without MARS, I'd expect one of them to fail with HY000 "Connection is busy with results for another command".
• On 5.6.0, a query that was removed this way can't be cancelled. DriverMgr.cancel doesn't find it and fails with cannot cancel query (empty queue) or (not found) (lib/driver.js:137-156), and per 5.6.0: on cancel, 'done' is emitted before the query has ended, and also when nothing was cancelled #479 'done' is emitted anyway.
• The offset carries on. The removed query's own advances later remove the item after it, and so on, until an advance lands on an empty queue.

The queue handling is plain JS, so I expect it to be deterministic. What the ODBC driver does with two overlapping statements is the part I can't predict.

Repro (msnodesqlv8 only)

q2 takes 2 s. The script logs when each query is 'submitted', which begin() emits right after it hands the query to the native driver (reader.js:470).

• A checks whether q3 waits for q2.
• B (5.6.0 only) checks whether q2 can still be cancelled.

// MSSQL_CS="Driver={ODBC Driver 18 for SQL Server};Server=...;UID=...;PWD=...;TrustServerCertificate=yes" node queue-after-error.js
'use strict'
const sql = require('msnodesqlv8')
const { version } = require('msnodesqlv8/package.json')

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) }
  }
}

// A: q1, then q2 (2 s) and q3, queued straight away or from q1's 'free'.
// q3 should not be submitted until q2 has run (about 2 s later).
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()
  })
}

// B (5.6.0): q1, then from q1's 'free' a 2 s q2 that is cancelled 300 ms after it is submitted
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(process.env.MSSQL_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(() => {})
})

A1, A3 and B1 are the controls. [Infinity] is the value params.test.js uses to get IMNOD: [msnodesql] Parameter 1: Invalid number parameter.

On 5.1.0 to 5.5.x I'd expect A to look the same. B doesn't apply there, because those versions only cancel polling or paused queries.

Cause

Line numbers are for 5.6.0, which matches master.

A cancelled query in 5.6.0 ends through one of the two error rows:

• A cancel during execute ends through the execute-error row. That is the repro's B1, which is harmless there because nothing is queued after it.
• A cancel mid-fetch ends through end(err), as in 5.6.0: on cancel, 'done' is emitted before the query has ended, and also when nothing was cancelled #479's CI trace (reader.js:306, reached from :418).

On 5.1.0 to 5.5.x every execute error takes the execute-error row, because those versions don't look ahead after a failed SQLExecDirect. On 5.6.0 it is taken only when nothing follows in the batch.

• lib/queue.js:31-37: a new item runs at once only if the queue is empty or its head is paused. Otherwise it waits. :72-75: nextOp() removes the head, whatever it is, and runs the next item.
• lib/reader.js:293-312, end(err):
  • routes the error (:306);
  • queues the free through queryHandler.end, with a callback that advances (:308-310, via driver.js:226-238 and :209-224);
  • then calls close() (:311).
• lib/reader.js:187-203: on an execute error with no more results, beginQuery queues the free (:196) and advances (:203). The rejection reaches begin().catch (:459-469), which calls close() (:462) and advances again.
• lib/driver.js:199-207, raiseFree: calls back (:201), then a tick later emits 'free' (:203) and advances (:204).

Each path has a window, and work queued inside it gets taken out of the queue:

• Error while fetching: from end() queuing the free (reader.js:308) to driver.js:204. The query's callback and its 'free' listener both run inside it.
• Error at execute: from close() at :462 to driver.js:204. The 'error' listener (:463) and the 'free' listener run inside it. The callback doesn't, because the wrapper at connection.js:287-291 / :317-321 defers it until after :204.
• Parameter that fails to bind: anything already queued behind the query.

Prepared statements and procedures are affected too:

• A prepared statement queues no free item, but an error on either path advances twice for its one item (:309 then :311, or :203 then :462). So work already queued behind it is hit, as in the bind-failure case.
• A procedure advances 4 times for its 3 items: query, unbind and free.

The window is easy to hit from a real client. node-mssql releases a connection to its pool from the request's 'error' listener. So after an error at execute, the pool's validation SELECT 1, or the next request, is queued inside the window and runs without an entry in the queue. node-mssql only runs one query on a connection at a time, so I wouldn't expect that on its own to overlap anything.

When it started

• 4.5.0: end(err) routes the error from the free callback without advancing (reader.js:234-242), and an execute error also goes through end(). That is two advances for two items. 2.7.0 and 3.1.0 are the same.
• 5.1.0: the two extra advances came in with the 5.x rewrite, and both were first published in 5.1.0:
  • reader.js:309 came from 93f1590, "add corrected error handling for bulk tests".
  • reader.js:203 came from 40ae56b, "only submit a cancel when the handle has been returned to JS".
• Later versions: the same code is in 5.2.1 and 5.5.x (reader.js:119, :196, :301; driver.js:187).
• A hint about intent: in close(), the comment "Don't call nextOp here - it should be called after statement is freed" (reader.js:121) sits directly above a nextOp() call.

msnodesqlv8's own Pool

As far as I can see, the Pool is shielded for ordinary pool.query() work:

• It checks a connection back in on 'free' (pool.js:352-370).
• It only hands out new work from crank() in a setImmediate (pool.js:368-370, :647-656).
• By then the extra advance has already run against an empty queue.

Code that uses a Connection directly is exposed, and so are clients that queue more work on a connection before 'free'.

Suggested fix

These are just ideas.

1. Smallest change: make each path advance once per item.

   • At reader.js:203, call this.close() instead of this.queue.nextOp(). close() advances once and clears running, so the close() in begin().catch (:462) becomes a no-op through its guard (:117). This also fixes the bind-failure path.
   • In end(), drop the advance from the free callback (:308-310). close() already advances past the query, and raiseFree advances past the free.
   • From my reading, that gives 2 for 2 for a query, 1 for 1 for a prepared statement and 3 for 3 for a procedure on every path.
   • I don't know what the nextOp added in 93f1590 was fixing, so the bulk tests are worth re-running. I also haven't traced the other callers of end() with this change: the cancelled branch in moveToNextResult (:337-341) and the ODBC 17 JS timeout (:533-551).

2. Sturdier: make finishing an item specific to that item, and idempotent. For example, WorkQueue.finish(op) would:

   • remove op only if it is still queued;
   • start the new head only if op was the head;
   • compare by identity, as changePriority does with compareValue. remove()'s default comparator matches on priority, and every parked item shares Number.MAX_SAFE_INTEGER.

   close() would pass this.notify.getOperation(). freeStatement would keep the op it enqueues (driver.js:213), and raiseFree would finish that op, or nothing when there was no handle (driver.js:221-222, which today advances without having queued anything). A second advance for the same item would then do nothing, instead of removing a neighbour.

3. A regression test along the lines of the repro:

   • For each way a query can fail (error at execute, error after a result, a parameter that fails to bind, a cancel), queue two more queries inside the window. Check that the second isn't submitted until the first has returned its rows.
   • On 5.6.0, also check that a query started after a failed one can still be cancelled.