Constantly disconnecting from Mosquitto (again)

[Julian Knight]

Hi all,

I'm once again getting the problem of constantly disconnecting/reconnecting to Mosquitto on the Pi2.

I've even gone so far as to remove the contrib-mongodb node and configuration and even stop mongodb service. But although that has slowed things down, I'm still getting the problem. It seemed to have gone away but has now returned after me doing an npm update on my NR installation. I did that because it had been suggested that the mongodb node was causing an issue in a previous thread.

Example log output:

Dec 20 15:47:18 pi2 NR-Live2[1170]: 20 Dec 15:47:18 - [info] [mqtt-broker:3b2726f7.c4d8da] Disconnected from broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:47:23 pi2 NR-Live2[1170]: 20 Dec 15:47:23 - [info] [mqtt-broker:3b2726f7.c4d8da] Connected to broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:47:23 pi2 NR-Live2[1170]: 20 Dec 15:47:23 - [info] [mqtt-broker:3b2726f7.c4d8da] Disconnected from broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:47:23 pi2 NR-Live2[1170]: 20 Dec 15:47:23 - [info] [mqtt-broker:3b2726f7.c4d8da] Connected to broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:47:23 pi2 NR-Live2[1170]: 20 Dec 15:47:23 - [info] [mqtt-broker:3b2726f7.c4d8da] Disconnected from broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:47:28 pi2 NR-Live2[1170]: 20 Dec 15:47:28 - [info] [mqtt-broker:3b2726f7.c4d8da] Connected to broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:47:28 pi2 NR-Live2[1170]: 20 Dec 15:47:28 - [info] [mqtt-broker:3b2726f7.c4d8da] Connected to broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:47:29 pi2 NR-Live2[1170]: 20 Dec 15:47:29 - [info] [mqtt-broker:3b2726f7.c4d8da] Disconnected from broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:47:33 pi2 NR-Live2[1170]: 20 Dec 15:47:33 - [info] [mqtt-broker:3b2726f7.c4d8da] Connected to broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:47:33 pi2 NR-Live2[1170]: 20 Dec 15:47:33 - [info] [mqtt-broker:3b2726f7.c4d8da] Disconnected from broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:47:34 pi2 NR-Live2[1170]: 20 Dec 15:47:34 - [info] [mqtt-broker:3b2726f7.c4d8da] Connected to broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:47:34 pi2 NR-Live2[1170]: 20 Dec 15:47:34 - [info] [mqtt-broker:3b2726f7.c4d8da] Disconnected from broker: Pi2_NR-Live@mqtt://localhost:1883

mosquitto version 1.4.5 (build date Sun, 08 Nov 2015 21:43:12 +0000)

Instance is running:

Dec 20 15:54:05 pi2 NR-Live2[1596]: 20 Dec 15:54:05 - [info] Node-RED version: v0.12.4

Dec 20 15:54:05 pi2 NR-Live2[1596]: 20 Dec 15:54:05 - [info] Node.js  version: v0.10.28

When my original instance of NR is running, which connects to mongodb, the new instance goes mad:

Dec 20 15:50:30 pi2 NR-Live2[1170]: 20 Dec 15:50:30 - [info] [mqtt-broker:3b2726f7.c4d8da] Connected to broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:50:30 pi2 NR-Live2[1170]: 20 Dec 15:50:30 - [info] [mqtt-broker:3b2726f7.c4d8da] Disconnected from broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:50:30 pi2 NR-Live2[1170]: 20 Dec 15:50:30 - [info] [mqtt-broker:3b2726f7.c4d8da] Connected to broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:50:31 pi2 NR-Live2[1170]: 20 Dec 15:50:31 - [info] [mqtt-broker:3b2726f7.c4d8da] Disconnected from broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:50:31 pi2 NR-Live2[1170]: 20 Dec 15:50:31 - [info] [mqtt-broker:3b2726f7.c4d8da] Connected to broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:50:31 pi2 NR-Live2[1170]: 20 Dec 15:50:31 - [info] [mqtt-broker:3b2726f7.c4d8da] Connected to broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:50:31 pi2 NR-Live2[1170]: 20 Dec 15:50:31 - [info] [mqtt-broker:3b2726f7.c4d8da] Disconnected from broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:50:31 pi2 NR-Live2[1170]: 20 Dec 15:50:31 - [info] [mqtt-broker:3b2726f7.c4d8da] Connected to broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:50:31 pi2 NR-Live2[1170]: 20 Dec 15:50:31 - [info] [mqtt-broker:3b2726f7.c4d8da] Disconnected from broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:50:31 pi2 NR-Live2[1170]: 20 Dec 15:50:31 - [info] [mqtt-broker:3b2726f7.c4d8da] Connected to broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:50:32 pi2 NR-Live2[1170]: 20 Dec 15:50:32 - [info] [mqtt-broker:3b2726f7.c4d8da] Connected to broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:50:32 pi2 NR-Live2[1170]: 20 Dec 15:50:32 - [info] [mqtt-broker:3b2726f7.c4d8da] Disconnected from broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:50:32 pi2 NR-Live2[1170]: 20 Dec 15:50:32 - [info] [mqtt-broker:3b2726f7.c4d8da] Connected to broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:50:32 pi2 NR-Live2[1170]: 20 Dec 15:50:32 - [info] [mqtt-broker:3b2726f7.c4d8da] Disconnected from broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:50:32 pi2 NR-Live2[1170]: 20 Dec 15:50:32 - [info] [mqtt-broker:3b2726f7.c4d8da] Connected to broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:50:32 pi2 NR-Live2[1170]: 20 Dec 15:50:32 - [info] [mqtt-broker:3b2726f7.c4d8da] Disconnected from broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:50:32 pi2 NR-Live2[1170]: 20 Dec 15:50:32 - [info] [mqtt-broker:3b2726f7.c4d8da] Connected to broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:50:32 pi2 NR-Live2[1170]: 20 Dec 15:50:32 - [info] [mqtt-broker:3b2726f7.c4d8da] Disconnected from broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:50:32 pi2 NR-Live2[1170]: 20 Dec 15:50:32 - [info] [mqtt-broker:3b2726f7.c4d8da] Connected to broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:50:32 pi2 NR-Live2[1170]: 20 Dec 15:50:32 - [info] [mqtt-broker:3b2726f7.c4d8da] Disconnected from broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:50:32 pi2 NR-Live2[1170]: 20 Dec 15:50:32 - [info] [mqtt-broker:3b2726f7.c4d8da] Connected to broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:50:33 pi2 NR-Live2[1170]: 20 Dec 15:50:33 - [info] [mqtt-broker:3b2726f7.c4d8da] Disconnected from broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:50:33 pi2 NR-Live2[1170]: 20 Dec 15:50:33 - [info] [mqtt-broker:3b2726f7.c4d8da] Connected to broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:50:33 pi2 NR-Live2[1170]: 20 Dec 15:50:33 - [info] [mqtt-broker:3b2726f7.c4d8da] Disconnected from broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:50:33 pi2 NR-Live2[1170]: 20 Dec 15:50:33 - [info] [mqtt-broker:3b2726f7.c4d8da] Connected to broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:50:33 pi2 NR-Live2[1170]: 20 Dec 15:50:33 - [info] [mqtt-broker:3b2726f7.c4d8da] Disconnected from broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:50:33 pi2 NR-Live2[1170]: 20 Dec 15:50:33 - [info] [mqtt-broker:3b2726f7.c4d8da] Connected to broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:50:33 pi2 NR-Live2[1170]: 20 Dec 15:50:33 - [info] [mqtt-broker:3b2726f7.c4d8da] Connected to broker: Pi2_NR-Live@mqtt://localhost:1883

