sidorares / node-mysql2

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

Unhandled 'error' event #604

Closed leearmstrong closed 7 years ago

leearmstrong commented 7 years ago

I just switched to using mysql2 so I can get promise support but have an issue with pools that I didn't have before when using mysql.

I have the following code...

const tempPool = mysql.createPool({
                    host: this.configuration[i].server,
                    user: this.credentials.user,
                    password: this.credentials.password,
                    database: 'testDB',
                    connectionLimit: connectionLimit,
                    debug: false,
                    timezone: 'utc',
                    supportBigNumbers: true,
                    bigNumberStrings: true
                });

                _this.databaseConnections[name] = tempPool;

                tempPool.getConnection().then(function (connection) {
                    connection.release();
                }).catch(function (err) {
                    console.log(err);
                });

This creates a pool, a quick connect to test and then waits. If the mySQL server restarts once connected I get the following error.

events.js:182
      throw er; // Unhandled 'error' event
      ^

Error: Connection lost: The server closed the connection.
    at Socket.<anonymous> (/Users/me/Documents/code/node-archiver/node_modules/mysql2/lib/connection.js:113:35)
    at emitNone (events.js:110:20)
    at Socket.emit (events.js:207:7)
    at endReadableNT (_stream_readable.js:1047:12)
    at _combinedTickCallback (internal/process/next_tick.js:102:11)
    at process._tickCallback (internal/process/next_tick.js:161:9)

I have tried attaching an error event handler to tempPool but still get the unhandled error exception.

Any ideas where I need to add the handler!?

sidorares commented 7 years ago

the code looks right. what's in your connection limit? Also if you set debug connection flag to true it will enable verbose logging from driver

leearmstrong commented 7 years ago

50 is in the connection limit, I have just used this standalone example to replicate without all my code around it and still get it.

const mysql = require('mysql2/promise');

var db_config = {
    host: "localhost",
    user: "test",
    password: "test",
    database: 'mysql',
    connectionLimit: 50,
    debug: true,
    timezone: 'utc',
    supportBigNumbers: true,
    bigNumberStrings: true
};

var tempPool = mysql.createPool(db_config);

tempPool.getConnection().then(function (connection) {
    connection.release();
}).catch(function (err) {
    console.log(err);
});

console.log("Waiting for stuff....");

With debug set to true this is the log... The unhandled exception happens shortly after a stop of the MySQL service. Hopefully you can replicate this also

Add command: Connection
Waiting for stuff....
 raw: 0a352e362e33350005000000265d212a5035563200fff72102007f801500000000000000000000375a42785a3a526d5026695f006d7973716c5f6e61746976655f70617373776f726400
Trace
    at PoolConnection.Connection.handlePacket (/Users/leearmstrong/node_modules/mysql2/lib/connection.js:470:15)
    at PacketParser.onPacket (/Users/leearmstrong/node_modules/mysql2/lib/connection.js:94:16)
    at PacketParser.executeStart (/Users/leearmstrong/node_modules/mysql2/lib/packet_parser.js:77:14)
    at Socket.<anonymous> (/Users/leearmstrong/node_modules/mysql2/lib/connection.js:102:29)
    at emitOne (events.js:115:13)
    at Socket.emit (events.js:210:7)
    at addChunk (_stream_readable.js:252:12)
    at readableAddChunk (_stream_readable.js:239:11)
    at Socket.Readable.push (_stream_readable.js:197:10)
    at TCP.onread (net.js:589:20)
0 undefined ==> Connection#handshakeInit(0,,78)
Server hello packet: capability flags:2155870207=(long password, found rows, long flag, connect with db, no schema, compress, odbc, local files, ignore space, protocol 41, interactive, ignore sigpipe, transactions, reserved, secure connection, multi statements, multi results, ps multi results, plugin auth, connect attrs, plugin auth lenenc client data, can handle expired passwords, remember options)
Sending handshake packet: flags:8582095=(long password, found rows, long flag, connect with db, odbc, local files, ignore space, protocol 41, ignore sigpipe, transactions, reserved, secure connection, multi results, session track)
0 5 <== Connection#handshakeInit(1,,68)
0 5 <== 40000001cff3820000000000e000000000000000000000000000000000000000000000007465737400143304a74c80fc927f595793d27da2c375639d56296d7973716c00
 raw: 00000002000000
Trace
    at PoolConnection.Connection.handlePacket (/Users/leearmstrong/node_modules/mysql2/lib/connection.js:470:15)
    at PacketParser.onPacket (/Users/leearmstrong/node_modules/mysql2/lib/connection.js:94:16)
    at PacketParser.executeStart (/Users/leearmstrong/node_modules/mysql2/lib/packet_parser.js:77:14)
    at Socket.<anonymous> (/Users/leearmstrong/node_modules/mysql2/lib/connection.js:102:29)
    at emitOne (events.js:115:13)
    at Socket.emit (events.js:210:7)
    at addChunk (_stream_readable.js:252:12)
    at readableAddChunk (_stream_readable.js:239:11)
    at Socket.Readable.push (_stream_readable.js:197:10)
    at TCP.onread (net.js:589:20)
