The pfSense Store

Author Topic: Unbound crashing  (Read 460 times)

0 Members and 1 Guest are viewing this topic.

Offline mloiterman

  • Jr. Member
  • **
  • Posts: 61
  • Karma: +1/-0
    • View Profile
Unbound crashing
« on: October 19, 2017, 08:19:43 pm »
Since installing pfBlockerNG, unbound crashes randomly and as best as I can tell it's somehow related to what's going on here:

Code: [Select]
Oct 19 18:17:27 php-fpm /index.php: Successful login for user 'admin' from: 192.168.3.6
Oct 19 18:00:00 php [pfBlockerNG] Starting cron process.
Oct 19 17:00:00 php [pfBlockerNG] Starting cron process.
Oct 19 16:00:00 php [pfBlockerNG] Starting cron process.
Oct 19 15:04:03 check_reload_status Reloading filter
Oct 19 15:04:03 php-fpm 48009 /rc.newwanipv6: Removing static route for monitor fe80::201:5cff:fe6f:5046 and adding a new route through fe80::201:5cff:fe6f:5046%igb1
Oct 19 15:04:03 php-fpm 48009 /rc.newwanipv6: Removing static route for monitor 8.8.8.8 and adding a new route through 10.8.1.181
Oct 19 15:04:03 php-fpm 48009 /rc.newwanipv6: ROUTING: setting IPv6 default route to fe80::201:5cff:fe6f:5046%igb1
Oct 19 15:04:03 php-fpm 48009 /rc.newwanipv6: ROUTING: setting default route to comcast.ip.address
Oct 19 15:04:03 php-fpm 48009 /rc.newwanipv6: The command '/sbin/route change -host att.ip.address' returned exit code '1', the output was 'route: writing to routing socket: No such process route: writing to routing socket: Invalid argument change host att.ip.address fib 0: Invalid argument'
Oct 19 15:04:03 php-fpm 48009 /rc.newwanipv6: The command '/sbin/route change -host att.ip.address' returned exit code '1', the output was 'route: writing to routing socket: No such process route: writing to routing socket: Invalid argument change host att.ip.address fib 0: Invalid argument'
Oct 19 15:04:03 php-fpm 48009 /rc.newwanipv6: The command '/sbin/route change -host comcast.ip.address' returned exit code '1', the output was 'route: writing to routing socket: No such process route: writing to routing socket: Invalid argument change host comcast.ip.address fib 0: Invalid argument'
Oct 19 15:04:01 dhcpleases kqueue error: unkown
Oct 19 15:04:01 php-fpm 48009 /rc.newwanipv6: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1508443441] unbound[60763:0] error: bind: address already in use [1508443441] unbound[60763:0] fatal error: could not open ports'
Oct 19 15:04:00 dhcpleases /var/etc/hosts changed size from original!
Oct 19 15:03:59 php-fpm 48009 /rc.newwanipv6: rc.newwanipv6: on (IP address: comcast.ip6.address) (interface: wan) (real interface: igb1).
Oct 19 15:03:59 php-fpm 48009 /rc.newwanipv6: rc.newwanipv6: Info: starting on igb1.
Oct 19 15:03:53 check_reload_status Reloading filter
Oct 19 15:03:53 php-fpm 48009 /rc.newwanipv6: Removing static route for monitor fe80::201:5cff:fe6f:5046 and adding a new route through fe80::201:5cff:fe6f:5046%igb1
Oct 19 15:03:53 php-fpm 48009 /rc.newwanipv6: Removing static route for monitor 8.8.8.8 and adding a new route through 10.8.1.181
Oct 19 15:03:53 php-fpm 48009 /rc.newwanipv6: ROUTING: setting IPv6 default route to fe80::201:5cff:fe6f:5046%igb1
Oct 19 15:03:53 php-fpm 48009 /rc.newwanipv6: ROUTING: setting default route to comcast.ip.address
Oct 19 15:03:53 php-fpm 48009 /rc.newwanipv6: The command '/sbin/route change -host att.ip.address' returned exit code '1', the output was 'route: writing to routing socket: No such process route: writing to routing socket: Invalid argument change host att.ip.address fib 0: Invalid argument'
Oct 19 15:03:53 php-fpm 48009 /rc.newwanipv6: The command '/sbin/route change -host att.ip.address' returned exit code '1', the output was 'route: writing to routing socket: No such process route: writing to routing socket: Invalid argument change host att.ip.address fib 0: Invalid argument'
Oct 19 15:03:53 php-fpm 48009 /rc.newwanipv6: The command '/sbin/route change -host comcast.ip.address' returned exit code '1', the output was 'route: writing to routing socket: No such process route: writing to routing socket: Invalid argument change host comcast.ip.address fib 0: Invalid argument'
Oct 19 15:03:51 dhcpleases kqueue error: unkown
Oct 19 15:03:50 dhcpleases Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.
Oct 19 15:03:50 dhcpleases /var/etc/hosts changed size from original!
Oct 19 15:03:49 php-fpm 48009 /rc.newwanipv6: rc.newwanipv6: on (IP address: comcast.ip6.address) (interface: wan) (real interface: igb1).
Oct 19 15:03:49 php-fpm 48009 /rc.newwanipv6: rc.newwanipv6: Info: starting on igb1.
Oct 19 15:00:00 php [pfBlockerNG] Starting cron process.

