Connection.end never calls callback when connected through an SSH tunnel

[jarwol]

I'm trying to use node-mysql to connect to an AWS RDS instance that's only reachable from EC2 instances within the same VPC. My specific use case is allowing a CI tool such as Codeship to run DB migrations before deploying new builds. Since the Codeship hosts don't have access to my DB instance, it will have to tunnel through one of my EC2 instances. This works like a charm, and I can execute queries against the DB fine, but when I try to close the connection, the callback is never called. Since I need to close the tunnel after the db connection is closed, the script hangs. I'm able to repro this with the following code (ssh/db config changed).

var Tunnel = require('tunnel-ssh'),
    mysql = require('mysql');

var Tunnel = new Tunnel({
  remoteHost: "dbHost",
  remotePort: 3306,
  localPort: 33333,
  sshConfig: {
    host: "sshHost",
    username: "ec2-user",
    privateKey: require('fs').readFileSync("/path/to/private/key")
  }
});

Tunnel.connect(function(err) {
  if (err) {
    return console.log(err);
  }
  var conn = new mysql.createConnection({
    host: '127.0.0.1',
    port: 33333,
    database: "database",
    user: "dbUser",
    password: "dbPass"
  });

  conn.end(function(err) {
    console.log("END");
  });
});

I was able to follow the stack into the Quit sequence, but couldn't find where the problem was happening. Let me know if you need any more info, or if you think this is a problem on the tunnel-ssh side.

Thanks,
Jared

[dougwilson]

Hm, I'm not sure. I would even say maybe pasting the following information (probably as a Gist) may help us here:

1. Add debug: true to the mysql.createConnection options.
2. Start your script with the environment NODE_DEBUG=net

Then paste the stuff starting from when you see a line that shows the end packet is being sent to the MySQL server to the end of the log. That may help us a lot :)

[sidorares]

does it normally work without tunnel?
COM_QUIT does not return confirmation packet, so there is no OK or Error packet for Sequence class to wait - I'm not sure if end() callback work at all.

[dougwilson]

The end() callback works here--what we do is send COM_QUIT and then we'll call the callback if the connection is ended, but it has to actually be ended graceful with a proper TCP tear-down (i.e. Node.js has to actually know the remote site ended the TCP connection). The only reason the callback wouldn't be called is if the remote (or an intermediary) is not forwarding the ending FIN-ACK handshakes.

[jarwol]

@dougwilson Thanks for the quick response. Debug output is below.
@sidorares Yeah I've tested it connecting to localhost DB without a tunnel.

/usr/local/bin/node mysqltest.js
NET: 22508 _read
NET: 22508 _read wait for connection
NET: 22508 connect: find host 54.224.53.121
NET: 22508 afterConnect
NET: 22508 _read
NET: 22508 Socket._read readStart
NET: 22508 afterWrite 0 { domain: null, bytes: 22, oncomplete: [Function: afterWrite] }
NET: 22508 afterWrite call cb
NET: 22508 onread undefined 0 21 21
NET: 22508 got data
NET: 22508 _read
NET: 22508 afterWrite 0 { domain: null, bytes: 648, oncomplete: [Function: afterWrite] }
NET: 22508 afterWrite call cb
NET: 22508 onread undefined 32 1448 1480
NET: 22508 got data
NET: 22508 _read
NET: 22508 onread undefined 1488 96 1584
NET: 22508 got data
NET: 22508 _read
NET: 22508 afterWrite 0 { domain: null, bytes: 272, oncomplete: [Function: afterWrite] }
NET: 22508 afterWrite call cb
NET: 22508 onread undefined 1584 848 2432
NET: 22508 got data
NET: 22508 _read
NET: 22508 afterWrite 0 { domain: null, bytes: 16, oncomplete: [Function: afterWrite] }
NET: 22508 afterWrite call cb
NET: 22508 afterWrite 0 { domain: null, bytes: 32, oncomplete: [Function: afterWrite] }
NET: 22508 afterWrite call cb
NET: 22508 afterWrite 0 { domain: null, bytes: 16, oncomplete: [Function: afterWrite] }
NET: 22508 afterWrite call cb
NET: 22508 onread undefined 2432 48 2480
NET: 22508 got data
NET: 22508 _read
NET: 22508 afterWrite 0 { domain: null, bytes: 352, oncomplete: [Function: afterWrite] }
NET: 22508 afterWrite call cb
NET: 22508 afterWrite 0 { domain: null, bytes: 16, oncomplete: [Function: afterWrite] }
NET: 22508 afterWrite call cb
NET: 22508 onread undefined 2480 320 2800
NET: 22508 got data
NET: 22508 _read
NET: 22508 afterWrite 0 { domain: null, bytes: 624, oncomplete: [Function: afterWrite] }
NET: 22508 afterWrite call cb
NET: 22508 afterWrite 0 { domain: null, bytes: 16, oncomplete: [Function: afterWrite] }
NET: 22508 afterWrite call cb
NET: 22508 onread undefined 2800 32 2832
NET: 22508 got data
NET: 22508 _read
NET: 22508 listen2 0.0.0.0 33333 4 false
NET: 22508 _listen2: create a handle
NET: 22508 bind to 0.0.0.0
NET: 22508 connect: find host 127.0.0.1
NET: 22508 _read
NET: 22508 _read wait for connection
NET: 22508 afterConnect
NET: 22508 _read
NET: 22508 Socket._read readStart
NET: 22508 onconnection
NET: 22508 _read
NET: 22508 Socket._read readStart
NET: 22508 afterWrite 0 { domain: null, bytes: 112, oncomplete: [Function: afterWrite] }
NET: 22508 afterWrite call cb
NET: 22508 afterWrite 0 { domain: null, bytes: 16, oncomplete: [Function: afterWrite] }
NET: 22508 afterWrite call cb
NET: 22508 onread undefined 2832 48 2880
NET: 22508 got data
NET: 22508 _read
NET: 22508 onread undefined 2880 128 3008
NET: 22508 got data
NET: 22508 _read
NET: 22508 afterWrite 0 { domain: null, bytes: 82, oncomplete: [Function: afterWrite] }
NET: 22508 afterWrite call cb
NET: 22508 onread undefined 3008 82 3090
NET: 22508 got data
NET: 22508 _read
<-- HandshakeInitializationPacket
{ protocolVersion: 10,
  serverVersion: '5.6.21-log',
  threadId: 19765,
  scrambleBuff1: <Buffer 32 50 7b 3f 63 55 61 66>,
  filler1: <Buffer 00>,
  serverCapabilities1: 65535,
  serverLanguage: 8,
  serverStatus: 2,
  serverCapabilities2: 49279,
  scrambleLength: 21,
  filler2: <Buffer 00 00 00 00 00 00 00 00 00 00>,
  scrambleBuff2: <Buffer 5d 22 30 66 36 78 7d 29 52 41 2e 62>,
  filler3: <Buffer 00>,
  pluginData: 'mysql_native_password',
  protocol41: true }

