[systemd-devel] Journal message timestamps

[Mark Corbin]

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?

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