NTPClient icon indicating copy to clipboard operation
NTPClient copied to clipboard

First NTP sync is wrong

Open jhagberg opened this issue 7 years ago • 29 comments

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

jhagberg avatar Jan 08 '18 14:01 jhagberg

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

stelgenhof avatar Jan 08 '18 14:01 stelgenhof

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 avatar Jan 08 '18 15:01 jhagberg

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

jhagberg avatar Jan 08 '18 15:01 jhagberg

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

jhagberg avatar Jan 08 '18 15:01 jhagberg

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.

jhagberg avatar Jan 08 '18 21:01 jhagberg

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. :)

stelgenhof avatar Jan 09 '18 00:01 stelgenhof

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.

jhagberg avatar Jan 09 '18 08:01 jhagberg

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

stelgenhof avatar Jan 09 '18 08:01 stelgenhof

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

jhagberg avatar Jan 09 '18 08:01 jhagberg

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...

stelgenhof avatar Jan 09 '18 09:01 stelgenhof

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.

jhagberg avatar Jan 09 '18 09:01 jhagberg

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

stelgenhof avatar Jan 09 '18 10:01 stelgenhof

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.

jhagberg avatar Jan 09 '18 11:01 jhagberg

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 avatar Jan 09 '18 11:01 stelgenhof

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.

stelgenhof avatar Jan 09 '18 11:01 stelgenhof

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

jhagberg avatar Jan 09 '18 18:01 jhagberg

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...

stelgenhof avatar Jan 09 '18 23:01 stelgenhof

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 https://github.com/esp8266/Arduino/issues/4122 and https://github.com/esp8266/Arduino/issues/1679

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

jhagberg avatar Jan 10 '18 07:01 jhagberg

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...

stelgenhof avatar Jan 10 '18 07:01 stelgenhof

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...

jhagberg avatar Jan 10 '18 08:01 jhagberg

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

stelgenhof avatar Jan 10 '18 08:01 stelgenhof

Its the same as you are using. :) https://github.com/stelgenhof/NTPClient/blob/8bd5ebb88762b0a4e3c4179ba2167a20fde975fb/src/NTPClient.h#L17

TimeAlarms need the TimeLib to work.

jhagberg avatar Jan 10 '18 09:01 jhagberg

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.

stelgenhof avatar Jan 10 '18 09:01 stelgenhof

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

jhagberg avatar Jan 10 '18 09:01 jhagberg

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 avatar Jan 10 '18 11:01 stelgenhof

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) :)

stelgenhof avatar Jan 11 '18 00:01 stelgenhof

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.

jhagberg avatar Jan 11 '18 07:01 jhagberg

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 :)

stelgenhof avatar Jan 11 '18 08:01 stelgenhof

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.

peterakroon avatar Mar 14 '18 10:03 peterakroon