time#initialized>10 flag not triggered under heavy load (also not accurate)

pkkrusty commented 2 years ago

PROBLEM DESCRIPTION

A clear and concise description of what the problem is. When DS3231 is attached and functioning, the 8266 gets its time from the DS3231 before hitting the NTP server, and my rule trigger (time#initialized>10) never fires. Rule doesn't fire whether I have a valid NTP server or not, since DS3231 driver pre-empts the time#initialized flag in rtc_support.ino from firing by causing rtc.local_time to get filled in before the first rtcsecond() function call. Maybe because the rule is triggered before rtc.utc_time is distributed to all the system components, and thus the 10 second delay has a math error when it comes time to publish it?

When DS3231 is disconnected, and I have a valid NTP server, the time#initialized>10 trigger fires (albeit at the incorrect time).

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): Wemos Mini D1 knockoff
[ x] Tasmota binary firmware version number used: 10-0-0-3
- [ ] Pre-compiled
- [ x] Self-compiled
[ x] Flashing tools used: esptool.py then OTA

[ ] Provide the output of command: Backlog Template; Module; GPIO 255:


Configuration output here:
08:43:20.974 CMD: Backlog Template; Module; GPIO 255
08:43:20.976 SRC: WebConsole from 192.168.1.100
08:43:20.979 CMD: Grp 0, Cmnd 'BACKLOG', Idx 1, Len 26, Data 'Template; Module; GPIO 255'
08:43:20.994 SRC: Backlog
08:43:20.997 CMD: Grp 0, Cmnd 'TEMPLATE', Idx 1, Len 0, Data ''
08:43:21.002 MQT: freezer-energy-monitor/stat/RESULT = {"NAME":"HW-655 PZEM","GPIO":[0,1536,0,1472,0,0,0,0,0,0,0,0,0,0],"FLAG":0,"BASE":18}
08:43:21.195 SRC: Backlog
08:43:21.198 CMD: Grp 0, Cmnd 'MODULE', Idx 1, Len 0, Data ''
08:43:21.206 MQT: freezer-energy-monitor/stat/RESULT = {"Module":{"18":"Generic"}}
08:43:21.400 SRC: Backlog
08:43:21.403 CMD: Grp 0, Cmnd 'GPIO', Idx 1, Len 3, Data '255'
08:43:21.413 MQT: freezer-energy-monitor/stat/RESULT = {"GPIO0":{"258":"Relay_i3"},"GPIO1":{"1472":"PZEM0XX Tx"},"GPIO2":{"259":"Relay_i4"},"GPIO3":{"1536":"PZEM016 Rx"},"GPIO4":{"640":"I2C SDA"},"GPIO5":{"608":"I2C SCL"},"GPIO9":{"0":"None"},"GPIO10":{"0":"None"},"GPIO12":{"162":"Switch3"},"GPIO13":{"257":"Relay_i2"},"GPIO14":{"163":"Switch4"},"GPIO15":{"256":"Relay_i1"},"GPIO16":{"0":"None"},"GPIO17":{"0":"None"}}

