ResourceRequest timed out - connection not reestablished after db restarted

[codyseibert]

What you are doing?

We're running into an issue where Sequelize will not reconnect to the database after the database is stopped and started again. If you want, you can try hosting a local mssql database using this tutorial and running the following code, and following the steps I provide below:

https://medium.com/@reverentgeek/sql-server-running-on-a-mac-3efafda48861

const options = {
  host: 'localhost',
  dialect: 'mssql',
  pool: {
    max: 1,
    min: 0,
    idle: 5000,
    acquire: 5000
  },
  dialectOptions: {
    requestTimeout: 5000
  },
  isolationLevel: 'READ UNCOMMITTED'
};

const Sequelize = require('sequelize')

const sequelize = new Sequelize('testing', 'sa', 'P@55w0rd', options);

setInterval(() => {
  sequelize
    .query("SELECT 'connection is successful'", {
      type: Sequelize.QueryTypes.SELECT
    })
    .then((results) => {
      console.log(results);
    })
    .catch((err) => {
      console.log(err);
    })
}, 5000);

Steps after code is running and mssql container is running:

1. stop the container
2. wait until an interval fires and throws an error
3. start the container
4. notice that all future queries result in timeout errors

I'm pretty sure this should reject, but I'm not too sure: https://github.com/sequelize/sequelize/blob/master/lib/dialects/abstract/connection-manager.js#L98

What do you expect to happen?

Sequelize to reconnect and have queries work as normal.

What is actually happening?

Sequelize fails to reconnect the created pool resource.

Dialect: mssql, but probably all
Database version: XXX
Sequelize version: 4.4.2

[rogeriomq]

