DNS Resolver

phil.davis · Nov 29, 2014, 2:42 AM

@mattbunce - have a read of this thread: https://forum.pfsense.org/index.php?topic=84184.0
Perhaps now the unbound requests are going out with source IP as the VPN tunnel local end-point, and the DNS server at 10.30.1.1 does not have a route back to that?
In DNS Forwarder (dnsmasq) you might have been using the "Source IP" field in the Domain Overrides settings to help this. But that field no longer exists for DNS Resolver (unbound).

Edit: add: Your client will be adding anything in its DNS suffix searchlist automatically, thus tryin server.vpn.local as well as server.vpn
Put the terminating "." at the end of the name to stop that;

nslookup server.vpn.

MikeV7896 · Nov 29, 2014, 4:48 AM

So Unbound seems to have an issue where it restarts about every 70 minutes. Unfortunately I turned down the log verbosity because it was generating a massive amount of data even at level 1. So all I have are the start/stop entries. But here's a bit of the log…

Nov 28 00:41:25	unbound: [18673:0] info: service stopped (unbound 1.4.22).
Nov 28 00:41:25	unbound: [18673:0] info: start of service (unbound 1.4.22).
Nov 28 01:50:49	unbound: [18673:0] info: service stopped (unbound 1.4.22).
Nov 28 01:50:49	unbound: [18673:0] info: start of service (unbound 1.4.22).
Nov 28 03:00:08	unbound: [18673:0] info: service stopped (unbound 1.4.22).
Nov 28 03:00:08	unbound: [18673:0] info: start of service (unbound 1.4.22).
Nov 28 04:09:24	unbound: [18673:0] info: service stopped (unbound 1.4.22).
Nov 28 04:09:24	unbound: [18673:0] info: start of service (unbound 1.4.22).
Nov 28 05:18:43	unbound: [18673:0] info: service stopped (unbound 1.4.22).
Nov 28 05:18:43	unbound: [18673:0] info: start of service (unbound 1.4.22).
Nov 28 06:23:57	unbound: [18673:0] info: service stopped (unbound 1.4.22).
Nov 28 06:23:57	unbound: [18673:0] info: start of service (unbound 1.4.22).

I'll turn the verbosity back up and see if it provides any further enlightenment tomorrow… but given how much data it puts in that log file, it might be a bit harder to tell.

mattbunce · Nov 29, 2014, 11:21 AM

Hi, thanks for your help, reading that did lead me to something else… I'm not entirely sure what the "source IP" box was under DNS Forwarder, but I don't think I was using it. The only change I ever made was adding a couple of domains to the "DNS overrides" section.

I have realised a big error on my part though, I had set DNS Resolver to only use WAN, so without access to the VPN it could never send the request to the other server - Whoops!

So now I am getting a result, but it is slow, since the query is also being sent to my main WAN DNS servers, you can see this in the log below.

It seems strange that DNS resolver has identified this as a query that should be sent via the VPN, but it still sends it to the main DNS servers?


NOTE: MOST RECENT ENTRIES AT TOP

01/11/2029 11:12	unbound: [47949:0] debug: cache memory msg=67178 rrset=67824 infra=3600 val=0
01/11/2029 11:12	unbound: [47949:0] debug: sending to target: <vpn.>10.30.1.1#53
01/11/2029 11:12	unbound: [47949:0] info: sending query: server.vpn. AAAA IN
01/11/2029 11:12	unbound: [47949:0] info: processQueryTargets: server.vpn. AAAA IN
01/11/2029 11:12	unbound: [47949:0] info: iterator operate: query server.vpn. AAAA IN
01/11/2029 11:12	unbound: [47949:0] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_noreply
01/11/2029 11:12	unbound: [47949:0] debug: cache memory msg=67178 rrset=67824 infra=3600 val=0
01/11/2029 11:12	unbound: [47949:0] debug: sending to target: <vpn.>10.30.1.1#53
01/11/2029 11:12	unbound: [47949:0] info: sending query: server.vpn. AAAA IN
01/11/2029 11:12	unbound: [47949:0] info: processQueryTargets: server.vpn. AAAA IN
01/11/2029 11:12	unbound: [47949:0] info: iterator operate: query server.vpn. AAAA IN
01/11/2029 11:12	unbound: [47949:0] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_noreply
01/11/2029 11:12	unbound: [47949:0] debug: cache memory msg=67178 rrset=67824 infra=3600 val=0
01/11/2029 11:12	unbound: [47949:0] debug: sending to target: <vpn.>10.30.1.1#53
01/11/2029 11:12	unbound: [47949:0] info: sending query: server.vpn. AAAA IN
01/11/2029 11:12	unbound: [47949:0] info: processQueryTargets: server.vpn. AAAA IN
01/11/2029 11:12	unbound: [47949:0] info: iterator operate: query server.vpn. AAAA IN
01/11/2029 11:12	unbound: [47949:0] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_noreply
01/11/2029 11:12	unbound: [47949:0] debug: cache memory msg=67178 rrset=67824 infra=3600 val=0
01/11/2029 11:12	unbound: [47949:0] debug: sending to target: <vpn.>10.30.1.1#53
01/11/2029 11:12	unbound: [47949:0] info: sending query: server.vpn. AAAA IN
01/11/2029 11:12	unbound: [47949:0] info: processQueryTargets: server.vpn. AAAA IN
01/11/2029 11:12	unbound: [47949:0] info: resolving (init part 3): server.vpn. AAAA IN
01/11/2029 11:12	unbound: [47949:0] info: use stub vpn. NS IN
01/11/2029 11:12	unbound: [47949:0] info: resolving (init part 2): server.vpn. AAAA IN
01/11/2029 11:12	unbound: [47949:0] info: use stub vpn. NS IN
01/11/2029 11:12	unbound: [47949:0] info: resolving server.vpn. AAAA IN
01/11/2029 11:12	unbound: [47949:0] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new
01/11/2029 11:12	unbound: [47949:0] debug: cache memory msg=67178 rrset=67824 infra=3600 val=0
01/11/2029 11:12	unbound: [47949:0] info: finishing processing for server.vpn. A IN
01/11/2029 11:12	unbound: [47949:0] info: query response was ANSWER
01/11/2029 11:12	unbound: [47949:0] info: reply from <vpn.>10.30.1.1#53
01/11/2029 11:12	unbound: [47949:0] info: response for server.vpn. A IN
01/11/2029 11:12	unbound: [47949:0] info: iterator operate: query server.vpn. A IN
01/11/2029 11:12	unbound: [47949:0] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_reply
01/11/2029 11:12	unbound: [47949:0] debug: cache memory msg=66990 rrset=67638 infra=3600 val=0
01/11/2029 11:12	unbound: [47949:0] debug: sending to target: <vpn.>10.30.1.1#53
01/11/2029 11:12	unbound: [47949:0] info: sending query: server.vpn. A IN
01/11/2029 11:12	unbound: [47949:0] info: processQueryTargets: server.vpn. A IN
01/11/2029 11:12	unbound: [47949:0] info: resolving (init part 3): server.vpn. A IN
01/11/2029 11:12	unbound: [47949:0] info: use stub vpn. NS IN
01/11/2029 11:12	unbound: [47949:0] info: resolving (init part 2): server.vpn. A IN
01/11/2029 11:12	unbound: [47949:0] info: use stub vpn. NS IN
01/11/2029 11:12	unbound: [47949:0] info: resolving server.vpn. A IN
01/11/2029 11:12	unbound: [47949:0] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new
01/11/2029 11:12	unbound: [47949:0] debug: cache memory msg=66990 rrset=67638 infra=3347 val=0
01/11/2029 11:12	unbound: [47949:0] info: finishing processing for server.vpn.local. AAAA IN
01/11/2029 11:12	unbound: [47949:0] info: query response was NXDOMAIN ANSWER
01/11/2029 11:12	unbound: [47949:0] info: reply from <.> 8.8.4.4#53
01/11/2029 11:12	unbound: [47949:0] info: response for server.vpn.local. AAAA IN
01/11/2029 11:12	unbound: [47949:0] info: iterator operate: query server.vpn.local. AAAA IN
01/11/2029 11:12	unbound: [47949:0] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_reply
01/11/2029 11:12	unbound: [47949:0] debug: cache memory msg=66749 rrset=67638 infra=3347 val=0
01/11/2029 11:12	unbound: [47949:0] debug: sending to target: <.> 8.8.4.4#53
01/11/2029 11:12	unbound: [47949:0] info: sending query: server.vpn.local. AAAA IN
01/11/2029 11:12	unbound: [47949:0] info: processQueryTargets: server.vpn.local. AAAA IN
01/11/2029 11:12	unbound: [47949:0] info: resolving server.vpn.local. AAAA IN
01/11/2029 11:12	unbound: [47949:0] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new
01/11/2029 11:12	unbound: [47949:1] debug: cache memory msg=66749 rrset=67638 infra=3347 val=0
01/11/2029 11:12	unbound: [47949:1] info: finishing processing for server.vpn.local. A IN
01/11/2029 11:12	unbound: [47949:1] info: query response was NXDOMAIN ANSWER
01/11/2029 11:12	unbound: [47949:1] info: reply from <.> 8.8.4.4#53
01/11/2029 11:12	unbound: [47949:1] info: response for server.vpn.local. A IN
01/11/2029 11:12	unbound: [47949:1] info: iterator operate: query server.vpn.local. A IN
01/11/2029 11:12	unbound: [47949:1] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_reply
01/11/2029 11:12	unbound: [47949:1] debug: cache memory msg=66508 rrset=66508 infra=3347 val=0
01/11/2029 11:12	unbound: [47949:1] debug: sending to target: <.> 8.8.4.4#53
01/11/2029 11:12	unbound: [47949:1] info: sending query: server.vpn.local. A IN
01/11/2029 11:12	unbound: [47949:1] info: processQueryTargets: server.vpn.local. A IN
01/11/2029 11:12	unbound: [47949:1] info: resolving server.vpn.local. A IN</vpn.></vpn.></vpn.></vpn.></vpn.></vpn.>

phil.davis · Nov 29, 2014, 11:51 AM

In the latest build,
2.2-BETA (i386)
built on Sat Nov 29 02:37:09 CST 2014
FreeBSD 10.1-RELEASE

There is a small coding logic error in /etc/inc.unbound.inc that can cause this PHP message:

Warning: in_array() expects parameter 2 to be array, null given in /etc/inc/unbound.inc on line 607

This code change fixes it: https://github.com/pfsense/pfsense/pull/1355

If you are on this build, and using DNS Resolver (unbound) then make this fix, or move up to a later build when that comes…

DiskWizard · Nov 29, 2014, 9:00 PM

Good day !
After today's update the main page fixed now.
What about Unbound. I went into the very same issue https://forum.pfsense.org/index.php?topic=84146.msg461519#msg461519

The fix people provided did the trick :)

P.S. Borat is happy now.

Thank you !

BTW I had to put Routing-Gateways to proper values !!!

MikeV7896 · Nov 30, 2014, 1:36 AM

Additional on the start/stop issue… A snippet of log from early this morning... this basically shows up every 60-70 minutes in the log. Doesn't appear to be anything indicating why the stop/start at log level 1.

Nov 29 03:15:33 unbound: [previous restart]
Nov 29 04:23:51	unbound: [3561:0] info: service stopped (unbound 1.4.22).
Nov 29 04:23:51	unbound: [3561:0] info: server stats for thread 0: 265 queries, 94 answers from cache, 171 recursions, 0 prefetch
Nov 29 04:23:51	unbound: [3561:0] info: server stats for thread 0: requestlist max 13 avg 1.24561 exceeded 0 jostled 0
Nov 29 04:23:51	unbound: [3561:0] info: average recursion processing time 0.087121 sec
Nov 29 04:23:51	unbound: [3561:0] info: histogram of recursion processing times
Nov 29 04:23:51	unbound: [3561:0] info: [25%]=0.0113869 median[50%]=0.034816 [75%]=0.109773
Nov 29 04:23:51	unbound: [3561:0] info: lower(secs) upper(secs) recursions
Nov 29 04:23:51	unbound: [3561:0] info: 0.000000 0.000001 33
Nov 29 04:23:51	unbound: [3561:0] info: 0.008192 0.016384 25
Nov 29 04:23:51	unbound: [3561:0] info: 0.016384 0.032768 26
Nov 29 04:23:51	unbound: [3561:0] info: 0.032768 0.065536 24
Nov 29 04:23:51	unbound: [3561:0] info: 0.065536 0.131072 30
Nov 29 04:23:51	unbound: [3561:0] info: 0.131072 0.262144 17
Nov 29 04:23:51	unbound: [3561:0] info: 0.262144 0.524288 13
Nov 29 04:23:51	unbound: [3561:0] info: 0.524288 1.000000 3
Nov 29 04:23:51	unbound: [3561:0] info: server stats for thread 1: 22 queries, 12 answers from cache, 10 recursions, 0 prefetch
Nov 29 04:23:51	unbound: [3561:0] info: server stats for thread 1: requestlist max 4 avg 0.4 exceeded 0 jostled 0
Nov 29 04:23:51	unbound: [3561:0] info: average recursion processing time 0.129809 sec
Nov 29 04:23:51	unbound: [3561:0] info: histogram of recursion processing times
Nov 29 04:23:51	unbound: [3561:0] info: [25%]=0.049152 median[50%]=0.131072 [75%]=0.212992
Nov 29 04:23:51	unbound: [3561:0] info: lower(secs) upper(secs) recursions
Nov 29 04:23:51	unbound: [3561:0] info: 0.008192 0.016384 1
Nov 29 04:23:51	unbound: [3561:0] info: 0.016384 0.032768 1
Nov 29 04:23:51	unbound: [3561:0] info: 0.032768 0.065536 1
Nov 29 04:23:51	unbound: [3561:0] info: 0.065536 0.131072 2
Nov 29 04:23:51	unbound: [3561:0] info: 0.131072 0.262144 4
Nov 29 04:23:51	unbound: [3561:0] info: 0.262144 0.524288 1
Nov 29 04:23:51	unbound: [3561:0] info: server stats for thread 2: 48 queries, 19 answers from cache, 29 recursions, 0 prefetch
Nov 29 04:23:51	unbound: [3561:0] info: server stats for thread 2: requestlist max 5 avg 0.172414 exceeded 0 jostled 0
Nov 29 04:23:51	unbound: [3561:0] info: average recursion processing time 0.126308 sec
Nov 29 04:23:51	unbound: [3561:0] info: histogram of recursion processing times
Nov 29 04:23:51	unbound: [3561:0] info: [25%]=0.03072 median[50%]=0.090112 [75%]=0.208896
Nov 29 04:23:51	unbound: [3561:0] info: lower(secs) upper(secs) recursions
Nov 29 04:23:51	unbound: [3561:0] info: 0.008192 0.016384 2
Nov 29 04:23:51	unbound: [3561:0] info: 0.016384 0.032768 6
Nov 29 04:23:51	unbound: [3561:0] info: 0.032768 0.065536 5
Nov 29 04:23:51	unbound: [3561:0] info: 0.065536 0.131072 4
Nov 29 04:23:51	unbound: [3561:0] info: 0.131072 0.262144 8
Nov 29 04:23:51	unbound: [3561:0] info: 0.262144 0.524288 4
Nov 29 04:23:51	unbound: [3561:0] info: server stats for thread 3: 199 queries, 77 answers from cache, 122 recursions, 0 prefetch
Nov 29 04:23:51	unbound: [3561:0] info: server stats for thread 3: requestlist max 17 avg 0.967213 exceeded 0 jostled 0
Nov 29 04:23:51	unbound: [3561:0] info: average recursion processing time 0.088529 sec
Nov 29 04:23:51	unbound: [3561:0] info: histogram of recursion processing times
Nov 29 04:23:51	unbound: [3561:0] info: [25%]=0.0191147 median[50%]=0.0521309 [75%]=0.112503
Nov 29 04:23:51	unbound: [3561:0] info: lower(secs) upper(secs) recursions
Nov 29 04:23:51	unbound: [3561:0] info: 0.000000 0.000001 16
Nov 29 04:23:51	unbound: [3561:0] info: 0.008192 0.016384 11
Nov 29 04:23:51	unbound: [3561:0] info: 0.016384 0.032768 21
Nov 29 04:23:51	unbound: [3561:0] info: 0.032768 0.065536 22
Nov 29 04:23:51	unbound: [3561:0] info: 0.065536 0.131072 30
Nov 29 04:23:51	unbound: [3561:0] info: 0.131072 0.262144 12
Nov 29 04:23:51	unbound: [3561:0] info: 0.262144 0.524288 9
Nov 29 04:23:51	unbound: [3561:0] info: 0.524288 1.000000 1
Nov 29 04:23:51	unbound: [3561:0] notice: Restart of unbound 1.4.22.
Nov 29 04:23:51	unbound: [3561:0] notice: init module 0: validator
Nov 29 04:23:51	unbound: [3561:0] notice: init module 1: iterator
Nov 29 04:23:51	unbound: [3561:0] info: start of service (unbound 1.4.22).
Nov 29 05:24:32 unbound: [next restart]

