Uncaught Error: This socket is closed. MQTT connectivity issues

Hardware setup: Pico, wiznet 5500io, Dual relay module

I executed save() in the IDE to save the code.

Functionality:
Pico connects to my mqtt broker and sends commands to latch/unlatch my relay.

Odd behavior:
Code will execute even though there is an Error thrown; however, when I disconnect the Pico from the IDE the code doesn't execute. To debug this issue I disconnected the Pico from my computer and plugged it back in to reboot, but the code still doesn't execute.

I then connected the Pico to the IDE again. Once Console.log and the Error dumps out to the screen the code executes correctly again.

Error:

Uncaught Error: This socket is closed. at line 1 col 54
this.client&&this.client.write(g(d.PINGREQ<<4)+"\x00") ^ in function
"ping" called from line 1 col 8 a.ping() ^ in function called from
system

Code:

var MQTT_HOST = "192.168.0.22";
var PATH = "/mydevice/";
var mqtt;
var eth;

var inProcess =  false;
var shortPress = 1000; // ms 1 sec
var longPress = 5000; // ms 5 secs
var pressPin = B3;

function mqttMessage(pub) {
  console.log(
     "MQTT=> ",pub.topic,pub.message);
  if (pub.topic==PATH+"computer") {
    if (pub.message == "shutdown") {
      press(shortPress);
    }
  }
}

function mqttConnect() {
  console.log("mqttConnect");
  mqtt = require("MQTT").connect({
    host: MQTT_HOST,
  });
  mqtt.on('connected', function() {
    console.log("MQTT connected");
    // subscribe to wildcard for our name
    mqtt.subscribe(PATH+"#");
  });
  mqtt.on('publish', mqttMessage);
  mqtt.on('disconnected', function() {
    console.log("MQTT disconnected... reconnecting.");
    setTimeout(function() {
      mqtt.connect();
    }, 1000);
  });
}

function press(short) {
  // ignore press function when one is still going on
  if (inProcess) return;
  inProcess = true;

  //Relays act in an inverse manner
  //reset() will latch the relay
  pressPin.reset();
  mqtt.publish(PATH+"shutdown/status", 1);

  setTimeout(function(){
      //Relays act in an inverse manner
      //set() will unlatch the relay
      pressPin.set();

      inProcess = false;
    },(short) ? shortPress : longPress);
}

setWatch(function(e) {
  digitalWrite(LED1, e.state);
  press(shortPress);
}, BTN, { repeat: true });

function onInit() {
  console.log("Connecting to Ethernet");

  SPI2.setup({ mosi:B15, miso:B14, sck:B13 });
  eth = require("WIZnet").connect(SPI2, B10);

  isConnected = eth.setIP();

  if (isConnected == true) {
    mqttConnect();
  }
}

You might be hitting a classic Espruino USB issue here. What happens if you power it from a USB Wall supply or Power Bank?

Basically Espruino is using USB flow control and is trying not to lose any text that you output with console.log - it doesn't know if the PC isn't reading data because the IDE is busy, or because nothing is running, so when its output buffer gets full it just waits for it to start emptying before it continues.

It's a bit buried now, but it's worth checking out "I typed save() but Espruino won't work (or stops working quickly) when powered from a computer (it only works from a USB power supply, battery, or the computer when the Web IDE is running)" in http://www.espruino.com/Troubleshooting for a more detailed explanation.

As far as the MQTT message though, I'm not sure. Is it possible you were saving after running onInit (so it was basically saving with an open socket connection), or that you had 'save on send' turned on in the IDE so it was basically already saved?

@Gordon

Basically Espruino is using USB flow control and is trying not to lose
any text that you output with console.log - it doesn't know if the PC
isn't reading data because the IDE is busy, or because nothing is
running, so when its output buffer gets full it just waits for it to
start emptying before it continues.

That makes total sense. Is it possible for the espruino to check if it is connected to a computer, if not, don't output text or just periodically clear the buffer?

Is it possible you were saving after running onInit (so it was
basically saving with an open socket connection)

That sounds like what is going on. Does the current mqtt connection get terminated if the Pico looses power? Then once power is supplied again the mqtt connection should start back up as new? IF there is a fresh mqtt connection(without uploading/saving code again) I shouldn't be receiving the ping Uncaught Error as described earlier, but I still am.

Is it possible for the espruino to check if it is connected to a computer, if not, don't output text or just periodically clear the buffer?

That's what it does - hence why it works on a power bank. However it can't easily tell if an application is running on the PC or not, which is the frustrating bit :(

Does the current mqtt connection get terminated if the Pico looses power?

Yes - however what might have happened is when you save, it basically just stops everything right there, then kills all the socket connections. It means that the connection is killed, but by that point it's not running and JavaScript, so the JS never gets told the connection has been destroyed and so when it loads again it tries to use that connection and gets the error.

I guess the MQTT library could trap that error and then decide that the socket had closed and tidy up.

I re-flashed the firmware onto the PICO and changed the Save on Send setting to Direct to Flash (execute code at boot). I then uploaded the code again, waited a few minutes, and I haven't received the Uncaught Error. I also commented out all of my console.log code used for debugging purposes and the PICO stopped hanging waiting to dump out the buffer.

I guess the MQTT library could trap that error and then decide that
the socket had closed and tidy up.

Is this something that will need to be implemented into the Espruino firmware or is this something that I would need to code into the IDE? Either way I wouldn't know where to begin to "trap the error"

@Gordon

You might be hitting a classic Espruino USB issue here. What happens
if you power it from a USB Wall supply or Power Bank?

I apologize for overlooking your first question. I used an external power source and using my original code that I posted to this thread worked as expected. To double check this again I hooked the power source back to my computers usb port and after a few msgs sent back and forth the espruino stopped responding until I connected back to the IDE so the console.log can dump to the screen.

However, even though the ping error hasn't come back, it still bugs me :-/

Is this something that will need to be implemented into the Espruino firmware

It'd be done in the MQTT.js source code. I've just made some tweaks - please can you try using require("https://raw.githubusercontent.com/espruino/EspruinoDocs/master/modules/MQTT.js") in your code instead of just MQTT and see if that works? That'll use the version from GitHub rather than the one on the website.

However the issue would seem to be that you were uploading your code, running onInit() manually, and then calling save()? That could likely cause you other issues (like having multiple instances of the MQTT library kicking around), so I wonder how much it's worth bloating the MQTT lib to try and avoid that.

I'm not infront of my computer at the moment to check the require code.

However the issue would seem to be that you were uploading your code,
running onInit() manually, and then calling save()?

When I was getting the issue all I was doing was hitting the upload button then type save().

Now that I changed the Save on Send setting to "Direct to Flash (execute code at boot)" I haven't seen that Error again.

That could likely cause you other issues (like having multiple
instances of the MQTT library kicking around), so I wonder how much
it's worth bloating the MQTT lib to try and avoid that.

Honestly, I wouldn't spend too much time on that. I'm the only one that seemed to run across that issue. And hooking the pico into an external supply doesn't hang while waiting for text to be dumped, so it runs as expected.

require("https://raw.githubusercontent.c­om/espruino/EspruinoDocs/master/modules/­MQTT.js")

@Gordon. Before I tested your recommendations I unplugged the ethernet cable to my raspberrypi. waited a few moments and I received MQTT disconnected... reconnecting. which stayed there for a few more moments. Then I received "Uncaught Error: This socket is closed.".

I then reconnected everything and uploaded the code with the new require. Everything connected. Removed the lan cable again..... received the MQTT disconnected message. Waite a few more moments and no Error :-)

@Gordon I noticed after about 3 MQTT messages are received by the Espruino I get:

MQTT disconnected... reconnecting
MQTT connected

It's nothing major, everything seems to run.

Thank you for everything that you have been doing for Espruino community :-)

That's interesting - what happens if you switch back to the original MQTT?

