Tasmota occasionally loses connection to MQTT, but WiFi is fine?

[Kim Wall]

Out of interest, has anyone seen this behaviour:

After days, or indeed weeks, of uptime, a device will suddenly lose its
connection to the MQTT broker. It then sits there attempting to
reconnect at intervals. Mosquitto sees the attempted reconnection, but
gives its usual unhelpful "socket error" message. On the odd occasion
I've left one in this state, it usually manages to reconnect after tens
of minutes.

WiFi is fine throughout this, so you can ping the device, access the
Tasmota web interface, console, etc. Other Tasmotas (some with the same
hardware and firmware (I've tried 9.0.4 and 10.0.0.1), connected to the
same MQTT broker through the same WiFi network / access point) remain
connected without issues.

Telling Tasmota to restart works, but it is still unable to connect to MQTT.

Kicking it off the WiFi causes it to reassociate in the usual manner,
with no effect on the MQTT connection problem.

But if you power cycle the Tasmota, it connects flawlessly on the first
attempt, and stays connected for more days or weeks.

I'm wondering it it's somehow Mosquitto's fault...


Kim.
--

[Philip Knowles]

There was a change in Tasmota in the V9s which caused an issue if the topic and client were the same. Not sure if that’s the issue for you.

 

Regards

 

Phil K

 

Sent from Mail for Windows

--

You received this message because you are subscribed to the Google Groups "TasmotaUsers" group.

To unsubscribe from this group and stop receiving emails from it, send an email to sonoffusers...@googlegroups.com.

To view this discussion on the web, visit https://groups.google.com/d/msgid/sonoffusers/ac112753-17eb-8a5e-ae5e-74d8fd3a735c%40ductilebiscuit.net.

 

[Kim Wall]

They're set to different values, so not that.


Kim.

On 19/02/2022 07:46, Philip Knowles wrote:
> There was a change in Tasmota in the V9s which caused an issue if the
> topic and client were the same. Not sure if that’s the issue for you.
>
> Regards
>
> Phil K
>

> Sent from Mail <https://go.microsoft.com/fwlink/?LinkId=550986> for Windows
>
> *From: *Kim Wall <mailto:k...@ductilebiscuit.net>
> *Sent: *18 February 2022 23:02
> *To: *TasmotaUsers <mailto:sonof...@googlegroups.com>
> *Subject: *Tasmota occasionally loses connection to MQTT, but WiFi is fine?

> <mailto:sonoffusers...@googlegroups.com>.

> To view this discussion on the web, visit

> https://groups.google.com/d/msgid/sonoffusers/ED08FCAC-9FBF-4961-8B8D-429AD5B75CFD%40hxcore.ol
> <https://groups.google.com/d/msgid/sonoffusers/ED08FCAC-9FBF-4961-8B8D-429AD5B75CFD%40hxcore.ol?utm_medium=email&utm_source=footer>.

[Philip Knowles]

What is the MQTT result code that you get?

 

Sent from Mail for Windows

 

To view this discussion on the web, visit https://groups.google.com/d/msgid/sonoffusers/76eab868-80d6-889c-1294-8a87fbdc2ac2%40ductilebiscuit.net.

 

[Kim Wall]

Had to wait a while for it to happen, and this time I managed to catch
it quickly...

From the Tasmota console:

05:34:23.171 MQT: 12AR/bedroom/ceiling-lamp/STATE =
{"Time":"2022-03-02T05:34:23","Uptime":"5T05:15:19","UptimeSec":450919,"Heap":27,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":7,"POWER":"OFF","Wifi":{"AP":1,"SSId":"i_o_s","BSSId":"4E:D9:E7:FA:A2:26","Channel":3,"Mode":"11n","RSSI":68,"Signal":-66,"LinkCount":7,"Downtime":"0T00:00:20"}}
05:39:23.164 MQT: 12AR/bedroom/ceiling-lamp/STATE =
{"Time":"2022-03-02T05:39:23","Uptime":"5T05:20:19","UptimeSec":451219,"Heap":27,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":7,"POWER":"OFF","Wifi":{"AP":1,"SSId":"i_o_s","BSSId":"4E:D9:E7:FA:A2:26","Channel":3,"Mode":"11n","RSSI":64,"Signal":-68,"LinkCount":7,"Downtime":"0T00:00:20"}}
05:43:10.891 WIF: Connecting to AP1 i_o_s Channel 13 BSSId
FE:92:BF:5D:A1:5F in mode 11n as LT30-5...
05:43:13.757 MQT: Attempting connection...
05:43:18.075 MQT: Connect failed to mqtt.ductilebiscuit.net:1883, rc -4.
Retry in 10 sec
05:43:28.859 MQT: Attempting connection...
05:43:33.181 MQT: Connect failed to mqtt.ductilebiscuit.net:1883, rc -4.
Retry in 20 sec
05:43:53.979 MQT: Attempting connection...
05:43:58.294 MQT: Connect failed to mqtt.ductilebiscuit.net:1883, rc -4.
Retry in 30 sec
05:44:29.091 MQT: Attempting connection...
05:44:33.406 MQT: Connect failed to mqtt.ductilebiscuit.net:1883, rc -4.
Retry in 40 sec
05:44:38.453 RSL: STATE =
{"Time":"2022-03-02T05:44:38","Uptime":"5T05:25:34","UptimeSec":451534,"Heap":26,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":7,"POWER":"OFF","Wifi":{"AP":1,"SSId":"i_o_s","BSSId":"FE:92:BF:5D:A1:5F","Channel":13,"Mode":"11n","RSSI":72,"Signal":-64,"LinkCount":8,"Downtime":"0T00:00:23"}}
05:45:14.216 MQT: Attempting connection...
05:45:18.534 MQT: Connect failed to mqtt.ductilebiscuit.net:1883, rc -4.
Retry in 50 sec


And from the mosquitto log:

1646199799: New connection from 192.168.5.75 on port 1883.
1646199804: Client DVES_E27BEC already connected, closing old connection.
1646199804: Client DVES_E27BEC disconnected.
1646199804: New client connected from 192.168.5.75 as DVES_E27BEC (c1,
k30, u'tasmota').
1646199804: Socket error on client DVES_E27BEC, disconnecting.
1646199811: New connection from 192.168.5.75 on port 1883.
1646199819: New client connected from 192.168.5.75 as DVES_E27BEC (c1,
k30, u'tasmota').
1646199819: Socket error on client DVES_E27BEC, disconnecting.
1646199839: New connection from 192.168.5.75 on port 1883.
1646199844: New client connected from 192.168.5.75 as DVES_E27BEC (c1,
k30, u'tasmota').
1646199844: Socket error on client DVES_E27BEC, disconnecting.
1646199871: New connection from 192.168.5.75 on port 1883.
1646199879: New client connected from 192.168.5.75 as DVES_E27BEC (c1,
k30, u'tasmota').
1646199879: Socket error on client DVES_E27BEC, disconnecting.
1646199920: New connection from 192.168.5.75 on port 1883.
1646199924: New client connected from 192.168.5.75 as DVES_E27BEC (c1,
k30, u'tasmota').
1646199924: Socket error on client DVES_E27BEC, disconnecting.


So it looks like the WiFi pseudo-roams successfully (SetOption56 and
Setoption57 are enabled, as I have multiple access points), but
something goes wrong when reconnecting MQTT. rc -4 is 'connection timeout'.

Suspicious this might somehow be a Unifi, switch or pfSense issue (the
IOT devices are on their own isolated VLAN, and have to cross the
firewall to reach the broker). There's nothing in the firewall logs.
Possibly something isn't updating its ARP table properly? I think I
need to try connecting to the web console from the machine the broker is
running on (rather than the android that's within easy reach of bed at
5:43 in the morning) when it next happens...


Kim.

On 21/02/2022 07:35, Philip Knowles wrote:
> What is the MQTT result code that you get?
>

> Sent from Mail <https://go.microsoft.com/fwlink/?LinkId=550986> for Windows
>
> *From: *Kim Wall <mailto:k...@ductilebiscuit.net>

> *Sent: *20 February 2022 20:56
> *To: *sonof...@googlegroups.com <mailto:sonof...@googlegroups.com>
> *Subject: *Re: Tasmota occasionally loses connection to MQTT, but WiFi

> https://groups.google.com/d/msgid/sonoffusers/07CBAAC1-3A84-4656-A6F2-B8E22CFAB164%40hxcore.ol
> <https://groups.google.com/d/msgid/sonoffusers/07CBAAC1-3A84-4656-A6F2-B8E22CFAB164%40hxcore.ol?utm_medium=email&utm_source=footer>.

[Philip Knowles]

It looks like (perhaps) the wifi is dropping (05:43:10) on Channel 3 with the 4E BSSId, Tasmota is re-connecting (on Channel 13 with the FE BSSId) then trying to re-connect to MQTT (05:43:13) - but the broker doesn’t know it had gone so closes the old connection – Tasmota doesn’t have an ‘old’ connection so it gets closed and a bit of a tussle goes on.

 

The question is why is the wifi change happening and is that causing the issue?

 

Regards

 

Phil K

 

Sent from Mail for Windows

To view this discussion on the web, visit https://groups.google.com/d/msgid/sonoffusers/483e4a5d-3052-2123-8164-9e2c78667c14%40ductilebiscuit.net.

 

[Kim Wall]

As I have a WiFi network with multiple access points, I have SetOption56
and Setoption57 enabled. This causes Tasmota to check for a stronger
signal on a different AP every 44 minutes, and disconnect/reconnect if
necessary (the ESP core doesn't support proper WiFi roaming, so this is
Tasmota's work-around).

That particular Tasmota device is in in the overlap region between two
access points, so it makes sense for it to occasionally switch between
them due to the vagaries of interference, objects occluding the signal, etc.

So the change of access point is normal and expected. The problem is
that for some reason MQTT is unable to reconnect properly afterwards.


I've installed Tasmota on a Wemos D1 Mini that I had to hand, so I could
power it from a battery pack and easily move it around. Here's how
things are supposed to work:

00:00:00.064 Project tasmota - Tasmota Version
10.0.0.1(tasmota)-2_7_4_9(2022-03-02T15:30:49)
00:00:04.500 WIF: Connecting to AP1 i_o_s Channel 3 BSSId
4E:D9:E7:FA:A2:26 in mode 11n as tasmota-DEFEC5-7877...
00:00:05.753 WIF: Connected
00:00:06.005 HTP: Web server active on tasmota-DEFEC5-7877 with IP
address 192.168.5.211
00:00:06.487 QPC: Reset
15:47:38.028 MQT: Attempting connection...
15:47:38.045 MQT: Connected

(Device powers up and connects to the 4E access point as expected.)

I then physically move it to the other side of the house, where it's
closer to the FE access point...

16:27:42.476 MQT: test/tasmota_DEFEC5/STATE =
{"Time":"2022-03-02T16:27:42","Uptime":"0T00:40:13","UptimeSec":2413,"Heap":27,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":1,"Wifi":{"AP":1,"SSId":"i_o_s","BSSId":"4E:D9:E7:FA:A2:26","Channel":3,"Mode":"11n","RSSI":50,"Signal":-75,"LinkCount":1,"Downtime":"0T00:00:07"}}
16:31:33.134 WIF: Connecting to AP1 i_o_s Channel 13 BSSId
FE:92:BF:5D:A1:5F in mode 11n as tasmota-DEFEC5-7877...
16:31:34.755 MQT: Attempting connection...
16:31:34.781 MQT: Connected

(About 44 minutes later, Tasmota checks for a stronger signal and
reconnects to the FE access point. MQTT has to reconnect as the socket
is closed at the Tasmota end, and does so successfully, first time.)

Meanwhile, at the broker:

1646238694: New connection from 192.168.5.211 on port 1883.
1646238694: Client DVES_DEFEC5 already connected, closing old connection.
1646238694: Client DVES_DEFEC5 disconnected.
1646238694: New client connected from 192.168.5.211 as DVES_DEFEC5 (c1,
k30, u'tasmota').

(A new connection is made, mosquitto recognises the client ID, and
closes the old connection.)


I've moved it back and forward a couple of times now, and it hasn't yet
reproduced the timeout problem. I'll keep playing around...


Kim.

On 02/03/2022 18:15, Philip Knowles wrote:
> It looks like (perhaps) the wifi is dropping (05:43:10) on Channel 3
> with the 4E BSSId, Tasmota is re-connecting (on Channel 13 with the FE
> BSSId) then trying to re-connect to MQTT (05:43:13) - but the broker
> doesn’t know it had gone so closes the old connection – Tasmota doesn’t
> have an ‘old’ connection so it gets closed and a bit of a tussle goes on.
>
> The question is why is the wifi change happening and is that causing the
> issue?
>
> Regards
>
> Phil K
>

> Sent from Mail <https://go.microsoft.com/fwlink/?LinkId=550986> for Windows
>
> *From: *Kim Wall <mailto:k...@ductilebiscuit.net>

> *Sent: *02 March 2022 13:57
> *To: *TasmotaUsers <mailto:sonof...@googlegroups.com>

> https://groups.google.com/d/msgid/sonoffusers/4169F78D-BEA6-4F05-A77C-982D82781131%40hxcore.ol
> <https://groups.google.com/d/msgid/sonoffusers/4169F78D-BEA6-4F05-A77C-982D82781131%40hxcore.ol?utm_medium=email&utm_source=footer>.

[Kim Wall]

I finally caught a smartplug doing it, and tried restarting the broker.
It reconnected fine on the subsequent attempt. Suspect this may be a
mosquitto problem, rather than a Tasmota or Unifi problem...


Kim.