Unbound frequently restarts on 2.2 - is this normal?

macboy6 · Feb 11, 2015, 12:33 PM

I am going to have to assume this is the intended behaviour at this point. It doesn't cause any adverse effects for me.

I do have the OpenVPN client configured (in case this is somehow interacting with unbound) but it is constantly connected and not restarting.

Would be nice to get confirmation from one of the developers though…

kejianshi · Feb 11, 2015, 12:51 PM

No - Its not intentional (Unless mine is broken. Unbound has been running without service restart for a week)

hda · Feb 11, 2015, 1:45 PM

@macboy6:

While troubleshooting another issue, I discovered frequent restarts (every hour) in the unbound log. Is this normal or is something wrong?

Related to your ISP lease renewal ? Status: System logs: General:
…
() check_reload_status: Starting packages
() php-fpm[34310]: /rc.start_packages: Restarting/Starting all packages.
…

macboy6 · Feb 11, 2015, 2:12 PM

Nope, nothing correlates in system logs. I do have Dynamic DNS setup though but that only updates once per day, so doubt it's related.

Cron jobs output:

SHELL=/bin/sh
PATH=/etc:/bin:/sbin:/usr/bin:/usr/sbin
HOME=/var/log
#minute hour mday month wday who command

pfSense specific crontab entries

Created: February 7, 2015, 8:05 pm

1,31 0-5 * * * root /usr/bin/nice -n20 adjkerntz -a
1 3 1 * * root /usr/bin/nice -n20 /etc/rc.update_bogons.sh
*/60 * * * * root /usr/bin/nice -n20 /usr/local/sbin/expiretable -v -t 3600 sshlockout
*/60 * * * * root /usr/bin/nice -n20 /usr/local/sbin/expiretable -v -t 3600 webConfiguratorlockout
1 1 * * * root /usr/bin/nice -n20 /etc/rc.dyndns.update
*/60 * * * * root /usr/bin/nice -n20 /usr/local/sbin/expiretable -v -t 3600 virusprot
30 12 * * * root /usr/bin/nice -n20 /etc/rc.update_urltables

If possible do not add items to this file manually.

If you do so, this file must be terminated with a blank line (e.g. new line)

Inq · Feb 11, 2015, 4:50 PM

One thing is clear in my case : Every time the dhcp service writes leases to leases file the unbound service restarts…every single time.

macboy6 · Feb 11, 2015, 11:48 PM

Inq - I just noticed that one of my network devices (Apple TV) was going crazy asking for dhcp every few seconds. I did a clean install of 2.2 and didnt reboot some of my devices, which probably caused this issue.

I am now thinking that this issue could have been causing the frequent unbound resets. I will monitor and update this thread.

Thanks,
Marco

kejianshi · Feb 12, 2015, 12:31 AM

It would be interesting and probably helpful to see your DHCP server setting and your unbound settings.

macboy6 · Feb 12, 2015, 11:19 PM

Ok, this issue was definitely caused by a misconfiguration on my Apple TV (connected to both wired and wireless simultaneously). This was causing the Apple TV to get stuck in a DHCP request loop (verified by DHCP logs).

In addition, I have the following setting in Unbound: Register DHCP leases in the DNS Resolver

Since I corrected the Apple TV issue, the hourly unbound restarts have stopped.

Thanks,
Marco

kejianshi · Feb 12, 2015, 11:26 PM

Sounds like something I see lots of people doing with laptops. Plugging in wired while wireless is still on. Same with IP Cams.

wbond · Feb 18, 2015, 3:53 AM

@Inq:

One thing is clear in my case : Every time the dhcp service writes leases to leases file the unbound service restarts…every single time.

I noticed the same thing the other day, unbound restarting every time the dhcp service wrote the leases file, about once an hour. It hadn't been doing this until I changed the setting for "unwanted reply threshold" in the dns resolver advanced settings from disabled to 10 million. I changed it back to disabled yesterday and unbound has not restarted since. No idea what the relationship is, but there seems to be one.

edit: nevermind, changed another setting in dns resolver and now unbound is restarting at the same time the dhcp service writes the leases file again…

kevindd992002 · Mar 9, 2015, 12:58 AM

I'm experiencing the same problem with Unbound. Does this mean that it's normal for it to restart if the option to "Register DHCP leases in the DNS Resolver" is enabled?

Gertjan · Apr 6, 2015, 8:03 AM

@wbond:

edit: nevermind, changed another setting in dns resolver and now unbound is restarting at the same time the dhcp service writes the leases file again…

I see the same thing: Unbound is restarting on every DHCPREQUEST - DHCPACK sequence:
Status: System logs: DHCP log:

04-06-2015	09:49:36	Local7.Info	192.168.1.1	Apr  6 09:49:37 dhcpd: DHCPREQUEST for 192.168.2.235 from 78:3a:84:xx:34:1f (Philippes-Air) via sis0
04-06-2015	09:49:36	Local7.Info	192.168.1.1	Apr  6 09:49:37 dhcpd: DHCPACK on 192.168.2.235 to 78:3a:84:xx:34:1f (Philippes-Air) via sis0
04-06-2015	09:49:36	User.Info	192.168.1.1	Apr  6 09:49:37 dhcpleases: Sending HUP signal to dns daemon(53865)

I guess, when "Sending HUP signal to dns daemon" is fired, Unbound restarts.
At that moment, on the "Status: System logs: Resolver", I see (reversed time order):

04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info: start of service (unbound 1.5.3).
04-06-2015	09:52:08	Daemon.Notice	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] notice: init module 0: iterator
04-06-2015	09:52:08	Daemon.Notice	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] notice: Restart of unbound 1.5.3.
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info:    0.524288    1.000000 1
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info:    0.262144    0.524288 2
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info:    0.131072    0.262144 1
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info: lower(secs) upper(secs) recursions
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info: [25%]=0.262144 median[50%]=0.393216 [75%]=0.524288
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info: histogram of recursion processing times
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info: average recursion processing time 0.414164 sec
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info: server stats for thread 1: requestlist max 4 avg 1 exceeded 0 jostled 0
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info: server stats for thread 1: 4 queries, 0 answers from cache, 4 recursions, 0 prefetch
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info:    0.524288    1.000000 4
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info:    0.262144    0.524288 5
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info:    0.131072    0.262144 3
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info:    0.065536    0.131072 3
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info:    0.032768    0.065536 3
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info:    0.016384    0.032768 1
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info: lower(secs) upper(secs) recursions
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info: [25%]=0.08192 median[50%]=0.240299 [75%]=0.484966
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info: histogram of recursion processing times
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info: average recursion processing time 0.331678 sec
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info: server stats for thread 0: requestlist max 28 avg 3.36842 exceeded 0 jostled 0
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info: server stats for thread 0: 25 queries, 6 answers from cache, 19 recursions, 0 prefetch
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info: service stopped (unbound 1.5.3).

This means that unbound restart several times per minute … is this normal ???
Or is this what it is all about, the setting "DHCP Registration" on the "Services: DNS Resolver" page ?

doktornotor · Apr 6, 2015, 9:48 AM

@Gertjan:

Or is this what it is all about, the setting "DHCP Registration" on the "Services: DNS Resolver" page ?
This means that unbound restart several times per minute … is this normal ???

No, it's not normal. And in general, the "wheeeeeeeee something might have changed (99% of cases absolutely nothing at all changed and apinger just went haywire as usual) so lets restart all services and packages" mentality that pfSense has grown is an absolute disaster. (Recently, someone finally nuked this nonsense on routing packages like OpenBGPD/Quagga where it was making them just completely no-op.)

Example of this madness: https://redmine.pfsense.org/issues/4474

CiscoKid85 · Apr 7, 2015, 10:58 PM

I upgraded to 2.2.1 and this is still occurring very frequently for me.


Apr 7 18:46:45	unbound: [53511:0] info: start of service (unbound 1.5.3).
Apr 7 18:46:45	unbound: [53511:0] info: service stopped (unbound 1.5.3).
Apr 7 18:36:50	unbound: [53511:0] info: start of service (unbound 1.5.3).
Apr 7 18:36:50	unbound: [53511:0] info: service stopped (unbound 1.5.3).
Apr 7 18:31:39	unbound: [53511:0] info: start of service (unbound 1.5.3).
Apr 7 18:31:39	unbound: [53511:0] info: service stopped (unbound 1.5.3).
Apr 7 18:26:56	unbound: [53511:0] info: start of service (unbound 1.5.3).
Apr 7 18:26:56	unbound: [53511:0] info: service stopped (unbound 1.5.3).
Apr 7 18:21:31	unbound: [53511:0] info: start of service (unbound 1.5.3).
Apr 7 18:21:31	unbound: [53511:0] info: service stopped (unbound 1.5.3).
Apr 7 18:17:00	unbound: [53511:0] info: start of service (unbound 1.5.3).
Apr 7 18:17:00	unbound: [53511:0] info: service stopped (unbound 1.5.3).
Apr 7 18:10:10	unbound: [53511:0] info: start of service (unbound 1.5.3).
Apr 7 18:10:09	unbound: [53511:0] info: service stopped (unbound 1.5.3).
Apr 7 18:09:23	unbound: [53511:0] info: start of service (unbound 1.5.3).
Apr 7 18:09:23	unbound: [53511:0] info: service stopped (unbound 1.5.3).

Barnabas · Apr 11, 2015, 11:19 PM

I have been having this problem also.
I first thought it was BandwidthD, but I removed and did not help.

Apr 11 18:03:42 	unbound: [76411:0] info: service stopped (unbound 1.5.3).
Apr 11 18:03:42 	unbound: [76411:0] info: server stats for thread 0: 228 queries, 48 answers from cache, 180 recursions, 0 prefetch
Apr 11 18:03:42 	unbound: [76411:0] info: server stats for thread 0: requestlist max 20 avg 2.90556 exceeded 0 jostled 0
Apr 11 18:03:42 	unbound: [76411:0] info: average recursion processing time 0.291716 sec
Apr 11 18:03:42 	unbound: [76411:0] info: histogram of recursion processing times
Apr 11 18:03:42 	unbound: [76411:0] info: [25%]=0.107241 median[50%]=0.236444 [75%]=0.40778
Apr 11 18:03:42 	unbound: [76411:0] info: lower(secs) upper(secs) recursions
Apr 11 18:03:42 	unbound: [76411:0] info: 0.000000 0.000001 2
Apr 11 18:03:42 	unbound: [76411:0] info: 0.008192 0.016384 10
Apr 11 18:03:42 	unbound: [76411:0] info: 0.016384 0.032768 13
Apr 11 18:03:42 	unbound: [76411:0] info: 0.032768 0.065536 13
Apr 11 18:03:42 	unbound: [76411:0] info: 0.065536 0.131072 11
Apr 11 18:03:42 	unbound: [76411:0] info: 0.131072 0.262144 51
Apr 11 18:03:42 	unbound: [76411:0] info: 0.262144 0.524288 63
Apr 11 18:03:42 	unbound: [76411:0] info: 0.524288 1.000000 10
Apr 11 18:03:42 	unbound: [76411:0] info: 1.000000 2.000000 6
Apr 11 18:03:42 	unbound: [76411:0] info: 2.000000 4.000000 1
Apr 11 18:03:42 	unbound: [76411:0] notice: Restart of unbound 1.5.3.
Apr 11 18:03:42 	unbound: [76411:0] notice: init module 0: validator
Apr 11 18:03:42 	unbound: [76411:0] notice: init module 1: iterator
Apr 11 18:03:42 	unbound: [76411:0] info: start of service (unbound 1.5.3).
Apr 11 18:07:39 	unbound: [76411:0] info: service stopped (unbound 1.5.3).
Apr 11 18:07:39 	unbound: [76411:0] info: server stats for thread 0: 36 queries, 4 answers from cache, 32 recursions, 0 prefetch
Apr 11 18:07:39 	unbound: [76411:0] info: server stats for thread 0: requestlist max 14 avg 3.96875 exceeded 0 jostled 0
Apr 11 18:07:39 	unbound: [76411:0] info: average recursion processing time 0.224321 sec
Apr 11 18:07:39 	unbound: [76411:0] info: histogram of recursion processing times
Apr 11 18:07:39 	unbound: [76411:0] info: [25%]=0.104858 median[50%]=0.191567 [75%]=0.299593
Apr 11 18:07:39 	unbound: [76411:0] info: lower(secs) upper(secs) recursions
Apr 11 18:07:39 	unbound: [76411:0] info: 0.008192 0.016384 1
Apr 11 18:07:39 	unbound: [76411:0] info: 0.016384 0.032768 2
Apr 11 18:07:39 	unbound: [76411:0] info: 0.032768 0.065536 2
Apr 11 18:07:39 	unbound: [76411:0] info: 0.065536 0.131072 5
Apr 11 18:07:39 	unbound: [76411:0] info: 0.131072 0.262144 13
Apr 11 18:07:39 	unbound: [76411:0] info: 0.262144 0.524288 7
Apr 11 18:07:39 	unbound: [76411:0] info: 0.524288 1.000000 1
Apr 11 18:07:39 	unbound: [76411:0] info: 1.000000 2.000000 1
Apr 11 18:07:39 	unbound: [76411:0] notice: Restart of unbound 1.5.3.
Apr 11 18:07:39 	unbound: [76411:0] notice: init module 0: validator
Apr 11 18:07:39 	unbound: [76411:0] notice: init module 1: iterator
Apr 11 18:07:39 	unbound: [76411:0] info: start of service (unbound 1.5.3).

Any clues?

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.