Unbound can't start after snapshot update (new thread!)

clarknova

2.0-RC1 (amd64)
built on Tue Mar 15 23:34:27 EDT 2011
Unbound 1.4.8_131

After a couple weeks on an early March snapshot, I decided to update. I was already running the latest Unbound. After the restart Unbound did not start, and I saw many of these in the system log:

php: /pkg_mgr_install.php: The command '/usr/local/sbin/unbound-control start' returned exit code '1', the output was '/usr/local/etc/unbound/unbound.conf:35: error: unknown keyword '69.165.225.254' read /usr/local/etc/unbound/unbound.conf failed: 1 errors in configuration file [1300261417] unbound[27096:0] fatal error: Could not read config file: /usr/local/etc/unbound/unbound.conf'

I checked the file in question and line 35 simply reads

interface: 69.165.225.254

which is correct, as that is the address of one of my internal interfaces. I did notice however that the line above looked like this:

interface:

Reinstalling the package didn't solve the problem, but de-selecting that interface I was then able to manually start it from the Status: Services page in the UI. I then went back and re-added that interface and it appears to be running fine (although I can't test from that interface at the moment). Checking the conf file again, the blank interface: line is now gone.

wagonza

Odd, almost as though there was an empty interface in your config. Will add a safety belt for that, although one shouldn't have to.
Have you updated since the 15th?

wagonza

Do you make use of CARP? I have noticed that for some reason if a carp address doesn't come up and there is no interface for it (eg. vip100) then it returns the empty address. I'll see if i can report on this then at least it gives you and idea of whats wrong.

clarknova

No CARP here. I haven't updated or rebooted since starting this thread, but I will post here next time I do.

clarknova

2.0-RC1 (amd64)
built on Sat Mar 26 00:18:39 EDT 2011
Unbound 1.4.8_131

Everything appears fine after the reboot. This is in the log once:


php: : The command '/usr/local/sbin/unbound-control start' returned exit code '1', the output was '[1301386064] unbound[32002:0] error: bind: address already in use [1301386064] unbound[32002:0] fatal error: could not open ports'

but no other symptoms present.

clarknova

2.0-RC1 (amd64)
built on Wed Apr 6 21:25:25 EDT 2011
Unbound 1.4.8_131

I just updated pfsense to the latest snap and Unbound did not start (even after several hours of me not noticing!). When I clicked on the "Unbound DNS Status" page it would not load, and I don't know where to look for the config file (I'm too sleep-deprived to find it), so I just hit the save button on the main config page and Unbound then started. The system log page shows "php: : The command '/usr/local/sbin/unbound-control start' returned exit code '1', the output was '[1302158617] unbound[45448:0] error: bind: address already in use [1302158617] unbound[45448:0] fatal error: could not open ports'" a few times right after reboot, and then nothing apparently related.

Sorry, not much useful information here.

clarknova

I rebooted pfsense twice in the past 30 minutes and this happened again once. The other time it came up fine.

wagonza

Hrmmm…I have noticed this as well on at least two separate occasions. I have some additional (advanced) features added but will add this to the bug list to check out before I commit the latest features. Thanks for the feedback.

ToxIcon

wagonza is one of the additional (advanced) features going to be DNSSEC encryption

wagonza

@ToxIcon:

wagonza is one of the additional (advanced) features going to be DNSSEC encryption

By encryption I assume you mean you want the contents of the DNS packets encrypted? DNSSEC's aim is to ensure the authenticity of the record i.e unbound will use the public key to authenticate whether the RRSet that it receives is authorized. This is obviously already in the package.

I think you may want to look at DNSCurve which provides encryption of DNS packets.

The advanced features are more related optimization and fine tuning features for Unbound, which are mainly aimed for larger/busy installs.

iFloris

Since yesterday evening something changed in my installation of unbound.

I've been getting a lot of the following:```
php[2147483647] /pkg_edit.php: The command '/usr/local/sbin/unbound-control start' returned exit code '1', the output was '[1309508768] unbound[21850:0] error: can't bind socket: Can't assign requested address [1309508768] unbound[21850:0] debug: failed address 2001:470:snip:snip::1 port 53 [1309508768] unbound[21850:0] fatal error: could not open ports'


Those errors only show when I have the lan interface selected to query from.
Using either wan or wan-v6 I see the following:

php[2147483647] : The command '/usr/local/sbin/unbound-control dump_cache > /var/tmp/unbound_cache' returned exit code '1', the output was ''


What could be wrong?
Is there something that I have set up incorrectly?

Edit 19-07:

Sorry to bump an old thread, but there might be something new here.
I've been doing some additional digging while running the default dns forwarder while unbound was out of order.
After setting unbound's logging level to the maximum I found some interesting errors in /var/log/unbound.log.

