Unbound frequently restarts on 2.2 - is this normal?
-
While troubleshooting another issue, I discovered frequent restarts (every hour) in the unbound log. Is this normal or is something wrong?
Feb 5 15:50:06 unbound: [13647:0] info: start of service (unbound 1.5.1).
Feb 5 15:50:06 unbound: [13647:0] notice: init module 0: iterator
Feb 5 15:50:06 unbound: [13647:0] notice: Restart of unbound 1.5.1.Feb 5 16:50:30 unbound: [13647:0] info: start of service (unbound 1.5.1).
Feb 5 16:50:30 unbound: [13647:0] notice: init module 0: iterator
Feb 5 16:50:30 unbound: [13647:0] notice: Restart of unbound 1.5.1.Thanks,
Marco2.2-RELEASE (i386)
nanobsd (2g) -
Check the system log for what's going on at the time when unbound gets restarted. Like, new DHCP lease on WAN.
-
Like, new DHCP lease on WAN.
Something is up with 2.2 and DHCP. I'm getting all kinds of DHCP resets that I never got before 2.2. It's causing all kinds of issues with apinger and unbound; typically manifested as me "loosing" internet connectivity for 3-5 minutes.
I've not been able to isolate what the heck is going on as there isn't much in the logs, but the common thread is DHCP address renewal (my WAN IP address hasn't changed since I initially got my FIOS connection). I don't know what is different but it's really been frustrating trying to nail down where the blame lies. I think most of it is with apinger which I'm about ready to just turn off, which is a shame since I like some of the RRD reports it contributes to. But I like stable internet even more :p
-
I have the same problem with unbound. There seems to be a direct connection between unbound stopping and restarting and DHCP leases. At 8:56:11 the unbound service stopped and then restarted:
Feb 11 08:56:11 unbound: [16927:0] info: start of service (unbound 1.5.1). Feb 11 08:56:11 unbound: [16927:0] notice: init module 1: iterator Feb 11 08:56:11 unbound: [16927:0] notice: init module 0: validator Feb 11 08:56:11 unbound: [16927:0] notice: Restart of unbound 1.5.1. Feb 11 08:56:11 unbound: [16927:0] info: 0.262144 0.524288 1 Feb 11 08:56:11 unbound: [16927:0] info: 0.065536 0.131072 1 Feb 11 08:56:11 unbound: [16927:0] info: 0.032768 0.065536 9 Feb 11 08:56:11 unbound: [16927:0] info: 0.016384 0.032768 2 Feb 11 08:56:11 unbound: [16927:0] info: 0.008192 0.016384 1 Feb 11 08:56:11 unbound: [16927:0] info: 0.004096 0.008192 1 Feb 11 08:56:11 unbound: [16927:0] info: 0.002048 0.004096 3 Feb 11 08:56:11 unbound: [16927:0] info: 0.001024 0.002048 1 Feb 11 08:56:11 unbound: [16927:0] info: 0.000000 0.000001 1 Feb 11 08:56:11 unbound: [16927:0] info: lower(secs) upper(secs) recursions Feb 11 08:56:11 unbound: [16927:0] info: [25%]=0.004096 median[50%]=0.0364089 [75%]=0.0546133 Feb 11 08:56:11 unbound: [16927:0] info: histogram of recursion processing times Feb 11 08:56:11 unbound: [16927:0] info: average recursion processing time 0.044537 sec Feb 11 08:56:11 unbound: [16927:0] info: server stats for thread 1: requestlist max 2 avg 0.3 exceeded 0 jostled 0 Feb 11 08:56:11 unbound: [16927:0] info: server stats for thread 1: 111 queries, 91 answers from cache, 20 recursions, 0 prefetch Feb 11 08:56:11 unbound: [16927:0] info: 0.524288 1.000000 1 Feb 11 08:56:11 unbound: [16927:0] info: 0.262144 0.524288 2 Feb 11 08:56:11 unbound: [16927:0] info: 0.131072 0.262144 1 Feb 11 08:56:11 unbound: [16927:0] info: 0.065536 0.131072 2 Feb 11 08:56:11 unbound: [16927:0] info: 0.032768 0.065536 6 Feb 11 08:56:11 unbound: [16927:0] info: 0.016384 0.032768 6 Feb 11 08:56:11 unbound: [16927:0] info: 0.008192 0.016384 1 Feb 11 08:56:11 unbound: [16927:0] info: 0.004096 0.008192 5 Feb 11 08:56:11 unbound: [16927:0] info: 0.002048 0.004096 4 Feb 11 08:56:11 unbound: [16927:0] info: lower(secs) upper(secs) recursions Feb 11 08:56:11 unbound: [16927:0] info: [25%]=0.0065536 median[50%]=0.0273067 [75%]=0.0600747 Feb 11 08:56:11 unbound: [16927:0] info: histogram of recursion processing times Feb 11 08:56:11 unbound: [16927:0] info: average recursion processing time 0.082688 sec Feb 11 08:56:11 unbound: [16927:0] info: server stats for thread 0: requestlist max 3 avg 0.857143 exceeded 0 jostled 0 Feb 11 08:56:11 unbound: [16927:0] info: server stats for thread 0: 136 queries, 108 answers from cache, 28 recursions, 0 prefetch Feb 11 08:56:11 unbound: [16927:0] info: service stopped (unbound 1.5.1).
At that exact time i get this in DHCP logs:
Feb 11 08:56:11 dhcpd: DHCPACK on 192.168.1.15 to 1c:af:f7:xx:xx:xx (DIR-600) via em0
Feb 11 08:56:11 dhcpd: DHCPREQUEST for 192.168.1.15 from 1c:af:f7:xx:xx:xx (DIR-600) via em0
Feb 11 08:56:11 dhcpd: Wrote 9 leases to leases file.
Feb 11 08:56:11 dhcpd: Wrote 0 new dynamic host decls to leases file.
Feb 11 08:56:11 dhcpd: Wrote 0 deleted host decls to leases file.Again at 09:57:00 unbound service restarts:
Feb 11 09:57:00 unbound: [16927:0] info: start of service (unbound 1.5.1). Feb 11 09:57:00 unbound: [16927:0] notice: init module 1: iterator Feb 11 09:57:00 unbound: [16927:0] notice: init module 0: validator Feb 11 09:57:00 unbound: [16927:0] notice: Restart of unbound 1.5.1. Feb 11 09:57:00 unbound: [16927:0] info: 0.524288 1.000000 1 Feb 11 09:57:00 unbound: [16927:0] info: 0.262144 0.524288 6
Corelated with this DHCP log:
Feb 11 09:57:00 router dhcpd: DHCPOFFER on 192.168.1.17 to 78:dd:08:xx:xx:xx (vaio) via em0 Feb 11 09:57:00 router dhcpd: Wrote 0 deleted host decls to leases file. Feb 11 09:57:00 router dhcpd: Wrote 0 new dynamic host decls to leases file. Feb 11 09:57:00 router dhcpd: Wrote 9 leases to leases file. Feb 11 09:57:00 router dhcpd: DHCPREQUEST for 192.168.1.17 (192.168.1.1) from 78:dd:08:xx:xx:xx (vaio) via em0 Feb 11 09:57:00 router dhcpd: DHCPACK on 192.168.1.17 to 78:dd:08:xx:xx:xx (vaio) via em0 Feb 11 09:57:00 router dhcpd: Request message from fe80::dc38:d6fa:xxx:xxx port 546, transaction ID 0x6B31FC00 Feb 11 09:57:00 router dhcpd: Sending Reply to fe80::dc38:d6fa:xxx:xxx port 546
And yet again at 10:57:17:
Feb 11 10:57:17 unbound: [16927:0] info: start of service (unbound 1.5.1). Feb 11 10:57:17 unbound: [16927:0] notice: init module 1: iterator Feb 11 10:57:17 unbound: [16927:0] notice: init module 0: validator Feb 11 10:57:17 unbound: [16927:0] notice: Restart of unbound 1.5.1. Feb 11 10:57:17 unbound: [16927:0] info: 2.000000 4.000000 1 Feb 11 10:57:17 unbound: [16927:0] info: 1.000000 2.000000 1 Feb 11 10:57:17 unbound: [16927:0] info: 0.524288 1.000000 4 Feb 11 10:57:17 unbound: [16927:0] info: 0.262144 0.524288 8 Feb 11 10:57:17 unbound: [16927:0] info: 0.131072 0.262144 9 Feb 11 10:57:17 unbound: [16927:0] info: 0.065536 0.131072 12 Feb 11 10:57:17 unbound: [16927:0] info: 0.032768 0.065536 23 Feb 11 10:57:17 unbound: [16927:0] info: 0.016384 0.032768 43 Feb 11 10:57:17 unbound: [16927:0] info: 0.008192 0.016384 41 Feb 11 10:57:17 unbound: [16927:0] info: 0.004096 0.008192 57 Feb 11 10:57:17 unbound: [16927:0] info: 0.002048 0.004096 43 Feb 11 10:57:17 unbound: [16927:0] info: 0.001024 0.002048 9 Feb 11 10:57:17 unbound: [16927:0] info: 0.000512 0.001024 1 Feb 11 10:57:17 unbound: [16927:0] info: 0.000000 0.000001 19 Feb 11 10:57:17 unbound: [16927:0] info: lower(secs) upper(secs) recursions Feb 11 10:57:17 unbound: [16927:0] info: [25%]=0.00389358 median[50%]=0.00949073 [75%]=0.029053 Feb 11 10:57:17 unbound: [16927:0] info: histogram of recursion processing times Feb 11 10:57:17 unbound: [16927:0] info: average recursion processing time 0.054781 sec Feb 11 10:57:17 unbound: [16927:0] info: server stats for thread 1: requestlist max 4 avg 0.231618 exceeded 0 jostled 0 Feb 11 10:57:17 unbound: [16927:0] info: server stats for thread 1: 329 queries, 57 answers from cache, 272 recursions, 0 prefetch Feb 11 10:57:17 unbound: [16927:0] info: 1.000000 2.000000 2 Feb 11 10:57:17 unbound: [16927:0] info: 0.524288 1.000000 9 Feb 11 10:57:17 unbound: [16927:0] info: 0.262144 0.524288 19 Feb 11 10:57:17 unbound: [16927:0] info: 0.131072 0.262144 23 Feb 11 10:57:17 unbound: [16927:0] info: 0.065536 0.131072 24 Feb 11 10:57:17 unbound: [16927:0] info: 0.032768 0.065536 44 Feb 11 10:57:17 unbound: [16927:0] info: 0.016384 0.032768 68 Feb 11 10:57:17 unbound: [16927:0] info: 0.008192 0.016384 66 Feb 11 10:57:17 unbound: [16927:0] info: 0.004096 0.008192 95 Feb 11 10:57:17 unbound: [16927:0] info: 0.002048 0.004096 45 Feb 11 10:57:17 unbound: [16927:0] info: 0.001024 0.002048 12 Feb 11 10:57:17 unbound: [16927:0] info: 0.000512 0.001024 1 Feb 11 10:57:17 unbound: [16927:0] info: 0.000000 0.000001 20 Feb 11 10:57:17 unbound: [16927:0] info: lower(secs) upper(secs) recursions Feb 11 10:57:17 unbound: [16927:0] info: [25%]=0.00534636 median[50%]=0.013281 [75%]=0.0431942 Feb 11 10:57:17 unbound: [16927:0] info: histogram of recursion processing times Feb 11 10:57:17 unbound: [16927:0] info: average recursion processing time 0.066407 sec Feb 11 10:57:17 unbound: [16927:0] info: server stats for thread 0: requestlist max 4 avg 0.441589 exceeded 0 jostled 0 Feb 11 10:57:17 unbound: [16927:0] info: server stats for thread 0: 516 queries, 88 answers from cache, 428 recursions, 0 prefetch Feb 11 10:57:17 unbound: [16927:0] info: service stopped (unbound 1.5.1).
DHCP logs:
Feb 11 10:57:17 dhcpd: Sending Reply to fe80::1863:4b13:xxxx:xxxx port 546 Feb 11 10:57:17 dhcpd: Confirm message from fe80::1863:4b13:xxxx:xxxx port 546, transaction ID 0x51830100 Feb 11 10:57:17 dhcpd: DHCPACK on 192.168.1.12 to 78:7e:61:xx:xx:xx (Anamas-iPhone) via em0 Feb 11 10:57:17 dhcpd: DHCPREQUEST for 192.168.1.12 from 78:7e:61:xx:xx:xx (Anamas-iPhone) via em0 Feb 11 10:57:17 dhcpd: Wrote 9 leases to leases file. Feb 11 10:57:17 dhcpd: Wrote 0 new dynamic host decls to leases file. Feb 11 10:57:17 dhcpd: Wrote 0 deleted host decls to leases file.
-
Do you have a cron job rc.backup_dhcpleases.sh that is running every hour?
It must be over-enthusiastic and restart unbound when the lease file is written. Perhaps it can just send unbound a message? Or perhaps it does not need to tell unbound anything - unbound should already be getting DHCP lease data on-the-fly as it happens?
-
Nope…
$ crontab -l
crontab: no crontab for root -
crontab -l
That does not work for me either.
cat /etc/crontab
and see what is there.
Or instal the Cron package and you an see the cron jobs in the webGUI. -
$ cat /etc/crontab
SHELL=/bin/sh
PATH=/etc:/bin:/sbin:/usr/bin:/usr/sbin
HOME=/var/log
#minute hour mday month wday who commandpfSense specific crontab entries
Created: February 8, 2015, 6:13 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
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
*/60 * * * * root /usr/bin/nice -n20 /usr/local/sbin/expiretable -v -t 3600 webConfiguratorlockoutIf 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)
-
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…
-
No - Its not intentional (Unless mine is broken. Unbound has been running without service restart for a week)
-
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.
… -
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 commandpfSense 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_urltablesIf 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)
-
One thing is clear in my case : Every time the dhcp service writes leases to leases file the unbound service restarts…every single time.
-
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 -
It would be interesting and probably helpful to see your DHCP server setting and your unbound settings.
-
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 -
Sounds like something I see lots of people doing with laptops. Plugging in wired while wireless is still on. Same with IP Cams.
-
@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…
-
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?
-
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 ? -
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
-
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).
-
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?
-
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…
-
Any solution to this?
-
Is this a confirmed bug? If so, how can we report it? I'm having the same issue.
-
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!
-
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.
-
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.
-
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.
-
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.
-
-
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 )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 :)
-
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.
-
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 ?).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. >:(
-
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 -HUPcat /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.
-
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…)
-
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.
-
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 ….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).
-
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?