2

While looking through some archived journal files from another machine, I noticed that some log entries have different __BOOT_ID values with extremely narrow time gaps in between. For an example, log entries that are milliseconds apart would have different __BOOT_ID values. This should not be possible as the machines could not restart within that small of a time gap.

When I run journalctl -o verbose --directory <dir path> | grep -B 30 -A 30 -- "-- Reboot --" I can see quote the following real example with two different boot ID values for log events that are 10ms apart.

Wed 2019-11-13 21:35:58.469925 ...
    _TRANSPORT=kernel
    PRIORITY=6
    SYSLOG_FACILITY=0
    SYSLOG_IDENTIFIER=kernel
    _BOOT_ID=fec227a60ef24474aacd023d6c02733f
...
...
...
    MESSAGE=spi1.0: ttyMAX1 at I/O 0x20 (irq = 30, base_baud = 3000000) is a MAX3109
-- Reboot --
Wed 2019-11-13 21:35:58.470352 ...
    _SOURCE_MONOTONIC_TIMESTAMP=0
    _TRANSPORT=kernel
    PRIORITY=6
    SYSLOG_FACILITY=0
    SYSLOG_IDENTIFIER=kernel
    MESSAGE=Booting Linux on physical CPU 0x0
    _BOOT_ID=21b95aabab034009a19d1b7deac80327
...
...
...

I've tried to search for what could possibly cause boot ID to rapidly change like that without any success. Looking at the systemd source for the version (v243) shows that sd_id128_get_boot() that seems to be the function used to read the boot ID just reads the kernel generated value from the file.


        if (sd_id128_is_null(saved_boot_id)) {
                r = id128_read("/proc/sys/kernel/random/boot_id", ID128_UUID, &saved_boot_id);
                if (r < 0)
                        return r;
        }

        *ret = saved_boot_id;
        return 0;

The end result is a list of reboots that show up in the logs that might not be reboots after all. Interestingly journalctl --list-boots will not show these as reboots at all (currently trying to understand get_boots() implementation).

Appreciate any ideas, inputs if anyone has seen this behavior earlier. I understand that jounalctl --list-boots is the go to place to get the list of reboots, but I'm trying to analyze the logs with a specific set of reboot information in mind. These false positives pollute the results out of the scripts I'm trying to write.

1 Answer 1

2

I don't think the boot ID is actually changing that rapidly. I think you're viewing logs from several different boots at once, and they're getting mixed together.

This can happen if your system doesn't have a battery-powered real-time clock.

journalctl uses the wall clock time to sort log messages that came from different boots. If the wall clock resets on each boot, it will look like the messages from different boots happened at the same time, and journalctl will interleave them confusingly.

See Lennart Poettering's comment on systemd feature request #662 (emphasis mine):

So here's what happens: each time you reboot, you start with a date in 1970, and a newly randomized boot id. A couple of messages are generated this way for each boot.

During display journalctl will now see this data, and try to make sense of it, and interleave it. Interleaving means it needs to sort the lines together, and put older data before newer data. To do that it tries to compare sequence numbers first. Sequence numbers are maintained in memory, and are reset to zero on each boot. They hence can be compared only if the boot ID matches between the two lines to compare. Since the boot ID is different for your reboots (obviously, and rightfully), this logic of ordering cannot be used. Next, journalctl tries to order things by the monotonic timestamp (i.e. the time passed since boot). Such ordering only works under the same conditions: we can only ordering lines of the same boot via the monotonic time. Which means we resort to the last way of comparing two lines: via the wallclock time. But that is always 1970, and hence results in the interleaving you see, where the lines are all mixed up.

One way to confirm this is to run journalctl --list-boots and check the date ranges. If they overlap, journalctl is using bogus timestamps.

2
  • yes. on raspberry pi (that don't have internal clock; unless you add one), you can see those kind of messed up log with journalctl.
    – solsTiCe
    Apr 19, 2020 at 21:25
  • Hello @Maxpm, I think this explains my case clearly. I'm not familiar with the device specs (and it looks like the battery has been drained a few times), but this could be the reason for the first few "reboots". I'll accept this as the answer.
    – chamilad
    May 10, 2020 at 23:11

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged .