Arduino: Debug SNTP

[jhagberg]

Basic Infos

Hardware

Hardware: SonOFF TH10 and Adafruit HUZZAH
Core Version: 2.4.0

Description

Running on SonOFF TH10 and one Adafruit HuzZazh I got a problem with delayed first sync using the sntp client with for example this library. https://github.com/stelgenhof/NTPClient/

[NTP] First synchronization: 1970-01-01T17:00:00.
Got NTP time: 1970-01-01T17:00:00
after a while, It gets the right sync. Same problem with different time servers both local and on the internet. Using the example ntp sketch that is not using the sntp part I get the right time at once.

Problem description

Other users report no problem so I would like to debug this but have a problem to turn on the debug of sntp.

I have added

Serial.begin(115200);
Serial.setDebugOutput(true);
os_printf("hello\n");

in my sketch that is the example sketch from the above lib.
the Hello is printed out. I have also added debug outputs in lwipopts.h found in my
bin/arduino-1.8.5/hardware/esp8266com/esp8266/tools/sdk/include
as this comment state:
https://github.com/esp8266/Arduino/issues/2330#issuecomment-339121094
But I am unable to get any DEBUG from the lwip or sntp.

What am I missing.

[d-a-v]

Can you have a look to another example appeared after the sntp fix
file/examples/esp8266/ntp-tz-dst

[jhagberg]

Hej

Thanks

Here is the serial output. Looks like it works super fast. First is wrong but I guess that's because the script does not wait for wifi. So what has been fixed? and how can I use this fix in the library? Just need to sync the time with ntp as easy and small size as possible.

~ld
clock:21/433517000ns millis:21433 micros:21433535 gtod:0/19922us time:28800 ctime:(UTC+120mn)Thu Jan  1 08:00:00 1970
clock:21/534312000ns millis:21534 micros:21534328 gtod:0/120726us time:28800 ctime:(UTC+120mn)Thu Jan  1 08:00:00 1970
scandone
state: 0 -> 2 (b0)
state: 2 -> 3 (0)
state: 3 -> 5 (10)
add 0
aid 1
cnt 

connected with FISTEL, channel 5
dhcp client start...
ip:192.168.1.43,mask:255.255.255.0,gw:192.168.1.1
clock:21/634834000ns millis:21634 micros:21634852 gtod:0/221239us time:28800 ctime:(UTC+120mn)Thu Jan  1 08:00:00 1970
------------------ settimeofday() was called ------------------

localtime:isdst=0:yday=8:wday=2:year=118:mon=0:mday=9:hour=20:min=20:sec=8
gmtime   :isdst=0:yday=8:wday=2:year=118:mon=0:mday=9:hour=20:min=20:sec=8

clock:21/735501000ns millis:21735 micros:21735512 gtod:1515522008/471858us time:1515529208 ctime:(UTC+120mn)Tue Jan  9 20:20:08 2018
clock:21/849546000ns millis:21849 micros:21849559 gtod:1515522008/585903us time:1515529208 ctime:(UTC+120mn)Tue Jan  9 20:20:08 2018
clock:21/950070000ns millis:21950 micros:21950081 gtod:1515522008/686428us time:1515529208 ctime:(UTC+120mn)Tue Jan  9 20:20:08 2018
clock:22/50597000ns millis:22050 micros:22050611 gtod:1515522008/786955us time:1515529208 ctime:(UTC+120mn)Tue Jan  9 20:20:08 2018
clock:22/151104000ns millis:22151 micros:22151115 gtod:1515522008/887461us time:1515529208 ctime:(UTC+120mn)Tue Jan  9 20:20:08 2018
clock:22/251629000ns millis:22251 micros:22251642 gtod:1515522008/987986us time:1515529208 ctime:(UTC+120mn)Tue Jan  9 20:20:08 2018

[d-a-v]

It does not wait for wifi on purpose. This example shows how to get accurate time without external library. You can use the callback to know when current time is set.

Regarding the external library, I have no information myself, that should be asked in its repo.

[reaper7]

@jhagberg - it's true, external libs like tandem https://github.com/gmag11/NtpClient + https://github.com/PaulStoffregen/Time do not get/set time from ntp servers but timeStatus() return "timeSet" - strange! (when lwIP v2 is selected)

but the same libs works ok on lwIP 1.4

