Connection to database hangs after Error: read ETIMEDOUT

[bmaupin]

We're using loopback-connector-mysql v6.0.2 and normally any time there's a database issue, the application automatically reconnects to the database without any intervention on our part.

However, we recently ran into an issue where this did not happen. Even though the database was running, the application would not reconnect to the database until I restarted it.

These were the errors in the log:

Error: Cannot enqueue Query after fatal error.
    at Protocol._validateEnqueue (/usr/src/app/node_modules/mysql/lib/protocol/Protocol.js:212:16)
    at Protocol._enqueue (/usr/src/app/node_modules/mysql/lib/protocol/Protocol.js:138:13)
    at PoolConnection.query (/usr/src/app/node_modules/mysql/lib/Connection.js:198:25)
    at runQuery (/usr/src/app/node_modules/loopback-connector-mysql/lib/mysql.js:197:16)
    at executeWithConnection (/usr/src/app/node_modules/loopback-connector-mysql/lib/mysql.js:239:7)
    at MySQL.executeSQL (/usr/src/app/node_modules/loopback-connector-mysql/lib/mysql.js:248:5)
    at /usr/src/app/node_modules/loopback-connector-mysql/node_modules/loopback-connector/lib/sql.js:597:10
    at /usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:259:9
    at doNotify (/usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:155:49)
    at MySQL.ObserverMixin._notifyBaseObservers (/usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:178:5)
    at MySQL.ObserverMixin.notifyObserversOf (/usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:153:8)
    at MySQL.ObserverMixin.notifyObserversAround (/usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:228:15)
    at MySQL.SQLConnector.execute (/usr/src/app/node_modules/loopback-connector-mysql/node_modules/loopback-connector/lib/sql.js:596:8)
    at MySQL._modifyOrCreate (/usr/src/app/node_modules/loopback-connector-mysql/lib/mysql.js:278:8)
    at MySQL.save.MySQL.updateOrCreate (/usr/src/app/node_modules/loopback-connector-mysql/lib/mysql.js:318:8)
    at invokeConnectorMethod (/usr/src/app/node_modules/loopback-datasource-juggler/lib/dao.js:172:21)
    at /usr/src/app/node_modules/loopback-datasource-juggler/lib/dao.js:637:13
    at doNotify (/usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:155:49)
    at doNotify (/usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:155:49)
    at doNotify (/usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:155:49)
    at doNotify (/usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:155:49)
    at Function.ObserverMixin._notifyBaseObservers (/usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:178:5)
    at Function.ObserverMixin.notifyObserversOf (/usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:153:8)
    at Function.ObserverMixin._notifyBaseObservers (/usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:176:15)
    at Function.ObserverMixin.notifyObserversOf (/usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:153:8)
    at Function.ObserverMixin._notifyBaseObservers (/usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:176:15)
    at Function.ObserverMixin.notifyObserversOf (/usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:153:8)
    at Function.ObserverMixin._notifyBaseObservers (/usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:176:15) 
Error: read ETIMEDOUT
    at TCP.onStreamRead (internal/stream_base_commons.js:209:20)
    at TCP.callbackTrampoline (internal/async_hooks.js:126:14)
    --------------------
    at Protocol._enqueue (/usr/src/app/node_modules/mysql/lib/protocol/Protocol.js:144:48)
    at PoolConnection.query (/usr/src/app/node_modules/mysql/lib/Connection.js:198:25)
    at runQuery (/usr/src/app/node_modules/loopback-connector-mysql/lib/mysql.js:197:16)
    at executeWithConnection (/usr/src/app/node_modules/loopback-connector-mysql/lib/mysql.js:239:7)
    at MySQL.executeSQL (/usr/src/app/node_modules/loopback-connector-mysql/lib/mysql.js:248:5)
    at /usr/src/app/node_modules/loopback-connector-mysql/node_modules/loopback-connector/lib/sql.js:597:10
    at /usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:259:9
    at doNotify (/usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:155:49)
    at MySQL.ObserverMixin._notifyBaseObservers (/usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:178:5)
    at MySQL.ObserverMixin.notifyObserversOf (/usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:153:8)
    at MySQL.ObserverMixin.notifyObserversAround (/usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:228:15)
    at MySQL.SQLConnector.execute (/usr/src/app/node_modules/loopback-connector-mysql/node_modules/loopback-connector/lib/sql.js:596:8)
    at MySQL._modifyOrCreate (/usr/src/app/node_modules/loopback-connector-mysql/lib/mysql.js:278:8)
    at MySQL.save.MySQL.updateOrCreate (/usr/src/app/node_modules/loopback-connector-mysql/lib/mysql.js:318:8)
    at invokeConnectorMethod (/usr/src/app/node_modules/loopback-datasource-juggler/lib/dao.js:172:21)
    at /usr/src/app/node_modules/loopback-datasource-juggler/lib/dao.js:637:13
    at doNotify (/usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:155:49)
    at doNotify (/usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:155:49)
    at doNotify (/usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:155:49)
    at doNotify (/usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:155:49)
    at Function.ObserverMixin._notifyBaseObservers (/usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:178:5)
    at Function.ObserverMixin.notifyObserversOf (/usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:153:8)
    at Function.ObserverMixin._notifyBaseObservers (/usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:176:15)
    at Function.ObserverMixin.notifyObserversOf (/usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:153:8)
    at Function.ObserverMixin._notifyBaseObservers (/usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:176:15)
    at Function.ObserverMixin.notifyObserversOf (/usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:153:8)
    at Function.ObserverMixin._notifyBaseObservers (/usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:176:15)
    at Function.ObserverMixin.notifyObserversOf (/usr/src/app/node_modules/loopback-datasource-juggler/lib/observer.js:153:8) 

