Skip to main content
Topic solved
This topic has been marked as solved and requires no further attention.
Topic: [SOLVED] Daemon logging broken with /var on a separate encrypted device (Read 1141 times) previous topic - next topic
0 Members and 3 Guests are viewing this topic.

[SOLVED] Daemon logging broken with /var on a separate encrypted device

Having multiple LVM on LUKS partitions with the root volume on one and /var on another during boot some daemons are activated and begin to access /var prior to opening all the devices specified in /etc/crypttab. The end result is that some data is written into a shadow directory on the root partition masked by the later mounted /var partition making the former data effectively inaccessible.

The following lsof listing shows open file descriptors on two different devices but under the same logical path:
Code: [Select]
$ sudo lsof | egrep "^COMMAND|/var/log"
COMMAND     PID   TID TASKCMD      USER   FD      TYPE             DEVICE  SIZE/OFF       NODE NAME
s6-log      472                   s6log    4wW     REG              253,1         0     262176 /var/log/dmesg/lock
s6-log      472                   s6log    5w      REG              253,1    405953     262178 /var/log/dmesg/current
s6-log      474                   s6log    4wW     REG              253,1         0     262179 /var/log/dhcpcd/lock
s6-log      474                   s6log    5w      REG              253,1      7163     262181 /var/log/dhcpcd/current
s6-log      475                   s6log    4wW     REG              253,1         0     262164 /var/log/lvmpolld/lock
s6-log      475                   s6log    5w      REG              253,1    319470     262166 /var/log/lvmpolld/current
s6-log      476                   s6log    4wW     REG              253,1         0     262167 /var/log/udevd/lock
s6-log      476                   s6log    5w      REG              253,1   4020849     262160 /var/log/udevd/current
s6-log     1066                   s6log    4wW     REG              253,6         0     393250 /var/log/dnsmasq/lock
s6-log     1066                   s6log    5w      REG              253,6      1655     393252 /var/log/dnsmasq/current
s6-log     1067                   s6log    4wW     REG              253,6         0     393247 /var/log/dbus/lock
s6-log     1067                   s6log    5w      REG              253,6      3514     393249 /var/log/dbus/current
s6-log     1068                   s6log    4wW     REG              253,6         0     393242 /var/log/chronyd/lock
s6-log     1068                   s6log    5w      REG              253,6      4723     393244 /var/log/chronyd/current

For good measure what you see trying to list /var/log directly:
Code: [Select]
$ sudo lsof +D /var/log
COMMAND  PID  USER   FD   TYPE DEVICE SIZE/OFF   NODE NAME
s6-log  1066 s6log    4wW  REG  253,6        0 393250 /var/log/dnsmasq/lock
s6-log  1066 s6log    5w   REG  253,6     1655 393252 /var/log/dnsmasq/current
s6-log  1067 s6log    4wW  REG  253,6        0 393247 /var/log/dbus/lock
s6-log  1067 s6log    5w   REG  253,6     3514 393249 /var/log/dbus/current
s6-log  1068 s6log    4wW  REG  253,6        0 393242 /var/log/chronyd/lock
s6-log  1068 s6log    5w   REG  253,6     4723 393244 /var/log/chronyd/current

Naturally this affects all file access to /var besides just logging with all sorts of directories and whatnot being written during boot to the wrong filesystem.

So as far as I can see the root of the issue is there's a problem with the dependency chain and various services in the boot bundle are started before or simultaneously while cryptsetup is being called rather than afterwards ensuring all required physical disks have been activated properly. What complicates matters is that some (e.g. udev) services need to be started first for the new decrypted devices to be seen which also do logging to the disk under /var/log.

(A tangential issue is the inability to open secondary encrypted devices with a password during boot necessitating the use of keyfiles, but I believe this is rather a known upstream flaw with s6-rc.)

Re: Daemon logging broken with /var on a separate encrypted device

