Question re slow DNS resolution/General DNS Resolver Options setup/Troubleshooting

guardian

@Gertjan said in Question re slow DNS resolution/General DNS Resolver Options setup/Troubleshooting:

@guardian said in Question re slow DNS resolution/General DNS Resolver Options setup/Troubleshooting:

Is there a way for me to see how long since Unbound was restarted, and/or the state of the cache?

@johnpoz posted that command some time ago.

Not sure what you mean here. my best guess is that examining clog /var/log/resolver.log is the best way to determine what is going on.

@guardian said in Question re slow DNS resolution/General DNS Resolver Options setup/Troubleshooting:

How can I troubleshoot to determine the cause of the problem?

First step : Remove pfBBlocker and does the issue goes away ?
Next step : use pfBlocker with minimal options and feeds, just a small one.
Closely monitor system resources at each step.
Monitor unbound restarts.
Etc etc

@Gertjan Thanks for the suggestions.... I was able to able to repeat the problem at approximately "Jun 8 02:39:01" -- I have copied some of the log both before an after the problem. I'm not sure where to look next but I suspect:

Jun 8 02:39:01 guardian unbound: [75093:0] info: service stopped (unbound 1.9.6).
and the presence of IPv6 (when IPv6 is turned off on all interfaces and on most network devices.
I have attached the relevant log entries-there are some "noise" searches from an open web browser on a PC..

Why is the service stopped? Does the log give any clue?

DNS_Resolver_Log.txt

Gertjan

@guardian said in Question re slow DNS resolution/General DNS Resolver Options setup/Troubleshooting:

Does the log give any clue?

Noop.
That is : it was asked to stop - actually : restart - at :

Jun  8 02:39:01 guardian unbound: [75093:0] info: service stopped (unbound 1.9.6)

After that line, a lot of sessions statistics are logged.
Then, as it was asked to restart :

Jun  8 02:39:26 guardian unbound: [75093:0] info: start of service (unbound 1.9.6).

You might try to stop the usage of IPv6, that's ok for now.
The rest of the world - that is : the Internet itself - is already IPv6 - and if that doesn't work out, it falls back to IPv4.

This :

....
Jun  8 02:39:26 guardian unbound: [75093:1] debug: Need to send query but have no outgoing interfaces of that family
Jun  8 02:39:26 guardian unbound: [75093:1] info: error sending query to auth server 2001:500:9f::42 port 53
Jun  8 02:39:26 guardian unbound: [75093:1] info: processQueryTargets: . NS IN
Jun  8 02:39:26 guardian unbound: [75093:1] info: sending query: . NS IN
Jun  8 02:39:26 guardian unbound: [75093:1] debug: sending to target: <.> 192.112.36.4#53
....

The first IPv6 and second IPv4 when it falls back to it , is one of the 13 main Internet Root servers.
unbound contacts them when it starts.
unbound is compiled with IPv6 - and use IPv4 as an alternative.

Btw : this is is not a problem, as it is good enough if one of both protocols works.
For now ;)

Too find who restarted unbound : see the other logs - at the same this moment : 02:39:01

guardian

Thanks @Gertjan

@Gertjan said in Question re slow DNS resolution/General DNS Resolver Options setup/Troubleshooting:

@guardian said in Question re slow DNS resolution/General DNS Resolver Options setup/Troubleshooting:

Does the log give any clue?

Noop.
That is : it was asked to stop - actually : restart - at :

What process would ask it to stop/restart? I could not find anything in /var/log/system.log where else would I look

Jun  8 02:39:01 guardian unbound: [75093:0] info: service stopped (unbound 1.9.6)
After that line, a lot of sessions statistics are logged.
Then, as it was asked to restart :
Jun  8 02:39:26 guardian unbound: [75093:0] info: start of service (unbound 1.9.6).
You might try to stop the usage of IPv6, that's ok for now.

How do I do that? I IPv6 is disabled on all interfaces - What else do I need to do

The rest of the world - that is : the Internet itself - is already IPv6 - and if that doesn't work out, it falls back to IPv4.

This :
....
Jun  8 02:39:26 guardian unbound: [75093:1] debug: Need to send query but have no outgoing interfaces of that family
Jun  8 02:39:26 guardian unbound: [75093:1] info: error sending query to auth server 2001:500:9f::42 port 53
Jun  8 02:39:26 guardian unbound: [75093:1] info: processQueryTargets: . NS IN
Jun  8 02:39:26 guardian unbound: [75093:1] info: sending query: . NS IN
Jun  8 02:39:26 guardian unbound: [75093:1] debug: sending to target: <.> 192.112.36.4#53
....
The first IPv6 and second IPv4 when it falls back to it , is one of the 13 main Internet Root servers.
unbound contacts them when it starts.
unbound is compiled with IPv6 - and use IPv4 as an alternative.

Btw : this is is not a problem, as it is good enough if one of both protocols works.
For now ;)

Too find who restarted unbound : see the other logs - at the same this moment : 02:39:01

This is the complete contents of /var/log/system.log around this time are:

Jun  8 02:05:28 guardian sshd[67229]: Accepted password for root from 172.16.50.33 port 45302 ssh2
Jun  8 02:15:09 guardian php: [pfBlockerNG] Starting cron process.
Jun  8 02:42:52 guardian kernel: ugen0.4: <Logitech USB Optical Mouse> at usbus0

Suggestions?

Gertjan

@guardian said in Question re slow DNS resolution/General DNS Resolver Options setup/Troubleshooting:

Jun 8 02:15:09 guardian php: [pfBlockerNG] Starting cron process.
...
What process would ask it to stop/restart? I could not find anything in /var/log/system.log where else would I look

You missed a log ........ and were not aware the pfBlockerNG has "something to do with DNS" .....

According to you, pfBlockerNG does what ? using what ?
A short answer It download and "handles" lists with hostnames and IP's, so it can be used by unbound, the DNS resolver.
unbound only re reads these list - if changed - during startup.
Check the pfBlockerNG logs. It's restarting unbound '"all the time".

Btw : incoming new DHCP lease could also restart unbound, as many other system events.

@guardian said in Question re slow DNS resolution/General DNS Resolver Options setup/Troubleshooting:

How do I do that? I IPv6 is disabled on all interfaces - What else do I need to do

The fact that you block incoming IPv6 traffic on interfaces doesn't mean process running on pfSense, or even the kernel itself do not try to use IPv6.
Again, not really a problem.

guardian

@Gertjan said in Question re slow DNS resolution/General DNS Resolver Options setup/Troubleshooting:

@guardian said in Question re slow DNS resolution/General DNS Resolver Options setup/Troubleshooting:

Jun 8 02:15:09 guardian php: [pfBlockerNG] Starting cron process.
...
What process would ask it to stop/restart? I could not find anything in /var/log/system.log where else would I look

You missed a log ........ and were not aware the pfBlockerNG has "something to do with DNS" .....

According to you, pfBlockerNG does what ? using what ?
A short answer It download and "handles" lists with hostnames and IP's, so it can be used by unbound, the DNS resolver.
unbound only re reads these list - if changed - during startup.
Check the pfBlockerNG logs. It's restarting unbound '"all the time".

Btw : incoming new DHCP lease could also restart unbound, as many other system events.

@guardian said in Question re slow DNS resolution/General DNS Resolver Options setup/Troubleshooting:

How do I do that? I IPv6 is disabled on all interfaces - What else do I need to do

The fact that you block incoming IPv6 traffic on interfaces doesn't mean process running on pfSense, or even the kernel itself do not try to use IPv6.
Again, not really a problem.

Thanks for the input @Gertjan can you (or anyone else please elaborate or clarify any on the following):

Check the pfBlockerNG logs. It's restarting unbound '"all the time".
Thanks for mentioning that - just checked the log - I was aware that it will reload on update, which is maximum 1/hour -- the problem is more frequent than the the number of reloads I am seeing in the pfBlocker log -- I am only seeing a reload after update.

Btw : incoming new DHCP lease could also restart unbound, as many other system events.
Why would I have a incoming new DHCP lease? (I should also mention that I took your advice and uncheced Register DHCP leases in the DNS Resolver.) I am on a small home network, there a re not a lot of changes occurring (unless there is something I am not aware of or my understanding of how things work is off). Am I missing something? How can I check this?

The fact that you block incoming IPv6 traffic on interfaces doesn't mean process running on pfSense, or even the kernel itself do not try to use IPv6.

That was my understanding. What did you mean in one of your early posts by:

You might try to stop the usage of IPv6, that's ok for now.

Suggestions?

Gertjan

@guardian said in Question re slow DNS resolution/General DNS Resolver Options setup/Troubleshooting:

clarify any on the following

pfBlockerNG-devel : you're using it, right ?
Wrong. The actual work is done by the unbound, that matches DNS requests and IP's with the lists it loaded. These lists are prepared by pfBlockerNG-devel. When pfBlockerNG-deve has new info, it restart unbound.
Can't be more clear about that.

