Debug SNTP #4122

jhagberg · 2018-01-09T17:46:27Z

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:
#2330 (comment)
But I am unable to get any DEBUG from the lwip or sntp.

What am I missing.

The text was updated successfully, but these errors were encountered:

d-a-v · 2018-01-09T18:08:10Z

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

jhagberg · 2018-01-09T18:25:26Z

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.

a2d16f38
~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 · 2018-01-09T18:35:50Z

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 · 2018-01-09T20:09:21Z

@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 · 2018-01-09T20:14:53Z

@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 #1679 (comment)
and here https://sourceware.org/newlib/libc.html#Timefns

jhagberg · 2018-01-09T20:23:04Z

@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 · 2018-01-09T20:26:01Z

@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 · 2018-01-09T20:36:19Z

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 · 2018-01-09T20:42:46Z

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 · 2018-01-09T20:49:21Z

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

5chufti · 2018-01-09T21:06:03Z

can you define "long time"?
here #1679 (comment) 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 · 2018-01-09T21:46:31Z

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

5chufti · 2018-01-09T22:02:10Z

and what if fixed ip is used?

d-a-v · 2018-01-09T22:13:20Z

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 · 2018-01-10T07:50:54Z

@5chufti Several minutes. Sometimes shorter sometimes longer.

5chufti · 2018-01-10T12:50:27Z

@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 · 2018-01-10T13:02:48Z

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

5chufti · 2018-01-10T21:42:22Z

@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 · 2018-01-11T09:38:11Z

@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 · 2018-01-11T14:14:28Z

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

5chufti · 2018-01-11T16:40:49Z

one can't use

configTime(0, 0, "192.168.1.1")

or

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

jhagberg · 2018-01-17T08:03:01Z

@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 · 2018-01-17T08:31:03Z

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

5chufti · 2018-01-17T18:36:04Z

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 · 2019-10-01T09:19:46Z

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.

#6373 (comment)

Arduino/libraries/esp8266/examples/NTP-TZ-DST/NTP-TZ-DST.ino

Line 42 in 1aeea12

#define MYTZ TZ_Europe_London

d-a-v self-assigned this Jan 9, 2018

jhagberg mentioned this issue Jan 10, 2018

First NTP sync is wrong stelgenhof/NTPClient#5

Open

digi-thomas2003 mentioned this issue Jan 10, 2018

Sketch using Timezone-Lib will not compile in v2.4.0 #4106

Closed

3rwww1 mentioned this issue Jun 13, 2018

Use ESP8266 SDK SNTP to fix "benchmark" loop LeClubSandwichStudio/LaCOOLBoard#75

Closed

andrei-markeev mentioned this issue Aug 4, 2018

Updated dependencies andriyadi/AzureIoTHubMQTTClient#11

Open

s0170071 mentioned this issue Nov 3, 2018

NTP time failure- year is always 1970 arendst/Tasmota#4243

Closed

1 task

d-a-v closed this as completed Oct 1, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Debug SNTP #4122

Debug SNTP #4122

jhagberg commented Jan 9, 2018

d-a-v commented Jan 9, 2018

jhagberg commented Jan 9, 2018

d-a-v commented Jan 9, 2018

reaper7 commented Jan 9, 2018 •

edited

Loading

5chufti commented Jan 9, 2018

jhagberg commented Jan 9, 2018

jhagberg commented Jan 9, 2018

d-a-v commented Jan 9, 2018

5chufti commented Jan 9, 2018

jhagberg commented Jan 9, 2018

5chufti commented Jan 9, 2018 •

edited

Loading

d-a-v commented Jan 9, 2018

5chufti commented Jan 9, 2018

d-a-v commented Jan 9, 2018

jhagberg commented Jan 10, 2018

5chufti commented Jan 10, 2018 •

edited

Loading

d-a-v commented Jan 10, 2018 •

edited

Loading

5chufti commented Jan 10, 2018 •

edited

Loading

5chufti commented Jan 11, 2018 •

edited

Loading

d-a-v commented Jan 11, 2018

5chufti commented Jan 11, 2018

jhagberg commented Jan 17, 2018

jhagberg commented Jan 17, 2018

5chufti commented Jan 17, 2018

d-a-v commented Oct 1, 2019

Debug SNTP #4122

Debug SNTP #4122

Comments

jhagberg commented Jan 9, 2018

Basic Infos

Hardware

Description

d-a-v commented Jan 9, 2018

jhagberg commented Jan 9, 2018

d-a-v commented Jan 9, 2018

reaper7 commented Jan 9, 2018 • edited Loading

5chufti commented Jan 9, 2018

jhagberg commented Jan 9, 2018

jhagberg commented Jan 9, 2018

d-a-v commented Jan 9, 2018

5chufti commented Jan 9, 2018

jhagberg commented Jan 9, 2018

5chufti commented Jan 9, 2018 • edited Loading

d-a-v commented Jan 9, 2018

5chufti commented Jan 9, 2018

d-a-v commented Jan 9, 2018

jhagberg commented Jan 10, 2018

5chufti commented Jan 10, 2018 • edited Loading

d-a-v commented Jan 10, 2018 • edited Loading

5chufti commented Jan 10, 2018 • edited Loading

5chufti commented Jan 11, 2018 • edited Loading

d-a-v commented Jan 11, 2018

5chufti commented Jan 11, 2018

jhagberg commented Jan 17, 2018

jhagberg commented Jan 17, 2018

5chufti commented Jan 17, 2018

d-a-v commented Oct 1, 2019

reaper7 commented Jan 9, 2018 •

edited

Loading

5chufti commented Jan 9, 2018 •

edited

Loading

5chufti commented Jan 10, 2018 •

edited

Loading

d-a-v commented Jan 10, 2018 •

edited

Loading

5chufti commented Jan 10, 2018 •

edited

Loading

5chufti commented Jan 11, 2018 •

edited

Loading