Queries in async.waterfall() is resulting in Error PROTOCOL_CONNECTION_LOST.

[o1lab]

For sake of simplicity to reproduce - below scenario has two simple queries.

First query returns the results fine and whilst executing second query : error PROTOCOL_CONNECTION_LOST is seen.

Im failing to see what is wrong

var mysql = require('mysql');
var async = require('async')

var pool = mysql.createPool({
  connectionLimit: 10,
  host: 'localhost',
  user: 'root',
  password: 'secret',
  database: 'exampledb'
});

async.waterfall([

  function (cbk) {

    pool.query('select * from customers limit 0,10', function (error, results, fields) {
      console.log(error, results);
      cbk(); //not passing any args or restults - for sake of simplicity in this example

    });

  },

  function (cbk) {

    pool.query('select * from offices limit 0,10', function (error, results, fields) {
      console.log(error, results);
      cbk(null, results);

    });

  }

], function (err, results) { //async.waterfall final result

  console.log(err, results);

});

[dougwilson]

Hi @o1lab I made two blank tables for those two queries and it just logged out two empty result sets without error. Maybe some more information can help me reproduce the issue:

1. Version of this module you're using.
2. Version of Node.js
3. Version of MySQL server.
4. Some DDL for those tables and maybe does the issue depend on there being data in the tables?

Thanks! I'll take a closer look with that info. Another possible way to figure this out, with it being a connection lost, is instead of that, a packet capture during those queries that includes the time of the error would be an alternative that can help narrow this down.

[o1lab]

@dougwilson : thanks for your quick reply

Dependencies:

  "dependencies": {
    "async": "^2.5.0",
    "mysql": "^2.15.0"
  }

= = = = = Node.js version : v8.2.1 MySql version : 5.7.15 = = = = =

Sample database Im using : click-to-download http://www.mysqltutorial.org/mysql-sample-database.aspx

// login to mysql mysql> create database classicmodels mysql> use classicmodels mysql> source path_to_downloaded_file.sql

Tables and data : Above mysql schema download has tables and data with it Query : Same as in sample code pasted above

= = = = =

[o1lab]

.. adding wireshark capture - please unzip it - github is not supporting pcap files

waterfall.pcapng.zip

[dougwilson]

Thanks @o1lab . I looked at the packet capture and don't see the connection closing within that given capture -- just the first query. I'm still working on getting the environment you described setup, but I may not be able to finish that today.

[dougwilson]

