Archive > 19.7 Legacy Series

Unbound DNS not starting when DHCP Registration option is enabled

(1/2) > >>

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

Navigation

[0] Message Index

[#] Next page