snap.juju-db.daemon Apparmor profile causes excessive logging

[Simon Déziel]

Having 'snap install juju --classic' yesterday my logs are filled with Apparmor denials:

$ journalctl -o cat -b0 --grep snap.juju-db.daemon | grep -cF 'apparmor="DENIED"'
136138

Those are all about /proc/$PID/net/{netstat,snmp}:

$ journalctl -o cat -b0 --grep snap.juju-db.daemon | grep -F 'apparmor="DENIED"' | tail -n 4
audit: type=1400 audit(1620133548.999:75999): apparmor="DENIED" operation="open" namespace="root//lxd-juju-d24df9-0_<var-snap-lxd-common-lxd>" profile="snap.juju-db.daemon" name="/proc/3219/net/netstat" pid=1605657 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=1000000 ouid=1000000
audit: type=1400 audit(1620133548.999:76000): apparmor="DENIED" operation="open" namespace="root//lxd-juju-d24df9-0_<var-snap-lxd-common-lxd>" profile="snap.juju-db.daemon" name="/proc/3219/net/snmp" pid=1605657 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=1000000 ouid=1000000
AVC apparmor="DENIED" operation="open" namespace="root//lxd-juju-d24df9-0_<var-snap-lxd-common-lxd>" profile="snap.juju-db.daemon" name="/proc/3219/net/netstat" pid=1605657 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=1000000 ouid=1000000
AVC apparmor="DENIED" operation="open" namespace="root//lxd-juju-d24df9-0_<var-snap-lxd-common-lxd>" profile="snap.juju-db.daemon" name="/proc/3219/net/snmp" pid=1605657 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=1000000 ouid=1000000

Additional information:
$ snap info juju | grep installed
installed: 2.9.0 (16132) 99MB classic

$ lsb_release -rd
Description: Ubuntu 20.04.2 LTS
Release: 20.04

$ uname -a
Linux simon-lemur 5.8.0-50-generic #56~20.04.1-Ubuntu SMP Mon Apr 12 21:46:35 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux

[Simon Richardson (simonrichardson)]

I'm marking this as incomplete, as I'm trying to reproduce this. I'm missing some information about how to trigger this (time element or deployment).

Can we get some information about what provider was bootstrapped (assuming localhost LXD, what version?) and the type of deployment that occurred. Additionally, was the journal logs captured on the controller machine?

[John A Meinel (jameinel)]

bootstrapping juju with mongodb from a snap into an LXD container was sufficient for me to see these messages in my syslog

[John A Meinel (jameinel)]

So inside of a Focal VM, I just did:

$ /snap/bin/juju --version
2.9.4-ubuntu-amd64
$ /snap/bin/juju bootstrap lxd lxd --bootstrap-series focal
Creating Juju controller "lxd" on lxd/default
Looking for packaged Juju agent version 2.9.4 for amd64
No packaged binary found, preparing local Juju agent binary
To configure your system to better support LXD containers, please see: https://github.com/lxc/lxd/blob/master/doc/production-setup.md
Launching controller instance(s) on lxd/default...
 - juju-97ff2b-0 (arch=amd64)
Installing Juju agent on bootstrap instance
Fetching Juju Dashboard 0.7.1
Waiting for address
Attempting to connect to 10.5.24.169:22
Connected to 10.5.24.169
Running machine configuration script...
Bootstrap agent now started
Contacting Juju controller at 10.5.24.169 to verify accessibility...

Bootstrap complete, controller "lxd" is now available
Controller machines are in the "controller" model
Initial model "default" added