Hi @o1lab I was able to finish it up and I couldn't reproduce. I didn't see anything helpful in the packet capture (not sure if it just isn't complete or what), and couldn't reproduce the issue with the provided instructions. It's possible I'm missing something in order to reproduce. Please examine all the steps I went through below to setup my environment to your specs and run the provided code and let me know where I went wrong and what I need to change to see the issue:

$ node -v
v8.2.1

$ npm i mysql async
+ mysql@2.15.0
+ async@2.5.0
added 13 packages in 3.087s

$ cat test.js
var mysql = require('mysql');
var async = require('async')

var pool = mysql.createPool({
  connectionLimit: 10,
  host: 'localhost',
  user: 'root',
  password: 'secret',
  database: 'exampledb'
});

async.waterfall([

  function (cbk) {

    pool.query('select * from customers limit 0,10', function (error, results, fields) {
      console.log(error, results);
      cbk(); //not passing any args or restults - for sake of simplicity in this example

    });

  },

  function (cbk) {

    pool.query('select * from offices limit 0,10', function (error, results, fields) {
      console.log(error, results);
      cbk(null, results);

    });

  }

], function (err, results) { //async.waterfall final result

  console.log(err, results);

});

$ docker run -d --name mysql-1841 -e MYSQL_ROOT_PASSWORD=secret -e MYSQL_DATABASE=exampledb -p 3306:3306 mysql:5.7.15
Unable to find image 'mysql:5.7.15' locally
5.7.15: Pulling from library/mysql
6a5a5368e0c2: Pull complete 
0689904e86f0: Pull complete 
486087a8071d: Pull complete 
3eff318f6785: Pull complete 
3df41d8a4cfb: Pull complete 
1b4a00485931: Pull complete 
0bab0b2c2630: Pull complete 
264fc9ce512d: Pull complete 
e0181dcdbbe8: Pull complete 
53b082fa47c7: Pull complete 
e5cf4fe00c4c: Pull complete 
Digest: sha256:966490bda4576655dc940923c4883db68cca0b3607920be5efff7514e0379aa7
Status: Downloaded newer image for mysql:5.7.15
e61505b1468d1135e989102608eaab0752552de95d323e2d5b7c325838eb6b59

$ docker exec mysql-1841 mysql -psecret -e 'select version()'
mysql: [Warning] Using a password on the command line interface can be insecure.
version()
5.7.15

$ wget -q -O sql.zip http://www.mysqltutorial.org/download/2

$ unzip sql.zip 
Archive:  sql.zip
  inflating: mysqlsampledatabase.sql  

$ sed -i '' 's/classicmodels/exampledb/g' mysqlsampledatabase.sql

$ docker exec -i mysql-1841 mysql -psecret exampledb < mysqlsampledatabase.sql
mysql: [Warning] Using a password on the command line interface can be insecure.

$ node test.js
null [ RowDataPacket {
    customerNumber: 103,
    customerName: 'Atelier graphique',
    contactLastName: 'Schmitt',
    contactFirstName: 'Carine ',
    phone: '40.32.2555',
    addressLine1: '54, rue Royale',
    addressLine2: null,
    city: 'Nantes',
    state: null,
    postalCode: '44000',
    country: 'France',
    salesRepEmployeeNumber: 1370,
    creditLimit: 21000 },
  RowDataPacket {
    customerNumber: 112,
    customerName: 'Signal Gift Stores',
    contactLastName: 'King',
    contactFirstName: 'Jean',
    phone: '7025551838',
    addressLine1: '8489 Strong St.',
    addressLine2: null,
    city: 'Las Vegas',
    state: 'NV',
    postalCode: '83030',
    country: 'USA',
    salesRepEmployeeNumber: 1166,
    creditLimit: 71800 },
  RowDataPacket {
    customerNumber: 114,
    customerName: 'Australian Collectors, Co.',
    contactLastName: 'Ferguson',
    contactFirstName: 'Peter',
    phone: '03 9520 4555',
    addressLine1: '636 St Kilda Road',
    addressLine2: 'Level 3',
    city: 'Melbourne',
    state: 'Victoria',
    postalCode: '3004',
    country: 'Australia',
    salesRepEmployeeNumber: 1611,
    creditLimit: 117300 },
  RowDataPacket {
    customerNumber: 119,
    customerName: 'La Rochelle Gifts',
    contactLastName: 'Labrune',
    contactFirstName: 'Janine ',
    phone: '40.67.8555',
    addressLine1: '67, rue des Cinquante Otages',
    addressLine2: null,
    city: 'Nantes',
    state: null,
    postalCode: '44000',
    country: 'France',
    salesRepEmployeeNumber: 1370,
    creditLimit: 118200 },
  RowDataPacket {
    customerNumber: 121,
    customerName: 'Baane Mini Imports',
    contactLastName: 'Bergulfsen',
    contactFirstName: 'Jonas ',
    phone: '07-98 9555',
    addressLine1: 'Erling Skakkes gate 78',
    addressLine2: null,
    city: 'Stavern',
    state: null,
    postalCode: '4110',
    country: 'Norway',
    salesRepEmployeeNumber: 1504,
    creditLimit: 81700 },
  RowDataPacket {
    customerNumber: 124,
    customerName: 'Mini Gifts Distributors Ltd.',
    contactLastName: 'Nelson',
    contactFirstName: 'Susan',
    phone: '4155551450',
    addressLine1: '5677 Strong St.',
    addressLine2: null,
    city: 'San Rafael',
    state: 'CA',
    postalCode: '97562',
    country: 'USA',
    salesRepEmployeeNumber: 1165,
    creditLimit: 210500 },
  RowDataPacket {
    customerNumber: 125,
    customerName: 'Havel & Zbyszek Co',
    contactLastName: 'Piestrzeniewicz',
    contactFirstName: 'Zbyszek ',
    phone: '(26) 642-7555',
    addressLine1: 'ul. Filtrowa 68',
    addressLine2: null,
    city: 'Warszawa',
    state: null,
    postalCode: '01-012',
    country: 'Poland',
    salesRepEmployeeNumber: null,
    creditLimit: 0 },
  RowDataPacket {
    customerNumber: 128,
    customerName: 'Blauer See Auto, Co.',
    contactLastName: 'Keitel',
    contactFirstName: 'Roland',
    phone: '+49 69 66 90 2555',
    addressLine1: 'Lyonerstr. 34',
    addressLine2: null,
    city: 'Frankfurt',
    state: null,
    postalCode: '60528',
    country: 'Germany',
    salesRepEmployeeNumber: 1504,
    creditLimit: 59700 },
  RowDataPacket {
    customerNumber: 129,
    customerName: 'Mini Wheels Co.',
    contactLastName: 'Murphy',
    contactFirstName: 'Julie',
    phone: '6505555787',
    addressLine1: '5557 North Pendale Street',
    addressLine2: null,
    city: 'San Francisco',
    state: 'CA',
    postalCode: '94217',
    country: 'USA',
    salesRepEmployeeNumber: 1165,
    creditLimit: 64600 },
  RowDataPacket {
    customerNumber: 131,
    customerName: 'Land of Toys Inc.',
    contactLastName: 'Lee',
    contactFirstName: 'Kwai',
    phone: '2125557818',
    addressLine1: '897 Long Airport Avenue',
    addressLine2: null,
    city: 'NYC',
    state: 'NY',
    postalCode: '10022',
    country: 'USA',
    salesRepEmployeeNumber: 1323,
    creditLimit: 114900 } ]
null [ RowDataPacket {
    officeCode: '1',
    city: 'San Francisco',
    phone: '+1 650 219 4782',
    addressLine1: '100 Market Street',
    addressLine2: 'Suite 300',
    state: 'CA',
    country: 'USA',
    postalCode: '94080',
    territory: 'NA' },
  RowDataPacket {
    officeCode: '2',
    city: 'Boston',
    phone: '+1 215 837 0825',
    addressLine1: '1550 Court Place',
    addressLine2: 'Suite 102',
    state: 'MA',
    country: 'USA',
    postalCode: '02107',
    territory: 'NA' },
  RowDataPacket {
    officeCode: '3',
    city: 'NYC',
    phone: '+1 212 555 3000',
    addressLine1: '523 East 53rd Street',
    addressLine2: 'apt. 5A',
    state: 'NY',
    country: 'USA',
    postalCode: '10022',
    territory: 'NA' },
  RowDataPacket {
    officeCode: '4',
    city: 'Paris',
    phone: '+33 14 723 4404',
    addressLine1: '43 Rue Jouffroy D\'abbans',
    addressLine2: null,
    state: null,
    country: 'France',
    postalCode: '75017',
    territory: 'EMEA' },
  RowDataPacket {
    officeCode: '5',
    city: 'Tokyo',
    phone: '+81 33 224 5000',
    addressLine1: '4-1 Kioicho',
    addressLine2: null,
    state: 'Chiyoda-Ku',
    country: 'Japan',
    postalCode: '102-8578',
    territory: 'Japan' },
  RowDataPacket {
    officeCode: '6',
    city: 'Sydney',
    phone: '+61 2 9264 2451',
    addressLine1: '5-11 Wentworth Avenue',
    addressLine2: 'Floor #2',
    state: null,
    country: 'Australia',
    postalCode: 'NSW 2010',
    territory: 'APAC' },
  RowDataPacket {
    officeCode: '7',
    city: 'London',
    phone: '+44 20 7877 2041',
    addressLine1: '25 Old Broad Street',
    addressLine2: 'Level 7',
    state: null,
    country: 'UK',
    postalCode: 'EC2N 1HN',
    territory: 'EMEA' } ]
null [ RowDataPacket {
    officeCode: '1',
    city: 'San Francisco',
    phone: '+1 650 219 4782',
    addressLine1: '100 Market Street',
    addressLine2: 'Suite 300',
    state: 'CA',
    country: 'USA',
    postalCode: '94080',
    territory: 'NA' },
  RowDataPacket {
    officeCode: '2',
    city: 'Boston',
    phone: '+1 215 837 0825',
    addressLine1: '1550 Court Place',
    addressLine2: 'Suite 102',
    state: 'MA',
    country: 'USA',
    postalCode: '02107',
    territory: 'NA' },
  RowDataPacket {
    officeCode: '3',
    city: 'NYC',
    phone: '+1 212 555 3000',
    addressLine1: '523 East 53rd Street',
    addressLine2: 'apt. 5A',
    state: 'NY',
    country: 'USA',
    postalCode: '10022',
    territory: 'NA' },
  RowDataPacket {
    officeCode: '4',
    city: 'Paris',
    phone: '+33 14 723 4404',
    addressLine1: '43 Rue Jouffroy D\'abbans',
    addressLine2: null,
    state: null,
    country: 'France',
    postalCode: '75017',
    territory: 'EMEA' },
  RowDataPacket {
    officeCode: '5',
    city: 'Tokyo',
    phone: '+81 33 224 5000',
    addressLine1: '4-1 Kioicho',
    addressLine2: null,
    state: 'Chiyoda-Ku',
    country: 'Japan',
    postalCode: '102-8578',
    territory: 'Japan' },
  RowDataPacket {
    officeCode: '6',
    city: 'Sydney',
    phone: '+61 2 9264 2451',
    addressLine1: '5-11 Wentworth Avenue',
    addressLine2: 'Floor #2',
    state: null,
    country: 'Australia',
    postalCode: 'NSW 2010',
    territory: 'APAC' },
  RowDataPacket {
    officeCode: '7',
    city: 'London',
    phone: '+44 20 7877 2041',
    addressLine1: '25 Old Broad Street',
    addressLine2: 'Level 7',
    state: null,
    country: 'UK',
    postalCode: 'EC2N 1HN',
    territory: 'EMEA' } ]

[o1lab]

don't see the connection closing within that given capture

I don't know much of tcp internals but before second query is made mysql server is sending [fin,ack] in #30 - it should have sent an [ack] ( I may be wrong )

26 - syn (60694->3306)

27 - syn,ack (3306->60694)

28 - ack (60694->3306)

29 - tcp window update

#30 - fin, ack (3306->60694) - close connection ?

Can you pls share your wireshark capture

[o1lab]

I was able to finish it up and I couldn't reproduce

Could you please run it few times after finish running

[dougwilson]

Yes, but port 60694 is a different port than the one that was in there. I've left the computer for the day, but I'll be back to that computer Monday to get a capture on my side for you.

[o1lab]

Ok, I restarted my machine and problem is not appearing as of now!

But it has bugged me all evening and it did appear even after several restarts this evening. I will leave more info of what I find

Thanks @dougwilson

[o1lab]

Is there a clean up act with mysql pool created before I terminate or restart my app : pool.end() ?

Im using nodemon which watches for file changes and restarts.

[dougwilson]

Hi @o1lab good to hear. Is there some kind of firewall software you are running that may be doing something? I was running on a test machine with everything off. I can still get you that packet capture on Monday, though, if this is still open.

As for your recent question, with the pool, it keeps open a pool of connections for when you want to make queries. The pool.end() method will tell the pool to close all the connections if you want to close down the event loop gracefully.

I'm not familiar with nodemon, so don't really understand the part about that.

[o1lab]

Cool @dougwilson - I've successful packet capture with me now.

I will try few more things to narrow this and hopefully have something by Monday.

[o1lab]

Hi @dougwilson

Scenario I have described previously didn't encounter problem when I restarted my machine.

I noticed that problem occurred in midst of running and testing queries - where mysql lib and server got into this funny state where async.waterfall always resulted in the problem.

---

Below is a definite reproducible scenario in my setup. Happens 10 out of 10 times from fresh restart.

// after a fresh restart of machine git clone https://github.com/o1lab/rap-mysql cd rap-mysql && npm install open tests/tests.js in editor - goto line 21

// change mysql password to your local mysql server password args['password'] = 'secret'

// login to mysql shell and create test db and data create database classicmodels use classicmodels source /path/to/rap-mysql/tests/sqldata/classicmodels-sampledb.sql

// within shell run tests - three times npm test (ctrl+c when finished) npm test (ctrl+c when finished) npm test

All tests pass - during initial two times. On 3rd run - POOL_CONNECTION_LOST error is seen.

If I disable first function async.waterfall in lib/rap.mydb.js (lines 430 - 453)

npm test - all pass again

Im failing to see where it is going wrong and why it passes in initial two runs. The repo is still under work (so there can be bugs in code and docs).

Attaching pcap where problem is reproduced. async-waterfall-prob.pcapng.gz

[dougwilson]

Hi @o1lab I followed your instructions with my local MySQL server and could not reproduce it -- no matter how many times I ran npm test it always worked. I took a look at the capture you gave, and it seems that there are connections where your MySQL server (or maybe a firewall on your machine?) is immediately closing down the connection Node.js opened. For example tcp.stream eq 58 the connection was closed by the remote end where normally the MySQL server would have sent the server greeting data.

[o1lab]

I checked (OSX) firewall - that is in OFF status.

How can I narrow down on what is going wrong ? Any logs to enable in node mysql lib or better way to handle current situation. The problem has been persistent in my machine.

I can take out the explain part of query in async.waterfall. But Im sure the problem will come up when I have async.waterfall somewhere else. I am using async.waterfall with queries in a different project - but have never come across this issue.

Do you see any thing suspicious with code rap.api.js and rap.mysql.js ? I might be doing something not good ?

[o1lab]

Below is error print for reference

{ Error: Connection lost: The server closed the connection.
  at Protocol.end (/Users/mysql-express/node_modules/mysql/lib/protocol/Protocol.js:113:13)
  at Socket.<anonymous> (/Users/mysql-express/node_modules/mysql/lib/Connection.js:109:28)
  at emitNone (events.js:110:20)
  at Socket.emit (events.js:207:7)
  at endReadableNT (_stream_readable.js:1045:12)
  at _combinedTickCallback (internal/process/next_tick.js:138:11)
  at process._tickCallback (internal/process/next_tick.js:180:9)
  --------------------
    at Protocol._enqueue (/Users/mysql-express/node_modules/mysql/lib/protocol/Protocol.js:145:48)
  at Protocol.handshake (/Users/mysql-express/node_modules/mysql/lib/protocol/Protocol.js:52:23)
  at PoolConnection.connect (/Users/mysql-express/node_modules/mysql/lib/Connection.js:130:18)
  at Pool.getConnection (/Users/mysql-express/node_modules/mysql/lib/Pool.js:48:16)
  at Pool.query (/Users/mysql-express/node_modules/mysql/lib/Pool.js:202:8)
  at /Users/mysql-express/lib/rap.mydb.js:458:18
  at nextTask (/Users/mysql-express/node_modules/async/dist/async.js:5297:14)
  at next (/Users/mysql-express/node_modules/async/dist/async.js:5304:9)
  at /Users/mysql-express/node_modules/async/dist/async.js:906:16
  at Query._callback (/Users/mysql-express/lib/rap.mydb.js:449:11)
  at Query.Sequence.end (/Users/mysql-express/node_modules/mysql/lib/protocol/sequences/Sequence.js:88:24)
  at Query._handleFinalResultPacket (/Users/mysql-express/node_modules/mysql/lib/protocol/sequences/Query.js:139:8)
  at Query.EofPacket (/Users/mysql-express/node_modules/mysql/lib/protocol/sequences/Query.js:123:8)
  at Protocol._parsePacket (/Users/mysql-express/node_modules/mysql/lib/protocol/Protocol.js:279:23)
  at Parser.write (/Users/mysql-express/node_modules/mysql/lib/protocol/Parser.js:76:12)
  at Protocol.write (/Users/mysql-express/node_modules/mysql/lib/protocol/Protocol.js:39:16)
  at Socket.<anonymous> (/Users/mysql-express/node_modules/mysql/lib/Connection.js:103:28)
  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) fatal: true, code: 'PROTOCOL_CONNECTION_LOST' } 