(the last error is repeated, I'm guessing for each connection in the pool).

In searching online for similar errors, using a pool seems to be the solution for this sort of problem. Of course, this connector is already using a pool, so I'm not sure what options I have to fix this. Unfortunately despite my best efforts I've been unable to reproduce that exact error and so I can't provide a way to reproduce it at this time.

My understanding is that any time a connection encounters an error, it's supposed to be released from the pool to make room for new connections. Why didn't that happen?

According to mysqljs/mysql#2522 (comment), I wonder if it could be a bug in this library since we aren't calling any of the underlying methods directly:

What's so special about Error: read ETIMEDOUT at TCP.onStreamRead that prevents the pool from reconnecting to the database?

This means that you have a reference to a specific connection object in your code. That connection then emitted an error that had the .fatal property set to true, but then your code called .query on that same object after the error.

Ideally if you get a fatal error on a connection, you should either call .release on it to destroy it and call .getConnection to get a new one if you are using the pool, or just call .createConnection to create a new connection if not. Always be careful how you structure your logic, as when the TCP connection is lost from the server, ant temp tables, variables, and uncommitted transactions are lost.

I don't see a single mention of fatal in this library. Maybe some extra logic needs to be added to handle fatal errors? Even crashing the application would be preferable to it hanging, because at least then we could know to restart it.

Thanks!

[achrinza]

Thanks for the detailed report on the issue, @bmaupin!

I've read through the other issue, and cross-checked with the source code here; It does seem that this package doesn't properly handle connection errors after the initial connection:

normally any time there's a database issue, the application automatically reconnects to the database without any intervention on our part.

Unfortunately I'm not sure why this is the case; This could be due to a retry mechanism either in the mysql package or the transport protocol.

I don't see a single mention of fatal in this library. Maybe some extra logic needs to be added to handle fatal errors?

My understanding is that any time a connection encounters an error, it's supposed to be released from the pool to make room for new connections.

When starting up, the connector does check for any errors, but does not distinguish between fatal and non-fatal:

loopback-connector-mysql/lib/mysql.js

Lines 90 to 105 in 76e09ea

	this.client.getConnection(function(err, connection) {
	const conn = connection;
	if (!err) {
	if (self.debug) {
	debug('MySQL connection is established: ' + self.settings || {});
	}
	connection.release();
	} else {
	if (self.debug || !callback) {
	console.error('MySQL connection is failed: ' + self.settings || {}, err);
	}
	}
	callback && callback(err, conn);
	});
	}
	};

Though this check only happens during app startup; Afterwards, it does not seem that there's any re-connection logic in either the connector nor the Juggler ORM.

When .query() is called, the response is always passed to handleResponse:

loopback-connector-mysql/lib/mysql.js

Lines 186 to 194 in 76e09ea

	function handleResponse(connection, err, result) {
	if (!transaction) {
	connection.release();
	}
	if (err) {
	err = setHttpCode(err);
	}
	callback && callback(err, result);
	}

Which should throw an error; This should cause the application to continue or crash (depending on several factors), but it shouldn't hang.

NB: The use of setHttpCode in the above code snippet is a remnant of how LB2 and LB3 works. This isn't as relevant for LB4.

---

I've not tested for a potential solution, but I suspect the issue is with this line:

loopback-connector-mysql/lib/mysql.js

Line 250 in 76e09ea

client.getConnection(executeWithConnection);

This seems to be where all query logic converges at, and there's no check for fatal errors.

Unfortunately, why is hangs is still a mystery.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.