[systemd-devel] Antw: [EXT] Journal message timestamps

[Ulrich Windl]

>>> Mark Corbin <mark at dibsco.co.uk> schrieb am 27.08.2020 um 12:33 in
Nachricht
<c2edc2b5-0c6a-2d34-42ff-569c2626294a at dibsco.co.uk>:
> Hello
> 
> I am working on time synchronisation issues at boot for systems without 
> an RTC (using balenaOS on a Raspberry Pi 3) and have some questions 
> about how journald assigns timestamps to log messages.
> 
> When I boot my system and look at the journal I see an initial date/time 
> for kernel messages, e.g. '1 June 2020 10:00:00' followed by messages 
> with the 'correct' date/time once the system time has been set from 
> another source, e.g. build time, NTP, etc. This means that over several 
> reboots I have lots of sets of log messages from 1 June 2020 which 
> understandably confuses the 'journalctl ‑‑list‑boots' command. I found 
> an issue that describes the problem here 
> https://github.com/systemd/systemd/issues/662 and had assumed that there 
> wasn't anything I could do about this.

"Good old UNIX" had the feature to "guess" the current time by looking at the
last update in the root filesystem (when that seemed newer than the "current
time").
One idea would be to have a "timestamp file" (much like a low-resolution
software RTC) that is updated periodically when it's known that the system time
is correct. Then after boot you would get a good guess, and time wouldn't jump
backwards, too.

> 
> However, when running some tests on a board with Raspberry Pi OS I found 
> that it didn't suffer from the same problem. RPI OS uses a 
> 'fake‑hwclock' service to restore the previous boot time from a file and 
> this time gets applied to all messages in the journal prior to this 
> point. I added the 'fake‑hwclock' service to my system which resulted in 
> the timestamps being correct the majority of the time, but I was still 
> seeing some boots where the initial messages were showing '1 June 2020'. 

So you did exactly what I'm proposing.

> I eventually tracked the intermittent behaviour down to whether the 
> 'fake‑hwclock' time setting occurred in the same system log file as the 
> initial kernel boot messages. On my RPI OS board the runtime journal was 
> set to 8MB, so the date/time setting always occurred in the first 
> journal file. On my system the runtime journal was set to 4MB, so the 
> date/time setting was sometimes happening in the second journal file 
> leaving the messages in the first file with a date of '1 June 2020'.
> 
> So my questions are...
> 
> It seems that journald is using the date/time from the 'fake‑hwclock' 
> service to update the timestamps of earlier log messages within the same 
> file. Is this correct?
> 
> What would be the best technique for ensuring that my journal logs 
> always display the 'best' time for log messages (either 'fake‑hwclock' 
> or NTP)? Do I always have to ensure that the journal is large enough to 
> capture my initial time setting event in the first file?
> 
> Any general details about how journald applies timestamps would also be 
> greatly appreciated.
> 
> Thanks
> 
> Mark
> _______________________________________________
> systemd‑devel mailing list
> systemd‑devel at lists.freedesktop.org 
> https://lists.freedesktop.org/mailman/listinfo/systemd‑devel