2022-12-24
The systemd journal is primarily time-based
Recently, I encountered a surprising systemd behavior:
Dear systemd: apparently using absolute system date (at boot?!) to determine 'the system boot before this one' and so on is not necessarily a great idea, given that systems can boot with scrambled system time. If I want to look at 'the previous boot', I want that to work even given bad time. Especially if the system booted with bad time, ran with bad time for a bit, and then rebooted again.
(There are some replies by Lennart Poettering that are worth reading, 1, 2, and a systemd issue about this.)
However, on deeper examination I realized that this goes deeper
than just what 'journalctl -b-1' will report is the boot before
the current one (or even earlier boots). If your system boots with
a bad time in the past and then corrects the time, 'journalctl -r'
will stop abruptly at a log line where the time began to be stepped
to the correct value, like this (in reversed order):
[...] Dec 19 08:49:44 <host> systemd-journald[881]: [...] Journal header limits reached or header out-of-date, rotating. Dec 19 08:49:44 <host> systemd-journald[881]: [...] is older than the configured file retention duration (1month), suggesting rotation. Jul 13 20:00:33 <host> chronyd[2510]: Selected source [...] -- Boot <previous boot id> -- [...]
If you can retrieve the correct journalctl boot identifier, you can see all of that boot's messages (in forward or reverse time order), but otherwise you get cut off and jump straight back to the previous boot. You do at least get one line of warning about it, and if you're specifically looking for early boot lines you'll likely notice that they're missing.
Assuming that the system time was corrected after boot, the times
reported for such a boot in 'journalctl --list-boots' seem to be
set to when the time was corrected. This particular boot had its
start time reported as '2022-12-19 08:49:44', which is actually not
the correct start of boot time even after the time correction (it
seems that it took 33 seconds to reach that point). I'm not sure
what sort of boot record you get if you boot a system with such
incorrect time and never reset it to the correct time before it
reboots.
This is probably old hand to systemd journal people, but it's not at all how I expect '(syslog) log files' to work. Log lines have an order and that order is not dependent on the nominal system time at the time they were logged. Still, the journal is what it is, and we can always use syslog files in addition to the journal when this matters.
(And I do feel that the systemd journal is in many ways an improvement on syslog files. It captures more information and provides more convenient access to it.)