unbound: Service Failed with 'timeout'

I’m seeing serious issues with unbound where the service simply restarts itself intermittently. I say intermittently but I’m beginning to think it’s related to the service failed timeout + the restart delay.

When I attempt to start the service normally via systemctl start unbound or systemctl restart unbound the prompt hangs and waits. Eventually there’s an error message along the lines of:

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

In the unbound log I can see that it’s reached a status of info: start of service (unbound 1.9.0). within milliseconds of the service start though.

tls-upstream is set to yes, and looking at the more verbose outputs requests are getting resolved. However when the service restarts the cache is dropped, which is the one of the main reasons for using unbound on this LAN (as well as part of a wider security & privacy design).

I’m using DNS-over-TLS upstreams only, and are configured as per this example:

forward-zone:
        name: "."
        forward-tls-upstream: yes

        ### straight connect instead of via stubby
        ## https://ripe78.ripe.net/on-site/tech-info/dns-over-tls-resolvers/
        forward-addr:   193.0.31.237@853#nscache.ripemtg.ripe.net
        forward-addr:   193.0.31.238@853#nscache.ripemtg.ripe.net

I know this generally works because if I start the service directly (stopping the systemd service) via /usr/sbin/unbound -dvv, I see it working as expected. No restarts or drop-outs.

It’s almost like the systemd service thinks the startup hasn’t completed, and assumes timeout - and forces the restart based on the unbound.service Restart=on-failed setting. If I remove the Restart=... line from the service I see the following in the systemctl status:

unbound.service - Unbound DNS server Loaded: loaded (/lib/systemd/system/unbound.service; enabled; vendor preset: enabled) Active: failed (Result: timeout) since Wed 2019-08-07 18:21:22 CEST; 38s ago Docs: man:unbound(8) Process: 6990 ExecStartPre=/usr/lib/unbound/package-helper chroot_setup (code=exited, status=0/SUCCESS) Process: 6993 ExecStartPre=/usr/lib/unbound/package-helper root_trust_anchor_update (code=exited, status=0/SUCCESS) Process: 6997 ExecStart=/usr/sbin/unbound -d $DAEMON_OPTS (code=exited, status=0/SUCCESS) Main PID: 6997 (code=exited, status=0/SUCCESS)

Aug 07 18:19:51 ServerName systemd[1]: Starting Unbound DNS server… Aug 07 18:19:51 ServerName package-helper[6993]: /var/lib/unbound/root.key has content Aug 07 18:19:51 ServerName package-helper[6993]: success: the anchor is ok Aug 07 18:21:21 ServerName systemd[1]: unbound.service: Start operation timed out. Terminating. Aug 07 18:21:22 ServerName systemd[1]: unbound.service: Failed with result ‘timeout’. Aug 07 18:21:22 ServerName systemd[1]: Failed to start Unbound DNS server.

The pre-reqs for chroot and trust anchors appear to operate as expected, it’s the actual unbound service which seems to timeout as a systemd service.

The server in question is a new build to replace an older server, running another Debian derivative with unbound 1.6.0, and that uses Stubby and DnsCrypt as its forwarders. I’ve tried swapping out the DoT configuration for a straight udp forwarder with known-good DNS (Cloudflare in the test), and that exhibits the same symptoms.

Version in use: 1.9.0.2 OS: Debian Buster (stable) arm64

I enabled a higher verbosity and captured a part of the log for reference - it shows the brief time unbound was actually up through to the timeout ‘happening’ and the service dropping. Just after the systemctl start unbound I hit it with a dig google.com +dnssec:

[1565196026] unbound[7414:0] debug: validator[module 1] operate: extstate:module_wait_subquery event:module_event_pass [1565196026] unbound[7414:0] info: validator operate: query google.com. A IN [1565196026] unbound[7414:0] debug: val handle processing q with state VAL_FINDKEY_STATE [1565196026] unbound[7414:0] info: validator: FindKey google.com. A IN [1565196026] unbound[7414:0] info: current keyname com. DNSKEY IN [1565196026] unbound[7414:0] info: target keyname google.com. DNSKEY IN [1565196026] unbound[7414:0] debug: striplab 0 [1565196026] unbound[7414:0] info: next keyname google.com. DNSKEY IN [1565196026] unbound[7414:0] info: DS RRset com. DS IN [1565196026] unbound[7414:0] info: generate request google.com. DS IN [1565196026] unbound[7414:0] debug: mesh_run: validator module exit state is module_wait_subquery [1565196026] unbound[7414:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_pass [1565196026] unbound[7414:0] info: subnet operate: query google.com. DS IN [1565196026] unbound[7414:0] debug: subnet: pass to next module [1565196026] unbound[7414:0] debug: mesh_run: subnet module exit state is module_wait_module [1565196026] unbound[7414:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass [1565196026] unbound[7414:0] info: validator operate: query google.com. DS IN [1565196026] unbound[7414:0] debug: validator: pass to next module [1565196026] unbound[7414:0] debug: mesh_run: validator module exit state is module_wait_module [1565196026] unbound[7414:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass [1565196026] unbound[7414:0] debug: process_request: new external request event [1565196026] unbound[7414:0] debug: iter_handle processing q with state INIT REQUEST STATE [1565196026] unbound[7414:0] info: resolving google.com. DS IN [1565196026] unbound[7414:0] debug: request has dependency depth of 0 [1565196026] unbound[7414:0] debug: forwarding request [1565196026] unbound[7414:0] debug: iter_handle processing q with state QUERY TARGETS STATE [1565196026] unbound[7414:0] info: processQueryTargets: google.com. DS IN [1565196026] unbound[7414:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0 [1565196026] unbound[7414:0] info: DelegationPoint<.>: 0 names (0 missing), 7 addrs (0 result, 7 avail) parentNS [1565196026] unbound[7414:0] debug: [dns.larsdebruin.net] ip4 51.15.70.167 port 853 (len 16) [1565196026] unbound[7414:0] debug: [dnsovertls.sinodun.com] ip4 145.100.185.15 port 853 (len 16) [1565196026] unbound[7414:0] debug: [dns.cmrg.net] ip4 199.58.81.218 port 443 (len 16) [1565196026] unbound[7414:0] debug: [dnsovertls.sinodun.com] ip4 145.100.185.15 port 443 (len 16) [1565196026] unbound[7414:0] debug: [getdnsapi.net] ip4 185.49.141.37 port 853 (len 16) [1565196026] unbound[7414:0] debug: [nscache.ripemtg.ripe.net] ip4 193.0.31.238 port 853 (len 16) [1565196026] unbound[7414:0] debug: [nscache.ripemtg.ripe.net] ip4 193.0.31.237 port 853 (len 16) [1565196026] unbound[7414:0] debug: attempt to get extra 3 targets [1565196026] unbound[7414:0] debug: servselect ip4 193.0.31.237 port 853 (len 16) [1565196026] unbound[7414:0] debug: rtt=1504 [1565196026] unbound[7414:0] debug: servselect ip4 193.0.31.238 port 853 (len 16) [1565196026] unbound[7414:0] debug: rtt=1504 [1565196026] unbound[7414:0] debug: servselect ip4 185.49.141.37 port 853 (len 16) [1565196026] unbound[7414:0] debug: rtt=649 [1565196026] unbound[7414:0] debug: servselect ip4 145.100.185.15 port 443 (len 16) [1565196026] unbound[7414:0] debug: rtt=569 [1565196026] unbound[7414:0] debug: servselect ip4 199.58.81.218 port 443 (len 16) [1565196026] unbound[7414:0] debug: rtt=1147 [1565196026] unbound[7414:0] debug: servselect ip4 145.100.185.15 port 853 (len 16) [1565196026] unbound[7414:0] debug: rtt=598 [1565196026] unbound[7414:0] debug: selrtt 376 [1565196026] unbound[7414:0] info: sending query: google.com. DS IN [1565196026] unbound[7414:0] debug: sending to target: <.> 145.100.185.15#443 [1565196026] unbound[7414:0] debug: dnssec status: not expected [1565196026] unbound[7414:0] debug: qname perturbed to GOogLE.cOM. [1565196026] unbound[7414:0] debug: comm point start listening 39 [1565196026] unbound[7414:0] debug: mesh_run: iterator module exit state is module_wait_reply [1565196026] unbound[7414:0] info: mesh_run: end 2 recursion states (1 with reply, 0 detached), 1 waiting replies, 1 recursion replies sent, 0 replies dropped, 0 states jostled out [1565196026] unbound[7414:0] info: average recursion processing time 4.325272 sec [1565196026] unbound[7414:0] info: histogram of recursion processing times [1565196026] unbound[7414:0] info: [25%]=0 median[50%]=0 [75%]=0 [1565196026] unbound[7414:0] info: lower(secs) upper(secs) recursions [1565196026] unbound[7414:0] info: 4.000000 8.000000 1 [1565196026] unbound[7414:0] info: 0vRDCD mod2 google.com. DS IN [1565196026] unbound[7414:0] info: 1RDdc mod1 rep google.com. A IN [1565196026] unbound[7414:0] debug: cache memory msg=68665 rrset=73891 infra=9590 val=69820 subnet=74504 [1565196026] unbound[7414:0] debug: svcd callbacks end [1565196026] unbound[7414:0] debug: close fd 38 [1565196026] unbound[7414:0] debug: comm point listen_for_rw 39 0 [1565196026] unbound[7414:0] debug: peer certificate: Issuer: C=US, O=Let’s Encrypt, CN=Let’s Encrypt Authority X3 Validity Not Before: Jul 8 10:15:11 2019 GMT Not After : Oct 6 10:15:11 2019 GMT Subject: CN=dnsovertls.sinodun.com X509v3 extensions: X509v3 Key Usage: critical Digital Signature, Key Encipherment X509v3 Extended Key Usage: TLS Web Server Authentication, TLS Web Client Authentication X509v3 Basic Constraints: critical CA:FALSE X509v3 Subject Key Identifier: 05:3C:F3:1F:64:B2:4C:57:F0:79:8B:0D:55:7B:33:7B:EF:B6:CA:1F X509v3 Authority Key Identifier: keyid:A8:4A:6A:63:04:7D:DD:BA:E6:D1:39:B7:A6:45:65:EF:F3:A8:EC:A1

        Authority Information Access: 
            OCSP - URI:http://ocsp.int-x3.letsencrypt.org
            CA Issuers - URI:http://cert.int-x3.letsencrypt.org/

        X509v3 Subject Alternative Name: 
            DNS:dnsovertls.sinodun.com
        X509v3 Certificate Policies: 
            Policy: 2.23.140.1.2.1
            Policy: 1.3.6.1.4.1.44947.1.1.1
              CPS: http://cps.letsencrypt.org

        CT Precertificate SCTs: 
            Signed Certificate Timestamp:
                Version   : v1 (0x0)
                Log ID    : 74:7E:DA:83:31:AD:33:10:91:21:9C:CE:25:4F:42:70:
                            C2:BF:FD:5E:42:20:08:C6:37:35:79:E6:10:7B:CC:56
                Timestamp : Jul  8 11:15:11.999 2019 GMT
                Extensions: none
                Signature : ecdsa-with-SHA256
                            30:44:02:20:4C:D9:6C:B3:34:4B:7E:D9:E7:90:A4:D5:
                            AB:1D:13:B0:3F:6C:16:CA:93:3C:F6:AC:1D:62:3F:96:
                            5B:E3:F0:1B:02:20:59:0F:B5:B1:8F:FB:74:4F:CE:56:
                            D5:E1:27:C4:C7:98:99:20:2C:12:DF:94:1C:09:50:FD:
                            88:B4:03:E1:65:40
            Signed Certificate Timestamp:
                Version   : v1 (0x0)
                Log ID    : 29:3C:51:96:54:C8:39:65:BA:AA:50:FC:58:07:D4:B7:
                            6F:BF:58:7A:29:72:DC:A4:C3:0C:F4:E5:45:47:F4:78
                Timestamp : Jul  8 11:15:12.030 2019 GMT
                Extensions: none
                Signature : ecdsa-with-SHA256
                            30:46:02:21:00:B8:23:CD:36:89:77:64:0A:88:1B:68:
                            10:F9:D2:8A:27:28:75:F9:13:AF:58:5F:A6:40:F6:CD:
                            41:92:59:70:34:02:21:00:8B:71:0F:CD:DE:E7:9A:54:
                            6D:05:BD:7D:95:DE:A4:7C:ED:1E:65:3C:5F:BC:48:F6:
                            91:67:50:5A:AD:97:57:CB

[1565196026] unbound[7414:0] debug: SSL connection to dnsovertls.sinodun.com authenticated ip4 145.100.185.15 port 443 (len 16) [1565196026] unbound[7414:0] debug: comm point listen_for_rw 39 1 [1565196026] unbound[7414:0] debug: comm point stop listening 39 [1565196026] unbound[7414:0] debug: comm point start listening 39 [1565196026] unbound[7414:0] debug: Reading ssl tcp query of length 766 [1565196026] unbound[7414:0] debug: comm point stop listening 39 [1565196026] unbound[7414:0] debug: outnettcp cb [1565196026] unbound[7414:0] debug: measured TCP-time at 207 msec [1565196026] unbound[7414:0] debug: svcd callbacks start [1565196026] unbound[7414:0] debug: good 0x20-ID in reply qname [1565196026] unbound[7414:0] debug: worker svcd callback for qstate 0xaaab0d9901b0 [1565196026] unbound[7414:0] debug: mesh_run: start [1565196026] unbound[7414:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply [1565196026] unbound[7414:0] info: iterator operate: query google.com. DS IN [1565196026] unbound[7414:0] debug: process_response: new external response event [1565196026] unbound[7414:0] info: scrub for . NS IN [1565196026] unbound[7414:0] info: response for google.com. DS IN [1565196026] unbound[7414:0] info: reply from <.> 145.100.185.15#443 [1565196026] unbound[7414:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0 ;; flags: qr rd ra ; QUERY: 1, ANSWER: 0, AUTHORITY: 6, ADDITIONAL: 0 ;; QUESTION SECTION: google.com. IN DS

;; ANSWER SECTION:

;; AUTHORITY SECTION: com. 1200 IN SOA a.gtld-servers.net. nstld.verisign-grs.com. 1565195898 1800 900 604800 86400 com. 1200 IN RRSIG SOA 8 1 900 20190814163818 20190807152818 17708 com. b/iaRYjfVFnFfMeWeTvihmSBwHG0FxpjtSHMjwYxoj0H4zzga/JM8wzO3Bj4/XXaJZA6wKWvR58znpfhUkqS/U3jbsPwRTH6Zavl/0IZ08b4iTwGUFmiMOAnddkzpjqNaIxfnC/py5k3Nd4iNY0Pz/PydcQhL4viSS1bg33JVS4= ;{id = 17708} CK0POJMG874LJREF7EFN8430QVIT8BSM.com. 1200 IN NSEC3 1 1 0 - ck0q1gin43n1arrc9osm6qpqr81h5m9a NS SOA RRSIG DNSKEY NSEC3PARAM ;{flags: optout} CK0POJMG874LJREF7EFN8430QVIT8BSM.com. 1200 IN RRSIG NSEC3 8 2 86400 20190811044603 20190804033603 17708 com. DFIdCVmw76xkgFouDSnCX8/TUMjZOkvQ/VmNcdSW3tE2rTDsD6VszVwNp5vV0iBTyXFk1lM3F4edA+zWR+fyCMwFfQs0vGdL4PHYbYMfxlY9cswx36W5suvp6oZGEMapfhDFRCcQG88kmIYjGKLjo9QAeTQKEStghE7DWD5SO3M= ;{id = 17708} S84BDVKNH5AGDSI7F5J0O3NPRHU0G7JQ.com. 1200 IN NSEC3 1 1 0 - s84cfh3a62n0fjpc5d9ij2vjr71oglv5 NS DS RRSIG ;{flags: optout} S84BDVKNH5AGDSI7F5J0O3NPRHU0G7JQ.com. 1200 IN RRSIG NSEC3 8 2 86400 20190812045756 20190805034756 17708 com. tCi2xBJY/XO0kpl2Sj23eyW/dFAgmeY11F+zcaeuLdCrwHzP4EM3yLq/XgbQV3L+9icbvcpqCHPv6B3461NGQ5HRvq4wrBgtoFMi0oFp2hZRHaVIMrJqTyerTH+dnoQioY+62bLf8tJ7A/BZVfpe28fg5JNHe3XbgAFVrVgKyWE= ;{id = 17708}

;; ADDITIONAL SECTION: ;; MSG SIZE rcvd: 749

[1565196026] unbound[7414:0] debug: iter_handle processing q with state QUERY RESPONSE STATE [1565196026] unbound[7414:0] info: query response was nodata ANSWER [1565196026] unbound[7414:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE [1565196026] unbound[7414:0] info: finishing processing for google.com. DS IN [1565196026] unbound[7414:0] debug: mesh_run: iterator module exit state is module_finished [1565196026] unbound[7414:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone [1565196026] unbound[7414:0] info: validator operate: query google.com. DS IN [1565196026] unbound[7414:0] debug: validator: nextmodule returned [1565196026] unbound[7414:0] debug: not validating response, is valrec(validation recursion lookup) [1565196026] unbound[7414:0] debug: mesh_run: validator module exit state is module_finished [1565196026] unbound[7414:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone [1565196026] unbound[7414:0] info: subnet operate: query google.com. DS IN [1565196026] unbound[7414:0] debug: mesh_run: subnet module exit state is module_finished [1565196026] unbound[7414:0] info: validator: inform_super, sub is google.com. DS IN [1565196026] unbound[7414:0] info: super is google.com. A IN [1565196026] unbound[7414:0] info: verify rrset CK0POJMG874LJREF7EFN8430QVIT8BSM.com. NSEC3 IN [1565196026] unbound[7414:0] debug: verify sig 17708 8 [1565196026] unbound[7414:0] debug: verify result: sec_status_secure [1565196026] unbound[7414:0] info: verify rrset S84BDVKNH5AGDSI7F5J0O3NPRHU0G7JQ.com. NSEC3 IN [1565196026] unbound[7414:0] debug: verify sig 17708 8 [1565196026] unbound[7414:0] debug: verify result: sec_status_secure [1565196026] unbound[7414:0] debug: nsec3: keysize 1024 bits, max iterations 150 [1565196026] unbound[7414:0] info: ce candidate com. TYPE0 CLASS0 [1565196026] unbound[7414:0] info: NSEC3s for the referral proved no DS. [1565196026] unbound[7414:0] debug: validator[module 1] operate: extstate:module_wait_subquery event:module_event_pass [1565196026] unbound[7414:0] info: validator operate: query google.com. A IN [1565196026] unbound[7414:0] debug: val handle processing q with state VAL_VALIDATE_STATE [1565196026] unbound[7414:0] info: Verified that unsigned response is INSECURE [1565196026] unbound[7414:0] debug: val handle processing q with state VAL_FINISHED_STATE [1565196026] unbound[7414:0] debug: mesh_run: validator module exit state is module_finished [1565196026] unbound[7414:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone [1565196026] unbound[7414:0] info: subnet operate: query google.com. A IN [1565196026] unbound[7414:0] debug: mesh_run: subnet module exit state is module_finished [1565196026] unbound[7414:0] debug: query took 0.794191 sec [1565196026] unbound[7414:0] info: mesh_run: end 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 2 recursion replies sent, 0 replies dropped, 0 states jostled out [1565196026] unbound[7414:0] info: average recursion processing time 2.559731 sec [1565196026] unbound[7414:0] info: histogram of recursion processing times [1565196026] unbound[7414:0] info: [25%]=0 median[50%]=0 [75%]=0 [1565196026] unbound[7414:0] info: lower(secs) upper(secs) recursions [1565196026] unbound[7414:0] info: 0.524288 1.000000 1 [1565196026] unbound[7414:0] info: 4.000000 8.000000 1 [1565196026] unbound[7414:0] debug: cache memory msg=68965 rrset=75290 infra=9590 val=70000 subnet=74504 [1565196026] unbound[7414:0] debug: svcd callbacks end [1565196026] unbound[7414:0] debug: close fd 39 [1565196053] unbound[7414:0] info: service stopped (unbound 1.9.0). [1565196053] unbound[7414:0] debug: stop threads [1565196053] unbound[7414:0] debug: join 1 [1565196053] unbound[7414:1] debug: got control cmd quit [1565196053] unbound[7414:0] debug: join success 1 [1565196053] unbound[7414:0] debug: join 2 [1565196053] unbound[7414:2] debug: got control cmd quit [1565196053] unbound[7414:0] debug: join success 2 [1565196053] unbound[7414:0] debug: cleanup.

==> /var/log/syslog <== Aug 7 18:40:53 localhost systemd[1]: unbound.service: Start operation timed out. Terminating.

==> /etc/unbound/logs/default.log <== [1565196053] unbound[7414:0] info: server stats for thread 0: 2 queries, 0 answers from cache, 2 recursions, 0 prefetch, 0 rejected by ip ratelimiting [1565196053] unbound[7414:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0 [1565196053] unbound[7414:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 2 recursion replies sent, 0 replies dropped, 0 states jostled out [1565196053] unbound[7414:0] info: average recursion processing time 2.559731 sec [1565196053] unbound[7414:0] info: histogram of recursion processing times [1565196053] unbound[7414:0] info: [25%]=0 median[50%]=0 [75%]=0 [1565196053] unbound[7414:0] info: lower(secs) upper(secs) recursions [1565196053] unbound[7414:0] info: 0.524288 1.000000 1 [1565196053] unbound[7414:0] info: 4.000000 8.000000 1 [1565196053] unbound[7414:0] debug: cache memory msg=66072 rrset=66072 infra=9590 val=70000 subnet=74504 [1565196054] unbound[7414:0] info: server stats for thread 1: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting [1565196054] unbound[7414:0] info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0 [1565196054] unbound[7414:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 1 recursion replies sent, 0 replies dropped, 0 states jostled out [1565196054] unbound[7414:0] info: average recursion processing time 9.752778 sec [1565196054] unbound[7414:0] info: histogram of recursion processing times [1565196054] unbound[7414:0] info: [25%]=0 median[50%]=0 [75%]=0 [1565196054] unbound[7414:0] info: lower(secs) upper(secs) recursions [1565196054] unbound[7414:0] info: 8.000000 16.000000 1 [1565196054] unbound[7414:0] debug: cache memory msg=66072 rrset=66072 infra=9590 val=70000 subnet=74504 [1565196054] unbound[7414:0] info: server stats for thread 2: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting [1565196054] unbound[7414:0] info: server stats for thread 2: requestlist max 0 avg 0 exceeded 0 jostled 0 [1565196054] unbound[7414:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out [1565196054] unbound[7414:0] debug: cache memory msg=66072 rrset=66072 infra=9590 val=70000 subnet=74504 [1565196054] unbound[7414:0] debug: Exit cleanup. [1565196054] unbound[7414:0] debug: switching log to stderr

==> /var/log/syslog <== Aug 7 18:40:54 localhost systemd[1]: unbound.service: Failed with result ‘timeout’. Aug 7 18:40:54 localhost systemd[1]: Failed to start Unbound DNS server.