[5chufti]

@jhagberg - with 2.4.0 there is no longer need for 3rd party libs.
All sntp (is in lwip) function including TZ and DST (in newlibc) support is in core .
see here https://github.com/esp8266/Arduino/issues/1679#issuecomment-346631781
and here https://sourceware.org/newlib/libc.html#Timefns

[jhagberg]

@reaper7 Thanks. Aha that strange but that explains that the lib owner did not have any issues. And that also might explain why my efforts to turn on lwip debug in version 1 did not work since I am now using lwip 2.

[jhagberg]

@5chufti Good to know. I am updating an old sketch that I had running on an Arduino Uno and a Sparkfun WiFly Sheild to a SonOff TH10 esp8266 module. I used timelib and TimeAlarms library. If I want to implement some TimeAlarms what is the best way now to do it without using https://github.com/PaulStoffregen/Time and https://github.com/PaulStoffregen/TimeAlarms ?

[d-a-v]

If all former NTP libs do not work with 2.4.0 then I guess something should be done here for the sake of coherency and compatibility.

[5chufti]

since time functions (apart from setup) are "compatible" in most "former NTP" libs, I see no reason why TimeAlarms shouldn't work with "core" sntp implementation

[jhagberg]

Yes They work but it takes long time to get an accurate time.

[5chufti]

can you define "long time"?
here https://github.com/esp8266/Arduino/issues/1679#issuecomment-346962934 I did a compare of "sync times" for. old and new implementation, also utilizing the sntp_force_request(); function.
Unfortunately I don't know if this is still available in the final 2.4.0.

[d-a-v]

sntp_force_request() was a test and is no more. Instead it is automatically done when esp gets its IP via DHCP.

[5chufti]

and what if fixed ip is used?

[d-a-v]

I admit I have not tested this precisely, but it should work.
It is not on a DHCP answer but rather on IP set: There is a lwip netif callback and it is done in it.

[jhagberg]

@5chufti Several minutes. Sometimes shorter sometimes longer.

[5chufti]

@d-a-v @igrr : ok, confirmed,

with DHCP the first sync appears within 0.4s / 3.6s depending on persistence of WiFi.
with static IP the time to first sync makes it unusable ....

EDIT: see later post

[d-a-v]

