I’m testing some configuration changes and have rebooted my router a couple of times and I noticed that the system log in Luci looks very weird. I believe the first log part comes from the kernel lag and the second part from the system log.
The system log part shows timestamps that seems ok. But the timestamps for the kernel part shows timestamps that indicates that the logs comes from a previous boot several hours ago. I have actually rebooted the system several times since that time.
This is because most embedded systems do not have a real time clock with a battery backup. This means that each time you reboot, the time is lost. The system will use the timestamp of the most recently modified file as the “best guess” time during the initial boot, until such time as the network stack is up and running and the system can get a time sync via ntp.
This is normal and expected behavior, so nothing to worry about.
So the log is actually from the current boot but the timestamps are wrong? I can see that if I use ssh to view the log it does not show a clock time but just start at 0. So is it some Luci component that translates that to an actual time? Sounds like it could be done in a better way then. I would prefer to not have it translated at all rather than having it translated wrong.
Early in the boot process, but not immediately, there is a process to get the timestamp of the most recently modified file. Stuff before that will start from zero.
The fix for this is to use a battery-backed rtc. Without that, this is the best option that exists since there is no persistent time when the system reboots power cycles.
Its still not clear to me how it can work at some seemingly random point and then get stuck. E.g. I reboot at 11:22:33 and the log stamps starts at 11:22:33. Then I reboot 20 minutes later and the new log also starts at 11:22:33. Repeat and again it starts at 11:22:33. Although every time the system clock has been updated to correct time before reboot.
Is that normal behaviour for all devices without battery backup clock?
The timestamp will not continue at the exact same time as your reboot unless you write to persistent storage (i.e. flash memory) exactly at the moment of reboot.
This is expected.
Right. But the time is not persistent across power cycles or reboots.
Specifically, a device like a consumer all-in-one wifi router or a similar type device does not have a Real Time Clock -- this is a specific hardware component that keeps time.
Typically, RTCs are designed such that they can use a battery backup to ensure that the time is kept when the power is off. However, a device with an RTC, even without a battery backup, will keep the time across warm-reboots (i.e. reboot but power is not interrupted).
In the case of a device without an RTC, the time is stored in RAM. Every time that the power is interrupted or a reboot is performed, the data in RAM is lost. This means that there is no information about time available to the system when it initially boots up.
OpenWrt, by default, assumes the there is no RTC in the system and it will thus assume that it will eventually be able to set its clock over the internet using NTP (Network Time Protocol). But, there is a gap in time between the initial phases of the startup process and the time that the network/internet can be reached. Therefore, the system does the following:
Initial boot: time = 0
... a few things happen ...
sysfixtime: if hardware RTC exists, get time; otherwise find the most recently modified file, use its timestamp as the new 'time'
... more stuff happens ...
... network stack becomes ready ...
ntp sync: get the time from an NTP server (usually on the internet)
This happens every time you boot up. The temporary time from sysfixtime is better than no time, but not accurate. That is why it is followed, as soon as reasonably possible, by an accurate time set via ntp.