[systemd-devel] Journal message timestamps

[Mantas Mikulėnas]

On Fri, Sep 4, 2020 at 6:59 PM Lennart Poettering <lennart at poettering.net>
wrote:

> On Do, 27.08.20 11:33, Mark Corbin (mark at dibsco.co.uk) wrote:
>
> > 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.
> >
> > 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'. 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?
>
> No. We do not retroactively change written out records.
>
> However, when comparing log entries we prefer the record sequence
> number if two records come from the same system. And if that doesn't
> work, then we prefer monotonic clocks if two records cme from the same
> boot. Wallclock is only used for comparing two records if they are
> from different boots altogether.
>
> > 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?
>
> There's no nice answer for that. We do not patch written out journal
> records once they are written. They are considered immutable. This
> means, from the journal's PoV if you generated a bunch of records in
> the initrd or early boot (i.e. before /var/log/journal is available)
> and you have no usable wallclock time, and you power cycle 10 times in a
> row, then we have no indication about which of the 10 series of
> recrods came in which order before the others.
>
> To fix that we'd have to keep a separate log of boot ids or so
> somewhere, which we could use as auxiliary source of truth if all we
> have are bootids+monotonic time which came first by comparing boot
> ids. But that would still not be perfect since we could write that out
> only late (i.e. after /var becomes writable), so the order before that
> could not be reconstructed either if the system doesn't get that far.
>

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.

Also, if /var *is* available, didn't .journal files also have some sort of
global sequence number that could be used when timestamps fail?

-- 
Mantas Mikulėnas
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/systemd-devel/attachments/20200907/7ff122bc/attachment-0001.htm>