<div dir="ltr"><div dir="ltr">On Fri, Sep 4, 2020 at 6:59 PM Lennart Poettering <<a href="mailto:lennart@poettering.net">lennart@poettering.net</a>> wrote:<br></div><div class="gmail_quote"><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">On Do, 27.08.20 11:33, Mark Corbin (<a href="mailto:mark@dibsco.co.uk" target="_blank">mark@dibsco.co.uk</a>) wrote:<br>
<br>
> Hello<br>
><br>
> I am working on time synchronisation issues at boot for systems without an<br>
> RTC (using balenaOS on a Raspberry Pi 3) and have some questions about how<br>
> journald assigns timestamps to log messages.<br>
><br>
> When I boot my system and look at the journal I see an initial date/time for<br>
> kernel messages, e.g. '1 June 2020 10:00:00' followed by messages with the<br>
> 'correct' date/time once the system time has been set from another source,<br>
> e.g. build time, NTP, etc. This means that over several reboots I have lots<br>
> of sets of log messages from 1 June 2020 which understandably confuses the<br>
> 'journalctl --list-boots' command. I found an issue that describes the<br>
> problem here <a href="https://github.com/systemd/systemd/issues/662" rel="noreferrer" target="_blank">https://github.com/systemd/systemd/issues/662</a> and had assumed<br>
> that there wasn't anything I could do about this.<br>
><br>
> However, when running some tests on a board with Raspberry Pi OS I found<br>
> that it didn't suffer from the same problem. RPI OS uses a 'fake-hwclock'<br>
> service to restore the previous boot time from a file and this time gets<br>
> applied to all messages in the journal prior to this point. I added the<br>
> 'fake-hwclock' service to my system which resulted in the timestamps being<br>
> correct the majority of the time, but I was still seeing some boots where<br>
> the initial messages were showing '1 June 2020'. I eventually tracked the<br>
> intermittent behaviour down to whether the 'fake-hwclock' time setting<br>
> occurred in the same system log file as the initial kernel boot messages. On<br>
> my RPI OS board the runtime journal was set to 8MB, so the date/time setting<br>
> always occurred in the first journal file. On my system the runtime journal<br>
> was set to 4MB, so the date/time setting was sometimes happening in the<br>
> second journal file leaving the messages in the first file with a date of '1<br>
> June 2020'.<br>
><br>
> So my questions are...<br>
><br>
> It seems that journald is using the date/time from the 'fake-hwclock'<br>
> service to update the timestamps of earlier log messages within the same<br>
> file. Is this correct?<br>
<br>
No. We do not retroactively change written out records.<br>
<br>
However, when comparing log entries we prefer the record sequence<br>
number if two records come from the same system. And if that doesn't<br>
work, then we prefer monotonic clocks if two records cme from the same<br>
boot. Wallclock is only used for comparing two records if they are<br>
from different boots altogether.<br>
<br>
> What would be the best technique for ensuring that my journal logs always<br>
> display the 'best' time for log messages (either 'fake-hwclock' or NTP)? Do<br>
> I always have to ensure that the journal is large enough to capture my<br>
> initial time setting event in the first file?<br>
<br>
There's no nice answer for that. We do not patch written out journal<br>
records once they are written. They are considered immutable. This<br>
means, from the journal's PoV if you generated a bunch of records in<br>
the initrd or early boot (i.e. before /var/log/journal is available)<br>
and you have no usable wallclock time, and you power cycle 10 times in a<br>
row, then we have no indication about which of the 10 series of<br>
recrods came in which order before the others.<br>
<br>
To fix that we'd have to keep a separate log of boot ids or so<br>
somewhere, which we could use as auxiliary source of truth if all we<br>
have are bootids+monotonic time which came first by comparing boot<br>
ids. But that would still not be perfect since we could write that out<br>
only late (i.e. after /var becomes writable), so the order before that<br>
could not be reconstructed either if the system doesn't get that far.<br></blockquote><div><br></div><div>Hmm, but if there's no /var in which to store the append-only log of boot IDs, then there's also no /var in which journal messages would persist either, is there? So one wouldn't be seeing messages from previous boots anyway.</div><div><br></div><div><div>Also, if /var *is* available, didn't .journal files also have some sort of global sequence number that could be used when timestamps fail?</div></div></div><div><br></div>-- <br><div dir="ltr" class="gmail_signature"><div dir="ltr">Mantas Mikulėnas</div></div></div>