Device lag when unable to contact MQTT server

[robc22]

PROBLEM DESCRIPTION

I am using multiple Sonoff and Shelly Devices and I am currently testing a Shelly1. I have noticed that when the device cannot contact the MQTT broker, there is a lag that causes the device to become unresponsive for a period of 3-10 seconds. I can reproduce this by simply changing the IP of the MQTT broker in the device to an incorrect IP and this induces the lag each time the device attempts to connect.

All other network components seem fine and I have no issues with connecting to the device using IP.

The rationale for the problem is that the device, when configured should be lag free even if the MQTT broker is failed so that the user experience appears the same. My example device is used behind a light switch and it seems odd when a user flicks a toggle switch and then they have to wait for the light to go off!

Is there anyway of resolving this?

Many thanks in advance for any help provided.

REQUESTED INFORMATION

Make sure your have performed every step and checked the applicable boxes before submitting your issue. Thank you!

• Read the Contributing Guide and Policy and the Code of Conduct
• Searched the problem in issues
• Searched the problem in the docs
• Searched the problem in the forum
• Searched the problem in the chat
• Device used (e.g., Sonoff Basic): Shelly1
• Tasmota binary firmware version number used: 8.3.1
  • Pre-compiled
  • Self-compiled
    • IDE / Compiler used: _____
• Flashing tools used: Visual Studio Code
• Provide the output of command: Backlog Template; Module; GPIO 255:

  Configuration output here:

• If using rules, provide the output of this command: Backlog Rule1; Rule2; Rule3:

  Rules output here:
Rule 1 ON Switch1#State=0 DO Power1 0 ENDON ON Switch1#State=1 DO Power1 1 ENDON

This is a really simple rule, which is actually inspired to resolve the lag issue, but it hasnt helped and actually implementing it pointed me to the source of the lag being the MQTT server connection.  I would like to have this code in use so that it equivalent node-red code can be removed.

• Provide the output of this command: Status 0:

  STATUS 0 output here:
16:55:45 CMD: status 0
16:55:45 RSL: STATUS = {"Status":{"Module":46,"DeviceName":"Office Light","FriendlyName":["Office Light"],"Topic":"Office/Light/Shelly","ButtonTopic":"0","Power":1,"PowerOnState":3,"LedState":1,"LedMask":"FFFF","SaveData":1,"SaveState":1,"SwitchTopic":"Office/Light/Shelly","SwitchMode":[1,0,0,0,0,0,0,0],"ButtonRetain":0,"SwitchRetain":0,"SensorRetain":0,"PowerRetain":0}}
16:55:45 RSL: STATUS1 = {"StatusPRM":{"Baudrate":115200,"SerialConfig":"8N1","GroupTopic":"ShellyLights","OtaUrl":"http://thehackbox.org/tasmota/release/tasmota.bin","RestartReason":"Software/System restart","Uptime":"0T00:21:12","StartupUTC":"2020-11-16T15:34:33","Sleep":50,"CfgHolder":4717,"BootCount":140,"BCResetTime":"2020-07-01T16:30:23","SaveCount":1845,"SaveAddress":"F7000"}}
16:55:45 RSL: STATUS2 = {"StatusFWR":{"Version":"8.3.1(tasmota)","BuildDateTime":"2020-07-01T09:24:22","Boot":31,"Core":"2_7_1","SDK":"2.2.2-dev(38a443e)","Hardware":"ESP8266EX","CR":"421/699"}}
16:55:45 RSL: STATUS3 = {"StatusLOG":{"SerialLog":2,"WebLog":2,"MqttLog":0,"SysLog":0,"LogHost":"","LogPort":514,"SSId":["HouseNET",""],"TelePeriod":300,"Resolution":"55A180C0","SetOption":["00008001","2805C8000100060000005A00000000000000","00000000","00000000"]}}
16:55:45 RSL: STATUS4 = {"StatusMEM":{"ProgramSize":587,"Free":416,"Heap":26,"ProgramFlashSize":2048,"FlashSize":2048,"FlashChipId":"1540EF","FlashMode":3,"Features":["00000809","8FDAE797","043683A1","000000CD","010013C0","C000F981","00000024"],"Drivers":"1,2,3,4,5,6,7,8,9,10,12,16,18,19,20,21,22,24,26,27,29,30,35,37","Sensors":"1,2,3,4,5,6"}}
16:55:45 RSL: STATUS5 = {"StatusNET":{"Hostname":"OfficeLight","IPAddress":"172.16.19.30","Gateway":"172.16.19.254","Subnetmask":"255.255.255.0","DNSServer":"172.16.19.254","Mac":"A4:CF:12:F4:79:49","Webserver":2,"WifiConfig":2,"WifiPower":17.0}}
16:55:45 RSL: STATUS7 = {"StatusTIM":{"UTC":"2020-11-16T15:55:45","Local":"2020-11-16T16:55:45","StartDST":"2020-03-29T02:00:00","EndDST":"2020-10-25T03:00:00","Timezone":"+01:00","Sunrise":"08:01","Sunset":"17:08"}}
16:55:45 RSL: STATUS10 = {"StatusSNS":{"Time":"2020-11-16T16:55:45","Switch1":"ON"}}
16:55:45 RSL: STATUS11 = {"StatusSTS":{"Time":"2020-11-16T16:55:45","Uptime":"0T00:21:12","UptimeSec":1272,"Heap":26,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":0,"POWER":"ON","Wifi":{"AP":1,"SSId":"HouseNET","BSSId":"74:DA:38:81:8E:8C","Channel":1,"RSSI":54,"Signal":-73,"LinkCount":1,"Downtime":"0T00:00:03"}}}

• Provide the output of the Console log output when you experience your issue; if applicable:
  (Please use weblog 4 for more debug information)

00:00:00 CFG: Loaded from flash at F4, Count 1848
00:00:00 Project tasmota Office Light Version 8.3.1(tasmota)-2_7_1
00:00:00 WIF: Connecting to AP1 HouseNET Channel 1 BSSId 74:DA:38:81:8E:8C in mode 11N as OfficeLight...
00:00:01 WIF: Connected
00:00:01 HTP: Web server active on OfficeLight with IP address 172.16.19.30
00:00:01 UPP: Multicast (re)joined
16:57:24 MQT: Attempting connection...
16:57:29 MQT: Connect failed to 172.16.19.271:1883, rc -2. Retry in 10 sec
16:57:30 UPP: Multicast (re)joined
16:57:40 MQT: Attempting connection...
16:57:45 MQT: Connect failed to 172.16.19.271:1883, rc -2. Retry in 10 sec
16:57:46 UPP: Multicast (re)joined

TO REPRODUCE

Steps to reproduce the behavior:

Change IP of MQTT broker to incorrect IP to simulate failed broker, introduces lag. As soon as the IP is set correctly the behaviour goes away.

EXPECTED BEHAVIOUR

A clear and concise description of what you expected to happen.

This specific use case is a Shelly1 with a hard wired toggle switch and a light fixture, the idea being that the light can be turned on or off using the switch so it appears the same as before with no changes in look or feel. In the situation where the MQTT broker fails, until I can recover the unit my expectation would be that the unit continues to work with the hardware switch without any lag.

Thanks again for any and all help!

[ascillato]

Old duplicated issue.

Was related to the arduino core.

Please update to latest Tasmota.

[robc22]

Thanks so much for the quick response. I am pretty new to this but the research I did suggested that these issues were solved on older versions of the firmware that I have deployed, hence the new ticket. What version is this solved in?

[robc22]

Hi, Thanks for the response. I am a bit confused. When I looked all the tickets date back to Feb this year and older and were supposedly fixed in older versions of Tasmota than I have in use. What am I missing as I would really like to solve this issue!! Kind regards Rob Sent from Mail<https://go.microsoft.com/fwlink/?LinkId=550986> for Windows 10 From: Adrian Scillato<mailto:notifications@github.com> Sent: 16 November 2020 16:18 To: arendst/Tasmota<mailto:Tasmota@noreply.github.com> Cc: robc22<mailto:robertcroucher@outlook.com>; Author<mailto:author@noreply.github.com> Subject: Re: [arendst/Tasmota] Device lag when unable to contact MQTT server (#9886) Old duplicated issue. Was related to the arduino core. Please update to latest Tasmota. — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub<#9886 (comment)>, or unsubscribe<https://github.com/notifications/unsubscribe-auth/ARYZONPMH7QOBDI3CXSPPK3SQFGDXANCNFSM4TXLAXTA>.

[ascillato2]

Please update to latest Tasmota from the development branch. Thanks.

[ascillato2]

You can do an OTAurl upgrade from http://ota.tasmota.com/tasmota/tasmota.bin

This is the latest version

[robc22]

Thanks very much for the steer, I’ll do that and see what happens. Kind regards Rob Sent from Mail<https://go.microsoft.com/fwlink/?LinkId=550986> for Windows 10 From: Adrian Scillato<mailto:notifications@github.com> Sent: 16 November 2020 16:24 To: arendst/Tasmota<mailto:Tasmota@noreply.github.com> Cc: robc22<mailto:robertcroucher@outlook.com>; Author<mailto:author@noreply.github.com> Subject: Re: [arendst/Tasmota] Device lag when unable to contact MQTT server (#9886) You can do an OTA upgrade from http://ota.tasmota.com/tasmota/tasmota.bin This is the latest version — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub<#9886 (comment)>, or unsubscribe<https://github.com/notifications/unsubscribe-auth/ARYZONM7DLCDF3XM3BF4TL3SQFG35ANCNFSM4TXLAXTA>.

[robc22]

Just wanted to add to this, I have now updated to 9.1.0

Program Version	9.1.0(tasmota)
2020-11-07T11:57:45
2_7_4_5/2.2.2-dev(38a443e)
0T00:01:19

and the same issue still persists, if I enable MQTT but put an incorrect IP in to simulate an uncontactable broker, every time the unit attempts to connect there is a lag that affects the normal operation of the device.

What can I try now?

[ascillato2]

So, seems that the bug have reappeared again.

Reopening issue.

[ascillato2]

Hi,

Please, test latest Tasmota version from development branch. Theo have just fixed it. Thanks.

[robc22]

Will do, many thanks!

[robc22]

So I have now tested using the latest dev fw 9.1.0.2

The build details are below

Program Version	9.1.0.2(tasmota)
2020-11-18T11:20:55
2_7_4_7/2.2.2-dev(38a443e)

and my observations are as follows

1. The timeout when checking for the MQTT server now extends out in blocks of 10 seconds...starts off at 10s interval, then 20, then 30 etc.

2. While manually operating the switch to trigger the light across a timeout period I did not see any delays in responsiveness
   12:43:40 RSL: stat/Office/Light/Shelly/RESULT = {"POWER":"ON"}
   12:43:40 RSL: stat/Office/Light/Shelly/POWER = ON
   12:43:41 RSL: stat/Office/Light/Shelly/RESULT = {"POWER":"OFF"}
   12:43:41 RSL: stat/Office/Light/Shelly/POWER = OFF
   12:43:42 RSL: stat/Office/Light/Shelly/RESULT = {"POWER":"ON"}
   12:43:42 RSL: stat/Office/Light/Shelly/POWER = ON
   12:43:43 RSL: stat/Office/Light/Shelly/RESULT = {"POWER":"OFF"}
   12:43:43 RSL: stat/Office/Light/Shelly/POWER = OFF
   12:43:43 MQT: Attempting connection...
   12:43:43 MQT: Connect failed to 172.16.19.271:1883, rc -2. Retry in 60 sec
   12:43:43 RSL: stat/Office/Light/Shelly/RESULT = {"POWER":"ON"}
   12:43:43 RSL: stat/Office/Light/Shelly/POWER = ON
   12:43:44 UPP: Multicast (re)joined
   12:43:44 RSL: stat/Office/Light/Shelly/RESULT = {"POWER":"OFF"}
   12:43:44 RSL: stat/Office/Light/Shelly/POWER = OFF
   12:43:45 RSL: stat/Office/Light/Shelly/RESULT = {"POWER":"ON"}
   12:43:45 RSL: stat/Office/Light/Shelly/POWER = ON
   12:43:46 RSL: stat/Office/Light/Shelly/RESULT = {"POWER":"OFF"}
   12:43:46 RSL: stat/Office/Light/Shelly/POWER = OFF
   12:43:47 RSL: stat/Office/Light/Shelly/RESULT = {"POWER":"ON"}
   12:43:47 RSL: stat/Office/Light/Shelly/POWER = ON
   12:43:48 RSL: stat/Office/Light/Shelly/RESULT = {"POWER":"OFF"}
   12:43:48 RSL: stat/Office/Light/Shelly/POWER = OFF

For me at least this issue appears to be fixed! Just a couple of outstanding questions!

1. Will this change be rolled into the next mainstream version of Tasmota? Should I wait for that to update the remaining devices or use this dev version?

2. Will this change work equally well for Sonoff and Shelly devices?

Many thanks for all your help getting this resolved.

[arendst]

In general once a fix is in dev it will be in release too. Next release is planned around mid-December so I suggest you start using dev and report any issues you encounter to get a stable release.

As it's a global MQTT wifi fix I'm quite sure it works on any hardware.

[robc22]

Just wanted to follow-up on this after a few days. Today I noticed that all of the devices with the dev firmware were uncontactable (could not be pinged), however I could communicate with them using MQTT and after a quick restart they were all pingable again.... This isnt behaviour I experienced using 8.3.1 previously.

[ascillato]

The ping issue is from your router's side. Search in issues for ARP issue. (#7098, #7770, #8439)

You can workaround this following the information in that old issue (depending on your router brand) and if your router was not listed and don't have any ARP option, you can enable gratuitous ARP feature of Tasmota (setoption41 105)

[miazza99]

I discovered this also on my Tasmota POW2 device and I thought the push button was defective ... ... now I understand it's worth to update to latest FW.
Is this issue now solved in the latest stable release ?
My POW2 is also powering the raspberry where the MQTT server is installed so everytime the switch is OFF, the MQTT is down and the the device becomes unresponsive for a while....