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

Seth Arnold 1723900 at bugs.launchpad.net
Mon Oct 16 23:06:13 UTC 2017 

Looks good to me, thanks

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