Unhandled 'error' event with pooled connections

[yashgt]

My application starts fine and runs for a few hours. Then all of a sudden I see the error:

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

> Error: Connection lost: The server closed the connection.

at Protocol.end (/home/ec2-user/production/code/admin/node_modules/mysql/lib/protocol/Protocol.js:113:13)
at Socket.<anonymous> (/home/ec2-user/production/code/admin/node_modules/mysql/lib/Connection.js:109:28)
at Socket.emit (events.js:185:15)
at endReadableNT (_stream_readable.js:1106:12)
at process._tickCallback (internal/process/next_tick.js:114:19)

Emitted 'error' event at:
at Connection._handleProtocolError (/home/ec2-user/production/code/admin/node_modules/mysql/lib/Connection.js:433:8)
at Protocol.emit (events.js:180:13)
at Protocol._delegateError (/home/ec2-user/production/code/admin/node_modules/mysql/lib/protocol/Protocol.js:392:10)
at Protocol.end (/home/ec2-user/production/code/admin/node_modules/mysql/lib/protocol/Protocol.js:117:8)
at Socket. (/home/ec2-user/production/code/admin/node_modules/mysql/lib/Connection.js:109:28)
[... lines matching original stack trace ...]

This error comes when no user is doing any action on the application. The system is idle.

I have the following code:

exports.createPool = function createPool(dbConfig)
{
        logger.debug('Creating pool');
        pool = mysql.createPool(dbConfig);
        pool.on('connection', function (connection) {
                logger.info('Setting error handler for {0}',connection);
                connection.on('error', function(err) {
                        logger.error(err); // 'ER_BAD_DB_ERROR'
                });
        });
        pool.on('release', function(connection) {
                logger.error('Releasing {0}', connection); //
        });
};

If a connection goes in Error, I expect the handler to be called. It does get called and that is the reason we see:
Error: Connection lost: The server closed the connection.
I also expect the connection to get released and the pool to generate another connection.

Even though I have applied an error handler, it says the 'error' even is not handled and the application crashes.

[dougwilson]

Very strange. It should be working just like you describe you expect it to work. We have some tests around this too that pass. We may have missed some strange edge case. Is it possible you can provide all the information necessary such that we can reproduce the same error? Someone who is able to reproduce the issue can then attach a debugger and start examining what is happening when this condition occurs and see why it's not being handled.

1. Version of Node.js
2. Version of this module you're using
3. Full source code that can run without modification that will reproduce this error
4. All relevant steps to get the code running and trigger the error

Thanks!

[yashgt]

[ec2-user@ip-172-31-21-161 admin]$ node -v
v9.10.1

"_id": "mysql@2.15.0"

The process sometimes gives the Unhandled 'error' event or sometimes crashes all of a sudden.
Here are the steps to reproduce:

run npm install.
run nohup 2049.js > 2049.out &
run nohup watch -n 3000 curl http://localhost:3001 &

The application establishes a connection using a pool.
It establishes another connection and makes a query.
It then goes in a loop to keep printing the time.
It also listens for GET requests.

With the above commands we keep making GET requests. After about 8 hrs, the connection to DB breaks. The attached 2049.out file shows that this is logged correctly. Sometimes it throws the error. In the test done yesterday, the application just stopped after 9 hours.

2049.zip

[yashgt]

2049.zip
This version reproduces the defect consistently. See the log file 2049.out.

[dougwilson]

Thanks for the code and instructions @yashgt . I believe I see where the issue is happening. I will continue investigating on Monday 👍

[yashgt]

I tried a workaround. Every 5 min I tried to make a dummy query to keep the connection alive:

//Dummy query to keep connection alive
setInterval(function() {
        db.query("select 1 from dual", function(results){
                logger.debug('Dummy query');
        });
}, 300000);

But this was of no use. The problem still happens.

[dougwilson]

Sorry this got lost around. I want to run your program to be able to reproduce, but I don't know all the module versions you have installed, as installing the latest of all the needed modules doesn't seem to work at all. Also the ZIP you provide requires files that are not included in the ZIP which contain code. Can you either (a) provide all the missing information / files or (b) provide a file that does not include any external modules / files besides this module?

[dougwilson]

The best I can think of right now is that you may be encountering a (fixed) bug in the connect-mysql library. Your package.json file has "connect-mysql": "^2.0.5", which means you may locally have version 2.0.5, 2.1.0, 2.1.1, 2.1.3, 2.1.4, 2.1.5, 2.1.6, or 2.1.7 installed, but I have no way to know which one you are using. Some of those versions have a bug that produces the unhandled error you posted above, so maybe you just need to make sure that module it upgraded to the latest version?

[yashgt]

in node_modules, the version of connect-mysql is:
"_from": "connect-mysql@^2.0.5",
"_id": "connect-mysql@2.1.7",
as seen in the package.json

and that of mysql is:
{
"_from": "mysql@*",
"_id": "mysql@2.15.0",

[yashgt]

Attaching the complete project for simulating the issue.
nohup 2049.js > 2049.out &
nohup watch -n 3000 curl http://localhost:3001/api/gtfs &

Wait for 8 hours. You will see an error in 2049.out

2049.zip