- [ ] If using rules, provide the output of this command: `Backlog Rule1; Rule2; Rule3`:
```lua
  Rules output here:
08:43:59.580 CMD: Backlog Rule1; Rule2; Rule3
08:43:59.582 SRC: WebConsole from 192.168.1.100
08:43:59.585 CMD: Grp 0, Cmnd 'BACKLOG', Idx 1, Len 19, Data 'Rule1; Rule2; Rule3'
08:43:59.599 SRC: Backlog
08:43:59.601 CMD: Grp 0, Cmnd 'RULE', Idx 1, Len 0, Data ''
08:43:59.605 RUL: Rule1 On system#init do backlog power1 1;power2 1;var1 1;var2 1 endon On time#initialized>10 do backlog status 10 endon On statussns#switch3=1 do backlog var1 2;event Hr1=%time% endon On statussns#switch4=1 do backlog var2 2;event Hr2=%time% endon On switch3#state=1 do backlog var1 2;event Hr1=%time% endon On switch3#state=0 do backlog var1 1;power1 1 endon On switch4#state=1 do backlog var2 2;event Hr2=%time% endon On switch4#state=0 do backlog var2 1;power2 1 endon On event#Hr1<1140 do backlog var1 1;var2 1
08:43:59.607 RUL: Rule1 +endon On event#Hr2<1140 do backlog var1 1;var2 1 endon On event#Hr1<480 do backlog delay 100;var1 2 endon On event#Hr2<480 do backlog delay 100;var2 2 endon On time#minute=479 do backlog power1 1;power2 1;var1 1;var2 1 endon On time#minute=1200 do backlog status 10 endon On time#minute|60 do backlog power1 %var1%;ruletimer1 3595 endon On rules#timer=1 do power2 %var2% endon
08:43:59.616 MQT: freezer-energy-monitor/stat/RESULT = {"Rule1":{"State":"ON","Once":"OFF","StopOnError":"OFF","Length":885,"Free":206,"Rules":"On system#init do backlog power1 1;power2 1;var1 1;var2 1 endon On time#initialized>10 do backlog status 10 endon On statussns#switch3=1 do backlog var1 2;event Hr1=%time% endon On statussns#switch4=1 do backlog var2 2;event Hr2=%time% endon On switch3#state=1 do backlog var1 2;event Hr1=%time% endon On switch3#state=0 do backlog var1 1;power1 1 endon On switch4#state=1 do backlog var2 2;event Hr2=%time% endon On switch4#state=0 do backlog var2 1;power2 1 endon On event#Hr1<1140 do backlog var1 1;var2 1 endon On event#Hr2<1140 do backlog var1 1;var2 1 endon On event#Hr1<480 do backlog delay 100;var1 2 endon On event#Hr2<480 do backlog delay 100;var2 2 endon On time#minute=479 do backlog power1 1;power2 1;var1 1;var2 1 endon On time#minute=1200 do backlog status 10 endon On time#minute|60 do backlog power1 %var1%;ruletimer1 3595 endon On rules#timer=1 do power2 %var2% endon"}}
08:43:59.803 SRC: Backlog
08:43:59.806 CMD: Grp 0, Cmnd 'RULE', Idx 2, Len 0, Data ''
08:43:59.813 MQT: freezer-energy-monitor/stat/RESULT = {"Rule2":{"State":"ON","Once":"OFF","StopOnError":"OFF","Length":123,"Free":388,"Rules":"on time#minute|5 do ruletimer2 10 endon on rules#timer=2 do publish topic/stat/test {\"Var1\":\"%var1%\",\"Var2\":\"%var2%\"} endon"}}
08:44:00.007 SRC: Backlog
08:44:00.010 CMD: Grp 0, Cmnd 'RULE', Idx 3, Len 0, Data ''
08:44:00.017 MQT: freezer-energy-monitor/stat/RESULT = {"Rule3":{"State":"OFF","Once":"OFF","StopOnError":"OFF","Length":0,"Free":511,"Rules":""}}

[ ] Provide the output of this command: Status 0:


STATUS 0 output here:
08:44:53.950 MQT: freezer-energy-monitor/stat/STATUS = {"Status":{"Module":18,"DeviceName":"Freezer Energy Monitor","FriendlyName":["Switch 1","Switch 2","",""],"Topic":"freezer-energy-monitor","ButtonTopic":"0","Power":11,"PowerOnState":3,"LedState":1,"LedMask":"FFFF","SaveData":1,"SaveState":0,"SwitchTopic":"0","SwitchMode":[0,0,1,1,0,0,0,0],"ButtonRetain":0,"SwitchRetain":0,"SensorRetain":0,"PowerRetain":0,"InfoRetain":0,"StateRetain":0}}
08:44:54.012 MQT: freezer-energy-monitor/stat/STATUS1 = {"StatusPRM":{"Baudrate":9600,"SerialConfig":"8N1","GroupTopic":"tasmotas","OtaUrl":"http://ota.tasmota.com/tasmota/release/tasmota.bin.gz","RestartReason":"Software/System restart","Uptime":"0T00:11:32","StartupUTC":"2022-01-04T08:33:22","Sleep":50,"CfgHolder":4642,"BootCount":21,"BCResetTime":"2021-11-18T16:45:08","SaveCount":67,"SaveAddress":"FD000"}}
08:44:54.073 MQT: freezer-energy-monitor/stat/STATUS2 = {"StatusFWR":{"Version":"10.0.0.3(tasmota)","BuildDateTime":"2022-01-03T20:24:29","Boot":31,"Core":"2_7_4_9","SDK":"2.2.2-dev(38a443e)","CpuFrequency":80,"Hardware":"ESP8266EX","CR":"486/699"}}
08:44:54.131 MQT: freezer-energy-monitor/stat/STATUS3 = {"StatusLOG":{"SerialLog":0,"WebLog":3,"MqttLog":1,"SysLog":3,"LogHost":"192.168.1.14","LogPort":514,"SSId":["beersheba","Roatan"],"TelePeriod":900,"Resolution":"55CB88C0","SetOption":["00008008","2805C80001000600003C5A00000000000000","00408089","08006000","00004000"]}}
08:44:54.195 MQT: freezer-energy-monitor/stat/STATUS4 = {"StatusMEM":{"ProgramSize":639,"Free":1408,"Heap":13,"ProgramFlashSize":4096,"FlashSize":4096,"FlashChipId":"16405E","FlashFrequency":40,"FlashMode":3,"Features":["00000809","0FE0078E","04100001","0003904F","000016C0","40400810","020040A0","40200000","00000A00"],"Drivers":"1,2,3,4,8,9,10,12,13,20,21,29,38,50,57,59","Sensors":"1,2,3,5,10,12,13,14,33,54,60,77"}}
08:44:54.261 MQT: freezer-energy-monitor/stat/STATUS5 = {"StatusNET":{"Hostname":"freezer-energy-monitor","IPAddress":"192.168.1.28","Gateway":"192.168.1.1","Subnetmask":"255.255.255.0","DNSServer1":"192.168.1.1","DNSServer2":"0.0.0.0","Mac":"E8:DB:84:AF:9F:0E","Webserver":2,"HTTP_API":1,"WifiConfig":4,"WifiPower":17.0}}
08:44:54.318 MQT: freezer-energy-monitor/stat/STATUS6 = {"StatusMQT":{"MqttHost":"192.168.1.14","MqttPort":1883,"MqttClientMask":"DVES_%06X","MqttClient":"DVES_AF9F0E","MqttUser":"pkkrusty","MqttCount":1,"MAX_PACKET_SIZE":1200,"KEEPALIVE":30,"SOCKET_TIMEOUT":4}}
08:44:54.378 MQT: freezer-energy-monitor/stat/STATUS7 = {"StatusTIM":{"UTC":"2022-01-04T08:44:54","Local":"2022-01-04T08:44:54","StartDST":"2022-03-27T00:00:00","EndDST":"2022-10-30T00:00:00","Timezone":"+00:00","Sunrise":"07:32","Sunset":"18:50"}}
08:44:54.439 MQT: freezer-energy-monitor/stat/STATUS10 = {"StatusSNS":{"Time":"2022-01-04T08:44:54","Switch3":"ON","Switch4":"ON","ENERGY":{"TotalStartTime":"2022-01-03T21:34:56","Total":189.046,"Yesterday":0.063,"Today":0.150,"Power":31.0,"ApparentPower":65.5,"ReactivePower":57.7,"Factor":0.47,"Frequency":49.9,"Voltage":230.7,"Current":0.284}}}
08:44:54.501 MQT: freezer-energy-monitor/stat/STATUS11 = {"StatusSTS":{"Time":"2022-01-04T08:44:54","Uptime":"0T00:11:32","UptimeSec":692,"Heap":13,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":1,"POWER1":"ON","POWER2":"ON","POWER3":"OFF","POWER4":"ON","Wifi":{"AP":2,"SSId":"Roatan","BSSId":"E4:0E:EE:1C:E2:69","Channel":1,"Mode":"11n","RSSI":78,"Signal":-61,"LinkCount":1,"Downtime":"0T00:00:03"}}}

- [ ] Set `weblog` to 4 and then, when you experience your issue, provide the output of the Console log:
```lua
  Console output here:
00:00:00.001 HDW: ESP8266EX
00:00:00.016 UFS: FlashFS mounted with 1992 kB free
00:00:00.091 CFG: Loaded from File, Count 65
00:00:00.101 MSH: Initialized
00:00:00.103 Project pkkrusty - Freezer Energy Monitor Version 10.0.0.3(tasmota)-2_7_4_9(2022-01-03T20:24:29)
00:00:00.139 SNS: Hardware Serial
00:00:00.143 I2C: DS3231 found at 0x68
00:00:00.421 Set time from DS3231 to RTC (UTC) 2022-01-04T08:33:11, (DST) 2022-03-27T00:00:00, (STD) 2022-10-30T00:00:00
00:00:00.468 WIF: Checking connection...
00:00:00.469 WIF: Attempting connection...
00:00:00.806 WIF: Connecting to AP2 Roatan Channel 1 BSSId E4:0E:EE:1C:E2:69 in mode 11n as freezer-energy-monitor...
00:00:00.819 RUL: SYSTEM#INIT performs "backlog power1 1;power2 1;var1 1;var2 1"
00:00:00.820 SRC: Rule
00:00:00.821 CMD: Grp 0, Cmnd 'BACKLOG', Idx 1, Len 31, Data 'power1 1;power2 1;var1 1;var2 1'
00:00:00.869 SRC: Backlog
00:00:00.871 CMD: Grp 0, Cmnd 'POWER', Idx 1, Len 1, Data '1'
00:00:00.874 RSL: RESULT = {"POWER1":"ON"}
00:00:00.875 RSL: POWER1 = ON
00:00:00.001 RTC: Not synced
08:33:12.003 SRC: Backlog
08:33:12.004 CMD: Grp 0, Cmnd 'POWER', Idx 2, Len 1, Data '1'
08:33:12.007 RSL: RESULT = {"POWER2":"ON"}
08:33:12.009 RSL: POWER2 = ON
08:33:12.205 SRC: Backlog
08:33:12.207 CMD: Grp 0, Cmnd 'VAR', Idx 1, Len 1, Data '1'
08:33:12.211 RSL: RESULT = {"Var1":"1"}
08:33:12.408 SRC: Backlog
08:33:12.410 CMD: Grp 0, Cmnd 'VAR', Idx 2, Len 1, Data '1'
08:33:12.414 RSL: RESULT = {"Var2":"1"}
08:33:12.510 WIF: Checking connection...
08:33:12.511 WIF: Connected
08:33:12.762 HTP: Web server active on freezer-energy-monitor with IP address 192.168.1.28
08:33:12.764 UPP: Multicast (re)joined
08:33:13.168 WIF: Sending Gratuitous ARP
08:33:13.169 NTP: Synch time...
08:33:14.176 NTP: No reply
08:33:14.179 IFX: Url http://192.168.1.14:8086/write?db=homeautomation&u=tasmota&p=
08:33:14.181 IFX: Validating connection to http://192.168.1.14:8086/ping?verbose=true&u=tasmota&p=
08:33:14.212 HTP: Console
08:33:14.796 UPP: Multicast disabled
08:33:14.798 MQT: Attempting connection...
08:33:15.010 MQT: Connect failed to 192.168.1.14:1883, rc -2. Retry in 10 sec
08:33:15.851 UPP: Multicast (re)joined
08:33:18.123 NRG: Energy reset by invalid data
08:33:19.123 APP: Boot Count 21
08:33:19.509 CFG: Saved to flash at 3FB, Count 66, Bytes 4096
08:33:58.822 CMD: ntpserver2
08:33:58.824 SRC: WebConsole from 192.168.1.100
08:33:58.827 CMD: Grp 0, Cmnd 'NTPSERVER', Idx 2, Len 0, Data ''
08:33:58.832 MQT: freezer-energy-monitor/stat/RESULT = {"NtpServer2":"192.168.1.14"}