Is this to be expected for some reason? If so, what's the reason? Is it due to a setting I can turn off? I've been surfing when it happens and all of a sudden I get DNS errors because the service is restarting. It's a bit annoying.

phil.davis · Nov 30, 2014, 1:40 AM

Does the pid [3561:0] remain the same as previously?
If so, then it is getting a message to reload its config, and I guess spitting out all that log stuff as it resets itdelf. That is still annoying if it has noticeable time when it is not responding to queries.

What is in the system log around that time?

Maybe there are real events happening - WAN down/up, a VPN down/up… that have caused it.

MikeV7896 · Nov 30, 2014, 1:48 AM

Ok, so it's just reloading the config then… the PID remained the same until about 19:22 this evening, and it changed then because one of my interfaces bounced. Nothing else in the normal system log lined up with the Resolver log.

Any thought on why the hourly config reload then? Could it be related to including DHCP hosts?

cmb · Nov 30, 2014, 5:30 AM

DHCP renewals update Unbound's config and reload it, I'm sure that's all that is. dnsmasq is the same. It's not restarting the service and won't cause DNS to fail.

mattbunce · Nov 30, 2014, 11:20 AM

Hi - Sorry to be cheeky, I was wondering if anyone had any idea what might be going wrong in my case when using Domain Overrides to send specific domain queries to a different DNS server. (You can see more in my post above…)

