Netgate Discussion Forum
    • Categories
    • Recent
    • Tags
    • Popular
    • Users
    • Search
    • Register
    • Login

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

    Scheduled Pinned Locked Moved Problems Installing or Upgrading pfSense Software
    5 Posts 2 Posters 2.0k Views
    Loading More Posts
    • Oldest to Newest
    • Newest to Oldest
    • Most Votes
    Reply
    • Reply as topic
    Log in to reply
    This topic has been deleted. Only users with topic management privileges can see it.
    • stan-qazS Offline
      stan-qaz
      last edited by

      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
      1 Reply Last reply Reply Quote 0
      • C Offline
        cmb
        last edited by

        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.

        1 Reply Last reply Reply Quote 0
        • stan-qazS Offline
          stan-qaz
          last edited by

          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.
          1 Reply Last reply Reply Quote 0
          • C Offline
            cmb
            last edited by

            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.

            1 Reply Last reply Reply Quote 0
            • stan-qazS Offline
              stan-qaz
              last edited by

              Thanks I'll do that now.

              1 Reply Last reply Reply Quote 0
              • First post
                Last post
              Copyright 2025 Rubicon Communications LLC (Netgate). All rights reserved.