Ubuntu
unbound package

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

Bug #1723900 reported by AlphasCodes
318
This bug affects 13 people
Affects Status Importance Assigned to Milestone
unbound (Debian)
Fix Released
Unknown
unbound (Ubuntu)
Fix Released
Undecided
Unassigned
Artful
Fix Released
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: patch apparmor
Kai Kasurinen (kai-kasurinen)
tags: added: apparmor
Bug Watch Updater (bug-watch-updater)
Changed in unbound (Debian):
status: Unknown → New
Revision history for this message
Simon Déziel (sdeziel) wrote :

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

Revision history for this message
Ubuntu Foundations Team Bug Bot (crichton) wrote :

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)
Changed in unbound (Ubuntu):
status: New → Confirmed
Revision history for this message
Seth Arnold (seth-arnold) wrote :

Looks good to me, thanks

Revision history for this message
Simon Déziel (sdeziel) wrote :

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

Revision history for this message
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

Revision history for this message
Simon Déziel (sdeziel) wrote : Re: [Bug 1723900] Re: unbound systemctl (re)start fails due to Apparmor profile issue

I'll hand around on #ubuntu-devel then, thanks Seth!

Revision history for this message
Jeff (jeffsf) wrote :

Thanks for tracking this down, same issue on Ubuntu 17.10

Resolved by manually applying the patch above

Revision history for this message
Floris (bos) wrote :

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.

Revision history for this message
Thomas Duboucher (serianox) wrote :

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

Dimitri John Ledkov (xnox)
information type: Public → Public Security
Revision history for this message
Thomas Duboucher (serianox) wrote :

I checked again, to confirm the behavior. After reverting the changes in /etc/apparmor.d/usr.sbin.unbound:

sudo service apparmor reload

sudo service unbound restart
Job for unbound.service failed because a timeout was exceeded.
See "systemctl status unbound.service" and "journalctl -xe" for details.

dig +dnssec SOA iis.se

; <<>> DiG 9.10.3-P4-Ubuntu <<>> +dnssec SOA iis.se
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 61659
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 65494
;; QUESTION SECTION:
;iis.se. IN SOA

;; ANSWER SECTION:
iis.se. 3600 IN SOA ns.nic.se. hostmaster.iis.se. 1519057201 14400 3600 1814400 14400

;; Query time: 79 msec
;; SERVER: 127.0.0.53#53(127.0.0.53)
;; WHEN: Mon Feb 19 18:52:44 CET 2018
;; MSG SIZE rcvd: 89

Versus applying the patch again.

sudo service apparmor reload

sudo service unbound restart

dig +dnssec SOA iis.se

; <<>> DiG 9.10.3-P4-Ubuntu <<>> +dnssec SOA iis.se
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 3817
;; flags: qr rd ra ad; QUERY: 1, ANSWER: 2, AUTHORITY: 4, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 4096
;; QUESTION SECTION:
;iis.se. IN SOA

;; ANSWER SECTION:
iis.se. 3600 IN SOA ns.nic.se. hostmaster.iis.se. 1519057201 14400 3600 1814400 14400
iis.se. 3600 IN RRSIG SOA 5 2 3600 20180301152001 20180219152001 65490 iis.se. jRZmwmeu1HeAhITwVf27l+3tWG+MenaxsfMDAngDWKQL7XX8ZzS4D2b8 KfntCeXSY0CLWJIo+jO3FKVOD/zydxyyhFlkovvT9f0QFgR+SMd7O7An H+P3UC1aTcudXbFmY3v5v+9UQOB5MXliZO2L3Ceyn6mV3mAq9zCO4jSO gSk=

;; AUTHORITY SECTION:
iis.se. 3600 IN NS ns.nic.se.
iis.se. 3600 IN NS ns3.nic.se.
iis.se. 3600 IN NS i.ns.se.
iis.se. 3600 IN RRSIG NS 5 2 3600 20180301152001 20180219152001 65490 iis.se. J5a516jlDZgx1kGeL6lzSfqzjbfiCzMO+Mg8R4lSeznkfNYNA50ord6M vYc8QZnHsX8ooUkt5uuZGbNIhp6OM7PCP3U6GT/od5Hul+x1Kucvddi3 0y0vXzmd0thIdve8iqSbhcaZw6SsSZPKsTb93ssgliK/89M5zr8cjOw6 d+A=

;; Query time: 311 msec
;; SERVER: 127.0.0.1#53(127.0.0.1)
;; WHEN: Mon Feb 19 18:54:17 CET 2018
;; MSG SIZE rcvd: 472

Revision history for this message
Emily Ratliff (emilyr) wrote :

The updated package for 17.10/Artful has been uploaded to the security-proposed ppa.
https://launchpad.net/~ubuntu-security-proposed/+archive/ubuntu/ppa
My testing shows that the bug is resolved. Please try it out.
Thanks for providing the debdiff, Simon!

Revision history for this message
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package unbound - 1.6.5-1ubuntu0.1

---------------
unbound (1.6.5-1ubuntu0.1) artful-security; urgency=medium

  * apparmor: permit unbound to notify readiness to systemd
   (Closes: #867186, LP: #1723900)

 -- Simon Deziel <email address hidden> Mon, 16 Oct 2017 13:11:12 +0000

Changed in unbound (Ubuntu Artful):
status: Confirmed → Fix Released
Revision history for this message
Simon Déziel (sdeziel) wrote :

Thanks Emily!

Revision history for this message
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package unbound - 1.6.7-1ubuntu1

---------------
unbound (1.6.7-1ubuntu1) bionic; urgency=medium

  * debian/apparmor: update to allow writing to /run/systemd/notify
    (Closes: #867186, LP: #1723900)

 -- Jamie Strandboge <email address hidden> Thu, 22 Feb 2018 19:35:23 +0000

Changed in unbound (Ubuntu):
status: Confirmed → Fix Released
Bug Watch Updater (bug-watch-updater)
Changed in unbound (Debian):
status: New → Fix Released
To post a comment you must log in.
This report contains Public Security information  
Everyone can see this security related information.
Subscribing...

Other bug subscribers

Remote bug watches

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