Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

closing connection throws uncaught error. #1027

Closed
CamJN opened this issue Mar 15, 2015 · 29 comments
Closed

closing connection throws uncaught error. #1027

CamJN opened this issue Mar 15, 2015 · 29 comments

Comments

@CamJN
Copy link

CamJN commented Mar 15, 2015

Both:

require('fs').readFile('/etc/mysql/mysql-ssl-ca-cert.pem','utf8',function(err,caFile){
    if(err){
        console.error(err);
    }else{
        var connection = require('mysql').createConnection({
            host     : 'localhost',
            user     : 'root',
            password : 'password',
            ssl      : { ca : caFile }
        });
        connection.connect(function(err){
            if(err){
                console.error(err);
            }else{
                console.log('connected');
            }
        });
        connection.end(function(err) { if(err) console.error('Error On DB Close.'); });
    }
});

and

require('fs').readFile('/etc/mysql/mysql-ssl-ca-cert.pem','utf8',function(err,caFile){
    if(err){
        console.error(err);
    }else{
        var connection = require('mysql').createConnection({
            host     : 'localhost',
            user     : 'root',
            password : 'password',
            ssl      : { ca : caFile }
        });
        connection.connect(function(err){
            if(err){
                console.error(err);
            }else{
                console.log('connected');
                connection.end(function(err) { if(err) console.error('Error On DB Close.'); });
            }
        });
    }
});

Fatal on connection.end(...) with an unhandled ENOTCONN which is obviously not being caught by the error handling suggested by the documentation. Either this is a bug in the library or the docs; either way I'd like to know how to actually use this library as right now it defies me.

@sidorares
Copy link
Member

I just tried your example and error was handled by both callbacks:

{ [Error: connect ECONNREFUSED 127.0.0.1:1234]
  code: 'ECONNREFUSED',
  errno: 'ECONNREFUSED',
  syscall: 'connect',
  address: '127.0.0.1',
  port: 1234,
  fatal: true }
Error On DB Close.

@sidorares
Copy link
Member

( that's without ssl, connection to port 1234 on which no server is listening )

@CamJN
Copy link
Author

CamJN commented Mar 15, 2015

The connection does connect. I can run queries before end. The fatal happens when I call end, which is bizarre.

@dougwilson
Copy link
Member

Definitely bizarre. I'll be at a computer soon to take a look. It's possible it's specific to using SSL. In the mean time, what version of this library are you using and what version of Node.js?

@CamJN
Copy link
Author

CamJN commented Mar 15, 2015

I realized why we seemed (from my perspective) to be talking about different things at first. I did additional testing after writing the first comment, namely trying some queries before calling .end. So when I wrote this I thought that no connection was made at all. But by the time I saw your comment I forgot what I set the title of the issue as and that I had previously been unaware that the connection was made.

Anyway here's the versions (both installed today):
node v0.12.0
node-mysql mysql@2.5.5

@CamJN CamJN changed the title node-mysql lies about connecting. closing connection throws uncaught error. Mar 15, 2015
@dougwilson
Copy link
Member

Hmm. So I looked a little and didn't see anything obvious (yet; to me). So I saw you said "with an unhandled ENOTCONN". So when Node.js has an unhandled error, what it does it prints a line of course to the screen, a line with a carrot, and then a full stack trace. Would you be able to paste all that here, please?

@dougwilson
Copy link
Member

And just to confirm, @CamJN , you're not running Node.js from cygwin environment, correct?

@CamJN
Copy link
Author

CamJN commented Mar 15, 2015

events.js:85
      throw er; // Unhandled 'error' event
            ^
Error: shutdown ENOTCONN
    at exports._errnoException (util.js:746:11)
    at Socket.onSocketFinish (net.js:232:26)
    at Socket.emit (events.js:104:17)
    at finishMaybe (_stream_writable.js:484:14)
    at endWritable (_stream_writable.js:493:3)
    at Socket.Writable.end (_stream_writable.js:459:5)
    at Socket.end (net.js:407:31)
    at Protocol.<anonymous> (/Users/camdennarzt/Developer/JS/barcoding/node_modules/mysql/lib/Connection.js:85:27)
    at Protocol.emit (events.js:129:20)
    at Protocol.end (/Users/camdennarzt/Developer/JS/barcoding/node_modules/mysql/lib/protocol/Protocol.js:99:10)

And no, not under cygwin, I'm on OS X and node was installed via homebrew.

@dougwilson
Copy link
Member

Cool. I think this stack trace helps a lot :)

@dougwilson dougwilson self-assigned this Mar 15, 2015
@dougwilson
Copy link
Member

Basically it shows that our call to socket.end() is throwing. I've never seen Node.js do this before :/ so we of course don't wrap that in a try - catch block. @CamJN do you happen to be willing to install the more stable v0.10.x line of Node.js to see if you still encounter this to help me rule out of it's a Node.js 0.12 regression? If not, that's ok, just let me know :)

@dougwilson
Copy link
Member

Also, I assume that what you posted above is the only thing in your file? If not, can you try running a file that does nothing but try to connect to MySQL to help rune out the potential of other modules doing something strange?

@dougwilson
Copy link
Member

In the meantime, I think I may have a lead in that it's SSL-specific.

@dougwilson
Copy link
Member

Additional data that may help us is if you can set the environment variable NODE_DEBUG=net and then run this little code again. Then pasting the output from those messages may help us understand the order of the events within Node.js networking.

@CamJN
Copy link
Author

CamJN commented Mar 15, 2015

Yeah that code is all that's in file, I had already been trying to narrow it down to a minimal test case.
I made a few tiny changes since then, so I'll paste the exact test case here:

require('fs').readFile('/etc/mysql/mysql-ssl-ca-cert.pem','utf8',function(err,caFile){
    if(err){
        console.error(err);
    }else{
        var connection = require('mysql').createConnection({
            host     : 'localhost',
            user     : 'root',
            password : 'password',
            database : 'database_name',
            ssl      : { ca : caFile }
        });
        connection.connect(function(err){
            if(err){
                console.error(err);
            }else{
                console.log('connected');
                connection.query('select count(*) as found from `list_of_codes` where `code` = ?', ['HHH888H8'], function(err, rows, fields) {
                    if (err) {
                        console.error(err);
                    }else{
                        console.log(rows[0].found);
                    }
                });
                connection.end(function(err) { if(err) console.error('Error On DB Close.'); });
            }
        });
    }
});

running that with NODE_DEBUG=net node test.js gives:

NET 51900: createConnection [ { port: 3306, host: 'localhost' } ]
NET 51900: pipe false undefined
NET 51900: connect: find host localhost
NET 51900: connect: dns options [object Object]
NET 51900: _read
NET 51900: _read wait for connection
NET 51900: afterConnect
NET 51900: _read
NET 51900: Socket._read readStart
NET 51900: onread 82
NET 51900: got data
NET 51900: _read
NET 51900: _read
NET 51900: afterWrite 0
NET 51900: afterWrite call cb
NET 51900: onread 11
NET 51900: got data
connected
NET 51900: _read
NET 51900: afterWrite 0
NET 51900: afterWrite call cb
NET 51900: onread 60
NET 51900: got data
1
NET 51900: _read
NET 51900: afterWrite 0
NET 51900: afterWrite call cb
NET 51900: onread -4095
NET 51900: EOF
NET 51900: onSocketEnd { objectMode: false,
  highWaterMark: 16384,
  buffer: [],
  length: 0,
  pipes: 
   { domain: null,
     _events: 
      { end: [Object],
        handshake: [Function],
        unhandledError: [Function],
        drain: [Object],
        enqueue: [Function],
        unpipe: [Function: onunpipe],
        error: [Function: onerror],
        close: [Object],
        finish: [Object],
        data: [Function] },
     _maxListeners: undefined,
     readable: true,
     writable: true,
     _config: 
      { host: 'localhost',
        port: 3306,
        localAddress: undefined,
        socketPath: undefined,
        user: 'root',
        password: 'password',
        database: 'database_name',
        connectTimeout: 10000,
        insecureAuth: false,
        supportBigNumbers: false,
        bigNumberStrings: false,
        dateStrings: false,
        debug: undefined,
        trace: true,
        stringifyObjects: false,
        timezone: 'local',
        flags: '',
        queryFormat: undefined,
        pool: undefined,
        ssl: [Object],
        multipleStatements: false,
        typeCast: true,
        maxPacketSize: 0,
        charsetNumber: 33,
        clientFlags: 457679,
        protocol41: true },
     _connection: 
      { domain: null,
        _events: {},
        _maxListeners: undefined,
        config: [Object],
        _socket: [Object],
        _protocol: [Circular],
        _connectCalled: true,
        state: 'authenticated',
        threadId: 1166 },
     _callback: null,
     _fatalError: null,
     _quitSequence: 
      { domain: null,
        _events: [Object],
        _maxListeners: undefined,
        _callback: [Function],
        _callSite: [Error],
        _ended: false,
        _timeout: undefined,
        _idleNext: null,
        _idlePrev: null,
        _idleStart: null,
        _idleTimeout: undefined,
        _repeat: null },
     _handshakeSequence: 
      { domain: null,
        _events: [Object],
        _maxListeners: undefined,
        _callback: [Function],
        _callSite: null,
        _ended: true,
        _timeout: undefined,
        _idleNext: null,
        _idlePrev: null,
        _idleStart: null,
        _idleTimeout: -1,
        _repeat: null,
        _config: [Object],
        _handshakeInitializationPacket: [Object] },
     _handshaked: true,
     _ended: false,
     _destroyed: false,
     _queue: [ [Object] ],
     _handshakeInitializationPacket: 
      { protocolVersion: 10,
        serverVersion: '5.6.23-log',
        threadId: 1166,
        scrambleBuff1: <Buffer 26 6f 21 52 59 4a 46 5e>,
        filler1: <Buffer 00>,
        serverCapabilities1: 65535,
        serverLanguage: 33,
        serverStatus: 2,
        serverCapabilities2: 49279,
        scrambleLength: 21,
        filler2: <Buffer 00 00 00 00 00 00 00 00 00 00>,
        scrambleBuff2: <Buffer 29 4e 2e 3a 78 6f 45 49 7c 59 27 53>,
        filler3: <Buffer 00>,
        pluginData: 'mysql_native_password',
        protocol41: true },
     _parser: 
      { _supportBigNumbers: false,
        _buffer: <Buffer 01 00 00 01 01 1b 00 00 02 03 64 65 66 00 00 00 05 66 6f 75 6e 64 00 0c 3f 00 15 00 00 00 08 81 00 00 00 00 05 00 00 03 fe 00 00 02 00 02 00 00 04 01 ... >,
        _longPacketBuffers: [],
        _offset: 60,
        _packetEnd: null,
        _packetHeader: null,
        _packetOffset: null,
        _onError: [Function],
        _onPacket: [Function],
        _nextPacketNumber: 1,
        _encoding: 'utf-8',
        _paused: false } },
  pipesCount: 1,
  flowing: true,
  ended: true,
  endEmitted: false,
  reading: false,
  sync: false,
  needReadable: false,
  emittedReadable: false,
  readableListening: false,
  defaultEncoding: 'utf8',
  ranOut: false,
  awaitDrain: 0,
  readingMore: false,
  decoder: null,
  encoding: null,
  resumeScheduled: false }
