DNS Resolver

cmb

Today with build Fri Nov 21 01:58:53 CST 2014 I'm getting again 'fatal error: Could not read config file: /unbound.conf' with DHCP Registration checked.

Can't seem to replicate that. How is your Unbound configured?

hiwi

@cmb:

@hiwi:

Today with build Fri Nov 21 01:58:53 CST 2014 I'm getting again 'fatal error: Could not read config file: /unbound.conf' with DHCP Registration checked.

Can't seem to replicate that. How is your Unbound configured?

What information do you need?

Hugovsky

To me, it gives the error attached if I try to start resolver with "Register DHCP leases in the DNS Resolver" set.

2.2-BETA (amd64)
built on Fri Nov 21 08:16:06 CST 2014
FreeBSD 10.1-RELEASE

system.jpg_thumb

hiwi

@cmb:

@hiwi:

Today with build Fri Nov 21 01:58:53 CST 2014 I'm getting again 'fatal error: Could not read config file: /unbound.conf' with DHCP Registration checked.

Can't seem to replicate that. How is your Unbound configured?

With version '2.2-BETA (amd64) built on Fri Nov 21 08:16:06 CST 2014' unbound started directly after upgrade. After another reboot it didn't start with DHCP Registration ('Register DHCP leases in the DNS Resolver') on.

cmb

What's in your resolver log? Re: config, how are all the settings under Services>DNS Resolver configured?

hiwi

resolver.log

