[Bug 2064096] Re: Services fail to start in noble deployed with TPM+FDE

Wed May 22 14:39:59 UTC 2024

I have verified the fix according to the test plan above, using
255.4-1ubuntu8.1 from noble-proposed. Note, as I mentioned in an earlier
comment, this fix is NOT available on Desktop with TPM FDE until the
appropriate snap is rebuilt.

I have previously prepared a noble VM, and installed dracut for
generating the initrd, which means running systemd in the initrd.
Currently, I can see the AppArmor denials for rsyslog:

ubuntu at ubuntu:~$ sudo dmesg | grep rsyslog
[    2.816998] systemd[1]: unit_file_build_name_map: normal unit file: /usr/lib/systemd/system/rsyslog.service
[    5.588869] audit: type=1400 audit(1716388183.334:149): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="rsyslogd" pid=993 comm="apparmor_parser"
[    5.676353] audit: type=1400 audit(1716388183.422:150): apparmor="DENIED" operation="sendmsg" class="file" info="Failed name lookup - disconnected path" error=-13 profile="rsyslogd" name="systemd/notify" pid=1055 comm="rsyslogd" requested_mask="w" denied_mask="w" fsuid=102 ouid=0
[    5.676388] audit: type=1400 audit(1716388183.422:151): apparmor="DENIED" operation="sendmsg" class="file" info="Failed name lookup - disconnected path" error=-13 profile="rsyslogd" name="systemd/journal/dev-log" pid=1055 comm="rsyslogd" requested_mask="w" denied_mask="w" fsuid=102 ouid=0
[    5.676407] audit: type=1400 audit(1716388183.422:152): apparmor="DENIED" operation="sendmsg" class="file" info="Failed name lookup - disconnected path" error=-13 profile="rsyslogd" name="systemd/journal/dev-log" pid=1055 comm="rsyslogd" requested_mask="w" denied_mask="w" fsuid=102 ouid=0
[    5.676425] audit: type=1400 audit(1716388183.422:153): apparmor="DENIED" operation="sendmsg" class="file" info="Failed name lookup - disconnected path" error=-13 profile="rsyslogd" name="systemd/journal/dev-log" pid=1055 comm="rsyslogd" requested_mask="w" denied_mask="w" fsuid=102 ouid=0
[    5.676440] audit: type=1400 audit(1716388183.422:154): apparmor="DENIED" operation="sendmsg" class="file" info="Failed name lookup - disconnected path" error=-13 profile="rsyslogd" name="systemd/journal/dev-log" pid=1055 comm="rsyslogd" requested_mask="w" denied_mask="w" fsuid=102 ouid=0
[   95.610731] audit: type=1400 audit(1716388273.356:166): apparmor="DENIED" operation="sendmsg" class="file" info="Failed name lookup - disconnected path" error=-13 profile="rsyslogd" name="systemd/journal/dev-log" pid=1055 comm="rsyslogd" requested_mask="w" denied_mask="w" fsuid=102 ouid=0
[   95.974029] audit: type=1400 audit(1716388273.719:167): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="rsyslogd" pid=2072 comm="apparmor_parser"
[   96.010658] audit: type=1400 audit(1716388273.756:168): apparmor="DENIED" operation="sendmsg" class="file" info="Failed name lookup - disconnected path" error=-13 profile="rsyslogd" name="systemd/notify" pid=2073 comm="rsyslogd" requested_mask="w" denied_mask="w" fsuid=102 ouid=0
[   96.010664] audit: type=1400 audit(1716388273.756:169): apparmor="DENIED" operation="sendmsg" class="file" info="Failed name lookup - disconnected path" error=-13 profile="rsyslogd" name="systemd/journal/dev-log" pid=2073 comm="rsyslogd" requested_mask="w" denied_mask="w" fsuid=102 ouid=0
[   96.010666] audit: type=1400 audit(1716388273.756:170): apparmor="DENIED" operation="sendmsg" class="file" info="Failed name lookup - disconnected path" error=-13 profile="rsyslogd" name="systemd/journal/dev-log" pid=2073 comm="rsyslogd" requested_mask="w" denied_mask="w" fsuid=102 ouid=0
[   96.010669] audit: type=1400 audit(1716388273.756:171): apparmor="DENIED" operation="sendmsg" class="file" info="Failed name lookup - disconnected path" error=-13 profile="rsyslogd" name="systemd/journal/dev-log" pid=2073 comm="rsyslogd" requested_mask="w" denied_mask="w" fsuid=102 ouid=0
[   96.010670] audit: type=1400 audit(1716388273.756:172): apparmor="DENIED" operation="sendmsg" class="file" info="Failed name lookup - disconnected path" error=-13 profile="rsyslogd" name="systemd/journal/dev-log" pid=2073 comm="rsyslogd" requested_mask="w" denied_mask="w" fsuid=102 ouid=0
ubuntu at ubuntu:~$ apt policy systemd
systemd:
  Installed: 255.4-1ubuntu8
  Candidate: 255.4-1ubuntu8
  Version table:
     255.4-1ubuntu8.1 100
        100 http://archive.ubuntu.com/ubuntu noble-proposed/main amd64 Packages
 *** 255.4-1ubuntu8 500
        500 http://archive.ubuntu.com/ubuntu noble/main amd64 Packages
        100 /var/lib/dpkg/status

