This is just something I'm curious about. It's not a significant problem. I have observed this happening for a few years, but I've not done any investigation.
I'm just posting in case someone else has seen this and knows what causes it.
The screen snip is from an ESP32 web server. I log 'interesting' things that happen. Normally (apart from reboots) there's nothing in the log.
See the 3 times with the red line around them. Straight after returning from my NTP class init() method, the NTP time has obviously been used to get the date correctly and the time is reasonable, but always significantly off the real value. I've not checked if it's alaways off by the same amount. Initialisation takes seconds, not minutes.
I don't understand how the NTP time can be 'kind of right'. I'd expect it to be junk if it hadn't done the NTP sync, or correct if it had, but not 'close but not right'.
As I said earlier I'm just curious as to whether anyone else has seen this kind of thing. I'm not asking for help to fix it. I may do some further experimenting, e.g. I've not tried putting in a delay() between returning from ntp.init() and writing to the log. Even if that 'fixed' it, it wouldn't satisfy my curiousity about how the time is always almost ,but not quite, right immediately after initialisation.
I've not posted any code because it's huge (30 + source files). It would take me more time than I've got available right now to make a stripped down version that just uses the ntp class and prints results to the serial monitor.
Add time zone to the debug output, and is there an adjustment field like for leap second that may be un-initialized and could contain random data? Maybe print the raw fields in the time/date structures.
I'm in the UK so my time zone is UTC (GMT) in the winter and UTC+1 (BST) in the summer. But that's a thought about the time zone thing. I'll include that in any debugging I do.
I think there's a setting where, when there is a sudden difference in the NTP time compared to the MCU's internal clock, in either direction, it doesn't move the internal clock to match the NPT time in one sudden step, but staggers the change over some defined period. In other words, it speeds up or slows down the internal clock so that it catches up or allows the internal clock to be caught up by the NTP time, over that defined interval, so that they match at the end of that period.
If the NTP time is ahead of the internal clock time, that's not so much a problem. But when the NTP time is behind the internal clock, that's more serious, because if, as in your case, events are being logged with timestamps, the timestamps could suddenly jump backwards. Even worse, there's the possibility of two events getting logged with the same timestamp which were not in reality concurrent events. This "gradual synchronisation" option helps avoid those problems.
Could this somehow explain that ~30-minute-slow timestamp?
I don't normally reboot it frequently. The UI has a reboot option that calls esp_restart(). After posting yesterday I rebooted it a few times in a row. The NTP time seemed to be right first time in this case. The most frequent reboots happen when I'm modifying / uploading new code versions using OTA.
Thanks to all for the suggestions of the possible causes. I'm probably not going to spend time investigating this issue in the short term as I have other more pressing things to get on with.
"call NTP.init() . . ."
It looks like you may be using an external library to obtain NTP time instead of using the inbuilt ESP32 functions.
If that is the case then look at something like ESP32 NTP Time - Setting Up Timezones and Daylight Saving Time | Random Nerd Tutorials
and see if you can reproduce your problem with that. The core of it is only a few lines of code.
The init() method is in a class that I wrote, and it contains this code:
int Ntp::init()
{
// this doesn't return anything so can't check
// configTime(gmtOffset_sec, daylightOffset_sec, ntpServer);
configTime(0, 0, ntpServer); // Can use 0,0 because using TZ below now
setenv("TZ","GMTGMT-1,M3.4.0/01,M10.4.0/02",1); // London
// setenv("TZ","CET-1CEST,M3.5.0,M10.5.0/3",1); // Paris - can use this to check time is +1 hour
tzset();
initialised = true;
return SUCCESS;
}
I used the info from that site to get me started. I also bought their book on ESP32 webservers, and did some of the examples from it to familiarise myself with how to implement a web server on an ESP32.
OK. If you are using native ESP32 NTP code then that already rules out a large number of possible error sources.
I share your surprise about 30 minute jumps. If you can reproduce the issue with a smaller sketch say like the one in my previous link then that could help to narrow it down and let others try to reproduce it.
You could also configure the ESP32 core debug level to "verbose" in the IDE tools menu to see if you see any strange activity which could be related to this phenomenon.
I only posted originally in case in was a known issue, or perhaps someone reading it would have had a similar experience. It has pretty much zero impact.
The main purpose of my log is to print info about 'interesting' things that happen during normal operation. It's always on so I get to see e.g. times when the router goes down and back up again. Usually in the early hours of the morning, which I assume is due to maintenance.
Whenever I reboot it, I clear the log after it's booted, because I only want to see unexpected reboots in the log.
So the fact that one NTP timestamp is wrong in the log when booting, is merely a curiosity.
