Constant unbound reloading with DNSBL



  • Hi,

    I noticed that surfing is very slow every now and then. I just started debugging and noticed that unbound is sucking up 100% CPU. Further analysis shows that it seems to keep restarting every few minutes:

    Feb 12 21:01:24	unbound	13278:1	info: query response was THROWAWAY
    Feb 12 21:01:24	unbound	13278:1	info: response for 65.196.63.92.in-addr.arpa. PTR IN
    Feb 12 21:01:24	unbound	13278:1	info: reply from <196.63.92.in-addr.arpa.> 205.251.198.162#53
    Feb 12 21:01:24	unbound	13278:1	info: query response was THROWAWAY
    Feb 12 21:01:24	unbound	13278:1	info: response for 65.196.63.92.in-addr.arpa. PTR IN
    Feb 12 21:01:24	unbound	13278:1	info: reply from <196.63.92.in-addr.arpa.> 205.251.194.99#53
    Feb 12 21:01:24	unbound	13278:1	info: query response was THROWAWAY
    Feb 12 21:01:24	unbound	13278:0	info: service stopped (unbound 1.8.1).
    Feb 12 21:01:24	unbound	13278:0	info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
    Feb 12 21:01:24	unbound	13278:0	info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
    Feb 12 21:01:24	unbound	13278:0	info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
    Feb 12 21:01:24	unbound	13278:0	info: server stats for thread 1: 387 queries, 142 answers from cache, 245 recursions, 5 prefetch, 0 rejected by ip ratelimiting
    Feb 12 21:01:24	unbound	13278:0	info: server stats for thread 1: requestlist max 94 avg 4.128 exceeded 0 jostled 0
    Feb 12 21:01:24	unbound	13278:0	info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 325 recursion replies sent, 0 replies dropped, 0 states jostled out
    Feb 12 21:01:24	unbound	13278:0	info: average recursion processing time 0.282232 sec
    Feb 12 21:01:24	unbound	13278:0	info: histogram of recursion processing times
    Feb 12 21:01:24	unbound	13278:0	info: [25%]=0.0307861 median[50%]=0.112454 [75%]=0.528983
    Feb 12 21:01:24	unbound	13278:0	info: lower(secs) upper(secs) recursions
    Feb 12 21:01:24	unbound	13278:0	info: 0.000000 0.000001 27
    Feb 12 21:01:24	unbound	13278:0	info: 0.004096 0.008192 1
    Feb 12 21:01:24	unbound	13278:0	info: 0.008192 0.016384 26
    Feb 12 21:01:24	unbound	13278:0	info: 0.016384 0.032768 31
    Feb 12 21:01:24	unbound	13278:0	info: 0.032768 0.065536 46
    Feb 12 21:01:24	unbound	13278:0	info: 0.065536 0.131072 44
    Feb 12 21:01:24	unbound	13278:0	info: 0.131072 0.262144 23
    Feb 12 21:01:24	unbound	13278:0	info: 0.262144 0.524288 45
    Feb 12 21:01:24	unbound	13278:0	info: 0.524288 1.000000 76
    Feb 12 21:01:24	unbound	13278:0	info: 1.000000 2.000000 6
    Feb 12 21:01:24	unbound	13278:0	notice: Restart of unbound 1.8.1.
    

    Any idea how to approach this? I have quite a bit of DNSBL lists in it however top shows > 400MB free RAM. Whenever it reloads naturally unbound is unresponsive for quite a bit which would explain the slow browsing experience.

    Regards
    JP



  • Do you have DHCP Registration disabled in Resolver settings ?

    How long between

    Feb 12 14:18:35 	unbound 	18050:0 	notice: Restart of unbound 1.8.1.
    

    and

    Feb 12 14:18:38 	unbound 	18050:0 	info: start of service (unbound 1.8.1).
    

    As far as memory usage, use Status Monitoring System / Memory to track the usage. When unbound reload it suck a lot of memory but about 2 hrs later that memory become Inactive however Free stays low.



  • Hi,

    just found a post also relating to DHCP Registration. And indeed:

    Feb 12 21:20:10 dhcpleases Sending HUP signal to dns daemon(13278)

    Exactly then it reloads with a several second delay and 100% CPU. This is rather unfortunate. I will disable DHCP Registration for the time being but why is this reloading unbound entirely the entire time?

    https://redmine.pfsense.org/issues/5413

    Hard to believe that there is no fix... :-(



  • @ronpfs

    Feb 12 21:26:45 pfSense unbound: [13278:0] info: service stopped (unbound 1.8.1).
    Feb 12 21:27:13 pfSense unbound: [96350:0] info: start of service (unbound 1.8.1).
    

    This was a manual restart but it is a good indication (due to the many DNSBL lists I suppose).



  • @j-koopmann said in Constant unbound reloading with DNSBL:

    g but why is this reloading unbound entirely the entire time?

    That's the way the DHCP service is configured. Maybe the DHCP service could use unbound-control commands to inform unbound about new leases, but that's another story.

    Future version of pfblockerNG will use the Python module instead of pfb_dnsbl.conf, so reload only takes a few seconds (3 sec on my pfSense😀 ) compared to around a minute when using 1MB DNSBL entries.



  • @ronpfs Thanks! At least I now know the problem and was hopefully able to solve it. :-)

    When you say "future version": Any ETA or version? Just so I know what to keep looking for and upgrade... I am on devel 2.2.5_19 at the moment.



  • @j-koopmann said in Constant unbound reloading with DNSBL:

    Any ETA or version?

    We are in the debugging phase now. No ETA is planned yet.


Log in to reply