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

[Ulrich Windl]

>>> Pekka Paalanen <ppaalanen at gmail.com> schrieb am 28.08.2020 um 09:54 in
Nachricht <20200828105459.00eb21eb at eldfell>:
> On Thu, 27 Aug 2020 11:33:04 +0100
> 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.
> 
> ...
> 
>> Any general details about how journald applies timestamps would also be 
>> greatly appreciated.
> 
> Hi,
> 
> I'm not sure if this is relevant to you, but I have encountered a
> different issue that causes journald to lose track of boots and
> therefore the message ordering becomes useless: boot_id not
> changing on reboot. More info at
> https://bugs.debian.org/cgi‑bin/bugreport.cgi?bug=963977 
> 

The boot_id is just a normal UUID, but maybe one of the first being
generated.

The code in the kernel relies on feeding the random pool probably before
getting the first UUID (but obviously too late for boot_id):
 *      echo "Initializing random number generator..."
 *      random_seed=/var/run/random-seed
 *      # Carry a random seed from start-up to start-up
 *      # Load and then save the whole entropy pool
 *      if [ -f $random_seed ]; then
 *              cat $random_seed >/dev/urandom
 *      else
 *              touch $random_seed
 *      fi
 *      chmod 600 $random_seed
 *      dd if=/dev/urandom of=$random_seed count=1 bs=512

The random generator itself relies in add_device_randomness() being called to
provide some randomness.
Usually there's a kernel warning when not enough entropy is available (seen
with systemd on "normal" systems during boot).
The random generator in turn relies on arch_get_random_seed_long() to provide
some random data and on the number of timer interrupts until the generator
initializes. Unsure whether the latter varies over boots.


> The messages still show up with the right wall‑clock time (once
> the clock is set), they are just ordered badly: it is as if the
> wall‑clock time would be jumping forward and backward days, weeks or
> months randomly.

What systemd might do is: Save the last boot_id. If the current boot_id is the
same as the last one during boot, either do:
a) Complain and do not use the boot_id, but get a UUID until it differs from
the boot_id
b) just complain
c) panic (the boot_id actually is expected to change during boots)

I guess when all drivers are modular and loaded from initrd, then the first
init process (systemd) that loads the modules did not get enough randomness on
start.

Regards,
Ulrich