[systemd-devel] Are logs at /run/log/journal automerged?

Fri Aug 26 02:01:09 UTC 2022

Let me first reply to your answers. Then I'll provide more details.
And a couple of questions at the end.

> > I'm experiencing this on Digital Ocean. The machine id there changes
> > (which I think shouldn't happen) on the first boot (supposedly by
> > cloud-init).
>
> The machine ID may change during the initrd to host-fs
> transition. Otherwise that's not OK though.

Is the transition somehow logged to the journal?

> When the logs from /run/ are flushed to /var/ they are all merged
> together into one.

> By default journalctl will show logs associated with the current
> machine ID and those associated with the current boot ID. The latter
> should usually ensure that logs from the initrd phase are shown as
> well if it has a different machine ID.

That might explain what I experience under CentOS, but not under
Ubuntu. Under Ubuntu I need --merge to see the records from the old
journal.

> > In Ubuntu 22.04 droplets, where logs are stored at
> > /var/log/journal, that leads to journalctl outputting no records
> > (because the log for the new machine-id has not been created), unless
> > I pass --file or --merge. Also, the records continue to be added to
> > the old log (for the old machine id).
> >
> > In CentOS 9 droplets, where logs are stored at /run/log/journal,
> > journalctl outputs records from all 3 files:
> >
> > cb754b7b85bb42d1af6b48e7ca843674/system.journal
> > 61238251e3db916639eaa8cd54998712/system at 6600bdad291b419c8a0b1fea2564c472-0000000000000001-0005e6d123825866.journal
> > 61238251e3db916639eaa8cd54998712/system.journal
> >
> > In this case records also are being added to the old log. But the new
> > log somehow contains the beginning of the log (starting with boot).
> >
> > Is my guess correct? Logs at /run/log/journal are automerged, logs at
> > /var/run/journal aren't.
>
> As mentioned abive, when the logs are flushed from /run/ to /var/ in
> systemd-journal-flush.service they are merged into one new journal
> file, which is located in the machine ID subdir of the actual machine
> ID of the system.

Um, by "automerged" I meant that journalctl doesn't need --merge to
display records from several journals (corresponding to different
machine ids).

The details:

Ubuntu 22.04 (249-11)
---------------------

After creating a droplet (Digital Ocean) it starts with one machine id
(c3a57680c1d26ca313b9c7ec36a5beaa), but after this line in the
journal:

Aug 25 23:32:59 d1 cloud-init[1318]: Initializing machine ID from
D-Bus machine ID.

the machine id changes:

# cat /etc/machine-id
b05137603357003a36d3c69c630806ab

And journalctl starts saying:

No journal files were found.
-- No entries --

Also:

# ls -R /var/log/journal
/var/log/journal:
c3a57680c1d26ca313b9c7ec36a5beaa

/var/log/journal/c3a57680c1d26ca313b9c7ec36a5beaa:
system.journal

I can inspect the journal with one of these commands (the records
continue to be created in the old journal):

# journalctl --file
/var/log/journal/c3a57680c1d26ca313b9c7ec36a5beaa/system.journal
# journalctl --merge

Alternatively I can do:

# systemctl restart systemd-journald
# journalctl

Then it creates a new journal, and journalctl displays the new journal
(only the records created after restart).

# ls -R /var/log/journal
/var/log/journal:
b05137603357003a36d3c69c630806ab
c3a57680c1d26ca313b9c7ec36a5beaa

/var/log/journal/b05137603357003a36d3c69c630806ab:
system.journal

/var/log/journal/c3a57680c1d26ca313b9c7ec36a5beaa:
system.journal

# journalctl --merge -u systemd-journald
Aug 25 23:31:32 ubuntu systemd-journald[333]: Journal started
Aug 25 23:31:32 ubuntu systemd-journald[333]: Runtime Journal
(/run/log/journal/c3a57680c1d26ca313b9c7ec36a5beaa) is 600.0K, max
4.6M, 4.0M free.
Aug 25 23:31:32 ubuntu systemd-journald[333]: Time spent on flushing
to /var/log/journal/c3a57680c1d26ca313b9c7ec36a5beaa is 33.441ms for
598 entries.
Aug 25 23:31:32 ubuntu systemd-journald[333]: System Journal
(/var/log/journal/c3a57680c1d26ca313b9c7ec36a5beaa) is 8.0M, max
200.3M, 192.3M free.
Aug 25 23:35:32 d1 systemd-journald[333]: Journal stopped
Aug 25 23:35:33 d1 systemd-journald[2098]: Journal started
Aug 25 23:35:33 d1 systemd-journald[2098]: System Journal
(/var/log/journal/b05137603357003a36d3c69c630806ab) is 8.0M, max
974.0M, 966.0M free.

CentOS 9 (systemd-250.4)
------------------------

The difference. A different starting machine id
(61238251e3db916639eaa8cd54998712). A slightly different message:

Aug 25 20:20:16 dc cloud-init[872]: Initializing machine ID from VM UUID.

