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

Fri Aug 28 13:34:07 UTC 2020

On 28/08/2020 08:06, Ulrich Windl wrote:
>>>> 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.

Yes, the fake-hwclock service is definitely what is needed here, but my 
problem is that the journal log messages only get updated with a 'good' 
timestamp when the start of the fake-hwclock service is captured in the 
first system journal file along with the initial kernel boot messages.

For example, when /run/log/journal/d197a2e910964a7f9a0de6462d0d7c62/ 
contains just 'system.journal' which has all log messages from:

'kernel: Booting Linux on physical CPU 0x0'
up to and including:
'fake-hwclock[827]: Fri Aug 28 12:12:08 UTC 2020'

then all messages displayed by journalctl are time stamped starting from 
'Fri Aug 28 12:12:08' onwards. This is good - no problem.

However when /run/log/journal/d197a2e910964a7f9a0de6462d0d7c62/ contains 
'system.journal' and a 'system at xxx-yyy-zzz.journal file' (where 
system.journal is the current journal file and 
system at xxx-yyy-zzz.journal is the first journal file that contains the 
initial kernel log messages) one of two things happens:

a) when the fake-hwclock log message is in the first journal file 
(system at xxx-yyy-zzz.journal) along with the initial kernel log messages 
the timestamps are all displayed correctly i.e. starting from 'Fri Aug 
28 12:12:08' onwards. Again this is what we want as above.

b) when the fake-hwclock log message falls into the second journal file 
(system.journal) only the messages in the second journal file are 
timestamped starting from 'Fri Aug 28 12:12:08' onwards. The initial 
kernel log messages from the first journal file 
(system at xxx-yyy-zzz.journal) are timestamped with an incorrect date/time 
(in my case always Jul 08 09:04:09 2020).

It seems that on my system the fake-hwclock service is starting right 
around the point where a second journal file is created during the boot 
process, so sometimes it falls in the first journal file and sometimes 
in the second.

The only way I have found to work around this so far is to increase the 
runtime file size from 4MB to 8MB to try and ensure that the 
fake-hwclock log message is always captured in the first journal file 
along with the initial kernel log messages.

I was just wondering whether this is the correct thing to do or whether 
there were any better solutions.

> 
>> 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
> 
> 
> 