@mattbunce:

It seems strange that DNS resolver has identified this as a query that should be sent via the VPN, but it still sends it to the main DNS servers?

Is anyone else using the Domain Overrides feature and do they also see the requests being sent to the wrong servers before eventually being sent to the correct one?

Thanks, Matt

Hugovsky · Nov 30, 2014, 5:00 PM

Sorry to ask again but is there news about my issue reported back in page 6? Or is just misconfiguration I'm doing?

phil.davis · Nov 30, 2014, 6:48 PM

@mattbunce:

Hi - Sorry to be cheeky, I was wondering if anyone had any idea what might be going wrong in my case when using Domain Overrides to send specific domain queries to a different DNS server. (You can see more in my post above…)

@mattbunce:

It seems strange that DNS resolver has identified this as a query that should be sent via the VPN, but it still sends it to the main DNS servers?

Is anyone else using the Domain Overrides feature and do they also see the requests being sent to the wrong servers before eventually being sent to the correct one?

Thanks, Matt

My system happily sends requests for domain override names just to the specified server.
In your log, yours is doing that also - server.vpn goes internally.
But server.vpn.local gets sent externally - you have specified .local as your domain for pfSense/LAN so clients on LAN are getting .local in their DNS suffix searchlist, and trying to append ".local" also when trying name lookups.
You could also add an override for "local" that points to an internal IP address that does not exist (or to pfSense itself? That might make an interesting loop.) so that anything ending in ".local" does not go to the public DNS.
DNS Forwarder has an optoin to put "!" instead of an IP address, and requests for that domain are not forwarded anywhere - if the name is not in the local hosts file, then NXDOMAIN is returned. That option is not in DNS Resolver.
That would be useful to have - I will look in unbound manual and see if it will do it.

Edit: Add: I think something in the config like:

local-zone: "local" static

