Tasmota icon indicating copy to clipboard operation
Tasmota copied to clipboard

Published 20 hours ago • verified publisher icon arendst

Missing counter increment triggers in rules.

Open sebw7561 opened this issue 1 year ago • 0 comments

PROBLEM DESCRIPTION

I am using 'rule1 on counter#c1>%var1% do var1 %value% endon' to trigger on counter increments. I have more than 10s between pulses coming in and the counter is keeping up, with the number of pulses updating on the sonoff home page for each pulse. However, the trigger does not happen on each pulse. What I see is a counter increment sequence like 1,2,5,6,9,10,13 ..... It triggers 2 pulses in a row, as expected, but then skips 2 pulses before the next trigger.

REQUESTED INFORMATION

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

  • [x] Read the Contributing Guide and Policy and the Code of Conduct
  • [x] Searched the problem in issues
  • [x] Searched the problem in discussions
  • [x] Searched the problem in the docs
  • [x] Searched the problem in the chat
  • [x] Device used (e.g., Sonoff Basic): Sonioff Basic
  • [x] Tasmota binary firmware version number used: V12.0.2
    • [x] Pre-compiled
    • [ ] Self-compiled
  • [x] Flashing tools used: Tazmotizer.exe V1.2
  • [x] Provide the output of command: Backlog Template; Module; GPIO 255:
  Configuration output here:
09:50:47.412 CMD: Backlog Template; Module; GPIO 255
09:50:47.473 MQT: stat/solar/RESULT = {"NAME":"Generic","GPIO":[1,1,1,1,1,1,1,1,1,1,1,1,1,4704],"FLAG":0,"BASE":18}
09:50:47.821 MQT: stat/solar/RESULT = {"Module":{"1":"Sonoff Basic"}}
09:50:48.026 MQT: stat/solar/RESULT = {"GPIO0":{"32":"Button1"},"GPIO1":{"385":"Counter_n2"},"GPIO2":{"0":"None"},"GPIO3":{"384":"Counter_n1"},"GPIO4":{"0":"None"},"GPIO5":{"0":"None"},"GPIO9":{"0":"None"},"GPIO10":{"0":"None"},"GPIO12":{"224":"Relay1"},"GPIO13":{"320":"Led_i1"},"GPIO14":{"0":"None"},"GPIO15":{"0":"None"},"GPIO16":{"0":"None"},"GPIO17":{"0":"None"}}
  • [x] If using rules, provide the output of this command: Backlog Rule1; Rule2; Rule3:
  Rules output here:
09:52:17.365 CMD: Backlog Rule1; Rule2; Rule3
09:52:17.463 MQT: stat/solar/RESULT = {"Rule1":{"State":"ON","Once":"OFF","StopOnError":"OFF","Length":251,"Free":260,"Rules":"on counter#c1>%var1% do var1 %value% endon on counter#c2>%var2% do var2 %value% endon on time#minute|5 do backlog teleperiod; var3 %var1%; sub3 %mem1%; mult3 0.001; publish2 tele/solar/TODAY {\"DAILY\":%var3%} endon on time#minute=0 do mem1 %var1% endon"}}
09:52:17.664 MQT: stat/solar/RESULT = {"Rule2":{"State":"OFF","Once":"OFF","StopOnError":"OFF","Length":35,"Free":476,"Rules":"ON COUNTER#C2 DO Var1 %Value% ENDON"}}
09:52:17.864 MQT: stat/solar/RESULT = {"Rule3":{"State":"OFF","Once":"OFF","StopOnError":"OFF","Length":0,"Free":511,"Rules":""}}
  • [x] Provide the output of this command: Status 0:
  STATUS 0 output here:
09:52:59.522 CMD: Status 0
09:52:59.530 MQT: stat/solar/STATUS = {"Status":{"Module":1,"DeviceName":"Sonoff4 - Solar Power","FriendlyName":["Sonoff4 - Solar Power"],"Topic":"solar","ButtonTopic":"0","Power":0,"PowerOnState":3,"LedState":1,"LedMask":"FFFF","SaveData":1,"SaveState":1,"SwitchTopic":"0","SwitchMode":[0,0,0,0,0,0,0,0],"ButtonRetain":0,"SwitchRetain":0,"SensorRetain":1,"PowerRetain":0,"InfoRetain":0,"StateRetain":0}}
09:52:59.553 MQT: stat/solar/STATUS1 = {"StatusPRM":{"Baudrate":115200,"SerialConfig":"8N1","GroupTopic":"sonoffs","OtaUrl":"http://ota.tasmota.com/tasmota/release/tasmota.bin.gz","RestartReason":"Software/System restart","Uptime":"0T10:42:17","StartupUTC":"2022-07-17T22:10:42","Sleep":0,"CfgHolder":4617,"BootCount":56,"BCResetTime":"2020-09-20T11:20:04","SaveCount":2906,"SaveAddress":"F5000"}}
09:52:59.574 MQT: stat/solar/STATUS2 = {"StatusFWR":{"Version":"12.0.2(tasmota)","BuildDateTime":"2022-06-20T12:41:03","Boot":31,"Core":"2_7_4_9","SDK":"2.2.2-dev(38a443e)","CpuFrequency":80,"Hardware":"ESP8285","CR":"443/699"}}
09:52:59.593 MQT: stat/solar/STATUS3 = {"StatusLOG":{"SerialLog":0,"WebLog":2,"MqttLog":0,"SysLog":0,"LogHost":"","LogPort":514,"SSId":["WoodcockNest","Lofty"],"TelePeriod":0,"Resolution":"558180F0","SetOption":["00008209","2805C80001000600003C5AFF000000000000","00000080","00006000","00004000","00000000"]}}
09:52:59.616 MQT: stat/solar/STATUS4 = {"StatusMEM":{"ProgramSize":619,"Free":384,"Heap":26,"ProgramFlashSize":1024,"FlashSize":1024,"FlashChipId":"144051","FlashFrequency":40,"FlashMode":3,"Features":["00000809","8F9AC787","04368001","000000CF","010013C0","C000F981","00004004","00001000","14000020","00000000"],"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,45,62","Sensors":"1,2,3,4,5,6"}}
09:52:59.639 MQT: stat/solar/STATUS5 = {"StatusNET":{"Hostname":"Sonoff4","IPAddress":"192.168.0.104","Gateway":"192.168.0.1","Subnetmask":"255.255.255.0","DNSServer1":"192.168.0.91","DNSServer2":"0.0.0.0","Mac":"84:0D:8E:50:B4:38","Webserver":2,"HTTP_API":1,"WifiConfig":4,"WifiPower":17.0}}
09:52:59.657 MQT: stat/solar/STATUS6 = {"StatusMQT":{"MqttHost":"PiStudy.home","MqttPort":1883,"MqttClientMask":"DVES_%06X","MqttClient":"DVES_50B438","MqttUser":"DVES_USER","MqttCount":2,"MAX_PACKET_SIZE":1200,"KEEPALIVE":30,"SOCKET_TIMEOUT":4}}
09:52:59.679 MQT: stat/solar/STATUS7 = {"StatusTIM":{"UTC":"2022-07-18T08:52:59","Local":"2022-07-18T09:52:59","StartDST":"2022-03-27T01:00:00","EndDST":"2022-10-30T01:00:00","Timezone":99,"Sunrise":"05:12","Sunset":"21:10"}}
09:52:59.699 MQT: stat/solar/STATUS10 = {"StatusSNS":{"Time":"2022-07-18T09:52:59.693","COUNTER":{"C1":17265247,"C2":17032710}}}
09:52:59.719 MQT: stat/solar/STATUS11 = {"StatusSTS":{"Time":"2022-07-18T09:52:59.713","Uptime":"0T10:42:17","UptimeSec":38537,"Heap":24,"SleepMode":"Dynamic","Sleep":0,"LoadAvg":999,"MqttCount":2,"POWER":"OFF","Wifi":{"AP":1,"SSId":"WoodcockNest","BSSId":"18:0F:76:08:B2:FF","Channel":6,"Mode":"11n","RSSI":100,"Signal":-49,"LinkCount":2,"Downtime":"0T00:00:16"}}}
  • [x] Set weblog to 4 and then, when you experience your issue, provide the output of the Console log:
  Console output here:
09:53:34.484 MQT: stat/solar/RESULT = {"WebLog":4}
09:53:34.565 RUL: COUNTER#C1>%VAR1% performs "var1 17265259"
09:53:34.566 SRC: Rule
09:53:34.569 CMD: Grp 0, Cmd 'VAR', Idx 1, Len 8, Pld 17265259, Data '17265259'
09:53:34.576 MQT: stat/solar/RESULT = {"Var1":"17265259"}
09:53:34.701 CFG: Saved to flash at F4, Count 2907, Bytes 4096
09:53:38.768 WIF: Checking connection...
09:53:42.840 WIF: Sending Gratuitous ARP
09:53:43.613 RUL: COUNTER#C1>%VAR1% performs "var1 17265262"
09:53:43.614 SRC: Rule
09:53:43.617 CMD: Grp 0, Cmd 'VAR', Idx 1, Len 8, Pld 17265262, Data '17265262'
09:53:43.623 MQT: stat/solar/RESULT = {"Var1":"17265262"}
09:53:46.614 RUL: COUNTER#C1>%VAR1% performs "var1 17265263"
09:53:46.615 SRC: Rule
09:53:46.618 CMD: Grp 0, Cmd 'VAR', Idx 1, Len 8, Pld 17265263, Data '17265263'
09:53:46.624 MQT: stat/solar/RESULT = {"Var1":"17265263"}
09:53:50.816 RUL: COUNTER#C2>%VAR2% performs "var2 17032714"
09:53:50.817 SRC: Rule
09:53:50.820 CMD: Grp 0, Cmd 'VAR', Idx 2, Len 8, Pld 17032714, Data '17032714'
09:53:50.826 MQT: stat/solar/RESULT = {"Var2":"17032714"}
09:53:55.014 RUL: COUNTER#C1>%VAR1% performs "var1 17265266"
09:53:55.016 SRC: Rule
09:53:55.018 CMD: Grp 0, Cmd 'VAR', Idx 1, Len 8, Pld 17265266, Data '17265266'
09:53:55.024 MQT: stat/solar/RESULT = {"Var1":"17265266"}
09:53:58.014 RUL: COUNTER#C1>%VAR1% performs "var1 17265267"
09:53:58.015 SRC: Rule
09:53:58.018 CMD: Grp 0, Cmd 'VAR', Idx 1, Len 8, Pld 17265267, Data '17265267'
09:53:58.024 MQT: stat/solar/RESULT = {"Var1":"17265267"}
09:53:58.768 WIF: Checking connection...
09:54:04.016 RUL: COUNTER#C2>%VAR2% performs "var2 17032715"
09:54:04.018 SRC: Rule
09:54:04.020 CMD: Grp 0, Cmd 'VAR', Idx 2, Len 8, Pld 17032715, Data '17032715'
09:54:04.026 MQT: stat/solar/RESULT = {"Var2":"17032715"}
09:54:07.014 RUL: COUNTER#C1>%VAR1% performs "var1 17265270"
09:54:07.016 SRC: Rule
09:54:07.018 CMD: Grp 0, Cmd 'VAR', Idx 1, Len 8, Pld 17265270, Data '17265270'
09:54:07.025 MQT: stat/solar/RESULT = {"Var1":"17265270"}
09:54:09.414 RUL: COUNTER#C1>%VAR1% performs "var1 17265271"
09:54:09.415 SRC: Rule
09:54:09.418 CMD: Grp 0, Cmd 'VAR', Idx 1, Len 8, Pld 17265271, Data '17265271'
09:54:09.424 MQT: stat/solar/RESULT = {"Var1":"17265271"}
09:54:17.814 RUL: COUNTER#C1>%VAR1% performs "var1 17265274"
09:54:17.816 SRC: Rule
09:54:17.818 CMD: Grp 0, Cmd 'VAR', Idx 1, Len 8, Pld 17265274, Data '17265274'
09:54:17.824 MQT: stat/solar/RESULT = {"Var1":"17265274"}
09:54:18.768 WIF: Checking connection...
09:54:20.814 RUL: COUNTER#C1>%VAR1% performs "var1 17265275"
09:54:20.816 SRC: Rule
09:54:20.818 CMD: Grp 0, Cmd 'VAR', Idx 1, Len 8, Pld 17265275, Data '17265275'
09:54:20.824 MQT: stat/solar/RESULT = {"Var1":"17265275"}
09:54:29.814 RUL: COUNTER#C1>%VAR1% performs "var1 17265278"
09:54:29.816 SRC: Rule
09:54:29.818 CMD: Grp 0, Cmd 'VAR', Idx 1, Len 8, Pld 17265278, Data '17265278'
09:54:29.824 MQT: stat/solar/RESULT = {"Var1":"17265278"}
09:54:32.214 RUL: COUNTER#C1>%VAR1% performs "var1 17265279"
09:54:32.216 SRC: Rule
09:54:32.218 CMD: Grp 0, Cmd 'VAR', Idx 1, Len 8, Pld 17265279, Data '17265279'
09:54:32.224 MQT: stat/solar/RESULT = {"Var1":"17265279"}
09:54:38.768 WIF: Checking connection...
09:54:41.214 RUL: COUNTER#C1>%VAR1% performs "var1 17265282"
09:54:41.216 SRC: Rule
09:54:41.219 CMD: Grp 0, Cmd 'VAR', Idx 1, Len 8, Pld 17265282, Data '17265282'
09:54:41.225 MQT: stat/solar/RESULT = {"Var1":"17265282"}
09:54:42.841 WIF: Sending Gratuitous ARP
09:54:44.214 RUL: COUNTER#C1>%VAR1% performs "var1 17265283"
09:54:44.216 SRC: Rule
09:54:44.218 CMD: Grp 0, Cmd 'VAR', Idx 1, Len 8, Pld 17265283, Data '17265283'
09:54:44.225 MQT: stat/solar/RESULT = {"Var1":"17265283"}
09:54:45.416 RUL: COUNTER#C2>%VAR2% performs "var2 17032718"
09:54:45.418 SRC: Rule
09:54:45.420 CMD: Grp 0, Cmd 'VAR', Idx 2, Len 8, Pld 17032718, Data '17032718'
09:54:45.427 MQT: stat/solar/RESULT = {"Var2":"17032718"}