0 5 ==> Connection#handshakeResult(2,maybeOK,11)
events.js:182
      throw er; // Unhandled 'error' event
      ^

Error: Connection lost: The server closed the connection.
    at Socket.<anonymous> (/Users/leearmstrong/node_modules/mysql2/lib/connection.js:113:35)
    at emitNone (events.js:110:20)
    at Socket.emit (events.js:207:7)
    at endReadableNT (_stream_readable.js:1047:12)
    at _combinedTickCallback (internal/process/next_tick.js:102:11)
    at process._tickCallback (internal/process/next_tick.js:161:9)
sidorares commented 7 years ago

I'm afraid this is type of error you have to handle in your app

While pool tries to remove connection when there is 'fatal error' ( underlying socket closed etc ) sometimes it does not get notified about that and you see error in the query callback after timeout

This is expected in case of total radio silence from mysql server ( there is no way to know if it's down except for timing out ) However on my windows machine I don't even see 'error' event on node net stream when I turn off wifi or eject ethernect cable

Possible work around is to add 'heartbeat' to your pool ( setInterval on on 'connect' event and stop when connection closed) so that timeout error triggered early and connection removed from pool

leearmstrong commented 7 years ago

I would handle in my app if I could attach to an error event handler which it doesn't seem possible to do in mysql2?

Using mysql the following code doesn't error at all when the sql server goes away.

const mysql = require('mysql');

var db_config = {
    host: "localhost",
    user: "test",
    password: "test",
    database: 'mysql',
    connectionLimit: 1,
    debug: false,
    timezone: 'utc',
    supportBigNumbers: true,
    bigNumberStrings: true
};

var tempPool = mysql.createPool(db_config);

tempPool.getConnection(function(err, connection) {
    // connected! (unless `err` is set) 
    if (err){
        console.log(err);
    }else{
       connection.release(); 
    }
});

console.log("Waiting for stuff....");

My test is restarting the mysql service, I am not pulling a cable or network. Simply stopping the mysql server process.

Like I said, happy to handle the logic in my app but I can't seem to attach to an error event to then handle it which then panics node

sidorares commented 7 years ago

Do you see same behaviour if you use non-promise mysql2 client similar to your last example?

const mysql = require('mysql2');

var db_config = {
    host: "localhost",
    user: "test",
    password: "test",
    database: 'mysql',
    connectionLimit: 1,
    debug: false,
    timezone: 'utc',
    supportBigNumbers: true,
    bigNumberStrings: true
};

var tempPool = mysql.createPool(db_config);

tempPool.getConnection(function(err, connection) {
    // connected! (unless `err` is set) 
    if (err){
        console.log(err);
    }else{
       connection.release(); 
    }
});

console.log("Waiting for stuff....");
leearmstrong commented 7 years ago

Good point, sorry I had not tried that before!

So I ran the code and no unhandled exception error at all and the script as you would expect (and same behaviour as "mysql") is that the script ends without an error.

sidorares commented 7 years ago

ok I assume there might be a bug in a way promise wrapper handles pool errors, I'll try to Isolate that ( if you happen to discover anything before me feel free to add more info! )

leearmstrong commented 7 years ago

Yeah sure no problem, I'd love to help with the debugging if at all possible, if you can offer any advice on where to look I will have a go!

I wonder if it's somewhere in pool.js where it doesn't handle the 'error' exception but not sure why it works in the non promise model.

I'll give it some time today as I'd really like to get this solved :D

leearmstrong commented 7 years ago

Ok so far I have seen that the PoolConnection is getting the error callback that is being bubbled up in this event.

function PoolConnection(pool, options) {
  Connection.call(this, options);
  this._pool = pool;

  // When a fatal error occurs the connection's protocol ends, which will cause
  // the connection to end as well, thus we only need to watch for the end event
  // and we will be notified of disconnects.
  var connection = this;
  this.on('end', function(err) {
    this._removeFromPool();
  });
  this.on('error', function(err) {
    this._removeFromPool();
  });
}

The removeFromPool seems to be running so I think the error is being handled it is almost as if the symantics around the 'error' event being handled are not being captured by node?

sidorares commented 7 years ago

error is being handled it is almost as if the symantics around the 'error' event being handled are not being captured by node?

yes, that what I was talking about with "no error on socket even when I unplug cable" - not sure if this is I doing something wrong or node / libuv feature

leearmstrong commented 7 years ago

Do you get the error when restarting the MySQL server process as well?

I'm starting to get out of my depth a little but trying to understand why it doesn't happen in the non Promise version!

sidorares commented 7 years ago

Do you get the error when restarting the MySQL server process as well?

looks like not, or at least not always

leearmstrong commented 7 years ago

Ok well I get this on macOS and Linux so please let me know if I can capture any data for you! My node is ok but not as good as yours!!

sidorares commented 7 years ago

very related discussion in #447

a0000778 commented 7 years ago

I think this issue has been fixed in #620.

leearmstrong commented 7 years ago

Yes it does look like that. Is it in a published NPM version yet? @sidorares

sidorares commented 7 years ago

yes #620 is in 1.4.0

leearmstrong commented 7 years ago

Thanks. I looked in the changelog and couldn't see it listed. On Sat, 12 Aug 2017 at 10:57, Andrey Sidorov notifications@github.com wrote:

yes #620 https://github.com/sidorares/node-mysql2/pull/620 is in 1.4.0

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/sidorares/node-mysql2/issues/604#issuecomment-321970667, or mute the thread https://github.com/notifications/unsubscribe-auth/AAFDyzlvvXlmp-yTxTYw84DTmAt4x9Ufks5sXXcRgaJpZM4OQ9HG .

leearmstrong commented 7 years ago

I have run my test scripts with 1.4.1 and this is fixed now.

juan-ferrer-toribio commented 6 years ago

I think this bug it's open again at version 1.5.2

With the following code:

async funcion foo() {
    const mysql = require('mysql2/promise');
    while(true) {
        try {
            let conn = await mysql.createConnection({
                host: 'localhost',
                user: 'root'
            });
            conn.end();
        } catch (e) {
            console.error(e.message);
            // Error handling...
        }
    }
}

Sometimes, when connection isn't established due to timeout, I can't capture the error in the catch, it goes to the global scope:

events.js:183
      throw er; // Unhandled 'error' event
      ^

Error: connect ETIMEDOUT
    at Connection._handleTimeoutError (/home/juan/Projects/salix/node_modules/mysql2/lib/connection.js:181:13)
    at ontimeout (timers.js:475:11)
    at tryOnTimeout (timers.js:310:5)
    at Timer.listOnTimeout (timers.js:270:5)
sidorares commented 6 years ago

@juan-ferrer-toribio are you sure it's 1.5.2? Can't replicate this, get errors caught in catch(e) block and stack trace points to createConnection() line ( this is because we save original callsite here - https://github.com/sidorares/node-mysql2/blob/415959b2855a0002a24b6b3a86a68f09b5d6c923/promise.js#L31 )

I'm testing with local tcp server ( and no mysql server running ) to simulate timeout:

async function foo() {
  const mysql = require('mysql2/promise');
  while (true) {
    try {
      let conn = await mysql.createConnection({
        host: 'localhost',
        user: 'root',
        connectTimeout: 1000
      });
      await conn.end();
    } catch (e) {
      console.error('TIMEOUT here', e.message);
      console.log(e.stack);
      // Error handling...
    }
  }
}

const net = require('net');

const s = net
  .createServer(s => {
    console.log('connection!');
  })
  .listen(3306);

foo().catch(e => {
  console.log('AAAAA', e);
});
juan-ferrer-toribio commented 6 years ago

Yes, it was 1.5.2 under Debian stretch with node 8.9.0.

I tested it under windows 10 with same mysql2 version (1.5.2) and same node version (8.9.0) and the code works as spected (Errors are always captured in catch).

Researching a litle bit more I found the problem is related to the unhandled 'error' event emitted by the conn object, but it only happens under Linux.

As a workaround i used this line of code after establishing connection.

conn.on('error', () => {});

digiperfect-janak commented 6 years ago

I get a similar error in version 1.5.3

events.js:183
      throw er; // Unhandled 'error' event
      ^
Error: Connection lost: The server closed the connection.
    at Socket.<anonymous> (/home/......./node_modules/mysql2/lib/connection.js:100:35)
    at emitNone (events.js:111:20)
    at Socket.emit (events.js:208:7)
    at endReadableNT (_stream_readable.js:1064:12)
    at _combinedTickCallback (internal/process/next_tick.js:138:11)
    at process._tickCallback (internal/process/next_tick.js:180:9)

Node version 8.11.2

The code I have is (using typescript):


class Database {
    private static _instance: Database;
    private dbConnection;

    private constructor() {
        this.dbConnection = createConnection( databaseConfig );
        this.dbConnection.queryWithAwait = util.promisify(this.dbConnection.query);
    }

    public static getInstance() {
        return Database._instance || (Database._instance = new this());
    }

    public executeQuery( sql, args, cb ) {
        this.dbConnection.query( sql, args, ( err, rows ) => {
            if ( err )
                return cb(err, null) ;
            return cb(null, rows);
        } );
    }

    public executeQueryWithAwait( sql, args ) {
        return this.dbConnection.queryWithAwait( sql, args );
    }

    public close(cb) {
        this.dbConnection.end( err => {
            if ( err )
                return cb(err, null);
            Database._instance = null;
            return cb(null, true);
        } );
    }
}

We are rewriting code using async/await hence temporarily we have 2 executeQuery styles. Currently executeQueryWithAwait is not being used.