Unbound service restart on its own

jrmitchell83

Hello,

I have been experiencing issues with Unbound where the service will stop and start on its own multiple times throughout the day. I am running 2.2.6 on 64 bit platform.

See the full log from an event earlier today. Because of this issue I am going to have to switch over to dnsmasq until I can figure out the cause of this problem.

Any ideas?

Mar 29 09:34:50 unbound: [84337:0] info: service stopped (unbound 1.5.4).
Mar 29 09:34:50 unbound: [84337:0] info: server stats for thread 0: 38635 queries, 13597 answers from cache, 25038 recursions, 793 prefetch
Mar 29 09:34:50 unbound: [84337:0] info: server stats for thread 0: requestlist max 78 avg 2.44075 exceeded 0 jostled 0
Mar 29 09:34:50 unbound: [84337:0] info: average recursion processing time 0.095388 sec
Mar 29 09:34:50 unbound: [84337:0] info: histogram of recursion processing times
Mar 29 09:34:50 unbound: [84337:0] info: [25%]=0.0293627 median[50%]=0.0634251 [75%]=0.120897
Mar 29 09:34:50 unbound: [84337:0] info: lower(secs) upper(secs) recursions
Mar 29 09:34:50 unbound: [84337:0] info: 0.000000 0.000001 1087
Mar 29 09:34:50 unbound: [84337:0] info: 0.000512 0.001024 7
Mar 29 09:34:50 unbound: [84337:0] info: 0.001024 0.002048 5
Mar 29 09:34:50 unbound: [84337:0] info: 0.002048 0.004096 14
Mar 29 09:34:50 unbound: [84337:0] info: 0.004096 0.008192 13
Mar 29 09:34:50 unbound: [84337:0] info: 0.008192 0.016384 539
Mar 29 09:34:50 unbound: [84337:0] info: 0.016384 0.032768 5800
Mar 29 09:34:50 unbound: [84337:0] info: 0.032768 0.065536 5402
Mar 29 09:34:50 unbound: [84337:0] info: 0.065536 0.131072 6998
Mar 29 09:34:50 unbound: [84337:0] info: 0.131072 0.262144 3871
Mar 29 09:34:50 unbound: [84337:0] info: 0.262144 0.524288 968
Mar 29 09:34:50 unbound: [84337:0] info: 0.524288 1.000000 262
Mar 29 09:34:50 unbound: [84337:0] info: 1.000000 2.000000 66
Mar 29 09:34:50 unbound: [84337:0] info: 2.000000 4.000000 5
Mar 29 09:34:50 unbound: [84337:0] info: 4.000000 8.000000 1
Mar 29 09:34:50 unbound: [84337:0] info: server stats for thread 1: 14679 queries, 3329 answers from cache, 11350 recursions, 293 prefetch
Mar 29 09:34:50 unbound: [84337:0] info: server stats for thread 1: requestlist max 57 avg 1.04896 exceeded 0 jostled 0
Mar 29 09:34:50 unbound: [84337:0] info: average recursion processing time 0.095710 sec
Mar 29 09:34:50 unbound: [84337:0] info: histogram of recursion processing times
Mar 29 09:34:50 unbound: [84337:0] info: [25%]=0.0310089 median[50%]=0.0663676 [75%]=0.122548
Mar 29 09:34:50 unbound: [84337:0] info: lower(secs) upper(secs) recursions
Mar 29 09:34:50 unbound: [84337:0] info: 0.000000 0.000001 317
Mar 29 09:34:50 unbound: [84337:0] info: 0.002048 0.004096 1
Mar 29 09:34:50 unbound: [84337:0] info: 0.004096 0.008192 6
Mar 29 09:34:50 unbound: [84337:0] info: 0.008192 0.016384 223
Mar 29 09:34:50 unbound: [84337:0] info: 0.016384 0.032768 2566
Mar 29 09:34:50 unbound: [84337:0] info: 0.032768 0.065536 2520
Mar 29 09:34:50 unbound: [84337:0] info: 0.065536 0.131072 3310
Mar 29 09:34:50 unbound: [84337:0] info: 0.131072 0.262144 1860
Mar 29 09:34:50 unbound: [84337:0] info: 0.262144 0.524288 431
Mar 29 09:34:50 unbound: [84337:0] info: 0.524288 1.000000 90
Mar 29 09:34:50 unbound: [84337:0] info: 1.000000 2.000000 25
Mar 29 09:34:50 unbound: [84337:0] info: 4.000000 8.000000 1
Mar 29 09:34:51 unbound: [28453:0] notice: init module 0: iterator
Mar 29 09:34:51 unbound: [28453:0] info: start of service (unbound 1.5.4).
Mar 29 09:34:54 unbound: [28453:0] info: service stopped (unbound 1.5.4).
Mar 29 09:34:54 unbound: [28453:0] info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch
Mar 29 09:34:54 unbound: [28453:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
Mar 29 09:34:54 unbound: [28453:0] info: server stats for thread 1: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch
Mar 29 09:34:54 unbound: [28453:0] info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
Mar 29 09:34:56 unbound: [46077:0] notice: init module 0: iterator
Mar 29 09:34:56 unbound: [46077:0] info: start of service (unbound 1.5.4).

tha_toadman

I'm getting the same thing too. What has driving me nuts was that my Windows boxes were all saying "No Internet" yet they were connected just fine. My troubleshooting steps were as follows:

Manually overrode my local DNS to Google's – problem solved on the Windows machines
Reinstated unbound to effectively use pfBlocker – issue came back
Bypassed unbound and used dnsmasq (like OP mentioned) – problem solved
Reinstated unbound to effectively use pfBlocker – issue came back

I checked my logs as well…


Mar 29 21:15:04	unbound: [31025:0] info: service stopped (unbound 1.5.4).
Mar 29 21:14:29	unbound: [31025:0] info: start of service (unbound 1.5.4).
-----
Mar 29 21:14:18	unbound: [31025:0] info: service stopped (unbound 1.5.4).
Mar 29 21:14:18	unbound: [31025:0] info: start of service (unbound 1.5.4).
-----
Mar 29 21:14:08	unbound: [31025:0] info: service stopped (unbound 1.5.4).
Mar 29 20:59:27	unbound: [31025:0] info: start of service (unbound 1.5.4).
-----
Mar 29 20:59:16	unbound: [31025:0] info: service stopped (unbound 1.5.4).
Mar 29 20:59:16	unbound: [31025:0] info: start of service (unbound 1.5.4).

If there's anything else I can provide for further troubleshooting, please let me know and I'll be glad to help.

BBcan177

Is Unbound in forwarding or resolver mode? Is DNSSEC enabled?

If forwarding mode, make sure the DNS servers that you defined support DNSSEC…

Also do you have the DHCP Reg checkboxes enabled?

tha_toadman

BBcan117, thanks for your reply. Your pfBlockerNG solution is amazing. I can't imagine using pfSense anymore without it. As for your questions:

Is Unbound in forwarding or resolver mode? Is DNSSEC enabled?

It's in resolver mode. Yes, DNSSEC is enabled.

Also do you have the DHCP Reg checkboxes enabled?

Yes, I have both DHCP Reg checkboxes enabled.

BBcan177

If you don't require the DHCP reg, uncheck those two checkboxes and see how that goes… Thanks for the feedback ;)

cmb

It restarts upon DHCP hostname changes when you're registering those names.
https://redmine.pfsense.org/issues/5413

jrmitchell83

In my case I have the following configuration:
Network Interfaces: LAN, Localhost
Outgoing Network Interfaces: WAN
DNSSEC: Disabled
DNS Forwarding: Enabled (Using 8.8.8.8,8.8.4.4,2001:4860:4860::8888,2001:4860:4860::8844) on the general tab and
Allow DNS server list to be overridden by DHCP/PPP on WAN: Enabled
DHCP Reg: Disabled
Static DHCP: Disabled

Perhaps the "Do not use the DNS Forwarder or Resolver as a DNS server for the firewall" needs to be disabled to avoid this issue??? Any thoughts? Thank you!

![Unbound General.png](/public/imported_attachments/1/Unbound General.png)
![Unbound General.png_thumb](/public/imported_attachments/1/Unbound General.png_thumb)
![Unbound Advanced.png](/public/imported_attachments/1/Unbound Advanced.png)
![Unbound Advanced.png_thumb](/public/imported_attachments/1/Unbound Advanced.png_thumb)
![General DNS Settings For Forwarder.png](/public/imported_attachments/1/General DNS Settings For Forwarder.png)
![General DNS Settings For Forwarder.png_thumb](/public/imported_attachments/1/General DNS Settings For Forwarder.png_thumb)
![Interface DNS Settings.png](/public/imported_attachments/1/Interface DNS Settings.png)
![Interface DNS Settings.png_thumb](/public/imported_attachments/1/Interface DNS Settings.png_thumb)
![Dashboard DNS Servers.png](/public/imported_attachments/1/Dashboard DNS Servers.png)
![Dashboard DNS Servers.png_thumb](/public/imported_attachments/1/Dashboard DNS Servers.png_thumb)

luckman212

@cmb:

It restarts upon DHCP hostname changes when you're registering those names.
https://redmine.pfsense.org/issues/5413

So is it best practice then to NOT enable that option? (register DHCP leases in DNS)

It would seem that all that stopping/reloading of Unbound is "bound" to cause some problems especially on a busy network…