Are you still doing the thing where you save when there's an active connection? It could be that the connection that was active when you saved tries to ping, and can't because it finds out it is closed. It'll then clean up and emit the disconnected event, so that it tries to reconnect.

However in the mean time you already created a second MQTT connection in onInit.

You could try replacing:

  mqtt.on('disconnected', function() {
    console.log("MQTT disconnected... reconnecting.");
    setTimeout(function() {
      mqtt.connect();
    }, 1000);
  });

with

  var thisMQTT = mqtt;
  mqtt.on('disconnected', function() {
    if (mqtt!=thisMQTT) {
      console.log("MQTT disconnected - but we already have a new MQTT");
      return;
    }
    console.log("MQTT disconnected... reconnecting.");
    setTimeout(function() {
      mqtt.connect();
    }, 1000);
  });

and see if that helps?

@Gordon

That's interesting - what happens if you switch back to the original
MQTT?

I executed reset(true) changed the mqtt require to mqtt = require("MQTT").connect then uploaded my code.
after about 3 mqtt messages I get: MQTT disconnected... reconnecting. Then mqtt reconnects with message MQTT connected

You could try replacing:

I changed the code with your suggestion, executed reset(true) then uploaded the code.
After about 3 messages I receive: MQTT disconnected... reconnecting. Then mqtt reconnects with message MQTT connected

code:

var MQTT_HOST = "192.168.0.17";
var PATH = "/mydevice/";
var mqtt;
var eth;

var inProcess =  false;
var shortPress = 1000; // ms 1 sec
var longPress = 5000; // ms 5 secs
var pressPin = B3;

// output like 'open collector' see reference
pinMode(pressPin,"opendrain"); 
pressPin.set();

function mqttMessage(pub) {
  console.log(
     "MQTT=> ",pub.topic,pub.message);
  if (pub.topic==PATH+"computer") {
    if (pub.message == "shutdown") {
      press(shortPress);
    }
  }
}

function mqttConnect() {
  console.log("mqttConnect");
  mqtt = require("MQTT").connect({
    host: MQTT_HOST,
  });
  mqtt.on('connected', function() {
    console.log("MQTT connected");
    // subscribe to wildcard for our name
    mqtt.subscribe(PATH+"#");
  });
  mqtt.on('publish', mqttMessage);
  var thisMQTT = mqtt;
  mqtt.on('disconnected', function() {
    if (mqtt!=thisMQTT) {
      console.log("MQTT disconnected - but we already have a new MQTT");
      return;
    }
    console.log("MQTT disconnected... reconnecting.");
    setTimeout(function() {
      mqtt.connect();
    }, 1000);
  });
}

function press(short) {
  // ignore press function when one is still going on
  if (inProcess) return; 
  inProcess = true;
  // Relays (board) act in an inverse manner
  // reset() will latch the relay
  pressPin.reset();
  setTimeout(function(){
      // Relays (board) act in an inverse manner
      // set() will unlatch the relay
      pressPin.set();
      inProcess = false;
    },(short) ? shortPress : longPress);
}

setWatch(function(e) {
  digitalWrite(LED1, e.state);
  press(shortPress);
}, BTN, { repeat: true });

function onInit() {
  console.log("Connecting to Ethernet");

  SPI2.setup({ mosi:B15, miso:B14, sck:B13 });
  eth = require("WIZnet").connect(SPI2, B10);

  isConnected = eth.setIP();

  if (isConnected == true) {
    mqttConnect();
  }
}

Is it good practice to execute reset(true) before I upload any new code in the future?

Is it good practice to execute reset(true) before I upload any new code in the future?

