Replay the event contract corpus over a fake native driver

lib/connection.js

@@ -442,3 +442,5 @@ class ConnectionWrapper {
 }
 
 exports.PrivateConnection = PrivateConnection
+
+exports.ConnectionWrapper = ConnectionWrapper // test/common/fake-native.js builds one over a fake driver

test/common/fake-native.js

@@ -0,0 +1,179 @@
+'use strict'
+
+// a fake native Connection, for testing the JS layer (queue, reader, notifier) without a
+// server. it replays a log recorded from the real driver (test/contract/native-tap.js):
+// when JS makes a call, the fake matches it to the recorded call, and gives back what the
+// driver gave back then.
+//
+// results are released in causal order: a recorded result is delivered only once JS has
+// made every call recorded before it, one result per tick. so a query whose recorded result
+// is HY008 waits until JS has actually sent the cancel - no timestamps needed.
+//
+// it also checks, whatever the log says, that JS respects the driver:
+//   overlap        a second call (cancel apart) while one is still in flight on the connection
+//   after release  a call on a statement that has been released
+//   after close    a call once the connection is closed
+//   diverged       a call that is not the next one recorded for that query
+//   unrecorded     a call the log has nothing for (it is never answered)
+//   stalled        nothing can move: JS waits on a result that waits on a call JS never makes
+
+const path = require('path')
+const { decode } = require('../contract/native-tap')
+
+const STALL_MS = 1000
+
+class ReplayNative {
+  constructor (log, { stallMs = STALL_MS } = {}) {
+    this.log = log
+    this.stallMs = stallMs
+    this.consumed = new Set() // recorded call ids JS has made
+    this.callbacks = new Map() // recorded call id -> JS callback
+    this.stateCallbacks = new Map() // recorded call id -> JS stateChangeCallback
+    this.cursor = 0
+    this.delivering = false
+    this.inFlight = new Map() // recorded call id -> name, main calls only (not cancel)
+    this.released = new Set() // statementIds
+    this.closed = false
+    this.violations = []
+    this.stallTimer = null
+  }
+
+  violation (kind, detail) {
+    this.violations.push(`${kind}: ${detail}`)
+  }
+
+  // the recorded calls JS has not made
+  unconsumed () {
+    return this.log.filter(e => e.ev === 'call' && !this.consumed.has(e.id)).map(e => `${e.name}(${JSON.stringify(e.args[0])})`)
+  }
+
+  match (name, args) {
+    const qid = typeof args[0] === 'number' ? args[0] : null
+    const sameQuery = e => e.ev === 'call' && !this.consumed.has(e.id) &&
+      (qid === null || e.args[0] === qid)
+    // a cancel runs alongside the statement's other calls, so it is matched on its own
+    const channel = e => (e.name === 'cancelQuery') === (name === 'cancelQuery')
+    const next = this.log.find(e => sameQuery(e) && channel(e))
+    if (next && next.name === name) return next
+    const later = this.log.find(e => sameQuery(e) && e.name === name)
+    if (later) {
+      this.violation('diverged', `${name}(${qid}) made where the log has ${next?.name ?? 'nothing'} next`)
+      return later
+    }
+    this.violation('unrecorded', `${name}(${qid ?? ''})`)
+    return null
+  }
+
+  invoke (name, args) {
+    const cb = typeof args[args.length - 1] === 'function' ? args[args.length - 1] : null
+    const callArgs = cb ? args.slice(0, -1) : args
+    if (this.closed) this.violation('after close', name)
+    const handle = callArgs[1]
+    if (handle && typeof handle.statementId === 'number' && this.released.has(handle.statementId)) {
+      this.violation('after release', `${name} on statement ${handle.statementId}`)
+    }
+    if (name !== 'cancelQuery' && this.inFlight.size > 0) {
+      this.violation('overlap', `${name} while ${[...this.inFlight.values()].join(', ')} in flight`)
+    }
+    const entry = this.match(name, callArgs)
+    if (!entry) return
+    this.consumed.add(entry.id)
+    if (cb) this.callbacks.set(entry.id, { name, cb })
+    if (name !== 'cancelQuery' && cb) this.inFlight.set(entry.id, name)
+    const queryObj = callArgs[1]
+    if (queryObj && typeof queryObj.stateChangeCallback === 'function') {
+      this.stateCallbacks.set(entry.id, queryObj.stateChangeCallback)
+    }
+    if (name === 'releaseStatement' && handle) this.released.add(handle.statementId)
+    if (name === 'close') this.closed = true
+    this.pump()
+  }
+
+  // deliver recorded states and results, in recorded order, until a recorded call JS has
+  // not made yet
+  pump () {
+    this.armStall()
+    if (this.delivering) return
+    while (this.cursor < this.log.length) {
+      const e = this.log[this.cursor]
+      if (e.ev === 'call') {
+        if (!this.consumed.has(e.id)) return
+        this.cursor++
+        continue
+      }
+      this.delivering = true
+      setImmediate(() => {
+        this.delivering = false
+        this.cursor++
+        this.deliver(e)
+        this.pump()
+      })
+      return
+    }
+  }
+
+  deliver (e) {
+    if (e.ev === 'state') {
+      const onState = this.stateCallbacks.get(e.of)
+      if (onState) onState(null, decode(e.change))
+      return
+    }
+    const call = this.callbacks.get(e.of)
+    this.inFlight.delete(e.of)
+    if (call) call.cb(...decode(e.result))
+  }
+
+  // a result JS is waiting for is held back by a call JS is not going to make
+  armStall () {
+    clearTimeout(this.stallTimer)
+    this.stallTimer = setTimeout(() => {
+      const waiting = [...this.inFlight.values()]
+      const blocked = this.log[this.cursor]
+      if (waiting.length > 0 && blocked) {
+        this.violation('stalled', `JS waits on ${waiting.join(', ')}; the log waits on ${blocked.name ?? blocked.ev}(${JSON.stringify(blocked.args?.[0] ?? '')})`)
+      }
+    }, this.stallMs)
+    this.stallTimer.unref()
+  }
+
+  // the native Connection interface
+  open (...a) { this.invoke('open', a) }
+  close (...a) { this.invoke('close', a) }
+  query (...a) { this.invoke('query', a) }
+  bindQuery (...a) { this.invoke('bindQuery', a) }
+  prepare (...a) { this.invoke('prepare', a) }
+  fetchRows (...a) { this.invoke('fetchRows', a) }
+  nextResultSet (...a) { this.invoke('nextResultSet', a) }
+  releaseStatement (...a) { this.invoke('releaseStatement', a) }
+  cancelQuery (...a) { this.invoke('cancelQuery', a) }
+  callProcedure (...a) { this.invoke('callProcedure', a) }
+  unbind (...a) { this.invoke('unbind', a) }
+  beginTransaction (...a) { this.invoke('beginTransaction', a) }
+  commit (...a) { this.invoke('commit', a) }
+  rollback (...a) { this.invoke('rollback', a) }
+}
+
+// an msnodesqlv8-shaped module whose connections run over the given fake native
+// connection, through the real JS layer (ConnectionWrapper, DriverMgr, reader, queue)
+function fakeSql (native, { version = 18 } = {}) {
+  const root = path.join(__dirname, '../..')
+  const { ConnectionWrapper } = require(path.join(root, 'lib/connection'))
+  const { driverModule } = require(path.join(root, 'lib/driver'))
+  const defaultCallback = err => { if (err) throw new Error(err) }
+
+  const open = (connectionString, cb) => {
+    const driverMgr = new driverModule.DriverMgr(native, version)
+    const conn = new ConnectionWrapper({}, {}, driverMgr, defaultCallback, 0)
+    conn.setUseUTC(true)
+    conn.setDriverVersion(version)
+    native.open(connectionString, 0, err => setImmediate(() => cb(Array.isArray(err) ? err[0] : err, conn)))
+  }
+  return {
+    open,
+    promises: {
+      open: connectionString => new Promise((resolve, reject) => open(connectionString, (e, c) => e ? reject(e) : resolve(c)))
+    }
+  }
+}
+
+module.exports = { ReplayNative, fakeSql }

test/contract/README.md

@@ -17,6 +17,9 @@ event order shows up as a diff in review, and the contract can be discussed line
 | `capture.js` | CLI to record and compare |
 | `contract.test.js` | mocha: every scenario must match its corpus file |
 | `run-one.js` | runs one scenario in a child process, so a hang or runaway can't affect the next |
+| `native-tap.js` | records the native calls of a run: each call into the driver, state change and result, in order |
+| `native/` | those recordings, `<name>.<platform>.json`, one per scenario |
+| `replay.js`, `replay.test.js` | replay each recording over the fake driver (`test/common/fake-native.js`), through the real JS layer, with no server |
 
 ## Workflow
 
@@ -34,6 +37,31 @@ node test/contract/capture.js --root ../some-dir/node_modules/msnodesqlv8
 npx mocha test/contract/contract.test.js
 ```
 
+## Replaying without a server
+
+`capture.js --native` records, for each scenario, what passed between the JS layer and the
+native driver (secrets and host names are left out). `replay.test.js` replays it: the fake
+driver answers each call with what the real one answered, in causal order. The transcript
+has to match the corpus, and the fake checks that the JS respects the driver:
+
+- `overlap`: a second call (a cancel apart) while one is still in flight on the connection;
+- `after release`: a call on a released statement;
+- `diverged` / `unrecorded`: a call the recording doesn't have next, or at all;
+- `stalled`: JS waits on a result that waits on a call JS never makes.
+
+A race the real driver shows once in ten runs then fails every time. Against 5.6.0's `lib/`
+it reports the pause crash (`diverged: nextResultSet ... where the log has fetchRows`), #481
+(`overlap: query while query in flight`) and the late free (`stalled`).
+
+```sh
+node test/contract/capture.js --native cancel/   # record (keeps a log only if its run matches the corpus)
+node test/contract/replay.js cancel/             # replay and compare
+npx mocha test/contract/replay.test.js           # all of them, ~20 s
+```
+
+When a change to the JS is meant to change the native calls (not just the events), record
+again. The recordings are per platform, because the drivers differ (#483).
+
 ## Status of a transcript
 
 Each file has `# status: unreviewed` or `# status: agreed`.

