pfSense 2.7 DNS Resolver doesn't start

TampertK

@Gertjan Perhaps @SergBrNord does not use DHCP, I do and never claimed otherwise :)

My WAN interface indeed had 'DHCP6' set as 'IPv6 Configuration Type', but in System/Advanced/Networking 'Allow IPv6' was unchecked (= disabled). Setting 'IPv6 Configuration Type' to 'None' fixes the issue of Unbound not starting at boot, I'll monitor for random halts. Interesting that this has not been an issue up until 2.7, my config did not change.

TampertK

This post is deleted!

TampertK

Cheered too early, just had another random crash of Unbound. Digging deeper into the logs, it seems that an OpenVPN client instance may be involved. Look at the timing:

/var/log/openvpn.log

Jul 31 17:57:50 pfSense openvpn[6398]: [{OpenVPN server name}] Inactivity timeout (--ping-restart), restarting
Jul 31 17:57:50 pfSense openvpn[6398]: SIGUSR1[soft,ping-restart] received, process restarting
Jul 31 17:57:50 pfSense openvpn[6398]: Restart pause, 1 second(s)

/var/log/resolver.log

Jul 31 17:58:57 pfSense unbound[77815]: [77815:0] info: service stopped (unbound 1.17.1).

So OpenVPN initiates a restart, and a few seconds later Unbound crashes. I'm not using the OpenVPN server provided DNS servers (Pull DNS disabled), and the connection is set to IPv4 only Any ideas on this combo @Gertjan ?

johnpoz

@TampertK if your unbound outbound interfaces is set to all, then the restart of any of your interfaces can cause a problem with unbound that is bound to that interface.

Just use localhost as the only outbound interface. Should remove any care if some other interface resets for any reason.

TampertK

@johnpoz Thanks for the suggestion. The outgoing interface was set to WAN, now changed to localhost. Nothing about my configuration has changed between 2.6 and 2.7, so I can't help but feel that this is a bug or regression of some sort.

Gertjan

@TampertK

Just checking : you don't have the pfSense watchdog package loaded and activated for unbound ?
If so, don't.

Not using IPv6, and have dhcpv6 trying to get an IPv6 (and if it does work out, this will impact the WAN interface).
So, as proposed : set dhcpv6 to none.

You are using the OpenVPN client - and it is ordered to "ping-restart" == when ping loss, it will restart the connection.
If unbound uses this VPN connection as an outgoing connection == WAN to upstream DNS servers, then unbound will restart. This means that a 'bad' upstream' connection will influence the uptime of unbound.
You've set unbound outgoing to 'localhost'. This doesn't mean unbound doesn't use whatever route is available to the internet (straight WAN or VPN routed WAN) , as 'localhost' won't offer any upstream DNS servers.

What device is this ? bare bone ? VM ? Netgate device, Intel or AMD ?

TampertK

@Gertjan Watchdog package is not installed.

As per your earlier suggestion, I set 'IPv6 Configuration Type' on WAN to 'None'. This resolved Unbound not starting at boot, but did not resolve Unbound crashing randomly.

Unbound did not use the OpenVPN client as outgoing connection, only WAN was selected under 'Outgoing Network Interfaces'. Per @johnpoz 's suggestion I've now set this to 'localhost'.

My pfSense installation is running in ESXi 8, on a Dell 5070. The NICs (Intel X520) are passed through to the VM. But again, nothing has changed to the hardware or hypervisor between my 2.6 and 2.7 installations.

LastOfTheRonnies

Hi, I believe I'm seeing a somewhat similar unbound issue.
Unbound goes for a restart but does not complete the reload. This happens roughly once a week and appears to be random in terms of the time.

