sidorares / node-mysql2

:zap: fast mysqljs/mysql compatible mysql driver for node.js
https://sidorares.github.io/node-mysql2/
MIT License
4.07k stars 618 forks source link

connection.query callback never executed #202

Closed ghost closed 8 years ago

ghost commented 9 years ago

Hi, I'm working on app which download and process database. After downloading when I try to insert data in mysql on certain rounds program failing silently. I tracked problem to connection.query method from mysql2 library,even though query executed its callback never executed and program just exits.

Sometimes this problem not bother but other time can execute up to 20 times my app and it exits on very same round giving no error at all.

I'm working on Windows 8, node 0.12.7, mysql2 0.15.8.

I can't see any special about circumstances, it fails on query "USE my dbName" (have to do that several times cause otherwise get mysql error that database not chosen. Using pool = mysql.createPool() from mysql2).

Here is code:

`function addAndUpdateUsers(table,usersData,cb){

//console.log("addAndUpdateUsers");

if(utils.isItemsEmpty(usersData) === true){

    cb(null);

    return;

}

var currentRegistrationDate = Object.keys(usersData)[0];

var users = [];

console.log("before array");

for(var item in usersData[currentRegistrationDate]){

    users.push(usersData[currentRegistrationDate][item]);

}

console.log("before use");

connection.query("USE " + config.dbName, function(err,rows,field){

    if(err) console.log(err);

    console.log("after use");`

I can see log "before use", but don't see "after use".

Ready to give any additional info needed.

sidorares commented 9 years ago

could you try to create connection with debug: true flag?

ghost commented 9 years ago

I did. Got this piece of info before exit: Add command: query Sending query command: USE ssDataProxy 1 1125 <== query#start(0,,20)

sidorares commented 9 years ago

is that connection from pool? Looks like server closed connection but for some reason you are not getting callback with error

ghost commented 9 years ago

Yeah, connection from pool. Well anyway callback get lost somewhere on the way. How ti figure out where?

sidorares commented 9 years ago

try to debug if connection.on('error') handler present and what happens in that handler Looks like pool manager is marking connection as closed and removes from list of active connections but does not call callback

sidorares commented 9 years ago

console.log( connection.listeners('error') )

console.log( connection.listeners('error')[0].toString() )

ghost commented 9 years ago

Alright.

ghost commented 9 years ago

connection.listeners is undefined. Can find only two string in file connection.js:

stream.removeAllListeners('data'); mysql2/lib/connection.js:185 this.stream.removeAllListeners('data'); mysql2/lib/connection.js:265

Tracked problem further. Now in file mysql2/lib/commands/query.js

Query.prototype.start = function(packet, connection) { if (connection.config.debug) { console.log(' Sending query command: %s', this.query); } this._connection = connection; var cmdPacket = new Packets.Query(this.query); connection.writePacket(cmdPacket.toPacket(1)); console.log("Before Query.prototype.resultsetHeader"); return Query.prototype.resultsetHeader; };

I can see log "Before Query.prototype.resultsetHeader" but can't see log which follows as first command in that method.

sidorares commented 9 years ago

if connection is closed before data is sent from server Query.prototype.resultsetHeader is not called, this is expected. Could you put log here: https://github.com/sidorares/node-mysql2/blob/master/lib/connection.js#L101 and see if error is emitted (and if there is connection close et all)?

ghost commented 9 years ago

Added there log but don't see it. Seems app fails even before that. Also added log on stream.on('data') and on that bad round don't see this log either.

sidorares commented 9 years ago

so the process just exits without calling callback? Are you sure there is no process.exit() somewhere?

ghost commented 9 years ago

Myself only set console.log or console.dir in mysql2. And in my code absolutely sure there is no process.exit(); Also few times already (today) app managed to proceed that troubled round and continue executing next rounds.

sidorares commented 9 years ago

one more guess: could it be that proccess is killed with OOM killer? can you try to reproduce the problem running under strcace?

ghost commented 9 years ago

I work under Windows 8 and actually it does not eat all resources. Later rounds much more massive and working just fine. And what means running under strcace?

ghost commented 9 years ago

Got it!

on stream error log { [Error: read ECONNRESET] code: 'ECONNRESET', errno: 'ECONNRESET', syscall: 'read' }

added log mysql2/lib/connection.js:72

this.stream.on('error', function(err) { console.log("on stream error log"); console.log(err); connection.emit('error', err); });

sidorares commented 9 years ago

oops, meant strace(1) but that's not relevant for windows

sidorares commented 9 years ago

looks like current command callback is never called indeed if there is stream error

ghost commented 9 years ago

What can be done about that?

sidorares commented 9 years ago

Try "stream-error-callback" branch or just apply what I did in b7e296579dbd3549671c59b981c6eb9ef8f0d935 to your code. Previously only unexpected end was propagated as error to all commands as callback with error parameter, now also stream error

ghost commented 9 years ago

Thank you very much!

sidorares commented 9 years ago

I'll need to add tests before releasing this, but thank you for pointing in right direction!

ghost commented 9 years ago

Alright. Glad to help mysql2 project.

ghost commented 9 years ago

Another kind of error got on that place:

{ [Error: This socket has been ended by the other party] code: 'EPIPE' }