Reply #1
In theory, this is supposed to work already. What should happen is that logging daemons, if they do not immediately have write access to /var (test -w /var/log should fail), will instead write to the /run directory (which is always writeable of course). After the remount-root step (which should happen after all partitions, encrypted or not, are mounted), then a script is executed that moves anything logged in /run to the appropriate directory in /var and restarts the logging service.

I didn't design this mechanism with encryption specifically in mind (it was for read-only root mounting) so maybe there's something I have overlooked but I'm not sure why this doesn't already work.

Re: Daemon logging broken with /var on a separate encrypted device

Reply #2
I've spent some time digging into this now. For the curious and to help anyone debugging similar issues, to make s6-rc more verbose you can add "-v 2" to the "exec s6-rc" line in the /etc/s6/current/scripts/runlevel file. This'll make it spit out information on what gets started in what order during boot to the console and is viewable at /run/uncaught-logs/current after logging in.

The main culprits for what were happening are the lvm2-monitor, lvm2-pvscan, tmpfiles-setup and cleanup services.

lvm2-monitor and lvm2-pvscan both unconditionally write to their respective directories under /var/log and since this happens early we now have a writable directory there leading to any tests for it to succeed later on. The fix to this is to simply change /var/log to /run/log in their 'up' scripts. Afterwards the logs get moved around to /var/log by the log-service-reload.sh script called by remount-root. This script also tries to restart their *-log services which of course fails since they are oneshots and have no such. One way to fix that is to simply put an if block around it:

Code: [Select]
if [ -d /run/s6-rc/servicedirs/"${dir}"-log ]; then
    s6-svc -r /run/s6-rc/servicedirs/"${dir}"-log
fi

There's also a bug in the lvmpolld-log service, the last line has ${DIRECTIVES} written where it should be ${LVMPOLLD_DIRECTIVES}. This was unrelated to my issue but was still throwing an error.

tmpfiles-setup is responsible for touching various things under /var among other things, giving it remount-root as a dependency makes it stop causing issues.

