[systemd-devel] journald deleting logs on LiveOS boots

Wed Jun 19 16:35:28 UTC 2019

On Wed, Jun 19, 2019 at 6:15 AM Lennart Poettering
<lennart at poettering.net> wrote:
>
> On Di, 18.06.19 20:34, Chris Murphy (lists at colorremedies.com) wrote:
>
> > When I boot Fedora 30/Rawhide Workstation (LiveOS install media) in a
> > VM with ~2GiB memory, using any combination of systemd, dracut, or
> > udev debugging, events are missing from the journal.
> >
> > systemd-241-7.gita2eaa1c.fc30.x86_64
> > systemd-242-3.git7a6d834.fc31.x86_64
> >
> > 'journalctl -b -o short-monotonic' starts at ~22s monotonic time. i.e.
> > all the messages before that are not in the journal. This problem
> > doesn't happen with netinstalls. Fedora LiveOS boots setup a memory
> > based persistent overlay, and /var/log/journal exists and
>
> what do you mean by "memory based persistent overlay"? if its in
> memory it's not persistant, is it? /me is confused...

I agree it is an oxymoron. The device-mapper rw ext4 volume where all
writes go is memory based, as the install media and the base image are
read-only. Since this volume is rw, and it's mounted at /, that makes
/var/log/journal rw, and appears to be persistent from the
systemd-journald point of view, so it uses it instead of
/run/log/journal

[    9.127691] localhost systemd[1]: Starting Flush Journal to
Persistent Storage...

>
> is this LVM stuff or overlayfs?

Neither, only device mapper.

[root at localhost-live liveuser]# lvs
[root at localhost-live liveuser]# vgs
[root at localhost-live liveuser]# pvs
[root at localhost-live liveuser]# dmsetup status
live-base: 0 13635584 linear
live-rw: 0 13635584 snapshot 163328/67108864 648
[root at localhost-live liveuser]#

All of this is setup by dracut with the boot parameter 'rd.live.image'

>
> > systemd-journald tries to flush there, whereas on netinstalls
> > /var/log/journal does not exist.
> >
> > Using systemd.log_target=kmsg I discovered that systemd-journald is
> > deleting logs in the LiveOS case, but I don't know why, / has ~750M
> > free
> >
> > [   24.910792] systemd-journald[922]: Vacuuming...
> > [   24.921802] systemd-journald[922]: Deleted archived journal
> > /var/log/journal/05d0a9c86a0e4bbcb36c5e0082b987ee/system at 818f3f40f19849e08a1b37b9c1e304f1-0000000000000001-00058ba31bec725e.journal
> > (8.0M).
> > [   24.921808] systemd-journald[922]: Vacuuming done, freed 8.0M of
> > archived journals from
> > /var/log/journal/05d0a9c86a0e4bbcb36c5e0082b987ee.
> >
> > I filed a bug here and have nominated it as a blocker bug for the
> > F31 cycle.
>
> Note that journald logs early on how much disk space it assumes to
> have free, you might see that in dmesg? (if not, boot with
> systemd.journald.forward_to_kmsg=1 on the kernel cmdline)

Using systemd.log_level=debug and systemd.journald.forward_to_kmsg=1 I only see:

[    4.224599] systemd-journald[327]: Fixed min_use=1.0M
max_use=145.8M max_size=18.2M min_size=512.0K keep_free=218.7M
n_max_files=100

If I boot with defaults (no debug options), I now see the following,
which is otherwise lost (not in the journal and not in dmesg, despite
systemd.journald.forward_to_kmsg=1)

[    9.124045] localhost systemd-journald[933]: Runtime journal
(/run/log/journal/05d0a9c86a0e4bbcb36c5e0082b987ee) is 8.0M, max
146.6M, 138.6M free.
...snip...
[    9.179050] localhost systemd-journald[933]: Time spent on flushing
to /var is 17.824ms for 936 entries.
[    9.179050] localhost systemd-journald[933]: System journal
(/var/log/journal/05d0a9c86a0e4bbcb36c5e0082b987ee) is 8.0M, max 8.0M,
0B free.

Why does it say 0B free?

[root at localhost-live liveuser]# df -h
Filesystem           Size  Used Avail Use% Mounted on
devtmpfs             1.5G     0  1.5G   0% /dev
tmpfs                1.5G  4.0K  1.5G   1% /dev/shm
tmpfs                1.5G  1.1M  1.5G   1% /run
tmpfs                1.5G     0  1.5G   0% /sys/fs/cgroup
/dev/sr0             1.9G  1.9G     0 100% /run/initramfs/live
/dev/mapper/live-rw  6.4G  5.5G  879M  87% /
tmpfs                1.5G  4.0K  1.5G   1% /tmp
vartmp               1.5G     0  1.5G   0% /var/tmp
tmpfs                294M     0  294M   0% /run/user/0
tmpfs                294M  4.0K  294M   1% /run/user/1000
[root at localhost-live liveuser]# free -m
              total        used        free      shared  buff/cache   available
Mem:           2932         223        1754           1         954        2435
Swap:             0           0           0
[root at localhost-live liveuser]# cat /etc/systemd/journald.conf
#  This file is part of systemd.
#
#  systemd is free software; you can redistribute it and/or modify it
#  under the terms of the GNU Lesser General Public License as published by
#  the Free Software Foundation; either version 2.1 of the License, or
#  (at your option) any later version.
#
# Entries in this file show the compile time defaults.
# You can change settings by editing this file.
# Defaults can be restored by simply deleting this file.
#
# See journald.conf(5) for details.

[Journal]
#Storage=auto
#Compress=yes
#Seal=yes
#SplitMode=uid
#SyncIntervalSec=5m
#RateLimitIntervalSec=30s
#RateLimitBurst=10000
#SystemMaxUse=
#SystemKeepFree=
#SystemMaxFileSize=
#SystemMaxFiles=100
#RuntimeMaxUse=
#RuntimeKeepFree=
#RuntimeMaxFileSize=
#RuntimeMaxFiles=100
#MaxRetentionSec=
#MaxFileSec=1month
#ForwardToSyslog=no
#ForwardToKMsg=no
#ForwardToConsole=no
#ForwardToWall=yes
#TTYPath=/dev/console
#MaxLevelStore=debug
#MaxLevelSyslog=debug
#MaxLevelKMsg=notice
#MaxLevelConsole=info
#MaxLevelWall=emerg
#LineMax=48K
#ReadKMsg=yes

Anyway, this helps in that systemd-journald thinks there isn't enough
space on /var so it almost immediately starts vacuuming. But I don't
see why it thinks /var has no free space.

>
> There is not much point in using /var if /run works too and /var isn't
> persistent anyway...

It's apparently a difficult problem to have /var/log/journal on an
installed system, but not have it on a liveOS system. Something would
have to manually create /var/log/journal during installation.

-- 
Chris Murphy