Jul 19 18:27:32 firebox1 unbound: [58109:0] debug: setup SSL certificates
Jul 19 18:27:32 firebox1 unbound: [58109:0] warning: did not exit gracefully last time (33360)
Jul 19 18:27:32 firebox1 unbound: [58380:0] debug: chdir to /usr/local/etc/unbound
Jul 19 18:27:32 firebox1 unbound: [58380:0] debug: drop user privileges, run as unbound
Jul 19 18:27:32 firebox1 unbound: [58380:0] error: error parsing local-data 'www.facebook.com IN A 2620:0:1cfe:face:b00c::3': Syntax error, could not parse the RR's rdata
Jul 19 18:27:32 firebox1 unbound: [58380:0] error: Bad local-data RR www.facebook.com IN A 2620:0:1cfe:face:b00c::3
Jul 19 18:27:32 firebox1 unbound: [58380:0] fatal error: Could not set up local zones
Jul 19 18:29:11 firebox1 unbound: [42872:0] debug: setup SSL certificates
Jul 19 18:29:11 firebox1 unbound: [42872:0] warning: did not exit gracefully last time (58380)
Jul 19 18:29:11 firebox1 unbound: [43007:0] debug: chdir to /usr/local/etc/unbound
Jul 19 18:29:11 firebox1 unbound: [43007:0] debug: drop user privileges, run as unbound
Jul 19 18:29:11 firebox1 unbound: [43007:0] error: error parsing local-data 'firebox1.domain IN A 2001:470:xxxx:xxx::1': Syntax error, could not parse the RR's rdata
Jul 19 18:29:11 firebox1 unbound: [43007:0] error: Bad local-data RR firebox1.domain IN A 2001:470:xxxx:xxx::1
Jul 19 18:29:11 firebox1 unbound: [43007:0] fatal error: Could not set up local zones

Etcetera.

In dnsforwarder I've made some edits to always forward the dns request for my pfsense installation to the v6 address as well as always using the v6 facebook.
I've also added numerous other dns overrides to have clients use v6.
It seems that unbound /really/ doesn't like those addresses.

What do you guys think?

Is there a different (right?) way of doing this?
Would removing all of my overrides help?

Update 01-08:

I've removed all my v6 overrides in dns forwarder and unbound now successfully starts up.

wagonza

@iFloris:

Jul 19 18:29:11 firebox1 unbound: [43007:0] error: error parsing local-data 'firebox1.domain IN A 2001:470:xxxx:xxx::1': Syntax error, could not parse the RR's rdata
Jul 19 18:29:11 firebox1 unbound: [43007:0] error: Bad local-data RR firebox1.domain IN A 2001:470:xxxx:xxx::1

In dnsforwarder I've made some edits to always forward the dns request for my pfsense installation to the v6 address as well as always using the v6 facebook.
I've also added numerous other dns overrides to have clients use v6.
It seems that unbound /really/ doesn't like those addresses.

For v6 RR's it should be "IN AAAA". Ive just committed a fix - so reinstall the package and you can add your v6 host entries back.

iFloris

Thanks a lot!

wagonza

Cool - all working for you?

iFloris

Unfortunately, not everything is working as I imagine it should.
I've been getting errors about ssl handshakes and was only able to get unbound up and running after enabling forwarding mode and removing the testing v6 dns overrides.

php: /pkg_edit.php: The command '/usr/local/sbin/unbound-control load_cache < /var/tmp/unbound_cache' returned exit code '1', the output was '[1313843955] unbound-control[44879:0] debug: address 127.0.0.1 port 953 [1313843955] unbound-control[44879:0] error: connect: Operation timed out'
php: /pkg_edit.php: The command '/usr/local/sbin/unbound-control forward ' returned exit code '1', the output was 'error: SSL handshake failed'
php: /pkg_edit.php: The command '/usr/local/sbin/unbound-control start' returned exit code '1', the output was '[1313843873] unbound[44392:0] debug: creating udp4 socket xxx.xxx.xxx.xxx 53 [1313843873] unbound[44392:0] error: bind: address already in use [1313843873] unbound[44392:0] fatal error: could not open ports'

I am not entirely sure what is happening here.

wagonza

@iFloris:

Unfortunately, not everything is working as I imagine it should.
I've been getting errors about ssl handshakes and was only able to get unbound up and running after enabling forwarding mode and removing the testing v6 dns overrides.

php: /pkg_edit.php: The command '/usr/local/sbin/unbound-control load_cache < /var/tmp/unbound_cache' returned exit code '1', the output was '[1313843955] unbound-control[44879:0] debug: address 127.0.0.1 port 953 [1313843955] unbound-control[44879:0] error: connect: Operation timed out'
php: /pkg_edit.php: The command '/usr/local/sbin/unbound-control forward ' returned exit code '1', the output was 'error: SSL handshake failed'
php: /pkg_edit.php: The command '/usr/local/sbin/unbound-control start' returned exit code '1', the output was '[1313843873] unbound[44392:0] debug: creating udp4 socket xxx.xxx.xxx.xxx 53 [1313843873] unbound[44392:0] error: bind: address already in use [1313843873] unbound[44392:0] fatal error: could not open ports'

I am not entirely sure what is happening here.

The ssl handshake problem is related to the first error where Unbound could not connect to the local remote control.
Im investigating…

wagonza

ok all fixed - reinstall. Also fixed some other startup errors.

iFloris

Sorry wagonza, but unbound still doesn't fully work for me.

Unbound is reporting the following error over and over again:```
php[2147483647] : The command '/usr/local/sbin/unbound-control forward ' returned exit code '1', the output was '[1314033304] unbound-control[45855:0] debug: address 127.0.0.1 port 953 [1314033304] unbound-control[45855:0] error: connect: Operation timed out'


Also, when clicking save in the webconfigurator, everything php-related seems to lock up for a while.
Ssh still works.
After a while, the webconfigurator starts working again and I see the following line in the syslog:```
kernel: pid 62904 (php), uid 0: exited on signal 11 (core dumped)

Removing the testing v6 redirects helps unbound start again.

wagonza

You did reinstall the package right?

iFloris

To be certain I just reinstalled Unbound again, although I think I did.
When I have v6 overrides in dns forwarder, unbound fails to start without error messages.
It's not a big deal, as the v6 overrides are merely out of curiosity and to drive global v6 traffic a bit higher.

wagonza

Hrmm odd if i add a v6 override, for example:

v6 google.com 2800:3f0:XXX:XXX::1014

And restart unbound it is fine.
Do me a favour please, log in via ssh and execute a unbound-checkconf - it should return "unbound-checkconf: no errors in /usr/local/etc/unbound/unbound.conf"

iFloris

Unbound gives me a no errors reply, just as you said it should. I'll try and enable my testing v6 forwards one by one to see if there is a specific scenario which causes unbound to stop working. Thanks for your help so far!

wagonza

@iFloris:

Unbound gives me a no errors reply, just as you said it should. I'll try and enable my testing v6 forwards one by one to see if there is a specific scenario which causes unbound to stop working. Thanks for your help so far!

Have you managed to test the v6 forwards?

iFloris

Hello Wagonza,

Unbound still gives me errors in the log but works with the forwards.
Adding the forwards one by one and reloading unbound in the ssh-console has helped unbound start properly.

Thanks for all your help!

wagonza

@iFloris:

Hello Wagonza,

Unbound still gives me errors in the log but works with the forwards.
Adding the forwards one by one and reloading unbound in the ssh-console has helped unbound start properly.

Thanks for all your help!

What error did you see in the logs, the same timeout one? Can you do me a favour please and pm me the xml of the unbound section of your config.xml?

Thanks

iFloris

The very same. I will send you the unbound section(s) of my config.xml.

Edit: Sent.

wagonza

Thanks, got it - will go through it a little later and let you know.

wagonza

Problem sorted with host over rides that have empty host values. So just reinstall the package. Otherwise any other problems, please open up a new thread.

iFloris

Having set some v6 forwards yesterday, I can confirm that the new fixes work as expected.
Thanks a lot wagonza!

wagonza

wicked! Only v6 ACLs now left…

johnpoz

Sweet!! ipv6 ACLs are NEXT ;)

wagonza

Finally committed support for IPv6 acls :P I have also updated the package to latest Unbound version 1.4.13. So give it a couple of hours while the package builder is building the new port.

johnpoz

Sweet! Can remove them from my custom options section, which is how I have been adding them now.

See it listed already, installing now

Looks like you forgot a _ in the allow_snoop

php: /unbound_acls.php: The command '/usr/local/sbin/unbound-control start' returned exit code '1', the output was '/usr/local/etc/unbound/unbound.conf:67: error: unknown keyword 'snoop' /usr/local/etc/unbound/unbound.conf:68: error: unknown keyword 'snoop' /usr/local/etc/unbound/unbound.conf:69: error: unknown keyword 'snoop' /usr/local/etc/unbound/unbound.conf:70: error: unknown keyword 'snoop' read /usr/local/etc/unbound/unbound.conf failed: 4 errors in configuration file [1317328224] unbound[30144:0] fatal error: Could not read config file: /usr/local/etc/unbound/unbound.conf'

So I have an ACL that allows snoop, but in the .conf file its put in as "allow snoop" which killed my unbound now it can not start. Trying to manually edit the ubound.conf now so I can get unbound to start.

wagonza

Cool let me know if you get any problems.

johnpoz

just edited my last post – looks like a problem ;)

wagonza

bah! and i did test that specifically. hang 5.

johnpoz

ok changed to allow vs allow snoop and looks good

from conf file
#allow
access-control: 192.168.1.0/24 allow
access-control: 10.0.200.0/24 allow
access-control: 127.0.0.0/8 allow
access-control: 2001:470:1f11:b85:0:0:0:0/64 allow

changed it to allow snoop in dropdown and get this.

access-control: 192.168.1.0/24 allow snoop
access-control: 10.0.200.0/24 allow snoop
access-control: 127.0.0.0/8 allow snoop
access-control: 2001:470:1f11:b85:0:0:0:0/64 allow snoop

missing the _ looks like to me.

wagonza

Yeah 100% correct - fixed. So just update.

johnpoz

Sweet thanks!! Looks like same build number, just reinstall or will you be pushing say 1.4.13_01

wagonza

Nah same build number - I didnt increase the version number for this change.