Nov 21 23:04:26	unbound: [6842:0] fatal error: Could not read config file: /unbound.conf
Nov 21 23:04:26	unbound: [6842:0] info: ignored infra-lame-ttl: 900 (option removed, use infra-host-ttl)
Nov 21 23:04:26	unbound: [6842:0] notice: Restart of unbound 1.4.22.
Nov 21 23:04:26	unbound: [6842:0] debug: cache memory msg=66072 rrset=66072 infra=2600 val=66280
Nov 21 23:04:26	unbound: [6842:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
Nov 21 23:04:26	unbound: [6842:0] info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
Nov 21 23:04:26	unbound: [6842:0] info: server stats for thread 1: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch
Nov 21 23:04:26	unbound: [6842:0] debug: cache memory msg=66072 rrset=66072 infra=2600 val=66280
Nov 21 23:04:26	unbound: [6842:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
Nov 21 23:04:26	unbound: [6842:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
Nov 21 23:04:26	unbound: [6842:0] info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch
Nov 21 23:04:26	unbound: [6842:0] info: service stopped (unbound 1.4.22).
Nov 21 23:04:26	unbound: [6842:0] debug: caught signal SIGHUP
Nov 21 23:04:26	unbound: [6842:1] debug: cache memory msg=66072 rrset=66072 infra=2600 val=66280
Nov 21 23:04:26	unbound: [6842:0] info: start of service (unbound 1.4.22).
Nov 21 23:04:26	unbound: [6842:0] debug: cache memory msg=66072 rrset=66072 infra=2600 val=66280
Nov 21 23:04:26	unbound: [6842:0] debug: target fetch policy for level 4 is 0
Nov 21 23:04:26	unbound: [6842:0] debug: target fetch policy for level 3 is 0
Nov 21 23:04:26	unbound: [6842:0] debug: target fetch policy for level 2 is 1
Nov 21 23:04:26	unbound: [6842:0] debug: target fetch policy for level 1 is 2
Nov 21 23:04:26	unbound: [6842:0] debug: target fetch policy for level 0 is 3
Nov 21 23:04:26	unbound: [6842:0] notice: init module 1: iterator
Nov 21 23:04:26	unbound: [6842:0] notice: init module 0: validator
Nov 21 23:04:26	unbound: [6842:0] debug: module config: "validator iterator"
Nov 21 23:04:26	unbound: [6842:0] debug: duplicate acl address ignored.
Nov 21 23:04:26	unbound: [6842:0] debug: drop user privileges, run as unbound
Nov 21 23:04:26	unbound: [6842:0] debug: chroot to /var/unbound
Nov 21 23:04:26	unbound: [6842:0] debug: chdir to /var/unbound
Nov 21 23:04:25	unbound: [87880:0] debug: switching log to stderr
Nov 21 23:04:25	unbound: [87880:0] debug: cache memory msg=66072 rrset=66072 infra=288782 val=149925
Nov 21 23:04:25	unbound: [87880:0] info: 1.000000 2.000000 7
Nov 21 23:04:25	unbound: [87880:0] info: 0.524288 1.000000 21
Nov 21 23:04:25	unbound: [87880:0] info: 0.262144 0.524288 62
Nov 21 23:04:25	unbound: [87880:0] info: 0.131072 0.262144 100
Nov 21 23:04:25	unbound: [87880:0] info: 0.065536 0.131072 50
Nov 21 23:04:25	unbound: [87880:0] info: 0.032768 0.065536 83
Nov 21 23:04:25	unbound: [87880:0] info: 0.016384 0.032768 176
Nov 21 23:04:25	unbound: [87880:0] info: 0.008192 0.016384 27
Nov 21 23:04:25	unbound: [87880:0] info: 0.004096 0.008192 1
Nov 21 23:04:25	unbound: [87880:0] info: 0.000000 0.000001 37
Nov 21 23:04:25	unbound: [87880:0] info: lower(secs) upper(secs) recursions
Nov 21 23:04:25	unbound: [87880:0] info: [25%]=0.0234589 median[50%]=0.0489546 [75%]=0.195297
Nov 21 23:04:25	unbound: [87880:0] info: histogram of recursion processing times
Nov 21 23:04:25	unbound: [87880:0] info: average recursion processing time 0.139959 sec
Nov 21 23:04:25	unbound: [87880:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 564 recursion replies sent, 0 replies dropped, 0 states jostled out
Nov 21 23:04:25	unbound: [87880:0] info: server stats for thread 1: requestlist max 14 avg 0.603774 exceeded 0 jostled 0
Nov 21 23:04:25	unbound: [87880:0] info: server stats for thread 1: 1688 queries, 1124 answers from cache, 564 recursions, 178 prefetch
Nov 21 23:04:25	unbound: [87880:0] debug: cache memory msg=66072 rrset=66072 infra=288782 val=149925
Nov 21 23:04:25	unbound: [87880:0] info: 1.000000 2.000000 1
Nov 21 23:04:25	unbound: [87880:0] info: 0.524288 1.000000 14
Nov 21 23:04:25	unbound: [87880:0] info: 0.262144 0.524288 30
Nov 21 23:04:25	unbound: [87880:0] info: 0.131072 0.262144 42
Nov 21 23:04:25	unbound: [87880:0] info: 0.065536 0.131072 28
Nov 21 23:04:25	unbound: [87880:0] info: 0.032768 0.065536 39
Nov 21 23:04:25	unbound: [87880:0] info: 0.016384 0.032768 52
Nov 21 23:04:25	unbound: [87880:0] info: 0.008192 0.016384 13
Nov 21 23:04:25	unbound: [87880:0] info: 0.004096 0.008192 1
Nov 21 23:04:25	unbound: [87880:0] info: 0.000000 0.000001 18
Nov 21 23:04:25	unbound: [87880:0] info: lower(secs) upper(secs) recursions
Nov 21 23:04:25	unbound: [87880:0] info: [25%]=0.0250486 median[50%]=0.0621752 [75%]=0.216893
Nov 21 23:04:25	unbound: [87880:0] info: histogram of recursion processing times
Nov 21 23:04:25	unbound: [87880:0] info: average recursion processing time 0.147787 sec
Nov 21 23:04:25	unbound: [87880:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 238 recursion replies sent, 0 replies dropped, 0 states jostled out
Nov 21 23:04:25	unbound: [87880:0] info: server stats for thread 0: requestlist max 40 avg 3.168 exceeded 0 jostled 0
Nov 21 23:04:25	unbound: [87880:0] info: server stats for thread 0: 548 queries, 310 answers from cache, 238 recursions, 12 prefetch
Nov 21 23:04:25	unbound: [87880:0] info: service stopped (unbound 1.4.22).
Nov 21 23:04:25	unbound: [87880:0] debug: caught signal SIGTERM
Nov 21 23:04:23	unbound: [87880:1] debug: cache memory msg=418824 rrset=714129 infra=288782 val=149925
Nov 21 23:04:23	unbound: [87880:1] info: validator operate: query cl4appf.com. A IN
Nov 21 23:04:23	unbound: [87880:1] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone
Nov 21 23:04:23	unbound: [87880:1] info: finishing processing for cl4appf.com. A IN
Nov 21 23:04:23	unbound: [87880:1] info: query response was ANSWER
Nov 21 23:04:23	unbound: [87880:1] info: reply from <cl4appf.com.> 78.140.168.56#53
Nov 21 23:04:23	unbound: [87880:1] info: response for cl4appf.com. A IN
Nov 21 23:04:23	unbound: [87880:1] info: sanitize: storing potential poison RRset: ns2.dcrmt.net. A IN
Nov 21 23:04:23	unbound: [87880:1] info: sanitize: storing potential poison RRset: ns1.dcrmt.net. A IN
Nov 21 23:04:23	unbound: [87880:1] info: iterator operate: query cl4appf.com. A IN
Nov 21 23:04:23	unbound: [87880:1] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
Nov 21 23:04:23	unbound: [87880:1] debug: cache memory msg=418824 rrset=714129 infra=288782 val=149925
Nov 21 23:04:23	unbound: [87880:1] info: Verified that unsigned response is INSECURE
Nov 21 23:04:23	unbound: [87880:1] info: validator operate: query cl4appf.com. AAAA IN
Nov 21 23:04:23	unbound: [87880:1] debug: validator[module 0] operate: extstate:module_wait_subquery event:module_event_pass
Nov 21 23:04:23	unbound: [87880:1] info: NSEC3s for the referral proved no DS.
Nov 21 23:04:23	unbound: [87880:1] info: validator operate: query cl4appf.com. DS IN
Nov 21 23:04:23	unbound: [87880:1] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone
Nov 21 23:04:23	unbound: [87880:1] info: finishing processing for cl4appf.com. DS IN
Nov 21 23:04:23	unbound: [87880:1] info: query response was nodata ANSWER
Nov 21 23:04:23	unbound: [87880:1] info: reply from <com.> 2001:503:a83e::2:30#53
Nov 21 23:04:23	unbound: [87880:1] info: response for cl4appf.com. DS IN
Nov 21 23:04:23	unbound: [87880:1] info: iterator operate: query cl4appf.com. DS IN
Nov 21 23:04:23	unbound: [87880:1] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
Nov 21 23:04:23	unbound: [87880:1] debug: cache memory msg=418824 rrset=714129 infra=288782 val=149925
Nov 21 23:04:23	unbound: [87880:1] debug: sending to target: <com.> 2001:503:a83e::2:30#53
Nov 21 23:04:23	unbound: [87880:1] info: sending query: cl4appf.com. DS IN
Nov 21 23:04:23	unbound: [87880:1] info: processQueryTargets: cl4appf.com. DS IN
Nov 21 23:04:23	unbound: [87880:1] info: resolving (init part 3): cl4appf.com. DS IN
Nov 21 23:04:23	unbound: [87880:1] info: resolving (init part 2): cl4appf.com. DS IN
Nov 21 23:04:23	unbound: [87880:1] info: resolving cl4appf.com. DS IN
Nov 21 23:04:23	unbound: [87880:1] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass
Nov 21 23:04:23	unbound: [87880:1] info: validator operate: query cl4appf.com. DS IN</com.></com.></cl4appf.com.>

system.log

Nov 21 23:04:26 zh01-rt02 dhcpleases: Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.
Nov 21 23:04:27 zh01-rt02 dhcpleases: Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.
Nov 21 23:04:29 zh01-rt02 dhcpleases: Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.
Nov 21 23:04:29 zh01-rt02 dhcpleases: kqueue error: unkown
Nov 21 23:04:29 zh01-rt02 dhcpleases: Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.

Image with options is attached.

![Screenshot 2014-11-21 23.10.46.gif](/public/imported_attachments/1/Screenshot 2014-11-21 23.10.46.gif)
![Screenshot 2014-11-21 23.10.46.gif_thumb](/public/imported_attachments/1/Screenshot 2014-11-21 23.10.46.gif_thumb)

DiskWizard

2.2-BETA (amd64)
built on Sat Nov 22 01:52:19 CST 2014
FreeBSD 10.1-RELEASE

After today's upgrade Resolver "went to sleep", had to switch for DNS Forwarder.

Oct 28 14:12:42 unbound: [23277:3] notice: sendto failed: No buffer space available

I know, the date is wrong.

cmb

@hiwi:

Today with build Fri Nov 21 01:58:53 CST 2014 I'm getting again 'fatal error: Could not read config file: /unbound.conf' with DHCP Registration checked.

That seems to be fixed after merging a pull request from wagonza yesterday. I found one system where I could replicate that, and after that change, I no longer could. There is a bug ticket on that issue. https://redmine.pfsense.org/issues/4036

Others who could replicate that, are you seeing it on snapshots from the 23rd or newer?

hiwi

@cmb:

That seems to be fixed after merging a pull request from wagonza yesterday. I found one system where I could replicate that, and after that change, I no longer could. There is a bug ticket on that issue. https://redmine.pfsense.org/issues/4036

Others who could replicate that, are you seeing it on snapshots from the 23rd or newer?

The latest snapshot I can get is 'Sat Nov 22 01:52:19 CST 2014'.

hiwi

@cmb:

That seems to be fixed after merging a pull request from wagonza yesterday. I found one system where I could replicate that, and after that change, I no longer could. There is a bug ticket on that issue. https://redmine.pfsense.org/issues/4036

Others who could replicate that, are you seeing it on snapshots from the 23rd or newer?

With snapshot 'Mon Nov 24 02:33:34 CST 2014' my unbound problem is gone.

Thank You!

Hugovsky

Seems solved. It starts normally now.

2.2-BETA (amd64)
built on Mon Nov 24 02:33:34 CST 2014
FreeBSD 10.1-RELEASE

Hugovsky

well…. spoke to soon. Can't enable "Register DHCP leases in the DNS Resolver". It refuses to start again.

2.2-BETA (amd64)
built on Tue Nov 25 11:18:23 CST 2014
FreeBSD 10.1-RELEASE

cmb

@Hugovsky:

well…. spoke to soon. Can't enable "Register DHCP leases in the DNS Resolver". It refuses to start again.

and logs what?

Hugovsky

ups… sorry about that. There you go..

System log:

Nov 25 20:27:40 dhcpleases: Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.
Nov 25 20:27:40 dhcpleases: kqueue error: unkown
Nov 25 20:27:40 dhcpleases: Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.
Nov 25 20:27:39 dhcpleases: Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.

Unbound log:

Nov 25 20:29:40 unbound: [93575:0] fatal error: Could not read config file: /unbound.conf
Nov 25 20:29:40 unbound: [93575:0] notice: Restart of unbound 1.4.22.
Nov 25 20:29:40 unbound: [93575:0] info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
Nov 25 20:29:40 unbound: [93575:0] info: server stats for thread 1: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch
Nov 25 20:29:40 unbound: [93575:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
Nov 25 20:29:40 unbound: [93575:0] info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch
Nov 25 20:29:40 unbound: [93575:0] info: service stopped (unbound 1.4.22).
Nov 25 20:29:40 unbound: [93575:0] info: start of service (unbound 1.4.22).
Nov 25 20:29:40 unbound: [93575:0] notice: init module 1: iterator
Nov 25 20:29:40 unbound: [93575:0] notice: init module 0: validator

BUT, this is only try if I put includes in advanced config. With default config, I can start resolver with "Register DHCP leases in the DNS Resolver" set.

cmb

@Hugovsky:

BUT, this is only try if I put includes in advanced config. With default config, I can start resolver with "Register DHCP leases in the DNS Resolver" set.

Seems you're putting something invalid in there.

Hugovsky

@cmb:

@Hugovsky:

BUT, this is only try if I put includes in advanced config. With default config, I can start resolver with "Register DHCP leases in the DNS Resolver" set.

Seems you're putting something invalid in there.

server:
include: /conf/local-blocking-data.conf

MikeV7896

I just set up a new 2.2 installation… unbound appears to be running, but these entries appear in the log whenever the service is started. I do have the options to register DHCP leases and static DHCP entries checked.

Nov 25 19:15:29 unbound: [88622:0] error: cannot parse netblock: '/'
Nov 25 19:15:29 unbound: [88622:0] error: cannot parse access control: / allow
Nov 25 19:15:29 unbound: [88622:0] fatal error: Could not setup access control list

Also, the service IS running, but the Status > Services page shows it as stopped.

EDIT: Nope… it's not running. My computer is using the Google IPv6 DNS servers I put into pfSense, not the local resolver. I guess there's no way to have the router specify its own IPv6 address (even if it's link-local) for DNS to DHCP clients? I only know it's not running because my IP phone - which only supports IPv4 - can't resolve my VoIP provider hostname, and the only DNS server it has is the IPv4 LAN address of my box.

This appears to be caused by the fact that I'm not requesting an IPv6 address on my WAN interface, just a prefix. Since there's no address, there's nothing to put in the access_lists.conf file, resulting in a access-control: / allow line.

Bug 4046 created for this…

cmb

@virgiliomi:

This appears to be caused by the fact that I'm not requesting an IPv6 address on my WAN interface, just a prefix. Since there's no address, there's nothing to put in the access_lists.conf file, resulting in a access-control: / allow line.

Pretty sure you have to be running an old version, that was fixed over a week ago.

MikeV7896

@cmb:

@virgiliomi:

This appears to be caused by the fact that I'm not requesting an IPv6 address on my WAN interface, just a prefix. Since there's no address, there's nothing to put in the access_lists.conf file, resulting in a access-control: / allow line.

Pretty sure you have to be running an old version, that was fixed over a week ago.

2.2-BETA (amd64)
built on Tue Nov 25 11:18:23 CST 2014

MikeV7896

I updated to the latest snapshot as of this morning (built on Thu Nov 27 00:15:05 CST 2014) and the above issue seems to be resolved. Now I run into something else. My computer (Win7) has both the IPv6 and v4 addresses of my box as DNS servers. When I try to do nslookup, it appears that unbound is refusing queries to the IPv6 address, while queries via IPv4 go through no problem.

> [internal hostname]
Server:  UnKnown
Address:  2601:8:a00:xxx:xxx:xxx:xxx:xxx

*** UnKnown can't find [internal hostname]: Query refused

> [external hostname]
Server:  UnKnown
Address:  2601:8:a00:xxx:xxx:xxx:xxx:xxx

*** UnKnown can't find [external hostname]: Query refused

> server 192.168.1.1
Default Server:  [192.168.1.1]
Address:  192.168.1.1

> [internal hostname]
Server:  [192.168.1.1]
Address:  192.168.1.1

Name:    [internal hostname]
Address:  192.168.1.108

> [external hostname]
Server:  [192.168.1.1]
Address:  192.168.1.1

Non-authoritative answer:
Name:    [external hostname]
Addresses:  [ip addresses]