And now in /var/log/syslog I'm getting:
Jun 4 10:40:32 focal kernel: [1156088.912281] audit: type=1400 audit(1622817632.004:1837714): apparmor="DENIED" operation="open" namespace="root//lxd-juju-97ff2b-0_<var-snap-lxd-common-lxd>" profile="snap.juju-db.daemon" name="/proc/3732/net/netstat" pid=3413485 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=1000000 ouid=1000000
Jun 4 10:40:32 focal kernel: [1156088.912293] audit: type=1400 audit(1622817632.004:1837715): apparmor="DENIED" operation="open" namespace="root//lxd-juju-97ff2b-0_<var-snap-lxd-common-lxd>" profile="snap.juju-db.daemon" name="/proc/3732/net/snmp" pid=3413485 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=1000000 ouid=1000000
Jun 4 10:40:33 focal kernel: [1156089.914841] audit: type=1400 audit(1622817633.008:1837716): apparmor="DENIED" operation="open" namespace="root//lxd-juju-97ff2b-0_<var-snap-lxd-common-lxd>" profile="snap.juju-db.daemon" name="/proc/3732/net/netstat" pid=3413485 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=1000000 ouid=1000000
Jun 4 10:40:33 focal kernel: [1156089.914855] audit: type=1400 audit(1622817633.008:1837717): apparmor="DENIED" operation="open" namespace="root//lxd-juju-97ff2b-0_<var-snap-lxd-common-lxd>" profile="snap.juju-db.daemon" name="/proc/3732/net/snmp" pid=3413485 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=1000000 ouid=1000000
Jun 4 10:40:35 focal kernel: [1156091.909630] kauditd_printk_skb: 2 callbacks suppressed
Jun 4 10:40:35 focal kernel: [1156091.909633] audit: type=1400 audit(1622817635.004:1837720): apparmor="DENIED" operation="open" namespace="root//lxd-juju-97ff2b-0_<var-snap-lxd-common-lxd>" profile="snap.juju-db.daemon" name="/proc/3732/net/netstat" pid=3413485 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=1000000 ouid=1000000
Jun 4 10:40:35 focal kernel: [1156091.909640] audit: type=1400 audit(1622817635.004:1837721): apparmor="DENIED" operation="open" namespace="root//lxd-juju-97ff2b-0_<var-snap-lxd-common-lxd>" profile="snap.juju-db.daemon" name="/proc/3732/net/snmp" pid=3413485 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=1000000 ouid=1000000
Jun 4 10:40:36 focal kernel: [1156092.904198] audit: type=1400 audit(1622817635.996:1837722): ap...

[John A Meinel (jameinel)]

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: ...

[Jon Seager (jnsgruk)]

FWIW, my machine also suffers with this, so happy to help with any extra info needed. If I have a controller bootstrapped on LXD, I get this issue.

Right now, my machine is:

Ubuntu 21.04
Juju 2.9.14-ubuntu-amd64
LXD 4.18

[Branislav Neskovic (branislav.neskovic)]

Hi, we have the same issue but controller is not on LXD.

Sep 23 10:18:18 controller kernel: [1118002.152227] audit: type=1400 audit(1632385097.999:2213256): apparmor="DENIED" operation="open" profile="snap.juju-db.daemon" name="/proc/20311/net/snmp" pid=20311 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Sep 23 10:18:19 controller kernel: [1118003.151739] audit: type=1400 audit(1632385098.999:2213257): apparmor="DENIED" operation="open" profile="snap.juju-db.daemon" name="/proc/20311/net/netstat" pid=20311 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Sep 23 10:18:19 controller kernel: [1118003.151981] audit: type=1400 audit(1632385098.999:2213258): apparmor="DENIED" operation="open" profile="snap.juju-db.daemon" name="/proc/20311/net/snmp" pid=20311 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Sep 23 10:18:20 controller kernel: [1118004.151879] audit: type=1400 audit(1632385099.999:2213259): apparmor="DENIED" operation="open" profile="snap.juju-db.daemon" name="/proc/20311/net/netstat" pid=20311 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Sep 23 10:18:20 controller kernel: [1118004.152381] audit: type=1400 audit(1632385099.999:2213260): apparmor="DENIED" operation="open" profile="snap.juju-db.daemon" name="/proc/20311/net/snmp" pid=20311 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0

[Ian Booth (wallyworld)]

we need to add and connect 2 interfaces:
- network-observer
- system-observe

See https://forum.snapcraft.io/t/auto-connect-interfaces-request-for-juju-db-snap/26841

An issue will be updating the juju-db snap in the 4.0 channel since a snap refresh restart mongod and juju 2.8 and earlier need a controller restart to get going again.

[John A Meinel (jameinel)]

https://github.com/juju/juju-db-snap/pull/23
https://github.com/juju/juju-db-snap/pull/24
https://github.com/juju/juju-db-snap/pull/25

are the PRs to add the interfaces for the snaps.

[Ian Booth (wallyworld)]

We now have the necessary auto connect exceptions pushed through for these new interfaces.

We can't yet update the 4.0 stable snap as the refresh will stop/start mongo and break 2.8 and early 2.9 controllers. But you can bootstrap using the candidate 4.0 snap to get the fix

juju bootstrap -config juju-db-snap-channel=4.0/candidate

[Ian Booth (wallyworld)]

I bootstrapped a 2.8 and 2.9 controller using the candidate juju-db snap and the ever increasing apparmor denials are gone. We'll plan for a stable juju-db snap upgrade but will need to give notice so that people can be aware that their controller agents will need to be restarted.

Marking as fix committed as the key snap work is done.