New Update Package DNS problem
-
@jason001 What do the logs show when it stops working?
-
Happened again, Under system logs this is what DNS resolver show
Last 500 DNS Resolver Log Entries. (Maximum 500)
Time Process PID Message
Feb 5 07:39:47 unbound 16827 [16827:0] info: 0.016384 0.032768 1
Feb 5 07:39:47 unbound 16827 [16827:0] info: 0.032768 0.065536 36
Feb 5 07:39:47 unbound 16827 [16827:0] info: 0.065536 0.131072 23
Feb 5 07:39:47 unbound 16827 [16827:0] info: 0.131072 0.262144 125
Feb 5 07:39:47 unbound 16827 [16827:0] info: 0.262144 0.524288 130
Feb 5 07:39:47 unbound 16827 [16827:0] info: 0.524288 1.000000 57
Feb 5 07:39:47 unbound 16827 [16827:0] info: 1.000000 2.000000 28
Feb 5 07:39:47 unbound 16827 [16827:0] info: 2.000000 4.000000 6
Feb 5 07:39:47 unbound 16827 [16827:0] info: 4.000000 8.000000 2
Feb 5 07:39:47 unbound 16827 [16827:0] info: 8.000000 16.000000 1
Feb 5 07:39:47 unbound 16827 [16827:0] info: 16.000000 32.000000 4
Feb 5 07:39:47 unbound 16827 [16827:0] info: server stats for thread 2: 170 queries, 52 answers from cache, 118 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Feb 5 07:39:47 unbound 16827 [16827:0] info: server stats for thread 2: requestlist max 6 avg 0.144068 exceeded 0 jostled 0
Feb 5 07:39:47 unbound 16827 [16827:0] info: average recursion processing time 0.847314 sec
Feb 5 07:39:47 unbound 16827 [16827:0] info: histogram of recursion processing times
Feb 5 07:39:47 unbound 16827 [16827:0] info: [25%]=0.242869 median[50%]=0.439091 [75%]=0.815001
Feb 5 07:39:47 unbound 16827 [16827:0] info: lower(secs) upper(secs) recursions
Feb 5 07:39:47 unbound 16827 [16827:0] info: 0.000000 0.000001 9
Feb 5 07:39:47 unbound 16827 [16827:0] info: 0.032768 0.065536 3
Feb 5 07:39:47 unbound 16827 [16827:0] info: 0.065536 0.131072 3
Feb 5 07:39:47 unbound 16827 [16827:0] info: 0.131072 0.262144 17
Feb 5 07:39:47 unbound 16827 [16827:0] info: 0.262144 0.524288 40
Feb 5 07:39:47 unbound 16827 [16827:0] info: 0.524288 1.000000 27
Feb 5 07:39:47 unbound 16827 [16827:0] info: 1.000000 2.000000 11
Feb 5 07:39:47 unbound 16827 [16827:0] info: 2.000000 4.000000 5
Feb 5 07:39:47 unbound 16827 [16827:0] info: 4.000000 8.000000 1
Feb 5 07:39:47 unbound 16827 [16827:0] info: 8.000000 16.000000 2
Feb 5 07:39:47 unbound 16827 [16827:0] info: server stats for thread 3: 211 queries, 51 answers from cache, 160 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Feb 5 07:39:47 unbound 16827 [16827:0] info: server stats for thread 3: requestlist max 6 avg 0.21875 exceeded 0 jostled 0
Feb 5 07:39:47 unbound 16827 [16827:0] info: average recursion processing time 0.596478 sec
Feb 5 07:39:47 unbound 16827 [16827:0] info: histogram of recursion processing times
Feb 5 07:39:47 unbound 16827 [16827:0] info: [25%]=0.16468 median[50%]=0.338028 [75%]=0.745154
Feb 5 07:39:47 unbound 16827 [16827:0] info: lower(secs) upper(secs) recursions
Feb 5 07:39:47 unbound 16827 [16827:0] info: 0.000000 0.000001 13
Feb 5 07:39:47 unbound 16827 [16827:0] info: 0.002048 0.004096 1
Feb 5 07:39:47 unbound 16827 [16827:0] info: 0.032768 0.065536 10
Feb 5 07:39:47 unbound 16827 [16827:0] info: 0.065536 0.131072 6
Feb 5 07:39:47 unbound 16827 [16827:0] info: 0.131072 0.262144 39
Feb 5 07:39:47 unbound 16827 [16827:0] info: 0.262144 0.524288 38
Feb 5 07:39:47 unbound 16827 [16827:0] info: 0.524288 1.000000 28
Feb 5 07:39:47 unbound 16827 [16827:0] info: 1.000000 2.000000 16
Feb 5 07:39:47 unbound 16827 [16827:0] info: 2.000000 4.000000 7
Feb 5 07:39:47 unbound 16827 [16827:0] info: 4.000000 8.000000 2
Feb 5 07:39:51 unbound 48775 [48775:0] notice: init module 0: validator
Feb 5 07:39:51 unbound 48775 [48775:0] notice: init module 1: iterator
Feb 5 07:39:51 unbound 48775 [48775:0] info: start of service (unbound 1.18.0).
Feb 5 07:39:54 unbound 48775 [48775:1] info: generate keytag query _ta-4f66. NULL IN
Feb 5 07:39:54 unbound 48775 [48775:0] info: generate keytag query _ta-4f66. NULL IN
Feb 5 19:22:11 unbound 48775 [48775:0] info: generate keytag query _ta-4f66. NULL IN
Feb 6 07:11:56 unbound 48775 [48775:0] info: generate keytag query _ta-4f66. NULL IN
Feb 6 18:13:22 unbound 48775 [48775:0] info: generate keytag query _ta-4f66. NULL IN
Feb 6 19:45:53 unbound 48775 [48775:0] info: service stopped (unbound 1.18.0).
Feb 6 19:45:53 unbound 48775 [48775:0] info: server stats for thread 0: 1621 queries, 218 answers from cache, 1403 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Feb 6 19:45:53 unbound 48775 [48775:0] info: server stats for thread 0: requestlist max 18 avg 0.488952 exceeded 0 jostled 0
Feb 6 19:45:53 unbound 48775 [48775:0] info: average recursion processing time 0.790178 sec
Feb 6 19:45:53 unbound 48775 [48775:0] info: histogram of recursion processing times
Feb 6 19:45:53 unbound 48775 [48775:0] info: [25%]=0.191865 median[50%]=0.441485 [75%]=0.915793 -
service stopped
Ok so it stopped and didn’t crash. Why? The usual culprit is registering DHCP leases. Which restarts unbound but doesn’t break DNS after it starts again.
What exactly is the symptom, DNS lookups fail but ping/connect by IP works?
-
@SteveITS said in New Update Package DNS problem:
The time this happens some sites work..
Example google.com,facebook will load and work.. But then if you choose other sites youtube.com example or Netflix it wont load.. first i thought it was a ISP problem.. then i connected directly to my ISP router then i noticed everything works. but when plugged back into PfSense the problem is still there.. then i clicked on Services and DNS resolver restart it the in refresh the pages that didnt want to load, all a sudden it all works.. It worked fine on previous build before update.. but after update not so much.. i mage a config backup, and did a clean install thinking maybe something went wrong with online update.. but then worked for 1-2 days fine then give issue till restart the DNS resolver service.. -
@jason001 Do you have DNS Resolver set to forward DNS queries? If so ensure the option to use DNSSEC is unchecked.
-
@SteveITS
No.. DNS Forwarder is disabled.. only resolver is enabled -
@jason001 But is it set to forward? here:
-
These are currently how it looks like
-
@jason001 Can you show "DNS Query Forwarding" on the Resolver page?
-
These regular log, every 12 hours or so, lines are normal for unbound lines :
@jason001 said in New Update Package DNS problem:
Feb 5 07:39:54 unbound 48775 [48775:1] info: generate keytag query _ta-4f66. NULL IN
Feb 5 07:39:54 unbound 48775 [48775:0] info: generate keytag query _ta-4f66. NULL IN
Feb 5 19:22:11 unbound 48775 [48775:0] info: generate keytag query _ta-4f66. NULL IN
Feb 6 07:11:56 unbound 48775 [48775:0] info: generate keytag query _ta-4f66. NULL IN
Feb 6 18:13:22 unbound 48775 [48775:0] info: generate keytag query _ta-4f66. NULL INwhat they mean : the DNSSEC 'main' key is refreshed. See it as the hart beat of unbound.
I've the same thing ( reverse order ) :
When unbound is told to restart, you see this :
Feb 6 19:45:53 unbound 48775 [48775:0] info: service stopped (unbound 1.18.0).
and right after this line you see a lot of statistics (more or less useful) logged.
Keep in mind that pfSense never stops unbound, as this leaves the system without DNS.
pfSense always a stops it - then there is a 10 sec (or so) wait period, and then it starts it.
This sequence is a restart.
The admin could stop unbound, for whatever reason, using the GUI, for example by using this button :
A reason might be : stop unbound, and set up dnsmasq, the forwarder, and use that one instead.
To inform pfSense that unbound shouldn't be (re)started anymore, during boot or at any time, you have to uncheck this option :
and then set up the forwarder, dnsmasq :
So, your logs you've shown above don't show everything, as it ends while unbound was dumping statistics to the log.
It should be followed by a2024-02-12 00:15:28.241637+01:00 unbound 51151 [51151:0] info: start of service (unbound 1.18.0).
if this - as shown :
was really the end of the logs, nothing more was added, then something really bad has happened.
Like unbound process died on the spot. That's not normal at all.