Aug 12 07:53:44 pfSense unbound[26068]: [26068:0] info: lower(secs) upper(secs) recursions
Aug 12 07:53:44 pfSense unbound[26068]: [26068:0] info:    0.008192    0.016384 1
Aug 12 07:53:44 pfSense unbound[26068]: [26068:0] info:    0.016384    0.032768 3
Aug 12 07:53:44 pfSense unbound[26068]: [26068:0] info:    0.032768    0.065536 6
Aug 12 07:53:44 pfSense unbound[26068]: [26068:0] info:    0.065536    0.131072 14
Aug 12 07:53:44 pfSense unbound[26068]: [26068:0] info:    0.131072    0.262144 8
Aug 12 07:53:44 pfSense unbound[26068]: [26068:0] info:    0.262144    0.524288 7
Aug 12 07:53:44 pfSense unbound[26068]: [26068:0] info:    0.524288    1.000000 1
Aug 12 07:53:44 pfSense unbound[26068]: [26068:0] info:    1.000000    2.000000 1
Aug 12 07:53:44 pfSense unbound[26068]: [26068:0] notice: Restart of unbound 1.17.1.
Aug 12 07:53:44 pfSense unbound[26068]: [26068:0] notice: init module 0: validator
Aug 12 07:53:44 pfSense unbound[26068]: [26068:0] notice: init module 1: iterator
Aug 12 07:53:44 pfSense unbound[26068]: [26068:0] info: start of service (unbound 1.17.1).
Aug 12 07:55:31 pfSense unbound[26068]: [26068:1] info: generate keytag query _ta-4f66. NULL IN
Aug 12 10:03:02 pfSense unbound[26068]: [26068:0] info: service stopped (unbound 1.17.1).
Aug 12 10:03:02 pfSense unbound[26068]: [26068:0] info: server stats for thread 0: 1850 queries, 788 answers from cache, 1062 recursions, 0 prefetch, 0 rejected by ip ratelimit
ing
Aug 12 10:03:02 pfSense unbound[26068]: [26068:0] info: server stats for thread 0: requestlist max 56 avg 4.08569 exceeded 0 jostled 0
Aug 12 10:03:02 pfSense unbound[26068]: [26068:0] info: average recursion processing time 0.239038 sec
Aug 12 10:03:02 pfSense unbound[26068]: [26068:0] info: histogram of recursion processing times

Here we can see that unbound restarted at 07:53:44 but appears to have incompletely loaded.
Interestingly the Service Status widget on the dashboard was showing that unbound was running/green-ticked.
I manually restarted the service at 10:03 and it came up ok.

I have OpenVPN, but there are no log entries since the 9th Aug, so it's not similar to @TampertK 's logs.
I did have IPV6 Configuration Type set to DHCP6 on the WAN interface, I have changed that to None now.

The system is an ALIX apu2e4 with 2.7.0-RELEASE.

LastOfTheRonnies

Oh I've cursed it now! Failed again at 11:03:45!
In the combined grep-log below I do see a HUP coming from dhcpd at 11:03:42, then the service fails to load afterwards...