Same thing from DHCP leases : if checked (see settings unbound first page) a new lease - the IP and host ,ame are added to the list of local devices, so that unbound can tell( == resolve ) how to address this device to the other devices. That's what DNS is all about on a local scale.

IPv6 : It works - it's the future. IPv4 will last for a while but soon IPv6 only hosts exist.

guardian

@Gertjan said in Question re slow DNS resolution/General DNS Resolver Options setup/Troubleshooting:

@guardian said in Question re slow DNS resolution/General DNS Resolver Options setup/Troubleshooting:

clarify any on the following

pfBlockerNG-devel : you're using it, right ?

I'm using pfBlockerNG v2.1.4_22 not the devel version

Wrong. The actual work is done by the unbound, that matches DNS requests and IP's with the lists it loaded. These lists are prepared by pfBlockerNG-devel. When pfBlockerNG-deve has new info, it restart unbound.
Can't be more clear about that.

I understand that - what I don't understand is why Unbound is restarting so often

Same thing from DHCP leases : if checked (see settings unbound first page) a new lease - the IP and host ,ame are added to the list of local devices, so that unbound can tell( == resolve ) how to address this device to the other devices. That's what DNS is all about on a local scale.

IPv6 : It works - it's the future. IPv4 will last for a while but soon IPv6 only hosts exist.

I have been avoiding IPv6 for as long as possible since security practices/system have some catching up to do.

Gertjan

@guardian said in Question re slow DNS resolution/General DNS Resolver Options setup/Troubleshooting:

I'm using pfBlockerNG v2.1.4_22 not the devel version

Ah ....
We all, the author included, switch to devel years ago.

@guardian said in Question re slow DNS resolution/General DNS Resolver Options setup/Troubleshooting:

why Unbound is restarting so often

We're in a loop here.
To see what restarts unbound, check the logs. I can't tell it from here.
You'll have to look, tell us who's doing it.
We tell you what not do do so it starts less often.

What's often ?
Execute

clog /var/log/resolver.log | grep 'Restart of'

If you have this one checked :

then, related to the number of devices in your network - or if you have a stupid device that asks a new lease every minute or so, then yes, unbound will get restart that many times.

I also advise you to remove the ancient pfBlockerNG.
Get the far better pfBlockerNG-devel - version 2.2.5_32

First remove the current pfBlockerNG. Wait a day or so before installing the new one.
During that time, unbound starts less often ?

edit : this one :

When you use the OpenVPN server - and a client(s) are connected, every time the tunnel goes up and down, because you shifted Wifi SSID - or went from Wifi to data carrier, unbound gets restarted.
I just saw this :

Jun  9 09:27:09 pfsense unbound: [31040:0] notice: Restart of unbound 1.10.1.
Jun  9 09:27:14 pfsense unbound: [31040:0] notice: Restart of unbound 1.10.1.
Jun  9 09:27:38 pfsense unbound: [31040:0] notice: Restart of unbound 1.10.1.

So, keep this option unchecked also.

Gertjan

@Gertjan said in Question re slow DNS resolution/General DNS Resolver Options setup/Troubleshooting:

clog /var/log/resolver.log | grep 'Restart of
Followup :

Since the last

Jun  9 09:29:03 pfsense unbound: [31040:0] notice: Restart of unbound 1.10.1.

posted previously, I had no more unbound resstarts.

That is : I update pfBlockerNG-devel feeds every 3 days, or less frequent (if they are themselves updated every week, I respect that time frame - no need to update all feeds every hour as seen elsewhere) as pfBlockerNG will restart unbound if one or more of the lists changed.

guardian

@Gertjan said in Question re slow DNS resolution/General DNS Resolver Options setup/Troubleshooting:

@Gertjan said in Question re slow DNS resolution/General DNS Resolver Options setup/Troubleshooting:

clog /var/log/resolver.log | grep 'Restart of
Followup :

Since the last
Jun  9 09:29:03 pfsense unbound: [31040:0] notice: Restart of unbound 1.10.1.
posted previously, I had no more unbound resstarts.

That is : I update pfBlockerNG-devel feeds every 3 days, or less frequent (if they are themselves updated every week, I respect that time frame - no need to update all feeds every hour as seen elsewhere) as pfBlockerNG will restart unbound if one or more of the lists changed.

Thanks for the update @Gertjan - I'm not 100% sure what happened, but I think that I might have had a problem with one of the feeds. I did a bit of a cleanup, and got rid of a couple of feeds. The system still restarts, but just once an hour, and it doesn't seem to cause problems with DNS resolution now.

I have a script running as we speak that does a dig microsoft.com every 5 seconds until such time as an error occurs. It ran for several hours yesterday, and I have it running again now.