unbound systemctl (re)start fails due to Apparmor profile issue

Bug #1723900 reported by sourcepower on 2017-10-16
42
This bug affects 7 people
Affects Status Importance Assigned to Milestone
unbound (Debian)
New
Unknown
unbound (Ubuntu)
Undecided
Unassigned
Artful
Undecided
Unassigned

Bug Description

- install unbound: sudo apt install unbound
- unbound automatic start after installation will work

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

tags: added: apparmor
Changed in unbound (Debian):
status: Unknown → New
Simon Déziel (sdeziel) wrote :

Here is a debdiff for Artful with the same patch that I attached to the Debian bug.

The attachment "unbound-apparmor-sd_notify.debdiff" seems to be a debdiff. The ubuntu-sponsors team has been subscribed to the bug report so that they can review and hopefully sponsor the debdiff. If the attachment isn't a patch, please remove the "patch" flag from the attachment, remove the "patch" tag, and if you are member of the ~ubuntu-sponsors, unsubscribe the team.

[This is an automated message performed by a Launchpad user owned by ~brian-murray, for any issue please contact him.]

tags: added: patch
Simon Déziel (sdeziel) on 2017-10-16
Changed in unbound (Ubuntu):
status: New → Confirmed
Seth Arnold (seth-arnold) wrote :

Looks good to me, thanks

Simon Déziel (sdeziel) wrote :

@Seth, any chance to get that debdiff uploaded? Would be much appreciated.

Seth Arnold (seth-arnold) wrote :

Sorry Simon, I don't have any privileges to do so, hopefully someone doing Ubuntu patch piloting can pick it up.

Thanks

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.