Dec 20 15:50:33 pi2 NR-Live2[1170]: 20 Dec 15:50:33 - [info] [mqtt-broker:3b2726f7.c4d8da] Connected to broker: Pi2_NR-Live@mqtt://localhost:1883

Even though the original instance is working absolutely fine. Of course the original instance doesn't get updated at the moment because the updates tend to break things that I haven't had time to re-engineer as yet.

Original Instance is running:

Dec 20 15:52:46 pi2 NR-test[1526]: 20 Dec 15:52:46 - [info] Node-RED version: v0.11.1

Dec 20 15:52:46 pi2 NR-test[1526]: 20 Dec 15:52:46 - [info] Node.js  version: v0.10.28

This is now driving me a little crazy. It fills up my logs so I can't see what is going on. Can anyone help?!

[Nicholas O'Leary]

I have now seen something similar once last week, although I wasn't in a position to debug at the time and I've not been able to recreate.

It would be useful to know if you have the corresponding broker logs? Most interested in the logs when the disconnect first started. That will give a clue as to what the broker though was happening - the rapid disconnect cycles will be likely due to duplicate client id connections, but it may have been triggered by a keepalive timeout... it's those sorts of details from the broker logs that help to understand the underlying cause.

Nick

--
http://nodered.org
---
You received this message because you are subscribed to the Google Groups "Node-RED" group.
To unsubscribe from this group and stop receiving emails from it, send an email to node-red+u...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Julian Knight]

Hi Nick, thanks for responding.

I'm afraid the broker logs are distinctly uninformative:

-- Logs begin at Sun 2015-12-20 15:25:37 GMT. --

Dec 20 15:25:39 pi2 systemd[1]: Starting LSB: mosquitto MQTT v3.1 message broker...

Dec 20 15:25:40 pi2 mosquitto[422]: Starting network daemon:: mosquitto.

Dec 20 15:25:40 pi2 systemd[1]: Started LSB: mosquitto MQTT v3.1 message broker.

That is since the last restart of Mosquitto of course but I've restarted NR several times since then and it is currently going absolutely bananas! With at least 5 connect/disconnect pairs each second.

[Julian Knight]

Can I turn up the loggin in Mosquitto perhaps?

