Unhandled 'error' event and PROTOCOL_CONNECTION_LOST

[luizeduardogiampaoli]

Hello,
First of all, thank you for your work building this amazing library!

I am having the following problem when trying to connect on purpose for testing into a server using an invalid username:

events.js:187
      throw er; // Unhandled 'error' event
      ^
Error: Connection lost: The server closed the connection.
    at Socket.<anonymous> (G:\dev\giamcis\gwsi\aarm-api-n\node_modules\mysql2\lib\connection.js:88:31)
    at Socket.emit (events.js:210:5)
    at TCP.<anonymous> (net.js:658:12)
Emitted 'error' event on PoolConnection instance at:
    at PoolConnection._notifyError (G:\dev\giamcis\gwsi\aarm-api-n\node_modules\mysql2\lib\connection.js:218:12)
    at Socket.<anonymous> (G:\dev\giamcis\gwsi\aarm-api-n\node_modules\mysql2\lib\connection.js:94:12)
    at Socket.emit (events.js:210:5)
    at TCP.<anonymous> (net.js:658:12) {
  fatal: true,
  code: 'PROTOCOL_CONNECTION_LOST'
}

This is how I setup my connection pool:

this.connectionPool = mysql.createPool({
                host: this.cfg.dbServer,
                user: this.cfg.dbUserName,
                database: this.cfg.dbSchema,
                password: this.cfg.dbPassword,                
        
             }).promise();

This is how I attach the error listener, I use the following techniques (tried both):

this.connectionPool.on('connection', (connection) => {
                console.log('[MYSQL-DRIVER]-NEW CONNECTION ' + connection.threadId);
                connection.on('error', function(err){
                    console.log('[MYSQL-DRIVER]-PROBLEM: ' + err);
                })
            });

Or:
this.connectionPool.on('error', function(err) {
                console.log("[MYSQL-DRIVER]-PROBLEM(ATTACHED ON POOL): " + err);
             });

I have a simple test routine, so everytime I start my nodeJS server, after the pool is created, I run the following:

await this.connTest().then((result)=>{
                this.connected = 1;                
            }).catch((err) => {
                this.connected = 0;
            });

connTest() {
        return new Promise((resolve, reject) => {
            this.connectionPool.execute('SELECT 1 + 1 AS SOLUTION;', function (error, resulds, fields) {
                if (error) reject();
                resolve();
            })
        });
    }

Now the strange part. I am developing in a Windows 10 machine with MySQL hosted on another machine on the network. This problem “Unhandled 'error' event” does NOT always occur. Sometimes I work for hours and disconnections are handled JUST FINE by the ATTACHED ERROR FUNCTION. I repeat: sometimes the disconnections ARE handled by the handlers!

I don´t know exactly what changes for the behavior appear, but it appears to be after I restart MySQL server.

I decided to turn on the mysql2 library debug, to see what kind of information it shows, during the times the error is happening. Everytime I run my test routine, just before the error, I see this:

raw: 0a382e302e313800c50300001e014540076c0f0f00ffffe00200ffc71500000000000000000000235744157b3f7557525e27020063616368696e675f736861325f70617373776f726400
Trace
    at PoolConnection.handlePacket (G:\dev\giamcis\gwsi\aarm-api-n\node_modules\mysql2\lib\connection.js:393:17)
    at PacketParser.onPacket (G:\dev\giamcis\gwsi\aarm-api-n\node_modules\mysql2\lib\connection.js:70:12)
    at PacketParser.executeStart (G:\dev\giamcis\gwsi\aarm-api-n\node_modules\mysql2\lib\packet_parser.js:75:16)
    at Socket.<anonymous> (G:\dev\giamcis\gwsi\aarm-api-n\node_modules\mysql2\lib\connection.js:77:25)
    at Socket.emit (events.js:210:5)
    at addChunk (_stream_readable.js:308:12)
    at readableAddChunk (_stream_readable.js:289:11)
    at Socket.Readable.push (_stream_readable.js:223:10)
    at TCP.onStreamRead (internal/stream_base_commons.js:182:23)
0 undefined ==> undefined#unknown name(0,,78)
 raw: fe7368613235365f70617373776f726400717e517834167a03770763452506255719282e4100