TO REPRODUCE

Create the rule: rule1 on counter#c1>%var1% do var1 %value% endon rule1 1

EXPECTED BEHAVIOUR

I expect the rule to be triggered on each counter increment, unless the pulses stream is fast. In my case, the problem occurs even when there is more than 20s btween the pulses.

SCREENSHOTS

If applicable, add screenshots to help explain your problem.

ADDITIONAL CONTEXT

Add any other context about the problem here. I have tried the following rule and I see the pulse increments as expected: rule1 on counter#c1 do var1 %value% endon rule1 1 ... and I see each of the incrementing values as epected: 09:37:16.320 MQT: stat/solar/RESULT = {"Var1":"17264476"} 09:37:16.912 RUL: COUNTER#C1 performs "var1 17264477" 09:37:16.920 MQT: stat/solar/RESULT = {"Var1":"17264477"} 09:37:17.513 RUL: COUNTER#C1 performs "var1 17264477" 09:37:17.520 MQT: stat/solar/RESULT = {"Var1":"17264477"} 09:37:18.113 RUL: COUNTER#C1 performs "var1 17264478" 09:37:18.120 MQT: stat/solar/RESULT = {"Var1":"17264478"} 09:37:18.712 RUL: COUNTER#C1 performs "var1 17264478" 09:37:18.720 MQT: stat/solar/RESULT = {"Var1":"17264478"} 09:37:19.313 RUL: COUNTER#C1 performs "var1 17264479" 09:37:19.320 MQT: stat/solar/RESULT = {"Var1":"17264479"} 09:37:19.913 RUL: COUNTER#C1 performs "var1 17264479" 09:37:19.920 MQT: stat/solar/RESULT = {"Var1":"17264479"} 09:37:20.512 RUL: COUNTER#C1 performs "var1 17264480" 09:37:20.520 MQT: stat/solar/RESULT = {"Var1":"17264480"} 09:37:21.112 RUL: COUNTER#C1 performs "var1 17264480" 09:37:21.119 MQT: stat/solar/RESULT = {"Var1":"17264480"}

