After 2.3_1 update DNS Resolver won't start on reboot



  • After I updated my SG-2440 with the patch to 2.3_1 the DNS Resolver won't start on reboot, it will start from the dashboard widget or the DNS Resolver page in services. Logs don't tell me anything but I'm including them here in case they would help someone. I don't believe it was doing this on 2.3 before the update.

    At reboot:

    May 2 15:14:23	filterdns		unable to open configuration file
    May 2 15:14:00	filterdns		unable to open configuration file
    

    After pressing the start-service icon:

    May 2 15:14:58	unbound	11126:0	info: start of service (unbound 1.5.5).
    May 2 15:14:58	unbound	11126:0	notice: init module 0: iterator
    May 2 15:14:58	unbound	11126:0	notice: Restart of unbound 1.5.5.
    May 2 15:14:58	unbound	11126:0	info: server stats for thread 1: requestlist max 1 avg 0.5 exceeded 0 jostled 0
    May 2 15:14:58	unbound	11126:0	info: server stats for thread 1: 2 queries, 0 answers from cache, 2 recursions, 0 prefetch
    May 2 15:14:58	unbound	11126:0	info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
    May 2 15:14:58	unbound	11126:0	info: server stats for thread 0: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch
    May 2 15:14:58	unbound	11126:0	info: service stopped (unbound 1.5.5).
    May 2 15:14:58	unbound	11126:0	info: start of service (unbound 1.5.5).
    May 2 15:14:58	unbound	11126:0	notice: init module 0: iterator
    May 2 15:14:58	unbound	11126:0	notice: Restart of unbound 1.5.5.
    May 2 15:14:58	unbound	11126:0	info: 0.065536 0.131072 1
    May 2 15:14:58	unbound	11126:0	info: 0.032768 0.065536 1
    May 2 15:14:58	unbound	11126:0	info: 0.016384 0.032768 2
    May 2 15:14:58	unbound	11126:0	info: 0.001024 0.002048 2
    May 2 15:14:58	unbound	11126:0	info: 0.000512 0.001024 1
    May 2 15:14:58	unbound	11126:0	info: lower(secs) upper(secs) recursions
    May 2 15:14:58	unbound	11126:0	info: [25%]=0.001408 median[50%]=0.02048 [75%]=0.04096
    May 2 15:14:58	unbound	11126:0	info: histogram of recursion processing times
    May 2 15:14:58	unbound	11126:0	info: average recursion processing time 0.027213 sec
    May 2 15:14:58	unbound	11126:0	info: server stats for thread 1: requestlist max 2 avg 0.8 exceeded 0 jostled 0
    May 2 15:14:58	unbound	11126:0	info: server stats for thread 1: 13 queries, 3 answers from cache, 10 recursions, 0 prefetch
    May 2 15:14:58	unbound	11126:0	info: 0.065536 0.131072 1
    May 2 15:14:58	unbound	11126:0	info: 0.032768 0.065536 1
    May 2 15:14:58	unbound	11126:0	info: 0.016384 0.032768 1
    May 2 15:14:58	unbound	11126:0	info: 0.001024 0.002048 2
    May 2 15:14:58	unbound	11126:0	info: 0.000512 0.001024 1
    May 2 15:14:58	unbound	11126:0	info: lower(secs) upper(secs) recursions
    May 2 15:14:58	unbound	11126:0	info: [25%]=0.00128 median[50%]=0.002048 [75%]=0.049152
    May 2 15:14:58	unbound	11126:0	info: histogram of recursion processing times
    May 2 15:14:58	unbound	11126:0	info: average recursion processing time 0.023041 sec
    May 2 15:14:58	unbound	11126:0	info: server stats for thread 0: requestlist max 1 avg 0.444444 exceeded 0 jostled 0
    May 2 15:14:58	unbound	11126:0	info: server stats for thread 0: 12 queries, 3 answers from cache, 9 recursions, 0 prefetch
    May 2 15:14:58	unbound	11126:0	info: service stopped (unbound 1.5.5).
    May 2 15:14:57	unbound	11126:0	info: start of service (unbound 1.5.5).
    May 2 15:14:56	unbound	11126:0	notice: init module 0: iterator
    May 2 15:14:56	unbound	11126:0	notice: Restart of unbound 1.5.5.
    May 2 15:14:56	unbound	11126:0	info: server stats for thread 1: requestlist max 1 avg 0.5 exceeded 0 jostled 0
    May 2 15:14:56	unbound	11126:0	info: server stats for thread 1: 2 queries, 0 answers from cache, 2 recursions, 0 prefetch
    May 2 15:14:56	unbound	11126:0	info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
    May 2 15:14:56	unbound	11126:0	info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch
    May 2 15:14:56	unbound	11126:0	info: service stopped (unbound 1.5.5).
    May 2 15:14:56	unbound	11126:0	info: start of service (unbound 1.5.5).
    May 2 15:14:56	unbound	11126:0	notice: init module 0: iterator
    


  • 2.3_1 changed nothing but the NTP version, which can't impact Unbound. There are potential edge case issues that date back well before 2.3 which you might be hitting just by coincidence.

    Anything from unbound in your system log? That should be where it logs if it fails to start for any reason.



  • Looking at the system log I found a few instances where unbound is mentioned, the first code snip is what may be the error. I'm using Cox Cable for my ISP if that makes any difference. This is the first fiddling I've done with the SG-2440 after the initial setup about a week ago so this might well have been an existing 2.3 problem that I just hadn't activated before.

    Snip from log below, lines wrapped so it is easier to read

    May 2 15:13:51	php-fpm	20006	/rc.newwanipv6: 
    The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', 
    the output was '[1462227231] unbound[66739:0] error: can't bind socket: 
    Can't assign requested address for 2600:8800:2603:1d02:208:a2ff:fe0a:6b64 [1462227231] unbound[66739:0]
     fatal error: could not open ports'
    
    
    May 2 15:13:57	xinetd	18574	Starting reconfiguration
    May 2 15:13:57	check_reload_status		Updating all dyndns
    May 2 15:13:57	dhcpleases		Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.
    May 2 15:13:57	dhcpleases		kqueue error: unkown
    May 2 15:13:57	kernel		done.
    May 2 15:13:56	kernel		done.
    May 2 15:13:56	dhcpleases		Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.
    May 2 15:13:56	dhcpleases		Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.
    May 2 15:13:56	dhcpleases		Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.
    May 2 15:13:56	kernel		done.
    May 2 15:13:56	php-cgi		rc.bootup: NTPD is starting up.
    May 2 15:13:56	dhcpleases		Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.
    May 2 15:13:56	kernel		done.
    May 2 15:13:56	php-cgi		rc.bootup: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1462227236] unbound[90478:0] error: can't bind socket: Can't assign requested address for fe80::208:a2ff:fe0a:6b62 [1462227236] unbound[90478:0] fatal error: could not open ports'
    May 2 15:13:55	php-cgi		rc.bootup: ROUTING: setting IPv6 default route to fe80::212:d9ff:fe54:63a5%igb0
    May 2 15:13:55	kernel		done.
    May 2 15:13:55	php-cgi		rc.bootup: ROUTING: setting default route to 70.171.249.1
    May 2 15:13:55	php-fpm	20006	/rc.newwanipv6: Resyncing OpenVPN instances for interface WAN.
    May 2 15:13:55	php-fpm	20006	/rc.newwanipv6: Ignoring IPsec reload since there are no tunnels on interface wan
    May 2 15:13:54	kernel		done.
    May 2 15:13:54	php-fpm	20006	/rc.newwanipv6: phpDynDNS (all.dnsomatic.com): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
    May 2 15:13:53	kernel		done.
    May 2 15:13:52	php-fpm	20006	/rc.newwanipv6: ROUTING: setting IPv6 default route to fe80::212:d9ff:fe54:63a5%igb0
    May 2 15:13:52	php-fpm	20006	/rc.newwanipv6: ROUTING: setting default route to 70.171.249.1
    May 2 15:13:52	kernel		igb2: link state changed to UP
    May 2 15:13:52	check_reload_status		Linkup starting igb2
    May 2 15:13:52	kernel		.
    May 2 15:13:51	dhcpleases		Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such file or directory.
    May 2 15:13:51	kernel		..
    May 2 15:13:51	php-fpm	20006	/rc.newwanipv6: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1462227231] unbound[66739:0] error: can't bind socket: Can't assign requested address for 2600:8800:2603:1d02:208:a2ff:fe0a:6b64 [1462227231] unbound[66739:0] fatal error: could not open ports'
    May 2 15:13:51	xinetd	18574	Reconfigured: new=0 old=1 dropped=0 (services)
    May 2 15:13:51	xinetd	18574	readjusting service 6969-udp
    May 2 15:13:51	xinetd	18574	Swapping defaults
    May 2 15:13:51	xinetd	18574	Starting reconfiguration
    May 2 15:13:51	php-fpm	304	/rc.newwanip: Resyncing OpenVPN instances for interface WAN.
    May 2 15:13:51	kernel		done.
    May 2 15:13:51	php-fpm	304	/rc.newwanip: Ignoring IPsec reload since there are no tunnels on interface wan
    May 2 15:13:51	kernel		done.
    May 2 15:13:51	php-cgi		rc.bootup: Resyncing OpenVPN instances.
    


  • That's an issue with link local IPv6 IPs that are specifically bound. If you change your binding to "all", that won't happen. That's been around on occasion for a while, it's something I'm looking into.



  • Thanks I'll do that now.


Log in to reply