2.1-BETA0 -> 2.1-BETA1 unbound won't install

athurdent · Apr 26, 2013, 8:56 AM

On my NanoBSD test system (ALIX), the configuration in /usr/pbi/unbound-i386/etc/unbound/unbound.conf only gets updated when I reinstall the package. Changing the interfaces to listen on and pressing "Save" has no effect on my system, the config does not change. I have updated the ticket.

rbgarga · Apr 26, 2013, 10:48 AM

@jcyr:

System->Packages->Available Packages->Unbound says 1.4.20

but install script and unbound logs say 1.4.19!!!

pfSense package version is 1.4.20, PBI version is 1.4.19. You have the latest version, you can go ahead with tests.

rbgarga · Apr 26, 2013, 11:57 AM

@athurdent:

On my NanoBSD test system (ALIX), the configuration in /usr/pbi/unbound-i386/etc/unbound/unbound.conf only gets updated when I reinstall the package. Changing the interfaces to listen on and pressing "Save" has no effect on my system, the config does not change. I have updated the ticket.

Please update to 1.4.20_1 and try again

jimp · Apr 26, 2013, 3:52 PM

Binaries are 1.4.20 now also. I bumped it to 1.4.20_2

jcyr · Apr 27, 2013, 1:13 AM

Hangs during install since the 1.4.20_2 update:

Beginning package installation for Unbound…
Downloading package configuration file... done.
Saving updated package information... done.
Downloading Unbound and its dependencies...
Checking for package installation... Loading package configuration... done.
Configuring package components...
Additional files... done.
Loading package instructions...
Custom commands...
Executing custom_php_install_command()...

Installs the service but not the GUI components

survive · Apr 27, 2013, 4:16 AM

Hi guys,

Is there any indication that the problems in this post:

http://forum.pfsense.org/index.php/topic,43044.msg234009.html#msg234009

have been corrected?

I've been dying to use unbound with pfsense for going on a year but each time I've given it a shot it runs great for about an hour then all my dhcp leases drop & everything that uses dhcp goes off-line. I can quickly recover by disabling unbound and turning the dns forwarder back on.

-Will

athurdent · Apr 27, 2013, 5:04 AM

@jcyr:

Installs the service but not the GUI components

Same here, the GUI components won't show up anymore, reinstalling XML does not help.

LinuxTracker · Apr 27, 2013, 5:21 AM

@athurdent:

@jcyr:

Installs the service but not the GUI components

Same here, the GUI components won't show up anymore, reinstalling XML does not help.

I'll third it.
I did a ground up install of 2.0.3 x86 yesterday and unbound is working.
I did an upgrade from 2.0.2 x86 to 2.0.3 x86 today and am having the same issue mentioned just above.

Poking around to see if I can come across a solution.

rbgarga · Apr 27, 2013, 8:37 PM

It was caused by a typo, 1.4.20_3 fixes the issue.

athurdent · Apr 28, 2013, 7:45 AM

Thank you Renato and jimp, that looks really good now!

Edit: there still seems to be a problem writing this (on NanoBSD) at some point:

unbound: [78569:0] error: could not open autotrust file for writing, /usr/pbi/unbound-i386/etc/unbound/root-trust-anchor.78569-0: Read-only file system

But the file /usr/pbi/unbound-i386/etc/unbound/root-trust-anchor is there, seems valid and unbound runs anyway. I'll keep an eye on this. I have put it "in production" on my home gateway now.

Tawonga · Apr 28, 2013, 12:38 PM

2.1-Beta1(amd64).

Standard Package Install installed Unbound 1.4.20_3, both service and UI, fine. Functioning without issues for a couple of hours.

Thanks Renato and all others involved. Brilliant package - worth waiting for.

athurdent · Apr 28, 2013, 1:39 PM

Something is not quite right yet. It restarts every hour on my system (NanoBSD), at exactly the same time.


Apr 28 14:16:50	unbound: [61715:0] notice: Restart of unbound 1.4.20.
Apr 28 14:16:50	unbound: [61715:0] notice: init module 0: validator
Apr 28 14:16:50	unbound: [61715:0] notice: init module 1: iterator
Apr 28 14:16:50	unbound: [61715:0] info: start of service (unbound 1.4.20).

Apr 28 15:16:50	unbound: [61715:0] info: service stopped (unbound 1.4.20).
Apr 28 15:16:50	unbound: [61715:0] info: server stats for thread 0: 1096 queries, 874 answers from cache, 222 recursions, 23 prefetch
Apr 28 15:16:50	unbound: [61715:0] info: server stats for thread 0: requestlist max 13 avg 1.2898 exceeded 0 jostled 0
Apr 28 15:16:50	unbound: [61715:0] info: average recursion processing time 0.159908 sec
Apr 28 15:16:50	unbound: [61715:0] info: histogram of recursion processing times
Apr 28 15:16:50	unbound: [61715:0] info: [25%]=0.0201766 median[50%]=0.0504123 [75%]=0.237086
Apr 28 15:16:50	unbound: [61715:0] info: lower(secs) upper(secs) recursions
Apr 28 15:16:50	unbound: [61715:0] info: 0.000000 0.000001 25
Apr 28 15:16:50	unbound: [61715:0] info: 0.002048 0.004096 1
Apr 28 15:16:50	unbound: [61715:0] info: 0.008192 0.016384 17
Apr 28 15:16:50	unbound: [61715:0] info: 0.016384 0.032768 54
Apr 28 15:16:50	unbound: [61715:0] info: 0.032768 0.065536 26
Apr 28 15:16:50	unbound: [61715:0] info: 0.065536 0.131072 16
Apr 28 15:16:50	unbound: [61715:0] info: 0.131072 0.262144 34
Apr 28 15:16:50	unbound: [61715:0] info: 0.262144 0.524288 34
Apr 28 15:16:50	unbound: [61715:0] info: 0.524288 1.000000 13
Apr 28 15:16:50	unbound: [61715:0] info: 1.000000 2.000000 2
Apr 28 15:16:50	unbound: [61715:0] info: server stats for thread 1: 599 queries, 465 answers from cache, 134 recursions, 20 prefetch
Apr 28 15:16:50	unbound: [61715:0] info: server stats for thread 1: requestlist max 19 avg 1.32468 exceeded 0 jostled 0
Apr 28 15:16:50	unbound: [61715:0] info: average recursion processing time 0.113623 sec
Apr 28 15:16:50	unbound: [61715:0] info: histogram of recursion processing times
Apr 28 15:16:50	unbound: [61715:0] info: [25%]=0.0207076 median[50%]=0.0431942 [75%]=0.199339
Apr 28 15:16:50	unbound: [61715:0] info: lower(secs) upper(secs) recursions
Apr 28 15:16:50	unbound: [61715:0] info: 0.000000 0.000001 15
Apr 28 15:16:50	unbound: [61715:0] info: 0.001024 0.002048 1
Apr 28 15:16:50	unbound: [61715:0] info: 0.008192 0.016384 8
Apr 28 15:16:50	unbound: [61715:0] info: 0.016384 0.032768 36
Apr 28 15:16:50	unbound: [61715:0] info: 0.032768 0.065536 22
Apr 28 15:16:50	unbound: [61715:0] info: 0.065536 0.131072 6
Apr 28 15:16:50	unbound: [61715:0] info: 0.131072 0.262144 24
Apr 28 15:16:50	unbound: [61715:0] info: 0.262144 0.524288 21
Apr 28 15:16:50	unbound: [61715:0] info: 1.000000 2.000000 1
Apr 28 15:16:50	unbound: [61715:0] notice: Restart of unbound 1.4.20.
Apr 28 15:16:50	unbound: [61715:0] notice: init module 0: validator
Apr 28 15:16:50	unbound: [61715:0] notice: init module 1: iterator
Apr 28 15:16:50	unbound: [61715:0] info: start of service (unbound 1.4.20).
Apr 28 15:16:50	unbound: [61715:0] info: service stopped (unbound 1.4.20).
Apr 28 15:16:50	unbound: [61715:0] info: server stats for thread 0: 1 queries, 1 answers from cache, 0 recursions, 0 prefetch
Apr 28 15:16:50	unbound: [61715:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
Apr 28 15:16:50	unbound: [61715:0] info: server stats for thread 1: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch
Apr 28 15:16:50	unbound: [61715:0] info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
Apr 28 15:16:50	unbound: [61715:0] notice: Restart of unbound 1.4.20.
Apr 28 15:16:50	unbound: [61715:0] notice: init module 0: validator
Apr 28 15:16:50	unbound: [61715:0] notice: init module 1: iterator
Apr 28 15:16:50	unbound: [61715:0] info: start of service (unbound 1.4.20).

Maybe this is linked to DHCP somehow?


Apr 28 15:16:50	dhcpd: Wrote 0 deleted host decls to leases file.
Apr 28 15:16:50	dhcpd: Wrote 0 new dynamic host decls to leases file.
Apr 28 15:16:50	dhcpd: Wrote 14 leases to leases file.

I don't know why dhcpd does this, it's not configured to backup it's leases and I don't see any cronjob that maybe related.

There are quite a few monitor instances running, too:

ps auxwww | grep unb
root     5605  0.0  0.1  3644  1520  ??  SN   10:47AM   0:08.85 /bin/sh /usr/local/etc/rc.d/unbound_monitor.sh start
root    59518  0.0  0.1  3644  1348  ??  SN   10:32AM   0:09.01 /bin/sh /usr/local/etc/rc.d/unbound_monitor.sh start
unbound 61715  0.0  1.0 31352 19644  ??  Is   11:10AM   0:10.83 unbound -c /usr/pbi/unbound-i386/etc/unbound/unbound.conf
root    70174  0.0  0.1  3644  1520  ??  SN   10:45AM   0:09.04 /bin/sh /usr/local/etc/rc.d/unbound_monitor.sh start
root    72082  0.0  0.1  3644  1364  ??  SN   10:33AM   0:09.75 /bin/sh /usr/local/etc/rc.d/unbound_monitor.sh start
root    59935  0.0  0.1  3644  1364  u0- S    10:33AM   0:09.09 /bin/sh /usr/local/etc/rc.d/unbound_monitor.sh start

Also odd, that the running unbound process has a start time of 11:10AM, shouldn't that be 3:16PM if it really restarted?
Any hints for me?

jcyr · Apr 28, 2013, 3:12 PM

I, on the other hand, after 12 hours have no instances of unbound_monitor.sh running!

rbgarga · Apr 29, 2013, 3:35 PM

Please try 1.4.20_4 and let me know the results.

athurdent · Apr 29, 2013, 6:13 PM

Looks really good on the commandline now, only one unbound_monitor.sh. Works fine!
But it still restarts every hour, any idea what might be causing that?

rbgarga · Apr 29, 2013, 6:55 PM

@athurdent:

Looks really good on the commandline now, only one unbound_monitor.sh. Works fine!
But it still restarts every hour, any idea what might be causing that?

No idea until now, I couldn't replicate it on my local test env.

jcyr · Apr 29, 2013, 10:21 PM

Not quite there yet! Every time I change and save new dhcpd settings a new unbound_monitor.sh is added.

jcyr · Apr 30, 2013, 2:59 AM

At the beginning of the /usr/local/etc/rc.d/unbound_monitor.sh script, there is the following:

**PROCS=/bin/pgrep -f unbound_monitor.sh | wc -l | awk '{print $1}'

if [ ${PROCS} -gt [color=red]2 ]; then
echo "There are another unbound monitor proccess running"
exit 0
fi**
Shouldn't it be:

**PROCS=/bin/pgrep -f unbound_monitor.sh | wc -l | awk '{print $1}'

if [ ${PROCS} -gt [color=red]1 ]; then
echo "There are other unbound monitor proccess running"
exit 0
fi**
???

athurdent · Apr 30, 2013, 8:41 AM

Still reloads every hour, I cannot find a reason for that. The only thing I found out was that I have to issue```
unbound-control reload


Another problem is that my DMZ on opt1 is missing the option```
domain-name-servers 192.168.1.254;
```in /var/dhcpd/etc/dhcpd.conf when I use unbound. I have opt1 defined as Network interface in unbound configuration and I can "dig" it from the DMZ. Using the system forwarder the option is there.

rbgarga · Apr 30, 2013, 9:25 PM

unbound_monitor.sh was not working with last change, I changed the logic a bit and the way it's called and released 1.4.20_5. Let me know if you find any issues. I tested it on nanobsd and full installation.