Comment 7 for bug 1788622

Revision history for this message
Christian Ehrhardt  (paelzer) wrote :

Reproducing issue in Bionic as-is:
$ systemctl reload unbound
Job for unbound.service failed because a timeout was exceeded.
See "systemctl status unbound.service" and "journalctl -xe" for details.

Log:
Aug 31 05:36:18 b systemd[1]: Reloading Unbound DNS server.
Aug 31 05:36:18 b unbound[827]: [827:0] info: service stopped (unbound 1.6.7).
Aug 31 05:36:18 b unbound[827]: [827:0] info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Aug 31 05:36:18 b unbound-control[1027]: ok
Aug 31 05:36:18 b unbound[827]: [827:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
Aug 31 05:36:18 b unbound[827]: [827:0] notice: Restart of unbound 1.6.7.
Aug 31 05:36:18 b unbound[827]: [827:0] notice: init module 0: subnet
Aug 31 05:36:18 b unbound[827]: [827:0] notice: init module 1: validator
Aug 31 05:36:18 b unbound[827]: [827:0] notice: init module 2: iterator
Aug 31 05:36:18 b unbound[827]: [827:0] info: start of service (unbound 1.6.7).
Aug 31 05:37:01 b systemd-journald[57]: Forwarding to syslog missed 1 messages.
Aug 31 05:37:48 b systemd[1]: unbound.service: State 'stop-sigterm' timed out. Killing.
Aug 31 05:37:48 b systemd[1]: unbound.service: Killing process 827 (unbound) with signal SIGKILL.
Aug 31 05:37:48 b systemd[1]: unbound.service: Main process exited, code=killed, status=9/KILL
Aug 31 05:37:48 b systemd[1]: unbound.service: Failed with result 'timeout'.
Aug 31 05:37:48 b systemd[1]: Reload failed for Unbound DNS server.
Aug 31 05:37:48 b systemd[1]: unbound.service: Service hold-off time over, scheduling restart.
Aug 31 05:37:48 b systemd[1]: unbound.service: Scheduled restart job, restart counter is at 1.
Aug 31 05:37:48 b systemd[1]: Stopped Unbound DNS server.
Aug 31 05:37:48 b systemd[1]: unbound.service: Failed to reset devices.list: Operation not permitted
Aug 31 05:37:48 b systemd[1]: Starting Unbound DNS server...
Aug 31 05:37:48 b package-helper[1031]: /var/lib/unbound/root.key has content
Aug 31 05:37:48 b package-helper[1031]: success: the anchor is ok
Aug 31 05:37:48 b unbound[1035]: [1035:0] notice: init module 0: subnet
Aug 31 05:37:48 b unbound[1035]: [1035:0] notice: init module 1: validator
Aug 31 05:37:48 b unbound[1035]: [1035:0] notice: init module 2: iterator
Aug 31 05:37:49 b unbound[1035]: [1035:0] info: start of service (unbound 1.6.7).
Aug 31 05:37:49 b systemd[1]: Started Unbound DNS server.

Upgrade to Proposed

# apt install unbound unbound-anchor
Reading package lists... Done
Building dependency tree
Reading state information... Done
The following package was automatically installed and is no longer required:
  libfreetype6
Use 'apt autoremove' to remove it.
The following packages will be upgraded:
  unbound unbound-anchor
2 upgraded, 0 newly installed, 0 to remove and 29 not upgraded.
Need to get 603 kB of archives.
After this operation, 2048 B of additional disk space will be used.
Get:1 http://archive.ubuntu.com/ubuntu bionic-proposed/universe amd64 unbound-anchor amd64 1.6.7-1ubuntu2.2 [25.0 kB]
Get:2 http://archive.ubuntu.com/ubuntu bionic-proposed/universe amd64 unbound amd64 1.6.7-1ubuntu2.2 [578 kB]
Fetched 603 kB in 0s (2617 kB/s)
(Reading database ... 28556 files and directories currently installed.)
Preparing to unpack .../unbound-anchor_1.6.7-1ubuntu2.2_amd64.deb ...
Unpacking unbound-anchor (1.6.7-1ubuntu2.2) over (1.6.7-1ubuntu2.1) ...
Preparing to unpack .../unbound_1.6.7-1ubuntu2.2_amd64.deb ...
Unpacking unbound (1.6.7-1ubuntu2.2) over (1.6.7-1ubuntu2.1) ...
Processing triggers for ureadahead (0.100.0-20) ...
Processing triggers for systemd (237-3ubuntu10.3) ...
Setting up unbound-anchor (1.6.7-1ubuntu2.2) ...
Processing triggers for man-db (2.8.3-2) ...
Setting up unbound (1.6.7-1ubuntu2.2) ...

Retest:
$ systemctl reload unbound
# works immediately now

Log:
Aug 31 05:48:01 b systemd[1]: Reloading Unbound DNS server.
Aug 31 05:48:01 b unbound[1617]: [1617:0] info: service stopped (unbound 1.6.7).
Aug 31 05:48:01 b unbound[1617]: [1617:0] info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Aug 31 05:48:01 b unbound-control[1647]: ok
Aug 31 05:48:01 b unbound[1617]: [1617:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
Aug 31 05:48:01 b unbound[1617]: [1617:0] notice: Restart of unbound 1.6.7.
Aug 31 05:48:01 b unbound[1617]: [1617:0] notice: init module 0: subnet
Aug 31 05:48:01 b unbound[1617]: [1617:0] notice: init module 1: validator
Aug 31 05:48:01 b unbound[1617]: [1617:0] notice: init module 2: iterator
Aug 31 05:48:01 b unbound[1617]: [1617:0] info: start of service (unbound 1.6.7).
Aug 31 05:48:01 b systemd[1]: Reloaded Unbound DNS server.

I played with it in general but found no issue either:

# Run dns query against it

root@b:~# dig google.com @127.0.0.1

; <<>> DiG 9.11.3-1ubuntu1.1-Ubuntu <<>> google.com @127.0.0.1
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 22999
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 4096
;; QUESTION SECTION:
;google.com. IN A

;; ANSWER SECTION:
google.com. 300 IN A 216.58.206.14

;; Query time: 454 msec
;; SERVER: 127.0.0.1#53(127.0.0.1)
;; WHEN: Fri Aug 31 05:49:38 UTC 2018
;; MSG SIZE rcvd: 55

# see caching make it fast

root@b:~# dig google.com @127.0.0.1

; <<>> DiG 9.11.3-1ubuntu1.1-Ubuntu <<>> google.com @127.0.0.1
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 10895
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 4096
;; QUESTION SECTION:
;google.com. IN A

;; ANSWER SECTION:
google.com. 292 IN A 216.58.206.14

;; Query time: 0 msec
;; SERVER: 127.0.0.1#53(127.0.0.1)
;; WHEN: Fri Aug 31 05:49:46 UTC 2018
;; MSG SIZE rcvd: 55

root@b:~# netstat -eeapn | grep unb
tcp 0 0 127.0.0.1:53 0.0.0.0:* LISTEN 0 53978839 1617/unbound
tcp 0 0 127.0.0.1:8953 0.0.0.0:* LISTEN 0 53978841 1617/unbound
tcp6 0 0 ::1:53 :::* LISTEN 0 53978837 1617/unbound
tcp6 0 0 ::1:8953 :::* LISTEN 0 53978840 1617/unbound
udp 1536 0 127.0.0.1:53 0.0.0.0:* 0 53978838 1617/unbound
udp6 0 0 ::1:53 :::* 0 53978836 1617/unbound
unix 3 [ ] STREAM CONNECTED 53980039 1617/unbound
unix 3 [ ] STREAM CONNECTED 53980040 1617/unbound
unix 3 [ ] STREAM CONNECTED 53978832 1617/unbound
unix 2 [ ] DGRAM 53978842 1617/unbound

# use dnssec explicitly

root@b:~# dig google.com @127.0.0.1 +dnssec

; <<>> DiG 9.11.3-1ubuntu1.1-Ubuntu <<>> google.com @127.0.0.1 +dnssec
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 9661
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 4096
;; QUESTION SECTION:
;google.com. IN A

;; ANSWER SECTION:
google.com. 229 IN A 216.58.206.14

;; Query time: 0 msec
;; SERVER: 127.0.0.1#53(127.0.0.1)
;; WHEN: Fri Aug 31 05:50:49 UTC 2018
;; MSG SIZE rcvd: 55

With that setting verified.