search

arendst / Tasmota

Alternative firmware for ESP8266 and ESP32 based devices with easy configuration using webUI, OTA updates, automation using timers or rules, expandability and entirely local control over MQTT, HTTP, Serial or KNX. Full documentation at
https://tasmota.github.io/docs
GNU General Public License v3.0
22.22k stars 4.81k forks source link

Timers problem when MQTT connection lost #4555

Closed mvincm closed 5 years ago

mvincm commented 5 years ago

Describe the bug For some reasons when MQTT is on but there is a problem with the MQTT server (it is off or there is no internet connection), Timers go "crazy".

I am using rules and timers for a simple thermostat. My code looks very similar to a wiki example.

My code:

rule on system#boot do ruletimer1 70 endon on rules#timer=1 do backlog var1 0; ruletimer1 70; power1 0; endon on TELE-DS18B20#TEMPERATURE do backlog var1 1; ruletimer1 70; event ctrl_ready=1; event temp_demand=%value%; endon on event#ctrl_ready>%mem1% do var1 0 endon on event#temp_demand>%mem2% do power1 0 endon on event#temp_demand<%mem3% do power1 %var1% endon

and logs looks like that

17:37:51 RSL: sonoff_1/tele/SENSOR = {"Time":"2018-12-07T17:37:51","DS18B20":{"Temperature":21.4},"TempUnit":"C"}
17:37:51 RUL: TELE-DS18B20#TEMPERATURE performs "backlog backlog var1 1; ruletimer1 70; event ctrl_ready=1; event temp_demand=21.4;"
17:37:52 RSL: sonoff_1/stat/RESULT = {"Var1":"1"}
17:37:52 RSL: sonoff_1/stat/RESULT = {"T1":70,"T2":0,"T3":0,"T4":0,"T5":0,"T6":0,"T7":0,"T8":0}
17:37:52 MQT: Attempting connection...
17:37:58 MQT: Connect failed to 192.168.22.5:1883, rc -2. Retry in 10 sec
17:37:58 RSL: sonoff_1/stat/RESULT = {"Event":"Done"}
17:37:59 RSL: sonoff_1/stat/RESULT = {"Event":"Done"}
17:37:59 RUL: EVENT#TEMP_DEMAND<%MEM3% performs "power1 1"
17:37:59 RSL: sonoff_1/stat/RESULT = {"POWER1":"ON"}
17:37:59 RSL: sonoff_1/stat/POWER1 = ON
17:38:09 MQT: Attempting connection...
17:38:15 MQT: Connect failed to 192.168.22.5:1883, rc -2. Retry in 10 sec
17:38:26 MQT: Attempting connection...
17:38:32 MQT: Connect failed to 192.168.22.5:1883, rc -2. Retry in 10 sec
17:38:41 CMD: power
17:38:41 RSL: sonoff_1/stat/RESULT = {"POWER1":"ON"}
17:38:41 RSL: sonoff_1/stat/POWER1 = ON
17:38:43 MQT: Attempting connection...
17:38:49 MQT: Connect failed to 192.168.22.5:1883, rc -2. Retry in 10 sec
17:39:00 MQT: Attempting connection...
17:39:06 MQT: Connect failed to 192.168.22.5:1883, rc -2. Retry in 10 sec
17:39:06 RUL: RULES#TIMER=1 performs "backlog var1 0; ruletimer1 70; power1 0;"
17:39:06 RSL: sonoff_1/stat/RESULT = {"Var1":"0"}
17:39:07 RSL: sonoff_1/stat/RESULT = {"T1":70,"T2":0,"T3":0,"T4":0,"T5":0,"T6":0,"T7":0,"T8":0}
17:39:07 RSL: sonoff_1/stat/RESULT = {"POWER1":"OFF"}
17:39:07 RSL: sonoff_1/stat/POWER1 = OFF

as we can see every 60 sec we chceck tele-ds18b20 and this event rise ruletimer1 to 70 and if there is proper temeprature put POWER ON. Next timer goes down to 0 and rule timer=1 turn off power, next tele and so on, so on.

So, in my opinion, there is some race with rules or MQTT timer mess with Timer from the thermostat. If MQQT connection works proper rules works great.

17:51:05 CMD: status 0
17:51:05 RSL: sonoff_1/stat/STATUS = {"Status":{"Module":1,"FriendlyName":["sonoff_mm"],"Topic":"sonoff_1","ButtonTopic":"0","Power":1,"PowerOnState":0,"LedState":1,"SaveData":1,"SaveState":0,"ButtonRetain":0,"PowerRetain":0}}
17:51:05 RSL: sonoff_1/stat/STATUS1 = {"StatusPRM":{"Baudrate":115200,"GroupTopic":"sonoffs","OtaUrl":"http://sonoff.maddox.co.uk/tasmota/sonoff.bin","RestartReason":"Software/System restart","Uptime":"0T00:28:33","StartupUTC":"2018-12-07T16:22:32","Sleep":0,"BootCount":27,"SaveCount":73,"SaveAddress":"FB000"}}
17:51:05 RSL: sonoff_1/stat/STATUS2 = {"StatusFWR":{"Version":"6.2.1","BuildDateTime":"2018-09-09T16:50:26","Boot":31,"Core":"2_3_0","SDK":"1.5.3(aec24ac9)"}}
17:51:05 RSL: sonoff_1/stat/STATUS3 = {"StatusLOG":{"SerialLog":2,"WebLog":2,"SysLog":0,"LogHost":"","LogPort":514,"SSId":["KoroFlat",""],"TelePeriod":60,"SetOption":["04008008","55818000","00000000"]}}
17:51:05 RSL: sonoff_1/stat/STATUS4 = {"StatusMEM":{"ProgramSize":471,"Free":532,"Heap":15,"ProgramFlashSize":1024,"FlashSize":1024,"FlashMode":3,"Features":["00000809","0FDAE794","000003A0","23B617CE","00000000"]}}
17:51:05 RSL: sonoff_1/stat/STATUS5 = {"StatusNET":{"Hostname":"sonoff_mm","IPAddress":"192.168.22.162","Gateway":"192.168.22.1","Subnetmask":"255.255.255.0","DNSServer":"192.168.22.1","Mac":"84:F3:EB:48:6D:51","Webserver":2,"WifiConfig":5}}
17:51:05 RSL: sonoff_1/stat/STATUS6 = {"StatusMQT":{"MqttHost":"192.168.22.5","MqttPort":1883,"MqttClientMask":"sonoff_client_1","MqttClient":"sonoff_client_1","MqttUser":"sonoff_user","MqttType":1,"MAX_PACKET_SIZE":1000,"KEEPALIVE":15}}
17:51:05 RSL: sonoff_1/stat/STATUS7 = {"StatusTIM":{"UTC":"Fri Dec 07 16:51:05 2018","Local":"Fri Dec 07 17:51:05 2018","StartDST":"Sun Mar 25 02:00:00 2018","EndDST":"Sun Oct 28 03:00:00 2018","Timezone":1,"Sunrise":"08:29","Sunset":"16:53"}}
17:51:05 RSL: sonoff_1/stat/STATUS10 = {"StatusSNS":{"Time":"2018-12-07T17:51:05","DS18B20":{"Temperature":21.6},"TempUnit":"C"}}
17:51:05 RSL: sonoff_1/stat/STATUS11 = {"StatusSTS":{"Time":"2018-12-07T17:51:05","Uptime":"0T00:28:33","Vcc":3.185,"POWER1":"ON","Wifi":{"AP":1,"SSId":"KoroFlat","RSSI":74,"APMac":"34:CE:00:63:20:41"}}}

To Reproduce as described above

Expected behavior timers should work correctly if there are some mqtt connection problems

Best regards, MvincM

mvincm commented 5 years ago

Let's me think...

My rules work just fine. Without any MQTT or with properly working MQTT everything work as supposed to be.

But if there are some problems with MQTT communication for some reason "temp checking event" is not after 60 seconds so timer goes down to 0 because is not raised in "TELE-DS18B20#TEMPERATURE" event in proper time.

Why? It is a bug or something else...

MvincM

ascillato commented 5 years ago

Have you tried to increase to double your ruletimer time ?

mvincm commented 5 years ago

Ok so...

TelePeriod is set to 60 but event TELE-DS18B20#TEMPERATURE comes between 89 seconds to max 96 seconds. When I set ruletimer1 to 100 (it must be greater than teleperiod which is unstable but not greater than 96) it wokrs fine.

So the question is why TelePeriod is ustable? I know that MQTT reconnection process reset some timer but how it corresponds to TelePEriod and why 96 seconds is a maximum value... Increasing ruletimer1 to 100 seconds works but it looks like some kind of workaround.

mvincm commented 5 years ago

Update...

For example, now it takes 105 seconds to rise TELE event... so in such a case the whole solution is not deterministic and it is hard to leave sonoff like a standalone thermostat.

ascillato commented 5 years ago

There were several changes between your version and the latest 6.3.0.16

Indeed more than 700 changes.

Can you update and test again please to narrow the posibilities? Thanks

mvincm commented 5 years ago

Hello.

It's a pity but the same situation on 6.3.0.16. TELE event appears every 90 to 96 seconds. Unpredictable... There is no problem with the fact that it is about 90 seconds. A bigger problem is that it supposed to be every 60 seconds or a least stable 90 seconds (but who knows why it is about 90 seconds).

My "status 0" from 6.3.0.16

09:50:48 CMD: status 0
09:50:48 RSL: sonoff_1/stat/STATUS = {"Status":{"Module":1,"FriendlyName":["sonoff_mm"],"Topic":"sonoff_1","ButtonTopic":"0","Power":1,"PowerOnState":0,"LedState":1,"SaveData":1,"SaveState":0,"SwitchTopic":"","SwitchMode":[3,0,0,0,0,0,0,0],"ButtonRetain":0,"SwitchRetain":0,"SensorRetain":0,"PowerRetain":0}}
09:50:48 RSL: sonoff_1/stat/STATUS1 = {"StatusPRM":{"Baudrate":115200,"GroupTopic":"sonoffs","OtaUrl":"http://sonoff.maddox.co.uk/tasmota/sonoff.bin","RestartReason":"Software/System restart","Uptime":"0T00:17:07","StartupUTC":"2018-12-08T08:33:41","Sleep":50,"BootCount":32,"SaveCount":110,"SaveAddress":"F7000"}}
09:50:48 RSL: sonoff_1/stat/STATUS2 = {"StatusFWR":{"Version":"6.3.0.16(dc63d0f-sonoff)","BuildDateTime":"2018-12-07T19:01:28","Boot":31,"Core":"2_3_0","SDK":"1.5.3(aec24ac9)"}}
09:50:48 RSL: sonoff_1/stat/STATUS3 = {"StatusLOG":{"SerialLog":2,"WebLog":2,"SysLog":0,"LogHost":"","LogPort":514,"SSId":["KoroFlat",""],"TelePeriod":60,"SetOption":["04008008","558180C0","00000000"]}}
09:50:48 RSL: sonoff_1/stat/STATUS4 = {"StatusMEM":{"ProgramSize":502,"Free":500,"Heap":14,"ProgramFlashSize":1024,"FlashSize":1024,"FlashChipId":"14405E","FlashMode":3,"Features":["00000809","0FDAE794","000383A0","23B617CE","00003BC0"]}}
09:50:48 RSL: sonoff_1/stat/STATUS5 = {"StatusNET":{"Hostname":"sonoff_mm","IPAddress":"192.168.22.162","Gateway":"192.168.22.1","Subnetmask":"255.255.255.0","DNSServer":"192.168.22.1","Mac":"84:F3:EB:48:6D:51","Webserver":2,"WifiConfig":5}}
09:50:48 RSL: sonoff_1/stat/STATUS6 = {"StatusMQT":{"MqttHost":"192.168.22.5","MqttPort":1883,"MqttClientMask":"sonoff_client_1","MqttClient":"sonoff_client_1","MqttUser":"sonoff_user","MqttType":1,"MAX_PACKET_SIZE":1000,"KEEPALIVE":15}}
09:50:48 RSL: sonoff_1/stat/STATUS7 = {"StatusTIM":{"UTC":"Sat Dec 08 08:50:48 2018","Local":"Sat Dec 08 09:50:48 2018","StartDST":"Sun Mar 25 02:00:00 2018","EndDST":"Sun Oct 28 03:00:00 2018","Timezone":"+01:00","Sunrise":"08:30","Sunset":"16:53"}}
09:50:48 RSL: sonoff_1/stat/STATUS10 = {"StatusSNS":{"Time":"2018-12-08T09:50:48","DS18B20":{"Temperature":23.3},"TempUnit":"C"}}
09:50:48 RSL: sonoff_1/stat/STATUS11 = {"StatusSTS":{"Time":"2018-12-08T09:50:48","Uptime":"0T00:17:07","Vcc":3.184,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":241,"POWER1":"ON","Wifi":{"AP":1,"SSId":"KoroFlat","BSSId":"34:CE:00:63:20:41","Channel":6,"RSSI":86}}}
Jason2866 commented 5 years ago

Just a shot in the dark... Try set: Sleep 0

Jason2866 commented 5 years ago

Other question why you loose mqtt connection?

andrethomas commented 5 years ago

Even on sleep 50 you are having "LoadAvg":241 - Can you tell us what all you have connected to this device? Something is consuming an unexpectedly long loop time on your device.

Also can you confirm if this is happening when WiFi is down or when WiFi is up but mqtt is down?

Jason2866 commented 5 years ago

Have you tried to erase the whole flash with Esptool before flashing a different firmware? What andrethomas about LoadAvg commented makes me curios. If just a single DS18B20 is connected this value is too high

mvincm commented 5 years ago

@Jason2866

@andrethomas It is SONOFF Basic with GPIO14 used by DS18B20. Of course, the sensor is enabled in configuration.

My "rule" looks like that:

rule on system#boot do ruletimer1 100 endon on rules#timer=1 do backlog var1 0; ruletimer1 100; power1 0; endon on TELE-DS18B20#TEMPERATURE do backlog var1 1; ruletimer1 100; event ctrl_ready=1; event temp_demand=%value%; endon on event#ctrl_ready>%mem1% do var1 0 endon on event#temp_demand>%mem2% do power1 0 endon on event#temp_demand<%mem3% do power1 %var1% endon

Nothing more is connected (hardware) or no other rules or timers are set.

WiFi works well and only local MQTT server is down for test reasons and "yes" flash was erased before flashing.

My high LoadAvg corresponding to MQTT reconnect process and my "rule"???

Best regards, MvincM

andrethomas commented 5 years ago

@mvincm MQTT down will not cause that LoadAvg on sleep 50.

Can you please disable the rule and see if that brings the LoadAvg down to ~19

Set your teleperiod to 10 so that you can see the LoadAvg more frequently.

If disabling the rule does not bring down the LoadAvg to ~19, please also disable the pin for the sensor and see if that brings it down.

This way we can isolate whats keeping the main loop so busy and perhaps isolate the source of the problem you're experiencing.

When testing is done please remember to reset your teleperiod to the previous value you had configured.

Thanks

mvincm commented 5 years ago

Of course, I will try all your suggestions but for now, a strange thing has happened....

My connection to sonoff is dead. Sonoff is working (button toggle power, led is blinking) but ping doesn't replay at all. Reboot doesn't help either. I think that some process kill cpu to end.

I will try to reflash module and take fight one again. Say tune ;))

Best regards, MvincM

mvincm commented 5 years ago

OK... Totally fresh install (6.3.0.16) with full flash erased...

Case 1:

Part log of "status 0" command: "Uptime":"0T00:10:42","Vcc":3.197,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"POWER":"OFF"

Case 2:

Part log of "status 0" command: "Uptime":"0T01:07:58","Vcc":3.196,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"POWER":"OFF"

Case 3:

Part log of "status 0" command: "Uptime":"0T01:39:16","Vcc":3.196,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"POWER":"OFF"

Case 4:

Part log of "status 0" command: "Uptime":"0T02:03:43","Vcc":3.190,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"POWER1":"ON"

Custom rules:

backlog switchmode1 3; rule 1; rule 4; teleperiod 60; setoption26 1; setoption0 0; poweronstate 0; mem1 0; mem2 26; mem3 23; var1 0

rule on system#boot do ruletimer1 70 endon on rules#timer=1 do backlog var1 0; ruletimer1 70; power1 0; endon on TELE-DS18B20#TEMPERATURE do backlog var1 1; ruletimer1 70; event ctrl_ready=1; event temp_demand=%value%; endon on event#ctrl_ready>%mem1% do var1 0 endon on event#temp_demand>%mem2% do power1 0 endon on event#temp_demand<%mem3% do power1 %var1% endon

Teleperiod switch:

13:24:04 RSL: tele/sonoff/SENSOR
13:25:08 RSL: tele/sonoff/SENSOR
13:26:13 RSL: tele/sonoff/SENSOR
13:27:17 RSL: tele/sonoff/SENSOR
13:28:22 RSL: tele/sonoff/SENSOR
13:29:26 RSL: tele/sonoff/SENSOR
13:30:30 RSL: tele/sonoff/SENSOR

Case 5:

Part log of "status 0" command: "Uptime":"0T00:19:48","Vcc":3.190,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":610,"POWER1":"ON"

Teleperiod fluctuating:

13:45:11 RSL: tele/sonoff/SENSOR - 97 seconds 
13:46:48 RSL: tele/sonoff/SENSOR - 92 seconds
13:48:20 RSL: tele/sonoff/SENSOR - 97 seconds
13:49:57 RSL: tele/sonoff/SENSOR

Full log:

00:00:00 Project sonoff Sonoff (Topic sonoff, Fallback DVES_486D51, GroupTopic sonoffs) Version 6.3.0.16(dc63d0f-sonoff)-2_3_0
00:00:00 WIF: Connecting to AP1 KoroFlat in mode 11N as sonoff_mm...
00:00:05 WIF: Connected
00:00:05 DNS: Initialized
00:00:05 HTP: Web server active on sonoff_mm.local with IP address 192.168.22.162
00:00:06 MQT: Attempting connection...
13:43:53 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:44:04 MQT: Attempting connection...
13:44:11 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:44:21 MQT: Attempting connection...
13:44:28 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:44:39 MQT: Attempting connection...
13:44:45 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:44:56 MQT: Attempting connection...
13:45:02 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:45:11 RSL: tele/sonoff/STATE = {"Time":"2018-12-09T13:45:11","Uptime":"0T00:01:31","Vcc":3.207,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"POWER1":"ON","Wifi":{"AP":1,"SSId":"KoroFlat","BSSId":"34:CE:00:63:20:41","Channel":6,"RSSI":78}}
13:45:11 RSL: tele/sonoff/SENSOR = {"Time":"2018-12-09T13:45:11","DS18B20":{"Temperature":21.4},"TempUnit":"C"}
13:45:11 RUL: TELE-DS18B20#TEMPERATURE performs "backlog backlog var1 1; ruletimer1 70; event ctrl_ready=1; event temp_demand=21.4;"
13:45:11 RSL: stat/sonoff/RESULT = {"Var1":"1"}
13:45:11 RSL: stat/sonoff/RESULT = {"T1":70,"T2":0,"T3":0,"T4":0,"T5":0,"T6":0,"T7":0,"T8":0}
13:45:11 RSL: stat/sonoff/RESULT = {"Event":"Done"}
13:45:11 RSL: stat/sonoff/RESULT = {"Event":"Done"}
13:45:12 RUL: EVENT#TEMP_DEMAND<%MEM3% performs "power1 1"
13:45:12 RSL: stat/sonoff/RESULT = {"POWER1":"ON"}
13:45:12 RSL: stat/sonoff/POWER1 = ON
13:45:13 MQT: Attempting connection...
13:45:20 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:45:31 MQT: Attempting connection...
13:45:37 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:45:48 MQT: Attempting connection...
13:45:55 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:46:03 CMD: state 0
13:46:03 RSL: stat/sonoff/RESULT = {"Time":"2018-12-09T13:46:03","Uptime":"0T00:02:23","Vcc":3.192,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"POWER1":"ON","Wifi":{"AP":1,"SSId":"KoroFlat","BSSId":"34:CE:00:63:20:41","Channel":6,"RSSI":80}}
13:46:05 MQT: Attempting connection...
13:46:12 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:46:22 RUL: RULES#TIMER=1 performs "backlog var1 0; ruletimer1 70; power1 0;"
13:46:22 RSL: stat/sonoff/RESULT = {"Var1":"0"}
13:46:22 RSL: stat/sonoff/RESULT = {"T1":70,"T2":0,"T3":0,"T4":0,"T5":0,"T6":0,"T7":0,"T8":0}
13:46:23 MQT: Attempting connection...
13:46:29 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:46:29 RSL: stat/sonoff/RESULT = {"POWER1":"OFF"}
13:46:29 RSL: stat/sonoff/POWER1 = OFF
13:46:40 MQT: Attempting connection...
13:46:46 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:46:48 RSL: tele/sonoff/STATE = {"Time":"2018-12-09T13:46:48","Uptime":"0T00:03:08","Vcc":3.190,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":100,"POWER1":"OFF","Wifi":{"AP":1,"SSId":"KoroFlat","BSSId":"34:CE:00:63:20:41","Channel":6,"RSSI":80}}
13:46:48 RSL: tele/sonoff/SENSOR = {"Time":"2018-12-09T13:46:48","DS18B20":{"Temperature":21.4},"TempUnit":"C"}
13:46:48 RUL: TELE-DS18B20#TEMPERATURE performs "backlog backlog var1 1; ruletimer1 70; event ctrl_ready=1; event temp_demand=21.4;"
13:46:49 RSL: stat/sonoff/RESULT = {"Var1":"1"}
13:46:49 RSL: stat/sonoff/RESULT = {"T1":70,"T2":0,"T3":0,"T4":0,"T5":0,"T6":0,"T7":0,"T8":0}
13:46:49 RSL: stat/sonoff/RESULT = {"Event":"Done"}
13:46:50 RSL: stat/sonoff/RESULT = {"Event":"Done"}
13:46:50 RUL: EVENT#TEMP_DEMAND<%MEM3% performs "power1 1"
13:46:50 RSL: stat/sonoff/RESULT = {"POWER1":"ON"}
13:46:50 RSL: stat/sonoff/POWER1 = ON
13:46:57 MQT: Attempting connection...
13:47:04 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:47:15 MQT: Attempting connection...
13:47:21 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:47:32 MQT: Attempting connection...
13:47:38 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:47:49 MQT: Attempting connection...
13:47:55 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:47:59 RUL: RULES#TIMER=1 performs "backlog var1 0; ruletimer1 70; power1 0;"
13:48:00 RSL: stat/sonoff/RESULT = {"Var1":"0"}
13:48:00 RSL: stat/sonoff/RESULT = {"T1":70,"T2":0,"T3":0,"T4":0,"T5":0,"T6":0,"T7":0,"T8":0}
13:48:00 RSL: stat/sonoff/RESULT = {"POWER1":"OFF"}
13:48:00 RSL: stat/sonoff/POWER1 = OFF
13:48:06 MQT: Attempting connection...
13:48:13 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:48:20 RSL: tele/sonoff/STATE = {"Time":"2018-12-09T13:48:20","Uptime":"0T00:04:40","Vcc":3.190,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"POWER1":"OFF","Wifi":{"AP":1,"SSId":"KoroFlat","BSSId":"34:CE:00:63:20:41","Channel":6,"RSSI":82}}
13:48:20 RSL: tele/sonoff/SENSOR = {"Time":"2018-12-09T13:48:20","DS18B20":{"Temperature":21.4},"TempUnit":"C"}
13:48:20 RUL: TELE-DS18B20#TEMPERATURE performs "backlog backlog var1 1; ruletimer1 70; event ctrl_ready=1; event temp_demand=21.4;"
13:48:20 RSL: stat/sonoff/RESULT = {"Var1":"1"}
13:48:20 RSL: stat/sonoff/RESULT = {"T1":70,"T2":0,"T3":0,"T4":0,"T5":0,"T6":0,"T7":0,"T8":0}
13:48:20 RSL: stat/sonoff/RESULT = {"Event":"Done"}
13:48:21 RSL: stat/sonoff/RESULT = {"Event":"Done"}
13:48:21 RUL: EVENT#TEMP_DEMAND<%MEM3% performs "power1 1"
13:48:21 RSL: stat/sonoff/RESULT = {"POWER1":"ON"}
13:48:21 RSL: stat/sonoff/POWER1 = ON
13:48:23 MQT: Attempting connection...
13:48:30 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:48:40 MQT: Attempting connection...
13:48:47 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:48:58 MQT: Attempting connection...
13:49:04 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:49:15 MQT: Attempting connection...
13:49:21 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:49:30 RUL: RULES#TIMER=1 performs "backlog var1 0; ruletimer1 70; power1 0;"
13:49:31 RSL: stat/sonoff/RESULT = {"Var1":"0"}
13:49:31 RSL: stat/sonoff/RESULT = {"T1":70,"T2":0,"T3":0,"T4":0,"T5":0,"T6":0,"T7":0,"T8":0}
13:49:31 RSL: stat/sonoff/RESULT = {"POWER1":"OFF"}
13:49:31 RSL: stat/sonoff/POWER1 = OFF
13:49:32 MQT: Attempting connection...
13:49:38 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:49:49 MQT: Attempting connection...
13:49:56 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:49:57 RSL: tele/sonoff/STATE = {"Time":"2018-12-09T13:49:57","Uptime":"0T00:06:17","Vcc":3.190,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":259,"POWER1":"OFF","Wifi":{"AP":1,"SSId":"KoroFlat","BSSId":"34:CE:00:63:20:41","Channel":6,"RSSI":82}}
13:49:57 RSL: tele/sonoff/SENSOR = {"Time":"2018-12-09T13:49:57","DS18B20":{"Temperature":21.4},"TempUnit":"C"}
13:49:57 RUL: TELE-DS18B20#TEMPERATURE performs "backlog backlog var1 1; ruletimer1 70; event ctrl_ready=1; event temp_demand=21.4;"
13:49:57 RSL: stat/sonoff/RESULT = {"Var1":"1"}
13:49:57 RSL: stat/sonoff/RESULT = {"T1":70,"T2":0,"T3":0,"T4":0,"T5":0,"T6":0,"T7":0,"T8":0}
13:49:57 RSL: stat/sonoff/RESULT = {"Event":"Done"}
13:49:58 RSL: stat/sonoff/RESULT = {"Event":"Done"}
13:49:58 RUL: EVENT#TEMP_DEMAND<%MEM3% performs "power1 1"
13:49:58 RSL: stat/sonoff/RESULT = {"POWER1":"ON"}
13:49:58 RSL: stat/sonoff/POWER1 = ON
13:50:06 MQT: Attempting connection...
13:50:13 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:50:24 MQT: Attempting connection...
13:50:30 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:50:41 MQT: Attempting connection...
13:50:47 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:50:47 CMD: status 0
13:50:47 RSL: stat/sonoff/STATUS = {"Status":{"Module":1,"FriendlyName":["Sonoff"],"Topic":"sonoff","ButtonTopic":"0","Power":1,"PowerOnState":0,"LedState":1,"SaveData":1,"SaveState":0,"SwitchTopic":"0","SwitchMode":[3,0,0,0,0,0,0,0],"ButtonRetain":0,"SwitchRetain":0,"SensorRetain":0,"PowerRetain":0}}
13:50:47 RSL: stat/sonoff/STATUS1 = {"StatusPRM":{"Baudrate":115200,"GroupTopic":"sonoffs","OtaUrl":"http://thehackbox.org/tasmota/release/sonoff.bin","RestartReason":"Software/System restart","Uptime":"0T00:07:07","StartupUTC":"2018-12-09T12:43:40","Sleep":50,"BootCount":5,"SaveCount":18,"SaveAddress":"FA000"}}
13:50:47 RSL: stat/sonoff/STATUS2 = {"StatusFWR":{"Version":"6.3.0.16(dc63d0f-sonoff)","BuildDateTime":"2018-12-07T19:01:28","Boot":31,"Core":"2_3_0","SDK":"1.5.3(aec24ac9)"}}
13:50:47 RSL: stat/sonoff/STATUS3 = {"StatusLOG":{"SerialLog":2,"WebLog":2,"SysLog":0,"LogHost":"","LogPort":514,"SSId":["KoroFlat",""],"TelePeriod":60,"SetOption":["04008008","558180C0","00000000"]}}
13:50:47 RSL: stat/sonoff/STATUS4 = {"StatusMEM":{"ProgramSize":502,"Free":500,"Heap":14,"ProgramFlashSize":1024,"FlashSize":1024,"FlashChipId":"14405E","FlashMode":3,"Features":["00000809","0FDAE794","000383A0","23B617CE","00003BC0"]}}
13:50:47 RSL: stat/sonoff/STATUS5 = {"StatusNET":{"Hostname":"sonoff_mm","IPAddress":"192.168.22.162","Gateway":"192.168.22.1","Subnetmask":"255.255.255.0","DNSServer":"192.168.22.1","Mac":"84:F3:EB:48:6D:51","Webserver":2,"WifiConfig":4}}
13:50:47 RSL: stat/sonoff/STATUS6 = {"StatusMQT":{"MqttHost":"noserver.local","MqttPort":1883,"MqttClientMask":"DVES_%06X","MqttClient":"DVES_486D51","MqttUser":"DVES_USER","MqttType":1,"MAX_PACKET_SIZE":1000,"KEEPALIVE":15}}
13:50:47 RSL: stat/sonoff/STATUS7 = {"StatusTIM":{"UTC":"Sun Dec 09 12:50:47 2018","Local":"Sun Dec 09 13:50:47 2018","StartDST":"Sun Mar 25 02:00:00 2018","EndDST":"Sun Oct 28 03:00:00 2018","Timezone":"+01:00","Sunrise":"08:31","Sunset":"16:53"}}
13:50:47 RSL: stat/sonoff/STATUS10 = {"StatusSNS":{"Time":"2018-12-09T13:50:47","DS18B20":{"Temperature":21.4},"TempUnit":"C"}}
13:50:47 RSL: stat/sonoff/STATUS11 = {"StatusSTS":{"Time":"2018-12-09T13:50:47","Uptime":"0T00:07:07","Vcc":3.189,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":632,"POWER1":"ON","Wifi":{"AP":1,"SSId":"KoroFlat","BSSId":"34:CE:00:63:20:41","Channel":6,"RSSI":80}}}
13:50:58 MQT: Attempting connection...
13:51:04 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:51:08 RUL: RULES#TIMER=1 performs "backlog var1 0; ruletimer1 70; power1 0;"
13:51:08 RSL: stat/sonoff/RESULT = {"Var1":"0"}
13:51:08 RSL: stat/sonoff/RESULT = {"T1":70,"T2":0,"T3":0,"T4":0,"T5":0,"T6":0,"T7":0,"T8":0}
13:51:08 RSL: stat/sonoff/RESULT = {"POWER1":"OFF"}
13:51:08 RSL: stat/sonoff/POWER1 = OFF
13:51:15 MQT: Attempting connection...
13:51:22 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:56:44 MQT: Attempting connection...
13:56:50 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:57:01 MQT: Attempting connection...
13:57:08 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:57:18 MQT: Attempting connection...
13:57:25 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:57:25 RUL: RULES#TIMER=1 performs "backlog var1 0; ruletimer1 70; power1 0;"
13:57:25 RSL: stat/sonoff/RESULT = {"Var1":"0"}
13:57:25 RSL: stat/sonoff/RESULT = {"T1":70,"T2":0,"T3":0,"T4":0,"T5":0,"T6":0,"T7":0,"T8":0}
13:57:26 RSL: stat/sonoff/RESULT = {"POWER1":"OFF"}
13:57:26 RSL: stat/sonoff/POWER1 = OFF
13:57:36 MQT: Attempting connection...
13:57:42 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:57:46 RSL: tele/sonoff/STATE = {"Time":"2018-12-09T13:57:46","Uptime":"0T00:14:06","Vcc":3.190,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":20,"POWER1":"OFF","Wifi":{"AP":1,"SSId":"KoroFlat","BSSId":"34:CE:00:63:20:41","Channel":6,"RSSI":66}}
13:57:46 RSL: tele/sonoff/SENSOR = {"Time":"2018-12-09T13:57:46","DS18B20":{"Temperature":21.3},"TempUnit":"C"}
13:57:46 RUL: TELE-DS18B20#TEMPERATURE performs "backlog backlog var1 1; ruletimer1 70; event ctrl_ready=1; event temp_demand=21.3;"
13:57:46 RSL: stat/sonoff/RESULT = {"Var1":"1"}
13:57:47 RSL: stat/sonoff/RESULT = {"T1":70,"T2":0,"T3":0,"T4":0,"T5":0,"T6":0,"T7":0,"T8":0}
13:57:47 RSL: stat/sonoff/RESULT = {"Event":"Done"}
13:57:47 RSL: stat/sonoff/RESULT = {"Event":"Done"}
13:57:47 RUL: EVENT#TEMP_DEMAND<%MEM3% performs "power1 1"
13:57:47 RSL: stat/sonoff/RESULT = {"POWER1":"ON"}
13:57:47 RSL: stat/sonoff/POWER1 = ON
13:57:53 MQT: Attempting connection...
13:57:59 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:58:10 MQT: Attempting connection...
13:58:17 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:58:27 MQT: Attempting connection...
13:58:34 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:58:45 MQT: Attempting connection...
13:58:51 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:58:57 RUL: RULES#TIMER=1 performs "backlog var1 0; ruletimer1 70; power1 0;"
13:58:57 RSL: stat/sonoff/RESULT = {"Var1":"0"}
13:58:58 RSL: stat/sonoff/RESULT = {"T1":70,"T2":0,"T3":0,"T4":0,"T5":0,"T6":0,"T7":0,"T8":0}
13:58:58 RSL: stat/sonoff/RESULT = {"POWER1":"OFF"}
13:58:58 RSL: stat/sonoff/POWER1 = OFF
13:59:02 MQT: Attempting connection...
13:59:08 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:59:17 RSL: tele/sonoff/STATE = {"Time":"2018-12-09T13:59:17","Uptime":"0T00:15:37","Vcc":3.209,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"POWER1":"OFF","Wifi":{"AP":1,"SSId":"KoroFlat","BSSId":"34:CE:00:63:20:41","Channel":6,"RSSI":70}}
13:59:17 RSL: tele/sonoff/SENSOR = {"Time":"2018-12-09T13:59:17","DS18B20":{"Temperature":21.4},"TempUnit":"C"}
13:59:17 RUL: TELE-DS18B20#TEMPERATURE performs "backlog backlog var1 1; ruletimer1 70; event ctrl_ready=1; event temp_demand=21.4;"
13:59:18 RSL: stat/sonoff/RESULT = {"Var1":"1"}
13:59:18 RSL: stat/sonoff/RESULT = {"T1":70,"T2":0,"T3":0,"T4":0,"T5":0,"T6":0,"T7":0,"T8":0}
13:59:18 RSL: stat/sonoff/RESULT = {"Event":"Done"}
13:59:18 APP: Serial logging disabled
13:59:18 RSL: stat/sonoff/RESULT = {"Event":"Done"}
13:59:19 RUL: EVENT#TEMP_DEMAND<%MEM3% performs "power1 1"
13:59:19 RSL: stat/sonoff/RESULT = {"POWER1":"ON"}
13:59:19 RSL: stat/sonoff/POWER1 = ON
13:59:19 MQT: Attempting connection...
13:59:26 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:59:37 MQT: Attempting connection...
13:59:43 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
13:59:54 MQT: Attempting connection...
14:00:00 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
14:00:11 MQT: Attempting connection...
14:00:17 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
14:00:28 MQT: Attempting connection...
14:00:35 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
14:00:35 RUL: RULES#TIMER=1 performs "backlog var1 0; ruletimer1 70; power1 0;"
14:00:35 RSL: stat/sonoff/RESULT = {"Var1":"0"}
14:00:36 RSL: stat/sonoff/RESULT = {"T1":70,"T2":0,"T3":0,"T4":0,"T5":0,"T6":0,"T7":0,"T8":0}
14:00:36 RSL: stat/sonoff/RESULT = {"POWER1":"OFF"}
14:00:36 RSL: stat/sonoff/POWER1 = OFF
14:00:46 MQT: Attempting connection...
14:00:52 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
14:00:55 RSL: tele/sonoff/STATE = {"Time":"2018-12-09T14:00:55","Uptime":"0T00:17:15","Vcc":3.208,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":45,"POWER1":"OFF","Wifi":{"AP":1,"SSId":"KoroFlat","BSSId":"34:CE:00:63:20:41","Channel":6,"RSSI":84}}
14:00:55 RSL: tele/sonoff/SENSOR = {"Time":"2018-12-09T14:00:55","DS18B20":{"Temperature":21.3},"TempUnit":"C"}
14:00:55 RUL: TELE-DS18B20#TEMPERATURE performs "backlog backlog var1 1; ruletimer1 70; event ctrl_ready=1; event temp_demand=21.3;"
14:00:55 RSL: stat/sonoff/RESULT = {"Var1":"1"}
14:00:56 RSL: stat/sonoff/RESULT = {"T1":70,"T2":0,"T3":0,"T4":0,"T5":0,"T6":0,"T7":0,"T8":0}
14:00:56 RSL: stat/sonoff/RESULT = {"Event":"Done"}
14:00:56 RSL: stat/sonoff/RESULT = {"Event":"Done"}
14:00:56 RUL: EVENT#TEMP_DEMAND<%MEM3% performs "power1 1"
14:00:56 RSL: stat/sonoff/RESULT = {"POWER1":"ON"}
14:00:56 RSL: stat/sonoff/POWER1 = ON
14:01:03 MQT: Attempting connection...
14:01:09 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
14:01:20 MQT: Attempting connection...
14:01:27 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
14:01:38 MQT: Attempting connection...
14:01:44 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
14:01:55 MQT: Attempting connection...
14:02:01 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
14:02:01 RSL: tele/sonoff/UPTIME = {"Time":"2018-12-09T14:02:01","Uptime":"0T00:18:21"}
14:02:06 RUL: RULES#TIMER=1 performs "backlog var1 0; ruletimer1 70; power1 0;"
14:02:07 RSL: stat/sonoff/RESULT = {"Var1":"0"}
14:02:07 RSL: stat/sonoff/RESULT = {"T1":70,"T2":0,"T3":0,"T4":0,"T5":0,"T6":0,"T7":0,"T8":0}
14:02:07 RSL: stat/sonoff/RESULT = {"POWER1":"OFF"}
14:02:07 RSL: stat/sonoff/POWER1 = OFF
14:02:12 MQT: Attempting connection...
14:02:19 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
14:02:27 RSL: tele/sonoff/STATE = {"Time":"2018-12-09T14:02:27","Uptime":"0T00:18:47","Vcc":3.208,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"POWER1":"OFF","Wifi":{"AP":1,"SSId":"KoroFlat","BSSId":"34:CE:00:63:20:41","Channel":6,"RSSI":82}}
14:02:27 RSL: tele/sonoff/SENSOR = {"Time":"2018-12-09T14:02:27","DS18B20":{"Temperature":21.3},"TempUnit":"C"}
14:02:27 RUL: TELE-DS18B20#TEMPERATURE performs "backlog backlog var1 1; ruletimer1 70; event ctrl_ready=1; event temp_demand=21.3;"
14:02:27 RSL: stat/sonoff/RESULT = {"Var1":"1"}
14:02:27 RSL: stat/sonoff/RESULT = {"T1":70,"T2":0,"T3":0,"T4":0,"T5":0,"T6":0,"T7":0,"T8":0}
14:02:28 RSL: stat/sonoff/RESULT = {"Event":"Done"}
14:02:28 RSL: stat/sonoff/RESULT = {"Event":"Done"}
14:02:28 RUL: EVENT#TEMP_DEMAND<%MEM3% performs "power1 1"
14:02:28 RSL: stat/sonoff/RESULT = {"POWER1":"ON"}
14:02:28 RSL: stat/sonoff/POWER1 = ON
14:02:30 MQT: Attempting connection...
14:02:36 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
14:02:47 MQT: Attempting connection...
14:02:53 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
14:03:04 MQT: Attempting connection...
14:03:11 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
14:03:21 MQT: Attempting connection...
14:03:28 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
14:03:28 CMD: status 0
14:03:28 RSL: stat/sonoff/STATUS = {"Status":{"Module":1,"FriendlyName":["Sonoff"],"Topic":"sonoff","ButtonTopic":"0","Power":1,"PowerOnState":0,"LedState":1,"SaveData":1,"SaveState":0,"SwitchTopic":"0","SwitchMode":[3,0,0,0,0,0,0,0],"ButtonRetain":0,"SwitchRetain":0,"SensorRetain":0,"PowerRetain":0}}
14:03:28 RSL: stat/sonoff/STATUS1 = {"StatusPRM":{"Baudrate":115200,"GroupTopic":"sonoffs","OtaUrl":"http://thehackbox.org/tasmota/release/sonoff.bin","RestartReason":"Software/System restart","Uptime":"0T00:19:48","StartupUTC":"2018-12-09T12:43:40","Sleep":50,"BootCount":5,"SaveCount":18,"SaveAddress":"FA000"}}
14:03:28 RSL: stat/sonoff/STATUS2 = {"StatusFWR":{"Version":"6.3.0.16(dc63d0f-sonoff)","BuildDateTime":"2018-12-07T19:01:28","Boot":31,"Core":"2_3_0","SDK":"1.5.3(aec24ac9)"}}
14:03:28 RSL: stat/sonoff/STATUS3 = {"StatusLOG":{"SerialLog":2,"WebLog":2,"SysLog":0,"LogHost":"","LogPort":514,"SSId":["KoroFlat",""],"TelePeriod":60,"SetOption":["04008008","558180C0","00000000"]}}
14:03:28 RSL: stat/sonoff/STATUS4 = {"StatusMEM":{"ProgramSize":502,"Free":500,"Heap":14,"ProgramFlashSize":1024,"FlashSize":1024,"FlashChipId":"14405E","FlashMode":3,"Features":["00000809","0FDAE794","000383A0","23B617CE","00003BC0"]}}
14:03:28 RSL: stat/sonoff/STATUS5 = {"StatusNET":{"Hostname":"sonoff_mm","IPAddress":"192.168.22.162","Gateway":"192.168.22.1","Subnetmask":"255.255.255.0","DNSServer":"192.168.22.1","Mac":"84:F3:EB:48:6D:51","Webserver":2,"WifiConfig":4}}
14:03:28 RSL: stat/sonoff/STATUS6 = {"StatusMQT":{"MqttHost":"noserver.local","MqttPort":1883,"MqttClientMask":"DVES_%06X","MqttClient":"DVES_486D51","MqttUser":"DVES_USER","MqttType":1,"MAX_PACKET_SIZE":1000,"KEEPALIVE":15}}
14:03:28 RSL: stat/sonoff/STATUS7 = {"StatusTIM":{"UTC":"Sun Dec 09 13:03:28 2018","Local":"Sun Dec 09 14:03:28 2018","StartDST":"Sun Mar 25 02:00:00 2018","EndDST":"Sun Oct 28 03:00:00 2018","Timezone":"+01:00","Sunrise":"08:31","Sunset":"16:53"}}
14:03:28 RSL: stat/sonoff/STATUS10 = {"StatusSNS":{"Time":"2018-12-09T14:03:28","DS18B20":{"Temperature":21.4},"TempUnit":"C"}}
14:03:28 RSL: stat/sonoff/STATUS11 = {"StatusSTS":{"Time":"2018-12-09T14:03:28","Uptime":"0T00:19:48","Vcc":3.190,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":610,"POWER1":"ON","Wifi":{"AP":1,"SSId":"KoroFlat","BSSId":"34:CE:00:63:20:41","Channel":6,"RSSI":84}}}
14:03:38 RUL: RULES#TIMER=1 performs "backlog var1 0; ruletimer1 70; power1 0;"
14:03:38 RSL: stat/sonoff/RESULT = {"Var1":"0"}
14:03:38 RSL: stat/sonoff/RESULT = {"T1":70,"T2":0,"T3":0,"T4":0,"T5":0,"T6":0,"T7":0,"T8":0}
14:03:39 MQT: Attempting connection...
14:03:45 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
14:03:45 RSL: stat/sonoff/RESULT = {"POWER1":"OFF"}
14:03:45 RSL: stat/sonoff/POWER1 = OFF
14:03:56 MQT: Attempting connection...
14:04:02 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
14:04:04 RSL: tele/sonoff/STATE = {"Time":"2018-12-09T14:04:04","Uptime":"0T00:20:24","Vcc":3.191,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":99,"POWER1":"OFF","Wifi":{"AP":1,"SSId":"KoroFlat","BSSId":"34:CE:00:63:20:41","Channel":6,"RSSI":82}}
14:04:04 RSL: tele/sonoff/SENSOR = {"Time":"2018-12-09T14:04:04","DS18B20":{"Temperature":21.4},"TempUnit":"C"}
14:04:04 RUL: TELE-DS18B20#TEMPERATURE performs "backlog backlog var1 1; ruletimer1 70; event ctrl_ready=1; event temp_demand=21.4;"
14:04:05 RSL: stat/sonoff/RESULT = {"Var1":"1"}
14:04:05 RSL: stat/sonoff/RESULT = {"T1":70,"T2":0,"T3":0,"T4":0,"T5":0,"T6":0,"T7":0,"T8":0}
14:04:05 RSL: stat/sonoff/RESULT = {"Event":"Done"}
14:04:05 RSL: stat/sonoff/RESULT = {"Event":"Done"}
14:04:06 RUL: EVENT#TEMP_DEMAND<%MEM3% performs "power1 1"
14:04:06 RSL: stat/sonoff/RESULT = {"POWER1":"ON"}
14:04:06 RSL: stat/sonoff/POWER1 = ON
14:04:07 CMD: status 0
14:04:07 RSL: stat/sonoff/STATUS = {"Status":{"Module":1,"FriendlyName":["Sonoff"],"Topic":"sonoff","ButtonTopic":"0","Power":1,"PowerOnState":0,"LedState":1,"SaveData":1,"SaveState":0,"SwitchTopic":"0","SwitchMode":[3,0,0,0,0,0,0,0],"ButtonRetain":0,"SwitchRetain":0,"SensorRetain":0,"PowerRetain":0}}
14:04:07 RSL: stat/sonoff/STATUS1 = {"StatusPRM":{"Baudrate":115200,"GroupTopic":"sonoffs","OtaUrl":"http://thehackbox.org/tasmota/release/sonoff.bin","RestartReason":"Software/System restart","Uptime":"0T00:20:27","StartupUTC":"2018-12-09T12:43:40","Sleep":50,"BootCount":5,"SaveCount":18,"SaveAddress":"FA000"}}
14:04:07 RSL: stat/sonoff/STATUS2 = {"StatusFWR":{"Version":"6.3.0.16(dc63d0f-sonoff)","BuildDateTime":"2018-12-07T19:01:28","Boot":31,"Core":"2_3_0","SDK":"1.5.3(aec24ac9)"}}
14:04:07 RSL: stat/sonoff/STATUS3 = {"StatusLOG":{"SerialLog":2,"WebLog":2,"SysLog":0,"LogHost":"","LogPort":514,"SSId":["KoroFlat",""],"TelePeriod":60,"SetOption":["04008008","558180C0","00000000"]}}
14:04:07 RSL: stat/sonoff/STATUS4 = {"StatusMEM":{"ProgramSize":502,"Free":500,"Heap":14,"ProgramFlashSize":1024,"FlashSize":1024,"FlashChipId":"14405E","FlashMode":3,"Features":["00000809","0FDAE794","000383A0","23B617CE","00003BC0"]}}
14:04:07 RSL: stat/sonoff/STATUS5 = {"StatusNET":{"Hostname":"sonoff_mm","IPAddress":"192.168.22.162","Gateway":"192.168.22.1","Subnetmask":"255.255.255.0","DNSServer":"192.168.22.1","Mac":"84:F3:EB:48:6D:51","Webserver":2,"WifiConfig":4}}
14:04:07 RSL: stat/sonoff/STATUS6 = {"StatusMQT":{"MqttHost":"noserver.local","MqttPort":1883,"MqttClientMask":"DVES_%06X","MqttClient":"DVES_486D51","MqttUser":"DVES_USER","MqttType":1,"MAX_PACKET_SIZE":1000,"KEEPALIVE":15}}
14:04:07 RSL: stat/sonoff/STATUS7 = {"StatusTIM":{"UTC":"Sun Dec 09 13:04:07 2018","Local":"Sun Dec 09 14:04:07 2018","StartDST":"Sun Mar 25 02:00:00 2018","EndDST":"Sun Oct 28 03:00:00 2018","Timezone":"+01:00","Sunrise":"08:31","Sunset":"16:53"}}
14:04:07 RSL: stat/sonoff/STATUS10 = {"StatusSNS":{"Time":"2018-12-09T14:04:07","DS18B20":{"Temperature":21.4},"TempUnit":"C"}}
14:04:07 RSL: stat/sonoff/STATUS11 = {"StatusSTS":{"Time":"2018-12-09T14:04:07","Uptime":"0T00:20:27","Vcc":3.191,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":20,"POWER1":"ON","Wifi":{"AP":1,"SSId":"KoroFlat","BSSId":"34:CE:00:63:20:41","Channel":6,"RSSI":82}}}
14:04:13 MQT: Attempting connection...
14:04:20 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
14:04:20 CMD: status 0
14:04:20 RSL: stat/sonoff/STATUS = {"Status":{"Module":1,"FriendlyName":["Sonoff"],"Topic":"sonoff","ButtonTopic":"0","Power":1,"PowerOnState":0,"LedState":1,"SaveData":1,"SaveState":0,"SwitchTopic":"0","SwitchMode":[3,0,0,0,0,0,0,0],"ButtonRetain":0,"SwitchRetain":0,"SensorRetain":0,"PowerRetain":0}}
14:04:20 RSL: stat/sonoff/STATUS1 = {"StatusPRM":{"Baudrate":115200,"GroupTopic":"sonoffs","OtaUrl":"http://thehackbox.org/tasmota/release/sonoff.bin","RestartReason":"Software/System restart","Uptime":"0T00:20:40","StartupUTC":"2018-12-09T12:43:40","Sleep":50,"BootCount":5,"SaveCount":18,"SaveAddress":"FA000"}}
14:04:20 RSL: stat/sonoff/STATUS2 = {"StatusFWR":{"Version":"6.3.0.16(dc63d0f-sonoff)","BuildDateTime":"2018-12-07T19:01:28","Boot":31,"Core":"2_3_0","SDK":"1.5.3(aec24ac9)"}}
14:04:20 RSL: stat/sonoff/STATUS3 = {"StatusLOG":{"SerialLog":2,"WebLog":2,"SysLog":0,"LogHost":"","LogPort":514,"SSId":["KoroFlat",""],"TelePeriod":60,"SetOption":["04008008","558180C0","00000000"]}}
14:04:20 RSL: stat/sonoff/STATUS4 = {"StatusMEM":{"ProgramSize":502,"Free":500,"Heap":14,"ProgramFlashSize":1024,"FlashSize":1024,"FlashChipId":"14405E","FlashMode":3,"Features":["00000809","0FDAE794","000383A0","23B617CE","00003BC0"]}}
14:04:20 RSL: stat/sonoff/STATUS5 = {"StatusNET":{"Hostname":"sonoff_mm","IPAddress":"192.168.22.162","Gateway":"192.168.22.1","Subnetmask":"255.255.255.0","DNSServer":"192.168.22.1","Mac":"84:F3:EB:48:6D:51","Webserver":2,"WifiConfig":4}}
14:04:20 RSL: stat/sonoff/STATUS6 = {"StatusMQT":{"MqttHost":"noserver.local","MqttPort":1883,"MqttClientMask":"DVES_%06X","MqttClient":"DVES_486D51","MqttUser":"DVES_USER","MqttType":1,"MAX_PACKET_SIZE":1000,"KEEPALIVE":15}}
14:04:20 RSL: stat/sonoff/STATUS7 = {"StatusTIM":{"UTC":"Sun Dec 09 13:04:20 2018","Local":"Sun Dec 09 14:04:20 2018","StartDST":"Sun Mar 25 02:00:00 2018","EndDST":"Sun Oct 28 03:00:00 2018","Timezone":"+01:00","Sunrise":"08:31","Sunset":"16:53"}}
14:04:20 RSL: stat/sonoff/STATUS10 = {"StatusSNS":{"Time":"2018-12-09T14:04:20","DS18B20":{"Temperature":21.4},"TempUnit":"C"}}
14:04:20 RSL: stat/sonoff/STATUS11 = {"StatusSTS":{"Time":"2018-12-09T14:04:20","Uptime":"0T00:20:40","Vcc":3.209,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":676,"POWER1":"ON","Wifi":{"AP":1,"SSId":"KoroFlat","BSSId":"34:CE:00:63:20:41","Channel":6,"RSSI":82}}}
14:04:22 CMD: status 0
14:04:22 RSL: stat/sonoff/STATUS = {"Status":{"Module":1,"FriendlyName":["Sonoff"],"Topic":"sonoff","ButtonTopic":"0","Power":1,"PowerOnState":0,"LedState":1,"SaveData":1,"SaveState":0,"SwitchTopic":"0","SwitchMode":[3,0,0,0,0,0,0,0],"ButtonRetain":0,"SwitchRetain":0,"SensorRetain":0,"PowerRetain":0}}
14:04:22 RSL: stat/sonoff/STATUS1 = {"StatusPRM":{"Baudrate":115200,"GroupTopic":"sonoffs","OtaUrl":"http://thehackbox.org/tasmota/release/sonoff.bin","RestartReason":"Software/System restart","Uptime":"0T00:20:42","StartupUTC":"2018-12-09T12:43:40","Sleep":50,"BootCount":5,"SaveCount":18,"SaveAddress":"FA000"}}
14:04:22 RSL: stat/sonoff/STATUS2 = {"StatusFWR":{"Version":"6.3.0.16(dc63d0f-sonoff)","BuildDateTime":"2018-12-07T19:01:28","Boot":31,"Core":"2_3_0","SDK":"1.5.3(aec24ac9)"}}
14:04:22 RSL: stat/sonoff/STATUS3 = {"StatusLOG":{"SerialLog":2,"WebLog":2,"SysLog":0,"LogHost":"","LogPort":514,"SSId":["KoroFlat",""],"TelePeriod":60,"SetOption":["04008008","558180C0","00000000"]}}
14:04:22 RSL: stat/sonoff/STATUS4 = {"StatusMEM":{"ProgramSize":502,"Free":500,"Heap":14,"ProgramFlashSize":1024,"FlashSize":1024,"FlashChipId":"14405E","FlashMode":3,"Features":["00000809","0FDAE794","000383A0","23B617CE","00003BC0"]}}
14:04:22 RSL: stat/sonoff/STATUS5 = {"StatusNET":{"Hostname":"sonoff_mm","IPAddress":"192.168.22.162","Gateway":"192.168.22.1","Subnetmask":"255.255.255.0","DNSServer":"192.168.22.1","Mac":"84:F3:EB:48:6D:51","Webserver":2,"WifiConfig":4}}
14:04:22 RSL: stat/sonoff/STATUS6 = {"StatusMQT":{"MqttHost":"noserver.local","MqttPort":1883,"MqttClientMask":"DVES_%06X","MqttClient":"DVES_486D51","MqttUser":"DVES_USER","MqttType":1,"MAX_PACKET_SIZE":1000,"KEEPALIVE":15}}
14:04:22 RSL: stat/sonoff/STATUS7 = {"StatusTIM":{"UTC":"Sun Dec 09 13:04:22 2018","Local":"Sun Dec 09 14:04:22 2018","StartDST":"Sun Mar 25 02:00:00 2018","EndDST":"Sun Oct 28 03:00:00 2018","Timezone":"+01:00","Sunrise":"08:31","Sunset":"16:53"}}
14:04:22 RSL: stat/sonoff/STATUS10 = {"StatusSNS":{"Time":"2018-12-09T14:04:22","DS18B20":{"Temperature":21.4},"TempUnit":"C"}}
14:04:22 RSL: stat/sonoff/STATUS11 = {"StatusSTS":{"Time":"2018-12-09T14:04:22","Uptime":"0T00:20:42","Vcc":3.192,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":95,"POWER1":"ON","Wifi":{"AP":1,"SSId":"KoroFlat","BSSId":"34:CE:00:63:20:41","Channel":6,"RSSI":86}}}
14:04:28 CMD: status 0
14:04:28 RSL: stat/sonoff/STATUS = {"Status":{"Module":1,"FriendlyName":["Sonoff"],"Topic":"sonoff","ButtonTopic":"0","Power":1,"PowerOnState":0,"LedState":1,"SaveData":1,"SaveState":0,"SwitchTopic":"0","SwitchMode":[3,0,0,0,0,0,0,0],"ButtonRetain":0,"SwitchRetain":0,"SensorRetain":0,"PowerRetain":0}}
14:04:28 RSL: stat/sonoff/STATUS1 = {"StatusPRM":{"Baudrate":115200,"GroupTopic":"sonoffs","OtaUrl":"http://thehackbox.org/tasmota/release/sonoff.bin","RestartReason":"Software/System restart","Uptime":"0T00:20:48","StartupUTC":"2018-12-09T12:43:40","Sleep":50,"BootCount":5,"SaveCount":18,"SaveAddress":"FA000"}}
14:04:28 RSL: stat/sonoff/STATUS2 = {"StatusFWR":{"Version":"6.3.0.16(dc63d0f-sonoff)","BuildDateTime":"2018-12-07T19:01:28","Boot":31,"Core":"2_3_0","SDK":"1.5.3(aec24ac9)"}}
14:04:28 RSL: stat/sonoff/STATUS3 = {"StatusLOG":{"SerialLog":2,"WebLog":2,"SysLog":0,"LogHost":"","LogPort":514,"SSId":["KoroFlat",""],"TelePeriod":60,"SetOption":["04008008","558180C0","00000000"]}}
14:04:28 RSL: stat/sonoff/STATUS4 = {"StatusMEM":{"ProgramSize":502,"Free":500,"Heap":14,"ProgramFlashSize":1024,"FlashSize":1024,"FlashChipId":"14405E","FlashMode":3,"Features":["00000809","0FDAE794","000383A0","23B617CE","00003BC0"]}}
14:04:28 RSL: stat/sonoff/STATUS5 = {"StatusNET":{"Hostname":"sonoff_mm","IPAddress":"192.168.22.162","Gateway":"192.168.22.1","Subnetmask":"255.255.255.0","DNSServer":"192.168.22.1","Mac":"84:F3:EB:48:6D:51","Webserver":2,"WifiConfig":4}}
14:04:28 RSL: stat/sonoff/STATUS6 = {"StatusMQT":{"MqttHost":"noserver.local","MqttPort":1883,"MqttClientMask":"DVES_%06X","MqttClient":"DVES_486D51","MqttUser":"DVES_USER","MqttType":1,"MAX_PACKET_SIZE":1000,"KEEPALIVE":15}}
14:04:28 RSL: stat/sonoff/STATUS7 = {"StatusTIM":{"UTC":"Sun Dec 09 13:04:28 2018","Local":"Sun Dec 09 14:04:28 2018","StartDST":"Sun Mar 25 02:00:00 2018","EndDST":"Sun Oct 28 03:00:00 2018","Timezone":"+01:00","Sunrise":"08:31","Sunset":"16:53"}}
14:04:28 RSL: stat/sonoff/STATUS10 = {"StatusSNS":{"Time":"2018-12-09T14:04:28","DS18B20":{"Temperature":21.4},"TempUnit":"C"}}
14:04:28 RSL: stat/sonoff/STATUS11 = {"StatusSTS":{"Time":"2018-12-09T14:04:28","Uptime":"0T00:20:48","Vcc":3.190,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"POWER1":"ON","Wifi":{"AP":1,"SSId":"KoroFlat","BSSId":"34:CE:00:63:20:41","Channel":6,"RSSI":82}}}
14:04:30 MQT: Attempting connection...
14:04:37 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
14:04:37 CMD: status 0
14:04:37 RSL: stat/sonoff/STATUS = {"Status":{"Module":1,"FriendlyName":["Sonoff"],"Topic":"sonoff","ButtonTopic":"0","Power":1,"PowerOnState":0,"LedState":1,"SaveData":1,"SaveState":0,"SwitchTopic":"0","SwitchMode":[3,0,0,0,0,0,0,0],"ButtonRetain":0,"SwitchRetain":0,"SensorRetain":0,"PowerRetain":0}}
14:04:37 RSL: stat/sonoff/STATUS1 = {"StatusPRM":{"Baudrate":115200,"GroupTopic":"sonoffs","OtaUrl":"http://thehackbox.org/tasmota/release/sonoff.bin","RestartReason":"Software/System restart","Uptime":"0T00:20:57","StartupUTC":"2018-12-09T12:43:40","Sleep":50,"BootCount":5,"SaveCount":18,"SaveAddress":"FA000"}}
14:04:37 RSL: stat/sonoff/STATUS2 = {"StatusFWR":{"Version":"6.3.0.16(dc63d0f-sonoff)","BuildDateTime":"2018-12-07T19:01:28","Boot":31,"Core":"2_3_0","SDK":"1.5.3(aec24ac9)"}}
14:04:37 RSL: stat/sonoff/STATUS3 = {"StatusLOG":{"SerialLog":2,"WebLog":2,"SysLog":0,"LogHost":"","LogPort":514,"SSId":["KoroFlat",""],"TelePeriod":60,"SetOption":["04008008","558180C0","00000000"]}}
14:04:37 RSL: stat/sonoff/STATUS4 = {"StatusMEM":{"ProgramSize":502,"Free":500,"Heap":14,"ProgramFlashSize":1024,"FlashSize":1024,"FlashChipId":"14405E","FlashMode":3,"Features":["00000809","0FDAE794","000383A0","23B617CE","00003BC0"]}}
14:04:37 RSL: stat/sonoff/STATUS5 = {"StatusNET":{"Hostname":"sonoff_mm","IPAddress":"192.168.22.162","Gateway":"192.168.22.1","Subnetmask":"255.255.255.0","DNSServer":"192.168.22.1","Mac":"84:F3:EB:48:6D:51","Webserver":2,"WifiConfig":4}}
14:04:37 RSL: stat/sonoff/STATUS6 = {"StatusMQT":{"MqttHost":"noserver.local","MqttPort":1883,"MqttClientMask":"DVES_%06X","MqttClient":"DVES_486D51","MqttUser":"DVES_USER","MqttType":1,"MAX_PACKET_SIZE":1000,"KEEPALIVE":15}}
14:04:37 RSL: stat/sonoff/STATUS7 = {"StatusTIM":{"UTC":"Sun Dec 09 13:04:37 2018","Local":"Sun Dec 09 14:04:37 2018","StartDST":"Sun Mar 25 02:00:00 2018","EndDST":"Sun Oct 28 03:00:00 2018","Timezone":"+01:00","Sunrise":"08:31","Sunset":"16:53"}}
14:04:37 RSL: stat/sonoff/STATUS10 = {"StatusSNS":{"Time":"2018-12-09T14:04:37","DS18B20":{"Temperature":21.4},"TempUnit":"C"}}
14:04:37 RSL: stat/sonoff/STATUS11 = {"StatusSTS":{"Time":"2018-12-09T14:04:37","Uptime":"0T00:20:57","Vcc":3.190,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":683,"POWER1":"ON","Wifi":{"AP":1,"SSId":"KoroFlat","BSSId":"34:CE:00:63:20:41","Channel":6,"RSSI":80}}}
14:04:48 MQT: Attempting connection...
14:04:54 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
14:05:08 MQT: Attempting connection...
14:05:15 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
14:05:16 RUL: RULES#TIMER=1 performs "backlog var1 0; ruletimer1 70; power1 0;"
14:05:16 RSL: stat/sonoff/RESULT = {"Var1":"0"}
14:05:16 RSL: stat/sonoff/RESULT = {"T1":70,"T2":0,"T3":0,"T4":0,"T5":0,"T6":0,"T7":0,"T8":0}
14:05:16 RSL: stat/sonoff/RESULT = {"POWER1":"OFF"}
14:05:16 RSL: stat/sonoff/POWER1 = OFF
14:05:25 MQT: Attempting connection...
14:05:32 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
14:05:39 RSL: tele/sonoff/STATE = {"Time":"2018-12-09T14:05:39","Uptime":"0T00:21:59","Vcc":3.208,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":20,"POWER1":"OFF","Wifi":{"AP":1,"SSId":"KoroFlat","BSSId":"34:CE:00:63:20:41","Channel":6,"RSSI":78}}
14:05:39 RSL: tele/sonoff/SENSOR = {"Time":"2018-12-09T14:05:39","DS18B20":{"Temperature":21.4},"TempUnit":"C"}
14:05:39 RUL: TELE-DS18B20#TEMPERATURE performs "backlog backlog var1 1; ruletimer1 70; event ctrl_ready=1; event temp_demand=21.4;"
14:05:39 RSL: stat/sonoff/RESULT = {"Var1":"1"}
14:05:40 RSL: stat/sonoff/RESULT = {"T1":70,"T2":0,"T3":0,"T4":0,"T5":0,"T6":0,"T7":0,"T8":0}
14:05:40 RSL: stat/sonoff/RESULT = {"Event":"Done"}
14:05:40 RSL: stat/sonoff/RESULT = {"Event":"Done"}
14:05:40 RUL: EVENT#TEMP_DEMAND<%MEM3% performs "power1 1"
14:05:40 RSL: stat/sonoff/RESULT = {"POWER1":"ON"}
14:05:40 RSL: stat/sonoff/POWER1 = ON
14:05:43 MQT: Attempting connection...
14:05:49 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
14:06:00 MQT: Attempting connection...
14:06:06 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
14:06:17 MQT: Attempting connection...
14:06:23 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
14:06:34 MQT: Attempting connection...
14:06:41 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
14:06:50 RUL: RULES#TIMER=1 performs "backlog var1 0; ruletimer1 70; power1 0;"
14:06:50 RSL: stat/sonoff/RESULT = {"Var1":"0"}
14:06:50 RSL: stat/sonoff/RESULT = {"T1":70,"T2":0,"T3":0,"T4":0,"T5":0,"T6":0,"T7":0,"T8":0}
14:06:51 RSL: stat/sonoff/RESULT = {"POWER1":"OFF"}
14:06:51 RSL: stat/sonoff/POWER1 = OFF
14:06:52 MQT: Attempting connection...
14:06:58 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
14:07:09 MQT: Attempting connection...
14:07:15 MQT: Connect failed to noserver.local:1883, rc -2. Retry in 10 sec
14:07:16 RSL: tele/sonoff/STATE = {"Time":"2018-12-09T14:07:16","Uptime":"0T00:23:36","Vcc":3.208,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":250,"POWER1":"OFF","Wifi":{"AP":1,"SSId":"KoroFlat","BSSId":"34:CE:00:63:20:41","Channel":6,"RSSI":78}}
14:07:16 RSL: tele/sonoff/SENSOR = {"Time":"2018-12-09T14:07:16","DS18B20":{"Temperature":21.4},"TempUnit":"C"}
14:07:16 RUL: TELE-DS18B20#TEMPERATURE performs "backlog backlog var1 1; ruletimer1 70; event ctrl_ready=1; event temp_demand=21.4;"
14:07:17 RSL: stat/sonoff/RESULT = {"Var1":"1"}
14:07:17 RSL: stat/sonoff/RESULT = {"T1":70,"T2":0,"T3":0,"T4":0,"T5":0,"T6":0,"T7":0,"T8":0}
14:07:17 RSL: stat/sonoff/RESULT = {"Event":"Done"}
14:07:17 RSL: stat/sonoff/RESULT = {"Event":"Done"}
14:07:17 RUL: EVENT#TEMP_DEMAND<%MEM3% performs "power1 1"
14:07:17 RSL: stat/sonoff/RESULT = {"POWER1":"ON"}
14:07:17 RSL: stat/sonoff/POWER1 = ON

So in my humble opinion after those tests, I can say that the problem is in MQTT reconnect function.

Best regards, MvincM

arendst commented 5 years ago

So in the end timers work as expected but teleperiod does not?

If that's the case it is as expected; every mqtt retry seems to hold up the system for about 5 to 6 seconds. In that time TCP/IP handler is looking for a mqtt server. No time is made available for any resource so all internal timers will stall too. After 6 seconds they are services again and as most timers calculate the time spend since last time activated they will act correctly.

Except for the TelePeriod timer as that is just a counter being incremented every time the second timer is triggered. As said before this triggering is stalled by the core TCP/IP handler it is delayed by up to 6 seconds and will therefor skew by this amount of seconds. That's exactly what you experience. With mqtt retry set to 10 seconds you will see an increment of teleperiod time of 6 x 6 seconds is 36 seconds and that's why it triggers Teleperiod at 96 seconds.

Workarounds:

I'll reconsider Teleperiod routine to also use a separate timer which will still be delayed by max 6 seconds as explained before where ALL timers are stalled during mqtt reconnection time.

ascillato2 commented 5 years ago

Closing this issue as it has been answered.

Support Information

See Wiki for more information. See Chat for more user experience.

mvincm commented 5 years ago

So in the end timers work as expected but teleperiod does not?

Teleperiod was not as expected so then "ruletimer1" goes to 0 and flop "power".

But the true question is why LoadAvg reach so high level to unresponsible level (even after reboot)...

BTW... Thanks for your attention!

Best regards, MvincM

andrethomas commented 5 years ago

LoadAvg reach so high level

It is directly dependent on the sleep value configured. It's purely an academic value calculated based on the number of milliseconds it takes for the main loop to complete measured against the sleep setting.

With sleep set at 50 and the main loop duration of 9 milliseconds, it would translate to 9/50*100.

So the reason you get a load average of higher than 100, for example, just means your main loop is taking more than the sleep milliseconds to complete.

Given this, it means the main loop is also giving minimal time to the SDK (in the background handling the wifi functions etc which we have no direct control over from Tasmota's perspective) resulting in a lack of responsive web ui or command console interface or anything that would require wifi background time.

So the high level of LoadAvg is an artefact of the way ruletimer is working in conjunction when mqtt is down (which Theo is indicating he will rethink over some time)

It is by no means a direct indication of CPU load but does lend to the fact that a high CPU load cycle is probable.

It also means that the main loop is not looping as fast as it should.

In your case it was useful to determine where the "bottleneck" is, which Theo has indicated he will try and find another way to do it.

mvincm commented 5 years ago

Thank you all for support and interaction!

Best regards, MvincM