5.6.0: a failed statement's info messages are emitted before its error (3621 "The statement has been terminated." arrives before 2627) #478

Version: 5.6.0. The change is in 217a7f3, which is part of #475.
Platform: any. The reordering happens in lib/reader.js; only case D below depends on the platform. Found while investigating node-mssql CI failures on Windows (Node 22 and 24, SQL Server 2016 to 2022, SQL Server Native Client 11.0), but CI did not observe this behaviour directly.

How this was checked: by reading the 5.5.0 and 5.6.0 code. I could not run msnodesqlv8 myself (macOS, no ODBC). The server's message order was checked separately, by running the batches through tedious against SQL Server (Azure SQL Edge): ERROR 2627 (class 14), then INFO 3621 (class 0), under the same DONE token.

Keeping the prints that used to be dropped is a good change. The problem is only where they now land. A failed DML statement produces two diagnostic records in this order: [23000 / 2627 Violation of PRIMARY KEY…, 01000 / 3621 The statement has been terminated.]. You saw the same pair in #183, where the 3621 followed the 2627 in the same list. 5.6.0 now emits 'info' 3621 first and 'error' 2627 second.

This surfaced while we were investigating node-mssql's CI failure on 5.6.0 (run 38225080240). It was not one of the failing tests: no node-mssql test covered it at the time.

Who it affects

• Not affected: the promise API and the api-tour pattern, because err._results.info doesn't depend on order.
• Affected: event consumers that pair the 3621 with the error before it. node-mssql's handler has done that since 2020, following Emitting done after transaction failing #183. It treats 3621 as "the error just before this one was final".
  • On 5.6.0 the handler fires before any error has arrived, so an unpatched node-mssql rejects a duplicate-key insert with number 3621 instead of 2627.
  • The real 2627 is then dropped, because node-mssql has already removed its 'error' listener and routeStatementError only emits to listeners (reader.js:96).
  • We have since made node-mssql cope with either order (fix: support the msnodesqlv8 5.6 error, cancel and info events tediousjs/node-mssql#1917), so this isn't urgent for us.

Repro (msnodesqlv8 only)

// node repro.js "Driver={ODBC Driver 18 for SQL Server};Server=...;UID=...;PWD=...;TrustServerCertificate=yes"
'use strict'
const sql = require('msnodesqlv8')
const { version } = require('msnodesqlv8/package.json')
const strip = m => m.replace(/^(\[[^\]]*\])+/, '')

const events = (conn, text) => new Promise(resolve => {
  const ev = []
  const q = conn.query(text)
  q.on('meta', () => ev.push('meta'))
  q.on('info', m => ev.push(`info ${m.code}`))
  q.on('error', (e, more) => ev.push(`error ${e.code} more=${more}`))
  q.on('done', () => ev.push('done'))
  q.on('free', () => { ev.push('free'); resolve(ev) })
})
const run = (conn, text) => new Promise((resolve, reject) =>
  conn.query(text, (e, rows, more) => { if (e) reject(e); else if (!more) resolve() }))

sql.open(process.argv[2], async (err, conn) => {
  if (err) throw err
  await run(conn, 'create table #t (id int primary key); insert #t values (1)')
  const cases = {
    A: 'insert #t values (1)',                               // SQLExecDirect fails, batch ends
    B: 'select 1 as n; insert #t values (1)',                // fails at SQLMoreResults, batch ends
    C: 'select 1 as n; insert #t values (1); select 2 as m', // fails at SQLMoreResults, batch goes on
    D: 'insert #t values (1); select 2 as m'                 // SQLExecDirect fails, batch goes on (Windows)
  }
  for (const [k, text] of Object.entries(cases)) {
    console.log(version, process.platform, k, (await events(conn, text)).join(' > '))
  }
  conn.close(() => {})
})

Sequences

These come from reading the code; they were not run.

• Expected: error 2627 followed by info 3621 in every case. That is the server's order and the driver's.
• Before 5.1: releases up to 5.0.x gave that order for A (error 2627 more=false > info 3621 > free). In the SQLMoreResults path they dropped the 3621.
• No release has emitted a statement's 3621 before its error until now.
• 5.6.0 is inconsistent with itself: D on Windows already comes out in driver order, but C does not, even though it has the same pair of messages.

Cause

• lib/reader.js:134-153, dispatchInfoReturnErrors, as changed in 217a7f3:
  • It splits the set of diagnostics into infos and errors.
  • It routes the infos straight away and returns the errors.
  • The errors are routed later, from one of three places:
    • begin().catch → routeStatementError (:463) for A
    • end() (:306) for B
    • the carry-on branch of nativeNextResult (:165) for C
• lib/reader.js:437: begin()'s warning path routes the whole mixed list in driver order. That is why D differs from C.
• The native side keeps driver order:
  • read_errors walks SQLGetDiagRec from 1 to N (cpp/include/odbc/odbc_handles.h).
  • OdbcAsyncWorker::GetErrors copies the list in that order.

Suggested fix

• Route each set of diagnostics in the order the driver returned it, as begin() already does at :437:
  • When a set has no errors, route the infos and return [], as now.
  • When it has an error, don't route anything there. Return the whole list and let the callers route it in order:
    • the carry-on branch with moreResults = true;
    • the batch-ending paths through reject(list). This is what 5.0.x did for A.
• more in routeStatementError needs a matching change.
  • For callbacks, :90 uses i < errorsAndInfo.length - 1, so it counts info entries. Once a trailing 3621 is in the list, the last error's callback would get more=true. That is the Emitting done after transaction failing #183 problem, which was fixed then for events but not for callbacks.
  • For events, :95 compares against errorCount, but i still counts infos. So [print, e1, e2] would give e1 more=false.
  • Counting only errors, and using the number of errors still to come for both callbacks and events, avoids both problems.
• One thing to check first: does the driver list a print and a throw that arrive together as [print, throw] (arrival order)?
  • This is the case your test "a print in the same diagnostics as the final error is not dropped" covers.
  • ODBC lets a driver rank errors ahead of 01xxx warnings. If msodbcsql or SNAC do that, driver order would put that print after its throw.
  • For the 2627/3621 pair the two orders agree, so that pair is unaffected either way.
  • If the driver turns out to rank, splitting the sets differently, for example keeping trailing infos after the errors, would still fix the 3621 case.
• A test in batch-errors.test.js asserting error 2627 before info 3621 for A and C would pin the order.