will tell it that "local." is to be responded to just from pfSense itself - whatever host entries happen to be there that end in ".local" - but non-existent names in ".local" are immediately answered with NXDOMAIN.
I tried that quickly, in the Advanced box, but unbound is telling me I have a syntax error.
I also tried

local-zone "local." redirect

Still get syntax error message.
But it looks like it is possible to create an internal zone in unbound that will just return entries it knows about, and NXDOMAIN for things in the zone that it does not know.

mattbunce · Nov 30, 2014, 6:39 PM

Thanks Phil

So do you not have a domain set, and therefore your clients are not applying the suffix?

In the log I provided, I only did one NSLOOKUP to server.vpn - so either the client sent a second request without the DNS suffix or pfSense dropped the local domain portion after not getting a response from the public DNS servers.

phil.davis · Nov 30, 2014, 6:53 PM

The client will have tried server.vpn and server.vpn.local on your behalf. So the server sees 2 different requests.
My pfSenses have their domain as the same as our internal Windows Server AD domain - e.g. internal.mycompany.com - and then a domain override to point internal.mycompany.com to the nearest Active Directory DNS Server.

Having just 1 internal domain will also resolve the issue you see - at the moment you have a ".vpn" domain and a ".local"domain happening. Then your domain override will be for the domain that pfSense itself is in.

amunrara · Dec 2, 2014, 11:13 PM

working fine for me

mattbunce · Dec 4, 2014, 6:19 PM

Hmm - strange. I have had to use Phil's trick of directing the server.vpn.local requests to a non-existant server and then letting the server.vpn request go to the correct server. Without this I couldn't avoid the public DNS server being queried.

Maybe the issue is that I am not using AD? amunrara could you describe your set-up?

M

nzimmers · Dec 8, 2014, 1:21 PM

I'm a pretty novice user but wanted to provide some feedback and see if there are any suggestions. I'm currently using 2.2-BETA (i386) built on Thu Dec 04 08:23:23 CST 2014

when I check Status->Services several times in a row I see Unbound DNS Resolver running and stopped at various times so it seems like it's constantly stopping and restarting.

in the general setup, I have Allow "DNS server list to be overridden by DHCP/PPP on WAN" unchecked and "Do not use the DNS Forwarder as a DNS server for the firewall" checked.

not sure if I have something configured wrong…..

Hugovsky · Dec 8, 2014, 4:37 PM

Check the posts near the end of previous page. Might be your issue.

MikeV7896 · Dec 8, 2014, 7:22 PM

@Hugovsky:

Check the posts near the end of previous page. Might be your issue.

Specifically, this one…

https://forum.pfsense.org/index.php?topic=78356.msg464921#msg464921

xbipin · Dec 11, 2014, 5:46 AM

i started using the new dns resolver but im having one issue, i have set to reset the pppoe connection ever night so when this happens, unbound stops working, i get these errors in system log continuously

Dec 11 09:44:44 	unbound: [7669:0] error: can't bind socket: Can't assign requested address
Dec 11 09:44:44 	unbound: [7669:0] debug: failed address 92.98.234.229 port 61031
Dec 11 09:44:44 	unbound: [7669:0] error: can't bind socket: Can't assign requested address
Dec 11 09:44:44 	unbound: [7669:0] debug: failed address 92.98.234.229 port 19660
Dec 11 09:44:44 	unbound: [7669:0] error: can't bind socket: Can't assign requested address
Dec 11 09:44:44 	unbound: [7669:0] debug: failed address 92.98.234.229 port 26847
Dec 11 09:44:44 	unbound: [7669:0] error: can't bind socket: Can't assign requested address
Dec 11 09:44:44 	unbound: [7669:0] debug: failed address 92.98.234.229 port 26531
Dec 11 09:44:44 	unbound: [7669:0] error: can't bind socket: Can't assign requested address
Dec 11 09:44:44 	unbound: [7669:0] debug: failed address 92.98.234.229 port 65308
Dec 11 09:44:44 	unbound: [7669:0] error: can't bind socket: Can't assign requested address
Dec 11 09:44:44 	unbound: [7669:0] debug: failed address 92.98.234.229 port 19113