--> ClientAuthenticationPacket
{ clientFlags: 455631,
  maxPacketSize: 0,
  charsetNumber: 33,
  filler: undefined,
  user: 'dbuser',
  scrambleBuff: <Buffer 35 a3 9d 26 8d d9 88 7f 3e 6f 36 84 29 8f 3d c1 d6 2e 80 97>,
  database: 'ebdb',
  protocol41: true }

NET: 22508 afterWrite 0 { domain: null, bytes: 70, oncomplete: [Function: afterWrite] }
NET: 22508 afterWrite call cb
NET: 22508 onread undefined 3104 70 3174
NET: 22508 got data
NET: 22508 _read
NET: 22508 afterWrite 0 { domain: null, bytes: 96, oncomplete: [Function: afterWrite] }
NET: 22508 afterWrite call cb
NET: 22508 afterWrite 0 { domain: null, bytes: 16, oncomplete: [Function: afterWrite] }
NET: 22508 afterWrite call cb
<-- OkPacket
{ fieldCount: 0,
  affectedRows: 0,
  insertId: 0,
  serverStatus: 2,
  warningCount: 0,
  message: '',
  protocol41: true,
  changedRows: 0 }

--> ComQuitPacket
{ command: 1 }

NET: 22508 onread undefined 3184 48 3232
NET: 22508 got data
NET: 22508 _read
NET: 22508 afterWrite 0 { domain: null, bytes: 11, oncomplete: [Function: afterWrite] }
NET: 22508 afterWrite call cb
NET: 22508 onread undefined 3232 11 3243
NET: 22508 got data
NET: 22508 _read
NET: 22508 afterWrite 0 { domain: null, bytes: 5, oncomplete: [Function: afterWrite] }
NET: 22508 afterWrite call cb
NET: 22508 onread undefined 3248 5 3253
NET: 22508 got data
NET: 22508 _read
NET: 22508 afterWrite 0 { domain: null, bytes: 32, oncomplete: [Function: afterWrite] }
NET: 22508 afterWrite call cb
NET: 22508 afterWrite 0 { domain: null, bytes: 16, oncomplete: [Function: afterWrite] }
NET: 22508 afterWrite call cb
NET: 22508 onread undefined 3264 32 3296
NET: 22508 got data
NET: 22508 _read
NET: 22508 afterWrite 0 { domain: null, bytes: 16, oncomplete: [Function: afterWrite] }
NET: 22508 afterWrite call cb
NET: 22508 afterWrite 0 { domain: null, bytes: 16, oncomplete: [Function: afterWrite] }
NET: 22508 afterWrite call cb
NET: 22508 onread undefined 3296 32 3328
NET: 22508 got data
NET: 22508 _read

Process finished with exit code 130 (when I killed the script)

[dougwilson]

Thank! So the Node.js log definitely shows it just hanging there--the TCP connection was never cleanly shutdown. With that log, I would definitely look into tunnel-ssh to see if that's the issue, because Node.js doesn't think the remote has closed down the MySQL TCP connection.

[dougwilson]

It doesn't seem like tunnel-ssh is on GitHub for me to look at it's source code.

[dougwilson]

I just installed tunnel-ssh and the main issue I see is that it installed a really, really old version of the ssh2 module. Perhaps if that dependency is updated it may fix the issue?

[jarwol]

I manually updated to the latest ssh2, but that didn't fix the issue. Here is the github repo btw: https://github.com/Finanzchef24-GmbH/tunnel-ssh. I'll take a look at the code after work, and I'll cross-reference this issue on the tunnel-ssh repo.

[dougwilson]

Awesome. I'm also leaving this issue open, because I still don't know exactly what is going on, so until we have a definitive answer, it's still unresolved in my mind :)

[agebrock]

Hey guys thanks for reporting. I think i got the problem fixed in the next major version.
You may crosscheck https://github.com/Finanzchef24-GmbH/tunnel-ssh/blob/release/1.0.0/example/mysql.js

Thanks for reporting.

[dougwilson]

Awesome, thanks, @agebrock !