MQTT Disconnects & Feeds not updating

Hello,

Not quite sure when it started happening, but I am getting frequent MQTT disconnects which mean feeds are not updating, for some times 15+ minutes at a time.

EmonBase + EmonTx v3.

Relevant logs from EmonCMS:

2024-01-17 19:49:01.-51|WARN|index.php|406 Not Acceptable|postprocess/update
2024-01-17 19:50:02.013|WARN|index.php|406 Not Acceptable|postprocess/update
2024-01-17 19:51:01.-106|WARN|index.php|406 Not Acceptable|postprocess/update
2024-01-17 19:52:01.-55|WARN|index.php|406 Not Acceptable|postprocess/update
2024-01-17 19:53:01.-05|WARN|index.php|406 Not Acceptable|postprocess/update
2024-01-17 19:54:02.051|WARN|index.php|406 Not Acceptable|postprocess/update
2024-01-17 19:55:01.101|WARN|index.php|406 Not Acceptable|postprocess/update
2024-01-17 19:56:01.-422|WARN|index.php|406 Not Acceptable|postprocess/update
2024-01-17 19:57:01.-375|WARN|index.php|406 Not Acceptable|postprocess/update
2024-01-17 19:57:34.277|WARN|emoncms_mqtt.php|Not connected, retrying connection
2024-01-17 19:57:34.300|WARN|emoncms_mqtt.php|Connecting to MQTT server: Connection Accepted.: code: 0
2024-01-17 19:58:01.-330|WARN|index.php|406 Not Acceptable|postprocess/update
2024-01-17 19:58:14.281|WARN|emoncms_mqtt.php|Not connected, retrying connection
2024-01-17 19:58:14.305|WARN|emoncms_mqtt.php|Connecting to MQTT server: Connection Accepted.: code: 0
2024-01-17 19:58:34.259|WARN|emoncms_mqtt.php|Not connected, retrying connection
2024-01-17 19:58:34.278|WARN|emoncms_mqtt.php|Connecting to MQTT server: Connection Accepted.: code: 0
2024-01-17 19:58:54.261|WARN|emoncms_mqtt.php|Not connected, retrying connection
2024-01-17 19:58:54.283|WARN|emoncms_mqtt.php|Connecting to MQTT server: Connection Accepted.: code: 0
2024-01-17 19:59:01.-243|WARN|index.php|406 Not Acceptable|postprocess/update
2024-01-17 19:59:24.273|WARN|emoncms_mqtt.php|Not connected, retrying connection
2024-01-17 19:59:24.292|WARN|emoncms_mqtt.php|Connecting to MQTT server: Connection Accepted.: code: 0
2024-01-17 19:59:34.274|WARN|emoncms_mqtt.php|Not connected, retrying connection
2024-01-17 19:59:34.296|WARN|emoncms_mqtt.php|Connecting to MQTT server: Connection Accepted.: code: 0
2024-01-17 19:59:44.274|WARN|emoncms_mqtt.php|Not connected, retrying connection
2024-01-17 19:59:44.297|WARN|emoncms_mqtt.php|Connecting to MQTT server: Connection Accepted.: code: 0

Anyone have any suggestions as to what to check? I disabled IPv6 as per a similar issue in this thread: Frequently disconnects from mqtt / mosquitto. Stop feeds updates but it still keeps happening.

Please let me know if I can provide any more info / logs etc!

Many thanks

Adam

Hello Adam

I realise it’s hard to tell from these logs if the emoncms_mqtt crashed and restarted or if MQTT disconnected cleanly before reconnecting later.

I’ve pushed a couple of minor changes to log the script starting message and MQTT disconnect message as WARN level rather than info, this will hopefully make it easier to see what is happening.

Can you update emoncms core to the latest master branch and restart emoncms_mqtt via the Admin services interface?

Have you recently added any other input processing that might be tripping up the emoncms_mqtt script somehow?

Hey Trystan! Thanks so much for the reply and added logs :slight_smile:

I have updated and new logs below:

2024-01-18 15:45:26.289|WARN|emoncms_mqtt.php|Connecting to MQTT server: Connection Accepted.: code: 0
2024-01-18 15:45:36.262|WARN|emoncms_mqtt.php|Not connected, retrying connection
2024-01-18 15:45:36.284|WARN|emoncms_mqtt.php|Connecting to MQTT server: Connection Accepted.: code: 0
2024-01-18 15:45:36.-125|WARN|emoncms_mqtt.php|Starting MQTT Input script
2024-01-18 15:45:36.-55|WARN|emoncms_mqtt.php|Not connected, retrying connection
2024-01-18 15:45:36.-36|WARN|emoncms_mqtt.php|Connecting to MQTT server: Connection Accepted.: code: 0
2024-01-18 15:45:46.276|WARN|emoncms_mqtt.php|MQTT has disconnected - cleanly
2024-01-18 15:45:46.276|WARN|emoncms_mqtt.php|Not connected, retrying connection
2024-01-18 15:45:46.299|WARN|emoncms_mqtt.php|Connecting to MQTT server: Connection Accepted.: code: 0
2024-01-18 15:45:56.273|WARN|emoncms_mqtt.php|MQTT has disconnected - cleanly
2024-01-18 15:45:56.274|WARN|emoncms_mqtt.php|Not connected, retrying connection
2024-01-18 15:45:56.297|WARN|emoncms_mqtt.php|Connecting to MQTT server: Connection Accepted.: code: 0
2024-01-18 15:46:00.-94|WARN|index.php|406 Not Acceptable|postprocess/update
2024-01-18 15:46:06.275|WARN|emoncms_mqtt.php|MQTT has disconnected - cleanly
2024-01-18 15:46:06.276|WARN|emoncms_mqtt.php|Not connected, retrying connection
2024-01-18 15:46:06.298|WARN|emoncms_mqtt.php|Connecting to MQTT server: Connection Accepted.: code: 0
2024-01-18 15:46:16.257|WARN|emoncms_mqtt.php|MQTT has disconnected - cleanly
2024-01-18 15:46:16.258|WARN|emoncms_mqtt.php|Not connected, retrying connection
2024-01-18 15:46:16.279|WARN|emoncms_mqtt.php|Connecting to MQTT server: Connection Accepted.: code: 0
2024-01-18 15:46:26.258|WARN|emoncms_mqtt.php|MQTT has disconnected - cleanly
2024-01-18 15:46:26.258|WARN|emoncms_mqtt.php|Not connected, retrying connection
2024-01-18 15:46:26.280|WARN|emoncms_mqtt.php|Connecting to MQTT server: Connection Accepted.: code: 0
2024-01-18 15:46:36.272|WARN|emoncms_mqtt.php|MQTT has disconnected - cleanly
2024-01-18 15:46:36.272|WARN|emoncms_mqtt.php|Not connected, retrying connection
2024-01-18 15:46:36.296|WARN|emoncms_mqtt.php|Connecting to MQTT server: Connection Accepted.: code: 0

Looks like its a clean disconnect, which is odd :thinking:

oh! to answer this question, no I haven’t added anything else recently at all. Its been the same config for a very long time

Possibly relevant, I do have an external data source that I configured a pretty long time ago to publish the outside weather temp from the openweather API onto the same MQTT broker :thinking: Will stop that and see if it has any affect

Thanks that’s really useful - so at least we know now that it’s not emoncms_mqtt crashing.
This suggests that it’s the MQTT server (mosquitto) itself that’s stopping and starting… so we need to dig into what is happening there…

Could you check if there’s any info given with:

sudo systemctl status mosquitto.service

might be something useful in journalctl:

journalctl -f -n 1000

or the mosquitto log itself?

sudo tail -f /var/log/mosquitto/mosquitto.log -n 1000

Thanks for the suggestions! Nothing of note in any of those logs. Bizarrely, the last log line in the mosquito log is from 2 years ago…

1626860402: mosquitto version 1.5.7 starting
1626860402: Config loaded from /etc/mosquitto/mosquitto.conf.
1626860402: Opening ipv4 listen socket on port 1883.
1626860402: Opening ipv6 listen socket on port 1883.
1626860454: New connection from ::1 on port 1883.
1626860454: New client connected from ::1 as emoncms (c1, k5, u'emonpi').
1626860455: Socket error on client emoncms, disconnecting.
1626860455: New connection from ::1 on port 1883.
1626860455: New client connected from ::1 as emoncms (c1, k5, u'emonpi').
1626860528: New connection from ::1 on port 1883.
1626860528: New client connected from ::1 as mosq/uUY6ic?iqBsPfts6l6 (c1, k5, u'emonpi').
1626860796: Socket error on client emoncms, disconnecting.
1626860797: Socket error on client mosq/uUY6ic?iqBsPfts6l6, disconnecting.
1626860797: mosquitto version 1.5.7 terminating

Also strangely, since disabling my openweather MQTT service, its been stable for the last 25 mins… I am tempted to just see how that goes (its definitely not essential), as if it is that, I don’t wanna waste any more of your time :sweat_smile:

1 Like

I guess log partition is not full as your getting the emoncms logs above… What do you get with df -h?

You could always try restarting mosquitto to see if that appears in its log?

sudo systemctl restart mosquitto.service

Yeah disk space looks fine :slight_smile:

I am getting somewhere! Log level was set to error on mosquitto config. Changed it and I am now getting logs!

As soon as I re-enabled my other mqtt service, the problem started up again! Note to self, don’t try to be clever :sweat_smile: :joy:

In the logs it just gives:

Socket error on client emoncms, disconnecting.

Will try putting it into debug to see if I can get any more info and solve this in my own time!

Thank you very much for your assistance :smiley: Please consider this one sorted! (me trying to do things the system wasn’t meant to do :see_no_evil: )

As always, support on this is amazing :smiley:

2 Likes

Thanks Adam, my support is a bit sporadic! but glad I could help this time :+1:

2 Likes