ropg / ezTime

ezTime — pronounced "Easy Time" — is a very easy to use Arduino time and date library that provides NTP network time lookups, extensive timezone support, formatted time and date strings, user events, millisecond precision and more.
MIT License
327 stars 92 forks source link

Function for setting NTP_RETRY #73

Open Ing-Med opened 4 years ago

Ing-Med commented 4 years ago

After some debugging, i found out that my NTP Server sometimes fails to respond and hence due to my program design, ezTime blocks my EPS8266 for 20 seconds according to NTP_RETRY.

Heres my outline: i am trying to run a small battery and time efficient program on my EPS8266 but i need a time to work with and i found myself to be too lazy to use smaller libraries or use RTCs :) So this problem is more of a luxurious one. After i had the program running for a few hours i encountered that the runtimes are about 20sec higher than usual. It took a while to figure out, but it's due to the fact that ezTime will retry getting to the server 20 sec later. However, since i do not really use to update time in the future (as the program only runs 4 seconds) i only ever want to initialize and get the time once and do not rely on maintaining the library via events() (it simply would not be called upon. The only wait loop in existance is waiting for Wifi to be live)

For my specific use case, changing the NTP_RETRY time gets rid of my problem, as the ESP won't be blocked* too long by the library and just tries again in a bit. Unfortunately, i found nowhere to change the static value. For my usecase, it would be nice if i were able to, but i'll admit, thats probably not the main audience for this library.

*I initialize my time with waitforsync() which apparently by design blocks the program. If the NTP server fails to send the time, an event will be set for 20 seconds in the future and then it will be stuck in this loop https://github.com/ropg/ezTime/blob/master/src/ezTime.cpp#L531 for 20 seconds until the next NTP call.

