Unbound doesn't always start on a reboot
-
often unbound hasn't automatically started on a reboot, I dunno why. this has been happening throught he last few versions, and happened when I rebooted into 2.3.3 for the first time after an upgrade just now.
very plain jane configuration, on a apu1d4. unbound log entries since just before the upgrade.
Feb 21 21:24:48 unbound 66744:0 notice: Restart of unbound 1.5.9.
Feb 21 21:24:48 unbound 66744:0 notice: init module 0: validator
Feb 21 21:24:48 unbound 66744:0 notice: init module 1: iterator
Feb 21 21:24:49 unbound 66744:0 info: start of service (unbound 1.5.9).
Feb 21 21:28:01 kernel unbound: 1.5.9 -> 1.6.0 [pfSense]
Feb 21 21:29:12 unbound 22217:0 notice: init module 0: validator
Feb 21 21:29:12 unbound 22217:0 notice: init module 1: iterator
Feb 21 21:29:12 unbound 22217:0 info: start of service (unbound 1.6.0).
Feb 21 21:29:12 unbound 22217:0 info: service stopped (unbound 1.6.0).
Feb 21 21:29:12 unbound 22217:0 info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch
Feb 21 21:29:12 unbound 22217:0 info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
Feb 21 21:29:12 unbound 22217:0 info: server stats for thread 1: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch
Feb 21 21:29:12 unbound 22217:0 info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
Feb 21 21:29:12 unbound 22217:0 notice: Restart of unbound 1.6.0.
Feb 21 21:29:12 unbound 22217:0 error: cannot chdir to directory: (No such file or directory)
Feb 21 21:29:12 unbound 22217:0 notice: init module 0: validator
Feb 21 21:29:12 unbound 22217:0 notice: init module 1: iterator
Feb 21 21:29:13 unbound 22217:0 info: start of service (unbound 1.6.0).
Feb 21 21:29:14 unbound 22217:0 info: service stopped (unbound 1.6.0).
Feb 21 21:29:14 unbound 22217:0 info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch
Feb 21 21:29:14 unbound 22217:0 info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
Feb 21 21:29:14 unbound 22217:0 info: server stats for thread 1: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch
Feb 21 21:29:14 unbound 22217:0 info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
Feb 21 21:29:14 unbound 22217:0 notice: Restart of unbound 1.6.0.
Feb 21 21:29:14 unbound 22217:0 error: cannot chdir to directory: (No such file or directory)
Feb 21 21:29:14 unbound 22217:0 notice: init module 0: validator
Feb 21 21:29:14 unbound 22217:0 notice: init module 1: iterator
Feb 21 21:29:14 unbound 22217:0 info: start of service (unbound 1.6.0).
Feb 21 21:29:14 unbound 22217:0 info: service stopped (unbound 1.6.0).
Feb 21 21:29:14 unbound 22217:0 info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch
Feb 21 21:29:14 unbound 22217:0 info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
Feb 21 21:29:14 unbound 22217:0 info: server stats for thread 1: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch
Feb 21 21:29:14 unbound 22217:0 info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
Feb 21 21:29:14 unbound 22217:0 notice: Restart of unbound 1.6.0.
Feb 21 21:29:14 unbound 22217:0 error: cannot chdir to directory: (No such file or directory)
Feb 21 21:29:14 unbound 22217:0 notice: init module 0: validator
Feb 21 21:29:14 unbound 22217:0 notice: init module 1: iterator
Feb 21 21:29:14 unbound 22217:0 info: start of service (unbound 1.6.0). -
oh, and kernel (system/general) messages starting with network initialization…
Feb 21 21:28:01 check_reload_status Linkup starting re1
Feb 21 21:28:01 kernel re1: link state changed to DOWN
Feb 21 21:28:02 sshd 6733 Server listening on :: port 22.
Feb 21 21:28:02 sshd 6733 Server listening on 0.0.0.0 port 22.
Feb 21 21:28:02 sshlockout 7035 sshlockout/webConfigurator v3.0 starting up
Feb 21 21:28:04 check_reload_status Linkup starting re1
Feb 21 21:28:04 kernel re1: link state changed to UP
Feb 21 21:28:04 check_reload_status rc.newwanip starting re1
Feb 21 21:28:04 check_reload_status Linkup starting re2
Feb 21 21:28:04 kernel re2: link state changed to DOWN
Feb 21 21:28:05 php-cgi rc.bootup: Resyncing OpenVPN instances.
Feb 21 21:28:05 kernel tun2: changing name to 'ovpns2'
Feb 21 21:28:05 kernel ovpns2: link state changed to UP
Feb 21 21:28:05 check_reload_status rc.newwanip starting ovpns2
Feb 21 21:28:05 kernel pflog0: promiscuous mode enabled
Feb 21 21:28:05 kernel ...
Feb 21 21:28:05 kernel .done.
Feb 21 21:28:05 php-cgi rc.bootup: ROUTING: setting default route to 73.222.224.1
Feb 21 21:28:05 php-cgi rc.bootup: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1487741285] unbound[22119:0] error: can't bind socket: Can't assign requested address for fe80::20d:b9ff:fe35:933a [1487741285] unbound[22119:0] fatal error: could not open ports'
Feb 21 21:28:05 php-fpm 1076 /rc.newwanip: rc.newwanip: Info: starting on re1.
Feb 21 21:28:05 kernel done.
Feb 21 21:28:05 php-fpm 1076 /rc.newwanip: rc.newwanip: on (IP address: 73.222.225.64) (interface: WAN[wan]) (real interface: re1).
Feb 21 21:28:05 dhcpleases Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such file or directory.
Feb 21 21:28:05 dhcpleases /var/etc/hosts changed size from original!
Feb 21 21:28:06 php-fpm 1076 /rc.newwanip: Accept router advertisements on interface re1
Feb 21 21:28:06 php-fpm 24316 /rc.newwanip: rc.newwanip: Info: starting on ovpns2.
Feb 21 21:28:06 php-fpm 24316 /rc.newwanip: rc.newwanip: on (IP address: 192.168.2.1) (interface: []) (real interface: ovpns2).
Feb 21 21:28:06 kernel done.
Feb 21 21:28:07 rtsold Received RA specifying route fe80::201:5cff:fe75:8846 for interface wan(re1)
Feb 21 21:28:07 rtsold Starting dhcp6 client for interface wan(re1)
Feb 21 21:28:07 kernel done.
Feb 21 21:28:07 php-cgi rc.bootup: NTPD is starting up.
Feb 21 21:28:07 kernel done.
Feb 21 21:28:07 kernel done.
Feb 21 21:28:07 check_reload_status Updating all dyndns
Feb 21 21:28:07 dhcpleases Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such file or directory.
Feb 21 21:28:07 kernel ..
Feb 21 21:28:07 kernel re2: link state changed to UP
Feb 21 21:28:08 check_reload_status Linkup starting re2
Feb 21 21:28:08 php-fpm 24316 /rc.newwanipv6: rc.newwanipv6: Info: starting on re1.
Feb 21 21:28:08 php-fpm 24316 /rc.newwanipv6: rc.newwanipv6: on (IP address: 2001:558:6045:6c:21af:b4c8:9780:2241) (interface: wan) (real interface: re1).
Feb 21 21:28:08 php-fpm 24316 /rc.newwanipv6: ROUTING: setting default route to 73.222.224.1
Feb 21 21:28:08 php-fpm 24316 /rc.newwanipv6: ROUTING: setting IPv6 default route to fe80::201:5cff:fe75:8846%re1
Feb 21 21:28:08 php-fpm 24316 /rc.newwanipv6: Removing static route for monitor fe80::201:5cff:fe75:8846 and adding a new route through fe80::201:5cff:fe75:8846%re1
Feb 21 21:28:12 php-cgi rc.bootup: Creating rrd update script
Feb 21 21:28:12 kernel done.
Feb 21 21:28:12 syslogd exiting on signal 15
Feb 21 21:28:12 syslogd kernel boot file is /boot/kernel/kernel
Feb 21 21:28:12 php-fpm 24316 /rc.start_packages: Restarting/Starting all packages.
Feb 21 21:28:12 kernel done.
Feb 21 21:28:14 kernel done.
Feb 21 21:28:14 kernel done.
Feb 21 21:28:14 getty 99047 open /dev/ttyv0: No such file or directory
Feb 21 21:28:14 sshlockout 99501 sshlockout/webConfigurator v3.0 starting up
Feb 21 21:28:14 login login on ttyu0 as root
Feb 21 21:28:16 dhcpleases Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such file or directory.
Feb 21 21:29:01 php-fpm 24316 /index.php: Successful login for user 'admin' from: 192.168.0.2
Feb 21 21:29:12 dhcpleases /var/etc/hosts changed size from original!
Feb 21 21:29:12 dhcpleases Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such file or directory.
Feb 21 21:29:12 dhcpleases kqueue error: unkown
Feb 21 21:32:12 check_reload_status Linkup starting re0
Feb 21 21:32:12 kernel re0: link state changed to DOWN
Feb 21 21:32:13 check_reload_status Reloading filter -
It seems this is a common issue with some workarounds. I just fixed mine today. The important message to look for is in the system log is: (mine on 2.3.3 is below):
Mar 8 14:50:29 php-cgi rc.bootup: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1489006229] unbound[19386:0] error: can't bind socket: Can't assign requested address for fe80::250:56ff:feb7:527c [1489006229] unbound[19386:0] fatal error: could not open ports'
The issue is that IPv6 isn't the actual address of my interface. It's a SLAAC IPv6 address that only exists for a short time and isn't valid when unbound starts up and is trying to bind to it. It seems it's a service startup timing issue. The workaround I used was going to Services > DNS Resolver > General Settings > Network Interfaces and deselecting LAN IPv6 Link-Local. Save, reboot, and see if it starts up automatically.
-
I'm wondering if this could be related to an issue I've been observing with unbound and reported in this post:
https://forum.pfsense.org/index.php?topic=126925.0I notice that you have an ovpn interface too, which maybe has nothing to do with it, but I do too. In my configuration, I have unbound configured to only use my two ovpn interfaces for outgoing DNS (in order to force all DNS through the VPN client tunnels). What I've found is that following a reboot, DNS requests are not going through VPN, but straight out the WAN interface, as evidenced by running various online DNS leak tests. I was operating under the assumption that unbound's saved configuration was not being applied, and that it was using default settings, which include using all available interfaces for outbound DNS. However, perhaps it's just not starting at all. Except then I would expect to just have no working DNS at all until it's started. When you observe unbound fail to start, do you your DNS queries just fail? I will try rebooting my pfSense machine today and checking the logs to determine whether unbound is failing to start, or if something else is going on with my machine.
-
Just wanted to provide an update because I think the issue I'm observing is different. I haven't seen unbound fail to start after a reboot, but it consistently fails to restore the saved "Outgoing Interfaces" settings. I confirmed this by examining a diff of /var/unbound/unbound.conf immediately following a reboot and then after going to the "Services > DNS Resolver" page and clicking "Save" followed by "Apply Changes". The conf file immediately following a reboot had no "outgoing-interface" entries, which means it defaults to using all interfaces. The conf file after I did the "Save" and "Apply Changes" reflected my explicit outgoing interface settings, which is to only use my two ovpn client interfaces.