Unbound frequently restarts on 2.2 - is this normal?

Barnabas · Apr 11, 2015, 11:25 PM

I am also getting this in my system log

Apr 11 19:19:52 	php-fpm[2552]: /services_unbound.php: The command '/usr/local/sbin/dhcpd -user dhcpd -group _dhcp -chroot /var/dhcpd -cf /etc/dhcpd.conf -pf /var/run/dhcpd.pid bge0' returned exit code '1', the output was 'Internet Systems Consortium DHCP Server 4.2.6 Copyright 2004-2014 Internet Systems Consortium. All rights reserved. For info, please visit https://www.isc.org/software/dhcp/ Wrote 0 deleted host decls to leases file. Wrote 0 new dynamic host decls to leases file. Wrote 12 leases to leases file. Listening on BPF/bge0/00:14:22:db:b4:a9/10.8.8.0/24 Sending on BPF/bge0/00:14:22:db:b4:a9/10.8.8.0/24 Can't bind to dhcp address: Address already in use Please make sure there is no other dhcp server running and that there's no entry for dhcp or bootp in /etc/inetd.conf. Also make sure you are not running HP JetAdmin software, which includes a bootp server. If you did not get this software from ftp.isc.org, please get the latest from ftp.isc.org and install that before requesting help. If yo

DHCP doesn't like something…

kevindd992002 · Apr 17, 2015, 4:28 AM

Any solution to this?

CiscoKid85 · Apr 18, 2015, 12:13 AM

Is this a confirmed bug? If so, how can we report it? I'm having the same issue.

waingro · Apr 20, 2015, 7:40 AM

Hi,

I have the same issue. I use pfsense 2.2.1 and DNS Resolver in forwarding mode. DNSSEC is on, and I've set DHCP leases/mappings to be registered.

It is very flaky, as it often claims it cannot resolve hosts which are clearly available to others. And then the restarts multiple times per day (sometimes multiple times per hour)…. not good!

Anything I can do/try?

Thanks!

Gertjan · Apr 20, 2015, 9:15 PM

