Comment 4 for bug 1927098

Revision history for this message
John A Meinel (jameinel) wrote :

I then lxc exec into that container to do:
$ snap refresh juju-db --channel 4.0/candidate

to move from 4.0.9 to 4.0.23
This still leaves me with a juju apiserver that doesn't respond, so I run
$ systemctl restart jujud-machine-0

Even with the 4.0.23 snap, I still see the same syslog DENIED messages. So it is consistent with even a rebuilt snap.

I don't think it is safe to switch to the 4.4.5 snap (since that would corrupt the DB), but just to see if it makes the errors go away:
root@juju-97ff2b-0:~# snap refresh juju-db --channel 4.4
error: cannot perform the following tasks:
- Mount snap "juju-db" (71) (cannot validate license "SSPL-1.0": unknown license: SSPL-1.0)

well, that means my snapd is also out of date:
root@juju-97ff2b-0:~# snap refresh snapd
2021-06-04T14:49:30Z INFO Waiting for automatic snapd restart...
snapd 2.50.1 from Canonical✓ refreshed

that, in itself, did not fix the apparmor issues

root@juju-97ff2b-0:~# snap refresh juju-db --channel 4.0/stable
juju-db (4.0/stable) 4.0.9 from Canonical Juju QA Bot (juju-qa) refreshed

$ systemctl restart jujud-machine-0

the errors are still happening, back to candidate?

Jun 4 10:52:30 focal kernel: [1156807.047474] audit: type=1400 audit(1622818350.139:1838962): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" label="lxd-juju-97ff2b-0_</var/snap/lxd/common/lxd>//&:lxd-juju-97ff2b-0_<var-snap-lxd-common-lxd>:unconfined" name="/snap/snapd/12057/usr/lib/snapd/snap-confine" pid=3427374 comm="apparmor_parser"
Jun 4 10:52:30 focal kernel: [1156807.047480] audit: type=1400 audit(1622818350.139:1838963): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" label="lxd-juju-97ff2b-0_</var/snap/lxd/common/lxd>//&:lxd-juju-97ff2b-0_<var-snap-lxd-common-lxd>:unconfined" name="/snap/snapd/12057/usr/lib/snapd/snap-confine//mount-namespace-capture-helper" pid=3427374 comm="apparmor_parser"
Jun 4 10:52:30 focal kernel: [1156807.156300] audit: type=1400 audit(1622818350.247:1838964): apparmor="STATUS" operation="profile_replace" label="lxd-juju-97ff2b-0_</var/snap/lxd/common/lxd>//&:lxd-juju-97ff2b-0_<var-snap-lxd-common-lxd>:unconfined" name="snap.juju-db.hook.configure" pid=3427377 comm="apparmor_parser"
Jun 4 10:52:30 focal kernel: [1156807.158750] audit: type=1400 audit(1622818350.251:1838965): apparmor="STATUS" operation="profile_replace" label="lxd-juju-97ff2b-0_</var/snap/lxd/common/lxd>//&:lxd-juju-97ff2b-0_<var-snap-lxd-common-lxd>:unconfined" name="snap.juju-db.hook.install" pid=3427378 comm="apparmor_parser"

It does seem to consider a new apparmor profile, but it seems to say there is no actual difference.
Jun 4 10:52:30 focal kernel: [1156807.204794] audit: type=1400 audit(1622818350.299:1838969): apparmor="STATUS" operation="profile_replace" label="lxd-juju-97ff2b-0_</var/snap/lxd/common/lxd>//&:lxd-juju-97ff2b-0_<var-snap-lxd-common-lxd>:unconfined" name="snap.juju-db.mongod" pid=3427380 comm="apparmor_parser"

Note that the error do stop until I restart jujud-machine-0

Right at the beginning after restart I see some other things that are denied:
Jun 4 10:54:31 focal kernel: [1156928.177399] audit: type=1400 audit(1622818471.275:1838976): apparmor="DENIED" operation="file_inherit" namespace="root//lxd-juju-97ff2b-0_<var-snap-lxd-common-lxd>" profile="/snap/snapd/12057/usr/lib/snapd/snap-confine" pid=3428342 comm="snap-confine" family="netlink" sock_type="raw" protocol=15 requested_mask="send receive" denied_mask="send receive"
Jun 4 10:54:31 focal kernel: [1156928.182426] audit: type=1400 audit(1622818471.279:1838977): apparmor="DENIED" operation="file_inherit" namespace="root//lxd-juju-97ff2b-0_<var-snap-lxd-common-lxd>" profile="snap.juju-db.hook.configure" name="/apparmor/.null" pid=3428342 comm="snap-exec" requested_mask="wr" denied_mask="wr" fsuid=1000000 ouid=0
Jun 4 10:54:33 focal kernel: [1156930.069462] audit: type=1400 audit(1622818473.167:1838978): apparmor="DENIED" operation="open" namespace="root//lxd-juju-97ff2b-0_<var-snap-lxd-common-lxd>" profile="snap.juju-db.daemon" name="/sys/block/" pid=3428428 comm="mongod" requested_mask="r" denied_mask="r" fsuid=1000000 ouid=0
Jun 4 10:54:34 focal kernel: [1156930.916199] audit: type=1400 audit(1622818474.011:1838979): apparmor="DENIED" operation="open" namespace="root//lxd-juju-97ff2b-0_<var-snap-lxd-common-lxd>" profile="snap.juju-db.daemon" name="/proc/6443/net/netstat" pid=3428428 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=1000000 ouid=1000000
Jun 4 10:54:34 focal kernel: [1156930.916211] audit: type=1400 audit(1622818474.011:1838980): apparmor="DENIED" operation="open" namespace="root//lxd-juju-97ff2b-0_<var-snap-lxd-common-lxd>" profile="snap.juju-db.daemon" name="/proc/6443/net/snmp" pid=3428428 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=1000000 ouid=1000000
Jun 4 10:54:34 focal kernel: [1156930.916217] audit: type=1400 audit(1622818474.011:1838981): apparmor="DENIED" operation="open" namespace="root//lxd-juju-97ff2b-0_<var-snap-lxd-common-lxd>" profile="snap.juju-db.daemon" name="/proc/vmstat" pid=3428428 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=1000000 ouid=0

But those aren't triggered approximately every second.

I do see the ongoing net/stat issues, and I did confirm (again) that
# pgrep mongod
6443
matches
Jun 4 10:55:32 focal kernel: [1156988.903111] audit: type=1400 audit(1622818531.998:1839153): apparmor="DENIED" operation="open" namespace="root//lxd-juju-97ff2b-0_<var-snap-lxd-common-lxd>" profile="snap.juju-db.daemon" name="/proc/6443/net/netstat" pid=3428428 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=1000000 ouid=1000000

And outside the container:
$ pgrep mongod
3428428

so the log line says it is denying 'pid=3428428' from reading '/proc/6443' which very much matches the pid inside and outside of the container.

And now to try 4.4
root@juju-97ff2b-0:~# snap refresh juju-db --channel 4.4

root@juju-97ff2b-0:~# systemctl restart jujud-machine-0

At this point 'pgrep mongod' shows nothing running, so as expected, it isn't a fair test.