Using pfSense 2.3.4 and pfBlocker 2.1.1_10.

Is it related to this: https://redmine.pfsense.org/issues/7326#note-2?

Thoughts?
« Last Edit: October 19, 2017, 08:30:04 pm by mloiterman »

Offline MarcoP

  • Jr. Member
  • **
  • Posts: 31
  • Karma: +0/-0
    • View Profile
Re: Unbound crashing
« Reply #1 on: November 14, 2017, 08:56:23 am »
I'm not sure if it is the same issue, but for sure it is related. For sure I had this from a while, I'm on 2.4.2.a.20171110.1936

Code: [Select]
Nov 14 15:21:33 php-fpm[66907]: /services_unbound.php: The command '/sbin/route delete -host ' returned exit code '64', the output was 'route: destination parameter required route: usage: route [-46dnqtv] command [[modifiers] args]'
Nov 14 15:21:33 php-fpm[66907]: /services_unbound.php: The command '/sbin/route delete -host ' returned exit code '64', the output was 'route: destination parameter required route: usage: route [-46dnqtv] command [[modifiers] args]'
.....
Nov 11 18:17:43 php-fpm[82460]: /rc.newwanip: The command '/sbin/route delete -host ' returned exit code '64', the output was 'route: destination parameter required route: usage: route [-46dnqtv] command [[modifiers] args]'
Nov 11 18:17:43 php-fpm[82460]: /rc.newwanip: The command '/sbin/route delete -host ' returned exit code '64', the output was 'route: destination parameter required route: usage: route [-46dnqtv] command [[modifiers] args]'
Nov 11 18:17:43 php-fpm[82460]: /rc.newwanip: rc.newwanip: on (IP address: 192.168.30.254) (interface: SRV[opt3]) (real interface: lagg0.30).
Nov 11 18:17:43 php-fpm[82460]: /rc.newwanip: rc.newwanip: Info: starting on lagg0.30.
Nov 11 18:17:43 php-fpm[82460]: /rc.newwanip: The command '/sbin/route delete -host ' returned exit code '64', the output was 'route: destination parameter required route: usage: route [-46dnqtv] command [[modifiers] args]'
Nov 11 18:17:43 php-fpm[82460]: /rc.newwanip: The command '/sbin/route delete -host ' returned exit code '64', the output was 'route: destination parameter required route: usage: route [-46dnqtv] command [[modifiers] args]'
Nov 11 18:17:43 php-fpm[82460]: /rc.newwanip: rc.newwanip: on (IP address: 192.168.10.254) (interface: STD[opt1]) (real interface: lagg0.10).
Nov 11 18:17:43 php-fpm[82460]: /rc.newwanip: rc.newwanip: Info: starting on lagg0.10.
Nov 11 18:17:43 php-fpm[82460]: /rc.newwanip: The command '/sbin/route delete -host ' returned exit code '64', the output was 'route: destination parameter required route: usage: route [-46dnqtv] command [[modifiers] args]'
Nov 11 18:17:43 php-fpm[82460]: /rc.newwanip: The command '/sbin/route delete -host ' returned exit code '64', the output was 'route: destination parameter required route: usage: route [-46dnqtv] command [[modifiers] args]'
Nov 11 18:17:43 php-fpm[82460]: /rc.newwanip: rc.newwanip: on (IP address: 192.168.20.254) (interface: WIFI[opt2]) (real interface: lagg0.20).
Nov 11 18:17:43 php-fpm[82460]: /rc.newwanip: rc.newwanip: Info: starting on lagg0.20.
Nov 11 18:17:43 check_reload_status: Reloading filter
Nov 11 18:17:43 php-fpm[82460]: /rc.newwanip: The command '/sbin/route delete -host ' returned exit code '64', the output was 'route: destination parameter required route: usage: route [-46dnqtv] command [[modifiers] args]'
Nov 11 18:17:43 php-fpm[82460]: /rc.newwanip: The command '/sbin/route delete -host ' returned exit code '64', the output was 'route: destination parameter required route: usage: route [-46dnqtv] command [[modifiers] args]'
Nov 11 18:17:43 php-fpm[82460]: /rc.newwanip: rc.newwanip: on (IP address: 192.168.1.254) (interface: LAN[lan]) (real interface: lagg0).
Nov 11 18:17:43 php-fpm[82460]: /rc.newwanip: rc.newwanip: Info: starting on lagg0.
Nov 11 18:17:42 check_reload_status: rc.newwanip starting lagg0.30
Nov 11 18:17:42 php-fpm[92457]: /rc.linkup: Hotplug event detected for SRV(opt3) static IP (192.168.30.254 )
Nov 11 18:17:42 check_reload_status: rc.newwanip starting lagg0.10
Nov 11 18:17:42 php-fpm[92457]: /rc.linkup: Hotplug event detected for STD(opt1) static IP (192.168.10.254 )
Nov 11 18:17:41 check_reload_status: rc.newwanip starting lagg0.20
Nov 11 18:17:41 php-fpm[92457]: /rc.linkup: Hotplug event detected for WIFI(opt2) static IP (192.168.20.254 )
Nov 11 18:17:41 check_reload_status: Reloading filter
Nov 11 18:17:41 check_reload_status: rc.newwanip starting lagg0
Nov 11 18:17:41 php-fpm[92457]: /rc.linkup: Hotplug event detected for LAN(lan) static IP (192.168.1.254 )
Nov 11 18:17:41 check_reload_status: Reloading filter
Nov 11 18:17:40 kernel: igb2: link state changed to UP
Nov 11 18:17:40 check_reload_status: Linkup starting igb2
Nov 11 18:17:40 check_reload_status: Linkup starting lagg0.30
Nov 11 18:17:40 check_reload_status: Linkup starting lagg0.10
Nov 11 18:17:40 check_reload_status: Linkup starting lagg0.20
Nov 11 18:17:40 check_reload_status: Linkup starting lagg0
Nov 11 18:17:40 kernel: lagg0.30: link state changed to UP
Nov 11 18:17:40 kernel: lagg0.10: link state changed to UP
Nov 11 18:17:40 kernel: lagg0.20: link state changed to UP
Nov 11 18:17:40 kernel: lagg0: link state changed to UP
Nov 11 18:17:40 kernel: igb1: link state changed to UP
Nov 11 18:17:40 check_reload_status: Linkup starting igb1

