Unbound DNS not starting when DHCP Registration option is enabled

[campfred]

Hello fellow OpnSense users!
I'm facing a weird problem with the Unbound DNS instance on my OpnSense installation.
Whenever I have the DHCP Registration option enabled in Unbound DNS' settings, the service can't start until I disable it back.
The solutions I found so far pointed to updating to a version that came out about a year ago (1.7) that's behind what's currently installed in my OpnSense box (1.9.2_1).
I also took a look at the logs by clearing it then attempting to start the service and checking back the log but it's empty...

Current settings:
Enable : [✔]
Listen Port : 53 (default)
Network Interfaces : IOT, GUEST, LAN, OpenVPN Server
DNSSEC : [✔]
DHCP Registration : [  ]
DHCP Domain Override : (empty)
DHCP Static Mappings : [✔]
IPv6 Link-local : [  ]
TXT Comment Support : [  ]
DNS Query Forwarding : [  ]
Local Zone Type : transparent (default)
Custom options : (empty)
Outgoing Network Interfaces : All (recommended)
WPAD Records : [  ]

Did you have this problem before? How did you solve it?

[campfred]

Anyone?

[franco]

Unbound logs are the key here. Would you mind sharing them?


Cheers,
Franco

[campfred]

Sure! Sorry for it to be missing. I attached it before when I did the initial post but it seems like it doesn't stay there indefinitely. I'm very sorry about that.

Here's the content of /var/log/resolver.log (found from Services>Unbound DNS>Log File):
Sep 11 09:15:17    unbound: [24912:0] info: 16.000000 32.000000 1
Sep 11 09:15:17    unbound: [24912:0] info: 8.000000 16.000000 4
Sep 11 09:15:17    unbound: [24912:0] info: 2.000000 4.000000 6
Sep 11 09:15:17    unbound: [24912:0] info: 1.000000 2.000000 53
Sep 11 09:15:17    unbound: [24912:0] info: 0.524288 1.000000 639
Sep 11 09:15:17    unbound: [24912:0] info: 0.262144 0.524288 5042
Sep 11 09:15:17    unbound: [24912:0] info: 0.131072 0.262144 10316
Sep 11 09:15:17    unbound: [24912:0] info: 0.065536 0.131072 13504
Sep 11 09:15:17    unbound: [24912:0] info: 0.032768 0.065536 11251
Sep 11 09:15:17    unbound: [24912:0] info: 0.016384 0.032768 91
Sep 11 09:15:17    unbound: [24912:0] info: 0.008192 0.016384 29
Sep 11 09:15:17    unbound: [24912:0] info: 0.004096 0.008192 12
Sep 11 09:15:17    unbound: [24912:0] info: 0.002048 0.004096 4
Sep 11 09:15:17    unbound: [24912:0] info: 0.001024 0.002048 2
Sep 11 09:15:17    unbound: [24912:0] info: 0.000512 0.001024 1
Sep 11 09:15:17    unbound: [24912:0] info: 0.000000 0.000001 2571
Sep 11 09:15:17    unbound: [24912:0] info: lower(secs) upper(secs) recursions
Sep 11 09:15:17    unbound: [24912:0] info: [25%]=0.0565671 median[50%]=0.1034 [75%]=0.196881
Sep 11 09:15:17    unbound: [24912:0] info: histogram of recursion processing times
Sep 11 09:15:17    unbound: [24912:0] info: average recursion processing time 0.139316 sec
Sep 11 09:15:17    unbound: [24912:0] info: server stats for thread 3: requestlist max 15 avg 0.202821 exceeded 0 jostled 0
Sep 11 09:15:17    unbound: [24912:0] info: server stats for thread 3: 163694 queries, 120168 answers from cache, 43526 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Sep 11 09:15:17    unbound: [24912:0] info: 16.000000 32.000000 1
Sep 11 09:15:17    unbound: [24912:0] info: 2.000000 4.000000 5
Sep 11 09:15:17    unbound: [24912:0] info: 1.000000 2.000000 19
Sep 11 09:15:17    unbound: [24912:0] info: 0.524288 1.000000 290
Sep 11 09:15:17    unbound: [24912:0] info: 0.262144 0.524288 2744
Sep 11 09:15:17    unbound: [24912:0] info: 0.131072 0.262144 5070
Sep 11 09:15:17    unbound: [24912:0] info: 0.065536 0.131072 5997
Sep 11 09:15:17    unbound: [24912:0] info: 0.032768 0.065536 4582
Sep 11 09:15:17    unbound: [24912:0] info: 0.016384 0.032768 10
Sep 11 09:15:17    unbound: [24912:0] info: 0.008192 0.016384 7
Sep 11 09:15:17    unbound: [24912:0] info: 0.004096 0.008192 1
Sep 11 09:15:17    unbound: [24912:0] info: 0.002048 0.004096 1
Sep 11 09:15:17    unbound: [24912:0] info: 0.001024 0.002048 2
Sep 11 09:15:17    unbound: [24912:0] info: 0.000512 0.001024 1
Sep 11 09:15:17    unbound: [24912:0] info: 0.000000 0.000001 913
Sep 11 09:15:17    unbound: [24912:0] info: lower(secs) upper(secs) recursions
Sep 11 09:15:17    unbound: [24912:0] info: [25%]=0.0612004 median[50%]=0.112576 [75%]=0.214272
Sep 11 09:15:17    unbound: [24912:0] info: histogram of recursion processing times
Sep 11 09:15:17    unbound: [24912:0] info: average recursion processing time 0.149820 sec
Sep 11 09:15:17    unbound: [24912:0] info: server stats for thread 2: requestlist max 9 avg 0.139643 exceeded 0 jostled 0
Sep 11 09:15:17    unbound: [24912:0] info: server stats for thread 2: 72369 queries, 52726 answers from cache, 19643 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Sep 11 09:15:17    unbound: [24912:0] info: 8.000000 16.000000 1
Sep 11 09:15:17    unbound: [24912:0] info: 4.000000 8.000000 2
Sep 11 09:15:17    unbound: [24912:0] info: 2.000000 4.000000 6
Sep 11 09:15:17    unbound: [24912:0] info: 1.000000 2.000000 28
Sep 11 09:15:17    unbound: [24912:0] info: 0.524288 1.000000 546
Sep 11 09:15:17    unbound: [24912:0] info: 0.262144 0.524288 4601
Sep 11 09:15:17    unbound: [24912:0] info: 0.131072 0.262144 9469