The journal is accessible even though the machine id changed. It's at
/run/log/journal (/var/log/journal doesn't exist):

# ls -R /run/log/journal
/run/log/journal:
48727b98ca35468eb885d68e67ab2fca
61238251e3db916639eaa8cd54998712

/run/log/journal/48727b98ca35468eb885d68e67ab2fca:
system.journal

/run/log/journal/61238251e3db916639eaa8cd54998712:
system at 1b641591e26b40b9a2dc994b34c71f97-0000000000000001-0005e719dec62219.journal
system.journal

`journalctl` displays data from all 3 files. The order:

(20:19:38 - 20:19:40)
/run/log/journal/48727b98ca35468eb885d68e67ab2fca/system.journal
(20:19:41 - 20:19:57)
/run/log/journal/61238251e3db916639eaa8cd54998712/system at 1b641591e26b40b9a2dc994b34c71f97-0000000000000001-0005e719dec62219.journal
(20:19:57 - 20:22:43)
/run/log/journal/61238251e3db916639eaa8cd54998712/system.journal

The records are still added to the old journal (6123.../system.journal).

Which means the --file and --merge tricks are not needed (or
restarting systemd-journald).

The funny thing here is that the original machine id is 6123..., but
the journal starts in 4872.../system.jounal.

After restarting systemd-journald (20:26:25):

# ls -R /run/log/journal
/run/log/journal:
48727b98ca35468eb885d68e67ab2fca
61238251e3db916639eaa8cd54998712

/run/log/journal/48727b98ca35468eb885d68e67ab2fca:
system at fe3455381e074349a3107b59c346b59d-0000000000000001-0005e719de99a3d4.journal
system.journal

/run/log/journal/61238251e3db916639eaa8cd54998712:
system at 1b641591e26b40b9a2dc994b34c71f97-0000000000000001-0005e719dec62219.journal
system.journal

The order:

(20:19:38 - 20:19:40,
 20:26:25 - 20:26:25)
/run/log/journal/48727b98ca35468eb885d68e67ab2fca/system at fe3455381e074349a3107b59c346b59d-0000000000000001-0005e719de99a3d4.journal
(20:19:41 - 20:19:57)
/run/log/journal/61238251e3db916639eaa8cd54998712/system at 1b641591e26b40b9a2dc994b34c71f97-0000000000000001-0005e719dec62219.journal
(20:19:57 - 20:26:25)
/run/log/journal/61238251e3db916639eaa8cd54998712/system.journal
(20:26:25 - 20:28:48)
/run/log/journal/48727b98ca35468eb885d68e67ab2fca/system.journal

Which means that it starts to log to the new journal (4872...), then
(at 20:19:40, the machine id supposedly changed at 20:20:16) switches
to the old one (6123...), then (when I restarted systemd-journald)
switches back to the new one (4872...).

# journalctl --merge -u systemd-journald
Aug 25 20:19:38 localhost systemd-journald[217]: Journal started
Aug 25 20:19:38 localhost systemd-journald[217]: Runtime Journal
(/run/log/journal/48727b98ca35468eb885d68e67ab2fca) is 1.1M, max 9.1M,
8.0M free.
Aug 25 20:19:40 localhost systemd-journald[217]: Journal stopped
Aug 25 20:19:41 localhost systemd-journald[564]: Journal started
Aug 25 20:19:41 localhost systemd-journald[564]: Runtime Journal
(/run/log/journal/61238251e3db916639eaa8cd54998712) is 1.1M, max 9.1M,
8.0M free.
Aug 25 20:19:41 localhost systemd[1]: systemd-journald.service:
Deactivated successfully.
Aug 25 20:19:41 localhost systemd-journald[564]: Runtime Journal
(/run/log/journal/61238251e3db916639eaa8cd54998712) is 1.1M, max 9.1M,
8.0M free.
Aug 25 20:19:41 localhost systemd-journald[564]: Received client
request to flush runtime journal.
Aug 25 20:19:57 dc systemd-journald[564]: Data hash table of
/run/log/journal/61238251e3db916639eaa8cd54998712/system.journal has a
fill level at 75.1 (1564 of 2083 items, 1200128 file size, 767 bytes
per hash table item), suggesting rotation.
Aug 25 20:19:57 dc systemd-journald[564]:
/run/log/journal/61238251e3db916639eaa8cd54998712/system.journal:
Journal header limits reached or header out-of-date, rotating.
Aug 25 20:26:25 dc systemd-journald[564]: Journal stopped
Aug 25 20:26:25 dc systemd-journald[11161]: Journal started
Aug 25 20:26:25 dc systemd-journald[11161]: Runtime Journal
(/run/log/journal/48727b98ca35468eb885d68e67ab2fca) is 1.1M, max 9.1M,
8.0M free.
Aug 25 20:26:25 dc systemd-journald[11161]: Data hash table of
/run/log/journal/48727b98ca35468eb885d68e67ab2fca/system.journal has a
fill level at 75.3 (1568 of 2083 items, 1200128 file size, 765 bytes
per hash table item), suggesting rotation.
Aug 25 20:26:25 dc systemd-journald[11161]:
/run/log/journal/48727b98ca35468eb885d68e67ab2fca/system.journal:
Journal header limits reached or header out-of-date, rotating.

Which supposedly means that systemd-journald... is passed the new
machine id? So it starts to log to the new journal. But then got
restarted and sees the current (old) machine id. Which makes it switch
to the old journal. And then when I restart it, it switches back to
the new journal.

Another not so expected thing that I couldn't reproduce on Ubuntu:

# journalctl --merge -e
Using --boot or --list-boots with --merge is not supported.
# journalctl --merge -f
Using --boot or --list-boots with --merge is not supported.

---

My guess is that they (Digital Ocean) have a machine id hardcoded into
the images (the initial machine id is always the same). And for each
droplet to have each own, they change machine id on the first boot.
Which makes me think, "Why not build images with no /etc/machine-id?"

What still confuses me (under CentOS):

* data from all files are displayed (from the old and the new
journals) w/o --merge, which doesn't happen under Ubuntu
* it starts with the new journal (new journal -> old journal -> new journal)
* the journalctl --merge -e/-f issue

Regards,
Yuri