Rather than having periodically checking events() and then trying again when the time is right, it stays in waitforsync() for these 20 seconds. I am not sure if that is by your design. (since you implemented a Timeout. The if function actually correctly does an "ERROR: Timeout" but continues with the loop.

Using updateNTP() instead of waitforsync() would work i suppose, but it doesn't reliably get the time, if there was a connection error to the NTP server. But this is due to my constricting program design.

Best,

Heres some Code:

debugSerial("Getting Time"); if(updateTime == false) //update time { setServer(WiFi.gatewayIP().toString()); setDebug(DEBUG); debugSerial("Time 1"); waitForSync(1000); debugSerial("Time 2"); atTime.setLocation(F("de")); updateTime = true; debugSerial("Getting Time - DONE"); Serial.println("\t\t"+ atTime.dateTime()); debugSerial("Time 3"); } //debug debugSerial("WLAN Connected, TIME done - Debug END"); standbyFunction(false);

Output:

||2165ms|| Getting Time ezTime debug level set to DEBUG

||2166ms|| Time 1Waiting for time sync Querying 10.10.10.1 ... ERROR: Timeout Set event (#1) to trigger on: Thursday, 01-Jan-1970 00:00:23 UTC Running event (#1) set for Thursday, 01-Jan-1970 00:00:23 UTC Querying 10.10.10.1 ... Received data: 0: 24, 2, 9, F1, 4: 0, 0, 3, 57, 8: 0, 0, 5, 8B, 12: D9, C4, 91, 2A, 16: E1, 94, 10, 3F, 20: 48, D7, 14, 59, 24: 0, 0, 0, 0, 28: 0, 0, 0, 0, 32: E1, 94, 11, 52, 36: 82, 19, 51, 2A, 40: E1, 94, 11, 52, 44: 82, 2A, B9, 30, success (round trip 227 ms) Received time: Thursday, 05-Dec-19 23:29:22.652 UTC Set event (#1) to trigger on: Thursday, 05-Dec-2019 23:59:23 UTC Time is in sync

||23581ms|| Time 2Timezone lookup for: de ... (round-trip 32 ms) success. Olson: Europe/Berlin Posix: CET-1CEST,M3.5.0,M10.5.0/3

||23726ms|| Getting Time - DONE Friday, 06-Dec-2019 00:29:22 CET

||23798ms|| Time 3 ||23819ms|| WLAN Connected, TIME done - Debug END`

another test within the library where i printed the variables in the loop:

`||3167ms|| Getting Time ezTime debug level set to DEBUG

||3168ms|| Time 1Waiting for time sync while: _time_status: 0 timeSet: 2 timeout: 0 millis: 3418 start: 3168 TIMEOUT: 3 Querying 10.10.10.1 ... ERROR: Timeout Set event (#1) to trigger on: Thursday, 01-Jan-1970 00:00:24 UTC while: _time_status: 0 timeSet: 2 timeout: 0 millis: 5171 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 5421 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 5672 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 5922 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 6172 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 6422 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 6673 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 6923 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 7173 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 7423 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 7674 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 7924 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 8174 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 8424 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 8675 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 8925 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 9175 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 9425 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 9676 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 9926 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 10176 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 10426 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 10677 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 10927 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 11177 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 11427 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 11678 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 11928 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 12178 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 12428 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 12679 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 12929 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 13179 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 13429 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 13680 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 13930 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 14180 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 14430 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 14681 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 14931 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 15181 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 15431 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 15682 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 15932 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 16182 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 16432 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 16683 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 16933 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 17183 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 17434 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 17684 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 17934 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 18184 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 18434 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 18685 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 18935 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 19185 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 19436 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 19686 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 19936 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 20186 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 20436 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 20687 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 20937 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 21187 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 21438 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 21688 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 21938 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 22188 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 22438 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 22689 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 22939 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 23190 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 23440 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 23690 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 23941 start: 3168 TIMEOUT: 3 while: _time_status: 0 timeSet: 2 timeout: 0 millis: 24191 start: 3168 TIMEOUT: 3 Running event (#1) set for Thursday, 01-Jan-1970 00:00:24 UTC Querying 10.10.10.1 ... Received data: 0: 24, 2, 9, F1, 4: 0, 0, 4, 47, 8: 0, 0, 6, A9, 12: D9, C4, 91, 2A, 16: E1, 93, EB, 15, 20: 53, 7C, 91, A6, 24: 0, 0, 0, 0, 28: 0, 0, 0, 0, 32: E1, 93, EB, 93, 36: B, 7F, E7, E6, 40: E1, 93, EB, 93, 44: B, 96, 73, 51, success (round trip 269 ms) Received time: Thursday, 05-Dec-19 20:48:19.209 UTC Set event (#1) to trigger on: Thursday, 05-Dec-2019 21:18:20 UTC _time_status: 2 timeSet: 2 Time is in sync

||24708ms|| Time 2Timezone lookup for: de ... (round-trip 36 ms) success. Olson: Europe/Berlin Posix: CET-1CEST,M3.5.0,M10.5.0/3

||24853ms|| Getting Time - DONE Thursday, 05-Dec-2019 21:48:19 CET

||24927ms|| Time 3 ||24948ms|| WLAN Connected, TIME done - Debug END`

ropg commented 4 years ago

I guess my thinking was that most people will run something that simply makes no sense until there is a correct time. Blocking things until there is makes sure no log entries from 1970 are created, it keeps wrong things from being displayed, it keeps https certificates from showing up as invalid, etc etc. I guess I can put in an option to set the NTP_RETRY value. What do you set it to, just out of curiosity...

Ing-Med commented 4 years ago

Yeah like I said, my problem probably does not fit the agenda of your library and hence is more or less a luxurious one.

I actually reduced it to 1 second and it works without any problem. The fact that the query sometimes does not work on the first try bothers me a bit, but I guess I have to live with that. I am using the ntp server from my router in order to save time, which would otherwise be spent on the DNS request. Although the DNS request is usually cached, I currently have a problem with minor DNS outages while using my own DNS resolving service via pihole. I wanted to mitigate that by using the ntp server of the router.

As to why the router sometimes fails to get the ntp request done, I have no idea. But like I said, a literal second after the first request, the second request gets the job done.

Thanks!