[dougwilson]

So there is debugging in this module (https://github.com/mysqljs/mysql#debugging-and-reporting-problems) but I'm not sure if it'll help if (from what I can tell in the pcap) the MySQL server never even sends a greeting, since this module's debugging it at the MySQL protocol level. You could also try the debugging in TCP in Node.js (however you do that, if you can) or debugging in the MySQL server (no idea how you'd do that, either).

Nothing seems wrong in those files, and since the waterfall doesn't really do anything but call two queries you can always just do that without the waterfall as well. I don't think your issue is the use of async.waterfall at all, especially based on the pcaps. It seems like something is happening on the machine that is making the remote end close the connection when this module tries to open a new connection.

The MySQL protocol is that TCP connection is opened and MySQL server sends the hello before this module does anything at all. Instead of sending the hello, the remote is closing it, and that is before any logic in this module is even executed, so there doesn't seem like there is any way to change something in here. It really seems like (a) something in TCP is broken in Node.js itself or (b) there is a firewall that closes the connection or (c) the MySQL server gets the new TCP connection but closes it down instead of sending the greeting data for some reason.

[o1lab]

Thank you for info @dougwilson

I have this doubt. Im creating pool for database 'classicmodels' in example. But I am running queries against information_schema tables i.e Im using 'classicmodels' database pool to query information from different database which is information_schema

Is that kind of pool usage legal at lib/protocol level ?

[dougwilson]

No, that is not an issue. You can query any database you user has grants on over a connection. The specified database only applies to identifiers that are not fully qualified in your queries.

[o1lab]

In the 3rd run of npm test where I see failure - only test cases which pass are the ones skipped in first async.waterfall function. These statements start with describe, show and explain. Rest of statements starting with select, insert, update and delete - all fail.

Can this info help at lib level ?

[o1lab]

No, that is not an issue.

Ok

[dougwilson]

No, that's not the issue, either. I explained with the issue is based on you pcap and that stack trace you gave. The remote end closes the TCP connection after it's opened, before the server sends the greeting packet. At that point, nothing from this lib is ever sent to the server, because the protocol never even started; the user didn't even log in yet.

[o1lab]

Hi @dougwilson - could you pls share mysql, node and os you used today.

[dougwilson]

It was the same machine I was using last week: https://github.com/mysqljs/mysql/issues/1841#issuecomment-335939538

[o1lab]

Thanks to this stackexchange question . This problem appears to be an issue with OSX mysql server.

After doing 3 runs of npm test - opened_files or opened_tables were hitting system/server limits. Variable values can be seen with SHOW GLOBAL STATUS.

Running 'FLUSH TABLES' resets these variables - then tests run fine. Im happy to get past this problem for now.

Thank you @dougwilson for your support.