Now, I install systemd from noble-proposed, and then re-generate the initrd so that the patched systemd is in the initrd:

ubuntu at ubuntu:~$ sudo apt install systemd -y -t noble-proposed
[ ... ]
ubuntu at ubuntu:~$ sudo dracut --force
dracut[I]: Executing: /usr/bin/dracut --force
dracut[I]: Module 'mksh' will not be installed, because command 'mksh' could not be found!
dracut[I]: Module 'warpclock' will not be installed, because command 'hwclock' could not be found!
dracut[I]: Module 'systemd-pcrphase' will not be installed, because command '/usr/lib/systemd/systemd-pcrphase' could not be found!
dracut[I]: Module 'systemd-timesyncd' will not be installed, because command '/usr/lib/systemd/systemd-timesyncd' could not be found!
dracut[I]: Module 'modsign' will not be installed, because command 'keyctl' could not be found!
dracut[I]: Module 'dbus-broker' will not be installed, because command 'dbus-broker' could not be found!
dracut[I]: Module 'rngd' will not be installed, because command 'rngd' could not be found!
dracut[I]: Module 'plymouth' will not be installed, because command 'plymouth-set-default-theme' could not be found!
dracut[I]: Module 'btrfs' will not be installed, because command 'btrfs' could not be found!
dracut[I]: Module 'dmraid' will not be installed, because command 'dmraid' could not be found!
dracut[I]: Module 'multipath' will not be installed, because command 'multipath' could not be found!
dracut[I]: Module 'pcsc' will not be installed, because command 'pcscd' could not be found!
dracut[I]: Module 'tpm2-tss' will not be installed, because command 'tpm2' could not be found!
dracut[I]: Module 'nvmf' will not be installed, because command 'nvme' could not be found!
dracut[I]: Module 'biosdevname' will not be installed, because command 'biosdevname' could not be found!
dracut[I]: Module 'memstrack' will not be installed, because command 'memstrack' could not be found!
dracut[I]: memstrack is not available
dracut[I]: If you need to use rd.memdebug>=4, please install memstrack and procps-ng
dracut[I]: *** Including module: systemd ***
dracut[I]: *** Including module: systemd-initrd ***
dracut[I]: *** Including module: console-setup ***
dracut[I]: *** Including module: i18n ***
dracut[I]: *** Including module: crypt ***
dracut[I]: *** Including module: dm ***
dracut[I]: *** Including module: kernel-modules ***
dracut[I]: *** Including module: kernel-modules-extra ***
dracut[I]: *** Including module: lvm ***
dracut[I]: *** Including module: mdraid ***
dracut[I]: *** Including module: nvdimm ***
dracut[I]: *** Including module: overlay-root ***
dracut[I]: *** Including module: qemu ***
dracut[I]: *** Including module: lunmask ***
dracut[I]: *** Including module: resume ***
dracut[I]: *** Including module: rootfs-block ***
dracut[I]: *** Including module: terminfo ***
dracut[I]: *** Including module: udev-rules ***
dracut[I]: *** Including module: virtfs ***
dracut[I]: *** Including module: virtiofs ***
dracut[I]: *** Including module: dracut-systemd ***
dracut[I]: *** Including module: usrmount ***
dracut[I]: *** Including module: base ***
dracut[I]: *** Including module: fs-lib ***
dracut[I]: *** Including module: shutdown ***
dracut[I]: *** Including modules done ***
dracut[I]: *** Installing kernel module dependencies ***
dracut[I]: *** Installing kernel module dependencies done ***
dracut[I]: *** Resolving executable dependencies ***
dracut[I]: *** Resolving executable dependencies done ***
dracut[I]: *** Hardlinking files ***
dracut[I]: *** Hardlinking files done ***
dracut[I]: *** Generating early-microcode cpio image ***
dracut[I]: *** Constructing AuthenticAMD.bin ***
dracut[I]: *** Constructing GenuineIntel.bin ***
dracut[I]: *** Store current command line parameters ***
dracut[I]: *** Stripping files ***
dracut[I]: *** Stripping files done ***
dracut[I]: *** Creating image file '/boot/initrd.img-6.8.0-31-generic' ***
dracut[I]: Using auto-determined compression method 'pigz'
dracut[I]: *** Creating initramfs image file '/boot/initrd.img-6.8.0-31-generic' done ***
ubuntu at ubuntu:~$ sudo reboot

