[Bug 1723900] Re: unbound systemctl (re)start fails due to Apparmor profile issue
Max
1723900 at bugs.launchpad.net
Sun Jan 28 13:45:02 UTC 2018
Same issue in Ubuntu 18.04 alpha
And dmesg is spammed full with messages like:
==
[ 458.960479] audit: type=1400 audit(1517146114.040:20): apparmor="DENIED" operation="sendmsg" profile="/usr/sbin/unbound" name="/run/systemd/notify" pid=594 comm="unbound" requested_mask="w" denied_mask="w" fsuid=108 ouid=0
[ 459.261996] audit: type=1400 audit(1517146114.342:21): apparmor="DENIED" operation="sendmsg" profile="/usr/sbin/unbound" name="/run/systemd/notify" pid=603 comm="unbound" requested_mask="w" denied_mask="w" fsuid=108 ouid=0
[ 549.460633] audit: type=1400 audit(1517146204.540:22): apparmor="DENIED" operation="sendmsg" profile="/usr/sbin/unbound" name="/run/systemd/notify" pid=603 comm="unbound" requested_mask="w" denied_mask="w" fsuid=108 ouid=0
[ 549.941806] audit: type=1400 audit(1517146205.021:23): apparmor="DENIED" operation="sendmsg" profile="/usr/sbin/unbound" name="/run/systemd/notify" pid=611 comm="unbound" requested_mask="w" denied_mask="w" fsuid=108 ouid=0
[ 639.960932] audit: type=1400 audit(1517146295.040:24): apparmor="DENIED" operation="sendmsg" profile="/usr/sbin/unbound" name="/run/systemd/notify" pid=611 comm="unbound" requested_mask="w" denied_mask="w" fsuid=108 ouid=0
[ 640.314353] audit: type=1400 audit(1517146295.393:25): apparmor="DENIED" operation="sendmsg" profile="/usr/sbin/unbound" name="/run/systemd/notify" pid=620 comm="unbound" requested_mask="w" denied_mask="w" fsuid=108 ouid=0
[ 730.461420] audit: type=1400 audit(1517146385.540:26): apparmor="DENIED" operation="sendmsg" profile="/usr/sbin/unbound" name="/run/systemd/notify" pid=620 comm="unbound" requested_mask="w" denied_mask="w" fsuid=108 ouid=0
[ 730.787530] audit: type=1400 audit(1517146385.866:27): apparmor="DENIED" operation="sendmsg" profile="/usr/sbin/unbound" name="/run/systemd/notify" pid=629 comm="unbound" requested_mask="w" denied_mask="w" fsuid=108 ouid=0
[ 820.961615] audit: type=1400 audit(1517146476.040:28): apparmor="DENIED" operation="sendmsg" profile="/usr/sbin/unbound" name="/run/systemd/notify" pid=629 comm="unbound" requested_mask="w" denied_mask="w" fsuid=108 ouid=0
[ 821.272747] audit: type=1400 audit(1517146476.351:29): apparmor="DENIED" operation="sendmsg" profile="/usr/sbin/unbound" name="/run/systemd/notify" pid=640 comm="unbound" requested_mask="w" denied_mask="w" fsuid=108 ouid=0
[ 911.463247] audit: type=1400 audit(1517146566.540:30): apparmor="DENIED" operation="sendmsg" profile="/usr/sbin/unbound" name="/run/systemd/notify" pid=640 comm="unbound" requested_mask="w" denied_mask="w" fsuid=108 ouid=0
[ 911.790331] audit: type=1400 audit(1517146566.869:31): apparmor="DENIED" operation="sendmsg" profile="/usr/sbin/unbound" name="/run/systemd/notify" pid=760 comm="unbound" requested_mask="w" denied_mask="w" fsuid=108 ouid=0
==
Goes away after adding the "/{,var/}run/systemd/notify w," line.
--
You received this bug notification because you are a member of Ubuntu
Sponsors Team, which is subscribed to the bug report.
https://bugs.launchpad.net/bugs/1723900
Title:
unbound systemctl (re)start fails due to Apparmor profile issue
Status in unbound package in Ubuntu:
Confirmed
Status in unbound source package in Artful:
Confirmed
Status in unbound package in Debian:
New
Bug description:
- install unbound: sudo apt install unbound
- unbound automatic start after installation will work
steven at box:~$ sudo systemctl status unbound
● unbound.service - Unbound DNS server
Loaded: loaded (/lib/systemd/system/unbound.service; enabled; vendor preset: enabled)
Active: active (running) since Mon 2017-10-16 10:05:55 CEST; 22s ago
Docs: man:unbound(8)
Main PID: 3016 (unbound)
Tasks: 1 (limit: 4915)
CGroup: /system.slice/unbound.service
└─3016 /usr/sbin/unbound -d
Oct 16 10:05:55 box systemd[1]: Starting Unbound DNS server...
Oct 16 10:05:55 box package-helper[3011]: /var/lib/unbound/root.key does not exist, copying from /usr/share/dns/root.key
Oct 16 10:05:55 box package-helper[3011]: /var/lib/unbound/root.key has content
Oct 16 10:05:55 box package-helper[3011]: success: the anchor is ok
Oct 16 10:05:55 box unbound[3016]: [3016:0] notice: init module 0: subnet
Oct 16 10:05:55 box unbound[3016]: [3016:0] notice: init module 1: validator
Oct 16 10:05:55 box unbound[3016]: [3016:0] notice: init module 2: iterator
Oct 16 10:05:55 box unbound[3016]: [3016:0] info: start of service (unbound 1.6.5).
Oct 16 10:05:55 box systemd[1]: Started Unbound DNS server.
- try to (re)start unbound.service via systemctl and it will fail
- stopping unbound.service via systemctl will work
steven at box:~$ sudo systemctl start unbound
Job for unbound.service failed because a timeout was exceeded.
See "systemctl status unbound.service" and "journalctl -xe" for details.
- you will find an apparmor related entry in the logs/journal
...
Oct 16 10:41:31 box systemd[1]: Starting Unbound DNS server...
Oct 16 10:41:32 box package-helper[4480]: /var/lib/unbound/root.key has content
Oct 16 10:41:32 box package-helper[4480]: success: the anchor is ok
Oct 16 10:41:35 box unbound[4485]: [4485:0] notice: init module 0: subnet
Oct 16 10:41:35 box unbound[4485]: [4485:0] notice: init module 1: validator
Oct 16 10:41:35 box unbound[4485]: [4485:0] notice: init module 2: iterator
Oct 16 10:41:35 box unbound[4485]: [4485:0] info: start of service (unbound 1.6.5).
Oct 16 10:41:35 box audit[4485]: AVC apparmor="DENIED" operation="sendmsg" profile="/usr/sbin/unbound" name="/run/systemd/notify" pid=4485 comm="unbound" requested_mask="w" denied_mask="w" fsuid=118 ouid=0
Oct 16 10:41:35 box kernel: audit: type=1400 audit(1508143295.929:118): apparmor="DENIED" operation="sendmsg" profile="/usr/sbin/unbound" name="/run/systemd/notify" pid=4485 comm="unbound" requested_mask="w" den
Oct 16 10:41:36 box sudo[4486]: steven : TTY=pts/1 ; PWD=/home/steven ; USER=root ; COMMAND=/bin/journalctl
Oct 16 10:41:36 box sudo[4486]: pam_unix(sudo:session): session opened for user root by (uid=0)
Oct 16 10:41:36 box sudo[4486]: pam_unix(sudo:session): session closed for user root
Oct 16 10:41:59 box sudo[4490]: steven : TTY=pts/1 ; PWD=/home/steven ; USER=root ; COMMAND=/bin/journalctl
Oct 16 10:41:59 box sudo[4490]: pam_unix(sudo:session): session opened for user root by (uid=0)
Oct 16 10:41:59 box sudo[4490]: pam_unix(sudo:session): session closed for user root
Oct 16 10:42:07 box sudo[4493]: steven : TTY=pts/1 ; PWD=/home/steven ; USER=root ; COMMAND=/bin/journalctl
Oct 16 10:42:07 box sudo[4493]: pam_unix(sudo:session): session opened for user root by (uid=0)
Oct 16 10:42:38 box dbus[1459]: apparmor="DENIED" operation="dbus_method_call" bus="session" path="/org/gtk/vfs/mounttracker" interface="org.gtk.vfs.MountTracker" member="ListMountableInfo" mask="send" name=":1
Oct 16 10:43:02 box systemd[1]: unbound.service: Start operation timed out. Terminating.
Oct 16 10:43:02 box audit[4485]: AVC apparmor="DENIED" operation="sendmsg" profile="/usr/sbin/unbound" name="/run/systemd/notify" pid=4485 comm="unbound" requested_mask="w" denied_mask="w" fsuid=118 ouid=0
Oct 16 10:43:02 box unbound[4485]: [4485:0] info: service stopped (unbound 1.6.5).
Oct 16 10:43:02 box kernel: audit: type=1400 audit(1508143382.772:119): apparmor="DENIED" operation="sendmsg" profile="/usr/sbin/unbound" name="/run/systemd/notify" pid=4485 comm="unbound" requested_mask="w" den
Oct 16 10:43:03 box unbound[4485]: [4485:0] info: server stats for thread 0: 50 queries, 4 answers from cache, 46 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Oct 16 10:43:03 box unbound[4485]: [4485:0] info: server stats for thread 0: requestlist max 10 avg 1.45652 exceeded 0 jostled 0
Oct 16 10:43:03 box unbound[4485]: [4485:0] info: average recursion processing time 0.175267 sec
Oct 16 10:43:03 box unbound[4485]: [4485:0] info: histogram of recursion processing times
Oct 16 10:43:03 box unbound[4485]: [4485:0] info: [25%]=0.0464213 median[50%]=0.0931301 [75%]=0.141995
Oct 16 10:43:03 box unbound[4485]: [4485:0] info: lower(secs) upper(secs) recursions
Oct 16 10:43:03 box unbound[4485]: [4485:0] info: 0.000000 0.000001 9
Oct 16 10:43:03 box unbound[4485]: [4485:0] info: 0.032768 0.065536 6
Oct 16 10:43:03 box unbound[4485]: [4485:0] info: 0.065536 0.131072 19
Oct 16 10:43:03 box unbound[4485]: [4485:0] info: 0.131072 0.262144 6
Oct 16 10:43:03 box unbound[4485]: [4485:0] info: 0.262144 0.524288 2
Oct 16 10:43:03 box unbound[4485]: [4485:0] info: 0.524288 1.000000 2
Oct 16 10:43:03 box unbound[4485]: [4485:0] info: 1.000000 2.000000 2
Oct 16 10:43:03 box systemd[1]: Failed to start Unbound DNS server.
Oct 16 10:43:03 box systemd[1]: unbound.service: Unit entered failed state.
Oct 16 10:43:03 box systemd[1]: unbound.service: Failed with result 'timeout'.
Oct 16 10:43:03 box sudo[4474]: pam_unix(sudo:session): session closed for user root
Oct 16 10:43:03 box systemd[1]: unbound.service: Service hold-off time over, scheduling restart.
Oct 16 10:43:03 box systemd[1]: Stopped Unbound DNS server.
...
- the important apparmor entry is
...
Oct 16 10:43:02 box audit[4485]: AVC apparmor="DENIED" operation="sendmsg" profile="/usr/sbin/unbound" name="/run/systemd/notify" pid=4485 comm="unbound" requested_mask="w" denied_mask="w" fsuid=118 ouid=0
...
- searching the internet shows similar issues, e.g. Bug 1530483 (https://bugs.launchpad.net/ubuntu/+source/rsyslog/+bug/1530483)
- so i can fix the issue with adding "/{,var/}run/systemd/notify w," to the Unbound apparmor profile (/etc/apparmor.d/usr.sbin.unbound)
...
# Unix control socket
/{,var/}run/unbound.ctl rw,
/{,var/}run/systemd/notify w,
#include <local/usr.sbin.unbound>
}
...
- now i can (re)start unbound via "sudo systemctl restart unbound"
without issue
To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/unbound/+bug/1723900/+subscriptions
More information about the Ubuntu-sponsors
mailing list