cleanup creates the /var/log/{wtmp,btmp} files at boot (in addition to trying to rm files under / which wouldn't work if it was still mounted ro at this point), so remount-root should be added to its dependencies as well.

With the fixes in place all data goes under a single /var as it should. However, the tests in the logger services for a writable /var/log directory remain problematic. If for whatever reason there's a temporary hiccup (typo in /etc/crypttab, loose power connector, etc) during system boot causing devices to not mount appropriately, files will be created on the root partition again. If the admin/user isn't aware of the issue and fails to remove everything under the wrong /var the next boot will see the issue re-emerge. This could possibly be solved by having the services in addition to testing for writable /var/log check for some kind of a signal, perhaps an environment variable, set by the log-service-reload.sh script, so they always default to /run/log until remount-root has been run. I don't know enough about execline and it's a spooky beast so I didn't try implementing anything like that myself.

I didn't design this mechanism with encryption specifically in mind (it was for read-only root mounting) so maybe there's something I have overlooked but I'm not sure why this doesn't already work.

Couple of other services I spotted in the boot bundle that didn't affect me but might cause an issue for this read-only root case are "rc-local" as it can call scripts that operate on the filesystem and "swap" which will fail if using a swap file on the root device. Both cases can be solved once again by making them depend on remount-root and thus bumping them to take place later in the boot process.

Then finally there's this:
Code: [Select]
@4000000061a15a0338dfddc8 s6-rc: info: service cronie: starting
@4000000061a15a0338e8bb64 s6-rc: info: service s6rc-fdholder: starting
@4000000061a15a0338ec9e63 s6-rc: info: service s6rc-oneshot-runner: starting
@4000000061a15a03398dabba s6-rc: info: service cronie successfully started
@4000000061a15a0339e6b59a s6-rc: info: service s6rc-oneshot-runner successfully started
@4000000061a15a033adf4ad8 s6-rc: info: service sysctl: starting
@4000000061a15a033af11ee9 s6-rc: info: service net-lo: starting
@4000000061a15a033afe7dfb s6-rc: info: service mount-tmpfs: starting
@4000000061a15a033b076d1d s6-rc: info: service mount-procfs: starting
@4000000061a15a033b56ce03 s6-rc: info: service lvm2-pvscan: starting
@4000000061a15a033b5aaa58 s6-rc: info: service lvm2-monitor: starting
...SNIP...
@4000000061a15a04129611f5 crond: can't open or create /var/run/crond.pid: No such file or directory
...SNIP...

This is the very beginning of the uncaught-logs file. As can be seen cronie is the very first service being started and it'll keep spitting out errors until the mounting processes have finished. This is because there are no dependencies whatsoever set for it. There are also others like acpid and dhcpcd also getting activated very early during boot. Note that these aren't in the boot bundle but the default one like the wiki and post-installation Pacman hooks instruct. As I understand this is happening because bundle contents don't act as dependencies but rather coalesces all of them together for dependency resolution by the database compile process. Is this an error or am I missing something here and this is actually the intended behaviour?

Re: Daemon logging broken with /var on a separate encrypted device

Reply #3
Thanks for the detailed report! Some of these are very clear bugs that I will fix.

This is the very beginning of the uncaught-logs file. As can be seen cronie is the very first service being started and it'll keep spitting out errors until the mounting processes have finished. This is because there are no dependencies whatsoever set for it. There are also others like acpid and dhcpcd also getting activated very early during boot. Note that these aren't in the boot bundle but the default one like the wiki and post-installation Pacman hooks instruct. As I understand this is happening because bundle contents don't act as dependencies but rather coalesces all of them together for dependency resolution by the database compile process. Is this an error or am I missing something here and this is actually the intended behaviour?

This is expected. The boot bundle is merely a subset of the default bundle. All of it is started at the exact same time by spinning up the default bundle. The intention is for services to be as parallel as possible.

Re: Daemon logging broken with /var on a separate encrypted device

Reply #4
@beflia: I have pushed s6-scripts-20211127-1 and lvm2-20211127-1 into the gremlins repo. When you get a chance, could you double check and make sure those work correctly on your setup?

Some additional comments:

Quote
Couple of other services I spotted in the boot bundle that didn't affect me but might cause an issue for this read-only root case are "rc-local" as it can call scripts that operate on the filesystem and "swap" which will fail if using a swap file on the root device. Both cases can be solved once again by making them depend on remount-root and thus bumping them to take place later in the boot process.

rc-local comes with an empty dependencies file. The user is expected to adjust this on his/her own to fit their needs. As for swap, it executes after filesystems are mounted. I don't think swapon requires read/write permissions on a swap file but perhaps I am wrong?

Edit: I moved the above s6-scripts and lvm2 packages to system just now so hopefully it just works after that update.

Re: Daemon logging broken with /var on a separate encrypted device

Reply #5
Unfortunately it's taken me until now to get back around to this.

Edit: I moved the above s6-scripts and lvm2 packages to system just now so hopefully it just works after that update.

After the changes it works as expected with everything written on the right device, but a couple of things still propped up.

On line 6 in /etc/s6/sv/lvm2-pvscan/up there's a typo:
Code: [Select]
if -n -t { test -d /var/log/lvm2-pvscan } install -d -m 0755 -o s6log -g s6log /run/log/lvm2-pvscan
Test for /var/log should be /run/log instead. Similar line in lvm2-monitor/up (also on line 6) has it correctly, however I feel these tests could be omitted altogether and have install run unconditionally in both cases, since the script was working correctly either way if slightly accidentally, and install will essentially perform a no-operation if the directory did happen to already exist under /run/log for some reason.

A much more troublesome issue exists in /etc/s6/log-service-reload.sh on line 19 with the cat command, where it moves over logs from /run/log/<foo>/current into /var/log/<foo>/current. if the destination file doesn't exist already (e.g. after a fresh install) it's created with owner set to root:root and not s6log:s6log as it should be. The end result is an unending stream of these on the console for every service that fell victim to it: "s6-log: fatal: unable to finish current .u for logdir /var/log/<foo>: Operation not permitted".

A couple of possible fix suggestions for it.
Either add a test before line 19 so the file is ensured to exist before cat'ing to it:
Code: [Select]
test ! -f /var/log/"${dir}"/current && install -m 0744 -o s6log -g s6log /dev/null /var/log/"${dir}"/current

Or in a more verbose manner by replacing the line with an if-else:
Code: [Select]
if [ -f /var/log/"${dir}"/current ]; then
    cat /run/log/"${dir}"/current >> /var/log/"${dir}"/current
else
    install -m 0744 -o s6log -g s6log /run/log/"${dir}"/current /var/log/"${dir}"/current
fi

The user executable bit on the new file must also be set on these so s6-log will use it instead of moving it over to a .u file and proceeding to open a new current file. (This had me confused for a while why s6-log insisted on clearing the log upon restart even with correct ownership.) Personally I'm probably partial to the latter way since it makes it very clear what is happening and why.

There's a chance of someone having this broken on their setup going unnoticed so it's probably worth either notifying users to take action manually or possibly by adding a post-install pacman hook to fix the log files in the vein of something like the following:
Code: [Select]
for cur in /var/log/*/current; do
    test ! -f "$cur" && continue
    if [ "`stat -c "%U" "$cur"`" != "s6log" ]; then
        chmod 744 "$cur"
        chown s6log:s6log "$cur"
    fi
done

I haven't messed with pacman scripts so that code is largely untested in that context and thus just a rough idea.

Quote
As for swap, it executes after filesystems are mounted. I don't think swapon requires read/write permissions on a swap file but perhaps I am wrong?

Easy enough to test:
Code: [Select]
$ sudo dd if=/dev/zero of=/swap.file bs=1M count=100; sudo chmod 600 /swap.file; sudo mkswap /swap.file
100+0 records in
100+0 records out
104857600 bytes (105 MB, 100 MiB) copied, 0.101121 s, 1.0 GB/s
Setting up swapspace version 1, size = 100 MiB (104853504 bytes)
no label, UUID=8f7c4ee6-04f5-4800-802a-5388206faf77
$ swapon
$ sudo mount -o remount,ro /
$ sudo swapon /swap.file
swapon: /swap.file: swapon failed: Read-only file system
$ swapon
$ sudo mount -o remount,rw /
$ sudo swapon /swap.file
$ swapon
NAME       TYPE SIZE USED PRIO
/swap.file file 100M   0B   -2

Also a test with the root partition actually set to read-only in Grub's config:
Code: [Select]
s6-rc: info: service swap: starting
s6-rc: info: service remount-root: starting
swapon: /swap.file: swapon failed: Read-only file system
s6-rc: warning: unable to start service swap: command exited 128
s6-rc: info: service remount-root successfully started

So it certainly does (or can, since I believe there's a race condition that might not trigger always) fail under these conditions. After switching the swap service's dependencies from mount-filesystems to remount-root it works without a hitch. The change only bumps up the service startup moment by a notch so I don't foresee it causing any issues either.

Re: Daemon logging broken with /var on a separate encrypted device

Reply #6
Thanks for the feedback! I've updated and pushed lvm-s6 and s6-scripts to system once again and that should address everything you mentioned. However, I did not attempt to add a script to automatically correct this should anyone be on a broken setup or anything like that. I figure this is a pretty rare edge case so I didn't want to add extra logic just for that.

 

Re: Daemon logging broken with /var on a separate encrypted device

Reply #7
Verified the update on a freshly installed system, logging looks to be working as expected now so this can be considered solved.