Seeing the pool randomly being destroyed after timeout

[tgriesser]

Not sure what's causing it and haven't had time to completely reproduce it, but the pool seems to be randomly being destroyed after a connect ETIMEDOUT - only seeing this recently so suspect it's something with the latest patch version.

I'll see about being able to reproduce it, but any ideas there?

[myndzi]

When you say "the pool is being destroyed", do you mean that knex reports it as destroyed or pool2 reports it as destroyed?

One thing I've observed in general, even with the previous pooler, is that "general problems/misconfigurations with connecting" in knex tend to wind up being reported as pool errors; this makes it hard to distinguish things sometimes.

The only call in the entire file that could initiate destruction of the pool itself is here:

https://github.com/myndzi/pool2/blob/master/lib/pool.js#L410

I believe we talked a little bit about this one before: the purpose is to throw an error if the pool receives an error trying to acquire its first resource(s), so that invalid instantiation/configuration causes a crash error instead of silently getting swallowed in an infinite invalid reconnect loop.

Once it has successfully acquired at least one resource, it is assumed that the configuration is valid, and this behavior is disabled, controlled by pool.live being set to true. The only place that happens is in the constructor.

So, if pool2 is reporting a 'destroyed' error, it would have to be 'failed to ever acquire any resource', or something external is calling the _destroyPool method (.end should be preferred, though perhaps it should fall back to destroy or export this method directly if we don't care about or can't clean up nicely).

If knex is reporting a 'destroyed' error, well, you'd know more about that one than I :)

[myndzi]

I just got something like this while doing some work, is this what you were referring to?

Knex:Error Pool2 - Error: connect ECONNREFUSED
Knex:Error Pool2 - Error: connect ECONNREFUSED
Error: Pool was destroyed

[tgriesser]

Yep

[myndzi]

Yeah, that's basically "the settings were wrong and I couldn't connect, ever"

[tgriesser]

Oh wait sorry it was ETIMEDOUT not ECONNREFUSED. I'm traveling right now but will take a look when I get back tomorrow

[myndzi]

Same thing, different error. ETIMEDOUT would be "settings were wrong" or possibly "network connectivity bombed while this thing tried to start up"

[myndzi]

Any news on this? If it's not an initial time out it might also be related to #14.

[dvp0]

I really hope @tgriesser or @myndzi can help me out with this.

PROBLEM
I have a hapi/bookshelf/knex(everything latest) setup where all the settings are to default.
Now when my rest api fails to connect to DB (RDS based postgres) it ETIMEDOUT s and destroys the pool after 1 minute. Second consecutive requests fails with "Pool is destroyed" error after 1 minute.

CONSOLE

hapi server started
sdfd
Knex:Error Pool2 - Error: Timed out acquiring resource
Unhandled rejection Error: Pool was destroyed
at Pool._destroyPool (/Users/hiral/projects/personal/rx-api/node_modules/knex/node_modules/pool2/lib/pool.js:487:16)
at Pool. (/Users/hiral/projects/personal/rx-api/node_modules/knex/node_modules/pool2/lib/pool.js:410:18)
at Pool. (/Users/hiral/projects/personal/rx-api/node_modules/knex/node_modules/pool2/lib/pool.js:421:13)
at Timer.listOnTimeout as ontimeout
Knex:Error Pool2 - Error: Timed out acquiring resource
Debug: request, closed, error
Knex:Error Pool2 - Error: connect ETIMEDOUT
Knex:Error Pool2 - Error: connect ETIMEDOUT
sdfd
Unhandled rejection Error: Pool is destroyed
at Pool.acquire (/Users/hiral/projects/personal/rx-api/node_modules/knex/node_modules/pool2/lib/pool.js:149:12)
at /Users/hiral/projects/personal/rx-api/node_modules/knex/lib/client.js:204:19
at tryCatcher (/Users/hiral/projects/personal/rx-api/node_modules/knex/node_modules/bluebird/js/main/util.js:24:31)
at Promise._resolveFromResolver (/Users/hiral/projects/personal/rx-api/node_modules/knex/node_modules/bluebird/js/main/promise.js:427:31)
at new Promise (/Users/hiral/projects/personal/rx-api/node_modules/knex/node_modules/bluebird/js/main/promise.js:53:37)
at Client.acquireConnection (/Users/hiral/projects/personal/rx-api/node_modules/knex/lib/client.js:200:12)
at /Users/hiral/projects/personal/rx-api/node_modules/knex/lib/runner.js:138:49
at tryCatcher (/Users/hiral/projects/personal/rx-api/node_modules/knex/node_modules/bluebird/js/main/util.js:24:31)
at Function.Promise.attempt.Promise.try (/Users/hiral/projects/personal/rx-api/node_modules/knex/node_modules/bluebird/js/main/method.js:31:24)
at Runner.ensureConnection (/Users/hiral/projects/personal/rx-api/node_modules/knex/lib/runner.js:137:26)
at Runner.run (/Users/hiral/projects/personal/rx-api/node_modules/knex/lib/runner.js:30:31)
at QueryBuilder.Target.then (/Users/hiral/projects/personal/rx-api/node_modules/knex/lib/interface.js:27:43)
at QueryBuilder.tryCatcher (/Users/hiral/projects/personal/rx-api/node_modules/bookshelf/node_modules/bluebird/js/main/util.js:24:31)
at doThenable (/Users/hiral/projects/personal/rx-api/node_modules/bookshelf/node_modules/bluebird/js/main/thenables.js:52:38)
at tryConvertToPromise (/Users/hiral/projects/personal/rx-api/node_modules/bookshelf/node_modules/bluebird/js/main/thenables.js:30:20)
at Promise._resolveCallback (/Users/hiral/projects/personal/rx-api/node_modules/bookshelf/node_modules/bluebird/js/main/promise.js:389:24)
at Promise._settlePromiseFromHandler (/Users/hiral/projects/personal/rx-api/node_modules/bookshelf/node_modules/bluebird/js/main/promise.js:462:17)
at Promise._settlePromiseAt (/Users/hiral/projects/personal/rx-api/node_modules/bookshelf/node_modules/bluebird/js/main/promise.js:530:18)
at Promise._settlePromises (/Users/hiral/projects/personal/rx-api/node_modules/bookshelf/node_modules/bluebird/js/main/promise.js:646:14)
at Promise.b (domain.js:183:18)
at Async._drainQueue (/Users/hiral/projects/personal/rx-api/node_modules/bookshelf/node_modules/bluebird/js/main/async.js:182:12)
at Async._drainQueues (/Users/hiral/projects/personal/rx-api/node_modules/bookshelf/node_modules/bluebird/js/main/async.js:187:10)
at Async.drainQueues (/Users/hiral/projects/personal/rx-api/node_modules/bookshelf/node_modules/bluebird/js/main/async.js:15:14)
at process._tickDomainCallback (node.js:463:13)

QUESTIONS

@myndzi Is there anyway I can recreate the pool (pretty newbie when comes to this stuff) whne destroyed so when the DB comes back up again it start acting normal? Any additional settings I need to set on knex/ pool2 config ?

@tgriesser Proper place to handle this exception in bookshelf to respond safely ?

[myndzi]

Can you clarify: does this happen when you start your application if the DB is inaccessible, or does this happen after your application has been running and working, but loses connection to the db? If the former, I have a patch to allow you to configure this behavior, I will probably just publish it shortly. I wanted to make sure I had a chance to catch tgriesser before pushing it out.

You can try installing the version of pool2 from master on this repository instead of the one installed with knex, and setting the 'bailAfter' option to something large enough to encompass the expected downtime.

[acgourley]

Just chiming in that I'm having this issue against mysql using bookshelf.

The application runs for a while, then a stack like this occurs:

 2015-08-27 00:49:09.000 Knex:Error Pool2 - Error: Pool.release(): Resource not member of pool
 2015-08-27 00:49:09.000 Error: read ETIMEDOUT
 2015-08-27 00:49:09.000 at exports._errnoException (util.js:746:11)
 2015-08-27 00:49:09.000 at TCP.onread (net.js:559:26)
 2015-08-27 00:49:09.000 --------------------
 2015-08-27 00:49:09.000 at Protocol._enqueue (/app/node_modules/mysql/lib/protocol/Protocol.js:135:48)
 2015-08-27 00:49:09.000 at Connection.query (/app/node_modules/mysql/lib/Connection.js:201:25)
 2015-08-27 00:49:09.000 at /app/node_modules/knex/lib/dialects/mysql/index.js:92:18
 2015-08-27 00:49:09.000 at tryCatcher (/app/node_modules/bluebird/js/main/util.js:26:23)
 2015-08-27 00:49:09.000 at Promise._resolveFromResolver (/app/node_modules/bluebird/js/main/promise.js:476:31)
 2015-08-27 00:49:09.000 at new Promise (/app/node_modules/bluebird/js/main/promise.js:69:37)
 2015-08-27 00:49:09.000 at Client._query (/app/node_modules/knex/lib/dialects/mysql/index.js:88:12)
 2015-08-27 00:49:09.000 at Client.query (/app/node_modules/knex/lib/client.js:127:24)
 2015-08-27 00:49:09.000 at Runner.<anonymous> (/app/node_modules/knex/lib/runner.js:118:24)
 2015-08-27 00:49:09.000 at Runner.tryCatcher (/app/node_modules/bluebird/js/main/util.js:26:23)
 2015-08-27 00:49:09.000 at Runner.query (/app/node_modules/bluebird/js/main/method.js:15:34)
 2015-08-27 00:49:09.000 at /app/node_modules/knex/lib/runner.js:44:21
 2015-08-27 00:49:09.000 at /app/node_modules/bluebird/js/main/using.js:165:30
 2015-08-27 00:49:09.000 at tryCatcher (/app/node_modules/bluebird/js/main/util.js:26:23)
 2015-08-27 00:49:09.000 at Promise._settlePromiseFromHandler (/app/node_modules/bluebird/js/main/promise.js:503:31)
 2015-08-27 00:49:09.000 at Promise._settlePromiseAt (/app/node_modules/bluebird/js/main/promise.js:577:18)
 2015-08-27 00:49:09.000 at Promise._settlePromises (/app/node_modules/bluebird/js/main/promise.js:693:14)
 2015-08-27 00:49:09.000 at Async._drainQueue (/app/node_modules/bluebird/js/main/async.js:123:16)
 2015-08-27 00:49:09.000 at Async._drainQueues (/app/node_modules/bluebird/js/main/async.js:133:10)
 2015-08-27 00:49:09.000 at Immediate.Async.drainQueues [as _onImmediate] (/app/node_modules/bluebird/js/main/async.js:15:14)
 2015-08-27 00:49:09.000 at processImmediate [as _immediateCallback] (timers.js:367:17)

[myndzi]

What version of pool2 is currently installed? (npm ls pool2)
Also, what version of knex?

[myndzi]

Ah, I think I see the problem. acquireRawConnection is returning a promise, however the error handler is attempting to destroy the connection object.

Alternately, it might be trying to release even after an error causes the resource to be destroyed. I can't see how that error would result from the connection error handler in knex, since it calls pool.destroy

[dvp0]

@myndzi I have knex 0.8.6 and with that pool2 1.1.0. Sorry for not replying earlier, notification email was lost in thousand other from work github.

[dvp0]

@myndzi
Recently I have seen that one particular connection was refused mostly only first time after long rest. I rerun it and it is fine. After couple of hours/days happens again. I compared the actual query knex was executing (through debug mode) and it is exact similar to consecutive success query. I am still debugging and it could be knex issue too, but I thought it might help.

[myndzi]

Refused the first time after a long rest = a timeout; pool2 was designed to throw an error if the first attempted connection fails. You could update to 1.2.0 to control some of this behavior if you desire, but there shouldn't be anything that changes functionally. This error is probably safe to ignore, unless knex is destroying the pool because of it, which it should not do. I'll try and reproduce a timed out query using knex and see if I can produce this problem and run it down.