NET 51900: onSocketFinish
NET 51900: oSF: ended, destroy { objectMode: false,
  highWaterMark: 16384,
  buffer: [],
  length: 0,
  pipes: 
   { domain: null,
     _events: 
      { end: [Object],
        handshake: [Function],
        unhandledError: [Function],
        drain: [Object],
        enqueue: [Function],
        unpipe: [Function: onunpipe],
        error: [Function: onerror],
        close: [Object],
        finish: [Object],
        data: [Function] },
     _maxListeners: undefined,
     readable: true,
     writable: true,
     _config: 
      { host: 'localhost',
        port: 3306,
        localAddress: undefined,
        socketPath: undefined,
        user: 'root',
        password: 'password',
        database: 'database_name',
        connectTimeout: 10000,
        insecureAuth: false,
        supportBigNumbers: false,
        bigNumberStrings: false,
        dateStrings: false,
        debug: undefined,
        trace: true,
        stringifyObjects: false,
        timezone: 'local',
        flags: '',
        queryFormat: undefined,
        pool: undefined,
        ssl: [Object],
        multipleStatements: false,
        typeCast: true,
        maxPacketSize: 0,
        charsetNumber: 33,
        clientFlags: 457679,
        protocol41: true },
     _connection: 
      { domain: null,
        _events: {},
        _maxListeners: undefined,
        config: [Object],
        _socket: [Object],
        _protocol: [Circular],
        _connectCalled: true,
        state: 'authenticated',
        threadId: 1166 },
     _callback: null,
     _fatalError: null,
     _quitSequence: 
      { domain: null,
        _events: [Object],
        _maxListeners: undefined,
        _callback: [Function],
        _callSite: [Error],
        _ended: false,
        _timeout: undefined,
        _idleNext: null,
        _idlePrev: null,
        _idleStart: null,
        _idleTimeout: undefined,
        _repeat: null },
     _handshakeSequence: 
      { domain: null,
        _events: [Object],
        _maxListeners: undefined,
        _callback: [Function],
        _callSite: null,
        _ended: true,
        _timeout: undefined,
        _idleNext: null,
        _idlePrev: null,
        _idleStart: null,
        _idleTimeout: -1,
        _repeat: null,
        _config: [Object],
        _handshakeInitializationPacket: [Object] },
     _handshaked: true,
     _ended: false,
     _destroyed: false,
     _queue: [ [Object] ],
     _handshakeInitializationPacket: 
      { protocolVersion: 10,
        serverVersion: '5.6.23-log',
        threadId: 1166,
        scrambleBuff1: <Buffer 26 6f 21 52 59 4a 46 5e>,
        filler1: <Buffer 00>,
        serverCapabilities1: 65535,
        serverLanguage: 33,
        serverStatus: 2,
        serverCapabilities2: 49279,
        scrambleLength: 21,
        filler2: <Buffer 00 00 00 00 00 00 00 00 00 00>,
        scrambleBuff2: <Buffer 29 4e 2e 3a 78 6f 45 49 7c 59 27 53>,
        filler3: <Buffer 00>,
        pluginData: 'mysql_native_password',
        protocol41: true },
     _parser: 
      { _supportBigNumbers: false,
        _buffer: <Buffer 01 00 00 01 01 1b 00 00 02 03 64 65 66 00 00 00 05 66 6f 75 6e 64 00 0c 3f 00 15 00 00 00 08 81 00 00 00 00 05 00 00 03 fe 00 00 02 00 02 00 00 04 01 ... >,
        _longPacketBuffers: [],
        _offset: 60,
        _packetEnd: null,
        _packetHeader: null,
        _packetOffset: null,
        _onError: [Function],
        _onPacket: [Function],
        _nextPacketNumber: 1,
        _encoding: 'utf-8',
        _paused: false } },
  pipesCount: 1,
  flowing: true,
  ended: true,
  endEmitted: false,
  reading: false,
  sync: false,
  needReadable: false,
  emittedReadable: false,
  readableListening: false,
  defaultEncoding: 'utf8',
  ranOut: false,
  awaitDrain: 0,
  readingMore: false,
  decoder: null,
  encoding: null,
  resumeScheduled: false }
