Clock is set to 2036-02-07 about 7:30AM sometimes by sync

BugerDread commented 5 years ago

Hallo,

I made simple NTP clock using your ezTime library (https://github.com/BugerDread/esp8266-ezTIME-wifi-clock), but I noticed that it sometimes shows wrong time / date randomly. The wrong time / date is always 2036-02-07 about 7:30 (timezone Europe/Prague). So I made a simple sketch sending actual time and ezTime debug data to serial port which I captured to file.

Here is the testing sketch:

#include <ESP8266WiFi.h>
#include <ezTime.h>

// configuration
static const char ourtimezone[] PROGMEM = "Europe/Prague";  //official timezone names https://en.wikipedia.org/wiki/List_of_tz_database_time_zones
static const char dot[] PROGMEM = ".";
#define wifi_ssid             "MikroTik-043865"                //ssid of your WiFi
#define wifi_pwd              "badik2323"                    //password for your WiFi

Timezone myTZ;

int i = 10;
String buf;

void setup() {
  Serial.begin(115200);
  Serial.println(F("\r\n* * * ESP BOOT * * *"));
  setDebug(INFO);

  Serial.print(F("# Connecting to WiFi"));
  WiFi.persistent(false);   //dont want to save wifi credentials into flash - it cause just fash wear every power-on, see https://arduino-esp8266.readthedocs.io/en/latest/esp8266wifi/generic-class.html#persistent
  WiFi.mode(WIFI_STA);      //we want just Wifi client (station), no AP
  WiFi.begin(wifi_ssid, wifi_pwd);
  while (WiFi.status() != WL_CONNECTED) {
    delay(500);
    Serial.print(FPSTR(dot));
  }

  Serial.println(F("\r\n# WiFi connected, waiting for sync"));
  waitForSync();
  Serial.println(F("# Setting timezone"));
  if (myTZ.setLocation(FPSTR(ourtimezone))) {
    Serial.println(F("# Timezone lookup OK"));
  } else {
    Serial.println(F("# Timezone lookup error!"));
  }

  Serial.println(F("# Setup finished"));
}

void loop() {
  events();

  if (secondChanged()) {
    buf = myTZ.dateTime("# Y-m-d H-i-s");
    if (++i >= 10) {
      Serial.print("\r\n" + buf);
      i = 0;
    } else {
      Serial.print(FPSTR(dot));
    }
  }

}

Here is the (truncated) log:

# 2019-01-27 16-32-59.........
# 2019-01-27 16-33-09.........
# 2019-01-27 16-33-19.........
# 2019-01-27 16-33-29.........
# 2019-01-27 16-33-39...Querying pool.ntp.org ... success (round trip 55 ms)
Received time: Sunday, 27-Jan-19 15:33:43.071 UTC (internal clock was 15 ms fast)
......
# 2019-01-27 16-33-49.........
# 2019-01-27 16-33-59.........
# 2019-01-27 16-34-09.........
# 2019-01-27 16-34-19.........
# 2019-01-27 16-34-29.........
# 2019-01-27 16-34-39.........
# 2019-01-27 16-34-49.........
# 2019-01-27 16-34-59.........
# 2019-01-27 16-35-09.........
# 2019-01-27 16-35-19.........
# 2019-01-27 16-35-29.........
# 2019-01-27 16-35-39.........
# 2019-01-27 16-35-49.........
# 2019-01-27 16-35-59.........
# 2019-01-27 16-36-09.........
# 2019-01-27 16-36-19.........
# 2019-01-27 16-36-29.........
# 2019-01-27 16-36-39.........
# 2019-01-27 16-36-49.........
# 2019-01-27 16-36-59.........
# 2019-01-27 16-37-09.........
# 2019-01-27 16-37-19.........
# 2019-01-27 16-37-29.........
# 2019-01-27 16-37-39.........
# 2019-01-27 16-37-49.........
# 2019-01-27 16-37-59.........
# 2019-01-27 16-38-09.........
# 2019-01-27 16-38-19.........
# 2019-01-27 16-38-29.........
# 2019-01-27 16-38-39.........
# 2019-01-27 16-38-49.........
# 2019-01-27 16-38-59.........
# 2019-01-27 16-39-09.........
# 2019-01-27 16-39-19.........
# 2019-01-27 16-39-29.........
# 2019-01-27 16-39-39.........
# 2019-01-27 16-39-49.........
# 2019-01-27 16-39-59.........
# 2019-01-27 16-40-09.........
# 2019-01-27 16-40-19.........
# 2019-01-27 16-40-29.........
# 2019-01-27 16-40-39.........
# 2019-01-27 16-40-49.........
# 2019-01-27 16-40-59.........
# 2019-01-27 16-41-09.........
# 2019-01-27 16-41-19.........
# 2019-01-27 16-41-29.........
# 2019-01-27 16-41-39.........
# 2019-01-27 16-41-49.........
# 2019-01-27 16-41-59.........
# 2019-01-27 16-42-09.........
# 2019-01-27 16-42-19.........
# 2019-01-27 16-42-29.........
# 2019-01-27 16-42-39.........
# 2019-01-27 16-42-49.........
# 2019-01-27 16-42-59.........
# 2019-01-27 16-43-09.........
# 2019-01-27 16-43-19.........
# 2019-01-27 16-43-29.........
# 2019-01-27 16-43-39....Querying pool.ntp.org ... success (round trip 43 ms)
Received time: Thursday, 07-Feb-36 06:28:16.021 UTC (internal clock was 503760977 ms fast)
.....
# 2036-02-07 07-28-21.........
# 2036-02-07 07-28-31.........
# 2036-02-07 07-28-41.........
# 2036-02-07 07-28-51.........
# 2036-02-07 07-29-01.........
# 2036-02-07 07-29-11.........
# 2036-02-07 07-29-21.........
# 2036-02-07 07-29-31.........
# 2036-02-07 07-29-41.........
# 2036-02-07 07-29-51.........
# 2036-02-07 07-30-01.........
# 2036-02-07 07-30-11.........
# 2036-02-07 07-30-21.........
# 2036-02-07 07-30-31.........
# 2036-02-07 07-30-41.........
# 2036-02-07 07-30-51.........
# 2036-02-07 07-31-01.........
# 2036-02-07 07-31-11.........
# 2036-02-07 07-31-21.........
# 2036-02-07 07-31-31.........
# 2036-02-07 07-31-41.........
# 2036-02-07 07-31-51.........
# 2036-02-07 07-32-01.........
# 2036-02-07 07-32-11.........
# 2036-02-07 07-32-21.........
# 2036-02-07 07-32-31.........
# 2036-02-07 07-32-41.........
# 2036-02-07 07-32-51.........
# 2036-02-07 07-33-01.........
# 2036-02-07 07-33-11.........
# 2036-02-07 07-33-21.........
# 2036-02-07 07-33-31.........
# 2036-02-07 07-33-41.........
# 2036-02-07 07-33-51.........
# 2036-02-07 07-34-01.........
# 2036-02-07 07-34-11.........
# 2036-02-07 07-34-21.........
# 2036-02-07 07-34-31.........
# 2036-02-07 07-34-41.........
# 2036-02-07 07-34-51.........
# 2036-02-07 07-35-01.........
# 2036-02-07 07-35-11.........
# 2036-02-07 07-35-21.........
# 2036-02-07 07-35-31.........
# 2036-02-07 07-35-41.........
# 2036-02-07 07-35-51.........
# 2036-02-07 07-36-01.........
# 2036-02-07 07-36-11.........
# 2036-02-07 07-36-21.........
# 2036-02-07 07-36-31.........
# 2036-02-07 07-36-41.........
# 2036-02-07 07-36-51.........
# 2036-02-07 07-37-01.........
# 2036-02-07 07-37-11.........
# 2036-02-07 07-37-21.........
# 2036-02-07 07-37-31.........
# 2036-02-07 07-37-41.........
# 2036-02-07 07-37-51.........
# 2036-02-07 07-38-01.........
# 2036-02-07 07-38-11.....Querying pool.ntp.org ... success (round trip 19 ms)
Received time: Sunday, 27-Jan-19 15:53:43.109 UTC (internal clock was 503760912 ms slow)
....
# 2019-01-27 16-53-47.........
# 2019-01-27 16-53-57.........
# 2019-01-27 16-54-07.........
# 2019-01-27 16-54-17.........
# 2019-01-27 16-54-27.........

It occurs sometimes once / twice a day, randomly, it gets fixed after 10minutes as another sync is performed (as visible in the log above).

What can be source of the problem and how to avoid this?

Ggling around I found https://forum.arduino.cc/index.php?topic=92632.0 - maybe same or simmilar problem?

Ofcourse I can provide you with more info, just let me know...

chinswain commented 5 years ago

Related to #21?

BugerDread commented 5 years ago

Related to #21?

not sure, I dont think is related to lost WiFi signal (as the esp is in the same room as the AP) and always shifts me to 2036-02-07 about 7:30 when occurs.

ropg commented 5 years ago

Hmmm, interesting. Thanks for spending the time documenting. I think I only parse an NTP packet if it is valid, but clearly something is wrong there. I will have a look at that code as soon as I have some time. Worst case I can just reject that particular time as invalid so it would retry 5 seconds later, but I'd rather spend a bit more time to figure out what's going on.

BugerDread commented 5 years ago

Im happy to spend time to improve something what is worth, also when it helps others to avoid problems... Thank you

BugerDread commented 5 years ago

I found ezTime very usefull and want to use it in my home automation project. If you need something that can help you to investigate this, Im ready to help / test / etc...

BugerDread commented 5 years ago

Hi Ropg, I decided to try to fix this myslef, right now I added following into ezTime.cpp line 484 (release 0.7.9) and switched debuglevel to "debug" to be able to see the data received:

            //print out received for debug
            int i;
            debug(F("Received data:"));
            for (i = 0; i < NTP_PACKET_SIZE; i++) {
                if ((i % 4) == 0) {
                    debugln();
                    debug(String(i) + ": ");
                }
                debug(buffer[i], HEX);
                debug(F(", "));
            }
            debugln();

Now will wait until the issue occurs again and will inform you about the progress.

Im also thinking about to add condition into updateNTP function to check the "correction" and update the time only when correction < something_like_1_minute (or configurable) - to avoid stupid updates which shifts the time years ago or ahead.

BugerDread commented 5 years ago

First of all I have to say that there was a strong wind yesterday and my internet connection was unstable - because the log I captured yesterday is showing the problem occurred right after there was a problem with connection (in contrast with other logs I captured before, like that in first comment, not showing any problem with connection at all).

# 2019-03-04 18-35-00
# 2019-03-04 18-36-00
# 2019-03-04 18-37-00
Running event (#1) set for Monday, 04-Mar-2019 17:37:08 UTC
Querying pool.ntp.org ... ERROR: Timeout
Set event (#1) to trigger on: Monday, 04-Mar-2019 17:37:23 UTC
Running event (#1) set for Monday, 04-Mar-2019 17:37:23 UTC
Querying pool.ntp.org ... ERROR: Timeout
Set event (#1) to trigger on: Monday, 04-Mar-2019 17:37:32 UTC
Running event (#1) set for Monday, 04-Mar-2019 17:37:32 UTC
Querying pool.ntp.org ... success (round trip 40 ms)
Received data:
0: E4, 0, 9, EC, 
4: 0, 0, 0, 0, 
8: 0, 0, 0, 0, 
12: 52, 41, 54, 45, 
16: 0, 0, 0, 0, 
20: 0, 0, 0, 0, 
24: 0, 0, 0, 0, 
28: 0, 0, 0, 0, 
32: 0, 0, 0, 0, 
36: 0, 0, 0, 0, 
40: 0, 0, 0, 0, 
44: 0, 0, 0, 0, 
Received time: Thursday, 07-Feb-36 06:28:16.032 UTC (internal clock was 1681499275 ms fast)
Set event (#1) to trigger on: Thursday, 07-Feb-2036 06:38:16 UTC
# 2036-02-07 07-28-16
# 2036-02-07 07-29-00
# 2036-02-07 07-30-00
# 2036-02-07 07-31-00
# 2036-02-07 07-32-00
# 2036-02-07 07-33-00
# 2036-02-07 07-34-00
# 2036-02-07 07-35-00
# 2036-02-07 07-36-00
# 2036-02-07 07-37-00
# 2036-02-07 07-38-00
Running event (#1) set for Thursday, 07-Feb-2036 06:38:16 UTC
Querying pool.ntp.org ... success (round trip 70 ms)
Received data:
0: 24, 2, 9, E9, 
4: 0, 0, 0, 33, 
8: 0, 0, 8, 9C, 
12: C3, 71, 90, EE, 
16: E0, 27, E0, FA, 
20: D9, 38, E4, 3F, 
24: 0, 0, 0, 0, 
28: 0, 0, 0, 0, 
32: E0, 27, E3, 34, 
36: 24, FE, 3, 0, 
40: E0, 27, E3, 34, 
44: 25, 3, CD, 9A, 
Received time: Monday, 04-Mar-19 17:47:32.193 UTC (internal clock was 1681499188 ms slow)
Set event (#1) to trigger on: Monday, 04-Mar-2019 17:57:32 UTC
# 2019-03-04 18-47-32
# 2019-03-04 18-48-00

So the bad packet was in this case

0: E4, 0, 9, EC, 
4: 0, 0, 0, 0, 
8: 0, 0, 0, 0, 
12: 52, 41, 54, 45, 
16: 0, 0, 0, 0, 
20: 0, 0, 0, 0, 
24: 0, 0, 0, 0, 
28: 0, 0, 0, 0, 
32: 0, 0, 0, 0, 
36: 0, 0, 0, 0, 
40: 0, 0, 0, 0, 
44: 0, 0, 0, 0,

I read some docs about NTP namely: this by cisco and rfc4330

In that packet there is "stratum" byte (buffer[1]) = 0, there are no timestamps, and the "reference identifier" is "52, 41, 54, 45" means "RATE" in ascii.

They both say that reply with "stratum" = 0 (or anything else than 1..15) is not valid, more info about this is in the rfc4330 paragraph "8. The Kiss-o'-Death Packet"

So my plan is:

add a check that "stratum" byte is 1..15
add check that received timestamps makes sense sth like if (stratum >= 1) and (stratum <=15) and (TransmitTimestamp > ReceiveTimestamp) and (ReceiveTimestamp > ReferenceTimestamp) and (ReferenceTimestamp > 0) { //valid packet received }

BugerDread commented 5 years ago

First attempt to fix, compiled, logging running....

eztime-added-condition-src.tar.gz

BugerDread commented 5 years ago

^^^ seems to be running fine, so far not a single "2036-02-07 ...." occurrence

dobryj commented 5 years ago

I observe this bug too. ROPG: do do you have a plan to accept BurgerDreads pull request or fix it by another way? I thing that now is good time to have this fix for next library release forced by bugs #38 & #41.

ropg commented 5 years ago

Yes, I plan to release a new version today.

Rop

ropg commented 5 years ago

Supposedly fixed (means I haven't tested because I do not see this condition) by merging pull request (thanks Bugerdread)

ropg / ezTime

Clock is set to 2036-02-07 about 7:30AM sometimes by sync #25