NTP syncs every ~2 seconds

m-kozlowski commented 2 years ago

Bug description Just noticed this in debug tab:

[756582] [NTP] Sync Time  2021-12-09 02:21:18 (UTC)
[756582] [NTP] UTC Time   2021-12-09 02:21:18
[756582] [NTP] Local Time 2021-12-09 03:21:18 (CET-1CEST,M3.5.0,M10.5.0/3)
[758804] [NTP] Server     10.1.1.1
[758804] [NTP] Sync Time  2021-12-09 02:21:20 (UTC)
[758804] [NTP] UTC Time   2021-12-09 02:21:20
[758805] [NTP] Local Time 2021-12-09 03:21:20 (CET-1CEST,M3.5.0,M10.5.0/3)
[761033] [NTP] Server     10.1.1.1
[761034] [NTP] Sync Time  2021-12-09 02:21:22 (UTC)
[761034] [NTP] UTC Time   2021-12-09 02:21:22
[761034] [NTP] Local Time 2021-12-09 03:21:22 (CET-1CEST,M3.5.0,M10.5.0/3)
[763261] [NTP] Server     10.1.1.1
[763261] [NTP] Sync Time  2021-12-09 02:21:24 (UTC)
[763261] [NTP] UTC Time   2021-12-09 02:21:24
[763262] [NTP] Local Time 2021-12-09 03:21:24 (CET-1CEST,M3.5.0,M10.5.0/3)
[765485] [NTP] Server     10.1.1.1
[765486] [NTP] Sync Time  2021-12-09 02:21:27 (UTC)
[765486] [NTP] UTC Time   2021-12-09 02:21:27
[765486] [NTP] Local Time 2021-12-09 03:21:27 (CET-1CEST,M3.5.0,M10.5.0/3)
[767707] [NTP] Server     10.1.1.1
[767708] [NTP] Sync Time  2021-12-09 02:21:29 (UTC)
[767708] [NTP] UTC Time   2021-12-09 02:21:29
[767708] [NTP] Local Time 2021-12-09 03:21:29 (CET-1CEST,M3.5.0,M10.5.0/3)

Steps to reproduce current master (26d28db0ef8be719a296a81dcaa6094e6c5cc67c) ntpUpdateIntvl not set, so it should be at default 1800

Device information

ESPURNA 1.15.0-dev.git26d28db0 built 2021-12-09 02:37:26
mcu: esp8266 chipid: BCDDC22393F5 freq: 80mhz
sdk: 2.2.2-dev(38a443e) core: 2.7.4
md5: 94181e2c2ad7a348ebb722128a2b098e
support: ALEXA API BUTTON DEBUG_SERIAL DEBUG_TELNET DEBUG_WEB DOMOTICZ LED MDNS MQTT NTP ARDUINO_OTA OTA_WEB OTA_CLIENT METRICS RELAY SCHEDULER SENSOR TELNET TERMINAL WEB 
sensors: HLW8012 
system: OK boot counter: 0
last reset reason: Reboot after a successful OTA update

Tools used

For a custom builds:
- PlatformIO platform & environment(s) used

[env:blitzwolf-bwshpx-4M]
extends = env:esp8266-4m-base
src_build_flags = -DBLITZWOLF_BWSHPX -DUSE_CUSTOM_H

$ grep NTP ./espurna/config/custom.h
#define NTP_SERVER                  "ntp"
#define NTP_TIMEZONE                TZ_Europe_Warsaw

m-kozlowski commented 2 years ago

after setting ntpUpdateIntvl => "10000" it syncs every 15-16 seconds

mcspr commented 2 years ago

thx! these should've been wrapped with milliseconds https://github.com/xoseperez/espurna/blob/26d28db0ef8be719a296a81dcaa6094e6c5cc67c/code/espurna/ntp.cpp#L60 https://github.com/xoseperez/espurna/blob/26d28db0ef8be719a296a81dcaa6094e6c5cc67c/code/espurna/ntp.cpp#L65 (i.e. instead of value.count() -> espurna::duration::Milliseconds(value).count(), these are going into the sntp that only understand milliseconds)

it is also interesting that sntp does not actually enforce time limits mentioned in the func signature, I should've probably added a clamp() right when the value is randomized...

m-kozlowski commented 2 years ago

Too elegant, I'd just go with *1000L ;p But your way also works;)

diff --git a/code/espurna/ntp.cpp b/code/espurna/ntp.cpp
index e31b3e5e..f7822a1d 100644
--- a/code/espurna/ntp.cpp
+++ b/code/espurna/ntp.cpp
@@ -57,12 +57,12 @@ espurna::duration::Seconds _ntpRandomizeDelay(espurna::duration::Seconds base) {

 uint32_t sntp_startup_delay_MS_rfc_not_less_than_60000() {
     static_assert(sizeof(decltype(_ntp_startup_delay)::rep) <= sizeof(uint32_t), "");
-    return _ntp_startup_delay.count();
+    return espurna::duration::Milliseconds(_ntp_startup_delay).count();
 }

 uint32_t sntp_update_delay_MS_rfc_not_less_than_15000() {
     static_assert(sizeof(decltype(_ntp_update_delay)::rep) <= sizeof(uint32_t), "");
-    return _ntp_update_delay.count();
+    return espurna::duration::Milliseconds(_ntp_update_delay).count();
 }

 // We also must shim TimeLib functions until everything else is ported.

xoseperez / espurna

NTP syncs every ~2 seconds #2489