Thanks for testing this. [edit:if you don't plan to try and fix this,] Can you provide your sketch ?

[5chufti]

@d-a-v

I tested it with this modified sketch form #1679
(don't forget to adapt IP settings)

#define DYN 0                    // IP static=0 dhcp=1
#define PER 0                    // persistent n=0 y=1

#include <ESP8266WiFi.h>
#include <time.h>
#include <coredecls.h>                  // settimeofday_cb()

#define SSID "yourSSID"
#define WPWD "yourPASS"

#if !DYN
IPAddress ip(192, 168, X, Y);
IPAddress gw(192, 168, X, Z);
IPAddress nm(255, 255, 255, 0);
IPAddress ns(192, 168, X, Y);
#endif

time_t t = 0;

void time_is_set (void)
{
  time(&t);
  Serial.println("got time (@" + String(millis()) + "ms) " + ctime(&t));
  ESP.deepSleep(15000000);
  delay(10);
}

void setup() {
  Serial.begin(74880);
  Serial.println("setup(): " + String(millis()));
  settimeofday_cb(time_is_set);
  configTime(0, 0, "pool.ntp.org");
  WiFi.persistent(PER);
  WiFi.mode(WIFI_STA);
#if !DYN
  WiFi.config(ip, gw, nm, ns, ns);
#endif
  WiFi.begin(SSID, WPWD);
  while (WiFi.status() != WL_CONNECTED) delay(1);
  Serial.println("WiFi connected: " + String(millis()));
#if !PER
  ESP.eraseConfig();
#endif
}

void loop() {
  yield();
}

I experienced different behaviour at work than at home for static IP, at home I get periods of relativ fast (~7s) syncs and then some with longer waits; seems to depend on AP.

[5chufti]

@d-a-v @igrr
Ok, new day new luck:
after I was told that yesterday our dns servers were serviced (probably used bad DNS IP) I ran the test again at work:

######## persisted WiFi static IP #########

setup(): 195
WiFi connected: 2589
got time (@2615ms) Thu Jan 11 09:17:49 2018


setup(): 194
WiFi connected: 363
got time (@389ms) Thu Jan 11 09:18:05 2018


setup(): 200
WiFi connected: 1373
got time (@1409ms) Thu Jan 11 09:18:21 2018

setup(): 206
WiFi connected: 1372
got time (@1395ms) Thu Jan 11 09:18:37 2018


setup(): 196
WiFi connected: 359
got time (@375ms) Thu Jan 11 09:18:52 2018


setup(): 197
WiFi connected: 359
got time (@383ms) Thu Jan 11 09:19:07 2018


setup(): 197
WiFi connected: 363
got time (@1137ms) Thu Jan 11 09:19:23 2018

############ new WiFi static IP ###########

setup(): 346
WiFi connected: 3396
got time (@3621ms) Thu Jan 11 09:22:26 2018


setup(): 337
WiFi connected: 3385
got time (@3618ms) Thu Jan 11 09:22:44 2018


setup(): 339
WiFi connected: 3387
got time (@3616ms) Thu Jan 11 09:23:02 2018


setup(): 343
WiFi connected: 5621
got time (@5848ms) Thu Jan 11 09:23:23 2018


setup(): 358
WiFi connected: 3406
got time (@3642ms) Thu Jan 11 09:23:41 2018

######## persisted WiFi dynamic IP ########

setup(): 200
WiFi connected: 2142
got time (@2165ms) Thu Jan 11 09:27:47 2018


setup(): 203
WiFi connected: 388
got time (@406ms) Thu Jan 11 09:28:02 2018


setup(): 201
WiFi connected: 385
got time (@405ms) Thu Jan 11 09:28:17 2018


setup(): 202
WiFi connected: 2332
got time (@2355ms) Thu Jan 11 09:28:34 2018


setup(): 200
WiFi connected: 3374
got time (@3396ms) Thu Jan 11 09:28:53 2018


setup(): 201
WiFi connected: 383
got time (@402ms) Thu Jan 11 09:29:08 2018


########### new WiFi dynamic IP ###########

setup(): 341
WiFi connected: 3412
got time (@3640ms) Thu Jan 11 09:32:31 2018


setup(): 342
WiFi connected: 4422
got time (@4647ms) Thu Jan 11 09:32:51 2018


setup(): 349
WiFi connected: 8239
got time (@8464ms) Thu Jan 11 09:33:14 2018


setup(): 346
WiFi connected: 5182
got time (@5405ms) Thu Jan 11 09:33:34 2018


setup(): 347
WiFi connected: 3420
got time (@3644ms) Thu Jan 11 09:33:52 2018


setup(): 342
WiFi connected: 6179
got time (@6404ms) Thu Jan 11 09:34:13 2018

so against my yesterdays statement I have to say it is working as intended.
what definitely (still) doesn't work is giving IP for timeserver.
@jhagberg : maybe you want to try my small sketch and share your observations?

[d-a-v]

@5chufti what do you call "giving IP for timeserver" still not working ?

[5chufti]

one can't use

configTime(0, 0, "192.168.1.1") 

or

IPAddress ts(192, 168, 1, 1);
configTime(0, 0, ts);

[jhagberg]

@5chufti I have tested your sketch with dynamic IP and I get time sync direct after wifi connection. So it works very well.

I have understood the SNTP code right that it will update and sync time from NTP server about every hour that is the default TIMEOUT?

[jhagberg]

setup(): 21816
WiFi connected: 24877
got time (@26081ms) Tue Jan 16 17:17:59 2018

[5chufti]

hmmm, that could be the setup after a long compiling session: resets esp and keeps in flashing mode until restart after successfull flashing ... else I wouldn't know.

[d-a-v]

SNTP support and example have receive updates, and this thread is old.
Closing but feel free to open a new issue based on git-current sntp code and example.

Current code allows to update sntp startup and update time,
also once your timezone is set (with "continent/city"), DST is automatically handled and automatically updated on transition time without reflash/reboot.
check example.

https://github.com/esp8266/Arduino/pull/6373#issuecomment-536235781
https://github.com/esp8266/Arduino/blob/1aeea124b358c3dc63e1c6fb96376695cf24840b/libraries/esp8266/examples/NTP-TZ-DST/NTP-TZ-DST.ino#L42