Trace
    at PoolConnection.handlePacket (G:\dev\giamcis\gwsi\aarm-api-n\node_modules\mysql2\lib\connection.js:393:17)
    at PacketParser.onPacket (G:\dev\giamcis\gwsi\aarm-api-n\node_modules\mysql2\lib\connection.js:70:12)
    at PacketParser.executeStart (G:\dev\giamcis\gwsi\aarm-api-n\node_modules\mysql2\lib\packet_parser.js:75:16)
    at Socket.<anonymous> (G:\dev\giamcis\gwsi\aarm-api-n\node_modules\mysql2\lib\connection.js:77:25)
    at Socket.emit (events.js:210:5)
    at addChunk (_stream_readable.js:308:12)
    at readableAddChunk (_stream_readable.js:289:11)
    at Socket.Readable.push (_stream_readable.js:223:10)
    at TCP.onStreamRead (internal/stream_base_commons.js:182:23)
0 965 ==> undefined#unknown name(2,,42)

I wonder if is there any reason why the emitted error in this situation does not arrive at my error handler?

Thank you!

[sidorares]

thanks for detail report! Don't have much time to read in details, could you have a look at comments below #683 (comment)
and maybe try enabling enableKeepAlive connect option ( this requires code from master, I'll try to publish to npm later today )

[luizeduardogiampaoli]

Hello @sidorares,

Well, I think I have an idea why the problem is happening in my situation. Please excuse me if I am wrong, I am not a hardcore nodejs developer, i am fairly new to this amazing world (I come from a C C++ background, I have my own IoT fog middleware) but appears to me that the handlers are not being attached on a connection that does not exist yet (well, at least does not exists from the mysql2 library point of view).

What happens is: I setup the pool and, suposedly, I setup the handlers, but on which connection? Then I try to connect, Mysql sends back those packets (which I converted to ascii and are things like the version and something like password). Library code does not acknoledge "if (this._closing) ", it proceeds to:

 if (!this._protocolError) {
        // no particular error message before disconnect
        this._protocolError = new Error(
          'Connection lost: The server closed the connection.'
        );
        this._protocolError.fatal = true;
        this._protocolError.code = 'PROTOCOL_CONNECTION_LOST';
      }

But nothing was attached to listen to this error, the concept of connection as the library understands is not there yet.

Well, this is what I THINK is happening. I think that because the handlers work in connections that were successfully connected at first. But I really do not know If I am right.

Regards,
Luiz

[ianbale]

I've seen this as well

Setting the underlying cause of the connection failure aside for a moment.
A legitimate error is occurring which instead of being trapped and handled is resulting in an unhandled promise reaction error. The logs indicate this occurs on line 151 of promise.js

  ping() {
    const c = this.connection;
    const localErr = new Error();
    return new this.Promise((resolve, reject) => {
      const done = makeDoneCb(resolve, reject, localErr);
      **c.ping(done);**
    });
  }

It looks to me like makeDoneCb is supposed to handle this, but doesn't seem to be.

This is my code:

exports.ping = async context => {
  try
  {
    if (dbConnection)
    {
      console.log("Pinging DB to keep connection alive")
      dbConnection.ping()
    }
    // If we do not have a connection then 
  }
  catch(err) {// Ignore ping error. Connection is lost. Well worry about that when we actually need it...
    dbConnection = null // Mark dbConnection as lost
  } 
}

I am trapping any error response from the ping. But in this case, the fatal exception has already caused my code to terminate.

Anything I can do differently to prevent this? Or is it a fault with mysql code?

[sidorares]

@ianbale yeah, when you get PROTOCOL_CONNECTION_LOST it's too late to ping

The logs indicate this occurs on line 151 of promise.js

Are you saying that reject(error) is never called from done returned by makeDoneCb?

[ianbale]

Doesn't look like it.

This is the full error:

{
    **"errorType": "Runtime.UnhandledPromiseRejection",**
    "errorMessage": "Error: Connection lost: The server closed the connection.",
    "reason": {
        "errorType": "Error",
        "errorMessage": "Connection lost: The server closed the connection.",
        "code": "PROTOCOL_CONNECTION_LOST",
        "message": "Connection lost: The server closed the connection.",
        "stack": [
            "Error: Connection lost: The server closed the connection.",
            **"    at PromiseConnection.ping (/var/task/node_modules/mysql2/promise.js:151:22)",**
            "    at Object.exports.ping (/var/task/smx-utilities/database.js:189:20)",
            "    at getContext (/var/task/smx-utilities/request-handler.js:155:8)",
            "    at Object.exports.getPayloadAndContext (/var/task/smx-utilities/request-handler.js:30:25)",
            "    at Runtime.exports.retrieveAsync [as handler] (/var/task/retrieve/handler.js:15:36)",
            "    at Runtime.handleOnce (/var/runtime/Runtime.js:66:25)"
        ]
    },
    "promise": {},
    "stack": [
        "Runtime.UnhandledPromiseRejection: Error: Connection lost: The server closed the connection.",
        "    at process.<anonymous> (/var/runtime/index.js:35:15)",
        "    at process.emit (events.js:310:20)",
        "    at process.EventEmitter.emit (domain.js:482:12)",
        "    at processPromiseRejections (internal/process/promises.js:209:33)",
        "    at processTicksAndRejections (internal/process/task_queues.js:98:32)"
    ]
}

Unhandled promise rejection in promise.js:151:22

My code:

exports.ping = async context => {
  try
  {
    if (dbConnection)
    {
      console.log("Pinging DB to keep connection alive")
      dbConnection.ping()
    }
    // If we do not have a connection then 
  }
  catch(err) {// Ignore ping error. Connection is lost. Well worry about that when we actually need it...
    dbConnection = null // Mark dbConnection as lost
  } 
}

I'm catching any error that comes back to me and just deleting my reference to the Db connection so that the next query creates a new one. But it doesn't hit that because the unhandled error exception is thrown upstream from me.

FYI: This is in am AWS Lambda function. It can lie dormant for some time - hence I do expect connections to be dropped, but I am doing my best to maintain the connection across invocations where possible.

I have the exact same problem with queries that run after an extended period of inactivity.

Is there any way to test if the connection has been dropped prior to ping / query?

Only other option is for me to drop the connection after the lambda completes and create a new one when the lambda is invoked again. Not as efficient, but should reduce these protocol errors - which are currently causing fatal errors in alive system...

[ianbale]

I've found a few instances of PROTOCOL_CONNECTION_LOST when I am doing queries. In those instances, the error is caught. I do not get the unhandled error exception in promise.js

Since they way ping and query are handled in promise.js is the same, I can only conclude that the error is upstream of there. For now I am going to replace my ping with a tiny query.

[sidorares]

@ianbale could you try to set enableKeepAlive connection option? see #1081 and #683 (comment) for some background

[ianbale]

That's not going to help me here. Firstly, I am not using pools and secondly, this code is in AWS Lambda. So the code terminates when the call ends, so there is no opportunity for mysql to keep the connection alive until it is invoked again (minimum of every 10 minutes) - which is when I am doing the ping. Variables / state is maintained, so mostly the connection is still ok when it next runs. But sometimes, it's not and the DB connection has been dropped.

The issue here is not maintaining the connection, but rather handling the case when the connection has been dropped. So, even if I could use enableKeepAlive, it would, at best, be masking the issue, not resolving it for me.

That aside, I have noticed that I was missing an await on the code that called the function where I do the ping. What seems to have been happening is that the code execution was complete and AWS Lambda was spinning down the instance by the time the error is thrown in your library. The upshot is that my error handler appears to have been disabled by the instance pausing. I've added that missing await and have now seen several instances of the same PROTOCOL_CONNECTION_LOST error, but without the unhandled exception error.

Upshot - self inflicted by missing the await, compounded by a very misleading error from node.js saying the exception was thrown in promise.js, when in fact, the unhandled exception error was occurring in my code!

Thank you for taking the time to look at this and for providing and maintaining this library. It is the core of so much of my work that it's almost forgotten, working its magic under the hood so well. Very much appreciated!

[sidorares]

oh, I suspect missing await was causing that issue. If connection is dead doing ping() without await would result in UnhandledPromiseRejection

[ianbale]

You were too quick! I just edited my comment above having just checked the logs that were produced in the last 30 mins... That was indeed the cause!

[chris-heathwood]

Just in case someone else finds this thread I had an issue with the PROTOCOL_CONNECTION_LOST on my local machine and in github actions and it was just me being too fast.

Waiting for 10 seconds or so and then try the connection worked.