After the reboot:

ubuntu at ubuntu:~$ journalctl -b --grep "Switching root"
May 22 10:33:50 localhost @ystemctl[467]: Switching root - root: /sysroot; init: n/a
May 22 10:33:50 localhost systemd[1]: Switching root.
ubuntu at ubuntu:~$ sudo dmesg | grep rsyslog
[sudo] password for ubuntu: 
[    2.278177] systemd[1]: unit_file_build_name_map: normal unit file: /usr/lib/systemd/system/rsyslog.service
ubuntu at ubuntu:~$ systemctl status rsyslog
● rsyslog.service - System Logging Service
     Loaded: loaded (/usr/lib/systemd/system/rsyslog.service; enabled; preset: enabled)
     Active: active (running) since Wed 2024-05-22 10:33:53 EDT; 59s ago
TriggeredBy: ● syslog.socket
       Docs: man:rsyslogd(8)
             man:rsyslog.conf(5)
             https://www.rsyslog.com/doc/
   Main PID: 1055 (rsyslogd)
      Tasks: 4 (limit: 4608)
     Memory: 6.7M (peak: 7.0M)
        CPU: 513ms
     CGroup: /system.slice/rsyslog.service
             └─1055 /usr/sbin/rsyslogd -n -iNONE

May 22 10:33:53 ubuntu rsyslogd[1055]: rsyslogd's groupid changed to 102
May 22 10:33:53 ubuntu rsyslogd[1055]: rsyslogd's userid changed to 102
May 22 10:33:53 ubuntu rsyslogd[1055]: [origin software="rsyslogd" swVersion="8.2312.0" x-pid="1055" x-info="https://>
May 22 10:33:53 ubuntu systemd[1]: rsyslog.service: Got notification message from PID 1055 (READY=1)
May 22 10:33:53 ubuntu systemd[1]: rsyslog.service: Changed start -> running
May 22 10:33:53 ubuntu systemd[1]: rsyslog.service: Job 290 rsyslog.service/start finished, result=done
May 22 10:33:53 ubuntu systemd[1]: Started rsyslog.service - System Logging Service.
May 22 10:33:54 ubuntu systemd[1]: rsyslog.service: System call riscv_hwprobe is not known, ignoring.
May 22 10:33:54 ubuntu systemd[1]: /usr/lib/systemd/system/rsyslog.service:21: System call riscv_hwprobe is not known>
May 22 10:33:54 ubuntu systemd[1]: rsyslog.service: Changed dead -> running
ubuntu at ubuntu:~$ apt policy systemd
systemd:
  Installed: 255.4-1ubuntu8.1
  Candidate: 255.4-1ubuntu8.1
  Version table:
 *** 255.4-1ubuntu8.1 100
        100 http://archive.ubuntu.com/ubuntu noble-proposed/main amd64 Packages
        100 /var/lib/dpkg/status
     255.4-1ubuntu8 500
        500 http://archive.ubuntu.com/ubuntu noble/main amd64 Packages

Hence, with the patched systemd in the initrd, we no longer see the
AppArmor denials, and rsyslog starts normally.

** Tags removed: verification-needed-noble
** Tags added: verification-done-noble

-- 
You received this bug notification because you are a member of Ubuntu
Foundations Bugs, which is subscribed to rsyslog in Ubuntu.
https://bugs.launchpad.net/bugs/2064096

Title:
  Services fail to start in noble deployed with TPM+FDE

Status in apparmor package in Ubuntu:
  New
Status in cups package in Ubuntu:
  Confirmed
Status in rsyslog package in Ubuntu:
  Confirmed
Status in sssd package in Ubuntu:
  Confirmed
Status in systemd package in Ubuntu:
  Confirmed
Status in apparmor source package in Noble:
  New
Status in cups source package in Noble:
  New
Status in rsyslog source package in Noble:
  New
Status in sssd source package in Noble:
  New
Status in systemd source package in Noble:
  Fix Committed

Bug description:
  [Impact]

  On systems that have systemd in the initrd, after the switch root,
  services trying to access resources in /run (e.g. /run/systemd/notify)
  will get AppArmor denials. This is because as a part of the switch
  root, before the pivot_root(), the /run (and /proc, /sys, /dev) are
  "moved" with a bind mount. Hence the new /run has a different mount
  id, and AppArmor thinks that e.g. /run/systemd/notify is disconnected
  from the current mount tree.

  [Test Plan]

  The simplest way to test this is to use dracut on a classic Ubuntu
  system:

  1. Create a VM running Ubuntu 24.04 LTS. The virtualization implementation is not important.
  2. Install dracut, and then reboot.

  $ apt install -y dracut

  3. Once rebooted, verify that systemd did a switch root:

  $ journalctl -b --grep "Switching root"

  4. Check for rsyslog AppArmor denials:

  $ dmesg | grep rsyslog

  On an affected system, the denials will be present. With the patch,
  there should be no denials (or at least not related to accessing files
  in /run).

  [Where problems could occur]

  Using MS_MOVE rather than MS_BIND for /run during the switch root means that there is a brief time where /run (in the old root) is not available for units running before the pivot_root(). So, if we were to see problems, it would likely
  be related to problems with resources in /run, very close to the switch root timeframe. However, before noble, the switch root *is* done using MS_MOVE on /run (and /proc, /sys, and /dev), so have reasonable evidence that this is a safe change.

  [Other information]

  We only change the flags for /run because that is the filesystem that
  seems affected in practice. In particular, we leave /proc alone
  because code in systemd may use /proc between the time it is moved to
  the new root, but before the pivot_root(), which would be a riskier
  change.

  [Original Description]

  What's known so far:
  - 24.04 desktop deployed with TPM+FDE shows this bug
  - services confined with apparmor that need to access something in /run/systemd (like the notify socket) fail to do so, even if the apparmor profile is in complain mode. And the apparmor profile does already have rules to allow that access
  - only after running aa-disable <path> can the service start fine
  - paths logged by the apparmor DENIED or ALLOWED messages are missing the "/run" prefix from "/run/systemd/......".
  - When we add rules to the profile using "/systemd/...." (i.e., also dropping the /run prefix), then it works
  - other access in /run/systemd/ are also blocked, but the most noticeable one is the notify mechanism
  - comment #2 also states that azure CVM images are also impacted
  - comment #4 has instructions on how to create such a VM locally with LXD vms

  Original description follows:

  This might be related to #2064088

  The rsyslog service is continually timing out and restarting. If I use
  a service drop-in file and change the 'Type' from 'notify' to
  'simple', the service starts and appears to work normally.

  In the journal, I can see the attached apparmor errors. I can't make
  sense of them, but if it's a similar issue to #2064088, then I suspect
  apparmor is preventing the systemd notify function from alerting
  systemd that the service is up and running.

  ProblemType: Bug
  DistroRelease: Ubuntu 24.04
  Package: rsyslog 8.2312.0-3ubuntu9
  ProcVersionSignature: Ubuntu 6.8.0-31.31-generic 6.8.1
  Uname: Linux 6.8.0-31-generic x86_64
  ApportVersion: 2.28.1-0ubuntu2
  Architecture: amd64
  CasperMD5CheckMismatches: ./boot/grub/grub.cfg
  CasperMD5CheckResult: fail
  CurrentDesktop: ubuntu:GNOME
  Date: Mon Apr 29 10:37:46 2024
  ProcEnviron:
   LANG=en_GB.UTF-8
   PATH=(custom, no user)
   SHELL=/bin/bash
   TERM=xterm-256color
   XDG_RUNTIME_DIR=<set>
  SourcePackage: rsyslog
  UpgradeStatus: No upgrade log present (probably fresh install)

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/apparmor/+bug/2064096/+subscriptions