#connect callback invoked twice on authentication failure

[thelonious]

I'm testing some error cases, specifically authentication failures. I've noticed that my #connect callback will be invoked twice: once for the authentication failure, then, roughly a second later, another invocation for the socket being forcibly closed. Is this the expected behavior?

For reference, the first error is:

Error: Handshake terminated by server: 403 (ACCESS-REFUSED) with message "ACCESS_REFUSED - Login was refused using authentication mechanism PLAIN. For details see the broker logfile."

The second error is:

Error: Socket closed abruptly during opening handshake

And my test code is:

var fired = 1;

amqp.connect(url, function(error, connection) {
    if (fired === 1) {
        fired += 1;
        console.log(error);
        callback(error, connection);
    }
    else {
        console.log(error);
        console.log(`callback invoked ${fired} times`)
    }
});

I'm using node 8.2.1 and amqplib 0.5.2.

Thanks for any clarification on this.

[cressie176]

I've had similar problems relating to timeouts, but they were fixed in 0.5.2 (it was actually worse because I got a second successful connection). This was my workaround.

[thelonious]

Thanks @cressie176. I've ended up with something similar for now

[dnovvak]

I've encountered the same issue:

[2018-02-16 07:42:30.591] [INFO] [default] - Creating AMQP connection (URI: amqp://test_user:test_user@fps-rmq:5672/dummy) ...
[2018-02-16 07:42:30.599] [FATAL] [default] - Unable to create AMQP connection Error: Handshake terminated by server: 403 (ACCESS-REFUSED) with message "ACCESS_REFUSED - Login was refused using authentication mechanism PLAIN. For details see the broker logfile."
    at afterStartOk (/home/vcap/app/node_modules/amqplib/lib/connection.js:219:12)
    at /home/vcap/app/node_modules/amqplib/lib/connection.js:160:12
    at Socket.recv (/home/vcap/app/node_modules/amqplib/lib/connection.js:498:12)
    at Socket.g (events.js:292:16)
    at emitNone (events.js:86:13)
    at Socket.emit (events.js:185:7)
    at emitReadable_ (_stream_readable.js:432:10)
    at emitReadable (_stream_readable.js:426:7)
    at readableAddChunk (_stream_readable.js:187:13)
    at Socket.Readable.push (_stream_readable.js:134:10)
    at TCP.onread (net.js:559:20)
[2018-02-16 07:42:33.603] [FATAL] [default] - Unable to create AMQP connection { Error: read ECONNRESET
    at exports._errnoException (util.js:1020:11)
    at TCP.onread (net.js:580:26) code: 'ECONNRESET', errno: 'ECONNRESET', syscall: 'read' }

How to reproduce?
I've just restarted rabbitMQ server. My app lost connection and tried reconnect. After few unsuccessful attempts it had connected to the server again.

NOTE: I use own auto-reconnect module to handle connection errors a bit similar to rascal.

Tested with:
RabbitMQ 3.7.3
amqplib 0.5.2

[cressie176]

Still an issue...

const amqp = require('amqplib/callback_api');

let i = 0;
amqp.connect('amqp://foo:bar@localhost:5672', (err, connection) => {
  console.log(i++, err);
})

0 Error: Handshake terminated by server: 403 (ACCESS-REFUSED) with message "ACCESS_REFUSED - Login was refused using authentication mechanism PLAIN. For details see the broker logfile."
    at afterStartOk (/Users/steve/Development/cressie176/amqplib-402/node_modules/amqplib/lib/connection.js:220:12)
    at /Users/steve/Development/cressie176/amqplib-402/node_modules/amqplib/lib/connection.js:160:12
    at Socket.recv (/Users/steve/Development/cressie176/amqplib-402/node_modules/amqplib/lib/connection.js:499:12)
    at Object.onceWrapper (events.js:519:28)
    at Socket.emit (events.js:400:28)
    at emitReadable_ (internal/streams/readable.js:555:12)
    at processTicksAndRejections (internal/process/task_queues.js:81:21)
1 Error: Socket closed abruptly during opening handshake
    at Socket.endWhileOpening (/Users/steve/Development/cressie176/amqplib-402/node_modules/amqplib/lib/connection.js:260:17)
    at Socket.emit (events.js:412:35)
    at endReadableNT (internal/streams/readable.js:1334:12)
    at processTicksAndRejections (internal/process/task_queues.js:82:21)

This issue occurs when after kicking off the handshake the server is unhappy with something and replies with a ConnectionClose. amqplib invokes the callback with the error, but leaves the previously registered stream event handlers intact. A short while later the socket detects that it has been closed by the server, the end event it fired, causing the callback to be invoked a second time.

It also looks like there may be other problems with this code. There are a few places (1, 2, 3, 4 & 5) where it bails without notifying the server or closing the socket. If I'm right and the application retries instead of stopping we'll be left with a socket leak. If the dangling socket errors or is closed by the server then the callback will be called twice at that point.

[cressie176]

A quick experiment suggests removing the event handlers then ending the stream anywhere the code bails should do the job.

  function bail(err) {
    self.stream.removeAllListeners();
    self.stream.end();
    openCallback(err);
  }

[cressie176]

Seems done called twice on invalid options (PR 667 beat me to it. Included in v0.9.0