[2.7.0-RELEASE][root@pfSense.homenet.local]/var/log: grep -r -n . -i -e "Aug 12 11:03:4"
./filter.log:338:Aug 12 11:03:40 pfSense filterlog[40581]: 4,,,1000000103,igb0,match,block,in,4,0x0,,55,3949,0,DF,17,udp,96,188.166.128.84,109.255.17.211,3479,30112,76
./filter.log:339:Aug 12 11:03:41 pfSense filterlog[40581]: 4,,,1000000103,igb0,match,block,in,4,0x0,,245,62789,0,none,6,tcp,40,79.124.62.86,109.255.17.211,58350,16502,0,S,2150868192,,1024,,
./filter.log:340:Aug 12 11:03:42 pfSense filterlog[40581]: 4,,,1000000103,igb0,match,block,in,4,0x0,,55,4249,0,DF,17,udp,96,188.166.128.84,109.255.17.211,3479,30112,76
./filter.log:341:Aug 12 11:03:43 pfSense filterlog[40581]: 4,,,1000000103,igb0,match,block,in,4,0x0,,55,4546,0,DF,17,udp,96,188.166.128.84,109.255.17.211,3479,30112,76
./filter.log:342:Aug 12 11:03:44 pfSense filterlog[40581]: 4,,,1000000103,igb0,match,block,in,4,0x0,,51,34872,0,none,17,udp,132,92.178.111.50,109.255.17.211,49732,33737,112
./filter.log:343:Aug 12 11:03:45 pfSense filterlog[40581]: 4,,,1000000103,igb0,match,block,in,4,0x0,,55,4831,0,DF,17,udp,96,188.166.128.84,109.255.17.211,3479,30112,76
./dhcpd.log:5693:Aug 12 11:03:42 pfSense dhcpleases[64065]: Sending HUP signal to dns daemon(47791)
./resolver.log:4636:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info: service stopped (unbound 1.17.1).
./resolver.log:4637:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info: server stats for thread 0: 145 queries, 10 answers from cache, 135 recursions, 0 prefetch, 0 rejected by ip ratelimiting
./resolver.log:4638:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info: server stats for thread 0: requestlist max 13 avg 0.488889 exceeded 0 jostled 0
./resolver.log:4639:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info: average recursion processing time 0.158614 sec
./resolver.log:4640:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info: histogram of recursion processing times
./resolver.log:4641:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info: [25%]=0.0383535 median[50%]=0.0945591 [75%]=0.197778
./resolver.log:4642:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info: lower(secs) upper(secs) recursions
./resolver.log:4643:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    0.000000    0.000001 7
./resolver.log:4644:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    0.008192    0.016384 5
./resolver.log:4645:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    0.016384    0.032768 18
./resolver.log:4646:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    0.032768    0.065536 22
./resolver.log:4647:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    0.065536    0.131072 35
./resolver.log:4648:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    0.131072    0.262144 28
./resolver.log:4649:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    0.262144    0.524288 12
./resolver.log:4650:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    0.524288    1.000000 6
./resolver.log:4651:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    1.000000    2.000000 2
./resolver.log:4652:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info: server stats for thread 1: 95 queries, 7 answers from cache, 88 recursions, 0 prefetch, 0 rejected by ip ratelimiting
./resolver.log:4653:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info: server stats for thread 1: requestlist max 10 avg 0.443182 exceeded 0 jostled 0
./resolver.log:4654:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info: average recursion processing time 0.222569 sec
./resolver.log:4655:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info: histogram of recursion processing times
./resolver.log:4656:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info: [25%]=0.0512 median[50%]=0.123362 [75%]=0.297097
./resolver.log:4657:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info: lower(secs) upper(secs) recursions
./resolver.log:4658:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    0.000000    0.000001 7
./resolver.log:4659:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    0.016384    0.032768 6
./resolver.log:4660:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    0.032768    0.065536 16
./resolver.log:4661:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    0.065536    0.131072 17
./resolver.log:4662:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    0.131072    0.262144 18
./resolver.log:4663:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    0.262144    0.524288 15
./resolver.log:4664:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    0.524288    1.000000 7
./resolver.log:4665:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    1.000000    2.000000 1
./resolver.log:4666:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    2.000000    4.000000 1
./resolver.log:4667:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info: server stats for thread 2: 148 queries, 11 answers from cache, 137 recursions, 0 prefetch, 0 rejected by ip ratelimiting
./resolver.log:4668:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info: server stats for thread 2: requestlist max 12 avg 0.423358 exceeded 0 jostled 0
./resolver.log:4669:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info: average recursion processing time 0.169696 sec
./resolver.log:4670:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info: histogram of recursion processing times
./resolver.log:4671:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info: [25%]=0.0385707 median[50%]=0.102085 [75%]=0.221432
./resolver.log:4672:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info: lower(secs) upper(secs) recursions
./resolver.log:4673:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    0.000000    0.000001 11
./resolver.log:4674:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    0.008192    0.016384 3
./resolver.log:4675:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    0.016384    0.032768 16
./resolver.log:4676:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    0.032768    0.065536 24
./resolver.log:4677:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    0.065536    0.131072 26
./resolver.log:4678:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    0.131072    0.262144 33
./resolver.log:4679:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    0.262144    0.524288 16
./resolver.log:4680:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    0.524288    1.000000 6
./resolver.log:4681:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    1.000000    2.000000 2
./resolver.log:4682:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info: server stats for thread 3: 211 queries, 19 answers from cache, 192 recursions, 0 prefetch, 0 rejected by ip ratelimiting
./resolver.log:4683:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info: server stats for thread 3: requestlist max 6 avg 0.322917 exceeded 0 jostled 0
./resolver.log:4684:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info: average recursion processing time 0.146060 sec
./resolver.log:4685:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info: histogram of recursion processing times
./resolver.log:4686:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info: [25%]=0.0295969 median[50%]=0.0855609 [75%]=0.2046
./resolver.log:4687:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info: lower(secs) upper(secs) recursions
./resolver.log:4688:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    0.000000    0.000001 17
./resolver.log:4689:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    0.008192    0.016384 6
./resolver.log:4690:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    0.016384    0.032768 31
./resolver.log:4691:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    0.032768    0.065536 31
./resolver.log:4692:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    0.065536    0.131072 36
./resolver.log:4693:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    0.131072    0.262144 41
./resolver.log:4694:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    0.262144    0.524288 22
./resolver.log:4695:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    0.524288    1.000000 6
./resolver.log:4696:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info:    1.000000    2.000000 2
./resolver.log:4697:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] notice: Restart of unbound 1.17.1.
./resolver.log:4698:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] notice: init module 0: validator
./resolver.log:4699:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] notice: init module 1: iterator
./resolver.log:4700:Aug 12 11:03:42 pfSense unbound[47791]: [47791:0] info: start of service (unbound 1.17.1).
./resolver.log:4701:Aug 12 11:03:45 pfSense unbound[47791]: [47791:0] info: generate keytag query _ta-4f66. NULL IN

