First NTP sync is wrong #5

jhagberg · 2018-01-08T14:03:03Z

Hej

I am testing your code on a SonOff Th10 but I have a slight problem the first sync gives me the wrong time.

Serial print follows

`MDNS responder started
HTTP server started
....Got IP: 192.168.1.21

Got NTP time: 1970-01-01T00:00:08 last sync 1970-01-01T09:00:02
Got NTP time: 1970-01-01T09:01:02 last sync 2018-01-08T14:57:02
Got NTP time: 2018-01-08T14:58:03 last sync 2018-01-08T14:58:04
Got NTP time: 2018-01-08T14:59:05 last sync 2018-01-08T14:59:05
`

I have changed to print out the current time also.

`
case NTP_EVENT_SYNCHRONIZED:

Serial.printf("Got NTP time: %s last sync %s\n", NTP.getTimeDate(now()), NTP.getTimeDate(NTP.getLastSync()));

break;`

Any ideas whats going on. The NTP server works when using regular ntpdate so thats not the issue.
I was thinking maybe I could force the update in setup but gettime is private so that is not an option at this stage.

cheers

stelgenhof · 2018-01-08T14:20:23Z

Hard to tell from what you describe. Can you run your code with DEBUG_NTPCLIENT=1? This will produce some more debug message that may help identifying what is happening.

Cheers! Sacha

jhagberg · 2018-01-08T15:00:28Z

Hej thanks
I added #define DEBUG_NTPCLIENT=1 in my ino file but I do not get anything more on the Serial port. Maybe I am missing something do not fully understand the line #define DEBUGLOG(...) os_printf(VA_ARGS) New to esp.

jhagberg · 2018-01-08T15:01:03Z

aha I need to enable Debug during compile will test that now

jhagberg · 2018-01-08T15:06:56Z

Nope still nothing from ntp I have
Debug=Serial,
maybe I need to change DebugLevel to something?

jhagberg · 2018-01-08T21:45:45Z

Hej
I had a problem to get the DEBUG to work but I forced it to use Serial and I then got this. But not much more help.

[NTP] NTP Server #0 set to: 192.168.1.1.
[NTP] Polling interval set to: 1800 seconds.
[NTP] Requesting time from: 192.168.1.1.
[NTP] First synchronization: 1970-01-01T09:00:02.
Got NTP time: 1970-01-01T00:00:08 last sync 1970-01-01T09:00:02
[NTP] Time successfully synchronized to: 1970-01-01T09:00:02.
[NTP] Time synchronization started.
[NTP] Polling interval set to: 60 seconds.
.pm open,type:2 0
[NTP] Requesting time from: 192.168.1.1.
Got NTP time: 1970-01-01T09:01:06 last sync 2018-01-08T21:51:28
[NTP] Time successfully synchronized to: 2018-01-08T21:51:28.

Looks like the first timestamp always is 28802 after some minutes it got real timestamp back.
So I guess it something in the sntp code that is slow to update but still returns a value.

Not sure how to proceed.

stelgenhof · 2018-01-09T00:30:16Z

I can see that you are using a local NTP server. Have you tried using another NTP server (public) to see if you have the same behavior?

I don't recall that I had this issue with my NTP server. Since I haven't used it in a while, I need to create a setup again to verify this. :)

jhagberg · 2018-01-09T08:25:16Z

Hej
No different really. I have added a in the NTPClient::getTime()
if (timestamp!=28802)

What I read it should set the sync interval to 5 but here it prints out 60?

[NTP] NTP Server #0 set to: ntp.bahnhof.se.
[NTP] Polling interval set to: 1800 seconds.
[NTP] Requesting time from: ntp.bahnhof.se.
[NTP] timestamp: 28802
[NTP] Error.
NTP server not reachable.
[NTP] Time synchronization started.
[NTP] Polling interval set to: 60 seconds.
.pm open,type:2 0
[NTP] Requesting time from: ntp.bahnhof.se.
[NTP] timestamp: 1515485989
[NTP] First synchronization: 2018-01-09T09:19:49.
Got NTP time: 1970-01-01T08:01:02 last sync 2018-01-09T09:19:49
[NTP] Time successfully synchronized to: 2018-01-09T09:19:49.