TO REPRODUCE

Steps to reproduce the behavior: Add a DS3231 and try to get time#initialized>5 or 10 or anything triggered

EXPECTED BEHAVIOUR

A clear and concise description of what you expected to happen. time#initialized>10 triggered once rtc.utc_time is set by either ntp or ds3231 (or ideally the time command)

SCREENSHOTS

If applicable, add screenshots to help explain your problem.

ADDITIONAL CONTEXT

Add any other context about the problem here.

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

pkkrusty commented 2 years ago

Added TasmotaGlobal.rules_flag.time_init = 1; after line 492 in support_rtc.ino to trigger time#initialized when time is entered manually. Not sure if that's acceptable to the broader community but it makes sense to me, if someone is purposely not using NTP, that time is initialized once it's entered from an alternative source (in this case, my fingers on the keyboard). Once I get some feedback from higher-ups, I can submit a PR.

pkkrusty commented 2 years ago

After more digging, it looks like an issue with my use of > with the time#initialized trigger. With a straight time#inititalized trigger, it fires normally at around 300ms after boot (before I'd like it to, since I get some conflicts with the resulting backlog execution from system#init. Thus I want to use time#initialized>10 to let the system settle down before my next set of rules executes. But between the DS3231 setting the time and 10 seconds, the flag gets lost.

While I'm messing around with DS3231 driver, I'd like to change the offset for re-writing to the DS3231 to 10 second instead of 60 (Line 157). Any objections to that? Personal preference, but computation time is cheap, and a sync every 5 days instead of 30 days doesn't make too much difference in terms of CPU load, but would keep the DS3231 much closer to true time if internet goes out for an extended period.

pkkrusty commented 2 years ago

Latest work: If I flash a lite build, without tasmesh, influxdb, sunrise, ping, expression, if_statement, and most sensors disabled, time#initialized>10 triggers. so does >50. And time#initialized fires at around 130ms.

However, I note that 120 does not equal 120 seconds as indicated by documentation. Makes no difference what number I put in, it still triggers about 20ms after the initial trigger.

00:00:00.001 HDW: ESP8266EX
00:00:00.020 UFS: FlashFS mounted with 1992 kB free
00:00:00.095 CFG: Loaded from File, Count 26
00:00:00.101 QPC: Count 1
00:00:00.103 CFG: CR 458/699, Busy 0
00:00:00.107 SRC: Restart
00:00:00.109 Project pkkrusty - Tasmota Version 10.0.0.3(tasmota)-2_7_4_9(2022-01-07T15:03:18)
00:00:00.111 I2C: DS3231 found at 0x68
00:00:00.131 Set time from DS3231 to RTC (UTC) 2022-01-07T15:33:15, (DST) 2022-03-27T00:00:00, (STD) 2022-10-30T00:00:00
00:00:00.131 RTC: Rtc.utc_time set correctly by DS3231
00:00:00.132 Rtc.utc_time 1641569595
00:00:00.132 Rtc.local_time 0
00:00:00.218 WIF: Attempting connection...
00:00:00.555 WIF: Connecting to AP2 beersheba Channel 6 BSSId D8:0D:17:B3:A6:E6 in mode 11n as pkkrusty-AF8D12-3346...
00:00:00.001 RTC: Not synced
15:33:16.010 RUL: TIME#INITIALIZED performs "power1 1"
15:33:16.011 SRC: Rule
15:33:16.012 CMD: Grp 0, Cmnd 'POWER', Idx 1, Len 1, Data '1'
15:33:16.015 RSL: RESULT = {"POWER":"ON"}
15:33:16.016 RSL: POWER = ON
15:33:16.027 RUL: TIME#INITIALIZED>111 performs "power1 1"
15:33:16.028 SRC: Rule
15:33:16.029 CMD: Grp 0, Cmnd 'POWER', Idx 1, Len 1, Data '1'
15:33:16.032 RSL: RESULT = {"POWER":"ON"}
15:33:16.033 RSL: POWER = ON
15:33:16.044 RUL: TIME#INITIALIZED>120 performs "power1 1"
15:33:16.045 SRC: Rule
15:33:16.046 CMD: Grp 0, Cmnd 'POWER', Idx 1, Len 1, Data '1'
15:33:16.049 RSL: RESULT = {"POWER":"ON"}
15:33:16.050 RSL: POWER = ON

If I remove the DS3231 and just use NTP servers, same issue.