(Please, remember to close the issue when the problem has been addressed)

sebw7561 avatar Jul 18 '22 09:07 sebw7561

This issue has been automatically marked as stale because it hasn't any activity in last few weeks. It will be closed if no further activity occurs. Thank you for your contributions.

github-actions[bot] avatar Aug 13 '22 02:08 github-actions[bot]

Has no one else witnessed this behaviour?

sebw7561 avatar Aug 13 '22 20:08 sebw7561

I have done a 'Reset Configuration' and updated to 12.1.0 Patricia, and I am still seeing this behaviour:

11:25:01.563 RUL: COUNTER#C2!=%VAR2% performs "var2 18444658" 11:25:01.571 MQT: stat/solar/RESULT = {"Var2":"18444658"} 11:25:12.958 RUL: COUNTER#C2!=%VAR2% performs "var2 18444659" 11:25:12.965 MQT: stat/solar/RESULT = {"Var2":"18444659"} 11:25:24.971 RUL: COUNTER#C1!=%VAR1% performs "var1 18010786" 11:25:24.982 MQT: stat/solar/RESULT = {"Var1":"18010786"} 11:25:35.182 RUL: COUNTER#C1!=%VAR1% performs "var1 18010787" 11:25:35.190 MQT: stat/solar/RESULT = {"Var1":"18010787"} 11:25:40.596 RUL: COUNTER#C2!=%VAR2% performs "var2 18444662" 11:25:40.603 MQT: stat/solar/RESULT = {"Var2":"18444662"} 11:25:46.585 RUL: COUNTER#C2!=%VAR2% performs "var2 18444663" 11:25:46.595 MQT: stat/solar/RESULT = {"Var2":"18444663"} 11:26:05.174 RUL: COUNTER#C1!=%VAR1% performs "var1 18010790" 11:26:05.183 MQT: stat/solar/RESULT = {"Var1":"18010790"} 11:26:15.364 RUL: COUNTER#C1!=%VAR1% performs "var1 18010791" 11:26:15.375 MQT: stat/solar/RESULT = {"Var1":"18010791"} 11:26:18.384 RUL: COUNTER#C2!=%VAR2% performs "var2 18444666" 11:26:18.392 MQT: stat/solar/RESULT = {"Var2":"18444666"} 11:26:19.937 RUL: COUNTER#C2!=%VAR2% performs "var2 18444667" 11:26:19.944 MQT: stat/solar/RESULT = {"Var2":"18444667"}

sebw7561 avatar Aug 25 '22 10:08 sebw7561

I have discovered that the increment triggers only start to be missed when the counter value exceeds 0xFFFFFF (decimal 16777215). Is some comparison of an unsigned long being done as a float?

sebw7561 avatar Aug 25 '22 17:08 sebw7561

The numeric processing done in Tasmota rules is never "unsigned long", but always single precision floating point, indeed leading to loss of precision with 7 decimal digits.

sfromis avatar Aug 25 '22 18:08 sfromis

Yep, that appears to be my problem. I have switched to using the string compare:

on counter#c1$!%var1% do var1 %value% endon

... and I am now getting the trigger on each counter increment.

sebw7561 avatar Aug 25 '22 18:08 sebw7561

It would be good to make it a little clearer in the documentation that:

  1. The 'Var' variables are stored as 32 character strings.
  2. The numerical 'Rule Trigger Comparison Operators' cause conversion of the string 'Var' to floats before comparison.
  3. The above can lead to a loss of precision which can effect the outcome of the comparison.

Many thanks to everyone involved with this wonderful firmware.

sebw7561 avatar Aug 26 '22 10:08 sebw7561