Unbound-times-out-with-communications-error-to-127-0-0-1-5335-timed-out

Help
1

Hi All
i have lost a few hairs trying to get unbound working. I installed unbound as per instructions here

Expected Behaviour:

I installed Pi-hole on the following.
Raspberry Pi 2
OS- Raspibian bookworm.
Pi-hole works flawlessly.
I then installed unbound and have not managed to get unbound to work.

Actual Behaviour:

Pihole works. no issues observed.
Unbound gives communications error.

Debug Token:

##below is the the error

root@piHole:~# dig pi-hole.net @127.0.0.1 -p 5335
;; communications error to 127.0.0.1#5335: timed out
;; communications error to 127.0.0.1#5335: timed out
;; communications error to 127.0.0.1#5335: timed out

##Config file sudo grep -v '#|^ -R /etc/unbound/unbound.conf*

root@piHole:~# sudo grep -v '#\|^$' -R /etc/unbound/unbound.conf*
/etc/unbound/unbound.conf:include-toplevel: "/etc/unbound/unbound.conf.d/*.conf"
/etc/unbound/unbound.conf.d/remote-control.conf:remote-control:
/etc/unbound/unbound.conf.d/remote-control.conf:  control-enable: yes
/etc/unbound/unbound.conf.d/remote-control.conf:  control-interface: /run/unbound.ctl
/etc/unbound/unbound.conf.d/pi-hole.conf:server:
/etc/unbound/unbound.conf.d/pi-hole.conf:    verbosity: 4
/etc/unbound/unbound.conf.d/pi-hole.conf:    logfile: "/var/log/unbound/unbound.log"
/etc/unbound/unbound.conf.d/pi-hole.conf:    log-time-ascii: yes
/etc/unbound/unbound.conf.d/pi-hole.conf:    interface: 127.0.0.1
/etc/unbound/unbound.conf.d/pi-hole.conf:    interface-automatic: yes
/etc/unbound/unbound.conf.d/pi-hole.conf:    port: 5335
/etc/unbound/unbound.conf.d/pi-hole.conf:    do-ip4: yes
/etc/unbound/unbound.conf.d/pi-hole.conf:    do-udp: yes
/etc/unbound/unbound.conf.d/pi-hole.conf:    do-tcp: yes
/etc/unbound/unbound.conf.d/pi-hole.conf:    do-ip6: no
/etc/unbound/unbound.conf.d/pi-hole.conf:    prefer-ip6: no
/etc/unbound/unbound.conf.d/pi-hole.conf:    harden-glue: yes
/etc/unbound/unbound.conf.d/pi-hole.conf:    harden-dnssec-stripped: yes
/etc/unbound/unbound.conf.d/pi-hole.conf:    use-caps-for-id: no
/etc/unbound/unbound.conf.d/pi-hole.conf:    edns-buffer-size: 1232
/etc/unbound/unbound.conf.d/pi-hole.conf:    prefetch: yes
/etc/unbound/unbound.conf.d/pi-hole.conf:    num-threads: 1
/etc/unbound/unbound.conf.d/pi-hole.conf:    so-rcvbuf: 1m
/etc/unbound/unbound.conf.d/pi-hole.conf:    private-address: 192.168.0.0/16
/etc/unbound/unbound.conf.d/pi-hole.conf:    private-address: 169.254.0.0/16
/etc/unbound/unbound.conf.d/pi-hole.conf:    private-address: 172.16.0.0/12
/etc/unbound/unbound.conf.d/pi-hole.conf:    private-address: 10.0.0.0/8
/etc/unbound/unbound.conf.d/pi-hole.conf:    private-address: fd00::/8
/etc/unbound/unbound.conf.d/pi-hole.conf:    private-address: fe80::/10
/etc/unbound/unbound.conf.d/root-auto-trust-anchor-file.conf:server:
/etc/unbound/unbound.conf.d/root-auto-trust-anchor-file.conf:    auto-trust-anchor-file: "/var/lib/unbound/root.key"

ss -tulpn sport = 5335

Netid           State            Recv-Q           Send-Q                     Local Address:Port                     Peer Address:Port           Process
udp             UNCONN           0                0                                0.0.0.0:5335                          0.0.0.0:*               users:(("unbound",pid=4463,fd=3))
tcp             LISTEN           0                256                              0.0.0.0:5335                          0.0.0.0:*               users:(("unbound",pid=4463,fd=4))
2

below is tests from various other troublehsooting commands observed from other similar threads. Strangely nslookup localhost -port 5335 works.

root@piHole:~# nslookup pi-hole.net
Server:         127.0.0.1
Address:        127.0.0.1#53

Non-authoritative answer:
Name:   pi-hole.net
Address: 3.18.136.52

root@piHole:~#
root@piHole:~# nslookup pi-hole.net 8.8.8.8
Server:         8.8.8.8
Address:        8.8.8.8#53

Non-authoritative answer:
Name:   pi-hole.net
Address: 3.18.136.52

root@piHole:~# nslookup ns-407.awsdns-50.com 8.8.8.8
Server:         8.8.8.8
Address:        8.8.8.8#53

Non-authoritative answer:
Name:   ns-407.awsdns-50.com
Address: 205.251.193.151
Name:   ns-407.awsdns-50.com
Address: 2600:9000:5301:9700::1

root@piHole:~# nslookup ns-407.awsdns-50.com 127.0.0.1
Server:         127.0.0.1
Address:        127.0.0.1#53

Non-authoritative answer:
Name:   ns-407.awsdns-50.com
Address: 205.251.193.151
Name:   ns-407.awsdns-50.com
Address: 2600:9000:5301:9700::1

root@piHole:~# nslookup -port=5335 ns-407.awsdns-50.com 127.0.0.1
;; communications error to 127.0.0.1#5335: timed out
;; communications error to 127.0.0.1#5335: timed out
;; communications error to 127.0.0.1#5335: timed out
;; no servers could be reached


root@piHole:~# nslookup pi-hole.net 205.251.193.151
Server:         205.251.193.151
Address:        205.251.193.151#53

Non-authoritative answer:
Name:   pi-hole.net
Address: 3.18.136.52

root@piHole:~# ls -l /etc/dnsmasq.d/
total 12
-rw-r--r-- 1 root root 1380 Dec 30 19:02 01-pihole.conf
-rw-r--r-- 1 root root 2190 Dec 30 19:01 06-rfc6761.conf
-rw-r--r-- 1 root root   21 Dec 30 01:01 99-edns.conf
3

Does running unbound-checkconf show any errors?

4

No errors reported.

root@piHole:~# unbound-checkconf
unbound-checkconf: no errors in /etc/unbound/unbound.conf
5

I looked at your grep of the config files in /etc/unbound/unbound.conf.d/ and notice one thing missing that is in mine and that is lines for remote-control.conf. Does this file exist in that directory ( should be pi-hole.conf, remote-control.conf, root-auto-trust-anchor-file.conf )

Note that this file exists on a fresh install on Unbound.

Updated: added the contents of the file:

remote-control:
  control-enable: yes
  # by default the control interface is is 127.0.0.1 and ::1 and port 8953
  # it is possible to use a unix socket too
  control-interface: /run/unbound.ctl
6

yes that one definitely exists,

root@piHole:~# ls -l  /etc/unbound/unbound.conf.d/
total 12
-rw-r--r-- 1 root root 650 Dec 30 19:56 pi-hole.conf
-rw-r--r-- 1 root root 195 Feb 13  2024 remote-control.conf
-rw-r--r-- 1 root root 190 Feb 13  2024 root-auto-trust-anchor-file.conf
root@piHole:~# ls -l  /etc/unbound/unbound.conf.d/remote-control.conf
-rw-r--r-- 1 root root 195 Feb 13  2024 /etc/unbound/unbound.conf.d/remote-control.conf
root@piHole:~# cat  /etc/unbound/unbound.conf.d/remote-control.conf
remote-control:
  control-enable: yes
  # by default the control interface is is 127.0.0.1 and ::1 and port 8953
  # it is possible to use a unix socket too
  control-interface: /run/unbound.ctl
7

Perhaps this is something different with Bullseye. Can you run cat /etc/ os-release and uname -a and post results.

8

Apologies, version bookworm, my mind is stuck on bullseye

PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)"
NAME="Raspbian GNU/Linux"
VERSION_ID="12"
VERSION="12 (bookworm)"
VERSION_CODENAME=bookworm
ID=raspbian
ID_LIKE=debian
HOME_URL="http://www.raspbian.org/"
SUPPORT_URL="http://www.raspbian.org/RaspbianForums"
BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs"
root@piHole:~# uname -a
Linux piHole 5.10.103+ #1529 Tue Mar 8 12:19:18 GMT 2022 armv6l GNU/Linux
9

No worries. I was going to install it on a test pi but no need if its Bookworm.

Only two things left I can think of are the contents of /etc/hosts and /etc/resolv.conf.

It might not hurt to also post results for systemctl status unbound

10

service is definitely running.

root@piHole:~# systemctl status unbound
● unbound.service - Unbound DNS server
     Loaded: loaded (/lib/systemd/system/unbound.service; enabled; preset: enabled)
     Active: active (running) since Mon 2024-12-30 19:56:39 SAST; 3h 46min ago
       Docs: man:unbound(8)
    Process: 4459 ExecStartPre=/usr/libexec/unbound-helper chroot_setup (code=exited, status=0/SUCCESS)
    Process: 4461 ExecStartPre=/usr/libexec/unbound-helper root_trust_anchor_update (code=exited, status=0/SUCCESS)
   Main PID: 4463 (unbound)
      Tasks: 1 (limit: 877)
        CPU: 6.842s
     CGroup: /system.slice/unbound.service
             └─4463 /usr/sbin/unbound -d -p

Dec 30 19:56:38 piHole systemd[1]: Starting unbound.service - Unbound DNS server...
Dec 30 19:56:38 piHole unbound[4463]: Dec 30 19:56:38 unbound[4463:0] debug: increased limit(open files) from 1024 to 4140
Dec 30 19:56:38 piHole unbound[4463]: Dec 30 19:56:38 unbound[4463:0] debug: creating udp4 socket 0.0.0.0 5335
Dec 30 19:56:38 piHole unbound[4463]: Dec 30 19:56:38 unbound[4463:0] debug: creating tcp4 socket 0.0.0.0 5335
Dec 30 19:56:38 piHole unbound[4463]: Dec 30 19:56:38 unbound[4463:0] debug: creating unix socket /run/unbound.ctl
Dec 30 19:56:38 piHole unbound[4463]: Dec 30 19:56:38 unbound[4463:0] debug: chdir to /etc/unbound
Dec 30 19:56:38 piHole unbound[4463]: Dec 30 19:56:38 unbound[4463:0] debug: drop user privileges, run as unbound
Dec 30 19:56:38 piHole unbound[4463]: Dec 30 19:56:38 unbound[4463:0] debug: switching log to /var/log/unbound/unbound.log
Dec 30 19:56:39 piHole systemd[1]: Started unbound.service - Unbound DNS server.
root@piHole:~# cat /etc/hosts
127.0.0.1       localhost
::1             localhost ip6-localhost ip6-loopback
ff02::1         ip6-allnodes
ff02::2         ip6-allrouters

127.0.1.1       piHole
root@piHole:~# cat /etc/resolv.conf
# Generated by resolvconf
nameserver 127.0.0.1
11

Yeah. Your log section looks different than mine. That might mean nothing. Curious what the output of journalctl --boot 0 --unit unbound.service is. This will look system logs for just today.

12

for a moment a i thought there is something to go after but seems i cant pick anything.

Dec 30 19:36:56 piHole systemd[1]: Starting unbound.service - Unbound DNS server...
Dec 30 19:36:57 piHole unbound[3087]: [3087:0] warning: subnetcache: prefetch is set but not working for data originating from the subnet module cache.
Dec 30 19:36:57 piHole systemd[1]: Started unbound.service - Unbound DNS server.
Dec 30 19:36:57 piHole unbound[3087]: [3087:0] info: start of service (unbound 1.17.1).
Dec 30 19:42:50 piHole unbound[3087]: [3087:0] info: service stopped (unbound 1.17.1).
Dec 30 19:42:50 piHole systemd[1]: Stopping unbound.service - Unbound DNS server...
Dec 30 19:42:51 piHole systemd[1]: unbound.service: Deactivated successfully.
Dec 30 19:42:51 piHole systemd[1]: Stopped unbound.service - Unbound DNS server.
Dec 30 19:42:51 piHole systemd[1]: unbound.service: Consumed 1.655s CPU time.
Dec 30 19:42:51 piHole systemd[1]: Starting unbound.service - Unbound DNS server...
Dec 30 19:42:52 piHole systemd[1]: Started unbound.service - Unbound DNS server.
Dec 30 19:56:02 piHole systemd[1]: Stopping unbound.service - Unbound DNS server...
Dec 30 19:56:02 piHole systemd[1]: unbound.service: Deactivated successfully.
Dec 30 19:56:02 piHole systemd[1]: Stopped unbound.service - Unbound DNS server.
Dec 30 19:56:02 piHole systemd[1]: unbound.service: Consumed 1.498s CPU time.
Dec 30 19:56:03 piHole systemd[1]: Starting unbound.service - Unbound DNS server...
Dec 30 19:56:03 piHole unbound[4350]: Dec 30 19:56:03 unbound[4350:0] debug: increased limit(open files) from 1024 to 4140
Dec 30 19:56:03 piHole unbound[4350]: Dec 30 19:56:03 unbound[4350:0] debug: creating udp4 socket 0.0.0.0 535
Dec 30 19:56:03 piHole unbound[4350]: Dec 30 19:56:03 unbound[4350:0] debug: creating tcp4 socket 0.0.0.0 535
Dec 30 19:56:03 piHole unbound[4350]: Dec 30 19:56:03 unbound[4350:0] debug: creating unix socket /run/unbound.ctl
Dec 30 19:56:03 piHole unbound[4350]: Dec 30 19:56:03 unbound[4350:0] debug: chdir to /etc/unbound
Dec 30 19:56:03 piHole unbound[4350]: Dec 30 19:56:03 unbound[4350:0] debug: drop user privileges, run as unbound
Dec 30 19:56:03 piHole unbound[4350]: Dec 30 19:56:03 unbound[4350:0] debug: switching log to /var/log/unbound/unbound.log
Dec 30 19:56:04 piHole systemd[1]: Started unbound.service - Unbound DNS server.
Dec 30 19:56:37 piHole systemd[1]: Stopping unbound.service - Unbound DNS server...
Dec 30 19:56:38 piHole systemd[1]: unbound.service: Deactivated successfully.
Dec 30 19:56:38 piHole systemd[1]: Stopped unbound.service - Unbound DNS server.
Dec 30 19:56:38 piHole systemd[1]: unbound.service: Consumed 2.013s CPU time.
Dec 30 19:56:38 piHole systemd[1]: Starting unbound.service - Unbound DNS server...
Dec 30 19:56:38 piHole unbound[4463]: Dec 30 19:56:38 unbound[4463:0] debug: increased limit(open files) from 1024 to 4140
Dec 30 19:56:38 piHole unbound[4463]: Dec 30 19:56:38 unbound[4463:0] debug: creating udp4 socket 0.0.0.0 5335
Dec 30 19:56:38 piHole unbound[4463]: Dec 30 19:56:38 unbound[4463:0] debug: creating tcp4 socket 0.0.0.0 5335
Dec 30 19:56:38 piHole unbound[4463]: Dec 30 19:56:38 unbound[4463:0] debug: creating unix socket /run/unbound.ctl
Dec 30 19:56:38 piHole unbound[4463]: Dec 30 19:56:38 unbound[4463:0] debug: chdir to /etc/unbound
Dec 30 19:56:38 piHole unbound[4463]: Dec 30 19:56:38 unbound[4463:0] debug: drop user privileges, run as unbound
Dec 30 19:56:38 piHole unbound[4463]: Dec 30 19:56:38 unbound[4463:0] debug: switching log to /var/log/unbound/unbound.log
Dec 30 19:56:39 piHole systemd[1]: Started unbound.service - Unbound DNS server.
13

I'm guessing the starting and stopping was you? If not that not correct.

One thing that I'm seeing that I don't see on either of my unbound setups are these lines:

Even going as far back as I can. Are you perhaps doing additonal logging? I noticed a line for "switching to /var/log/unbound/unbound.log"

14

that was me. yes i did additional logging. I will post that shortly. However i have run tcpdump in the meantime and picked up this

00:45:27.498651 lo    In  IP (tos 0x0, ttl 64, id 55167, offset 0, flags [none], proto UDP (17), length 82)
    127.0.0.1.38880 > 127.0.0.1.5335: [bad udp cksum 0xfe51 -> 0x89b3!] UDP, length 54
00:45:32.505548 lo    In  IP (tos 0x0, ttl 64, id 61516, offset 0, flags [none], proto UDP (17), length 82)
    127.0.0.1.56489 > 127.0.0.1.5335: [bad udp cksum 0xfe51 -> 0x44ea!] UDP, length 54
00:45:37.512037 lo    In  IP (tos 0x0, ttl 64, id 36211, offset 0, flags [none], proto UDP (17), length 82)
    127.0.0.1.54934 > 127.0.0.1.5335: [bad udp cksum 0xfe51 -> 0x4afd!] UDP, length 54
15

portion of log

Dec 31 00:49:10 unbound[6982:0] debug:    rtt=24064
Dec 31 00:49:10 unbound[6982:0] debug: servselect ip4 198.41.0.4 port 53 (len 16)
Dec 31 00:49:10 unbound[6982:0] debug:    rtt=24064
Dec 31 00:49:10 unbound[6982:0] debug: servselect ip4 202.12.27.33 port 53 (len 16)
Dec 31 00:49:10 unbound[6982:0] debug:    rtt=24064
Dec 31 00:49:10 unbound[6982:0] debug: servselect ip4 198.97.190.53 port 53 (len 16)
Dec 31 00:49:10 unbound[6982:0] debug:    rtt=24064
Dec 31 00:49:10 unbound[6982:0] debug: servselect ip4 199.7.91.13 port 53 (len 16)
Dec 31 00:49:10 unbound[6982:0] debug:    rtt=24064
Dec 31 00:49:10 unbound[6982:0] debug: servselect ip4 192.33.4.12 port 53 (len 16)
Dec 31 00:49:10 unbound[6982:0] debug:    rtt=24064
Dec 31 00:49:10 unbound[6982:0] debug: servselect ip4 199.7.83.42 port 53 (len 16)
Dec 31 00:49:10 unbound[6982:0] debug:    rtt=24064
Dec 31 00:49:10 unbound[6982:0] debug: servselect ip4 192.58.128.30 port 53 (len 16)
Dec 31 00:49:10 unbound[6982:0] debug:    rtt=24064
Dec 31 00:49:10 unbound[6982:0] debug: servselect ip4 193.0.14.129 port 53 (len 16)
Dec 31 00:49:10 unbound[6982:0] debug:    rtt=24064
Dec 31 00:49:10 unbound[6982:0] debug: servselect ip4 192.5.5.241 port 53 (len 16)
Dec 31 00:49:10 unbound[6982:0] debug:    rtt=24064
Dec 31 00:49:10 unbound[6982:0] debug: servselect ip4 192.203.230.10 port 53 (len 16)
Dec 31 00:49:10 unbound[6982:0] debug:    rtt=48128
Dec 31 00:49:10 unbound[6982:0] debug: selrtt 24064
Dec 31 00:49:10 unbound[6982:0] info: sending query: . NS IN
Dec 31 00:49:10 unbound[6982:0] debug: sending to target: <.> 202.12.27.33#53
Dec 31 00:49:10 unbound[6982:0] debug: dnssec status: expected
Dec 31 00:49:10 unbound[6982:0] debug: mesh_run: iterator module exit state is module_wait_reply
Dec 31 00:49:10 unbound[6982:0] info: mesh_run: end 4 recursion states (3 with reply, 0 detached), 3 waiting replies, 12 recursion replies sent, 0 replies dropped, 0 states jostled out
Dec 31 00:49:10 unbound[6982:0] info: average recursion processing time 223.181283 sec
Dec 31 00:49:10 unbound[6982:0] info: histogram of recursion processing times
Dec 31 00:49:10 unbound[6982:0] info: [25%]=128 median[50%]=256 [75%]=384
Dec 31 00:49:10 unbound[6982:0] info: lower(secs) upper(secs) recursions
Dec 31 00:49:10 unbound[6982:0] info:   64.000000  128.000000 3
Dec 31 00:49:10 unbound[6982:0] info:  128.000000  256.000000 3
Dec 31 00:49:10 unbound[6982:0] info:  256.000000  512.000000 6
Dec 31 00:49:10 unbound[6982:0] info: 0pvCD mod2  . NS IN
Dec 31 00:49:10 unbound[6982:0] info: 1RDdc mod2 rep microsoft.com. A IN
Dec 31 00:49:10 unbound[6982:0] info: 2RDdc mod2 rep microsoft.com. A IN
Dec 31 00:49:10 unbound[6982:0] info: 3RDdc mod2 rep microsoft.com. A IN
Dec 31 00:49:10 unbound[6982:0] debug: cache memory msg=33040 rrset=33040 infra=6897 val=33200 subnet=41372
Dec 31 00:49:10 unbound[6982:0] debug: svcd callbacks end
Dec 31 00:49:10 unbound[6982:0] debug: close of port 21831
Dec 31 00:49:10 unbound[6982:0] debug: close fd 12
Dec 31 00:49:10 unbound[6982:0] debug: serviced send timer
Dec 31 00:49:10 unbound[6982:0] debug: EDNS lookup known=0 vs=0
Dec 31 00:49:10 unbound[6982:0] debug: serviced query UDP timeout=24064 msec
Dec 31 00:49:10 unbound[6982:0] debug: inserted new pending reply id=b57a
Dec 31 00:49:10 unbound[6982:0] debug: opened UDP if=0 port=39985
Dec 31 00:49:10 unbound[6982:0] debug: comm point start listening 12 (-1 msec)
16

Thats starting to look like networking issues. Those UDP Checksum errors are likely dropped packets and you have what looks like some UDP timeouts.

It might be benifical to run something like iperf3 to test for packet loss.

17

Except, this is a problem only for Unbound. This is why i posted the entries showing dns resolution success earlier. If it was that drops then I would expect some packets to make it through or at least get occassional success. But this just does not work with unbound.

18

Fair enough. Unbound is performing the look ups recursively so its has more room for potential failures.

I'm afraid I'm running out of ideas to check. I did see a comment @deHakkelaar posted on a similar issue. He mentioned running nslookup -class=chaos -type=txt version.bind 127.0.0.1 to ensure pihole was getting queried. I imagine that it is as it seems to work but just not to local host which I'm scratching my head on.

19

thanks iam out of my depth now. here is the output. I changed my dns server on windows.

Please note the windows nslookup seems unreliable. M$ appears to have changed without notice. Server and port appears to be overridden by whatever is defined on the NIC. The result therefore comes from my router.

##On Pi

root@piHole:~# nslookup -class=chaos -type=txt version.bind 127.0.0.1
Server:         127.0.0.1
Address:        127.0.0.1#53

version.bind    text = "dnsmasq-pi-hole-v2.90+1"

then on Windows

nslookup -class=chaos -type=txt version.bind 192.168.2.5
Server:  UnKnown
Address:  192.168.2.5

version.bind    text =

        "dnsmasq-2.78"

for today let me take a nap, its almost wake up time :slight_smile: Thanks again for the assistance

20

Does unbound actually listen on port 5335? Check this with sudo lsof -i :5335

sudo lsof -i :5335
COMMAND PID    USER   FD   TYPE DEVICE SIZE/OFF NODE NAME
unbound 710 unbound    3u  IPv4   5818      0t0  UDP localhost:5335
unbound 710 unbound    4u  IPv4   5819      0t0  TCP localhost:5335 (LISTEN)