Espeasy: NTP timeadjustments gives restarts

[2bontb]

Summarize of the problem/feature request

On a number of my sensors I see webserver restarts, after an NTP update showing high offset:

10.2.1.112.1-Aug 31 16:31:08 10.2.1.112 SensorSproeien EspEasy: WD : Uptime 2749 ConnectFailures 0 FreeMem 19216 WiFiStatus 3
10.2.1.112.1-Aug 31 16:31:30 10.2.1.112 SensorSproeien EspEasy: WIFI : Static IP: 10.2.1.112 (SensorSproeien-112) GW: 10.2.1.138 SN: 255.255.255.0 duration: 184 ms
10.2.1.112.1-Aug 31 16:31:30 10.2.1.112 SensorSproeien EspEasy: NTP : NTP replied: delay 190 mSec Accuracy increased by 0.942 seconds
10.2.1.112.1-Aug 31 16:31:30 10.2.1.112 SensorSproeien EspEasy: Time adjusted by -1567261886073.30 msec. Wander: -435350523.91 msec/second
10.2.1.112.1-Aug 31 16:31:30 10.2.1.112 SensorSproeien EspEasy: Current Time Zone: DST time start: 2019-03-31 02:00:00 offset: 120 minSTD time start: 2019-10-27 03:00:00 offset: 60 min
10.2.1.112.1:Aug 31 16:31:30 10.2.1.112 SensorSproeien EspEasy: Webserver: start
10.2.1.112.1-Aug 31 16:31:30 10.2.1.112 SensorSproeien EspEasy: firstLoopConnectionsEstablished
10.2.1.112.1-Aug 31 16:31:57 10.2.1.112 SensorSproeien EspEasy: WD : Uptime 1 ConnectFailures 0 FreeMem 21664 WiFiStatus 3

Expected behavior

I do not expect restarts when there is NTP adjustment.

Steps to reproduce

It just happens on a number of sensors running ESP_Easy_mega-20190827_normal_ESP8266_4M.bin, but also on 0823 version.

System configuration

Wemos mini, running Mega 0830; As devices I have only 4 x Switch input + System info.
Controler is FHEM. Syslog and NTP enabled.

[TD-er]

I notice you're using a static IP for the NTP updates.
Could it be this host is not always available, or taking a long time to reply?
I see duration 190 msec, so it could also be > 2 sec when the host is not replying.

What is the restart reason? Software Watchdog?

[2bontb]

Here is a recent failure that caused a restart (Mind this one is running Mega 08-23 with itho plugin added to normal set)

Boot: | Manual reboot (122)
Reset Reason: | Exception
Last Task: | Const Interval timer, id: 3

Sep 1 12:43:22 10.2.1.87 ITHOremote EspEasy: RF signal received
Sep 1 12:43:22 10.2.1.87 ITHOremote EspEasy: Device-ID:6f:ae:5:54:11:d6:14:90 IGNORED
Sep 1 12:43:22 10.2.1.87 ITHOremote EspEasy: UPDATE by PLUGIN_READ
Sep 1 12:43:22 10.2.1.87 ITHOremote EspEasy: State: 1.00
Sep 1 12:43:22 10.2.1.87 ITHOremote EspEasy: Timer: 0.00
Sep 1 12:43:22 10.2.1.87 ITHOremote EspEasy: LastIDindex: 0.00
Sep 1 12:43:22 10.2.1.87 ITHOremote EspEasy: EVENT: ITHOremote#State=1.00
Sep 1 12:43:22 10.2.1.87 ITHOremote EspEasy: EVENT: ITHOremote#Timer=0.00
Sep 1 12:43:22 10.2.1.87 ITHOremote EspEasy: EVENT: ITHOremote#LastIDindex=0.00
Sep 1 12:43:32 10.2.1.87 ITHOremote EspEasy: NTP : NTP replied: delay 10 mSec Accuracy increased by 0.114 seconds
Sep 1 12:43:32 10.2.1.87 ITHOremote EspEasy: Time adjusted by -1567334607653.50 msec. Wander: -435370724.35 msec/second
Sep 1 12:43:32 10.2.1.87 ITHOremote EspEasy: Current Time Zone: DST time start: 2019-03-31 02:00:00 offset: 60 minSTD time start: 2019-10-27 03:00:00 offset: 0 min
Sep 1 12:43:32 10.2.1.87 ITHOremote EspEasy: EVENT: Time#Initialized
Sep 1 12:43:32 10.2.1.87 ITHOremote EspEasy: EVENT: WiFi#Connected
Sep 1 12:43:32 10.2.1.87 ITHOremote EspEasy: Webserver: start
Sep 1 12:43:32 10.2.1.87 ITHOremote EspEasy: firstLoopConnectionsEstablished
Sep 1 12:43:32 10.2.1.87 ITHOremote EspEasy: EVENT: Clock#Time=Sun,11:43
Sep 1 12:43:32 10.2.1.87 ITHOremote EspEasy: RF signal received

