Unbound does not automatically start after reboot

[jjstecchino]

I noticed after a restart, unbound does not start automatically. It is enabled on its page. As pfsense restarts, the notice that unbound is starting passes by without error, however after full reboot pfsense does not resolve DNS and on the service status page, unbound is not running. It starts ok manually. On the log I can only see the DHCP server complaining that cannot register addresses to unbound because it is off. (dhcpleases –> Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such file or directory.)

Of note I recently switched from dnsmasq to unbound on my system. dnsmasq is off but still installed.

[cmb]

If it fails to start, it should log something to the resolver or system log, it show anything there?

[jjstecchino]

Reading the system log I have this:
Jan 18 16:51:02 firewall php-cgi: rc.bootup: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1453153862] unbound[30411:0] error: can't bind socket: Can't assign requested address for fe80::ec4:7aff:fe31:aa09 [1453153862] unbound[30411:0] fatal error: could not open ports'

[cmb]

What do you have selected in "Network Interfaces"?

[jjstecchino]

LAN has a static IPV4 and IPV6 is set to track WAN.
WAN IPV4 is DHCP and IPV6 is a 6RD tunnel.

[cmb]

"Network Interfaces" field under Services>DNS Resolver I mean.

[jjstecchino]

Thank you for point me to the right place.
Indeed I had selected the IPV6 link local for LAN and after clearing that selection unbound starts at boot just fine. Why does selecting link local break unbound on reboot but not on manual service start? Does it have to do with the interface having another ipv6 already assigned to it?  The list shows a bunch of link locals, one for every interface in the system, including openvpn interfaces. Do all those link local selection belong in the list?

[cmb]

There is a link local address on each interface, that's correct. I'm guessing maybe with the 6rd config, the IPv6 coming up is delayed enough that the interface is still tentative.

If you're comfortable editing files, edit /etc/inc/unbound.inc and find the following.

function do_as_unbound_user($cmd, $param1 = "") {
        global $g;

        switch ($cmd) {
                case "start":
                        mwexec("/usr/local/sbin/unbound -c {$g['unbound_chroot_path']}/unbound.conf");
                        break;

Above the mwexec line, add the following line:

mwexec("ifconfig >> /root/ifconfig.txt");

So you have the following:

                case "start":
                        mwexec("ifconfig >> /root/ifconfig.txt");
                        mwexec("/usr/local/sbin/unbound -c {$g['unbound_chroot_path']}/unbound.conf");
                        break;

Then reboot. What are the contents of /root/ifconfig.txt after doing so?

[jjstecchino]

Here you go

igb0: flags=8843 <up,broadcast,running,simplex,multicast>metric 0 mtu 1500
	options=400bb <rxcsum,txcsum,vlan_mtu,vlan_hwtagging,jumbo_mtu,vlan_hwcsum,vlan_hwtso>ether xx:xx:7a:31:xx:xx
	inet6 fe80::ec4:7aff:xxxx:xxxx%igb0 prefixlen 64 scopeid 0x1 
	inet xxx.xxx.xxx.xxx netmask 0xfffff800 broadcast xxx.xxx.xxx.255 
	nd6 options=21 <performnud,auto_linklocal>media: Ethernet autoselect (1000baseT <full-duplex>)
	status: active
igb1: flags=8843 <up,broadcast,running,simplex,multicast>metric 0 mtu 1500
	options=400bb <rxcsum,txcsum,vlan_mtu,vlan_hwtagging,jumbo_mtu,vlan_hwcsum,vlan_hwtso>ether xx:xx:7a:31:xx:xx
	inet xxx.xxx.xxx.xxx netmask 0xffffff00 broadcast xxx.xxx.xxx.xxx 
	inet6 fe80::1:1%igb1 prefixlen 64 scopeid 0x2 
	inet6 2602:xxxx:xxxx:xxxx::1 prefixlen 64 
	nd6 options=21 <performnud,auto_linklocal>media: Ethernet autoselect
	status: no carrier
igb2: flags=8843 <up,broadcast,running,simplex,multicast>metric 0 mtu 1500
	options=400bb <rxcsum,txcsum,vlan_mtu,vlan_hwtagging,jumbo_mtu,vlan_hwcsum,vlan_hwtso>ether xx:xx:7a:31:xx:xx
	inet6 fe80::ec4:7aff:xxxx:xxxx%igb2 prefixlen 64 scopeid 0x3 
	inet xxx.xxx.xxx.xxx netmask 0xfffff800 broadcast xxx.xxx.xxx.255 
	nd6 options=21 <performnud,auto_linklocal>media: Ethernet autoselect (1000baseT <full-duplex>)
	status: active
igb3: flags=8c02 <broadcast,oactive,simplex,multicast>metric 0 mtu 1500
	options=403bb <rxcsum,txcsum,vlan_mtu,vlan_hwtagging,jumbo_mtu,vlan_hwcsum,tso4,tso6,vlan_hwtso>ether xx:xx:7a:31:xx:xx
	nd6 options=21 <performnud,auto_linklocal>media: Ethernet autoselect
	status: no carrier
pflog0: flags=0<> metric 0 mtu 33160
pfsync0: flags=0<> metric 0 mtu 1500
	syncpeer: 0.0.0.0 maxupd: 128 defer: off
	syncok: 1
enc0: flags=0<> metric 0 mtu 1536
	nd6 options=21 <performnud,auto_linklocal>lo0: flags=8049 <up,loopback,running,multicast>metric 0 mtu 16384
	options=600003 <rxcsum,txcsum,rxcsum_ipv6,txcsum_ipv6>inet 127.0.0.1 netmask 0xff000000 
	inet6 ::1 prefixlen 128 
	inet6 fe80::1%lo0 prefixlen 64 scopeid 0x8 
	nd6 options=21 <performnud,auto_linklocal>wan_stf: flags=4001 <up,link2>metric 0 mtu 1280
	inet6 2602:xxxx:xxxx:xxxx:: prefixlen 24 tentative 
	nd6 options=1 <performnud>v4net xxx.xxx.xxx.xxxx/32 -> tv4br 205.171.2.64
igb0: flags=8843 <up,broadcast,running,simplex,multicast>metric 0 mtu 1500
	options=400bb <rxcsum,txcsum,vlan_mtu,vlan_hwtagging,jumbo_mtu,vlan_hwcsum,vlan_hwtso>ether xx:xx:7a:31:xx:xx
	inet6 fe80::ec4:7aff:xxxx:xxxx%igb0 prefixlen 64 scopeid 0x1 
	inet xxx.xxx.xxx.xxx netmask 0xfffff800 broadcast xxx.xxx.xxx.255 
	nd6 options=21 <performnud,auto_linklocal>media: Ethernet autoselect (1000baseT <full-duplex>)
	status: active
igb1: flags=8843 <up,broadcast,running,simplex,multicast>metric 0 mtu 1500
	options=400bb <rxcsum,txcsum,vlan_mtu,vlan_hwtagging,jumbo_mtu,vlan_hwcsum,vlan_hwtso>ether xx:xx:7a:31:xx:xx
	inet xxx.xxx.xxx.xxx netmask 0xffffff00 broadcast xxx.xxx.xxx.255 
	inet6 fe80::1:1%igb1 prefixlen 64 scopeid 0x2 
	inet6 2602:xxxx:xxxx:xxxx::1 prefixlen 64 
	nd6 options=21 <performnud,auto_linklocal>media: Ethernet autoselect (1000baseT <full-duplex>)
	status: active
igb2: flags=8843 <up,broadcast,running,simplex,multicast>metric 0 mtu 1500
	options=400bb <rxcsum,txcsum,vlan_mtu,vlan_hwtagging,jumbo_mtu,vlan_hwcsum,vlan_hwtso>ether xx:xx:7a:31:xx:xx
	inet6 fe80::xxxx:xxxx:xxxx:xxxx%igb2 prefixlen 64 scopeid 0x3 
	inet xxx.xxx.xxx.xxx netmask 0xfffff800 broadcast xxx.xxx.xxx.255 
	nd6 options=21 <performnud,auto_linklocal>media: Ethernet autoselect (1000baseT <full-duplex>)
	status: active
igb3: flags=8c02 <broadcast,oactive,simplex,multicast>metric 0 mtu 1500
	options=403bb <rxcsum,txcsum,vlan_mtu,vlan_hwtagging,jumbo_mtu,vlan_hwcsum,tso4,tso6,vlan_hwtso>ether xx:xx:7a:31:xx:xx
	nd6 options=21 <performnud,auto_linklocal>media: Ethernet autoselect
	status: no carrier
pflog0: flags=100 <promisc>metric 0 mtu 33160
pfsync0: flags=0<> metric 0 mtu 1500
	syncpeer: 224.0.0.240 maxupd: 128 defer: on
	syncok: 1
enc0: flags=0<> metric 0 mtu 1536
	nd6 options=21 <performnud,auto_linklocal>lo0: flags=8049 <up,loopback,running,multicast>metric 0 mtu 16384
	options=600003 <rxcsum,txcsum,rxcsum_ipv6,txcsum_ipv6>inet 127.0.0.1 netmask 0xff000000 
	inet6 ::1 prefixlen 128 
	inet6 fe80::1%lo0 prefixlen 64 scopeid 0x8 
	nd6 options=21 <performnud,auto_linklocal>wan_stf: flags=4001 <up,link2>metric 0 mtu 1280
	inet6 2602:xxxx:xxxx:xxxx:: prefixlen 24 tentative 
	nd6 options=1 <performnud>v4net xxx.xxx.xxx.xxx/32 -> tv4br 205.171.2.64
ovpns1: flags=8051 <up,pointopoint,running,multicast>metric 0 mtu 1500
	options=80000 <linkstate>inet6 fe80::ec4:xxxx:xxxx:xxxx%ovpns1 prefixlen 64 scopeid 0xa 
	inet 192.168.xxx.xxx --> 192.188.xxx.xxx netmask 0xffffff00 
	nd6 options=21 <performnud,auto_linklocal>Opened by PID 32991
ovpns2: flags=8051 <up,pointopoint,running,multicast>metric 0 mtu 1500
	options=80000 <linkstate>inet6 fe80::ec4:xxxx:xxxx:xxxx%ovpns2 prefixlen 64 scopeid 0xb 
	inet 192.168.xxx.xxx --> 192.168.xxx.xxx netmask 0xffffffff 
	nd6 options=21 <performnud,auto_linklocal>Opened by PID 34674
ovpnc3: flags=8051 <up,pointopoint,running,multicast>metric 0 mtu 1500
	options=80000 <linkstate>inet6 fe80::ec4:xxxx:xxxx:xxxx%ovpnc3 prefixlen 64 scopeid 0xc 
	nd6 options=21 <performnud,auto_linklocal></performnud,auto_linklocal></linkstate></up,pointopoint,running,multicast></performnud,auto_linklocal></linkstate></up,pointopoint,running,multicast></performnud,auto_linklocal></linkstate></up,pointopoint,running,multicast></performnud></up,link2></performnud,auto_linklocal></rxcsum,txcsum,rxcsum_ipv6,txcsum_ipv6></up,loopback,running,multicast></performnud,auto_linklocal></promisc></performnud,auto_linklocal></rxcsum,txcsum,vlan_mtu,vlan_hwtagging,jumbo_mtu,vlan_hwcsum,tso4,tso6,vlan_hwtso></broadcast,oactive,simplex,multicast></full-duplex></performnud,auto_linklocal></rxcsum,txcsum,vlan_mtu,vlan_hwtagging,jumbo_mtu,vlan_hwcsum,vlan_hwtso></up,broadcast,running,simplex,multicast></full-duplex></performnud,auto_linklocal></rxcsum,txcsum,vlan_mtu,vlan_hwtagging,jumbo_mtu,vlan_hwcsum,vlan_hwtso></up,broadcast,running,simplex,multicast></full-duplex></performnud,auto_linklocal></rxcsum,txcsum,vlan_mtu,vlan_hwtagging,jumbo_mtu,vlan_hwcsum,vlan_hwtso></up,broadcast,running,simplex,multicast></performnud></up,link2></performnud,auto_linklocal></rxcsum,txcsum,rxcsum_ipv6,txcsum_ipv6></up,loopback,running,multicast></performnud,auto_linklocal></performnud,auto_linklocal></rxcsum,txcsum,vlan_mtu,vlan_hwtagging,jumbo_mtu,vlan_hwcsum,tso4,tso6,vlan_hwtso></broadcast,oactive,simplex,multicast></full-duplex></performnud,auto_linklocal></rxcsum,txcsum,vlan_mtu,vlan_hwtagging,jumbo_mtu,vlan_hwcsum,vlan_hwtso></up,broadcast,running,simplex,multicast></performnud,auto_linklocal></rxcsum,txcsum,vlan_mtu,vlan_hwtagging,jumbo_mtu,vlan_hwcsum,vlan_hwtso></up,broadcast,running,simplex,multicast></full-duplex></performnud,auto_linklocal></rxcsum,txcsum,vlan_mtu,vlan_hwtagging,jumbo_mtu,vlan_hwcsum,vlan_hwtso></up,broadcast,running,simplex,multicast> 

[cmb]

Hm, and during that boot it failed with that same "Can't assign requested address"?

[jjstecchino]

No, when it was failing to start, I had LAN, localhost and LAN IPV6 Link Local in network interfaces. After you pointed that out I de selected LAN IPV6 Link Local and left just LAN and localhost. After that unbound starts just fine.
The ifconfig output I gave you was after de-selecting LAN IPV6 link local, with unbound starting ok.

My question was that I have an IPV6 Link Local line in the network interface selection box for each and every interface in my box, i.e. LAN IPV6 Link Local, WAN IPV6 Link Local, WAN1 IPV6 Link Local, VPN IPV6 Link Local, but for example no LAN IPV6 (to real IPV6 address) and I was wondering if this is appropriate behavior

[cmb]

Looks like the link on the LAN NIC was down the first time it ran through the start. Which makes no sense because it should fail to bind any specific IP if that's where it's hitting the issue. I'm curious if that looks any different when it's in a config that will fail to start. Try first deleting that log.

rm /root/ifconfig.txt

Then select the link local IP that makes Unbound fail to start, and reboot. What's the ifconfig.txt look like after that? What Unbound logs do you end up with?

[jjstecchino]

Sorry for the late answer, got to catch up with life….

Here is the ifconfig.txt with the ipv6_link_local selected on network interface and unbound failing to start on reboot.

igb0: flags=8843 <up,broadcast,running,simplex,multicast>metric 0 mtu 1500
	options=400bb <rxcsum,txcsum,vlan_mtu,vlan_hwtagging,jumbo_mtu,vlan_hwcsum,vlan_hwtso>ether 0c:c4:7a:31:aa:08
	inet6 fe80::ec4:7aff:fe31:aa08%igb0 prefixlen 64 scopeid 0x1 
	inet 71.48.1.43 netmask 0xfffff800 broadcast 71.48.7.255 
	nd6 options=21 <performnud,auto_linklocal>media: Ethernet autoselect (1000baseT <full-duplex>)
	status: active
igb1: flags=8843 <up,broadcast,running,simplex,multicast>metric 0 mtu 1500
	options=400bb <rxcsum,txcsum,vlan_mtu,vlan_hwtagging,jumbo_mtu,vlan_hwcsum,vlan_hwtso>ether 0c:c4:7a:31:aa:09
	inet 192.168.100.250 netmask 0xffffff00 broadcast 192.168.100.255 
	inet6 fe80::1:1%igb1 prefixlen 64 scopeid 0x2 
	inet6 2602:47:3001:2b00::1 prefixlen 64 
	nd6 options=21 <performnud,auto_linklocal>media: Ethernet autoselect
	status: no carrier
igb2: flags=8843 <up,broadcast,running,simplex,multicast>metric 0 mtu 1500
	options=400bb <rxcsum,txcsum,vlan_mtu,vlan_hwtagging,jumbo_mtu,vlan_hwcsum,vlan_hwtso>ether 0c:c4:7a:31:aa:0a
	inet6 fe80::ec4:7aff:fe31:aa0a%igb2 prefixlen 64 scopeid 0x3 
	inet 71.48.1.75 netmask 0xfffff800 broadcast 71.48.7.255 
	nd6 options=21 <performnud,auto_linklocal>media: Ethernet autoselect (1000baseT <full-duplex>)
	status: active
igb3: flags=8c02 <broadcast,oactive,simplex,multicast>metric 0 mtu 1500
	options=403bb <rxcsum,txcsum,vlan_mtu,vlan_hwtagging,jumbo_mtu,vlan_hwcsum,tso4,tso6,vlan_hwtso>ether 0c:c4:7a:31:aa:0b
	nd6 options=21 <performnud,auto_linklocal>media: Ethernet autoselect
	status: no carrier
pflog0: flags=0<> metric 0 mtu 33160
pfsync0: flags=0<> metric 0 mtu 1500
	syncpeer: 0.0.0.0 maxupd: 128 defer: off
	syncok: 1
enc0: flags=0<> metric 0 mtu 1536
	nd6 options=21 <performnud,auto_linklocal>lo0: flags=8049 <up,loopback,running,multicast>metric 0 mtu 16384
	options=600003 <rxcsum,txcsum,rxcsum_ipv6,txcsum_ipv6>inet 127.0.0.1 netmask 0xff000000 
	inet6 ::1 prefixlen 128 
	inet6 fe80::1%lo0 prefixlen 64 scopeid 0x8 
	nd6 options=21 <performnud,auto_linklocal>wan_stf: flags=4041 <up,running,link2>metric 0 mtu 1280
	inet6 2602:47:3001:2b00:: prefixlen 24 
	nd6 options=1 <performnud>v4net 71.48.1.43/32 -> tv4br 205.171.2.64
igb0: flags=8843 <up,broadcast,running,simplex,multicast>metric 0 mtu 1500
	options=400bb <rxcsum,txcsum,vlan_mtu,vlan_hwtagging,jumbo_mtu,vlan_hwcsum,vlan_hwtso>ether 0c:c4:7a:31:aa:08
	inet6 fe80::ec4:7aff:fe31:aa08%igb0 prefixlen 64 scopeid 0x1 
	inet 71.48.1.43 netmask 0xfffff800 broadcast 71.48.7.255 
	nd6 options=21 <performnud,auto_linklocal>media: Ethernet autoselect (1000baseT <full-duplex>)
	status: active
igb1: flags=8843 <up,broadcast,running,simplex,multicast>metric 0 mtu 1500
	options=400bb <rxcsum,txcsum,vlan_mtu,vlan_hwtagging,jumbo_mtu,vlan_hwcsum,vlan_hwtso>ether 0c:c4:7a:31:aa:09
	inet 192.168.100.250 netmask 0xffffff00 broadcast 192.168.100.255 
	inet6 fe80::1:1%igb1 prefixlen 64 scopeid 0x2 
	inet6 2602:47:3001:2b00::1 prefixlen 64 
	nd6 options=21 <performnud,auto_linklocal>media: Ethernet autoselect (1000baseT <full-duplex>)
	status: active
igb2: flags=8843 <up,broadcast,running,simplex,multicast>metric 0 mtu 1500
	options=400bb <rxcsum,txcsum,vlan_mtu,vlan_hwtagging,jumbo_mtu,vlan_hwcsum,vlan_hwtso>ether 0c:c4:7a:31:aa:0a
	inet6 fe80::ec4:7aff:fe31:aa0a%igb2 prefixlen 64 scopeid 0x3 
	inet 71.48.1.75 netmask 0xfffff800 broadcast 71.48.7.255 
	nd6 options=21 <performnud,auto_linklocal>media: Ethernet autoselect (1000baseT <full-duplex>)
	status: active
igb3: flags=8c02 <broadcast,oactive,simplex,multicast>metric 0 mtu 1500
	options=403bb <rxcsum,txcsum,vlan_mtu,vlan_hwtagging,jumbo_mtu,vlan_hwcsum,tso4,tso6,vlan_hwtso>ether 0c:c4:7a:31:aa:0b
	nd6 options=21 <performnud,auto_linklocal>media: Ethernet autoselect
	status: no carrier
pflog0: flags=100 <promisc>metric 0 mtu 33160
pfsync0: flags=0<> metric 0 mtu 1500
	syncpeer: 224.0.0.240 maxupd: 128 defer: on
	syncok: 1
enc0: flags=0<> metric 0 mtu 1536
	nd6 options=21 <performnud,auto_linklocal>lo0: flags=8049 <up,loopback,running,multicast>metric 0 mtu 16384
	options=600003 <rxcsum,txcsum,rxcsum_ipv6,txcsum_ipv6>inet 127.0.0.1 netmask 0xff000000 
	inet6 ::1 prefixlen 128 
	inet6 fe80::1%lo0 prefixlen 64 scopeid 0x8 
	nd6 options=21 <performnud,auto_linklocal>wan_stf: flags=4041 <up,running,link2>metric 0 mtu 1280
	inet6 2602:47:3001:2b00:: prefixlen 24 
	nd6 options=1 <performnud>v4net 71.48.1.43/32 -> tv4br 205.171.2.64
ovpns1: flags=8051 <up,pointopoint,running,multicast>metric 0 mtu 1500
	options=80000 <linkstate>inet6 fe80::ec4:7aff:fe31:aa08%ovpns1 prefixlen 64 scopeid 0xa 
	inet 192.168.110.1 --> 192.168.110.2 netmask 0xffffff00 
	nd6 options=21 <performnud,auto_linklocal>Opened by PID 35006
ovpns2: flags=8051 <up,pointopoint,running,multicast>metric 0 mtu 1500
	options=80000 <linkstate>inet6 fe80::ec4:7aff:fe31:aa08%ovpns2 prefixlen 64 scopeid 0xb 
	inet 192.168.120.1 --> 192.168.120.2 netmask 0xffffffff 
	nd6 options=21 <performnud,auto_linklocal>Opened by PID 37481
ovpnc3: flags=8051 <up,pointopoint,running,multicast>metric 0 mtu 1500
	options=80000 <linkstate>inet6 fe80::ec4:7aff:fe31:aa08%ovpnc3 prefixlen 64 scopeid 0xc 
	nd6 options=21 <performnud,auto_linklocal></performnud,auto_linklocal></linkstate></up,pointopoint,running,multicast></performnud,auto_linklocal></linkstate></up,pointopoint,running,multicast></performnud,auto_linklocal></linkstate></up,pointopoint,running,multicast></performnud></up,running,link2></performnud,auto_linklocal></rxcsum,txcsum,rxcsum_ipv6,txcsum_ipv6></up,loopback,running,multicast></performnud,auto_linklocal></promisc></performnud,auto_linklocal></rxcsum,txcsum,vlan_mtu,vlan_hwtagging,jumbo_mtu,vlan_hwcsum,tso4,tso6,vlan_hwtso></broadcast,oactive,simplex,multicast></full-duplex></performnud,auto_linklocal></rxcsum,txcsum,vlan_mtu,vlan_hwtagging,jumbo_mtu,vlan_hwcsum,vlan_hwtso></up,broadcast,running,simplex,multicast></full-duplex></performnud,auto_linklocal></rxcsum,txcsum,vlan_mtu,vlan_hwtagging,jumbo_mtu,vlan_hwcsum,vlan_hwtso></up,broadcast,running,simplex,multicast></full-duplex></performnud,auto_linklocal></rxcsum,txcsum,vlan_mtu,vlan_hwtagging,jumbo_mtu,vlan_hwcsum,vlan_hwtso></up,broadcast,running,simplex,multicast></performnud></up,running,link2></performnud,auto_linklocal></rxcsum,txcsum,rxcsum_ipv6,txcsum_ipv6></up,loopback,running,multicast></performnud,auto_linklocal></performnud,auto_linklocal></rxcsum,txcsum,vlan_mtu,vlan_hwtagging,jumbo_mtu,vlan_hwcsum,tso4,tso6,vlan_hwtso></broadcast,oactive,simplex,multicast></full-duplex></performnud,auto_linklocal></rxcsum,txcsum,vlan_mtu,vlan_hwtagging,jumbo_mtu,vlan_hwcsum,vlan_hwtso></up,broadcast,running,simplex,multicast></performnud,auto_linklocal></rxcsum,txcsum,vlan_mtu,vlan_hwtagging,jumbo_mtu,vlan_hwcsum,vlan_hwtso></up,broadcast,running,simplex,multicast></full-duplex></performnud,auto_linklocal></rxcsum,txcsum,vlan_mtu,vlan_hwtagging,jumbo_mtu,vlan_hwcsum,vlan_hwtso></up,broadcast,running,simplex,multicast> 

system.log shows an error that unbound could not start because cannot bind socket: can't assign requested address for fe80:…..