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

Thomas Duboucher thomas at duboucher.eu
Mon Feb 19 08:41:54 UTC 2018 

This bug silently deactivate DNSSEC on systems where Unbound is
installed. The system will fallback to the default resolver and happily
resolve dns queries with invalid signatures.

This should be marked as a security issue.

Problem resolved (no pun intended) with the provided patch, then reloading the apparmor configuration.
systemctl reload apparmor.service 
systemctl restart unbound.service

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