Pool fills up with 'USED' connections - node app restart required as a result

[Slos]

Expected Behavior

On calling connection.release(), connections should be released back into the pool and these connections should be in state = 1, meaning 'FREE' state so that they can be reused in the future, regardless of errors having occurred on the connection (timeouts, etc...)

Current Behavior

My connection pool slowly fills up to the max number of connections where it ends up with all connections being in the 'USED' state (i.e. state = 2).

my minimum pool size = 5 and maximum pool size = 15.

After some time (this is variable, can be after 24 hours, sometimes 48 hours,... depends on the load on the database and how often timeouts occur) I end up with 15 connections in the 'USED' state and I need to restart my application.

Whenever this happens:

RequestError: Timeout: Request failed to complete in 15000ms

--> the connection on which the timeout occurred is not released properly and remains in state = 2 ('USED')

logs from a test run: the pool starts of with 5 connections in the 'FREE' state and every time a request timeout happens on a connection, that connection's state is set to 2 and it is never free'd up.

[2019-05-27T13:00:07.421] [INFO] default - Zdeapp beta_release_0.118_SNAPSHOT running on port 3000...
[2019-05-27T13:01:00.005] [INFO] default - pool status 1,1,1,1,1
[2019-05-27T13:02:00.004] [INFO] default - pool status 1,1,1,1,1
[2019-05-27T13:03:00.004] [INFO] default - pool status 1,1,1,1,1
[2019-05-27T13:04:00.004] [INFO] default - pool status 1,1,1,1,1
[2019-05-27T13:05:00.008] [INFO] default - pool status 1,1,1,1,1
[2019-05-27T13:05:00.111] [INFO] default - pool status 1,1,1,1,1
[2019-05-27T13:06:00.004] [INFO] default - pool status 1,1,1,1,1
[2019-05-27T13:07:00.006] [INFO] default - pool status 1,1,1,1,1
[2019-05-27T13:08:00.003] [INFO] default - pool status 1,1,1,1,1
[2019-05-27T13:09:00.005] [INFO] default - pool status 1,1,1,1,1
[2019-05-27T13:10:00.003] [INFO] default - pool status 1,1,1,1,1
[2019-05-27T13:10:00.103] [INFO] default - pool status 2,1,1,1,1
[2019-05-27T13:11:00.006] [INFO] default - pool status 1,1,1,1,1
[2019-05-27T13:11:15.022] [ERROR] default - Error retrieving todays order IDs RequestError: Timeout: Request failed to complete in 15000ms
[2019-05-27T13:12:00.003] [INFO] default - pool status 2,1,1,1,1
[2019-05-27T13:13:00.004] [INFO] default - pool status 2,1,1,1,1
[2019-05-27T13:14:00.003] [INFO] default - pool status 2,1,1,1,1
[2019-05-27T13:15:00.006] [INFO] default - pool status 2,1,1,1,1
[2019-05-27T13:15:00.105] [INFO] default - pool status 2,1,1,1,1
[2019-05-27T13:16:00.004] [INFO] default - pool status 2,1,1,1,1
[2019-05-27T13:17:00.003] [INFO] default - pool status 2,1,1,1,1
[2019-05-27T13:17:15.018] [ERROR] default - Error retrieving todays order IDs RequestError: Timeout: Request failed to complete in 15000ms
[2019-05-27T13:18:00.005] [INFO] default - pool status 2,2,1,1,1
[2019-05-27T13:19:00.003] [INFO] default - pool status 2,2,1,1,1
[2019-05-27T13:20:00.005] [INFO] default - pool status 2,2,1,1,0
[2019-05-27T13:20:00.100] [INFO] default - pool status 2,2,2,1,1
[2019-05-27T13:21:00.004] [INFO] default - pool status 2,2,1,1,1
[2019-05-27T13:22:00.004] [INFO] default - pool status 2,2,1,1,1

Steps to Reproduce (for bugs)

You won't be able to reproduce with only the code pasted here, I only copied the core of the code involved. I will write up another test case (a separate test application) and I'll also post that test code here if I the same issue manifests itself.

I started printing the status of all the connections in the pool every time a connection is acquired from the pool. As can be seen from the logs, the number of 'USED' connections slowly creeps up
log excerpt:

[2019-05-25T17:33:00.008] [INFO] default - pool status 1,1,1,1,1
[2019-05-25T17:35:00.499] [INFO] default - pool status 2,1,1,1,1
[2019-05-25T17:36:00.004] [INFO] default - pool status 2,1,1,1,1
[2019-05-25T17:39:00.009] [INFO] default - pool status 2,2,1,1,1
[2019-05-25T17:40:00.499] [INFO] default - pool status 2,2,2,1,1
[2019-05-25T17:42:00.005] [INFO] default - pool status 2,2,2,1,1
[2019-05-25T17:45:00.014] [INFO] default - pool status 2,2,2,2,1
[2019-05-25T17:45:00.545] [INFO] default - pool status 2,2,2,2,2
[2019-05-25T17:45:15.676] [ERROR] default - Error when checking for newly invoiced orders RequestError: Timeout: Request failed to complete in 15000ms
[2019-05-25T17:48:00.003] [INFO] default - pool status 2,2,2,2,2
[2019-05-25T17:50:00.489] [INFO] default - pool status 2,2,2,2,2,2
[2019-05-25T17:50:15.597] [ERROR] default - Error when checking for newly invoiced orders RequestError: Timeout: Request failed to complete in 15000ms
[2019-05-25T17:51:00.026] [INFO] default - pool status 2,2,2,2,2,2
[2019-05-25T17:54:00.005] [INFO] default - pool status 2,2,2,2,2,2
[2019-05-25T17:55:00.507] [INFO] default - pool status 2,2,2,2,2,2
[2019-05-25T17:57:00.007] [INFO] default - pool status 2,2,2,2,2,2
[2019-05-25T18:00:00.099] [INFO] default - pool status 2,2,2,2,2,2,2
[2019-05-25T18:00:00.619] [INFO] default - pool status 2,2,2,2,2,2,2,1
[2019-05-25T18:03:00.008] [INFO] default - pool status 2,2,2,2,2,2,2
[2019-05-25T18:05:00.493] [INFO] default - pool status 2,2,2,2,2,2,2
[2019-05-25T18:06:00.027] [INFO] default - pool status 2,2,2,2,2,2,2
[2019-05-25T18:09:00.006] [INFO] default - pool status 2,2,2,2,2,2,2,2
[2019-05-25T18:10:00.505] [INFO] default - pool status 2,2,2,2,2,2,2,2,2
[2019-05-25T18:12:00.029] [INFO] default - pool status 2,2,2,2,2,2,2,2,2
[2019-05-25T18:15:00.007] [INFO] default - pool status 2,2,2,2,2,2,2,2,2,2
[2019-05-25T18:15:00.577] [INFO] default - pool status 2,2,2,2,2,2,2,2,2,2,2
[2019-05-25T18:18:00.028] [INFO] default - pool status 2,2,2,2,2,2,2,2,2,2,2
[2019-05-25T18:20:00.495] [INFO] default - pool status 2,2,2,2,2,2,2,2,2,2,2,2
[2019-05-25T18:21:00.025] [INFO] default - pool status 2,2,2,2,2,2,2,2,2,2,2,2
[2019-05-25T18:24:00.004] [INFO] default - pool status 2,2,2,2,2,2,2,2,2,2,2,2
[2019-05-25T18:25:00.503] [INFO] default - pool status 2,2,2,2,2,2,2,2,2,2,2,2

My connection pool js file

const ConnectionPool = require('tedious-connection-pool')
const appConfig = require('./config')[process.env.ZAPENV]
const logger = require('./logger').mainLog

const poolConfig = {
  min: 5, // 5
  max: 15, // 15
  idleTimeout: 10000,
  acquireTimeout: 12000,
  log: false
}

const config = {
  userName: appConfig.mssql.MSSQL_USER,
  password: appConfig.mssql.MSSQL_PASS,
  // server: appConfig.mssql.MSSQL_EXT_SRV,
  server: appConfig.mssql.MSSQL_INT_SRV,
  options: {
    // port: appConfig.mssql.MSSQL_EXT_PORT,
    port: appConfig.mssql.MSSQL_INT_PORT,
    database: appConfig.mssql.MSSQL_DB,
    trustedConnection: true,
    rowCollectionOnRequestCompletion: true,
    useUTC: false,
    readOnlyIntent: true,
    // acquireTimeout: 10000,
    connectTimeout: 15000,
    requestTimeout: 15000,
    maxRetriesOnTransientErrors: 0
  }
}

const pool = new ConnectionPool(poolConfig, config)

pool.on('error', function (err) {
  logger.error(`db connection pool error - ${err} pool size ${pool.connections.length}`)
})

module.exports = pool

Here's one example usage of how I use the connection pool. There are many modules inside my application which rely on the connection pool and the pattern is always the same.

1. acquire connection
2. execute the sql
3. process the returned data in the sqlrequest callback function

Note that the first line in the callback is 'connection.release()'. This to make sure the connection is definitely released once the callback is hit regardless of connection errors/success.

function getTodaysOrderIds (callback) {
  logger.info('pool status ${connectionPool.connections.map(x => x.status)}')
  connectionPool.acquire(function (err, connection) {
    logger.info('acquiring sqlserver connection...')
    if (err) {
      logger.error(err)
      return
    }

    let dataSet = []

    let sqlRequest = new MssqlRequest('SELECT something FROM somewhere', function (err, rowCount, rows) {
      connection.release()

      if (err) {
        callback(err, null)
      } else if (rowCount === 0) {
        callback(null, null)
      } else {
        rows.forEach(function (row) {
          if (row[0].value !== '') {
            let element = { 'id': row[0].value, 'create_date': row[1].value }
            dataSet.push(element)
          }
        })

        callback(null, dataSet)
      }
    })

    connection.execSql(sqlRequest)
  })
}

Am I right in thinking that in the example code below (taken from the tedious-connection-pool github repo), the connection will not be released when an error occurs? For example, DB connection is established but the request times out...

    //use the connection as normal
    var request = new Request('select 42', function(err, rowCount) {
        if (err) {
            console.error(err);
            return;
        }

        console.log('rowCount: ' + rowCount);

        //release the connection back to the pool when finished
        connection.release();
    });

Ironically, this seems to be happening in my code - connections not being released back into the pool in the correct state.... should I move my connection.release() call back to the bottom of the callback function?

Reason For Request (for feature requests)

Possible Solution

Background Details

Regular restarts are required...

Environment

• Node.js Version: 8.12.0
• Windows/Mac/Linux: CentOS Linux release 7.5.1804, x86_64 x86_64 x86_64 GNU/Linux

[mudouasenha]

I'm with the same problem! In my case, the RequestTimeout is thrown trying to execute a DELETE statement, under a transaction, inside a connectionPool.