[systemd-devel] list-boots is incorrect, was: lost journal persistence

[Chris Murphy]

> Fedora 20, systemd-208-16.fc20.x86_64
> 
> I no longer have persistent journals written to disk. I've done at least two dozen reboots today, yet journalctl --list-boots always reports the last three entries as:
> 
> -2 43ba57a4decd4e2fb69bfd04493455c0 Mon 2014-04-14 14:43:38 MDT—Tue 2014-04-15 09:32:57 MDT
> -1 dd915a875c9b43168a4b43bd322a94ac Wed 2014-04-23 10:58:48 MDT—Wed 2014-04-23 11:32:20 MDT
>  0 eb5a4bb5c6364b84bf65020242c77347 Sat 2014-05-03 21:46:50 MDT—Sat 2014-05-03 22:22:54 MDT
> 
> /var/log/journal/b7670…
> -rw-r-----+ 1 root systemd-journal  8388608 May 10 17:46 system.journal
> 
> So it seems to have written something to system.journal.
> 
> 
> # systemctl status systemd-journald.service 
> systemd-journald.service - Journal Service
>   Loaded: loaded (/usr/lib/systemd/system/systemd-journald.service; static)
>   Active: active (running) since Sat 2014-05-10 17:45:32 MDT; 1min 8s ago
>     Docs: man:systemd-journald.service(8)
>           man:journald.conf(5)
> Main PID: 288 (systemd-journal)
>   Status: "Processing requests..."
>   CGroup: /system.slice/systemd-journald.service
>           └─288 /usr/lib/systemd/systemd-journald
> 
> May 10 17:45:32 f20v.localdomain systemd-journal[288]: Runtime journal is using 8.0M (max allowed 125.2M, trying to leave 187.9M fr...5.2M).
> May 10 17:45:32 f20v.localdomain systemd-journal[288]: Runtime journal is using 8.0M (max allowed 125.2M, trying to leave 187.9M fr...5.2M).
> May 10 17:45:32 f20v.localdomain systemd-journal[288]: Journal started
> May 10 17:45:32 f20v.localdomain systemd-journal[288]: Permanent journal is using 104.0M (max allowed 4.0G, trying to leave 4.0G fr...4.0G).
> May 10 17:45:32 f20v.localdomain systemd-journal[288]: Time spent on flushing to /var is 26.812ms for 761 entries.
> 
> I am mounting a Btrfs subvolume named var at /var, but it's always been this way and I have log entries going back to March. So I'm not sure when this started or what prompted it. The proximity to the journal start and flush to /var is the same time as mounting.
> 
> May 10 17:45:32 f20v.localdomain systemd[1]: Mounting /var...
> May 10 17:45:32 f20v.localdomain systemd[1]: var.mount: Directory /var to mount over is not empty, mounting anyway.
> May 10 17:45:32 f20v.localdomain systemd[1]: Mounted /var.
> 
> So I thought maybe the flush is happening to /var before var subvolume is mounted there, but that's not the case; the reason why it's not empty is due to dhclient always creating one folder prior to var subvolume mounting at /var.
> 
> /var/lib/dhclient
> 
> There are no AVC messages, and the selinux context for /var and /var/log/journal is correct. In /var/log the Xorg.0.log has today's date so clearly it can be written to. lastlog and boot.log also have the current boot date/time stamp.
> 
> journalctl --verify comes up with no problems, only pass.
> 
> 
> Very confusing.

It looks like --list-boots is broken. I have have the same problem on Rawhide with systemd-212-4.fc21.x86_64, which is a completely different VM. Here are the last three items with --list-boots

 -2 95117f702e4d43619072f87b20b2f31b Sat 2014-05-03 20:38:22 MDT—Sat 2014-05-03 20:47:17 MDT
 -1 c9bf102876774c7a8748920f6135ddf6 Sat 2014-05-03 20:47:35 MDT—Sat 2014-05-03 20:51:55 MDT
  0 f92e4dda29a54b89a3455a10bbb298b2 Sat 2014-05-03 21:01:17 MDT—Sat 2014-05-03 21:05:24 MDT

So its last entries end the same date the Fedora 20 system ends, May 3. But I have a week of usage on both systems, and using -b doesn't work because they're not in the list. But if I do

journalctl --since=today
or
--since=yesterday
or
--since=2014-05-04

They are all there. The journal is being written to disk. It's just that --list-boots isn't listing any boots since May 3, on two different VMs. So I don't know what broke it but it's broken in common with Fedora 20 and Rawhide.



Chris Murphy