Incorrect time on WiFi Loss

[chinswain]

I've had a few false triggers on setEvent that appear to be due to datetime being incorrect immediately after a WiFi loss and reconnect. On the next update it's corrected (if WiFi is ok) but all of the days event's are triggered.

I'll write a simplified example (with DEBUG level) and post\test tomorrow and leaving it running. I have a timer doing the following every 10 minutes:

 Serial.print("Time: "); Serial.println(myTZ.dateTime());

Output Example 1:

Querying pool.ntp.org ... success (round trip 64 ms)
Received time: Wednesday, 02-Jan-19 18:30:25.098 UTC (internal clock was 33 ms fast)

[0] Heartbeat timeout <-- WiFi Loss and Reconnect
[148] Ready (ping: 31ms).

**Time: Thursday, 21-Feb-2019 10:22:54 GMT**

Querying pool.ntp.org ... success (round trip 55 ms)
Received time: Wednesday, 02-Jan-19 18:31:42.317 UTC (internal clock was 4294973 ms fast)

Time: Wednesday, 02-Jan-2019 18:37:39 GMT

Querying pool.ntp.org ... success (round trip 906 ms)
Received time: Wednesday, 02-Jan-19 18:41:42.331 UTC (internal clock was 425 ms fast)

Output Example 2:

Time: Wednesday, 02-Jan-2019 23:25:20 UTC

[0] Heartbeat timeout <-- WiFi Loss and Reconnect
[148] Ready (ping: 35ms).

**Time: Thursday, 21-Feb-2019 15:16:33 UTC**

Querying pool.ntp.org ... success (round trip 44 ms)
Received time: Wednesday, 02-Jan-19 23:25:21.408 UTC (internal clock was 4294953 ms fast)

Time: Wednesday, 02-Jan-2019 23:25:21 UTC

[chinswain]

Example Sketch:

#include <ezTime.h>
#include <WiFi.h>

unsigned long previousMillis = 0;

Timezone myTZ;

void setup() {
  
  Serial.begin(115200);
  WiFi.begin("xxxxx", "xxxxx");
  while (WiFi.status() != WL_CONNECTED) {
    delay(500);
    Serial.print(".");
  }

  setDebug(DEBUG);
  waitForSync();
  myTZ.setLocation(F("gb"));
  myTZ.setDefault();
}

void loop() {

  unsigned long currentMillis = millis();
  events();
  if (currentMillis - previousMillis >= 1000) {
    previousMillis = currentMillis;
    Serial.println("Time: " + myTZ.dateTime());
  }
}

ezTime debug level set to DEBUG
Waiting for time sync
Querying pool.ntp.org ... success (round trip 17 ms)
Received time: Sunday, 06-Jan-19 19:08:57.553 UTC
Set event (#1) to trigger on: Sunday, 06-Jan-2019 19:18:57 UTC
Time is in sync
Timezone lookup for: gb ... (round-trip 54 ms)  success.
  Olsen: Europe/London
  Posix: GMT0BST,M3.5.0/1,M10.5.0
Default timezone set to Europe/London  GMT0BST,M3.5.0/1,M10.5.0
Time: Sunday, 06-Jan-2019 19:08:57 GMT
Time: Sunday, 06-Jan-2019 19:08:58 GMT
Time: Sunday, 06-Jan-2019 19:08:59 GMT
.....
Time: Sunday, 06-Jan-2019 20:18:53 GMT
Time: Sunday, 06-Jan-2019 20:18:54 GMT
Time: Sunday, 06-Jan-2019 20:18:55 GMT
Running event (#1) set for Sunday, 06-Jan-2019 20:18:56 UTC
Querying pool.ntp.org ... success (round trip 55 ms)
Received time: Sunday, 06-Jan-19 20:18:55.985 UTC (internal clock was 71 ms slow)
Set event (#1) to trigger on: Sunday, 06-Jan-2019 20:28:55 UTC
Time: Sunday, 06-Jan-2019 20:18:56 GMT
Time: Sunday, 06-Jan-2019 20:18:57 GMT
Time: Sunday, 06-Jan-2019 20:18:58 GMT

All good until the clock suddenly jumps from 20:19:00 to a future time, seems to then trigger an NTP update (And all events):

Time: Sunday, 06-Jan-2019 20:18:59 GMT
Time: Sunday, 06-Jan-2019 20:19:00 GMT
Running event (#1) set for Sunday, 06-Jan-2019 20:28:55 UTC
Querying pool.ntp.org ... success (round trip 19 ms)
Received time: Sunday, 06-Jan-19 20:19:01.366 UTC (internal clock was 4294951 ms fast)
Set event (#1) to trigger on: Sunday, 06-Jan-2019 20:29:01 UTC
Time: Sunday, 06-Jan-2019 20:19:01 GMT
Time: Sunday, 06-Jan-2019 20:19:02 GMT
Time: Sunday, 06-Jan-2019 20:19:03 GMT