stelgenhof · 2018-01-09T08:42:29Z

Not sure I follow what your are doing. However, let me try to replicate on my own setup.

jhagberg · 2018-01-09T08:47:50Z

Hej

I did this changed two lines.
So the first call to sntp_get_current_timestamp returns a none synced timestamp. I read elsewhere that sntp can be a bit slow with the initial sync.

time_t NTPClient::getTime() {
  if (!WiFi.isConnected()) {
    DEBUGLOG("[NTP] Error. WiFi not connected.\n");
    return 0;
  }

  DEBUGLOG("[NTP] Requesting time from: %s.\n", sntp_getservername(0));
  uint32_t timestamp = sntp_get_current_timestamp();
  **DEBUGLOG("[NTP]  timestamp: %d \n", timestamp);**

  **if (timestamp!=28802) {**
    setSyncInterval(NTP.getPollingInterval()); // Regular polling interval
    timestamp += utc_offset;                   // Adjust time with UTC Offset

stelgenhof · 2018-01-09T09:22:18Z

I used my own setup (ESP8266 chip) and get the following output after initial start:

Connecting to WiFi network: XXXXX
.....Got IP: 192.168.1.188
NTP server not reachable.
.Got NTP time: 2018-01-09T18:17:27
Current time: 2018-01-09T18:17:27 - First synchronized at: 2018-01-09T18:17:27.
Current time: 2018-01-09T18:17:32 - First synchronized at: 2018-01-09T18:17:27.
Current time: 2018-01-09T18:17:37 - First synchronized at: 2018-01-09T18:17:27.
Current time: 2018-01-09T18:17:42 - First synchronized at: 2018-01-09T18:17:27.
Current time: 2018-01-09T18:17:47 - First synchronized at: 2018-01-09T18:17:27.
Current time: 2018-01-09T18:17:52 - First synchronized at: 2018-01-09T18:17:27.

Using the standard example with this library. I tried also with my own private NTP server and a public one, however same results.

It looks indeed that on your side the NTP synchronization doesn't take place immediately, although the connection has been established. That would explain the date of '1970-01-01....', as the internal time variable has not been changed yet.

Not sure what I can do to further help you. Could you maybe try another ESP8266 device? Just to rule that out...

jhagberg · 2018-01-09T09:37:24Z

Hej

What HW are you using?
This is my Adafruit HUZZAH esp8266
Same error.

MDNS responder started
HTTP server started
Got IP: 192.168.1.43
[NTP] NTP Server #0 set to: 192.168.1.1.
[NTP] Polling interval set to: 1800 seconds.
[NTP] Requesting time from: 192.168.1.1.
[NTP]  timestamp: 28800 
[NTP] First synchronization: 1970-01-01T09:00:00.
Got NTP time: 1970-01-01T00:00:23 last sync 1970-01-01T09:00:00
[NTP] Time successfully synchronized to: 1970-01-01T09:00:00.
[NTP] Time synchronization started.
[NTP] Polling interval set to: 60 seconds.

stelgenhof · 2018-01-09T10:52:14Z

I have various ESP8266 boards (Wemos D1, Adafruit Huzzah ESP8266, NodeMCU, etc.). All work fine for me.

jhagberg · 2018-01-09T11:17:45Z

I am running the latest ESP 2.4.0 release and Arduino 1.8.5.
Using sntp it is slow to sync sometimes a bit faster. Using the NTPclient example from the esp library gives me instant sync.

stelgenhof · 2018-01-09T11:24:22Z

It is correct that the SNTP protocol has less accuracy and reliability. The ESP library encompasses an NTP implementation, which may explain the faster sync. (See also: https://www.meinbergglobal.com/english/faq/faq_37.htm)

In most cases SNTP is sufficient. If you really need higher accuracy and reliability, then NTP is recommended over SNTP.

stelgenhof · 2018-01-09T11:54:32Z

For completeness, I tried another board (NodeMCU v3) with the same code. I get the same output:

...............Got IP: 192.168.1.189
NTP server not reachable.
.Got NTP time: 2018-01-09T20:51:48
Current time: 2018-01-09T20:51:48 - First synchronized at: 2018-01-09T20:51:48.
Current time: 2018-01-09T20:51:53 - First synchronized at: 2018-01-09T20:51:48.
Current time: 2018-01-09T20:51:58 - First synchronized at: 2018-01-09T20:51:48.
Current time: 2018-01-09T20:52:03 - First synchronized at: 2018-01-09T20:51:48.
Current time: 2018-01-09T20:52:08 - First synchronized at: 2018-01-09T20:51:48.

Not sure how I can further be of assistance, as I am not able to replicate the issue you are experiencing.

jhagberg · 2018-01-09T18:01:13Z

What version of ESP8266 lib/tools are you using?
https://github.com/esp8266/Arduino

stelgenhof · 2018-01-09T23:49:31Z

I was actually using 2.3.0 of the ESP8266 framework (hadn't noticed it already moved to 2.4.0). After upgrading, I can also confirm the same behaviour.

Something must have been changed in 2.4.0 that causes this. Need to do some investigation...

jhagberg · 2018-01-10T07:49:31Z

Thanks!
Yes they have changed the whole implementation from lwip1 to lwip2 and using Newlib from
https://sourceware.org/newlib/libc.html#Timefns

So actually this lib is no longer needed or needs to be rewritten. You can follow the discussion here esp8266/Arduino#4122
and
esp8266/Arduino#1679

I did not manage to debug lwip since I was using lwip2 :)

stelgenhof · 2018-01-10T07:53:02Z

After doing some investigation, it indeed seems the implementation in 2.4.0 makes this library to be redundant :( Not sure if I will rewrite it or discontinue...

jhagberg · 2018-01-10T08:52:25Z

Yes I would like to use TimeAlarms that is dependent on TimeLib but if we do not actually need the Timelib I wonder how I easily can create TimeAlarms.

I updated my sketch using this in the setup

 configTime(0, 0, "192.168.1.1","192.168.1.219", "0.se.pool.ntp.org");
  setenv("TZ", "CET-1CEST,M3.5.0/2,M10.5.0/3", 3);
  tzset();
  
  while (WiFi.status() != WL_CONNECTED) {
    delay(500);
    Serial.print(".");
  }
  setSyncInterval(1800);
  setSyncProvider(getTim);
  Serial.println(getTimeDate(now()));

Adding this function

time_t getTim() {
  uint32_t timestamp = sntp_get_current_timestamp();
  return timestamp;
}

It updates the time direct...

stelgenhof · 2018-01-10T08:59:51Z

Sorry, I'm not familiar with these Timelib and TimeAlarms libraries.

jhagberg · 2018-01-10T09:12:15Z

Its the same as you are using. :)

NTPClient/src/NTPClient.h

Line 17 in 8bd5ebb

#include <TimeLib.h>

TimeAlarms need the TimeLib to work.

stelgenhof · 2018-01-10T09:14:10Z

Sorry yes, you used small caps so I thought it was a different library. TimeAlarms I'm not familiar with.

Your example looks indeed nice and simple, making my library totally redundant, haha.

jhagberg · 2018-01-10T09:30:44Z

Yes and DST works directly without any extra lib or so.
And sorry for misspelling and creating confusion. And thanks for your help here!

stelgenhof · 2018-01-10T11:12:02Z

You too for pointing this out. Maybe it's time to retire this library :( (Which is good thing, because there were already many NTP libraries and now the missing features I was looking for, are incorporated in ESP8266).

stelgenhof · 2018-01-11T00:07:24Z

Interestingly I get a similar output when using the NTP-TZ-DST.ino example of ESP 2.4.0:

localtime:isdst=0:yday=0:wday=4:year=70:mon=0:mday=1:hour=8:min=0:sec=2
gmtime   :isdst=0:yday=0:wday=4:year=70:mon=0:mday=1:hour=8:min=0:sec=2

clock:20/753908000ns millis:20753 micros:20753928 gtod:2/36255us time:28802
 ctime:(UTC+540mn)Thu Jan  1 08:00:02 1970
------------------ settimeofday() was called ------------------

localtime:isdst=0:yday=10:wday=4:year=118:mon=0:mday=11:hour=9:min=4:sec=18
gmtime   :isdst=0:yday=10:wday=4:year=118:mon=0:mday=11:hour=9:min=4:sec=18

clock:21/266384000ns millis:21266 micros:21266404 gtod:1515629059/142986us time:1515661458

Also displays initially the time of 01/01/1970 (ctime) :)

jhagberg · 2018-01-11T07:29:31Z

Hej

Yes I have also noticed that but for me it gets sync almost direct and I have added a wait for wifi before printing that helps get the initial sync.

stelgenhof · 2018-01-11T08:12:15Z

True. Well the ESP2.4.0 library contains the perfect features for time synchronization, so I've decided to retire this library. No need to keep it maintained now anylonger :)

peterakroon · 2018-03-14T10:54:05Z

I can confirm that the problems described in the first post of this issue:

don't occur with the SEP 2.3.0 Core Library.
does occur in the 2.4.0 and 2,4,1 Core Library.

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

First NTP sync is wrong #5

First NTP sync is wrong #5

jhagberg commented Jan 8, 2018

stelgenhof commented Jan 8, 2018 •

edited

Loading

jhagberg commented Jan 8, 2018

jhagberg commented Jan 8, 2018

jhagberg commented Jan 8, 2018

jhagberg commented Jan 8, 2018

stelgenhof commented Jan 9, 2018

jhagberg commented Jan 9, 2018

stelgenhof commented Jan 9, 2018

jhagberg commented Jan 9, 2018

stelgenhof commented Jan 9, 2018

jhagberg commented Jan 9, 2018

stelgenhof commented Jan 9, 2018

jhagberg commented Jan 9, 2018

stelgenhof commented Jan 9, 2018

stelgenhof commented Jan 9, 2018

jhagberg commented Jan 9, 2018 •

edited

Loading

stelgenhof commented Jan 9, 2018

jhagberg commented Jan 10, 2018

stelgenhof commented Jan 10, 2018

jhagberg commented Jan 10, 2018 •

edited

Loading

stelgenhof commented Jan 10, 2018

jhagberg commented Jan 10, 2018 •

edited

Loading

stelgenhof commented Jan 10, 2018 •

edited

Loading

jhagberg commented Jan 10, 2018 •

edited

Loading

stelgenhof commented Jan 10, 2018

stelgenhof commented Jan 11, 2018

jhagberg commented Jan 11, 2018

stelgenhof commented Jan 11, 2018

peterakroon commented Mar 14, 2018

First NTP sync is wrong #5

First NTP sync is wrong #5

Comments

jhagberg commented Jan 8, 2018

stelgenhof commented Jan 8, 2018 • edited Loading

jhagberg commented Jan 8, 2018

jhagberg commented Jan 8, 2018

jhagberg commented Jan 8, 2018

jhagberg commented Jan 8, 2018

stelgenhof commented Jan 9, 2018

jhagberg commented Jan 9, 2018

stelgenhof commented Jan 9, 2018

jhagberg commented Jan 9, 2018

stelgenhof commented Jan 9, 2018

jhagberg commented Jan 9, 2018

stelgenhof commented Jan 9, 2018

jhagberg commented Jan 9, 2018

stelgenhof commented Jan 9, 2018

stelgenhof commented Jan 9, 2018

jhagberg commented Jan 9, 2018 • edited Loading

stelgenhof commented Jan 9, 2018

jhagberg commented Jan 10, 2018

stelgenhof commented Jan 10, 2018

jhagberg commented Jan 10, 2018 • edited Loading

stelgenhof commented Jan 10, 2018

jhagberg commented Jan 10, 2018 • edited Loading

stelgenhof commented Jan 10, 2018 • edited Loading

jhagberg commented Jan 10, 2018 • edited Loading

stelgenhof commented Jan 10, 2018

stelgenhof commented Jan 11, 2018

jhagberg commented Jan 11, 2018

stelgenhof commented Jan 11, 2018

peterakroon commented Mar 14, 2018

stelgenhof commented Jan 8, 2018 •

edited

Loading

jhagberg commented Jan 9, 2018 •

edited

Loading

jhagberg commented Jan 10, 2018 •

edited

Loading

jhagberg commented Jan 10, 2018 •

edited

Loading

stelgenhof commented Jan 10, 2018 •

edited

Loading

jhagberg commented Jan 10, 2018 •

edited

Loading