I go through the same situation. I have not found a solution yet ;(

[smithdalec]

@sushantdhiman #8330 does not fix this issue. Still experiencing the ResourceRequest timed out error after SQL Server restart using sequelize@4.9.0.
#8022 Fixes this issue, and we're patiently waiting on it to be merged 😄

Could you please re-open this ticket until #8022 is merged?
I'll be happy to contribute in any way possible.

[sushantdhiman]

@smithdalec Can you provide me a test case to test with, something like #7884 (comment)

[smithdalec]

@sushantdhiman I can use the test case as described in the initial comment and reproduce the issue using the linked Docker container with MSSQL.
Here's my output with "sequelize": "^4.9.0", in my package.json installed:

> node db-test.js
Executing (default): SELECT 'connection is successful'
[ { '': 'connection is successful' } ]
Executing (default): SELECT 'connection is successful'
{ SequelizeDatabaseError: Connection closed before request completed.
    at Query.formatError (node_modules/sequelize/lib/dialects/mssql/query.js:322:12)
    at Request.connection.lib.Request [as userCallback] (node_modules/sequelize/lib/dialects/mssql/query.js:107:25)
    at Request._this.callback (node_modules/tedious/lib/request.js:47:27)
    at Connection.cleanupConnection (node_modules/tedious/lib/connection.js:324:24)
    at Connection.enter (node_modules/tedious/lib/connection.js:1440:19)
    at Connection.transitionTo (node_modules/tedious/lib/connection.js:676:33)
    at Connection.socketEnd (node_modules/tedious/lib/connection.js:719:19)
    at emitNone (events.js:91:20)
    at Socket.emit (events.js:185:7)
    at endReadableNT (_stream_readable.js:974:12)
    at _combinedTickCallback (internal/process/next_tick.js:80:11)
    at process._tickCallback (internal/process/next_tick.js:104:9)
  name: 'SequelizeDatabaseError',
  parent:
   { RequestError: Connection closed before request completed.
       at RequestError (node_modules/tedious/lib/errors.js:34:12)
       at Connection.cleanupConnection (node_modules/tedious/lib/connection.js:323:21)
       at Connection.enter (node_modules/tedious/lib/connection.js:1440:19)
       at Connection.transitionTo (node_modules/tedious/lib/connection.js:676:33)
       at Connection.socketEnd (node_modules/tedious/lib/connection.js:719:19)
       at emitNone (events.js:91:20)
       at Socket.emit (events.js:185:7)
       at endReadableNT (_stream_readable.js:974:12)
       at _combinedTickCallback (internal/process/next_tick.js:80:11)
       at process._tickCallback (internal/process/next_tick.js:104:9)
     message: 'Connection closed before request completed.',
     code: 'ECLOSE',
     sql: 'SELECT \'connection is successful\'' },
  original:
   { RequestError: Connection closed before request completed.
       at RequestError (node_modules/tedious/lib/errors.js:34:12)
       at Connection.cleanupConnection (node_modules/tedious/lib/connection.js:323:21)
       at Connection.enter (node_modules/tedious/lib/connection.js:1440:19)
       at Connection.transitionTo (node_modules/tedious/lib/connection.js:676:33)
       at Connection.socketEnd (node_modules/tedious/lib/connection.js:719:19)
       at emitNone (events.js:91:20)
       at Socket.emit (events.js:185:7)
       at endReadableNT (_stream_readable.js:974:12)
       at _combinedTickCallback (internal/process/next_tick.js:80:11)
       at process._tickCallback (internal/process/next_tick.js:104:9)
     message: 'Connection closed before request completed.',
     code: 'ECLOSE',
     sql: 'SELECT \'connection is successful\'' },
  sql: 'SELECT \'connection is successful\'' }
{ TimeoutError: ResourceRequest timed out
    at ResourceRequest._fireTimeout (node_modules/generic-pool/lib/ResourceRequest.js:58:17)
    at Timeout.bound (node_modules/generic-pool/lib/ResourceRequest.js:8:15)
    at ontimeout (timers.js:386:14)
    at tryOnTimeout (timers.js:250:5)
    at Timer.listOnTimeout (timers.js:214:5) name: 'TimeoutError' }
{ TimeoutError: ResourceRequest timed out
    at ResourceRequest._fireTimeout (node_modules/generic-pool/lib/ResourceRequest.js:58:17)
    at Timeout.bound (node_modules/generic-pool/lib/ResourceRequest.js:8:15)
    at ontimeout (timers.js:386:14)
    at tryOnTimeout (timers.js:250:5)
    at Timer.listOnTimeout (timers.js:214:5) name: 'TimeoutError' }
{ TimeoutError: ResourceRequest timed out
    at ResourceRequest._fireTimeout (node_modules/generic-pool/lib/ResourceRequest.js:58:17)
    at Timeout.bound (node_modules/generic-pool/lib/ResourceRequest.js:8:15)
    at ontimeout (timers.js:386:14)
    at tryOnTimeout (timers.js:250:5)
    at Timer.listOnTimeout (timers.js:214:5) name: 'TimeoutError' }

You can see that, while the db server is originally running, the [ { '': 'connection is successful' } ] message is getting logged.
When I restart the container and the server is offline, SequelizeDatabaseError: Connection closed before request completed. is getting logged.
After the db server is back up from the container restart and Sequelize tries to send a new query, TimeoutError: ResourceRequest timed out gets logged from then on.

Here's my output with "sequelize": "github:codyseibert/sequelize#2e7ce2e52a5fff8c75b99bd400412fe56e891dbb", (the latest commit from the #8022 PR) installed in package.json:

 node db-test.js
Executing (default): SELECT 'connection is successful'
[ { '': 'connection is successful' } ]
Executing (default): SELECT 'connection is successful'
[ { '': 'connection is successful' } ]
{ SequelizeConnectionError
    at Connection.connection.on (node_modules/sequelize/lib/dialects/mssql/connection-manager.js:77:18)
    at emitNone (events.js:86:13)
    at Connection.emit (events.js:185:7)
    at Connection.cleanupConnection (node_modules/tedious/lib/connection.js:318:16)
    at Connection.enter (node_modules/tedious/lib/connection.js:1440:19)
    at Connection.transitionTo (node_modules/tedious/lib/connection.js:676:33)
    at Connection.socketEnd (node_modules/tedious/lib/connection.js:719:19)
    at emitNone (events.js:91:20)
    at Socket.emit (events.js:185:7)
    at endReadableNT (_stream_readable.js:974:12)
    at _combinedTickCallback (internal/process/next_tick.js:80:11)
    at process._tickCallback (internal/process/next_tick.js:104:9)
  name: 'SequelizeConnectionError',
  message: undefined,
  parent: 'Error connecting to the database',
  original: 'Error connecting to the database' }
{ TimeoutError: ResourceRequest timed out
    at ResourceRequest._fireTimeout (node_modules/generic-pool/lib/ResourceRequest.js:58:17)
    at Timeout.bound (node_modules/generic-pool/lib/ResourceRequest.js:8:15)
    at ontimeout (timers.js:386:14)
    at tryOnTimeout (timers.js:250:5)
    at Timer.listOnTimeout (timers.js:214:5) name: 'TimeoutError' }
{ SequelizeConnectionError
    at Connection.connection.on (node_modules/sequelize/lib/dialects/mssql/connection-manager.js:77:18)
    at emitNone (events.js:86:13)
    at Connection.emit (events.js:185:7)
    at Connection.cleanupConnection (node_modules/tedious/lib/connection.js:318:16)
    at Connection.enter (node_modules/tedious/lib/connection.js:1440:19)
    at Connection.transitionTo (node_modules/tedious/lib/connection.js:676:33)
    at Connection.socketEnd (node_modules/tedious/lib/connection.js:719:19)
    at emitNone (events.js:91:20)
    at Socket.emit (events.js:185:7)
    at endReadableNT (_stream_readable.js:974:12)
    at _combinedTickCallback (internal/process/next_tick.js:80:11)
    at process._tickCallback (internal/process/next_tick.js:104:9)
  name: 'SequelizeConnectionError',
  message: undefined,
  parent: 'Error connecting to the database',
  original: 'Error connecting to the database' }
Executing (default): SELECT 'connection is successful'
[ { '': 'connection is successful' } ]
Executing (default): SELECT 'connection is successful'
[ { '': 'connection is successful' } ]
Executing (default): SELECT 'connection is successful'
[ { '': 'connection is successful' } ]

You can see here that the connection is properly re-established after the db server is restarted

Hope that helps 👍

[joe-angell]

I am also experiencing this problem. I think bad connections are not getting removed from the pool and the pool is filling up. I get similar problems after a couple days in production.

[ghost]

Hi everyone,
same issues here.
I know we have an old database and get some timeout issues sometimes, but at some point it just doesn't reconnect anymore.

Would be great to have a solution.

[ansongoldade]

I'm dealing with this same issue as @joe-angell . App runs along flawlessly for a two to three days and then all of a sudden there are resources in the pool that are never being removed and acquire is always timing out when trying to access them. I am using the default pool configuration and I have metrics that are monitoring the pool values (min, max, size, available,borrowed, pending). I can see pool size increasing, decreasing and often reaching zero over the course of the day. This issue arises when the size value never returns to zero which seems to indicate that there are resources in the pool that acquire is always timing out on.

If there is something I can write in the validate function the pool calls I'm happy to do that as a way to handle this issue but it seems as though the validate function is never getting called when mssql connection get's into this state. This fact in combination with the fact that it's never being removed from the pool puts my app into a non recoverable state. The only way to stop getting these errors is to restart the application. Would love to have a better solution than that.

[joe-angell]

@ansongoldade yeah even with my own custom improved validation function i'm still getting timeouts from failing to acquire the connection. 8 events on one machine we deployed the fix to in the last 2 days out of a couple million requests... But it seems to recover afterwards now. So probably an uncaught exception somewhere that is not getting to stdout is my guess.

See this for the extreme validation function... note that connection.query will be null if the db goes down for any length of time.
sidorares/node-mysql2#447 (comment)

[Jackychans]

Updated to 4.22.5 but still run into the issue ResourceRequest timed out sometimes.

My pool config

dialect: 'mssql',
pool: {
max: 5,
min: 1,
idle: 20000,
evict: 20000,
acquire: 20000
},

Looking for advise :(

[joe-angell]

My colleague has made some progress identifying a possibly related error: #8756

[cladjules]

I believe that PR is fixing that issue.
#8022
How can we get that merged into the next release?

[iamjoyce]

For anyone else who needs a quick reference, npm install codyseibert/sequelize#bug/fixing_reconnect_after_db_restart --save

Although the version is a little outdated - e.g. there is no operatorsAliases / Sequelize.Op option.

[smithdalec]

@sushantdhiman I'm still able to reproduce this error with sequelize@4.33.1.
My workaround is still to target the changes from #8022 via codyseibert/sequelize#bug/fixing_reconnect_after_db_restart in my package.json

[cladjules]

@smithdalec @sushantdhiman Same for me, I am still having the same issue.
I have done some test with adding/removing my IP from the firewall.
Any further request, I cannot connect anymore even though the IP is back.

[sushantdhiman]

@cladjules @smithdalec How you are using that fix?, have you actually set proper retry config which catch connection errors? Something like #2113 (comment)

[cladjules]

Hi @sushantdhiman I have tried different configuration,
currently:

retry: {
        match: [
          /SequelizeConnectionError/,
          /SequelizeConnectionRefusedError/,
          /SequelizeHostNotFoundError/,
          /SequelizeHostNotReachableError/,
          /SequelizeInvalidConnectionError/,
          /SequelizeConnectionTimedOutError/,
          /TimeoutError/,
        ],
        name: 'query',
        backoffBase: 100,
        backoffExponent: 1.1,
        timeout: 15000,
        max: 5,
      },

I have also tried to configuration mentioned in the PR.
Connection takes ages and ends up with a Timeout.

Thanks.

[sushantdhiman]

I can still reproduce this issue, will investigate