Any clues?

andhie13312328

Any update on this? I was having the same issue and trying to find a way to fix it but still failed to.

Gertjan

@LastOfTheRonnies said in pfSense 2.7 DNS Resolver doesn't start:

I do see a HUP coming from dhcpd at 11:03:42

You're close
This is the one :

@LastOfTheRonnies said in pfSense 2.7 DNS Resolver doesn't start:

pfSense dhcpleases[64065]: Sending HUP signal to dns daemon(47791)

'some one' has checked the option "Register DHCP ...." under the Resolver settings.
So, whenever a DHCP lease comes in or is renew, your unbound resolver gets shot (sorry : restarted).
Btw : "dhcpleases" asks for a restart, not a stop.
If your unbound won't restart any more then ... dono why ( maybe it was getting getting tired of being restarted all the time ? )

Anyway : now you know what to do.

Btw : I just discovered that these options do not exist any more under 23.09, so they probably wont exist any more under the upcoming 2.7.1.

LastOfTheRonnies

@Gertjan
Hi, yes I selected to register DNS names as I needed it for mDNS functionality with IOT devices. I moved to a Technitium DNS server instead, setting PFSense to forward, and it has been stable ever since (and I get pretty little graphs and better DNS management as a bonus).

So the option to register DNS on lease creation or renewal has now been removed? So how does local DNS work then if it's gone?

johnpoz

@LastOfTheRonnies said in pfSense 2.7 DNS Resolver doesn't start:

needed it for mDNS functionality

Think you might need to relook up how mdns works ;)

https://en.wikipedia.org/wiki/Multicast_DNS

the multicast DNS (mDNS) protocol resolves hostnames to IP addresses within small networks that do not include a local name server.

When an mDNS client needs to resolve a hostname, it sends an IP multicast query message that asks the host having that name to identify itself. That target machine then multicasts a message that includes its IP address. All machines in that subnet can then use that information to update their mDNS caches.

LastOfTheRonnies

@johnpoz Hmm - fair enough point. .local name resolution was what I was looking for rather than mDNS discovery specifically.
But the point stands: I should be able to register hostnames on DHCP register leases/renewals without the service dumping and not restarting, right?

johnpoz

@LastOfTheRonnies said in pfSense 2.7 DNS Resolver doesn't start:

I should be able to hostnames on DHCP register leases/renewals without the service dumping and not restarting, right?

That has been an issue with pfsense and unbound for very long time. While you can register dhcp, it forces a restart of unbound. Depending on how many clients you have, how often you have clients renew there lease it may not be a problem for you.

How fast your unbound restarts, also comes into play.

One solution is to just set a reservation for your devices, so they will always get the same IP. And just register these static/reservations which are only loaded when unbound starts.. So there are no restarts that happen every time a client renews a lease.

There is some hope that with the move to KEA vs isc dhcp that this issue will go away. But Kea is not yet fully functional, it is in preview mode and many features are not yet implemented in pfsense.

.local name resolution

if your trying to use that with your normal dns, your doing it wrong to start with. .local is really only for use with mdns.. Use some other domain, home.apra is the recommended/approved domain to use for local dns..

I use local.lan, but slowing moving away from that to home.arpa

LastOfTheRonnies

@johnpoz Ok, thanks for the pointers & education. I do have static reservations for ~98% of my devices. The issue only started once I updated from 2.6.x to 2.7.0.

johnpoz

@LastOfTheRonnies what issue exactly? There is not any issues that I am aware of with dns registration of reservations in 2.7..

LastOfTheRonnies

@johnpoz said in pfSense 2.7 DNS Resolver doesn't start:

what issue exactly?

@LastOfTheRonnies said in pfSense 2.7 DNS Resolver doesn't start:

Unbound goes for a restart but does not complete the reload.

johnpoz

@LastOfTheRonnies Well that is not related to loading static reservations.

You have to look to see why its not finishing the restart - but really it shouldn't restart unless your trying to register dhcp.

TampertK

I've followed all recommendations from @Gertjan and @johnpoz, but unfortunately I'm also still facing the issue of Unbound not completing a restart once every two weeks or so. Same behavior since updating to 2.7.1

I have no idea how to pinpoint the issue, besides this being an issue I'm facing since 2.7