[Nicholas O'Leary]

Hmm, mosquitto normally logs connects/disconnects by default.

So you are hitting the Connect/disconnect as soon as you start NR?

Have you got multiple mqtt-broker nodes or just the one? Have you got clientid hardcoded?

I'm away from my laptop until Tuesday, so not going to be able to debug properly until then - but be assured it is a top priority to resolve before the next release.

Nick

[Julian Knight]

I'm not sure what is going on with the logs to be honest. I've just updated to include more detail but it isn't working. I'm thinking I'm not looking in the right place.

I do have 2 broker configurations. One internal on the same Pi and that is the one that is having problems. The other is to Owntracks.

Yes, client id is hard coded to: "Pi2_NR-Live", nothing else uses that client id. Keep alive is 15s and I'm not using legacy v3.1. No security configured at present - no other access is available to the Pi other than my dev machine. I do have both a startup and a Will message.

I'll try and track down something more useful on the log front. 

By the way, there seem to be a number of things that cause the problem to go into overdrive which kills NR as it effectively locks it into a loop. The Pi isn't powerful enough to keep up. Resetting NR seems to slow it down again to around one connect/disconnect pair per 10 sec. Though even as we speak I'm watching it creep back up again.

[Nicholas O'Leary]

Can you try running without setting the clientid - ie let it pick a random one.

That would rule out the case that something else is using the clientid so what you are seeing is dueling clients competing to stay connected with that id.

Nick

[Nicholas O'Leary]

You could also try temporarily running mosquitto manually, rather then via systemd. That will get you the log output straight into the terminal.

[Julian Knight]

Right, I found the correct log this time! I'm still not quite familiar with systemd.

I reset the log so this is the output from the startup of Mosquitto with 2 instances of NR running:

1450631649: mosquitto version 1.4.5 (build date Sun, 08 Nov 2015 21:43:12 +0000) starting

1450631649: Config loaded from /etc/mosquitto/mosquitto.conf.

1450631649: Opening ipv4 listen socket on port 1883.

1450631649: Opening ipv6 listen socket on port 1883.

1450631649: Opening websockets listen socket on port 9001.

1450631649: New connection from 127.0.0.1 on port 1883.

1450631649: Client Pi2_NR-Live disconnected.

1450631649: New client connected from 127.0.0.1 as Pi2_NR-Live (c0, k15).

1450631649: Pi2_NR-Live 2 HARDWARE-IN/#

1450631649: Client mqttjs_browser disconnected.

1450631649: New client connected from 192.168.1.108 as mqttjs_browser (c0, k15).

1450631649: Pi2_NR-Live 2 COMMAND/#

1450631649: Outgoing messages are being dropped for client Pi2_NR-Live.

1450631649: Pi2_NR-Live 2 TEMPERATURE/HOME/IN/00/HALL/0x3001

1450631649: Pi2_NR-Live 2 TEMPERATURE/HOME/IN/02/LOFT/NANO1

1450631649: mqttjs_browser 1 #

1450631649: Pi2_NR-Live 2 TEMPERATURE/HOME/IN/02/LOFT/UNO1

1450631649: Pi2_NR-Live 2 HUMIDITY/HOME/IN/00/HALL/0x3001

1450631649: Pi2_NR-Live 2 HUMIDITY/HOME/IN/02/LOFT/NANO1

1450631649: Pi2_NR-Live 2 HUMIDITY/HOME/IN/02/LOFT/UNO1

1450631649: Pi2_NR-Live 2 PRESSURE/HOME/IN/02/LOFT/UNO1

1450631649: Pi2_NR-Live 2 DEVICES/#

1450631649: New connection from 127.0.0.1 on port 1883.

1450631649: New client connected from 127.0.0.1 as Pi2-NR (c1, k15, u'Pi2-NR').

1450631649: Pi2-NR 2 COMMAND/#

1450631649: Pi2-NR 2 SENSORS/#

1450631649: Pi2-NR 2 CONTROLS/#

1450631649: Pi2-NR 2 COMMAND/BELL01

1450631649: Pi2-NR 2 SENSORS/S/Bell_AC01/AC/RFX

1450631649: Pi2-NR 2 MOVEMENT/#

1450631649: Pi2-NR 2 LIGHT/HOME/IN/03/LOFT/#

1450631649: Pi2-NR 2 TEMPERATURE/HOME/IN/01/HALL/0x3001

1450631649: Pi2-NR 2 HUMIDITY/HOME/IN/01/HALL/0x3001

1450631649: Pi2-NR 2 SENSORS/TH/TH_OR01/OR/RFX

1450631649: Pi2-NR 2 SENSORS/THLP/THL_AR01/AR/SRF

1450631649: Pi2-NR 2 SENSORS/S/MagSw_MS01/LWRF/RFX

1450631649: Pi2-NR 2 SENSORS/M/PIR_HE01/HE/RFX

1450631649: Pi2-NR 2 SENSORS/THL/THL_AR02/AR/USB

1450631649: Socket error on client Pi2_NR-Live, disconnecting.

1450631650: New connection from 127.0.0.1 on port 1883.

1450631650: Client Pi2_NR-Live disconnected.

1450631650: New client connected from 127.0.0.1 as Pi2_NR-Live (c0, k15).

1450631650: Outgoing messages are being dropped for client Pi2_NR-Live.

1450631650: New connection from 127.0.0.1 on port 1883.

1450631650: Client Pi2_NR-Live already connected, closing old connection.

1450631650: Client Pi2_NR-Live disconnected.

1450631650: New client connected from 127.0.0.1 as Pi2_NR-Live (c0, k15).

1450631650: Outgoing messages are being dropped for client Pi2_NR-Live.

1450631650: New connection from 127.0.0.1 on port 1883.

1450631650: Client Pi2_NR-Live already connected, closing old connection.

1450631650: Client Pi2_NR-Live disconnected.

1450631650: New client connected from 127.0.0.1 as Pi2_NR-Live (c0, k15).

1450631650: Outgoing messages are being dropped for client Pi2_NR-Live.

1450631650: New connection from 127.0.0.1 on port 1883.

1450631650: Client Pi2_NR-Live already connected, closing old connection.

1450631650: Client Pi2_NR-Live disconnected.

1450631650: New client connected from 127.0.0.1 as Pi2_NR-Live (c0, k15).

1450631650: Outgoing messages are being dropped for client Pi2_NR-Live.

1450631650: New connection from 127.0.0.1 on port 1883.

1450631650: Client Pi2_NR-Live already connected, closing old connection.

1450631650: Client Pi2_NR-Live disconnected.

1450631650: New client connected from 127.0.0.1 as Pi2_NR-Live (c0, k15).

1450631650: Outgoing messages are being dropped for client Pi2_NR-Live.

1450631650: New connection from 127.0.0.1 on port 1883.

1450631650: Client Pi2_NR-Live already connected, closing old connection.

1450631650: Client Pi2_NR-Live disconnected.

1450631650: New client connected from 127.0.0.1 as Pi2_NR-Live (c0, k15).

1450631650: Outgoing messages are being dropped for client Pi2_NR-Live.

1450631651: New connection from 127.0.0.1 on port 1883.

1450631651: Client Pi2_NR-Live already connected, closing old connection.

1450631651: Client Pi2_NR-Live disconnected.

1450631651: New client connected from 127.0.0.1 as Pi2_NR-Live (c0, k15).

1450631651: Outgoing messages are being dropped for client Pi2_NR-Live.

1450631651: New connection from 127.0.0.1 on port 1883.

1450631651: Client Pi2_NR-Live already connected, closing old connection.

1450631651: Client Pi2_NR-Live disconnected.

1450631651: New client connected from 127.0.0.1 as Pi2_NR-Live (c0, k15).

1450631651: Outgoing messages are being dropped for client Pi2_NR-Live.

1450631651: New connection from 127.0.0.1 on port 1883.

1450631651: Client Pi2_NR-Live already connected, closing old connection.

1450631651: Client Pi2_NR-Live disconnected.

1450631651: New client connected from 127.0.0.1 as Pi2_NR-Live (c0, k15).

1450631651: Outgoing messages are being dropped for client Pi2_NR-Live.

1450631651: New connection from 127.0.0.1 on port 1883.

1450631651: Client Pi2_NR-Live already connected, closing old connection.

1450631651: Client Pi2_NR-Live disconnected.

1450631651: New client connected from 127.0.0.1 as Pi2_NR-Live (c0, k15).

1450631651: Pi2_NR-Live 2 HARDWARE-IN/#

1450631651: Pi2_NR-Live 2 COMMAND/#

1450631651: Outgoing messages are being dropped for client Pi2_NR-Live.

1450631651: Pi2_NR-Live 2 TEMPERATURE/HOME/IN/00/HALL/0x3001

1450631651: Pi2_NR-Live 2 TEMPERATURE/HOME/IN/02/LOFT/NANO1

...

I've not showed a load more subscribe messages as they didn't seem relevant.

[Julian Knight]

Yes, we crossed messages. I've done that now. But I had to restart everything. I'd forgotten that I'd set the MQTT config to NOT have a clean session on restart. So taking out the client ID required that setting to be ticked.

After restarting both Mosquitto and NR, that seems to have stopped the problem.

I wonder if I have misunderstood the reasons for not having a clean session on startup?

Logs looking more sensible now:

1450632083: mosquitto version 1.4.5 (build date Sun, 08 Nov 2015 21:43:12 +0000) starting

1450632083: Config loaded from /etc/mosquitto/mosquitto.conf.

1450632083: Opening ipv4 listen socket on port 1883.

1450632083: Opening ipv6 listen socket on port 1883.

1450632083: Opening websockets listen socket on port 9001.

1450632083: New connection from 127.0.0.1 on port 1883.

1450632083: New client connected from 127.0.0.1 as Pi2-NR (c1, k15, u'Pi2-NR').

1450632086: Client mqttjs_browser disconnected.

1450632086: New client connected from 192.168.1.108 as mqttjs_browser (c0, k15).

1450632118: New connection from 127.0.0.1 on port 1883.

You can see both clients connecting.

[Julian Knight]

And putting the client id back in but leaving Clean Session ticked is OK it seems.

[Julian Knight]

Feels like something changed though as I'd not altered my flows for a while. The only difference was running the npm update.

[Greg EVA]

FYI Julian... I was working on my installation last week, and noticed some strange MQTT related issues.  Some went away when I did a full redeploy (vs. just redeploying the changed flows), and once I had to actually reboot.

... and I have also noticed some strange Mosquitto behaviour and have made some notes on bugs to report.  I also note that the Moqsuitto configuration file includes other configuration files in a sub directory at the bottom of the file.  SO, if you set the log level and destination in the main configuration file, it may be overridden in the "customized" configuration file.

[Julian Knight]

Thanks Greg, in fact the issue with logging was firstly I was looking in the systemd log not the Mosquitto one! Then the layout for increasing log types was not clear and it took me a few goes to find the right way (each type has to be on its own line).

Got there in the end.

The problem I've got is that if you don't start with a clean session, you get constant dis/re-connects, anything up to 5 a second on my Pi2. Not sure if that is a Mosquitto bug or a Node-Red one.

[Toshi Bass]

Not wanting to stop you trying to trace this fault however as reported on 5th December I had problem with seemingly random MQTT disconnects / reconnects and extremely slow deploy of none-red, I moved my flows to a node-red instance on a pizero just for a test and this cleared the problems, I figured the problem only arose after the 0.12.2 node-red update and after considering the difference between node-red on my pi2 node-red v0.12.2 node.js v0.12.6 and pizero v0.12.2 node.js v0.10.29 I downgrade node.js to v0.10.41 (because I couldn't find v0.10.29)) on my pi2 and that solved both problems, its been fine working like this since, obviously this maybe unrelated to your problem but thought it was worth mentioning.


Toshi

[Dave C-J]

​We have since seen something similar here... but not exactly... it was only failing on redeploy... but...​ the workaround that seemed to work.... was to always use full deploy rather than partial...

[Julian Knight]

Tried most of that and I'm still on node v0.10.28 as that was the last one I could easily find for a Pi2 (ARM7) without having to faff around.

As I said, the issue only appears if you unselect the option to start with a clean session.

[Jan Van den Audenaerde]

Hi,

Today I got the same problem.

My node-red.log is filled with

7 Feb 14:03:54 - [info] [mqtt-broker:6fa4fb96.905b04] Disconnected from broker: mqtt://localhost:1883
7 Feb 14:03:54 - [info] [mqtt-broker:6ba77a63.945884] Disconnected from broker: mqtt://localhost:1883
7 Feb 14:03:54 - [info] [mqtt-broker:81dae091.7e252] Disconnected from broker: mqtt://localhost:1883
7 Feb 14:03:54 - [info] [mqtt-broker:6ba77a63.945884] Connected to broker: mqtt://localhost:1883
7 Feb 14:04:09 - [info] [mqtt-broker:6fa4fb96.905b04] Connected to broker: mqtt://localhost:1883
7 Feb 14:04:09 - [info] [mqtt-broker:6ba77a63.945884] Connected to broker: mqtt://localhost:1883
7 Feb 14:04:09 - [info] [mqtt-broker:81dae091.7e252] Connected to broker: mqtt://localhost:1883
7 Feb 14:04:09 - [info] [mqtt-broker:6ba77a63.945884] Disconnected from broker: mqtt://localhost:1883
7 Feb 14:04:24 - [info] [mqtt-broker:6ba77a63.945884] Connected to broker: mqtt://localhost:1883
7 Feb 14:04:24 - [info] [mqtt-broker:6ba77a63.945884] Disconnected from broker: mqtt://localhost:1883
7 Feb 14:04:39 - [info] [mqtt-broker:6ba77a63.945884] Connected to broker: mqtt://localhost:1883
7 Feb 14:04:39 - [info] [mqtt-broker:6ba77a63.945884] Disconnected from broker: mqtt://localhost:1883
7 Feb 14:04:54 - [info] [mqtt-broker:6ba77a63.945884] Connected to broker: mqtt://localhost:1883
7 Feb 14:04:54 - [info] [mqtt-broker:6ba77a63.945884] Disconnected from broker: mqtt://localhost:1883
7 Feb 14:04:54 - [info] [mqtt-broker:6ba77a63.945884] Connected to broker: mqtt://localhost:1883
7 Feb 14:04:54 - [info] [mqtt-broker:6ba77a63.945884] Disconnected from broker: mqtt://localhost:1883
7 Feb 14:05:09 - [info] [mqtt-broker:6ba77a63.945884] Connected to broker: mqtt://localhost:1883
7 Feb 14:05:09 - [info] [mqtt-broker:6ba77a63.945884] Disconnected from broker: mqtt://localhost:1883
7 Feb 14:05:09 - [info] [mqtt-broker:6ba77a63.945884] Connected to broker: mqtt://localhost:1883
7 Feb 14:05:09 - [info] [mqtt-broker:6ba77a63.945884] Disconnected from broker: mqtt://localhost:1883
7 Feb 14:05:24 - [info] [mqtt-broker:6ba77a63.945884] Connected to broker: mqtt://localhost:1883

I had to restart nodered to get it fixed.

FYI my node-red.log after the restart.

Welcome to Node-RED
===================
7 Feb 22:12:53 - [info] Node-RED version: v0.12.5
7 Feb 22:12:53 - [info] Node.js  version: v0.10.29
7 Feb 22:12:53 - [info] Loading palette nodes
7 Feb 22:14:08 - [info] UI started at /ui
7 Feb 22:14:31 - [info] Settings file  : /home/pi/.node-red/settings.js
7 Feb 22:14:31 - [info] User directory : /home/pi/.node-red
7 Feb 22:14:31 - [info] Flows file : /home/pi/.node-red/flows_raspberrypi.json
7 Feb 22:14:31 - [info] Server now running at http://127.0.0.1:1880/
7 Feb 22:14:32 - [info] Starting flows
7 Feb 22:14:52 - [info] Started flows
7 Feb 22:14:54 - [info] [mqtt-broker:6fa4fb96.905b04] Connected to broker: mqtt://localhost:1883
7 Feb 22:14:54 - [info] [mqtt-broker:6ba77a63.945884] Connected to broker: mqtt://localhost:1883

Mosquitto didn't log anything to the mosquitto.log file because the owner of the mosquitto.log was "root" while mosquitto service was running as user = "mosquitto".

I have now fixed the logging to the mosquitto.log files.  So if the problem reappears I can share the mosquitto.log file contents.

FYI my environment is a raspberry pi B (OS = Linux raspberrypi 4.1.13+ #826 PREEMPT Fri Nov 13 20:13:22 GMT 2015 armv6l GNU/Linux) 

which is running the following applications:

   - mosquitto version 1.4.7 (build date Tue, 22 Dec 2015 12:47:28 +0000)

   - node-red with several flows having an MQTT input node.  

   - emonhub that is sending MQTT message to mosquitto broker.

Is there anything I can do to prevent this problem from happening again ?

many thanks
jan.

[Dave C-J]

Thanks

yes please to those broker logs if they can be made to appear...

The suspicious lines in the above are

7 Feb 14:03:54 - [info] [mqtt-broker:6ba77a63.945884] Connected to broker: mqtt://localhost:1883
7 Feb 14:04:09 - [info] [mqtt-broker:6fa4fb96.905b04] Connected to broker: mqtt://localhost:1883
7 Feb 14:04:09 - [info] [mqtt-broker:6ba77a63.945884] Connected to broker: mqtt://localhost:1883

where  we see this node - mqtt-broker:6ba77a63.945884 connect twice - with no disconnect in between... which shouldn't happen - as it will then probably have two connections with the same client ID which will keep knocking one or the other off the broker. (the ping pong that then follows)

[Adrian Brown]

We had a similar issue in the past in our case a function node was running some code that was maxing out the CPU

Cheers

--

http://nodered.org
---
You received this message because you are subscribed to the Google Groups "Node-RED" group.
To unsubscribe from this group and stop receiving emails from it, send an email to node-red+u...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

Regards
Adrian Brown
0477173894

[Jan Van den Audenaerde]

Hi Dave,

Thanks for the very fast response.

I have no mosquitto logs for the problem period.

I fixed the issue with mosquitto logging: so if the problem reappears then I can and will also share the mosquitto log files.

Based on Dave's comment, I would conclude that the problem happened when I redeployed my flows at 7 Feb 14:93:54.

At that time it correctly disconnected the 3 connections to the mqtt broker but it almost immediately reconnected  to mqtt broker with client ID 6ba77a63.945884 (this is not expected).

15 seconds later (at 7 Feb 14:04:09)  it made the 3 connections to the mqtt broker again resulting in a second connection with client ID 6ba77a63.945884.

FYI Here below I have copy pasted again the problem part of nodered log file.

7 Feb 11:26:59 - [error] [function:extract cv pump state] [object Object]
7 Feb 14:03:54 - [info] [mqtt-broker:6fa4fb96.905b04] Disconnected from broker: mqtt://localhost:1883
7 Feb 14:03:54 - [info] [mqtt-broker:6ba77a63.945884] Disconnected from broker: mqtt://localhost:1883
7 Feb 14:03:54 - [info] [mqtt-broker:81dae091.7e252] Disconnected from broker: mqtt://localhost:1883

7 Feb 14:03:54 - [info] [mqtt-broker:6ba77a63.945884] Connected to broker: mqtt://localhost:1883
7 Feb 14:04:09 - [info] [mqtt-broker:6fa4fb96.905b04] Connected to broker: mqtt://localhost:1883
7 Feb 14:04:09 - [info] [mqtt-broker:6ba77a63.945884] Connected to broker: mqtt://localhost:1883

[Jan Van den Audenaerde]

Hi Dave,

Last 2 days I had the same problem 3 times:

• once at 10 Feb 10:21:49 : this is 34 hours after last time I redeployed the flows AND
• once at 11 Feb 00:12:37 : immediately after I restarted node-red 
• once at 11 Feb 22:21:41 : 2hours and 30 minutes after I restarted node-red.

FYI I have prefixed each line in the mosquitto.log with a proper timestamp using the script:

sudo gawk 'BEGIN {FS = ":"}; {print strftime("%c", $1), ":" $0}'  mosquitto.log.1 > /tmp/mosquitto.log.1.prefixed

The log files regarding the 1 st instance at 10 Feb 10:21:49:

• Node-red.log :

10 Feb 09:32:16 - [warn] [google-credentials:942c464d.6bd3b8] trying to refresh token due to expiry
10 Feb 09:32:54 - [warn] [function:arp-scan output to json] hosts responded (=9) != packets received (=10)
10 Feb 10:12:54 - [warn] [function:arp-scan output to json] hosts responded (=9) != packets received (=10)
10 Feb 10:21:49 - [info] [mqtt-broker:6fa4fb96.905b04] Disconnected from broker: mqtt://localhost:1883
10 Feb 10:21:49 - [info] [mqtt-broker:6ba77a63.945884] Disconnected from broker: mqtt://localhost:1883
10 Feb 10:21:54 - [info] [mqtt-broker:6ba77a63.945884] Connected to broker: mqtt://localhost:1883
10 Feb 10:22:04 - [info] [mqtt-broker:6fa4fb96.905b04] Connected to broker: mqtt://localhost:1883
10 Feb 10:22:04 - [info] [mqtt-broker:6ba77a63.945884] Connected to broker: mqtt://localhost:1883
10 Feb 10:22:04 - [info] [mqtt-broker:6ba77a63.945884] Disconnected from broker: mqtt://localhost:1883
10 Feb 10:22:19 - [info] [mqtt-broker:6ba77a63.945884] Connected to broker: mqtt://localhost:1883
10 Feb 10:22:19 - [info] [mqtt-broker:6ba77a63.945884] Disconnected from broker: mqtt://localhost:1883
10 Feb 10:22:34 - [info] [mqtt-broker:6ba77a63.945884] Connected to broker: mqtt://localhost:1883
10 Feb 10:22:34 - [info] [mqtt-broker:6ba77a63.945884] Disconnected from broker: mqtt://localhost:1883
10 Feb 10:22:49 - [info] [mqtt-broker:6ba77a63.945884] Connected to broker: mqtt://localhost:1883
10 Feb 10:22:49 - [info] [mqtt-broker:6ba77a63.945884] Disconnected from broker: mqtt://localhost:1883
10 Feb 10:22:54 - [info] [mqtt-broker:6ba77a63.945884] Connected to broker: mqtt://localhost:1883
10 Feb 10:22:54 - [info] [mqtt-broker:6ba77a63.945884] Disconnected from broker: mqtt://localhost:1883
10 Feb 10:22:55 - [warn] [function:arp-scan output to json] hosts responded (=9) != packets received (=10)
10 Feb 10:23:04 - [info] [mqtt-broker:6ba77a63.945884] Connected to broker: mqtt://localhost:1883
10 Feb 10:23:04 - [info] [mqtt-broker:6ba77a63.945884] Disconnected from broker: mqtt://localhost:1883
10 Feb 10:23:09 - [info] [mqtt-broker:6ba77a63.945884] Connected to broker: mqtt://localhost:1883

• mosquitto log:
  

Tue 09 Feb 2016 19:30:22 GMT-1 :1455042622: Client wifi_cv_relay already connected, closing old connection.
Tue 09 Feb 2016 19:30:22 GMT-1 :1455042622: Client wifi_cv_relay disconnected.
Tue 09 Feb 2016 19:30:22 GMT-1 :1455042622: New client connected from 192.168.1.30 as wifi_cv_relay (c1, k120).
Tue 09 Feb 2016 20:23:47 GMT-1 :1455045827: Client wifi_cv_relay has exceeded timeout, disconnecting.
Tue 09 Feb 2016 20:23:47 GMT-1 :1455045827: Socket error on client wifi_cv_relay, disconnecting.
Wed 10 Feb 2016 08:23:03 GMT-1 :1455088983: New connection from 192.168.1.30 on port 1883.
Wed 10 Feb 2016 08:23:03 GMT-1 :1455088983: New client connected from 192.168.1.30 as wifi_cv_relay (c1, k120).
Wed 10 Feb 2016 10:21:45 GMT-1 :1455096105: Client mqtt_8b2df741.74d208 has exceeded timeout, disconnecting.
Wed 10 Feb 2016 10:21:45 GMT-1 :1455096105: Socket error on client mqtt_8b2df741.74d208, disconnecting.
Wed 10 Feb 2016 10:21:48 GMT-1 :1455096108: Client mqtt_61b99207.9e466c has exceeded timeout, disconnecting.
Wed 10 Feb 2016 10:21:48 GMT-1 :1455096108: Socket error on client mqtt_61b99207.9e466c, disconnecting.
Wed 10 Feb 2016 10:21:54 GMT-1 :1455096114: New connection from 127.0.0.1 on port 1883.
Wed 10 Feb 2016 10:21:54 GMT-1 :1455096114: New client connected from 127.0.0.1 as mqtt_8b2df741.74d208 (c1, k15).
Wed 10 Feb 2016 10:22:04 GMT-1 :1455096124: New connection from 127.0.0.1 on port 1883.
Wed 10 Feb 2016 10:22:04 GMT-1 :1455096124: New client connected from 127.0.0.1 as mqtt_61b99207.9e466c (c1, k15).
Wed 10 Feb 2016 10:22:04 GMT-1 :1455096124: New connection from 127.0.0.1 on port 1883.
Wed 10 Feb 2016 10:22:04 GMT-1 :1455096124: Client mqtt_8b2df741.74d208 already connected, closing old connection.
Wed 10 Feb 2016 10:22:04 GMT-1 :1455096124: Client mqtt_8b2df741.74d208 disconnected.
Wed 10 Feb 2016 10:22:04 GMT-1 :1455096124: New client connected from 127.0.0.1 as mqtt_8b2df741.74d208 (c1, k15).
Wed 10 Feb 2016 10:22:19 GMT-1 :1455096139: New connection from 127.0.0.1 on port 1883.
Wed 10 Feb 2016 10:22:19 GMT-1 :1455096139: Client mqtt_8b2df741.74d208 already connected, closing old connection.
Wed 10 Feb 2016 10:22:19 GMT-1 :1455096139: Client mqtt_8b2df741.74d208 disconnected.
Wed 10 Feb 2016 10:22:19 GMT-1 :1455096139: New client connected from 127.0.0.1 as mqtt_8b2df741.74d208 (c1, k15).
Wed 10 Feb 2016 10:22:34 GMT-1 :1455096154: New connection from 127.0.0.1 on port 1883.
Wed 10 Feb 2016 10:22:34 GMT-1 :1455096154: Client mqtt_8b2df741.74d208 already connected, closing old connection.
Wed 10 Feb 2016 10:22:34 GMT-1 :1455096154: Client mqtt_8b2df741.74d208 disconnected.
Wed 10 Feb 2016 10:22:34 GMT-1 :1455096154: New client connected from 127.0.0.1 as mqtt_8b2df741.74d208 (c1, k15).
Wed 10 Feb 2016 10:22:49 GMT-1 :1455096169: New connection from 127.0.0.1 on port 1883.

The log files regarding the 2nd instance at  11 Feb 00:12:37 :

• Node-red.log:

Welcome to Node-RED
===================


11 Feb 00:09:30 - [info] Node-RED version: v0.12.5
11 Feb 00:09:30 - [info] Node.js  version: v0.10.29
11 Feb 00:09:30 - [info] Loading palette nodes
11 Feb 00:10:57 - [info] UI started at /ui
11 Feb 00:11:24 - [info] Settings file  : /home/pi/.node-red/settings.js
11 Feb 00:11:24 - [info] User directory : /home/pi/.node-red
11 Feb 00:11:24 - [info] Flows file : /home/pi/.node-red/flows_raspberrypi.json
11 Feb 00:11:24 - [info] Server now running at http://127.0.0.1:1880/
11 Feb 00:11:25 - [info] Starting flows
11 Feb 00:11:47 - [warn] [google-credentials:942c464d.6bd3b8] trying to refresh token due to expiry
11 Feb 00:11:47 - [info] Started flows
11 Feb 00:11:49 - [info] [mqtt-broker:6fa4fb96.905b04] Connected to broker: mqtt://localhost:1883
11 Feb 00:11:49 - [info] [mqtt-broker:6ba77a63.945884] Connected to broker: mqtt://localhost:1883
11 Feb 00:11:50 - [info] [mqtt-broker:81dae091.7e252] Connected to broker: mqtt://localhost:1883
11 Feb 00:12:37 - [info] [mqtt-broker:81dae091.7e252] Disconnected from broker: mqtt://localhost:1883
11 Feb 00:12:37 - [info] [mqtt-broker:6ba77a63.945884] Disconnected from broker: mqtt://localhost:1883
11 Feb 00:12:39 - [info] [mqtt-broker:6ba77a63.945884] Connected to broker: mqtt://localhost:1883
11 Feb 00:12:52 - [info] [mqtt-broker:81dae091.7e252] Connected to broker: mqtt://localhost:1883
11 Feb 00:12:52 - [info] [mqtt-broker:6ba77a63.945884] Connected to broker: mqtt://localhost:1883
11 Feb 00:12:52 - [info] [mqtt-broker:6ba77a63.945884] Disconnected from broker: mqtt://localhost:1883
11 Feb 00:13:07 - [info] [mqtt-broker:6ba77a63.945884] Connected to broker: mqtt://localhost:1883
11 Feb 00:13:07 - [info] [mqtt-broker:6ba77a63.945884] Disconnected from broker: mqtt://localhost:1883
11 Feb 00:13:22 - [info] [mqtt-broker:6ba77a63.945884] Connected to broker: mqtt://localhost:1883
11 Feb 00:13:22 - [info] [mqtt-broker:6ba77a63.945884] Disconnected from broker: mqtt://localhost:1883
11 Feb 00:13:38 - [info] [mqtt-broker:6ba77a63.945884] Connected to broker: mqtt://localhost:1883
11 Feb 00:13:38 - [info] [mqtt-broker:6ba77a63.945884] Disconnected from broker: mqtt://localhost:1883
11 Feb 00:13:39 - [info] [mqtt-broker:6ba77a63.945884] Connected to broker: mqtt://localhost:1883
11 Feb 00:13:39 - [info] [mqtt-broker:6ba77a63.945884] Disconnected from broker: mqtt://localhost:1883

• mosquitto log :
  
  

Wed 10 Feb 2016 15:25:12 GMT-1 :1455114312: Socket error on client <unknown>, disconnecting.
Thu 11 Feb 2016 00:11:49 GMT-1 :1455145909: New connection from 127.0.0.1 on port 1883.
Thu 11 Feb 2016 00:11:49 GMT-1 :1455145909: New connection from 127.0.0.1 on port 1883.
Thu 11 Feb 2016 00:11:49 GMT-1 :1455145909: New connection from 127.0.0.1 on port 1883.
Thu 11 Feb 2016 00:11:49 GMT-1 :1455145909: New client connected from 127.0.0.1 as mqtt_b0ff54cf.4f00a8 (c1, k15).
Thu 11 Feb 2016 00:11:49 GMT-1 :1455145909: New client connected from 127.0.0.1 as mqtt_9691b7de.696e48 (c1, k15).
Thu 11 Feb 2016 00:11:49 GMT-1 :1455145909: New client connected from 127.0.0.1 as mqtt_9547a270.6ab86 (c1, k15).
Thu 11 Feb 2016 00:12:27 GMT-1 :1455145947: Client mqtt_9547a270.6ab86 has exceeded timeout, disconnecting.
Thu 11 Feb 2016 00:12:27 GMT-1 :1455145947: Socket error on client mqtt_9547a270.6ab86, disconnecting.
Thu 11 Feb 2016 00:12:31 GMT-1 :1455145951: Client mqtt_9691b7de.696e48 has exceeded timeout, disconnecting.
Thu 11 Feb 2016 00:12:31 GMT-1 :1455145951: Socket error on client mqtt_9691b7de.696e48, disconnecting.
Thu 11 Feb 2016 00:12:38 GMT-1 :1455145958: New connection from 127.0.0.1 on port 1883.
Thu 11 Feb 2016 00:12:39 GMT-1 :1455145959: New client connected from 127.0.0.1 as mqtt_9691b7de.696e48 (c1, k15).
Thu 11 Feb 2016 00:12:52 GMT-1 :1455145972: New connection from 127.0.0.1 on port 1883.
Thu 11 Feb 2016 00:12:52 GMT-1 :1455145972: New client connected from 127.0.0.1 as mqtt_9547a270.6ab86 (c1, k15).
Thu 11 Feb 2016 00:12:52 GMT-1 :1455145972: New connection from 127.0.0.1 on port 1883.
Thu 11 Feb 2016 00:12:52 GMT-1 :1455145972: Client mqtt_9691b7de.696e48 already connected, closing old connection.
Thu 11 Feb 2016 00:12:52 GMT-1 :1455145972: Client mqtt_9691b7de.696e48 disconnected.
Thu 11 Feb 2016 00:12:52 GMT-1 :1455145972: New client connected from 127.0.0.1 as mqtt_9691b7de.696e48 (c1, k15).
Thu 11 Feb 2016 00:13:07 GMT-1 :1455145987: New connection from 127.0.0.1 on port 1883.
Thu 11 Feb 2016 00:13:07 GMT-1 :1455145987: Client mqtt_9691b7de.696e48 already connected, closing old connection.
Thu 11 Feb 2016 00:13:07 GMT-1 :1455145987: Client mqtt_9691b7de.696e48 disconnected.
Thu 11 Feb 2016 00:13:07 GMT-1 :1455145987: New client connected from 127.0.0.1 as mqtt_9691b7de.696e48 (c1, k15).
Thu 11 Feb 2016 00:13:22 GMT-1 :1455146002: New connection from 127.0.0.1 on port 1883.
Thu 11 Feb 2016 00:13:22 GMT-1 :1455146002: Client mqtt_9691b7de.696e48 already connected, closing old connection.
Thu 11 Feb 2016 00:13:22 GMT-1 :1455146002: Client mqtt_9691b7de.696e48 disconnected.
Thu 11 Feb 2016 00:13:22 GMT-1 :1455146002: New client connected from 127.0.0.1 as mqtt_9691b7de.696e48 (c1, k15).
Thu 11 Feb 2016 00:13:38 GMT-1 :1455146018: New connection from 127.0.0.1 on port 1883.
Thu 11 Feb 2016 00:13:38 GMT-1 :1455146018: Client mqtt_9691b7de.696e48 already connected, closing old connection.
Thu 11 Feb 2016 00:13:38 GMT-1 :1455146018: Client mqtt_9691b7de.696e48 disconnected.
Thu 11 Feb 2016 00:13:38 GMT-1 :1455146018: New client connected from 127.0.0.1 as mqtt_9691b7de.696e48 (c1, k15).
Thu 11 Feb 2016 00:13:39 GMT-1 :1455146019: New connection from 127.0.0.1 on port 1883.
Thu 11 Feb 2016 00:13:39 GMT-1 :1455146019: Client mqtt_9691b7de.696e48 already connected, closing old connection.
Thu 11 Feb 2016 00:13:39 GMT-1 :1455146019: Client mqtt_9691b7de.696e48 disconnected.

Maybe I should also increase the time-out used by mosquitto (mqtt broker) to disconnect clients.  This might reduce the likelyhood of this problem.

kr

jan

[Jan Van den Audenaerde]

Hi,

 

I have changed the "Keep alive times" of all MQTT nodes in my node-red flows from 15 to 60 seconds.

This seems to have fixed the problem: 

The last 2 days no lines with

 "Disconnected from broker: mqtt://localhost:1883" 

were reported in the node-red.log besides the expected ones when the flows became stopped due to a redeployement

kr

Jan.

[Nicholas O'Leary]

In case you hadn't spotted the announcement, the 0.13.2 release we did on Friday evening fixed the MQTT reconnect loops.

Nick

--