No, you should be fine without it - realistically it's only if you were switching the 'save on send' setting and you were sure you didn't want anything left behind (sometimes you might - eg if you're making your own bootloader ).

After about 3 messages I receive: MQTT disconnected... reconnecting

Ok - so this is unrelated to the recent changes then? What MQTT server are you using? Could you see if you can read the logs for it? It's entirely likely it doesn't like something that Espruino's MQTT client is doing, and so it drops it.

Ok - so this is unrelated to the recent changes then?

If I understood your question correctly... after about 3 messages I receive: MQTT disconnected... reconnecting for both mqtt = require("MQTT").connect({ and require("https://raw.githubusercontent.c­om/espruino/EspruinoDocs/master/modules/­MQTT.js").connect({

For the sake of debugging this, should I just use the normal require("MQTT")?

What MQTT server are you using?

I followed your guide: http://www.espruino.com/Home+Automation , I am using mosquitto.

Could you see if you can read the logs for it? It's entirely likely it
doesn't like something that Espruino's MQTT client is doing, and so it
drops it.

exceeded timeout and Socket error on client is what stood out the most. You are probably right, the mqtt broker doesn't like what the Espruino's MQTT client is doing, and so it drops the connection. I'm really not sure why or what the Socket error means and why I've exceeded the timeout, disconnecting. I executed mqtt in the console which spits out "keep_alive": 60 so, I'm not sure why it keeps timing out. So I can understand the keep_alive setting, does the Espruino mqtt client ping every 60 seconds to keep the session alive?

Log segment:

1533682953: New connection from 192.168.0.18 on port 1883.
1533682953: New client connected from 192.168.0.18 as 3b2ac31a3c98 (c1, k60).
1533683015: New connection from 192.168.0.9 on port 1883.
1533683015: New client connected from 192.168.0.9 as mqttjs_18553fd6 (c1, k60).
1533683016: Client 768aa6e0d3bc has exceeded timeout, disconnecting.
1533683016: Socket error on client 768aa6e0d3bc, disconnecting.
1533683121: Client 3b2ac31a3c98 has exceeded timeout, disconnecting.

Yes, you might as well use require("MQTT") for this.

Thanks for checking into this...

Looking at the code (here, if you're interested) it seems that the keep-alive and ping are very slightly different - but the end result is Espruino tells the server it has a keep-alive of 60s and then sends pings every 40s by default, which should be ok.

Having said that, it feels like there's something odd in the mosquitto log. What's the IP of the Espruino that's connecting? And do you know what mqttjs_18553fd6 is? that one doesn't seem to be causing any errors.

What's the IP of the Espruino that's connecting?

192.168.0.18

And do you know what mqttjs_18553fd6 is?

I created an Electron App using the mqttjs module. My Electron app just sends a mqtt message every 30 seconds with updates about the status of my computer.

Electron App code:

      const shutdown = require('electron-shutdown-command');
      var lockYourWindows = require('lock-your-windows');
      var mqtt = require('mqtt');
      var client  = mqtt.connect('mqtt://192.168.0.17', [{protocolId: 'MQTT'}]);
      client.on('connect', function () {
        client.subscribe('#');
      })

      client.on('message', function (topic, message) {
        // message is Buffer
        var msg = message.toString();
        //console.log(topic.toString());

        if(msg == "lockscreen") {
          var isLocked = lockYourWindows.isLocked();
          lockYourWindows.lock();
        }

        if(msg == "shutdown") {
          //shutdown.logoff();
        }

        if(msg == "logoff") {
          shutdown.logoff();
        }
      });

      function isScreenLocked() {
        var isLocked = lockYourWindows.isLocked();
        var v = isLocked ? 1 : 0;
        client.publish('/mydevice/lockscreen/status', v.toString());
      }

      // Ever 30 seconds send a MQTT msg to nodered to update the Lockscreen Status Guage
      setInterval(isScreenLocked, 30000);

Espruino IDE console:

MQTT=> /mydevice/lockscreen/status 0
MQTT=> /mydevice/lockscreen/status 0
MQTT=> /mydevice/lockscreen/status 0
MQTT disconnected... reconnecting.

Here is a new log:

1533770037: New connection from 192.168.0.18 on port 1883. 1533770037:
New client connected from 192.168.0.18 as 4de309a8004f (c1, k60).
1533770095: Client a7c51f6bdcc7 has exceeded timeout, disconnecting.
1533770095: Socket error on client a7c51f6bdcc7, disconnecting.
1533770363: New connection from 192.168.0.9 on port 1883. 1533770363:
New client connected from 192.168.0.9 as mqttjs_6ce48170 (c1, k60).
1533770480: Client 4de309a8004f has exceeded timeout, disconnecting.

Thanks - that definitely looks fine.

Can you try just publishing a random message every 10 seconds on the Pico and see if that helps? And also if you keep getting the messages on the server. I'm not sure why the built-in Ping wouldn't be doing it for you, but it'd be interesting to see if that fixed it - it might be that something has happened and the Pico isn't sending anything.

@Gordon You are definitely onto something.

I turned on verbose logging in mosquito. I didn't see a PINGREQ or a PINGRESP for the PICO. I uploaded a screen shot. I wish the log file wasn't so cluttered and easier to read/understand. PICO IP is now 192.168.0.89. I setup static IP for the PICO because I thought there might be an ip conflict, possibly causing that error, but that's not the case.

I am sending "Hello World!" mqtt message from the pico every 10 seconds. The Pico seems to work as expected WITHOUT those errors as I described earlier :-) I then commented out the setInterval and uploaded the code again. Now the PICO is disconnecting with the same error message :-(

It couldn't hurt for me to send an 'OK' message every few seconds from the PICO to nodered to keep everything up and running properly.

3 Attachments

Great - thanks! So it looks like the Ping isn't being sent at all? I'll take a look at the code and see if I can figure out why.

Please can you add the following code? I just tried this on desktop Espruino and it appears to be at least calling the 'ping' function:

mqtt._ping = mqtt.ping;mqtt.ping=function() { console.log("PING");this._ping(); }

@Gordon

I'm getting an error

Uncaught Error: Cannot read property '_ping' of undefined
at line 70 col 5
mqtt._ping = mqtt.ping;

Nevermind about that error. I moved the code into the onInit() function and only received one "PING" inside of the console. After the third mqtt message I get:

MQTT disconnected... reconnecting.
MQTT connected

I typed mqtt.ping() into the console and received "PING". I manually executed mqtt.ping() a few times and I haven't received those errors as of yet. So, I'm wondering if the PICO isn't pinging mosquito. To test that, I didn't manually ping the broker and after three messages I get:

MQTT disconnected... reconnecting.
MQTT connected

Update to my last post

I closed my Electron APP so there are no more mqtt messages being sent. I let the Espruino IDE just idle for a few minutes and I received multiple "PING" in the console. My mosquito log now shows PINGREQ and PINGRESP from the PICO.

PING seems to halt when messages are being received. To test this I opened my app again, after a few messages I get the same disconnected... reconnecting message. I then closed my app and PING seems to resume again and so does the PINGREQ and PINGRESP in my mosquito log file.

I also downloaded a chrome extension called mqttbox. I'm manually sending the same MQTT message using mqttbox every 30 seconds and again I'm getting the same disconnected... reconnecting. message in the console. I then just sent one message from mqttbox and waited... PING continued to resume without getting and MQTT disconnected... reconnecting. message.

I seem to not get the MQTT disconnected... message for any message received that was sent after 60 seconds. For example, I can send one message every 65 seconds and still receive a PINGREQ properly.

For my project the PICO doesn't need to receive EVERY single message over my mqtt network. Just only messages pertaining to the PICO; however, I will still run into the disconnected... issue if messages are received inside the 60 seconds keepalive window.

1 Attachment

Perfect - thanks for all your debugging!

That sounds like the issue then - I'd seen some code in the module that looked a bit odd... It reschedules the Ping whenever it receives data... So that means if it's always getting data but not sending anything, it won't get the ping and it'll time out.

I've just made a change - can you try require("https://raw.githubusercontent.c­om/espruino/EspruinoDocs/master/modules/­MQTT.js") again and see if that helps?