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). -
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.
-
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?
-
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.
-
" 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?
-
" 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?