00:00:00.001 HDW: ESP8266EX
00:00:00.022 UFS: FlashFS mounted with 1992 kB free
00:00:00.100 CFG: Loaded from File, Count 29
00:00:00.105 QPC: Count 1
00:00:00.107 CFG: CR 458/699, Busy 0
00:00:00.111 SRC: Restart
00:00:00.113 Project pkkrusty - Tasmota Version 10.0.0.3(tasmota)-2_7_4_9(2022-01-07T15:03:18)
00:00:00.221 WIF: Attempting connection...
00:00:00.558 WIF: Connecting to AP2 beersheba Channel 6 BSSId D8:0D:17:B3:A6:E6 in mode 11n as pkkrusty-AF8D12-3346...
00:00:01.753 WIF: Connected
00:00:02.005 HTP: Web server active on pkkrusty-AF8D12-3346 with IP address 192.168.1.50
00:00:02.006 UPP: Multicast (re)joined
00:00:02.312 HTP: Console
00:00:02.438 NTP: Synch time...
00:00:02.551 NTP: Runtime 0
00:00:02.551 Rtc.utc_time 1641569930
00:00:02.552 Rtc.local_time 2
00:00:02.554 RTC: UTC 2022-01-07T15:38:50, DST 2022-03-27T00:00:00, STD 2022-10-30T00:00:00
00:00:02.554 support_rtc function running correctly, rtc.utc_time set
00:00:02.555 Rtc.utc_time 1641569930
00:00:02.556 Rtc.local_time 2
15:38:50.000 NTP: Synched
15:38:50.035 RUL: TIME#INITIALIZED performs "power1 1"
15:38:50.036 SRC: Rule
15:38:50.037 CMD: Grp 0, Cmnd 'POWER', Idx 1, Len 1, Data '1'
15:38:50.040 RSL: RESULT = {"POWER":"ON"}
15:38:50.041 RSL: POWER = ON
15:38:50.054 RUL: TIME#INITIALIZED>10 performs "power1 1"
15:38:50.055 SRC: Rule
15:38:50.056 CMD: Grp 0, Cmnd 'POWER', Idx 1, Len 1, Data '1'
15:38:50.059 RSL: RESULT = {"POWER":"ON"}
15:38:50.061 RSL: POWER = ON
15:38:50.070 RUL: TIME#INITIALIZED>120 performs "power1 1"
15:38:50.071 SRC: Rule
15:38:50.072 CMD: Grp 0, Cmnd 'POWER', Idx 1, Len 1, Data '1'
15:38:50.075 RSL: RESULT = {"POWER":"ON"}
15:38:50.077 RSL: POWER = ON

Jason2866 commented 2 years ago

If sleep is activated it is normal that the MCU reacts not so fast. Reducing the drivers lowers the CPU load. So the behaviour you see is normal and as expected. Tasmota is NOT RTOS

pkkrusty commented 2 years ago

So documentation is not accurate? The > symbol doesn't seem to do anything. Load average for even the big firmware is only 19, leaving plenty of overhead in the sleep cycle. Seems like > symbol in that trigger is just getting executed on the next loop.

Jason2866 commented 2 years ago

A low LoadAVG does not mean the device will react as fast as when sleep is switched off.

pkkrusty commented 2 years ago

Makes sense. But > modifier still doesn't have an effect even on a lightly loaded processor.

Also doesn't work correctly if Sleep 0

sfromis commented 2 years ago

Do not assume that LoadAvg is a simple measure of how busy it is. It can even get above 100, depending on circumstances.

pkkrusty commented 2 years ago

@sfromis any way to get any kind of real-time feedback on load? I'm curious what levels it hits with various builds. For example, things definitely feel slower on the WebUI when I have Tasmesh included.

sfromis commented 2 years ago

Not really. And even having the LoadAvg every TelePeriod (not available faster, unless you fire off lots of commands to query state all the time), you may be assuming too much importance of that number.

While I've not at all looked into the Tasmesh driver, on a general level timing-depend things doing blocking delays can really mess with how well Tasmota operates, as techniques quite viable for the MCU only having one thing to do may just not work when it has to relinquish control to other functions having urgent needs of being allowed to run.

I'm not surprised if mixing types of network communication at the same time may not be snappy, as there is no "real multitasking".

stefanbode commented 2 years ago

