DNS Resolver problem - pfBlocker related?



  • I am on a SG-2440 and seeing DNS (unbound) stop running. Without pfBlocker running all is well as it is with pfBlocker with just the DNSBLs loaded, but when I add the IPv4 blocklists to pfBlocker I see problems with Unbound restarting automatically a few times per day. A manual start from the dashboard once this problem hits starts it just fine though.

    I'll post snips from my logs here just in case someone can see if what is happening isn't a pfBlocker issue and then go look at the link to pfBlocker memory errors mentioned in another topic in this forum.

    The only connection I see between Unbound, pfBlocker and this problem is that they were both active at the same time.

    I have no clue about the unbound IPv6 errors below that look to be what is triggering the restart failure unless there needs to be a delay added since a manual restart after a couple minutes does work.

    System General Log:

    Aug 19 23:41:27	php-fpm	36593	/index.php: Successful login for user 'admin' from: 172.16.0.11
    Aug 19 23:27:43	xinetd	19583	Reconfigured: new=0 old=1 dropped=0 (services)
    Aug 19 23:27:43	xinetd	19583	readjusting service 6969-udp
    Aug 19 23:27:43	xinetd	19583	Swapping defaults
    Aug 19 23:27:43	xinetd	19583	Starting reconfiguration
    Aug 19 23:27:42	check_reload_status		Reloading filter
    Aug 19 23:27:42	php-fpm	99318	/rc.newwanipv6: Removing static route for monitor fe80::212:d9ff:fe54:63a5 and adding a new route through fe80::212:d9ff:fe54:63a5%igb0
    Aug 19 23:27:42	php-fpm	99318	/rc.newwanipv6: ROUTING: setting IPv6 default route to fe80::212:d9ff:fe54:63a5%igb0
    Aug 19 23:27:42	php-fpm	99318	/rc.newwanipv6: ROUTING: setting default route to 70.171.249.1
    Aug 19 23:27:38	php-fpm	99318	/rc.newwanipv6: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1471674458] unbound[18415:0] error: bind: address already in use [1471674458] unbound[18415:0] fatal error: could not open ports'
    Aug 19 23:27:23	php-fpm	99318	/rc.newwanipv6: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1471674443] unbound[85739:0] error: bind: address already in use [1471674443] unbound[85739:0] fatal error: could not open ports'
    Aug 19 23:27:20	xinetd	19583	Reconfigured: new=0 old=1 dropped=0 (services)
    Aug 19 23:27:20	xinetd	19583	readjusting service 6969-udp
    Aug 19 23:27:20	xinetd	19583	Swapping defaults
    Aug 19 23:27:20	xinetd	19583	Starting reconfiguration
    Aug 19 23:27:20	php-fpm	99318	/rc.newwanipv6: rc.newwanipv6: on (IP address: 2600:8800:ff06:c00:91c1:9ca4:bcce:1de8) (interface: wan) (real interface: igb0).
    Aug 19 23:27:20	php-fpm	99318	/rc.newwanipv6: rc.newwanipv6: Info: starting on igb0.
    Aug 19 23:27:19	check_reload_status		Reloading filter
    Aug 19 23:27:19	php-fpm	89324	/rc.newwanipv6: Removing static route for monitor fe80::212:d9ff:fe54:63a5 and adding a new route through fe80::212:d9ff:fe54:63a5%igb0
    Aug 19 23:27:19	php-fpm	89324	/rc.newwanipv6: ROUTING: setting IPv6 default route to fe80::212:d9ff:fe54:63a5%igb0
    Aug 19 23:27:19	php-fpm	89324	/rc.newwanipv6: ROUTING: setting default route to 70.171.249.1
    Aug 19 23:27:15	php-fpm	89324	/rc.newwanipv6: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1471674435] unbound[66130:0] error: bind: address already in use [1471674435] unbound[66130:0] fatal error: could not open ports'
    Aug 19 23:27:08	php-fpm	89324	/rc.newwanipv6: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1471674428] unbound[30579:0] error: bind: address already in use [1471674428] unbound[30579:0] fatal error: could not open ports'
    Aug 19 23:26:58	php-fpm	89324	/rc.newwanipv6: rc.newwanipv6: on (IP address: 2600:8800:ff06:c00:91c1:9ca4:bcce:1de8) (interface: wan) (real interface: igb0).
    Aug 19 23:26:58	php-fpm	89324	/rc.newwanipv6: rc.newwanipv6: Info: starting on igb0.
    

    DNS Resolver Log:

    Aug 19 23:45:30	unbound	65080:0	info: start of service (unbound 1.5.9).
    Aug 19 23:45:30	unbound	65080:0	notice: init module 0: iterator
    Aug 19 23:45:02	unbound	65080:0	notice: Restart of unbound 1.5.9.
    Aug 19 23:45:02	unbound	65080:0	info: server stats for thread 1: requestlist max 25 avg 14 exceeded 0 jostled 0
    Aug 19 23:45:02	unbound	65080:0	info: server stats for thread 1: 37 queries, 0 answers from cache, 37 recursions, 0 prefetch
    Aug 19 23:45:02	unbound	65080:0	info: server stats for thread 0: requestlist max 36 avg 22.6771 exceeded 0 jostled 0
    Aug 19 23:45:02	unbound	65080:0	info: server stats for thread 0: 96 queries, 0 answers from cache, 96 recursions, 0 prefetch
    Aug 19 23:45:02	unbound	65080:0	info: service stopped (unbound 1.5.9).
    Aug 19 23:45:02	unbound	65080:0	info: start of service (unbound 1.5.9).
    Aug 19 23:45:02	unbound	65080:0	notice: init module 0: iterator
    Aug 19 23:27:58	unbound	1850:0	info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
    Aug 19 23:27:58	unbound	1850:0	info: server stats for thread 1: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch
    Aug 19 23:27:58	unbound	1850:0	info: server stats for thread 0: requestlist max 11 avg 7.71429 exceeded 0 jostled 0
    Aug 19 23:27:58	unbound	1850:0	info: server stats for thread 0: 28 queries, 0 answers from cache, 28 recursions, 0 prefetch
    Aug 19 23:27:58	unbound	1850:0	info: service stopped (unbound 1.5.9).
    Aug 19 23:27:58	unbound	1850:0	info: start of service (unbound 1.5.9).
    Aug 19 23:27:58	unbound	1850:0	notice: init module 0: iterator
    Aug 19 23:27:31	unbound	1036:0	info: server stats for thread 1: requestlist max 7 avg 4 exceeded 0 jostled 0
    Aug 19 23:27:31	unbound	1036:0	info: server stats for thread 1: 16 queries, 2 answers from cache, 14 recursions, 0 prefetch
    Aug 19 23:27:31	unbound	1036:0	info: server stats for thread 0: requestlist max 10 avg 5.83871 exceeded 0 jostled 0
    Aug 19 23:27:31	unbound	1036:0	info: server stats for thread 0: 33 queries, 2 answers from cache, 31 recursions, 0 prefetch
    Aug 19 23:27:31	unbound	1036:0	info: service stopped (unbound 1.5.9).
    Aug 19 23:27:31	unbound	1036:0	info: start of service (unbound 1.5.9).
    Aug 19 23:27:31	unbound	1036:0	notice: init module 0: iterator
    Aug 19 23:26:58	unbound	56977:0	info: 0.524288 1.000000 4
    Aug 19 23:26:58	unbound	56977:0	info: 0.262144 0.524288 21
    Aug 19 23:26:58	unbound	56977:0	info: 0.131072 0.262144 87
    Aug 19 23:26:58	unbound	56977:0	info: 0.065536 0.131072 223
    Aug 19 23:26:58	unbound	56977:0	info: 0.032768 0.065536 188
    Aug 19 23:26:58	unbound	56977:0	info: 0.016384 0.032768 213
    Aug 19 23:26:58	unbound	56977:0	info: 0.004096 0.008192 5
    Aug 19 23:26:58	unbound	56977:0	info: 0.002048 0.004096 6
    Aug 19 23:26:58	unbound	56977:0	info: 0.001024 0.002048 157
    Aug 19 23:26:58	unbound	56977:0	info: 0.000512 0.001024 57
    Aug 19 23:26:58	unbound	56977:0	info: 0.000000 0.000001 6
    Aug 19 23:26:58	unbound	56977:0	info: lower(secs) upper(secs) recursions
    Aug 19 23:26:58	unbound	56977:0	info: [25%]=0.0172109 median[50%]=0.0396528 [75%]=0.0929406
    Aug 19 23:26:58	unbound	56977:0	info: histogram of recursion processing times
    Aug 19 23:26:58	unbound	56977:0	info: average recursion processing time 0.061700 sec
    Aug 19 23:26:58	unbound	56977:0	info: server stats for thread 1: requestlist max 9 avg 1.03102 exceeded 0 jostled 0
    Aug 19 23:26:58	unbound	56977:0	info: server stats for thread 1: 1959 queries, 992 answers from cache, 967 recursions, 0 prefetch
    Aug 19 23:26:58	unbound	56977:0	info: 0.524288 1.000000 10
    Aug 19 23:26:58	unbound	56977:0	info: 0.262144 0.524288 39
    Aug 19 23:26:58	unbound	56977:0	info: 0.131072 0.262144 112
    Aug 19 23:26:58	unbound	56977:0	info: 0.065536 0.131072 248
    Aug 19 23:26:58	unbound	56977:0	info: 0.032768 0.065536 243
    Aug 19 23:26:58	unbound	56977:0	info: 0.016384 0.032768 321
    Aug 19 23:26:58	unbound	56977:0	info: 0.008192 0.016384 7
    Aug 19 23:26:58	unbound	56977:0	info: 0.004096 0.008192 4
    Aug 19 23:26:58	unbound	56977:0	info: 0.002048 0.004096 6
    Aug 19 23:26:58	unbound	56977:0	info: 0.001024 0.002048 140
    Aug 19 23:26:58	unbound	56977:0	info: 0.000512 0.001024 46
    Aug 19 23:26:58	unbound	56977:0	info: 0.000064 0.000128 1
    Aug 19 23:26:58	unbound	56977:0	info: 0.000000 0.000001 9
    Aug 19 23:26:58	unbound	56977:0	info: lower(secs) upper(secs) recursions
    Aug 19 23:26:58	unbound	56977:0	info: [25%]=0.0206459 median[50%]=0.040724 [75%]=0.095265
    Aug 19 23:26:58	unbound	56977:0	info: histogram of recursion processing times
    Aug 19 23:26:58	unbound	56977:0	info: average recursion processing time 0.068902 sec
    Aug 19 23:26:58	unbound	56977:0	info: server stats for thread 0: requestlist max 5 avg 0.487352 exceeded 0 jostled 0
    Aug 19 23:26:58	unbound	56977:0	info: server stats for thread 0: 2867 queries, 1681 answers from cache, 1186 recursions, 0 prefetch
    Aug 19 23:26:58	unbound	56977:0	info: service stopped (unbound 1.5.9).
    

  • Rebel Alliance Global Moderator

    pfblocker will restart unbound when it updates its lists.. So yeah pblocker will do a restart of it, if something is odd and hangs with that process then sure you could have issues.



  • Thats not a pfBlockerNG issue,  its a pfSense issue.  You will have to just disable DNSBL (you may still enable pfBlockerNG) in order to make it works. Disable DNSBL will remove the "server:include: /var/unbound/pfb_dnsbl.conf" from Unbound custom options, thats mostly caused the problem.



  • I found the problem, it is with pfSense and the DNS resolver and not pfBlocker.

    https://forum.pfsense.org/index.php?topic=111178.msg619152#msg619152

    The fix is simple: (I'm not sure how I managed to forget this but it is in my setup notes now!)

    @cmb:

    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.

    A couple clicks in the DNS Resolver settings to select All instead of specific interfaces and my pfSense box has been running for 48 hours with no glitches, with individual interfaces selected instead of All I have to manually restart Unbound several times per day.


  • Rebel Alliance Global Moderator

    I for sure do not have ALL set for interface - to be honest that is a bad idea all the way around to have default all.  I would personally like to see that default behavior discontinued.  I really can not think of a scenario where all would be the desired choice?

    I have specific lan side interface picked, because I do not want or allow some of my lan side networks to query pfsense for dns.  My guest network for example get handed public dns so thee is no reason for them to be able to query pfsense, so why should unbound listen for anything on that interface at all?

    And pfsense has no need to possible query out the lan side interfaces resolving public dns.  Now if your using domain overrides that point to a ns that is available via your lan side networks then yes you would have to make sure unbound is able to do outgoing connections via these interfaces.

    I do not have all selected for either and I do not have to restart unbound that is for sure, so not sure what aspect of your config would be fixed by such a setting?



  • @johnpoz:

    I for sure do not have ALL set for interface - to be honest that is a bad idea all the way around to have default all.  I would personally like to see that default behavior discontinued.  I really can not think of a scenario where all would be the desired choice?

    I have specific lan side interface picked, because I do not want or allow some of my lan side networks to query pfsense for dns.  My guest network for example get handed public dns so thee is no reason for them to be able to query pfsense, so why should unbound listen for anything on that interface at all?

    And pfsense has no need to possible query out the lan side interfaces resolving public dns.  Now if your using domain overrides that point to a ns that is available via your lan side networks then yes you would have to make sure unbound is able to do outgoing connections via these interfaces.

    I do not have all selected for either and I do not have to restart unbound that is for sure, so not sure what aspect of your config would be fixed by such a setting?

    What if users are using IPSec/Open VPN server to query, and unbound doesn't list these interfaces to be selected,  What is the choice other than selecting ALL?



  • Johnpoz, I have no clue what is going on other than what cmb gave me in that post. I just posted it here so someone else having the issue could find an answer when they searched since many won't be rebooting often enough to connect the dots of an unbound startup issue and pfBlocker's DNSBL system.


  • Rebel Alliance Global Moderator

    " unbound doesn't list these interfaces to be selecte"

    Then assign them to an interface..  I sure see my openvpn connection in my interface list, how would that be any different from an ipsec connection?




  • @johnpoz:

    " unbound doesn't list these interfaces to be selecte"

    Then assign them to an interface..  I sure see my openvpn connection in my interface list, how would that be any different from an ipsec connection?

    Ah, yeah, you can assign an OpenVPN server to an interface,  but no way for the IPSec connection, Can't use IPSec VPN unless ALL is selected, not sure whats missing.

    EDIT:  Could be because IPSec was set by using WAN interface?