First NTP sync is wrong

[jhagberg]

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]

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]

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]

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

[jhagberg]

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

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

[stelgenhof]

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]

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]

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

[jhagberg]

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]

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]

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]

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

[jhagberg]

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]

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]

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.