Looks for me also as a bug. Maybe you can output the value of time initialized when the rule gets executed. It looks like this value is much higher than the 10 or 120. this would explain why all the triggers get executed immediately.

pkkrusty commented 2 years ago

I added some debugging when I thought it was a problem with the ds3231 driver, and the two key values are rtc.local_time and rtc.utc_time being less than and greater than 2016-01-01 in epoch time, respectively. That lets an if statement trigger the flag. But I can't figure out the rules code that deals with comparators to see what the >10 or >120 is comparing against. Epoch time? Milliseconds since boot?

pkkrusty commented 2 years ago

Ah i didn't initially understand your suggestion, but now I do. I published %value% and sure enough, it looks like milliseconds from boot. I can work with that, but either documentation or implementation should get fixed. Votes?

arendst commented 2 years ago

Never the implementation as it has been working for many people for many years.

I haven't read this whole thread but from the beginning I understand the supposed rule time#initialized>10 was never meant to be used like this. Only time#initialized is supposed to be used and occurs when the RTC code is initialised with some kind of time but not a time after 2016.

Looking at the code you'll see what happens:

    if (Rtc.local_time < START_VALID_TIME) {  // 2016-01-01
      TasmotaGlobal.rules_flag.time_init = 1;
    } else {
      TasmotaGlobal.rules_flag.time_set = 1;
    }

The goal of this code is twofold:

Initial call to master time interrupt handler has been done (time#initialized).
Sync calls to master time handler have been done (time#set).

Again see code below:

            case 2: snprintf_P(json_event, sizeof(json_event), PSTR("{\"Time\":{\"Initialized\":%d}}"), MinutesPastMidnight()); break;
            case 3: snprintf_P(json_event, sizeof(json_event), PSTR("{\"Time\":{\"Set\":%d}}"), MinutesPastMidnight()); break;

I suggest you rather learn to read the code than keep suggesting solutions based on guess work to eleviate long discussions like this.

pkkrusty commented 2 years ago

Based on my last test, time#initialized value is milliseconds since boot. Thus the comparator will work, but not as described in documentation. I'm happy to fix that.

I'm also happy to leave my issues threads just stating the problem, but wanted to fill in readers with steps I took to narrow it down, since often problems are user error rather than coding or documentation. Reading code is like learning a language, it takes time. I'm currently at the 2-year-old copycat stage.

arendst commented 2 years ago

I totally understand but...

From the code you can clearly see it's NOT milliseconds after a reboot BUT it's minutes past midnight.

Feel free to update any documentation with valid information.

stefanbode commented 2 years ago

To overcome your problem just use time#initialized and fire a 10 second timer. The the timer will finally execute your script. I think this should work

Jason2866 commented 2 years ago

Closing since it is answered. As designed

pkkrusty commented 2 years ago

Question: Has anyone ever had success with Time#Initialized>10 (or any number) trigger? Even when I evaluate it as MinutesPastMidnight, it doesn't trigger when the threshhold is reached. Maybe doesn't belong in the Rules documentation.

sfromis commented 2 years ago

Did a small test, restarted with: on Time#Initialized do var1 %value% endon on Time#Initialized>100 do var2 %value% endon Seems to work as already suggested here.....

18:34:17.020 RUL: TIME#INITIALIZED performs "var1 1114"
18:34:17.022 SRC: Rule
18:34:17.023 CMD: Grp 0, Cmnd 'VAR', Idx 1, Len 4, Data '1114'
18:34:17.028 RSL: VAR = {"Var1":"1114"}
18:34:17.039 RUL: TIME#INITIALIZED>100 performs "var2 1114"
18:34:17.040 SRC: Rule
18:34:17.042 CMD: Grp 0, Cmnd 'VAR', Idx 2, Len 4, Data '1114'
18:34:17.046 RSL: VAR = {"Var2":"1114"}

Your phrase it doesn't trigger when the threshhold is reached does not seem to suggest you being aware that it is only being evaluated once, and not continuously. For "normal" timers, you may want Time#Minute>10

Anyway, while a number can be used with Time#Initialized, I'd say that the value of reacting to time-of-day at NTP init time may not be a very common use case.

arendst / Tasmota