NET 51900: destroy undefined
NET 51900: destroy
NET 51900: close
NET 51900: close handle
NET 51900: destroy undefined
NET 51900: destroy
NET 51900: already destroyed, fire error callbacks
NET 51900: onSocketFinish
NET 51900: oSF: not ended, call shutdown()
NET 51900: destroy
NET 51900: close
NET 51900: close handle
NET 51900: emit close
events.js:85
      throw er; // Unhandled 'error' event
            ^
Error: shutdown ENOTCONN
    at exports._errnoException (util.js:746:11)
    at Socket.onSocketFinish (net.js:232:26)
    at Socket.emit (events.js:104:17)
    at finishMaybe (_stream_writable.js:484:14)
    at endWritable (_stream_writable.js:493:3)
    at Socket.Writable.end (_stream_writable.js:459:5)
    at Socket.end (net.js:407:31)
    at Protocol.<anonymous> (/Users/camdennarzt/Developer/JS/barcoding/node_modules/mysql/lib/Connection.js:85:27)
    at Protocol.emit (events.js:129:20)
    at Protocol.end (/Users/camdennarzt/Developer/JS/barcoding/node_modules/mysql/lib/protocol/Protocol.js:99:10)

@CamJN
Copy link
Author

CamJN commented Mar 15, 2015

As for installing node 0.10.x, I'm willing to do that, but it'll take a while since I didn't go the nvm route to begin with.

@dougwilson
Copy link
Member

Ok, that's no problem :) That trace gives me a lot to work with, so I may have an answer prior to you getting around to installing v0.10 (hopefully) :)

@CamJN
Copy link
Author

CamJN commented Mar 16, 2015

I wound up installing node 0.10.36 on a different machine to save myself headaches; and my test case works perfectly. removed 0.10.36 and installed 0.12.0 and the crash happens (again, not the same box, so definitely a 0.12.0 issue).

@dougwilson
Copy link
Member

Ok. And I think I was able to reproduce on Nde.js 0.12 this weekend. I'm still digging in to see if this is an issue with this module or if I need to file a bug report with Node.js.

@dougwilson
Copy link
Member

@sidorares would you be wiling to help me with a way to get this to reproduce, mainly so we can determine what to provide to nodejs/node-v0.x-archive#9419 ?

@sidorares
Copy link
Member

I'll try to reproduce on osx and ubuntu

@CamJN
Copy link
Author

CamJN commented Mar 19, 2015

I found an interesting detail, if I don't use ssl, the connection closes cleanly.

@CamJN
Copy link
Author

CamJN commented Mar 19, 2015

Because creating certs for mysql is a massive pain, I have a script that automates it (if you have openssl.cnf setup correctly, if not you have to answer some questions but the only one that matters is the FQDN of the mysql server):

PATH=/usr/local/opt/openssl/bin/openssl:$PATH
openssl genrsa 2048 > ca-key.pem
openssl req -new -x509 -nodes -days 3600 -key ca-key.pem -out ca-cert.pem
openssl req -newkey rsa:2048 -days 3600 -nodes -keyout server-key.pem -out server-req.pem
openssl rsa -in server-key.pem -out server-key.pem
openssl x509 -req -in server-req.pem -days 3600 -CA ca-cert.pem -CAkey ca-key.pem -set_serial 01 -out server-cert.pem
openssl verify -CAfile ca-cert.pem server-cert.pem

In my.cnf:

[mysqld]
ssl-ca=/usr/local/opt/mysql/ca-cert.pem
ssl-cert=/usr/local/opt/mysql/server-cert.pem
ssl-key=/usr/local/opt/mysql/server-key.pem

and obviously keep a copy of ca-cert.pem for node-mysql to use.

@SeanDolan
Copy link

I am only new (less than a week) with Node/Socket/MySQL stuff.. but I was experiencing what I believe is the same issue:

var app = require("express")();
var http = require("http").Server(app);
var server = require("socket.io")(http);
var mysql = require('mysql');

var conn = mysql.createConnection({
      host     : 'localhost',
      user     : 'root',
      password : '******',
      database : 'databasename'
}); 

function dataQuery(query){
    var result = "";
    conn.query(query, function(err, rows, fields) {
    if (!err)
        result = rows;
    else
        result = 'error';
    });
    conn.end();     
    return result;
}

When this function was invoked the first time it would work fine. If it was called a second time then it would fail with the same errors as reported from others.

It appeared to me that the createConnection was actually invoking the connection to the database instead of declaring something I could use later. I solved this problem by moving the "var conn =" part of the code inside my dataQuery function as follows:

function dataQuery(query){
    var result = "";
    var conn = mysql.createConnection({
      host     : 'localhost',
      user     : 'root',
      password : '******',
      database : 'databasename'
    }); 
    conn.query(query, function(err, rows, fields) {
    if (!err)
        result = rows;
    else
        result = 'error';
    });
    conn.end();     
    return result;
}

This seems to work as I intended.. not sure if this will help others but please let me know if it does.

@dougwilson
Copy link
Member

@SeanDolan your issue is very different; essentially your issue is that for every one createConnection(), you can only call .end() on it once and then have to createConnection() for your next. You cannot re-use a connection after you ended it.

@ta3pks
Copy link

ta3pks commented Aug 27, 2015

i faced similar problem if you set connection variable to null inside the callback function you provide for .end() and set the connection variable by checking something like var cnn=cnn?cnn:mysql.createConnection(params) everything works fine

@ecs-hk
Copy link

ecs-hk commented Oct 19, 2015

Confirming the same issue @CamJN reported - using RHEL 6 x86_64 with Node v0.11.16.

events.js:85
      throw er; // Unhandled 'error' event
            ^
Error: shutdown ENOTCONN

As mentioned, it occurs at connection.end(), but only when the connection to MySQL was over SSL. (When the SSL connection option is removed, it works normally.)

Upgrading to Node's (current) long term support release - v4.2.1 - resolves this problem.

@talbensimhon
Copy link

I'm using "mysql": "2.11.1"

Got this call stack, after a few hours the connection was active. Is it the same problem?
Was it fixed?

events.js:141
throw er; // Unhandled 'error' event
^

Error: Connection lost: The server closed the connection.
at Protocol.end (C:\Users\talb\WebstormProjects\bsmartempty\node_modules\mysql\lib\protocol\Protocol.js:109:13)
at Socket. (C:\Users\talb\WebstormProjects\bsmartempty\node_modules\mysql\lib\Connection.js:115:28)
at emitNone (events.js:72:20)
at Socket.emit (events.js:166:7)
at endReadableNT (_stream_readable.js:921:12)
at nextTickCallbackWith2Args (node.js:442:9)
at process._tickCallback (node.js:356:17)

Process finished with exit code 1

@sidorares
Copy link
Member

@talbensimhon if you are not using pool you must attach 'error' event listener to connection object, as this is the only way to handle non-command level errors ( like this one - server decided to forcibly close connection )

@dougwilson
Copy link
Member

I'm going to close this old issue, as it was a Node.js core bug. Not sure if it was ever fixed, since the issue I opened with Node.js was never resolved.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Development

No branches or pull requests

7 participants