Think about it like this:
Every time a new lease is being registered on the DHCP server, it updates its lease-file - and if unbound is running, it also write to this file: /var/unbound/dhcpleases_entries.conf.
"unbound" should read this DHCP lease file to update its own internal records.
pfSense restarts the "unbound" service ( /etc/inc/unbound.inc: line 676: unbound_control("reload"); whenever a new DHCP lease is issued. This is normal and "by actual design".

The thing is : by default, unbound is noisy in the log when it 'restarts'. So switch to less log details : Goto Services: DNS Resolver: Advanced - look for "Log level verbosity" and set it to "level 0".

Idea: what about a bigger DHCP lease times ? That will lower the unboud-restart activity.

waingro · Apr 22, 2015, 3:25 PM

@Gertjan:

Think about it like this:
[…] whenever a new DHCP lease is issued. This is normal and "by actual design".

The thing is : by default, unbound is noisy in the log when it 'restarts'. So switch to less log details : Goto Services: DNS Resolver: Advanced - look for "Log level verbosity" and set it to "level 0".

Idea: what about a bigger DHCP lease times ? That will lower the unboud-restart activity.

Then "by actual design" means bad design.

Setting to "level 0" removes the log entries, but not the problem.

The fact of the matter is that DNS Resolver restarts ALL THE TIME on my network with quite a few LAN devices and after each restart there's a few seconds where DNS queries are not resolved.

This is horrible and makes resolver useless for us.

Please fix.

doktornotor · Apr 22, 2015, 3:24 PM

Errr… reload (SIGHUP) should re-read the configuration and not disrupt service (service stopped). Definitely not sure the last couple of posts is discussing the same issue.

waingro · Apr 22, 2015, 3:26 PM

@doktornotor:

Errr… reload (SIGHUP) should re-read the configuration and not disrupt service (service stopped). Definitely not sure the last couple of posts is discussing the same issue.

Beats me. My point is that DNS Resolver has a substantial problem that needs to be fixed.

hda · Apr 22, 2015, 6:06 PM

@waingro:

Beats me.

? Tried 2.2.2. ?

Gertjan · Apr 22, 2015, 9:34 PM

@doktornotor:

Errr… reload (SIGHUP) should re-read the configuration and not disrupt service (service stopped).

Check out for yourself:
/etc/inc/unbound.inc: last function : https://github.com/pfsense/pfsense/blob/master/etc/inc/unbound.inc#L706
This one gets called every time the system hosts file get rewritten. (here: /var/etc/hosts)
In this file (hosts) are all DHCP leases - and its always up to date.
So, a lot of DHCP activity means : ….. unbound gets "unbound-control reload" (here https://github.com/pfsense/pfsense/blob/master/etc/inc/unbound.inc#L468 )

@doktornotor:

Definitely not sure the last couple of posts is discussing the same issue.

I guess it is: I saw many many "reload" lines.
For me its was a stupid Windows 7 PC (one out of a serie of 6 PC bought, installed, setup identical) that renewed its DHCP lease every 5 (yes: 5 minutes) so …. I ditched the PC for the moment, the DHCP storm stopped, the frequent (as said, every 5 minutes) unbound reloading like a chain-gun stopped.

Right now, it reload about 40 times a day (I have Cpative portal visitors):

Apr 22 23:20:41 unbound: [68253:0] info: start of service (unbound 1.5.3).
Apr 22 23:20:41 unbound: [68253:0] info: service stopped (unbound 1.5.3).
Apr 22 22:19:25 unbound: [68253:0] info: start of service (unbound 1.5.3).
Apr 22 22:19:25 unbound: [68253:0] info: service stopped (unbound 1.5.3).
Apr 22 21:18:47 unbound: [68253:0] info: start of service (unbound 1.5.3).
Apr 22 21:18:47 unbound: [68253:0] info: service stopped (unbound 1.5.3).
Apr 22 20:18:46 unbound: [68253:0] info: start of service (unbound 1.5.3).
Apr 22 20:18:46 unbound: [68253:0] info: service stopped (unbound 1.5.3).
Apr 22 19:18:20 unbound: [68253:0] info: start of service (unbound 1.5.3).
Apr 22 19:18:20 unbound: [68253:0] info: service stopped (unbound 1.5.3).
Apr 22 18:17:45 unbound: [68253:0] info: start of service (unbound 1.5.3).
Apr 22 18:17:45 unbound: [68253:0] info: service stopped (unbound 1.5.3).
Apr 22 17:16:25 unbound: [68253:0] info: start of service (unbound 1.5.3).
Apr 22 17:16:25 unbound: [68253:0] info: service stopped (unbound 1.5.3).
Apr 22 16:15:58 unbound: [68253:0] info: start of service (unbound 1.5.3).
Apr 22 16:15:58 unbound: [68253:0] info: service stopped (unbound 1.5.3).
Apr 22 15:01:26 unbound: [68253:0] info: start of service (unbound 1.5.3).
Apr 22 15:01:26 unbound: [68253:0] info: service stopped (unbound 1.5.3).
Apr 22 13:34:37 unbound: [68253:0] info: start of service (unbound 1.5.3).
Apr 22 13:34:37 unbound: [68253:0] info: service stopped (unbound 1.5.3).
Apr 22 12:29:24 unbound: [68253:0] info: start of service (unbound 1.5.3).
Apr 22 12:29:24 unbound: [68253:0] info: service stopped (unbound 1.5.3).
Apr 22 10:22:12 unbound: [68253:0] info: start of service (unbound 1.5.3).
Apr 22 10:22:12 unbound: [68253:0] info: service stopped (unbound 1.5.3).
Apr 22 09:19:33 unbound: [68253:0] info: start of service (unbound 1.5.3).
Apr 22 09:19:33 unbound: [68253:0] info: service stopped (unbound 1.5.3).
Apr 22 08:11:30 unbound: [68253:0] info: start of service (unbound 1.5.3).
Apr 22 08:11:30 unbound: [68253:0] info: service stopped (unbound 1.5.3).
Apr 22 07:09:08 unbound: [68253:0] info: start of service (unbound 1.5.3).
Apr 22 07:09:08 unbound: [68253:0] info: service stopped (unbound 1.5.3).
Apr 22 06:05:15 unbound: [68253:0] info: start of service (unbound 1.5.3).
Apr 22 06:05:15 unbound: [68253:0] info: service stopped (unbound 1.5.3).
Apr 22 05:03:25 unbound: [68253:0] info: start of service (unbound 1.5.3).
Apr 22 05:03:25 unbound: [68253:0] info: service stopped (unbound 1.5.3).
Apr 22 03:55:15 unbound: [68253:0] info: start of service (unbound 1.5.3).
Apr 22 03:55:15 unbound: [68253:0] info: service stopped (unbound 1.5.3).
Apr 22 02:55:14 unbound: [68253:0] info: start of service (unbound 1.5.3).
Apr 22 02:55:14 unbound: [68253:0] info: service stopped (unbound 1.5.3).
Apr 22 01:53:57 unbound: [68253:0] info: start of service (unbound 1.5.3).
Apr 22 01:53:57 unbound: [68253:0] info: service stopped (unbound 1.5.3).
Apr 22 00:50:59 unbound: [68253:0] info: start of service (unbound 1.5.3).
Apr 22 00:50:59 unbound: [68253:0] info: service stopped (unbound 1.5.3).

I didn't have a look at the unbound source code (yet) but ""unbound-control reload" means to me : restart it.
All this to force it to reread the hosts file (and dhcp leases file ?).
I don't think its a bug, neither saying it wrong - maybe unbound could be informed otherwise to have it read some files again … maybe not .... let the coder decide ;)

Reloading happens when I see this in the DHCP log:

Apr 22 23:20:41 dhcpd: Wrote 250 leases to leases file.
Apr 22 23:20:41 dhcpd: Wrote 0 new dynamic host decls to leases file.
Apr 22 23:20:41 dhcpd: Wrote 0 deleted host decls to leases file.

That's why I was thinking that it is DHCP-activity related. (and thus, /var/etc/hosts file related)

I could be wrong, of course :)

phil.davis · Apr 23, 2015, 4:15 AM

I imagine/hope/think that "reload" causes the running unbound to simply re-read its config (which includes reading associated leases or whatever other stuff is pointed to by the config) and internally implement that on-the-fly without any significant interruption of user service.

But maybe that is not the case! Someone could look in the unbound source code and see how a "reload" message really is processed.

doktornotor · Apr 23, 2015, 6:37 AM

@Gertjan:

I didn't have a look at the unbound source code (yet) but ""unbound-control reload" means to me : restart it.
All this to force it to reread the hosts file (and dhcp leases file ?).

Hell no…

reload
Reload the server. This flushes the cache and reads the config file fresh.

This should not cause a service restart! Ever. The feature would be totally pointless otherwise.

If anyone's experiencing the issue, truss the reload and see if it's trying to load some include which does not exist… Like:


truss unbound-control -c /var/unbound/unbound.conf reload

Note: Having two threads about exactly the same does NOT help. >:(

Gertjan · Apr 23, 2015, 10:54 AM

@doktornotor:

Hell no…

reload
Reload the server. This flushes the cache and reads the config file fresh.

… and that is what I would like to see.

https://www.unbound.net/documentation/unbound.conf.html learns us how to reload "kill -HUP cat /usr/local/etc/unbound/unbound.pid".
For pfSense, that will be :
kill -HUP cat /var/run/unbound.pid

When doing so, the log shows :

04-23-2015 12:43:41 Daemon.Info 192.168.1.1 Apr 23 12:43:45 unbound: [45284:0] info: start of service (unbound 1.5.3).
04-23-2015 12:43:41 Daemon.Notice 192.168.1.1 Apr 23 12:43:45 unbound: [45284:0] notice: init module 0: iterator
04-23-2015 12:43:41 Daemon.Notice 192.168.1.1 Apr 23 12:43:45 unbound: [45284:0] notice: Restart of unbound 1.5.3.

Maybe unbound isn't logging exactly what it does.
HUPping ….. but it plain restarts.
HUPping, it reloads, but is says it restarts.
"unbound" uses a new definition of "reload" or "HUP" ?
Whatever ...

Anyway, again, not a bad thing, not a pfSense issue, its more an small "unbound" issue.

doktornotor · Apr 23, 2015, 11:04 AM

I did some digging into the unbound source code and seems like it restarts the worker process on SIGHUP/unbound-control reload. Looks like some half-assed server restart if you ask me. Then again, I'm definitely not familiar with the code, and in general do not have time to dig into it in detail. Since the upstream seemed pretty communicative, maybe get in touch with them instead. (Also, the cache flushing on reload seems like highly unwanted behaviour to me…)

kejianshi · Apr 23, 2015, 12:05 PM

In my case, restart/reload and cache flush is selected in the advanced settings under certain conditions when DNS is getting flooded with unwanted replies to prevent DNS cache poisoning. I'm not sure why I'm not seeing all this other bad behavior.

Gertjan · Apr 23, 2015, 4:13 PM

@doktornotor:

I did some digging into the unbound source code and seems like it restarts the worker process on SIGHUP/unbound-control reload. Looks like some half-assed server restart if you ask me. Then again, I'm definitely not familiar with the code, and in general do not have time to dig into it in detail. Since the upstream seemed pretty communicative, maybe get in touch with them instead. (Also, the cache flushing on reload seems like highly unwanted behaviour to me…)

I did the same thing this afternoon.
Your conclusion is mine ….

@kejianshi:

In my case, restart/reload and cache flush is selected in the advanced settings under certain conditions when DNS is getting flooded with unwanted replies to prevent DNS cache poisoning. I'm not sure why I'm not seeing all this other bad behavior.

That the real issue in 'the issue': who cares about (often) reloading/starting/whatever, but, if the cache is flushed …. then for what is unbound good for ? DNSForwarder is doing the same thing already.

@kejianshi : From what I saw, there is a strict relationship between DHCP activity (system host file rewriting when a new host is added - removed) and unbound reloading. Pretty logic, as a DNS server should know about local hosts - unbound parsers the file upon start reload (from what I understood).

dugeem · May 3, 2015, 2:49 AM

Running pfSense 2.2.2 on an Alix 2D3 with dual WANs - one with IPv4/IPv6 and other with only IPv4.

Regardless of whether I use Unbound or Dnsmasq I'm currently seeing DNS service restarts every 30 minutes which I think is due to DHCP6 (likely dhcp6c but this needs to be confirmed).

As per the comments of many - this renders DNS caching largely ineffective. I think doktornotor put his finger on it earlier in this thread noting that too many services are needlessly restarted when something happens - even if the something results in no IPv4/IPv6 address changes. Hopefully improvements can be made in the next few releases to mitigate this.

Secondly in the case of unbound DHCP registration there is a possibility of inserting/removing A records using the unbound-control local_data (& local_data_remove) command. This will obviously need some code refactoring with the main change being that if unbound is enabled that DHCP registrations would result in unbound-control local_data commands with no service restart. However the unbound.conf file would still need updating so that if unbound is restarted for other reasons it will load all the hosts defined in local-data etc.

Comments? Do we have sufficient understanding of these issues to create some problem tickets? Or has someone already done this?

A Former User · Jul 17, 2015, 12:51 PM

Unbound restarts here roughly every 3 hours. At this time I completely lose the connection to pfSense.

Do you have the same symptoms or is just the logs being written? Im curious if the restart really affects me or there is something else going which interrupts the connection between WIFI and pfSense.

ky41083 · Oct 4, 2015, 12:45 AM

Anyone still having this issue, try this:
https://forum.pfsense.org/index.php?topic=89589.msg558373#msg558373

Would like to get some feedback beyond the handful of devices I manage.

55c40e301e · Jan 23, 2016, 4:15 PM

@ky41083:

Anyone still having this issue, try this:
https://forum.pfsense.org/index.php?topic=89589.msg558373#msg558373

Would like to get some feedback beyond the handful of devices I manage.

For me this stopped the repeated "unbound: service stopped", "unbound: start of service" messages 2-3 times per minute. Thanks - this was a longstanding issue.

It fit because this installation was previously dnsmasq, switched to unbound some time ago.

Specifically, the relevant part of the config export looked like this before:

	 <dnsmasq><regdhcpstatic><custom_options><domain_needed><no_private_reverse><interface></interface></no_private_reverse></domain_needed></custom_options></regdhcpstatic></dnsmasq>

and like this after:

	 <dnsmasq><custom_options><domain_needed><no_private_reverse><interface></interface></no_private_reverse></domain_needed></custom_options></dnsmasq>

It also took a reboot.

A more subtle issue for me is that machines seem to lose DNS resolution (maybe all connectivity?) for about 5 seconds every time their DHCP lease expires and is renewed. For now I've just lengthened DHCP leases significantly - they were short for testing. Separate issue I guess.