Connection Pools continue to attempt to replenish connections after close is called

[dhensby]

If a connection errors and you attempt to close the pool the pool continues to attempt to re-establish new connections for some time after this.

Please see #470 for previous discussions around this.

Expected behaviour:

The connection pool should abort any pending connection attempts and stop any new attempts from occurring once connection.close is called.

Actual behaviour:

The connection pool continues to attempt to create connections after connection.close has been called.

Configuration:

NB: The config doesn't appear to make a difference here

const sqlConfig = {
    password: '********',
    database: '********',
    // connectionTimeout: undefined,
    // requestTimeout: 30000,
    stream: false,
    options: { encrypt: true },
    port: 1433,
    user: '********',
    server: 'localhost',
    pool: {
        acquireTimeoutMillis: 15000,
    },
};

Software versions

• NodeJS: v10.15.1
• node-mssql: v5.0.0-beta.1
• SQL Server: mssql-server-linux:2017-CU9

[dhensby]

I've created the following test code to try and get as simple a replication as possible (modified from #470):

const mssql = require('mssql')

const sqlConfig = {
  password: '********',
  database: '********',
  // connectionTimeout: undefined,
  // requestTimeout: 30000,
  stream: false,
  options: { encrypt: true },
  port: 1433,
  user: '********',
  server: 'localhost',
  pool: {
    acquireTimeoutMillis: 15000,
  },
}

let errorCount = 0;

let pool;

let reconnectTimer;

function connect() {
  console.log('trying to connect to server')
  mssql.connect(sqlConfig).then((connection) => {
    console.log('connection established')
    connection.on('error', (e) => {
      errorCount++
      console.log('Connection errored, trying to close connection', errorCount)
      // we have to call `mssql.close` here and not `connection.close`
      // because we need the globalConnection to be cleaned up
      mssql.close((e) => {
        console.log('connection closed')
        if (e) {
          errorCount++
          console.log('connection close error', errorCount)
        } else {
          // prevent multiple timers being queued
          if (reconnectTimer) {
            clearTimeout(reconnectTimer)
          }
          reconnectTimer = setTimeout(connect, 1500)
        }
      })
    })
    pool = connection
  }).catch((e) => {
    errorCount++
    console.log('failed to establish connection', errorCount)
    // clear the timer so that node can exit
    clearInterval(interval)
  })
}

function getTime() {
  if (!pool) {
    console.log('getTime called but no connection is ready')
    return
  }
  pool.request().query('SELECT GETUTCDATE()').then((result) => {
    console.log(result)
  }).catch((e) => {
    errorCount++
    console.log('error performing query', errorCount)
  })
}

const interval = setInterval(getTime, 5000)
connect()

In this example many connection errors are repeatedly emitted even after the mssql.close callback is executed.

Output:

$ node test.js
trying to connect to server
connection established
{ recordsets: [ [ [Object] ] ],
  recordset: [ { '': 2019-02-15T10:34:23.343Z } ],
  output: {},
  rowsAffected: [ 1 ] }
Connection errored, trying to close connection 1
Connection errored, trying to close connection 2
connection closed
Connection errored, trying to close connection 3
connection closed
...
Connection errored, trying to close connection 343
connection closed
error performing query 344
trying to connect to server
failed to establish connection 345
Connection errored, trying to close connection 346
connection closed
...
Connection errored, trying to close connection 469
connection closed
trying to connect to server
failed to establish connection 470
Connection errored, trying to close connection 471
connection closed
...
Connection errored, trying to close connection 594
connection closed
trying to connect to server
failed to establish connection 595
Connection errored, trying to close connection 596
connection closed
...
Connection errored, trying to close connection 719
connection closed
trying to connect to server
failed to establish connection 720
Connection errored, trying to close connection 721
connection closed
...
Connection errored, trying to close connection 844
connection closed
trying to connect to server
failed to establish connection 845
Connection errored, trying to close connection 846
connection closed
...
Connection errored, trying to close connection 969
connection closed
trying to connect to server
failed to establish connection 970
Connection errored, trying to close connection 971
connection closed
...
Connection errored, trying to close connection 1096
connection closed
trying to connect to server
failed to establish connection 1097

This logging appears to show that an error occurs on the pool. The pool is then closed and the callback fired but connection errors continue to be thrown. Reconnects then appear to be attempted, presumably by the timeout call) until eventually the original the backlog of timers are cleared.

[dhensby]

I think some of the problem here is that the way generic-pool works (and how we have implemented it) is that a call to close will try to gracefully drain the pool (ie: it will wait for all connections to be released back to the pool before actually closing), which means if some connections have been acquired (but gone bad) the close callback won't fire until they are returned to the pool...

There doesn't appear to be a way to force the pool to revoke all connections...

[dhensby]

The problem as I can determine it is as follows.

1. A query attempts to execute, as part of this there is an attempt to acquire a connection from the pool
2. The pool attempts to release a connection but all the connections are bad
3. The pool attempts to create new connections but they fail, triggering yet more attempts to create connections
4. The above code detects the error and attempts to close the pool
5. The pool is continuing to attempt to create connections to fulfil the request to acquire call until the acquireTimeoutMillis limit is reached
6. The acquire rejects and the pool is allowed to drain, the process comes to an end

The problem is that there is no kind of back-off or slowdown in attempting to create a new connection resulting in the repeated attempts to create connections that fail if the SQL Server has gone away.

Therefore, my suggested fix is that the factoryCreate method doesn't actually reject and instead it implements it's own back off allowing the acquireTimeoutMillis to determine when to stop connection attempts.

[dhensby]

A side issue is that a call to close the pool doesn't abort factoryCreate attempts, this could also be resolved by rejecting in factoryCreate if the pool is deemed to have been closed

[dhensby]

I've looked into this over the past couple of days and my conclusion is that generic-pool is a bit broken.

Even after attempting to drain and close the pool new resource create requests will be made, which is far from desirable.

There are relevant issues open against generic-pool so hopefully it's a matter of time before it's resolved in the upstream repo. Alternatively we can move to tarn

[dhensby]

This will be fixed in v6 with the move to tarn #808