unbound systemctl (re)start fails due to Apparmor profile issue
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/
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.
└─3016 /usr/sbin/unbound -d
Oct 16 10:05:55 box systemd[1]: Starting Unbound DNS server...
Oct 16 10:05:55 box package-
Oct 16 10:05:55 box package-
Oct 16 10:05:55 box package-
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-
Oct 16 10:41:32 box package-
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=
Oct 16 10:41:35 box kernel: audit: type=1400 audit(150814329
Oct 16 10:41:36 box sudo[4486]: steven : TTY=pts/1 ; PWD=/home/steven ; USER=root ; COMMAND=
Oct 16 10:41:36 box sudo[4486]: pam_unix(
Oct 16 10:41:36 box sudo[4486]: pam_unix(
Oct 16 10:41:59 box sudo[4490]: steven : TTY=pts/1 ; PWD=/home/steven ; USER=root ; COMMAND=
Oct 16 10:41:59 box sudo[4490]: pam_unix(
Oct 16 10:41:59 box sudo[4490]: pam_unix(
Oct 16 10:42:07 box sudo[4493]: steven : TTY=pts/1 ; PWD=/home/steven ; USER=root ; COMMAND=
Oct 16 10:42:07 box sudo[4493]: pam_unix(
Oct 16 10:42:38 box dbus[1459]: apparmor="DENIED" operation=
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=
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(150814338
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[
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(
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=
...
- searching the internet shows similar issues, e.g. Bug 1530483 (https:/
- so i can fix the issue with adding "/{,var/
...
# Unix control socket
/{,var/
/{,var/
#include <local/
}
...
- now i can (re)start unbound via "sudo systemctl restart unbound" without issue
tags: | added: apparmor |
Changed in unbound (Debian): | |
status: | Unknown → New |
Changed in unbound (Ubuntu): | |
status: | New → Confirmed |
information type: | Public → Public Security |
Changed in unbound (Debian): | |
status: | New → Fix Released |
Here is a debdiff for Artful with the same patch that I attached to the Debian bug.