The systemd journal is primarily time-based

December 24, 2022

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

Comments on this page:

By Michael Kohne at 2022-12-25 09:32:24:

systemd is one of those things that solves a number of very real problems, but along the way it does any number of bonkers decisions, like assuming that the clock isn't a completely garbled pile of crap.

Written on 24 December 2022.
« Handling numbers in Vim when they have a dash in front of them
Sorting out PC chassis power switches for ATX power supplies »

Page tools: View Source, View Normal, Add Comment.
Login: Password:
Atom Syndication: Recent Comments.

Last modified: Sat Dec 24 22:13:52 2022
This dinky wiki is brought to you by the Insane Hackers Guild, Python sub-branch.