pool.end() kills connection.query() in promise mode

[sergru]

I am working on server that handles several requests asynchronously. Found the problem when close the app gracefully while mysql query is still running. To stop the app, I call pool.end() created by mysql.createPool({}).promise();. But looks like, pool.end() just closes the pool without checking that some connections from the pool are still running. Connection query throws the exception with Error: Pool is closed. Or I do something wrong or inappropriate. Any suggestions?

Exception is:

D:\server\node_modules\mysql2\lib\pool.js:57
          return cb(new Error('Pool is closed.'));
                    ^
Error: Pool is closed.
    at D:\server\node_modules\mysql2\lib\pool.js:57:21
    at PoolConnection.<anonymous> (D:\server\node_modules\mysql2\lib\connection.js:777:13)
    at Object.onceWrapper (node:events:628:26)
    at PoolConnection.emit (node:events:513:28)
    at ClientHandshake.<anonymous> (D:\server\node_modules\mysql2\lib\connection.js:121:14)
    at ClientHandshake.emit (node:events:513:28)
    at ClientHandshake.execute (D:\server\node_modules\mysql2\lib\commands\command.js:49:10)
    at PoolConnection.handlePacket (D:\server\node_modules\mysql2\lib\connection.js:456:32)
    at PacketParser.onPacket (D:\server\node_modules\mysql2\lib\connection.js:85:12)
    at PacketParser.executeStart (D:\server\node_modules\mysql2\lib\packet_parser.js:75:16)
Node.js v18.12.0
Process finished with exit code 1

Here is simple test to reproduce:

'use strict';
const mysql = require('mysql2');
let pool;
// ---------------------------------------------------------------------
const start = () => {
  pool = mysql.createPool({host: 'localhost', user: '', password: ''})
  .promise();
}
// ---------------------------------------------------------------------
const stop = () => {
  if (pool) {
    pool.end();
    pool = undefined;
  }
}
// ---------------------------------------------------------------------
const query = (sql, params) => {
  let connection;
  return pool
  .getConnection()
  .then((conn) => {
    connection = conn;
    return connection.query(sql, params);
  })
  .then(([rows, fields]) => {
    connection.release();
    console.log('Rows', rows, fields);
  })
  .catch((ex) => {
    throw ex;
  });
}
// ---------------------------------------------------------------------
// Run
start();
query('SELECT 1');
stop();

My code is bit more sophisticated. I can have several complex queries executing in the pool and some queries waiting in a pool queue. But the root of the problem is the same.

If I wrap stop() in setTimeout() with short delay:

...

setTimeout(() => {
  stop();
}, 100)

the test finishes normally with exit code 0.

I am using:

Product	Version
mysql2:	2.3.3
nodejs:	18.12.0
mysql:	8.0.31
OS:	Windows 10

[sidorares]

hm, promise pool.end() just delegates it to callback implementation, which in turn enqueues end command to every connection which is only executed after all previous command in the connection queue are finished.

I'll try to reproduce, don't see anything wrong on your side

[sergru]

I found the bug. Here is a code snippet from pool.js of my version.

  getConnection(cb) {  // <----------------------------- pool.js:37
      ...

      this._allConnections.push(connection);  // <------ pool.js:54
      return connection.connect(err => {
        if (this._closed) {  // <----------------------- pool.js:56
          return cb(new Error('Pool is closed.'));
        }
...

  end(cb) {
    this._closed = true;  // <-------------------------- pool.js:98
    if (typeof cb !== 'function') {

Using my test as a workflow:

• First, query('SELECT 1') calls pool.getConnection(cb):pool.js:37. At line pool.js:54 pool is still open (this._closed = false). At this point connection.connect(cb) starts and its callback is waiting to be called.
• Second, stop() calls pool.end(cb):pool.js:97 and its first instruction is this._closed = true;:pool.js:98 marking pool as closed.
• And only then the callback from getConnection(cb) is called. But at that point the pool is already marked as closed (this._closed = true) and callback returns with error return cb(new Error('Pool is closed.')):pool.js:57

So, actually, the pool is marked as closed immediately and unconditionally when call pool.end() that causing an errors in asynchronous parts (callbacks) of currently executing connections.

Usually, in situations like this I use tree-state flag: 0 - open, 1 - closing, 2 - closed. The 'closing' state allows to finish the currently running tasks (in your case, connections), but prohibits to run from queue waiting tasks or to add to queue new ones. This approach requires extra work to properly handle the state switching, but it's worth it.

Hope, this will help.

[sidorares]

thanks for tracking down to the root cause @sergru

the intention of _closing flag is to help preventing from adding commands to a connection that already has COM_QUIT command in its queue

The more I think about possible scenarios the more difficult I think is to satisfy all of them. I'll try to post examples below

[sidorares]

btw simple

start();
query('SELECT 1').then(stop)

solve the problem ( on a consumer side ). Still, a bit surprising behaviour from the driver in your original example

[sidorares]

example in my head:

import mysql from './promise.js';

const pool = mysql.createPool({
  host: 'localhost',
  user: 'root',
  password: 'test',
  connectionLimit: 2,
});

async function endAfterDelay(ms) {
  return new Promise((resolve, reject) => {
    setTimeout(() => {
      console.log('calling pool.end()');
      pool.end()
      resolve();
    }, ms);
  });
}

const result = await Promise.allSettled([
  pool.query('select sleep(3)'),
  pool.query('select sleep(5)'),
  pool.query('select sleep(5)'),
  endAfterDelay(4000),
]);
console.log(result);

what would be the expected behaviour here ( also with different values for connectionLimit )?

Unlike regular connection where .query is "add enough information to be able to send COM_QUERY command to the server when there is no more command in front of me", the pool.query is "wait until there is a free connection, and then do .query() on it"

[sergru]

Thanks for response.

query('SELECT 1').then(stop) works for test but unfortunately will not help in my project. In my real scenario pool.end() is called on the app stop event (from UI button or SIGINT and SIGTERM events) while multiple connection.query() are simultaneously executing. I need that pool.end() starts its work only when all connection.query() finished.

I think I can use process.nextTick() to stop accepting queries, wait all connections finished and then call poop.end(). So this will be my app closing state implementation.

[sidorares]

can you describe a behaviour on a driver side that would have a better ergonomics for you? Right now what we have is: pool.query() might potentially fail for a number of reasons and you need to be prepared to handle them. One possible reason is: sometime between the pool.query() and connection is actually free pool.end() is called

[sidorares]

hm, another problem, even worse then the one you described:

if you call pool.query() after calling pool.end() it never resolves.

I think the correct behaviour is to notify all pool connections in the wait queue with "Pool is closed" error

hm, not sure if this actually the case. Looking at the code there is a check for that

https://github.com/sidorares/node-mysql2/blob/dd4d1d6b6086c763f54b3b006ec6acf4b10bae4c/lib/pool.js#L39

[sergru]

Sorry, I've been interrupted for a while.

In my example:

query('SELECT 1');
stop();

the execution sequence is:

• query() calls Pool::getConnection that checks this._closed which is false, line 38: https://github.com/sidorares/node-mysql2/blob/dd4d1d6b6086c763f54b3b006ec6acf4b10bae4c/lib/pool.js#L37-L40
• then stop() calls PromisePool::end() that sets this._closed to true, line 98 https://github.com/sidorares/node-mysql2/blob/dd4d1d6b6086c763f54b3b006ec6acf4b10bae4c/lib/pool.js#L97-L98
• and only after that the callback from Pool::getConnection() been called, which is part of not yet finished query(). But at this moment this._closed already true, line 56: https://github.com/sidorares/node-mysql2/blob/dd4d1d6b6086c763f54b3b006ec6acf4b10bae4c/lib/pool.js#L55-L58 and the app throws exception.

[sergru]

Here is my simplified work scenario is:

(1) - When app starts I call start() to initialize the pool (PromisePool). (2) - Then on each http request I call query({sql, params}) for connection gotten from pool. http handles it in separate threads. (3) - Then on arbitrary moment I call stop() from UI or by SIGINT or SIGTERM events and expect graceful finish of all running query() before exit. But exception happened instead.

[sergru]

I can make repro.js for this scenario if you like. But the simple test I sent first reproduce the exact problem.

[sergru]

I took the liberty to implement the workaround to my issue. Here is my changes in mysql2/promise.js, mysql2/lib/pool.js, and test script repro-exception.js . In this implementation there are no exceptions Error: Pool is closed anymore, and all asynchronous calls of query() and stop() executed as expected. The log of all calls added for debug purposes.

Files from mysql2:

• mysql2/promise.js
• mysql2/lib/pool.js

Test file:

• test/repro-exception.js

Kill .txt extra extension when download files. Somehow .js files are not allowed to be dropped in github.

Search for ADDED: to see all my changes in 2 mysql2 files.