On 28/08/2020 08:06, Ulrich Windl wrote:
Mark Corbin <mark@xxxxxxxxxxxx> schrieb am 27.08.2020 um 12:33 in
Nachricht
<c2edc2b5-0c6a-2d34-42ff-569c2626294a@xxxxxxxxxxxx>:
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@xxx-yyy-zzz.journal file' (where
system.journal is the current journal file and
system@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@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@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@xxxxxxxxxxxxxxxxxxxxx
https://lists.freedesktop.org/mailman/listinfo/systemd‑devel
_______________________________________________
systemd-devel mailing list
systemd-devel@xxxxxxxxxxxxxxxxxxxxx
https://lists.freedesktop.org/mailman/listinfo/systemd-devel
