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

athurdent · Apr 27, 2013, 5:04 AM

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

@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.

athurdent · May 1, 2013, 7:30 AM

I found the reason for the unbound reloads on my syslog server. Why would dhcpleases do this?

May  1 07:29:20 pfsense dhcpleases: Sending HUP signal to dns daemon(36838)
May  1 07:29:20 pfsense unbound: [36838:0] info: service stopped (unbound 1.4.20).

And domain-name-servers is still missing from my opt1 DHCPD config as stated in my reply above.
Other than that, everything looks good now, only one monitor process.
Thanks for looking into this!

wallabybob · May 1, 2013, 6:48 AM

@athurdent:

I found the reason for the unbound reloads on my syslog server. Why would dhcpleases do this?

PERHAPS it sends a signal to the local DNS to tell it the local name to IP address mapping has changed and the local DNS should read the updated information.

athurdent · May 1, 2013, 7:14 AM

Hmm, but I have not enabled "Register DHCP static mappings". What else could cause this?

wallabybob · May 1, 2013, 11:27 AM

@athurdent:

Hmm, but I have not enabled "Register DHCP static mappings". What else could cause this?

Perhaps it is trying to register a DHCP dynamic mapping! The thread at http://forum.pfsense.org/index.php/topic,33240.msg suggests dhcpleases sends a signal to the DNS to update the DNS registrations.

DNS forwarder has an option Register DHCP leases in DNS forwarder. Do you have the equivalent set in Unbound? I don't know about Unbound and don't run it - does it "inherit" DNS forwarder settings?

Maybe Unbound shouldn't stop when it gets a signal from dhcpleases.

athurdent · May 1, 2013, 12:33 PM

Thanks wallabybob, now I was able to solve it:
I had to turn DNS Forwarder back on, uncheck
"Register DHCP leases in DNS forwarder"
turn it off again and finally reboot. Otherwise dhcpleases would not pick up the change.
It (or something else) filled
/var/etc/hosts
with many of these:


# dhcpleases automatically entered

# dhcpleases automatically entered

# dhcpleases automatically entered

Now they don't show up anymore an unbound runs uninterrupted.

Thanks again for the help!

rbgarga · May 1, 2013, 1:51 PM

@athurdent:

I found the reason for the unbound reloads on my syslog server. Why would dhcpleases do this?
May  1 07:29:20 pfsense dhcpleases: Sending HUP signal to dns daemon(36838)
May  1 07:29:20 pfsense unbound: [36838:0] info: service stopped (unbound 1.4.20).
And domain-name-servers is still missing from my opt1 DHCPD config as stated in my reply above.
Other than that, everything looks good now, only one monitor process.
Thanks for looking into this!

Just to make sure, does this issue still persist? If yes, could you send more details about it?