I recorded it doing the following: Set Unbound DNS settings (but not applying them yet) > Clear Unbound DNS log > Apply Unbound DNS Settings (and noticing the service not going back up) > Attempting a manual start of the service > Get log file by SSH or by WebGUI.

[franco]

I only see Unbound reporting a happy operation. What am I missing?


Cheers,
Franco

[campfred]

Well, that's what I'm asking. I don't get why the service stops working and won't even start when I enable DHCP leases registration.
Here's a screenrecord of what I'm talking about. I guess it's gonna help understand the problem if my initial post didn't clarify enough what's happening. 😄
https://i.imgur.com/7T0s8bT.gifv

[franco]

I would suspect there is a lease that is unfriendly to Unbound, e.g. with a space in the host name.

As I have no way of reproducing that part or seeing Unbound complain about it in the log file I'll have to keep asking for more info in where the error is.


Cheers,
Franco

[campfred]

That would have made sense as I had a few devices that didn't have a hostname listed. But now that those have been taken care of, the service still can't start when the option is enabled. I also don't remember that to be a possibility to have a hostname with special characters.
I have attached a screenshot of all the hostnames we have on the network. I can't seem to find something that's not right with them. I'm probably mistaken though.

I also tried running temporarily a new install without transfering my current config on it and it still wouldn't start with the option enabled either. So, I'm out of ideas now. 😕

[campfred]

I still haven't given up on this and I've been able to test it clean with a clean, baremetal install with no clients on the LAN network.
Even on the default settings, I can't get the DNS service to start with the Register DHCP leases option enabled.
I really can't figure out what's happening with it. 

[franco]

I don't see anything unusual in the screenshot. Can you privately share your /var/unbound/dhcpleases.conf file when it crashes to franco@opnsense.org ?


Thanks,
Franco