snapd.seeded.service never finishes on s390x when privileged or nested

Bug #1952084 reported by Christian Ehrhardt 
8
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Ubuntu on IBM z Systems
Undecided
Unassigned
snapd (Ubuntu)
Undecided
Unassigned

Bug Description

This seems like the return of the giant hogweed, ... umm bug 1944004 I meant.

The twist is that it only happens with some conditions met:
Constraints that I found from my testing so far:
 1. Fails on s390x, but not on x86 (but that was Focal host, see #4)
 2. Fails on impish, but not B/F/H
 3. Only happens if security.nesting or security.privileged are true
 4. happens on Hirsute Host, but not Impish (details see below)

## Host versions
I've run this on a Hirsite host with 5.11.0-16-generic

FHeimes was so kind to cross test this on his machine, he found the same behavior on Impish were it worked fine. He then tried it on a Hirsute host of his which failed like mine.

I have had (for other reasons) lxd from channel 4.0/stable, switched that to latest/stable (4.20 atm) and that failed as well. Fheimes also tried both, same behavior (so we can ignore the LXD version)

This made me try
1. reboot (Hirsute still) => still failing
2. upgrade to impish no reboot => still failing
3. reboot into impish (kernel 5.13.0-22) => Works
4. impish but forcing an H kernel (5.11.0-41) => Works
5. impish but with the older H kernel (5.11.0-16) => Works

So it is something in the Impish userspace that makes the issue go away, but what?

## Reproducer

#!/bin/bash
set -uxe
lxc stop "i-runlevel-test" || true
lxc delete "i-runlevel-test" || true
lxc profile delete "test" || true
lxc profile create "test"
# Any of the two settings alone break it as well
cat << EOF > test_profile.yaml
name: test
config:
        security.nesting: "true"
        security.privileged: "true"
EOF
lxc profile edit "test" < "test_profile.yaml"
lxc launch ubuntu-daily:impish/s390x "i-runlevel-test" --profile default --profile "test"
lxc info "i-runlevel-test"
lxc profile show "test"
echo "Wait and check runlevel"
for w in $(seq 1 11); do
 sleep 1m;
 echo "Check i-runlevel-test after $w minutes"
 lxc exec "i-runlevel-test" runlevel || true
done
lxc exec "i-runlevel-test" -- systemctl status snapd.seeded
lxc exec "i-runlevel-test" -- snap debug seeding

In the container I see it fail by the seeding failing to complete:

$ lxc exec i-runlevel-test bash
root@i-runlevel-test:~# systemctl status snapd.seeded
● snapd.seeded.service - Wait until snapd is fully seeded
     Loaded: loaded (/lib/systemd/system/snapd.seeded.service; enabled; vendor preset: enabled)
     Active: activating (start) since Wed 2021-11-24 09:09:31 UTC; 1min 37s ago
   Main PID: 289 (snap)
        CPU: 177ms
     CGroup: /system.slice/snapd.seeded.service
             └─289 /usr/bin/snap wait system seed.loaded

Nov 24 09:09:31 i-runlevel-test systemd[1]: Starting Wait until snapd is fully seeded...

The above will hang for hours and never complete.

Debug seeding initially just shows it waits (~3 min after start)
Nov 24 09:09:31 i-runlevel-test systemd[1]: Starting Wait until snapd is fully seeded...
root@i-runlevel-test:~# snap debug seeding
seeded: false
preseeded: true
image-preseeding: 3.755s
seed-completion: –

Since it was apparmor related last time here a filtered journal of the host:

$ journalctl -b 0 --grep i-runlevel-test_ --no-pager
-- Journal begins at Sun 2021-02-21 14:16:29 UTC, ends at Wed 2021-11-24 09:17:01 UTC. --
Nov 24 09:07:09 s1lp5 audit[3314910]: AVC apparmor="STATUS" operation="profile_load" profile="unconfined" name="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>" pid=3314910 comm="apparmor_parser"
Nov 24 09:07:09 s1lp5 kernel: audit: type=1400 audit(1637744829.266:63232): apparmor="STATUS" operation="profile_load" profile="unconfined" name="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>" pid=3314910 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 audit[3315173]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="lsb_release" pid=3315173 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 kernel: audit: type=1400 audit(1637744830.086:63233): apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="lsb_release" pid=3315173 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 audit[3315174]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="nvidia_modprobe" pid=3315174 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 audit[3315174]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="nvidia_modprobe//kmod" pid=3315174 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 kernel: audit: type=1400 audit(1637744830.106:63234): apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="nvidia_modprobe" pid=3315174 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 kernel: audit: type=1400 audit(1637744830.106:63235): apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="nvidia_modprobe//kmod" pid=3315174 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 audit[3315176]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="/usr/bin/man" pid=3315176 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 kernel: audit: type=1400 audit(1637744830.146:63236): apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="/usr/bin/man" pid=3315176 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 audit[3315176]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="man_filter" pid=3315176 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 audit[3315176]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="man_groff" pid=3315176 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 kernel: audit: type=1400 audit(1637744830.156:63237): apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="man_filter" pid=3315176 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 kernel: audit: type=1400 audit(1637744830.156:63238): apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="man_groff" pid=3315176 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 audit[3315177]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="tcpdump" pid=3315177 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 kernel: audit: type=1400 audit(1637744830.206:63239): apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="tcpdump" pid=3315177 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 audit[3315175]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="/usr/lib/NetworkManager/nm-dhcp-client.action" pid=3315175 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 kernel: audit: type=1400 audit(1637744830.346:63240): apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="/usr/lib/NetworkManager/nm-dhcp-client.action" pid=3315175 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 audit[3315175]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="/usr/lib/NetworkManager/nm-dhcp-helper" pid=3315175 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 audit[3315175]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="/usr/lib/connman/scripts/dhclient-script" pid=3315175 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 audit[3315175]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="/{,usr/}sbin/dhclient" pid=3315175 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 kernel: audit: type=1400 audit(1637744830.356:63241): apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="/usr/lib/NetworkManager/nm-dhcp-helper" pid=3315175 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 audit[3315178]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="/usr/lib/snapd/snap-confine" pid=3315178 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 audit[3315178]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="/usr/lib/snapd/snap-confine//mount-namespace-capture-helper" pid=3315178 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 audit[3315212]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap-update-ns.lxd" pid=3315212 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 audit[3315219]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.hook.install" pid=3315219 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 audit[3315216]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.check-kernel" pid=3315216 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 audit[3315222]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.lxc-to-lxd" pid=3315222 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 audit[3315220]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.hook.remove" pid=3315220 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 audit[3315218]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.hook.configure" pid=3315218 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 audit[3315214]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.benchmark" pid=3315214 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 audit[3315223]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.lxd" pid=3315223 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 audit[3315213]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.activate" pid=3315213 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 audit[3315224]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.migrate" pid=3315224 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 audit[3315217]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.daemon" pid=3315217 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 audit[3315221]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.lxc" pid=3315221 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 audit[3315215]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.buginfo" pid=3315215 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 audit[3315211]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="/snap/snapd/13639/usr/lib/snapd/snap-confine" pid=3315211 comm="apparmor_parser"
Nov 24 09:07:10 s1lp5 audit[3315211]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="/snap/snapd/13639/usr/lib/snapd/snap-confine//mount-namespace-capture-helper" pid=3315211 comm="apparmor_parser"
Nov 24 09:07:13 s1lp5 audit[3315385]: AVC apparmor="DENIED" operation="file_inherit" namespace="root//lxd-i-runlevel-test_<var-snap-lxd-common-lxd>" profile="/usr/lib/snapd/snap-confine" pid=3315385 comm="snap-confine" family="netlink" sock_type="raw" protocol=15 requested_mask="send receive" denied_mask="send receive"
Nov 24 09:07:13 s1lp5 audit[3315405]: AVC apparmor="DENIED" operation="file_inherit" namespace="root//lxd-i-runlevel-test_<var-snap-lxd-common-lxd>" profile="snap-update-ns.lxd" name="/apparmor/.null" pid=3315405 comm="6" requested_mask="wr" denied_mask="wr" fsuid=0 ouid=0
Nov 24 09:09:26 s1lp5 audit[3316921]: AVC apparmor="STATUS" operation="profile_remove" profile="unconfined" name="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>" pid=3316921 comm="apparmor_parser"
Nov 24 09:09:26 s1lp5 kernel: audit: type=1400 audit(1637744966.256:63263): apparmor="STATUS" operation="profile_remove" profile="unconfined" name="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>" pid=3316921 comm="apparmor_parser"
Nov 24 09:09:27 s1lp5 audit[3317820]: AVC apparmor="STATUS" operation="profile_load" profile="unconfined" name="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>" pid=3317820 comm="apparmor_parser"
Nov 24 09:09:27 s1lp5 kernel: audit: type=1400 audit(1637744967.506:63264): apparmor="STATUS" operation="profile_load" profile="unconfined" name="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>" pid=3317820 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 audit[3318105]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="lsb_release" pid=3318105 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 kernel: audit: type=1400 audit(1637744968.296:63265): apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="lsb_release" pid=3318105 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 audit[3318106]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="nvidia_modprobe" pid=3318106 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 audit[3318106]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="nvidia_modprobe//kmod" pid=3318106 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 kernel: audit: type=1400 audit(1637744968.316:63266): apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="nvidia_modprobe" pid=3318106 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 kernel: audit: type=1400 audit(1637744968.316:63267): apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="nvidia_modprobe//kmod" pid=3318106 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 audit[3318108]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="/usr/bin/man" pid=3318108 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 audit[3318108]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="man_filter" pid=3318108 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 audit[3318108]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="man_groff" pid=3318108 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 kernel: audit: type=1400 audit(1637744968.366:63268): apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="/usr/bin/man" pid=3318108 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 kernel: audit: type=1400 audit(1637744968.366:63269): apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="man_filter" pid=3318108 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 kernel: audit: type=1400 audit(1637744968.366:63270): apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="man_groff" pid=3318108 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 audit[3318109]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="tcpdump" pid=3318109 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 kernel: audit: type=1400 audit(1637744968.426:63271): apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="tcpdump" pid=3318109 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 audit[3318107]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="/usr/lib/NetworkManager/nm-dhcp-client.action" pid=3318107 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 audit[3318107]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="/usr/lib/NetworkManager/nm-dhcp-helper" pid=3318107 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 audit[3318107]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="/usr/lib/connman/scripts/dhclient-script" pid=3318107 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 kernel: audit: type=1400 audit(1637744968.566:63272): apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="/usr/lib/NetworkManager/nm-dhcp-client.action" pid=3318107 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 audit[3318107]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="/{,usr/}sbin/dhclient" pid=3318107 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 audit[3318110]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="/usr/lib/snapd/snap-confine" pid=3318110 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 audit[3318110]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="/usr/lib/snapd/snap-confine//mount-namespace-capture-helper" pid=3318110 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 audit[3318145]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap-update-ns.lxd" pid=3318145 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 audit[3318152]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.hook.install" pid=3318152 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 audit[3318149]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.check-kernel" pid=3318149 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 audit[3318147]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.benchmark" pid=3318147 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 audit[3318155]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.lxc-to-lxd" pid=3318155 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 audit[3318156]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.lxd" pid=3318156 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 audit[3318148]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.buginfo" pid=3318148 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 audit[3318153]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.hook.remove" pid=3318153 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 audit[3318157]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.migrate" pid=3318157 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 audit[3318146]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.activate" pid=3318146 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 audit[3318154]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.lxc" pid=3318154 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 audit[3318150]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.daemon" pid=3318150 comm="apparmor_parser"
Nov 24 09:09:28 s1lp5 audit[3318151]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.hook.configure" pid=3318151 comm="apparmor_parser"
Nov 24 09:09:29 s1lp5 audit[3318144]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="/snap/snapd/13639/usr/lib/snapd/snap-confine" pid=3318144 comm="apparmor_parser"
Nov 24 09:09:29 s1lp5 audit[3318144]: AVC apparmor="STATUS" operation="profile_load" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="/snap/snapd/13639/usr/lib/snapd/snap-confine//mount-namespace-capture-helper" pid=3318144 comm="apparmor_parser"
Nov 24 09:09:32 s1lp5 audit[3318315]: AVC apparmor="DENIED" operation="file_inherit" namespace="root//lxd-i-runlevel-test_<var-snap-lxd-common-lxd>" profile="/usr/lib/snapd/snap-confine" pid=3318315 comm="snap-confine" family="netlink" sock_type="raw" protocol=15 requested_mask="send receive" denied_mask="send receive"
Nov 24 09:09:32 s1lp5 kernel: audit: type=1400 audit(1637744972.396:63293): apparmor="DENIED" operation="file_inherit" namespace="root//lxd-i-runlevel-test_<var-snap-lxd-common-lxd>" profile="/usr/lib/snapd/snap-confine" pid=3318315 comm="snap-confine" family="netlink" sock_type="raw" protocol=15 requested_mask="send receive" denied_mask="send receive"
Nov 24 09:09:32 s1lp5 audit[3318338]: AVC apparmor="DENIED" operation="file_inherit" namespace="root//lxd-i-runlevel-test_<var-snap-lxd-common-lxd>" profile="snap-update-ns.lxd" name="/apparmor/.null" pid=3318338 comm="6" requested_mask="wr" denied_mask="wr" fsuid=0 ouid=0
Nov 24 09:09:32 s1lp5 kernel: audit: type=1400 audit(1637744972.406:63294): apparmor="DENIED" operation="file_inherit" namespace="root//lxd-i-runlevel-test_<var-snap-lxd-common-lxd>" profile="snap-update-ns.lxd" name="/apparmor/.null" pid=3318338 comm="6" requested_mask="wr" denied_mask="wr" fsuid=0 ouid=0

It seems after 10 minutes something gives up and then enters (but that might be a red herring due some cleanup after 10 minutes)

● snapd.seeded.service - Wait until snapd is fully seeded
     Loaded: loaded (/lib/systemd/system/snapd.seeded.service; enabled; vendor preset: enabled)
     Active: activating (start) since Wed 2021-11-24 09:09:31 UTC; 11min ago
   Main PID: 289 (snap)
        CPU: 870ms
     CGroup: /system.slice/snapd.seeded.service
             └─289 /usr/bin/snap wait system seed.loaded

Nov 24 09:09:31 i-runlevel-test systemd[1]: Starting Wait until snapd is fully seeded...
seeded: false
seed-error: |
  cannot perform the following tasks:
  - Setup snap "snapd" (13639) security profiles (cannot setup udev for snap "snapd": cannot reload
  udev rules: exit status 1
  udev output:
  Failed to send reload request: No such file or directory
  )
  - Setup snap "snapd" (13639) security profiles (cannot reload udev rules: exit status 1
  udev output:
  Failed to send reload request: No such file or directory
  )
  - Run install hook of "lxd" snap if present (run hook "install": <exceeded maximum runtime of
  10m0s>)
preseeded: true
image-preseeding: 3.755s
seed-completion: –

At this 10 minute mark I get another few journal entries (again could be a red herring as by the time it already waited 10 minutes which isn't right)

Nov 24 09:19:32 s1lp5 audit[3320156]: AVC apparmor="STATUS" operation="profile_replace" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="/snap/snapd/13639/usr/lib/snapd/snap-confine" pid=3320156 comm="apparmor_parser"
Nov 24 09:19:32 s1lp5 kernel: audit: type=1400 audit(1637745572.367:63295): apparmor="STATUS" operation="profile_replace" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="/snap/snapd/13639/usr/lib/snapd/snap-confine" pid=3320156 comm="apparmor_parser"
Nov 24 09:19:32 s1lp5 audit[3320156]: AVC apparmor="STATUS" operation="profile_replace" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="/snap/snapd/13639/usr/lib/snapd/snap-confine//mount-namespace-capture-helper" pid=3320156 comm="apparmor_parser"
Nov 24 09:19:32 s1lp5 audit[3320158]: AVC apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap-update-ns.lxd" pid=3320158 comm="apparmor_parser"
Nov 24 09:19:32 s1lp5 audit[3320165]: AVC apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.hook.install" pid=3320165 comm="apparmor_parser"
Nov 24 09:19:32 s1lp5 audit[3320160]: AVC apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.benchmark" pid=3320160 comm="apparmor_parser"
Nov 24 09:19:32 s1lp5 audit[3320162]: AVC apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.check-kernel" pid=3320162 comm="apparmor_parser"
Nov 24 09:19:32 s1lp5 audit[3320161]: AVC apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.buginfo" pid=3320161 comm="apparmor_parser"
Nov 24 09:19:32 s1lp5 audit[3320166]: AVC apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.hook.remove" pid=3320166 comm="apparmor_parser"
Nov 24 09:19:32 s1lp5 audit[3320167]: AVC apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.lxc" pid=3320167 comm="apparmor_parser"
Nov 24 09:19:32 s1lp5 kernel: audit: type=1400 audit(1637745572.457:63296): apparmor="STATUS" operation="profile_replace" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="/snap/snapd/13639/usr/lib/snapd/snap-confine//mount-namespace-capture-helper" pid=3320156 comm="apparmor_parser"
Nov 24 09:19:32 s1lp5 kernel: audit: type=1400 audit(1637745572.457:63297): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap-update-ns.lxd" pid=3320158 comm="apparmor_parser"
Nov 24 09:19:32 s1lp5 kernel: audit: type=1400 audit(1637745572.457:63298): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.hook.install" pid=3320165 comm="apparmor_parser"
Nov 24 09:19:32 s1lp5 kernel: audit: type=1400 audit(1637745572.457:63299): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.benchmark" pid=3320160 comm="apparmor_parser"
Nov 24 09:19:32 s1lp5 kernel: audit: type=1400 audit(1637745572.457:63300): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.check-kernel" pid=3320162 comm="apparmor_parser"
Nov 24 09:19:32 s1lp5 kernel: audit: type=1400 audit(1637745572.457:63301): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.buginfo" pid=3320161 comm="apparmor_parser"
Nov 24 09:19:32 s1lp5 kernel: audit: type=1400 audit(1637745572.457:63302): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.hook.remove" pid=3320166 comm="apparmor_parser"
Nov 24 09:19:32 s1lp5 kernel: audit: type=1400 audit(1637745572.457:63303): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.lxc" pid=3320167 comm="apparmor_parser"
Nov 24 09:19:32 s1lp5 audit[3320170]: AVC apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.migrate" pid=3320170 comm="apparmor_parser"
Nov 24 09:19:32 s1lp5 audit[3320159]: AVC apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.activate" pid=3320159 comm="apparmor_parser"
Nov 24 09:19:32 s1lp5 audit[3320169]: AVC apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.lxd" pid=3320169 comm="apparmor_parser"
Nov 24 09:19:32 s1lp5 audit[3320168]: AVC apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.lxc-to-lxd" pid=3320168 comm="apparmor_parser"
Nov 24 09:19:32 s1lp5 audit[3320163]: AVC apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.daemon" pid=3320163 comm="apparmor_parser"
Nov 24 09:19:32 s1lp5 audit[3320164]: AVC apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.hook.configure" pid=3320164 comm="apparmor_parser"
Nov 24 09:19:32 s1lp5 kernel: audit: type=1400 audit(1637745572.467:63304): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" label="lxd-i-runlevel-test_</var/snap/lxd/common/lxd>//&:lxd-i-runlevel-test_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.migrate" pid=3320170 comm="apparmor_parser"

Frank Heimes (fheimes)
tags: added: s390x
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers