Skip to content
This repository has been archived by the owner on Feb 11, 2020. It is now read-only.

Error: This socket has been ended by the other party #67

Closed
ldstein opened this issue Nov 6, 2013 · 7 comments
Closed

Error: This socket has been ended by the other party #67

ldstein opened this issue Nov 6, 2013 · 7 comments

Comments

@ldstein
Copy link
Contributor

ldstein commented Nov 6, 2013

I'm evaluating a scenario where Mosca needs to be restarted, thereby causing a temporary connection failure between the broker and the client.

I'm simulating this by starting the Broker from the command line:

mosca -v | bunyan

then killing the process (CTRL-C) and restarting it.

Meanwhile, I have a simple NodeJS client which publishes every few seconds:

var mqtt = require('mqtt');

var c = 0;

var handleInterval = function()
{
    var topic = '/ping/' + c;
    c++;
    client.publish(topic, '');
    console.log('Published', topic);
}

var handleConnect = function()
{
    console.log('Connected to mqtt broker with ClientId:', client.options.clientId);
    client.subscribe('/ping/*');
}

var handleMessage = function(topic, message, packet)
{
    console.log('Received Message, topic:', topic, 'message length:', message.length ,'message:', message);
}

console.log('Connecting to broker...');
var client = mqtt.createClient(1883, 'localhost');

client.on('connect'   , handleConnect);
client.on('message'   , handleMessage);

var timer = setInterval(handleInterval, 3000);

On restarting Mosca, it will regularly fail and throw the following error:

[2013-11-06T07:55:15.074Z]  INFO: mosca/2680 on VIP-PC-LOE: server started (port=1883)
[2013-11-06T07:55:15.326Z]  INFO: mosca/2680 on VIP-PC-LOE: client connected (client=Patonga)
[2013-11-06T07:55:15.330Z]  INFO: mosca/2680 on VIP-PC-LOE: subscribed to topic(client=Patonga, topic=/ping/*, qos=0)
[2013-11-06T07:55:15.336Z]  INFO: mosca/2680 on VIP-PC-LOE: unsubscribed (client=Patonga, topic=/ping/*)
[2013-11-06T07:55:15.337Z]  INFO: mosca/2680 on VIP-PC-LOE: closed (client=Patonga)

Error: This socket has been ended by the other party
    at Socket.writeAfterFIN [as write] (net.js:276:12)
    at MqttServerClient.eval [as connack] (eval at <anonymous> (c:\nodeProjects\
nodist\bin\node_modules\mosca\node_modules\mqtt\lib\connection.js:58:29), <anony
mous>:2:126)
    at Client.completeConnection (c:\nodeProjects\nodist\bin\node_modules\mosca\
lib\client.js:277:14)
    at Socket.cleanup (c:\nodeProjects\nodist\bin\node_modules\mosca\lib\client.
js:507:7)
    at Socket.EventEmitter.emit (events.js:117:20)
    at _stream_readable.js:920:16
    at process._tickCallback (node.js:415:13)

The problem appears to stem from MQTT lib during a connack event, though I'm not yet familiar enough with the relationship between the two libs to provide a solution.

@ldstein
Copy link
Contributor Author

ldstein commented Nov 6, 2013

A little progress.

In mosca/node_modules/mqtt/lib/connection.js, line 49:

  var fun = "" +
  "   var p = this.generate." + v +"(opts); " +
  "   if (p instanceof Error) { " +
  "     this.emit('error', p) " +
  "   } else { " +
  "     this.stream.write(p) " +
  "   } "
  " } ";

stream.write is throwing an 'EPIPE' error. Try catch stops Mosca from falling over:

  "   } else { " +
  "     try{this.stream.write(p);}catch(e){console.log('ERROR', e)} " +
  "   } "

Appears to be specifically caused by the previous client connection being closed:

[2013-11-06T08:31:13.519Z]  INFO: mosca/5928 on VIP-PC-LOE: closed (client=Paton
ga)
[2013-11-06T08:31:13.519Z]  INFO: mosca/5928 on VIP-PC-LOE: client connected (cl
ient=Patonga)
Error { [Error: This socket has been ended by the other party] code: 'EPIPE' }

@mcollina
Copy link
Collaborator

mcollina commented Nov 6, 2013

What version of node are you in? On node v0.10.21 I was not able to reproduce it using your script.
However, the log you posted showed a 'subscribe' which is not included in the script.

@ldstein
Copy link
Contributor Author

ldstein commented Nov 6, 2013

My bad, I modified the client-test.js and didn't update the issue. Updated client.js:

var mqtt = require('mqtt');

var c = 0;

var handleInterval = function()
{
    var topic = '/ping/' + c;
    c++;
    client.publish(topic, '');
    console.log('Published', topic);
}

var handleConnect = function()
{
    console.log('Connected to mqtt broker with ClientId:', client.options.clientId);
    client.subscribe('/ping/*');
}

var handleMessage = function(topic, message, packet)
{
    console.log('Received Message, topic:', topic, 'message length:', message.length ,'message:', message);
}

console.log('Connecting to broker...');
var client = mqtt.createClient(1883, 'localhost');

client.on('connect'   , handleConnect);
client.on('message'   , handleMessage);

var timer = setInterval(handleInterval, 3000);

Here are associated outputs from both Client test script and Mosca. User interaction involves starting and stopping Mosca via command. Environment is Win8 x64, Node v0.10.21. Also tested running Mosca under Ubuntu 13.04, Node v0.10.21 with similar results.

Client Test:

C:\nodeProjects\nodist\bin\node.exe node-client-test\node-client-test.js
Connecting to broker...
Connected to mqtt broker with ClientId: mqttjs_aa44058e8ff6df81
Published /ping/0
Received Message, topic: /ping/0 message length: 0 message: 
Published /ping/1
Received Message, topic: /ping/1 message length: 0 message: 
Published /ping/2
Published /ping/3
Connected to mqtt broker with ClientId: mqttjs_aa44058e8ff6df81
Published /ping/4

Process finished with exit code -1

Mosca:

C:\>mosca -v | bunyan
[2013-11-06T09:48:54.386Z]  INFO: mosca/6668 on VIP-PC-LOE: server started (port
=1883)
[2013-11-06T09:48:57.997Z]  INFO: mosca/6668 on VIP-PC-LOE: client connected (cl
ient=mqttjs_aa44058e8ff6df81)
[2013-11-06T09:48:58.000Z]  INFO: mosca/6668 on VIP-PC-LOE: subscribed to topic
(client=mqttjs_aa44058e8ff6df81, topic=/ping/*, qos=0)
[2013-11-06T09:49:00.996Z]  INFO: mosca/6668 on VIP-PC-LOE: delivering message (
client=mqttjs_aa44058e8ff6df81, topic=/ping/0)
[2013-11-06T09:49:00.997Z]  INFO: mosca/6668 on VIP-PC-LOE: published packet (cl
ient=mqttjs_aa44058e8ff6df81)
    packet: {
      "topic": "/ping/0"
    }
[2013-11-06T09:49:04.007Z]  INFO: mosca/6668 on VIP-PC-LOE: delivering message (
client=mqttjs_aa44058e8ff6df81, topic=/ping/1)
[2013-11-06T09:49:04.008Z]  INFO: mosca/6668 on VIP-PC-LOE: published packet (cl
ient=mqttjs_aa44058e8ff6df81)
    packet: {
      "topic": "/ping/1"
    }
Terminate batch job (Y/N)? ^CTerminate batch job (Y/N)? y


C:\>mosca -v | bunyan
[2013-11-06T09:49:11.467Z]  INFO: mosca/8772 on VIP-PC-LOE: server started (port
=1883)
[2013-11-06T09:49:11.905Z]  INFO: mosca/8772 on VIP-PC-LOE: client connected (cl
ient=mqttjs_aa44058e8ff6df81)
[2013-11-06T09:49:11.915Z]  INFO: mosca/8772 on VIP-PC-LOE: published packet (cl
ient=mqttjs_aa44058e8ff6df81)
    packet: {
      "topic": "/ping/2"
    }
[2013-11-06T09:49:11.915Z]  INFO: mosca/8772 on VIP-PC-LOE: published packet (cl
ient=mqttjs_aa44058e8ff6df81)

    packet: {
      "topic": "/ping/3"
    }
Error: This socket has been ended by the other party
    at Socket.writeAfterFIN [as write] (net.js:276:12)
    at MqttServerClient.eval [as connack] (eval at <anonymous> (c:\nodeProjects\
nodist\bin\node_modules\mosca\node_modules\mqtt\lib\connection.js:58:29), <anony
mous>:2:126)
    at Client.completeConnection (c:\nodeProjects\nodist\bin\node_modules\mosca\
lib\client.js:277:14)
    at Socket.cleanup (c:\nodeProjects\nodist\bin\node_modules\mosca\lib\client.
js:507:7)
    at Socket.EventEmitter.emit (events.js:117:20)
    at _stream_readable.js:920:16
    at process._tickCallback (node.js:415:13)

C:\>�

@ldstein
Copy link
Contributor Author

ldstein commented Nov 6, 2013

Same test with Ubuntu. Here you can see the error is not always thrown on stop/restart of Mosca:

Client.js console output:

C:\nodeProjects\nodist\bin\node.exe node-client-test\node-client-test.js
Connecting to broker...
Connected to mqtt broker with ClientId: mqttjs_7020c184ce0e25fd
Published /ping/0
Received Message, topic: /ping/0 message length: 0 message: 
Published /ping/1
Received Message, topic: /ping/1 message length: 0 message: 
Published /ping/2
Published /ping/3
Connected to mqtt broker with ClientId: mqttjs_7020c184ce0e25fd
Published /ping/4
Received Message, topic: /ping/4 message length: 0 message: 
Published /ping/5
Received Message, topic: /ping/5 message length: 0 message: 
Published /ping/6
Published /ping/7
Connected to mqtt broker with ClientId: mqttjs_7020c184ce0e25fd
Published /ping/8
Received Message, topic: /ping/8 message length: 0 message: 
Published /ping/9
Connected to mqtt broker with ClientId: mqttjs_7020c184ce0e25fd
Published /ping/10
Received Message, topic: /ping/10 message length: 0 message: 
Published /ping/11
Published /ping/12
Published /ping/13
Connected to mqtt broker with ClientId: mqttjs_7020c184ce0e25fd
Published /ping/14
Received Message, topic: /ping/14 message length: 0 message: 
Published /ping/15
Connected to mqtt broker with ClientId: mqttjs_7020c184ce0e25fd
Published /ping/16

Mosca Bunyan output:

loe@loe-VirtualBox:~$ mosca -v | bunyan
[2013-11-06T10:08:50.867Z]  INFO: mosca/3347 on loe-VirtualBox: server started (port=1883)
[2013-11-06T10:08:52.852Z]  INFO: mosca/3347 on loe-VirtualBox: client connected (client=mqttjs_7020c184ce0e25fd)
[2013-11-06T10:08:52.856Z]  INFO: mosca/3347 on loe-VirtualBox: subscribed to topic (client=mqttjs_7020c184ce0e25fd, topic=/ping/*, qos=0)
[2013-11-06T10:08:55.853Z]  INFO: mosca/3347 on loe-VirtualBox: delivering message (client=mqttjs_7020c184ce0e25fd, topic=/ping/0)
[2013-11-06T10:08:55.855Z]  INFO: mosca/3347 on loe-VirtualBox: published packet (client=mqttjs_7020c184ce0e25fd)
    packet: {
      "topic": "/ping/0"
    }
[2013-11-06T10:08:58.862Z]  INFO: mosca/3347 on loe-VirtualBox: delivering message (client=mqttjs_7020c184ce0e25fd, topic=/ping/1)
[2013-11-06T10:08:58.863Z]  INFO: mosca/3347 on loe-VirtualBox: published packet (client=mqttjs_7020c184ce0e25fd)
    packet: {
      "topic": "/ping/1"
    }
^Cleo@loe-VirtualBox:~$ mosca -v | bunyan
[2013-11-06T10:09:07.054Z]  INFO: mosca/3351 on loe-VirtualBox: server started (port=1883)
[2013-11-06T10:09:07.529Z]  INFO: mosca/3351 on loe-VirtualBox: client connected (client=mqttjs_7020c184ce0e25fd)
[2013-11-06T10:09:07.540Z]  INFO: mosca/3351 on loe-VirtualBox: published packet (client=mqttjs_7020c184ce0e25fd)
    packet: {
      "topic": "/ping/2"
    }
[2013-11-06T10:09:07.575Z]  INFO: mosca/3351 on loe-VirtualBox: published packet (client=mqttjs_7020c184ce0e25fd)
    packet: {
      "topic": "/ping/3"
    }
[2013-11-06T10:09:07.575Z]  INFO: mosca/3351 on loe-VirtualBox: subscribed to topic (client=mqttjs_7020c184ce0e25fd, topic=/ping/*, qos=0)
[2013-11-06T10:09:07.875Z]  INFO: mosca/3351 on loe-VirtualBox: delivering message (client=mqttjs_7020c184ce0e25fd, topic=/ping/4)
[2013-11-06T10:09:07.876Z]  INFO: mosca/3351 on loe-VirtualBox: published packet (client=mqttjs_7020c184ce0e25fd)
    packet: {
      "topic": "/ping/4"
    }
[2013-11-06T10:09:10.876Z]  INFO: mosca/3351 on loe-VirtualBox: delivering message (client=mqttjs_7020c184ce0e25fd, topic=/ping/5)
[2013-11-06T10:09:10.877Z]  INFO: mosca/3351 on loe-VirtualBox: published packet (client=mqttjs_7020c184ce0e25fd)
    packet: {
      "topic": "/ping/5"
    }
^Cleo@loe-VirtualBox:~$ mosca -v | bunyan
[2013-11-06T10:09:17.793Z]  INFO: mosca/3355 on loe-VirtualBox: server started (port=1883)
[2013-11-06T10:09:18.156Z]  INFO: mosca/3355 on loe-VirtualBox: client connected (client=mqttjs_7020c184ce0e25fd)
[2013-11-06T10:09:18.166Z]  INFO: mosca/3355 on loe-VirtualBox: published packet (client=mqttjs_7020c184ce0e25fd)
    packet: {
      "topic": "/ping/6"
    }
[2013-11-06T10:09:18.200Z]  INFO: mosca/3355 on loe-VirtualBox: published packet (client=mqttjs_7020c184ce0e25fd)
    packet: {
      "topic": "/ping/7"
    }
[2013-11-06T10:09:18.201Z]  INFO: mosca/3355 on loe-VirtualBox: subscribed to topic (client=mqttjs_7020c184ce0e25fd, topic=/ping/*, qos=0)
[2013-11-06T10:09:19.895Z]  INFO: mosca/3355 on loe-VirtualBox: delivering message (client=mqttjs_7020c184ce0e25fd, topic=/ping/8)
[2013-11-06T10:09:19.896Z]  INFO: mosca/3355 on loe-VirtualBox: published packet (client=mqttjs_7020c184ce0e25fd)
    packet: {
      "topic": "/ping/8"
    }
^Cleo@loe-VirtualBox:~$ mosca -v | bunyan
[2013-11-06T10:09:24.592Z]  INFO: mosca/3359 on loe-VirtualBox: server started (port=1883)
[2013-11-06T10:09:24.952Z]  INFO: mosca/3359 on loe-VirtualBox: client connected (client=mqttjs_7020c184ce0e25fd)
[2013-11-06T10:09:24.963Z]  INFO: mosca/3359 on loe-VirtualBox: published packet (client=mqttjs_7020c184ce0e25fd)
    packet: {
      "topic": "/ping/9"
    }
[2013-11-06T10:09:24.995Z]  INFO: mosca/3359 on loe-VirtualBox: subscribed to topic (client=mqttjs_7020c184ce0e25fd, topic=/ping/*, qos=0)
[2013-11-06T10:09:25.895Z]  INFO: mosca/3359 on loe-VirtualBox: delivering message (client=mqttjs_7020c184ce0e25fd, topic=/ping/10)
[2013-11-06T10:09:25.899Z]  INFO: mosca/3359 on loe-VirtualBox: published packet (client=mqttjs_7020c184ce0e25fd)
    packet: {
      "topic": "/ping/10"
    }
^Cleo@loe-VirtualBox:~$ mosca -v | bunyan
[2013-11-06T10:09:36.105Z]  INFO: mosca/3363 on loe-VirtualBox: server started (port=1883)
[2013-11-06T10:09:36.148Z]  INFO: mosca/3363 on loe-VirtualBox: client connected (client=mqttjs_7020c184ce0e25fd)
[2013-11-06T10:09:36.152Z]  INFO: mosca/3363 on loe-VirtualBox: published packet (client=mqttjs_7020c184ce0e25fd)
    packet: {
      "topic": "/ping/11"
    }
[2013-11-06T10:09:36.187Z]  INFO: mosca/3363 on loe-VirtualBox: published packet (client=mqttjs_7020c184ce0e25fd)
    packet: {
      "topic": "/ping/12"
    }
[2013-11-06T10:09:36.187Z]  INFO: mosca/3363 on loe-VirtualBox: published packet (client=mqttjs_7020c184ce0e25fd)
    packet: {
      "topic": "/ping/13"
    }
[2013-11-06T10:09:36.188Z]  INFO: mosca/3363 on loe-VirtualBox: subscribed to topic (client=mqttjs_7020c184ce0e25fd, topic=/ping/*, qos=0)
[2013-11-06T10:09:37.919Z]  INFO: mosca/3363 on loe-VirtualBox: delivering message (client=mqttjs_7020c184ce0e25fd, topic=/ping/14)
[2013-11-06T10:09:37.920Z]  INFO: mosca/3363 on loe-VirtualBox: published packet (client=mqttjs_7020c184ce0e25fd)
    packet: {
      "topic": "/ping/14"
    }
^Cleo@loe-VirtualBox:~$ mosca -v | bunyan
[2013-11-06T10:09:41.744Z]  INFO: mosca/3367 on loe-VirtualBox: server started (port=1883)
[2013-11-06T10:09:42.122Z]  INFO: mosca/3367 on loe-VirtualBox: client connected (client=mqttjs_7020c184ce0e25fd)
[2013-11-06T10:09:42.140Z]  INFO: mosca/3367 on loe-VirtualBox: published packet (client=mqttjs_7020c184ce0e25fd)
    packet: {
      "topic": "/ping/15"
    }
[2013-11-06T10:09:42.146Z]  INFO: mosca/3367 on loe-VirtualBox: subscribed to topic (client=mqttjs_7020c184ce0e25fd, topic=/ping/*, qos=0)
[2013-11-06T10:09:42.154Z]  WARN: mosca/3367 on loe-VirtualBox: write after end (client=mqttjs_7020c184ce0e25fd)
    Error: write after end
        at writeAfterEnd (_stream_writable.js:130:12)
        at Socket.Writable.write (_stream_writable.js:178:5)
        at Socket.write (net.js:613:40)
        at MqttServerClient.eval [as suback] (eval at <anonymous> (/usr/local/lib/node_modules/mosca/node_modules/mqtt/lib/connection.js:58:29), <anonymous>:2:125)
        at /usr/local/lib/node_modules/mosca/lib/client.js:399:23
        at /usr/local/lib/node_modules/mosca/node_modules/async/lib/async.js:229:13
        at /usr/local/lib/node_modules/mosca/node_modules/async/lib/async.js:116:25
        at /usr/local/lib/node_modules/mosca/node_modules/async/lib/async.js:24:16
        at /usr/local/lib/node_modules/mosca/node_modules/async/lib/async.js:226:17
        at /usr/local/lib/node_modules/mosca/node_modules/async/lib/async.js:513:34
[2013-11-06T10:09:42.157Z]  INFO: mosca/3367 on loe-VirtualBox: closed (client=mqttjs_7020c184ce0e25fd)
[2013-11-06T10:09:42.159Z]  INFO: mosca/3367 on loe-VirtualBox: client connected (client=mqttjs_7020c184ce0e25fd)

Error: This socket has been ended by the other party
    at Socket.writeAfterFIN [as write] (net.js:276:12)
    at MqttServerClient.eval [as connack] (eval at <anonymous> (/usr/local/lib/node_modules/mosca/node_modules/mqtt/lib/connection.js:58:29), <anonymous>:2:126)
    at Client.completeConnection (/usr/local/lib/node_modules/mosca/lib/client.js:277:14)
    at Socket.cleanup (/usr/local/lib/node_modules/mosca/lib/client.js:507:7)
    at Socket.EventEmitter.emit (events.js:117:20)
    at _stream_readable.js:920:16
loe@loe-VirtualBox:~$
    at process._tickCallback (node.js:415:13)

@mcollina
Copy link
Collaborator

mcollina commented Nov 6, 2013

Are you using the latest version of Mosca?
I'm not able to reproduce on my Mac system running the master branch. Something very weird is going on.

Could you provide a test that exhibit this reliably? Otherwise it's very hard to debug and fix.

Looking at node source shows that it's not throwing, but rather it's emitting an error:
https://github.com/joyent/node/blob/v0.10.21-release/lib/net.js#L267-L286.
I'm not sure why a try-catch solves it.

From the log it seems the connection has a problem and it is closed down, then Mosca try writing something more there.

I think I got the problem, after this line https://github.com/mcollina/mosca/blob/master/lib/client.js#L495, try adding:

// ignore all errors after we close
this.connection.on('error', function() {});

@ldstein
Copy link
Contributor Author

ldstein commented Nov 6, 2013

Cool, that appears to solve the issue:

// ignore all errors after we close
that.connection.on('error', function() {});

@mcollina
Copy link
Collaborator

mcollina commented Nov 6, 2013

Released as 0.13.3.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants