myndzi
Seeing the pool randomly being destroyed after timeout
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?
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 :)
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
Yeah, that's basically "the settings were wrong and I couldn't connect, ever"
Oh wait sorry it was ETIMEDOUT not ECONNREFUSED. I'm traveling right now but will take a look when I get back tomorrow
Same thing, different error. ETIMEDOUT would be "settings were wrong" or possibly "network connectivity bombed while this thing tried to start up"
Any news on this? If it's not an initial time out it might also be related to #14.
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.
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 ?
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.
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)
What version of pool2 is currently installed? (npm ls pool2)
Also, what version of knex?
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
@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.
@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.
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.
My error was with pool2 1.1.6 and knex 0.8.6
Any update on this issue? Thanks for all your work here both @myndzi and @tgriesser
Apologies, I've gotten quite busy at work and didn't do what I said I would do to look into this. I would appreciate it if you could tell me if it appears to be a cosmetic problem (reporting an error but not affecting your application) or an actual functional problem, because I think the chance is strong it's the former. If it's the latter, I'll make it a priority to address it.
The unfortunate nature of this kind of error is that, since pool2 is involved at such a core level, any connection "stuff" that happens is going to have pool2's "name" attached to it -- but in a number of cases, these are situations pool2 is built to deal with; the message may simply be getting passed along when it would be better ignored.
Thanks for the reply - in my case it is serious because it crashes the node instance and I cannot figure out how to catch the exception in my code.
If what you are saying is correct, the quickest fix may be for knex to report the exception without propagating it. @tgriesser what do you think?
If it's crashing, then it's not being caught at all.. but the "Knex:Error" part gets added by knex so it must obviously be captured...? I recommend in the short term trying to find out what the error is being emitted on (the knex object?) and binding it. I'm sorry for letting this linger.
Okay! I managed to reproduce the error scenario by hooking into net.Socket and "eating" a selected write while emitting an error on the socket object. However, the application does not crash for me. I am using the same versions of knex and pool2 that you are. Can you please give the following code a try?
'use strict';
var Socket = require('net').Socket;
var writeCount = 0, readCount = 0;
var connect = Socket.prototype.connect;
var write = Socket.prototype.write;
var target;
Socket.prototype.write = function (chunk, encoding, cb) {
if (this !== process.stdout) {
console.log('write', writeCount++);
if (writeCount === 3) {
this.emit('error', new Error('foo'));
return;
}
}
return write.call(this, chunk, encoding, cb);
};
Socket.prototype.connect = function (options, cb) {
return connect.call(this, options, function (err, socket) {
console.log('got socket');
target = socket;
this.on('data', function () {
console.log('read', readCount++);
});
if (typeof cb === 'function') { cb(); }
});
};
var knex = require('knex')({
client: 'mysql',
connection: {
database: 'test'
},
pool: {
max: 1,
min: 1
}
});
function ping() {
return knex.select(knex.raw(1));
}
ping()
.then(function () {
console.log('ping 1 returned');
return ping();
})
.then(function () {
console.log('ping 2 returned');
})
.catch(function (e) {
console.error(e);
return ping();
})
.then(function () {
console.log('ping 3 returned');
});
My output looks like this:
got socket
write 0
read 0
read 1
write 1
read 2
ping 1 returned
write 2
Knex:Error Pool2 - Error: Pool.release(): Resource not member of pool
write 3
{ [Error: select 1 - foo] fatal: true }
got socket
write 4
read 3
read 4
write 5
read 5
ping 3 returned
^C
Be sure to adjust the connection parameters to a valid database. You will note that the third ping is executed after receiving the error, and that it succeeds, showing that the socket error case is handled correctly except for the fact that knex is likely double-releasing the resource or something, causing an error to be displayed that shouldn't.
We can see the double release here:
knex:client acquiring connection from pool: __knexUid1 +0ms
knex:query select 1 +1ms
write 2
pool2 Ungracefully destroying resource (id=0) +3ms
pool2 Attempting to acquire minimum resources (cur=0, min=1) +1ms
pool2 Attempting to acquire resource (cur=0, ac=0) +0ms
knex:client releasing connection to pool: __knexUid1 +3ms
Knex:Error Pool2 - Error: Pool.release(): Resource not member of pool
With a stack dump, it is revealed that the first release comes from here:
pool2 Ungracefully destroying resource (id=0) +3ms
Error
at Pool.destroy (/home/myndzi/pool2-issue-12/node_modules/knex/node_modules/pool2/lib/pool.js:204:16)
at connectionErrorHandler (/home/myndzi/pool2-issue-12/node_modules/knex/lib/dialects/mysql/index.js:133:17)
-> https://github.com/tgriesser/knex/blob/0.8.6/lib/dialects/mysql/index.js#L133
My original suspicion appears to be correct: the error handler destroys the resource, but the promise cleanup is attempting to release it even though there was an error:
-> https://github.com/tgriesser/knex/blob/0.8.6/lib/runner.js#L140
I'm not entirely sure how to cleanly address this; ideally the disposer would be aware of the error case and destroy the resource there instead of in the other place. Alternately, it could not attempt to release the connection if it had an error, or trap the error case and ignore it.
Fix turned out to be somewhat easy (though still a little messy) since there was already a property I could check to know if the connection had been disposed of. You can use npm install git+https://github.com/myndzi/knex#double-release to test with your app and verify that everything is working better until the fix makes its way into an NPM release.
I'm still uncertain why your application was exiting due to this error, perhaps this is programmed behavior on your part? (bound an error event and died when you didn't need to?) -- so if the problem continues for some reason, or your program still exits, do get back to me and let's dig in further.
I just wanted to post the log as I finally got the error to occur with DEBUG=pool2 on. I'm going to try your fix right now in parallel.
...
Sat, 12 Sep 2015 15:36:52 GMT pool2 Allocating resource (id=38) to request; waited 0s\n
Sat, 12 Sep 2015 15:36:52 GMT pool2 Pinging resource (id=38)\n
Sat, 12 Sep 2015 15:36:52 GMT pool2 Reserving request for resource (id=38)\n
Sat, 12 Sep 2015 15:36:55 GMT pool2 Successfully allocated new resource (cur=5, ac=0, id=39)\n
at processImmediate [as _immediateCallback] (timers.js:367:17)\n
at Immediate.Async.drainQueues [as _onImmediate] (/app/node_modules/bluebird/js/main/async.js:15:14)\n
at Async._drainQueues (/app/node_modules/bluebird/js/main/async.js:133:10)\n
at Async._drainQueue (/app/node_modules/bluebird/js/main/async.js:123:16)\n
at Promise._settlePromises (/app/node_modules/bluebird/js/main/promise.js:697:14)\n
at Promise._settlePromiseAt (/app/node_modules/bluebird/js/main/promise.js:581:18)\n
at Promise._settlePromiseFromHandler (/app/node_modules/bluebird/js/main/promise.js:507:31)\n
at tryCatcher (/app/node_modules/bluebird/js/main/util.js:26:23)\n
at /app/node_modules/bluebird/js/main/using.js:176:36\n
at /app/node_modules/knex/lib/runner.js:44:21\n
at Runner.query (/app/node_modules/bluebird/js/main/method.js:15:34)\n
at Runner.tryCatcher (/app/node_modules/bluebird/js/main/util.js:26:23)\n
at Runner.<anonymous> (/app/node_modules/knex/lib/runner.js:118:24)\n
at Client.query (/app/node_modules/knex/lib/client.js:127:24)\n
at Client._query (/app/node_modules/knex/lib/dialects/mysql/index.js:88:12)\n
at new Promise (/app/node_modules/bluebird/js/main/promise.js:70:37)\n
at Promise._resolveFromResolver (/app/node_modules/bluebird/js/main/promise.js:480:31)\n
at tryCatcher (/app/node_modules/bluebird/js/main/util.js:26:23)\n
at /app/node_modules/knex/lib/dialects/mysql/index.js:92:18\n
at Connection.query (/app/node_modules/mysql/lib/Connection.js:201:25)\n
at Protocol._enqueue (/app/node_modules/mysql/lib/protocol/Protocol.js:135:48)\n
--------------------\n
at TCP.onread (net.js:559:26)\n
at exports._errnoException (util.js:746:11)\n
Error: read ETIMEDOUT\n
at processImmediate [as _immediateCallback] (timers.js:367:17)\n
at Immediate.Async.drainQueues [as _onImmediate] (/app/node_modules/bluebird/js/main/async.js:15:14)\n
at Async._drainQueues (/app/node_modules/bluebird/js/main/async.js:133:10)\n
at Async._drainQueue (/app/node_modules/bluebird/js/main/async.js:123:16)\n
at Promise._settlePromises (/app/node_modules/bluebird/js/main/promise.js:697:14)\n
at Promise._settlePromiseAt (/app/node_modules/bluebird/js/main/promise.js:581:18)\n
at Promise._settlePromiseFromHandler (/app/node_modules/bluebird/js/main/promise.js:507:31)\n
at tryCatcher (/app/node_modules/bluebird/js/main/util.js:26:23)\n
at /app/node_modules/bluebird/js/main/using.js:176:36\n
at /app/node_modules/knex/lib/runner.js:44:21\n
at Runner.query (/app/node_modules/bluebird/js/main/method.js:15:34)\n
at Runner.tryCatcher (/app/node_modules/bluebird/js/main/util.js:26:23)\n
at Runner.<anonymous> (/app/node_modules/knex/lib/runner.js:118:24)\n
at Client.query (/app/node_modules/knex/lib/client.js:127:24)\n
at Client._query (/app/node_modules/knex/lib/dialects/mysql/index.js:88:12)\n
at new Promise (/app/node_modules/bluebird/js/main/promise.js:70:37)\n
at Promise._resolveFromResolver (/app/node_modules/bluebird/js/main/promise.js:480:31)\n
at tryCatcher (/app/node_modules/bluebird/js/main/util.js:26:23)\n
at /app/node_modules/knex/lib/dialects/mysql/index.js:92:18\n
at Connection.query (/app/node_modules/mysql/lib/Connection.js:201:25)\n
at Protocol._enqueue (/app/node_modules/mysql/lib/protocol/Protocol.js:135:48)\n
--------------------\n
at TCP.onread (net.js:559:26)\n
at exports._errnoException (util.js:746:11)\n
Top level error handling in API saw: Error: read ETIMEDOUT\n
Knex:Error Pool2 - Error: Pool.release(): Resource not member of pool\n
Sat, 12 Sep 2015 15:36:55 GMT pool2 Attempting to acquire resource (cur=5, ac=0)\n
Sat, 12 Sep 2015 15:36:55 GMT pool2 Attempting to acquire minimum resources (cur=5, min=6)\n
Sat, 12 Sep 2015 15:36:55 GMT pool2 Ungracefully destroying resource (id=37)\n
...
To clarify my crash issue - it was what Express decides to do when it has an unhanded exception when no error handler is defined. By defining an error handler I was able to stop the app from crashing (although the requests still failed as a result of this bug)
Express doesn't do that, node does -- but when I reproduced the error, it was not an unhandled error event -- I didn't bind a handler, but it did not appear to be emitted on any object without an error handler. So, if it's being re-emitted somewhere or not bound somewhere, that may be in the purview of your app and not knex. I'm uncertain.
The requests themselves will fail anyway; this is not inherently a bug that causes requests to fail -- it's the opposite. A network problem (timeout on reading from socket) causes the request to fail, and this occurs as a result of that. There is no way to recover the request other than to re-issue it, which would be either knex's job, or your job in response to a failed query. If the error isn't getting passed back to your query, that's something that should hopefully be fixed in knex, so that you have the ability to see that "this query failed because the underlying network socket died, so I can probably retry it" and do so if you so choose.
The stack dump after "Sat, 12 Sep 2015 15:36:55 GMT pool2 Successfully allocated new resource (cur=5, ac=0, id=39)" -- did you add that?
Thank you for the stack dump, too. Strangely, it seems to maybe not be the same problem, although sourced through the same files and for the same reason. I see the attempted release, but not the destroy as triggered by the connection error handler in the mysql client file. I'll have to dig a little deeper, but this supports the unhandled error scenario.
While you're testing with the new code, tack knex:* onto your debug line if you want a little more info on what knex itself is doing:
DEBUG=knex:*,pool2 node ...
You know what, do you have Skype? I have time this weekend and could get on a call so we could cut out all the back and forth...
(Add me: myndzi, the one in NC)
It does seem like your patch does not fix this issue :(
Here's a new log using the double released tag.
...
A gae-default-20150912t112337-iirf 2015-09-12 17:47:16.000 Sun, 13 Sep 2015 00:47:16 GMT pool2 Ungracefully destroying resource (id=7)
A gae-default-20150912t112337-iirf 2015-09-12 17:47:16.000 Sun, 13 Sep 2015 00:47:16 GMT pool2 Attempting to acquire minimum resources (cur=5, min=6)
A gae-default-20150912t112337-iirf 2015-09-12 17:47:16.000 Sun, 13 Sep 2015 00:47:16 GMT pool2 Attempting to acquire resource (cur=5, ac=0)
A gae-default-20150912t112337-iirf 2015-09-12 17:47:16.000 API ERROR: Error: read ETIMEDOUT
A gae-default-20150912t112337-iirf 2015-09-12 17:47:16.000 at exports._errnoException (util.js:746:11)
A gae-default-20150912t112337-iirf 2015-09-12 17:47:16.000 at TCP.onread (net.js:559:26)
A gae-default-20150912t112337-iirf 2015-09-12 17:47:16.000 --------------------
A gae-default-20150912t112337-iirf 2015-09-12 17:47:16.000 at Protocol._enqueue (/app/node_modules/mysql/lib/protocol/Protocol.js:135:48)
A gae-default-20150912t112337-iirf 2015-09-12 17:47:16.000 at Connection.query (/app/node_modules/mysql/lib/Connection.js:201:25)
A gae-default-20150912t112337-iirf 2015-09-12 17:47:16.000 at /app/node_modules/knex/lib/dialects/mysql/index.js:92:18
A gae-default-20150912t112337-iirf 2015-09-12 17:47:16.000 at tryCatcher (/app/node_modules/bluebird/js/main/util.js:26:23)
A gae-default-20150912t112337-iirf 2015-09-12 17:47:16.000 at Promise._resolveFromResolver (/app/node_modules/bluebird/js/main/promise.js:480:31)
A gae-default-20150912t112337-iirf 2015-09-12 17:47:16.000 at new Promise (/app/node_modules/bluebird/js/main/promise.js:70:37)
A gae-default-20150912t112337-iirf 2015-09-12 17:47:16.000 at Client._query (/app/node_modules/knex/lib/dialects/mysql/index.js:88:12)
A gae-default-20150912t112337-iirf 2015-09-12 17:47:16.000 at Client.query (/app/node_modules/knex/lib/client.js:127:24)
A gae-default-20150912t112337-iirf 2015-09-12 17:47:16.000 at Runner.<anonymous> (/app/node_modules/knex/lib/runner.js:116:24)
A gae-default-20150912t112337-iirf 2015-09-12 17:47:16.000 at Runner.tryCatcher (/app/node_modules/bluebird/js/main/util.js:26:23)
A gae-default-20150912t112337-iirf 2015-09-12 17:47:16.000 at Runner.query (/app/node_modules/bluebird/js/main/method.js:15:34)
A gae-default-20150912t112337-iirf 2015-09-12 17:47:16.000 at /app/node_modules/knex/lib/runner.js:44:21
A gae-default-20150912t112337-iirf 2015-09-12 17:47:16.000 at /app/node_modules/bluebird/js/main/using.js:176:36
A gae-default-20150912t112337-iirf 2015-09-12 17:47:16.000 at tryCatcher (/app/node_modules/bluebird/js/main/util.js:26:23)
A gae-default-20150912t112337-iirf 2015-09-12 17:47:16.000 at Promise._settlePromiseFromHandler (/app/node_modules/bluebird/js/main/promise.js:507:31)
A gae-default-20150912t112337-iirf 2015-09-12 17:47:16.000 at Promise._settlePromiseAt (/app/node_modules/bluebird/js/main/promise.js:581:18)
A gae-default-20150912t112337-iirf 2015-09-12 17:47:16.000 at Promise._settlePromises (/app/node_modules/bluebird/js/main/promise.js:697:14)
A gae-default-20150912t112337-iirf 2015-09-12 17:47:16.000 at Async._drainQueue (/app/node_modules/bluebird/js/main/async.js:123:16)
A gae-default-20150912t112337-iirf 2015-09-12 17:47:16.000 at Async._drainQueues (/app/node_modules/bluebird/js/main/async.js:133:10)
A gae-default-20150912t112337-iirf 2015-09-12 17:47:16.000 at Immediate.Async.drainQueues [as _onImmediate] (/app/node_modules/bluebird/js/main/async.js:15:14)
A gae-default-20150912t112337-iirf 2015-09-12 17:47:16.000 at processImmediate [as _immediateCallback] (timers.js:367:17)
A gae-default-20150912t112337-iirf 2015-09-12 17:47:16.000 Sun, 13 Sep 2015 00:47:16 GMT pool2 Successfully allocated new resource (cur=5, ac=0, id=23)
...