Offline renegade

  • Jr. Member
  • **
  • Posts: 85
  • Karma: +2/-1
    • View Profile
Re: Unbound crashing
« Reply #2 on: November 14, 2017, 04:06:42 pm »
on 2.41 i have very often no working, reachable DNS Service.

DNS Logs say

Code: [Select]
Nov 14 23:03:28 unbound 45240:0 info: start of service (unbound 1.6.6).
Nov 14 23:02:57 unbound 45240:0 info: service stopped (unbound 1.6.6).
Nov 14 23:02:57 unbound 45240:0 info: start of service (unbound 1.6.6).
Nov 14 23:02:25 unbound 45240:0 info: service stopped (unbound 1.6.6).
Nov 14 23:00:08 filterdns adding entry 2a02:26f0:6a:280::3d5 to pf table certbot for host acme-v01.api.letsencrypt.org
Nov 14 23:00:08 filterdns adding entry 2a02:26f0:6a:293::3d5 to pf table certbot for host acme-v01.api.letsencrypt.org
Nov 14 23:00:08 filterdns adding entry 104.74.107.171 to pf table certbot for host acme-v01.api.letsencrypt.org

filternds logs this every 15 minutes. maybe the same issue?

Offline BBcan177

  • Moderator
  • Hero Member
  • *****
  • Posts: 2554
  • Karma: +797/-5
    • View Profile
    • Click for Support
Re: Unbound crashing
« Reply #3 on: November 14, 2017, 09:02:03 pm »
These aren't related to pfBlockerNG... Best to post in the DNS forum section....
"Experience is something you don't get until just after you need it."

 | http://pfblockerng.com | Twitter @BBcan177  | #pfBlockerNG |

Offline JasonAU

  • Jr. Member
  • **
  • Posts: 35
  • Karma: +0/-0
    • View Profile
Re: Unbound crashing
« Reply #4 on: November 15, 2017, 03:03:36 am »
Since installing pfBlockerNG, unbound crashes randomly and as best as I can tell it's somehow related to what's going on here:

Code: [Select]
Oct 19 18:17:27 php-fpm /index.php: Successful login for user 'admin' from: 192.168.3.6
Oct 19 18:00:00 php [pfBlockerNG] Starting cron process.
Oct 19 17:00:00 php [pfBlockerNG] Starting cron process.
Oct 19 16:00:00 php [pfBlockerNG] Starting cron process.
Oct 19 15:04:03 check_reload_status Reloading filter
Oct 19 15:04:03 php-fpm 48009 /rc.newwanipv6: Removing static route for monitor fe80::201:5cff:fe6f:5046 and adding a new route through fe80::201:5cff:fe6f:5046%igb1
Oct 19 15:04:03 php-fpm 48009 /rc.newwanipv6: Removing static route for monitor 8.8.8.8 and adding a new route through 10.8.1.181
Oct 19 15:04:03 php-fpm 48009 /rc.newwanipv6: ROUTING: setting IPv6 default route to fe80::201:5cff:fe6f:5046%igb1
Oct 19 15:04:03 php-fpm 48009 /rc.newwanipv6: ROUTING: setting default route to comcast.ip.address
Oct 19 15:04:03 php-fpm 48009 /rc.newwanipv6: The command '/sbin/route change -host att.ip.address' returned exit code '1', the output was 'route: writing to routing socket: No such process route: writing to routing socket: Invalid argument change host att.ip.address fib 0: Invalid argument'
Oct 19 15:04:03 php-fpm 48009 /rc.newwanipv6: The command '/sbin/route change -host att.ip.address' returned exit code '1', the output was 'route: writing to routing socket: No such process route: writing to routing socket: Invalid argument change host att.ip.address fib 0: Invalid argument'
Oct 19 15:04:03 php-fpm 48009 /rc.newwanipv6: The command '/sbin/route change -host comcast.ip.address' returned exit code '1', the output was 'route: writing to routing socket: No such process route: writing to routing socket: Invalid argument change host comcast.ip.address fib 0: Invalid argument'
Oct 19 15:04:01 dhcpleases kqueue error: unkown
Oct 19 15:04:01 php-fpm 48009 /rc.newwanipv6: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1508443441] unbound[60763:0] error: bind: address already in use [1508443441] unbound[60763:0] fatal error: could not open ports'
Oct 19 15:04:00 dhcpleases /var/etc/hosts changed size from original!
Oct 19 15:03:59 php-fpm 48009 /rc.newwanipv6: rc.newwanipv6: on (IP address: comcast.ip6.address) (interface: wan) (real interface: igb1).
Oct 19 15:03:59 php-fpm 48009 /rc.newwanipv6: rc.newwanipv6: Info: starting on igb1.
Oct 19 15:03:53 check_reload_status Reloading filter
Oct 19 15:03:53 php-fpm 48009 /rc.newwanipv6: Removing static route for monitor fe80::201:5cff:fe6f:5046 and adding a new route through fe80::201:5cff:fe6f:5046%igb1
Oct 19 15:03:53 php-fpm 48009 /rc.newwanipv6: Removing static route for monitor 8.8.8.8 and adding a new route through 10.8.1.181
Oct 19 15:03:53 php-fpm 48009 /rc.newwanipv6: ROUTING: setting IPv6 default route to fe80::201:5cff:fe6f:5046%igb1
Oct 19 15:03:53 php-fpm 48009 /rc.newwanipv6: ROUTING: setting default route to comcast.ip.address
Oct 19 15:03:53 php-fpm 48009 /rc.newwanipv6: The command '/sbin/route change -host att.ip.address' returned exit code '1', the output was 'route: writing to routing socket: No such process route: writing to routing socket: Invalid argument change host att.ip.address fib 0: Invalid argument'
Oct 19 15:03:53 php-fpm 48009 /rc.newwanipv6: The command '/sbin/route change -host att.ip.address' returned exit code '1', the output was 'route: writing to routing socket: No such process route: writing to routing socket: Invalid argument change host att.ip.address fib 0: Invalid argument'
Oct 19 15:03:53 php-fpm 48009 /rc.newwanipv6: The command '/sbin/route change -host comcast.ip.address' returned exit code '1', the output was 'route: writing to routing socket: No such process route: writing to routing socket: Invalid argument change host comcast.ip.address fib 0: Invalid argument'
Oct 19 15:03:51 dhcpleases kqueue error: unkown
Oct 19 15:03:50 dhcpleases Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.
Oct 19 15:03:50 dhcpleases /var/etc/hosts changed size from original!
Oct 19 15:03:49 php-fpm 48009 /rc.newwanipv6: rc.newwanipv6: on (IP address: comcast.ip6.address) (interface: wan) (real interface: igb1).
Oct 19 15:03:49 php-fpm 48009 /rc.newwanipv6: rc.newwanipv6: Info: starting on igb1.
Oct 19 15:00:00 php [pfBlockerNG] Starting cron process.

Using pfSense 2.3.4 and pfBlocker 2.1.1_10.

Is it related to this: https://redmine.pfsense.org/issues/7326#note-2?

Thoughts?

Do you have DHCP setup to register new leases in DNS so that they resolve ? I had this setup and when a device got a DHCP lease it needed to restart unbound to get the hostname registered
Brisbane Queensland Australia

Offline motific

  • Jr. Member
  • **
  • Posts: 35
  • Karma: +3/-0
    • View Profile
Re: Unbound crashing
« Reply #5 on: November 16, 2017, 11:12:41 am »
I am tracking a similar issue though Iím on the beta (which is shaping up nicely btw) which also seems to be an unbound problem...  how many domains in total are blocked in your DNSBL? 

What Iím finding is that unbound is not crashing, it is hanging temporarily - if you record a network trace then it does *eventually* respond to all the requests, just not before the client times out.  Delays in responses can be up to 70s but will all come through at once.  I have found that if I dial down the number of blocked hosts then the problem goes away.

What I am seeing could just be unbound taking a long time to reload if a client added from DHCP by pfSense causes a restart, but that could be fixable as unbound does allow dynamic updates.  Iíll give the source a once-over and see if I can see anything (if I ever get time.)


Offline Vorkbaard

  • Jr. Member
  • **
  • Posts: 87
  • Karma: +0/-0
    • View Profile
Re: Unbound crashing
« Reply #6 on: December 05, 2017, 04:43:06 am »
Having the same problem, using pfBlockerNG with Unbound. What I am seeing is that things are working fine up to a point (say, half an hour) and then Unbound starts taking up 99% of cpu resources.

I have a script that does nslookups for twenty Alexa-listed sites which, if all is well, takes 2-5 seconds to complete. If Unbound is too busy they just time out but sometimes halfway Unbound gets the message and where the first ten lookups would time out the rest just flies by.

I'm not sure if this is related but I've been tracking changes in /var/unbound/pfb_dnsbl.conf and after about five to seven changes in pfBlockerNG's DNSBL lists this file stops getting updated. Restarting Unbound doesn't help, the only thing that fixes it it completely removing pfBlockerNG and reinstalling and reconfiguring it. Then Unbound works fine for a while untill the whole thing starts again.

Bringing down the number of blocked hosts seems to slightly help but because of the problem described above it is annoying to find a maximum number.

This behaviour is reproducable across installations. Using pfSense 2.4.2-RELEASE.

Has this been reported as bug? If so, where I can track it? If not, where should I report it?

Offline motific

  • Jr. Member
  • **
  • Posts: 35
  • Karma: +3/-0
    • View Profile
Re: Unbound crashing
« Reply #7 on: December 07, 2017, 11:07:42 am »
Unbound is a project in its own right and you can report the problem to the maintainers there.  However, youíre going to have to do a lot more digging to establish what configuration triggers the issue and what it actually does (are you sure that unbound is going into a race condition or if something else is happening).  They will need to know how to reproduce the issue - you arenít even close yet.

The behaviour sounds similar to what I see, you should consider putting a network trace on the DNS port on the LAN and CPU monitoring to see if unbound is doing what you think it is, and get back to us.  Either way can you tell us how many domains youíre blocking and what hardware spec youíre on?  Iím wondering if I should get my hands dirty with a patch to DHCP for the host registration (to reduce reloading)?  Could be fun...