I did set the NTP to my router that can also supply NTP, just for a try. I will set it back to the normal case using nl.pool.ntp.org, and I can share the following crash also.

[2bontb]

I checked another sensor that restarted. This had:
Boot: | Manual reboot (6)
Reset Reason: | Hardware Watchdog
Last Task: | Const Interval timer, id: 1

Another one:
Boot: | Manual reboot (22)
Reset Reason: | Hardware Watchdog
Last Task: | Const Interval timer, id: 1

And another one:
Boot: | Manual reboot (6)
Reset Reason: | Hardware Watchdog
Last Task: | Const Interval timer, id: 1

[Domosapiens]

@2bontb A very interesting catch !
NTP adjustment as cause for reboots would be very plausible for me.

Caused by this NTP modification, in the same time-frame as the async. WiFi modification?
https://github.com/letscontrolit/ESPEasy/commit/3a26ebf7b1108470beef3c8e93a61d4012777746

mega-20180326,
[wifi] Event based connect/reconnect
[NTP] Speedup NTP again with async WiFi

That would explain the reboot-free experience with end2017/begin2018 releases and also this remark: https://github.com/letscontrolit/ESPEasy/issues/2590#issuecomment-526878744

still running this (a bit older but great) ESP Easy release:
GIT version: mega-20180311

I will log and search for similar events

[Domosapiens]

Yes !!, I can confirm: ... but is it the Cause or an Effect ???

Sun Sep 01 21:35:02 2019;192.168.1.100; <13>MUC30_Bcontr EspEasy: WD   : Uptime 1643 ConnectFailures 0 FreeMem 21112 WiFiStatus 3
...... Uptime 1643 ... then some not relevant lines....and then ...
Sun Sep 01 21:35:49 2019;192.168.1.100; <13>MUC30_Bcontr EspEasy: EVENT: T1Q#T_1Q=21.37
Sun Sep 01 21:35:49 2019;192.168.1.100; <13>MUC30_Bcontr EspEasy:  Domoticz: Sensortype: 1 idx: 227 values: 21.4
........ mind the time gap ! ......reboot in between
Sun Sep 01 21:36:08 2019;192.168.1.100; <13>MUC30_Bcontr EspEasy: Webserver: start
Sun Sep 01 21:36:08 2019;192.168.1.100; <13>MUC30_Bcontr EspEasy: NTP  : NTP replied: delay 11 mSec Accuracy increased by 0.155 seconds
Sun Sep 01 21:36:08 2019;192.168.1.100; <13>MUC30_Bcontr EspEasy: Time adjusted by -1567366558435.41 msec. Wander: -435379599.57 msec/second
Sun Sep 01 21:36:08 2019;192.168.1.100; <13>MUC30_Bcontr EspEasy: Current Time Zone:  DST time start: 2019-03-31 02:00:00 offset: 120 minSTD time start: 2019-10-27 03:00:00 offset: 60 min
Sun Sep 01 21:36:08 2019;192.168.1.100; <13>MUC30_Bcontr EspEasy: EVENT: Time#Initialized
Sun Sep 01 21:36:08 2019;192.168.1.100; <13>MUC30_Bcontr EspEasy: EVENT: Clock#Time=Sun,21:36
..... back to standard operation ...
Sun Sep 01 21:36:10 2019;192.168.1.100; <13>MUC30_Bcontr EspEasy: DS   : Temperature: 51.94 (28-aa-5-50-50-14-1-75)
..........
Sun Sep 01 21:36:35 2019;192.168.1.100; <13>MUC30_Bcontr EspEasy: WD   : Uptime 1 ConnectFailures 0 FreeMem 21384 WiFiStatus 3

(OT: Why the minus sign in the time adjustment of -1567366558435.41 msec ??)

But, .... I think it's an Effect and not the Cause ...
The NTP adjustment comes after the watchdog reboot.

[TD-er]

The NTP adjustment comes after the watchdog reboot.

That's perfectly normal.
Just to make some analogy: The reboot also comes after the WDT reset. :)

Right now it is just a bit too late to think again why the offset is negative here. (might be just the other way around and thus a 'bug', but like I said past midnight here)
At least the 1.567 billion as a value is the Unix time in seconds, so that's about right.

[Domosapiens]

@TD-er sorry, false alarm .... desperately searching for the dog

[TD-er]

[2bontb]

Is there anything I can enable on logging to syslog that can help to catch the reasons for watchdog?
e.g. wifi loss or something else. Currently I do not see WiFi problems during the restart events in my syslog, but.... My syslog level I did set to debug level, and ofcourse if I loose WiFi syslog may not get anything anymore.

[TD-er]

It is logged as one of the first log items, so I don't think it will be sent to syslog (no wifi yet)
I think it will be useful to have some reboot reason sent as soon as the syslog is online, or at least have it present in some form in the rules.
For example, an event based on the last boot reason would be helpful.

[TD-er]

I just merged a commit that may reduce the needed amount of stack memory for sending out syslog log entries.
Hopefully that also fixes these issues.

Please let me know if it does fix these issues.