test/contract/capture.js

@@ -8,22 +8,28 @@
 //   node test/contract/capture.js --repeat 10 [filter] run each scenario 10 times (default 3)
 //   node test/contract/capture.js --root <dir>         use the msnodesqlv8 in <dir>, e.g. an
 //                                                      older release, to see how it differs
+//   node test/contract/capture.js --native [filter]    also record each scenario's native calls
+//                                                      into native/<name>.json, for the fake
+//                                                      driver to replay (a run whose transcript
+//                                                      is not in the corpus is not kept)
 //
 // a filter matches any part of a scenario name, e.g. 'cancel/' or 'dup-key'.
 // the connection string comes from the test environment, as for the mocha tests.
 
+const fs = require('fs')
 const path = require('path')
 const { TestEnv } = require('../env/test-env')
 const { scenarios } = require('./scenarios')
-const { captureScenario } = require('./recorder')
+const { captureScenario, runIsolated } = require('./recorder')
 const corpus = require('./corpus')
 
 function parseArgs (argv) {
-  const opts = { update: false, print: false, repeat: 3, root: path.join(__dirname, '../..'), filters: [] }
+  const opts = { update: false, print: false, native: false, repeat: 3, root: path.join(__dirname, '../..'), filters: [] }
   for (let i = 0; i < argv.length; i++) {
     const a = argv[i]
     if (a === '--update') opts.update = true
     else if (a === '--print') opts.print = true
+    else if (a === '--native') opts.native = true
     else if (a === '--repeat') opts.repeat = Number(argv[++i])
     else if (a === '--root') opts.root = path.resolve(argv[++i])
     else opts.filters.push(a)
@@ -61,6 +67,7 @@ async function main () {
     if (opts.update && !allMatch) {
       console.log(`  wrote ${path.relative(process.cwd(), corpus.write(scenario, variants))}`)
     }
+    if (opts.native) await recordNative(opts.root, connectionString, scenario)
   }
 
   console.log(`\n${summary.same} same, ${summary.different} different, ${summary.missing} new`)
@@ -71,6 +78,26 @@ async function main () {
   process.exit(0)
 }
 
+// one more run, recording its native calls; kept only if its transcript is in the corpus
+async function recordNative (root, connectionString, scenario) {
+  const file = nativeFile(scenario.name)
+  const tmp = `${file}.tmp`
+  fs.mkdirSync(path.dirname(file), { recursive: true })
+  const lines = await runIsolated(root, connectionString, scenario, tmp)
+  const expected = corpus.read(scenario.name)
+  if (fs.existsSync(tmp) && expected && corpus.matches(expected, lines)) {
+    fs.renameSync(tmp, file)
+    console.log(`  native log ${path.relative(process.cwd(), file)}`)
+  } else {
+    fs.rmSync(tmp, { force: true })
+    console.log('  native log not kept: that run does not match the corpus')
+  }
+}
+
+function nativeFile (name, platform = process.platform) {
+  return path.join(__dirname, 'native', `${name}.${platform}.json`)
+}
+
 main().catch(e => {
   console.error(e)
   process.exit(1)