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

BugerDread · 2019-01-30T14:24:59Z

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

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

chinswain · 2019-01-30T14:35:30Z

Related to #21?

BugerDread · 2019-01-30T14:51:24Z

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 · 2019-01-30T15:19:49Z

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 · 2019-01-30T19:08:40Z

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

BugerDread · 2019-01-30T19:13:30Z

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 · 2019-03-04T07:51:11Z

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 · 2019-03-05T08:04:25Z

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 · 2019-03-05T09:51:30Z

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

eztime-added-condition-src.tar.gz

BugerDread · 2019-03-07T11:47:27Z

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

Added condition checking that data we got from NTP server are valid. ropg#25

Added check that data received from NTP server makes sense. ropg#25

dobryj · 2019-03-25T09:53:37Z

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 · 2019-03-25T09:57:51Z

Yes, I plan to release a new version today. Rop

Fix for issue #25

ropg · 2019-03-25T18:32:12Z

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

BugerDread added a commit to BugerDread/ezTime that referenced this issue Mar 8, 2019

Fix for issue ropg#25

3401a97

Added condition checking that data we got from NTP server are valid. ropg#25

BugerDread added a commit to BugerDread/ezTime that referenced this issue Mar 8, 2019

Fix for issue ropg#25

17ed421

Added check that data received from NTP server makes sense. ropg#25

ropg added a commit that referenced this issue Mar 25, 2019

Merge pull request #33 from BugerDread/master

de16d0b

Fix for issue #25

ropg closed this as completed Mar 25, 2019

jnew123 mentioned this issue Dec 5, 2019

NTPClient object sets time to 2036-02-07 arduino-libraries/NTPClient#84

Open

morres83 mentioned this issue Mar 25, 2020

Clock is set to 2036-02-07 sometimes sstaub/NTP#9

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

BugerDread commented Jan 30, 2019

chinswain commented Jan 30, 2019

BugerDread commented Jan 30, 2019

ropg commented Jan 30, 2019

BugerDread commented Jan 30, 2019

BugerDread commented Jan 30, 2019

BugerDread commented Mar 4, 2019

BugerDread commented Mar 5, 2019 •

edited

Loading

BugerDread commented Mar 5, 2019

BugerDread commented Mar 7, 2019

dobryj commented Mar 25, 2019

ropg commented Mar 25, 2019 via email

ropg commented Mar 25, 2019 •

edited

Loading

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

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

Comments

BugerDread commented Jan 30, 2019

chinswain commented Jan 30, 2019

BugerDread commented Jan 30, 2019

ropg commented Jan 30, 2019

BugerDread commented Jan 30, 2019

BugerDread commented Jan 30, 2019

BugerDread commented Mar 4, 2019

BugerDread commented Mar 5, 2019 • edited Loading

BugerDread commented Mar 5, 2019

BugerDread commented Mar 7, 2019

dobryj commented Mar 25, 2019

ropg commented Mar 25, 2019 via email

ropg commented Mar 25, 2019 • edited Loading

BugerDread commented Mar 5, 2019 •

edited

Loading

ropg commented Mar 25, 2019 •

edited

Loading