[Bug 1723900] [NEW] unbound systemctl (re)start fails due to Apparmor profile issue

Launchpad Bug Tracker 1723900 at bugs.launchpad.net
Mon Oct 16 16:18:38 UTC 2017


You have been subscribed to a public bug by Ubuntu Foundations Team Bug Bot (crichton):

- 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

** Affects: unbound (Ubuntu)
     Importance: Undecided
         Status: New

** Affects: unbound (Debian)
     Importance: Unknown
         Status: New


** Tags: apparmor patch
-- 
unbound systemctl (re)start fails due to Apparmor profile issue
https://bugs.launchpad.net/bugs/1723900
You received this bug notification because you are a member of Ubuntu Sponsors Team, which is subscribed to the bug report.



More information about the Ubuntu-sponsors mailing list