unbound dns problem

[william.anthony]

Sometimes when I'm browsing the internet, the error occured: DNS cannot find address... or similar like that.
When it happened, I simply go to opnsense lobby and click restart button of Unbound and then solved the problem.

Is there any solution? not every user has opnsense login user, and I cannot restart unbound all day..

[franco]

Are you setting explicit Unbound listen interfaces?


Cheers,
Franco

[william.anthony]

no, unbound setting still the default one.

[franco]

What's in your Unbound log prior to restart?


Cheers,
Franco

[miroco]

I have experienced the same issue. I'd like to point out that I use dns-over-tls.

Changing the interfaces from the selected few to all (default), makes Unbound stop dead. I'm running 18.1.10 with LibreSSL and with Unbound 1.73 test version.

https://forum.opnsense.org/index.php?topic=8943.0

[william.anthony]

@franco
here is the log I took just after I restarted the unbound:

Jun 28 15:01:22   unbound: [90583:0] info: start of service (unbound 1.7.2).
Jun 28 15:01:22   unbound: [90583:0] notice: init module 0: iterator
Jun 28 15:01:21   unbound: [49875:0] info: 64.000000 128.000000 1
Jun 28 15:01:21   unbound: [49875:0] info: 32.000000 64.000000 4
Jun 28 15:01:21   unbound: [49875:0] info: 16.000000 32.000000 4
Jun 28 15:01:21   unbound: [49875:0] info: 8.000000 16.000000 12
Jun 28 15:01:21   unbound: [49875:0] info: 4.000000 8.000000 118
Jun 28 15:01:21   unbound: [49875:0] info: 2.000000 4.000000 237
Jun 28 15:01:21   unbound: [49875:0] info: 1.000000 2.000000 994
Jun 28 15:01:21   unbound: [49875:0] info: 0.524288 1.000000 1414
Jun 28 15:01:21   unbound: [49875:0] info: 0.262144 0.524288 1149
Jun 28 15:01:21   unbound: [49875:0] info: 0.131072 0.262144 1129
Jun 28 15:01:21   unbound: [49875:0] info: 0.065536 0.131072 1216
Jun 28 15:01:21   unbound: [49875:0] info: 0.032768 0.065536 349
Jun 28 15:01:21   unbound: [49875:0] info: 0.016384 0.032768 307
Jun 28 15:01:21   unbound: [49875:0] info: 0.008192 0.016384 5
Jun 28 15:01:21   unbound: [49875:0] info: 0.004096 0.008192 7
Jun 28 15:01:21   unbound: [49875:0] info: 0.002048 0.004096 10
Jun 28 15:01:21   unbound: [49875:0] info: 0.001024 0.002048 22
Jun 28 15:01:21   unbound: [49875:0] info: 0.000000 0.000001 1654
Jun 28 15:01:21   unbound: [49875:0] info: lower(secs) upper(secs) recursions
Jun 28 15:01:21   unbound: [49875:0] info: [25%]=0.0471333 median[50%]=0.217679 [75%]=0.734893
Jun 28 15:01:21   unbound: [49875:0] info: histogram of recursion processing times
Jun 28 15:01:21   unbound: [49875:0] info: average recursion processing time 0.572441 sec
Jun 28 15:01:21   unbound: [49875:0] info: server stats for thread 3: requestlist max 27 avg 1.10518 exceeded 0 jostled 0
Jun 28 15:01:21   unbound: [49875:0] info: server stats for thread 3: 16109 queries, 7476 answers from cache, 8633 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Jun 28 15:01:21   unbound: [49875:0] info: 128.000000 256.000000 3
Jun 28 15:01:21   unbound: [49875:0] info: 64.000000 128.000000 13
Jun 28 15:01:21   unbound: [49875:0] info: 32.000000 64.000000 20
Jun 28 15:01:21   unbound: [49875:0] info: 16.000000 32.000000 15
Jun 28 15:01:21   unbound: [49875:0] info: 8.000000 16.000000 43
Jun 28 15:01:21   unbound: [49875:0] info: 4.000000 8.000000 329
Jun 28 15:01:21   unbound: [49875:0] info: 2.000000 4.000000 925
Jun 28 15:01:21   unbound: [49875:0] info: 1.000000 2.000000 3871
Jun 28 15:01:21   unbound: [49875:0] info: 0.524288 1.000000 5311
Jun 28 15:01:21   unbound: [49875:0] info: 0.262144 0.524288 4219
Jun 28 15:01:21   unbound: [49875:0] info: 0.131072 0.262144 4116
Jun 28 15:01:21   unbound: [49875:0] info: 0.065536 0.131072 4432
Jun 28 15:01:21   unbound: [49875:0] info: 0.032768 0.065536 1296
Jun 28 15:01:21   unbound: [49875:0] info: 0.016384 0.032768 1059
Jun 28 15:01:21   unbound: [49875:0] info: 0.008192 0.016384 44
Jun 28 15:01:21   unbound: [49875:0] info: 0.004096 0.008192 39
Jun 28 15:01:21   unbound: [49875:0] info: 0.002048 0.004096 54
Jun 28 15:01:21   unbound: [49875:0] info: 0.001024 0.002048 55
Jun 28 15:01:21   unbound: [49875:0] info: 0.000512 0.001024 1
Jun 28 15:01:21   unbound: [49875:0] info: 0.000256 0.000512 2
Jun 28 15:01:21   unbound: [49875:0] info: 0.000064 0.000128 1
Jun 28 15:01:21   unbound: [49875:0] info: 0.000000 0.000001 5508
Jun 28 15:01:21   unbound: [49875:0] info: lower(secs) upper(secs) recursions
Jun 28 15:01:21   unbound: [49875:0] info: [25%]=0.0599735 median[50%]=0.23256 [75%]=0.765324

[william.anthony]

2nd restart today:

Jun 28 16:10:00   unbound: [47193:0] info: start of service (unbound 1.7.2).
Jun 28 16:10:00   unbound: [47193:0] notice: init module 0: iterator
Jun 28 16:09:59   unbound: [90583:0] info: 128.000000 256.000000 1
Jun 28 16:09:59   unbound: [90583:0] info: 32.000000 64.000000 4
Jun 28 16:09:59   unbound: [90583:0] info: 16.000000 32.000000 1
Jun 28 16:09:59   unbound: [90583:0] info: 8.000000 16.000000 4
Jun 28 16:09:59   unbound: [90583:0] info: 4.000000 8.000000 33
Jun 28 16:09:59   unbound: [90583:0] info: 2.000000 4.000000 207
Jun 28 16:09:59   unbound: [90583:0] info: 1.000000 2.000000 957
Jun 28 16:09:59   unbound: [90583:0] info: 0.524288 1.000000 1417
Jun 28 16:09:59   unbound: [90583:0] info: 0.262144 0.524288 939
Jun 28 16:09:59   unbound: [90583:0] info: 0.131072 0.262144 457
Jun 28 16:09:59   unbound: [90583:0] info: 0.065536 0.131072 266
Jun 28 16:09:59   unbound: [90583:0] info: 0.032768 0.065536 102
Jun 28 16:09:59   unbound: [90583:0] info: 0.016384 0.032768 72
Jun 28 16:09:59   unbound: [90583:0] info: 0.008192 0.016384 6
Jun 28 16:09:59   unbound: [90583:0] info: 0.004096 0.008192 6
Jun 28 16:09:59   unbound: [90583:0] info: 0.002048 0.004096 4
Jun 28 16:09:59   unbound: [90583:0] info: 0.001024 0.002048 2
Jun 28 16:09:59   unbound: [90583:0] info: 0.000256 0.000512 1
Jun 28 16:09:59   unbound: [90583:0] info: 0.000000 0.000001 1014
Jun 28 16:09:59   unbound: [90583:0] info: lower(secs) upper(secs) recursions
Jun 28 16:09:59   unbound: [90583:0] info: [25%]=0.106496 median[50%]=0.490089 [75%]=0.944187
Jun 28 16:09:59   unbound: [90583:0] info: histogram of recursion processing times
Jun 28 16:09:59   unbound: [90583:0] info: average recursion processing time 0.713392 sec
Jun 28 16:09:59   unbound: [90583:0] info: server stats for thread 3: requestlist max 37 avg 2.68942 exceeded 0 jostled 0
Jun 28 16:09:59   unbound: [90583:0] info: server stats for thread 3: 10333 queries, 4840 answers from cache, 5493 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Jun 28 16:09:59   unbound: [90583:0] info: 256.000000 512.000000 2
Jun 28 16:09:59   unbound: [90583:0] info: 32.000000 64.000000 1
Jun 28 16:09:59   unbound: [90583:0] info: 8.000000 16.000000 5
Jun 28 16:09:59   unbound: [90583:0] info: 4.000000 8.000000 29
Jun 28 16:09:59   unbound: [90583:0] info: 2.000000 4.000000 153
Jun 28 16:09:59   unbound: [90583:0] info: 1.000000 2.000000 630
Jun 28 16:09:59   unbound: [90583:0] info: 0.524288 1.000000 1014
Jun 28 16:09:59   unbound: [90583:0] info: 0.262144 0.524288 611
Jun 28 16:09:59   unbound: [90583:0] info: 0.131072 0.262144 264
Jun 28 16:09:59   unbound: [90583:0] info: 0.065536 0.131072 160
Jun 28 16:09:59   unbound: [90583:0] info: 0.032768 0.065536 81
Jun 28 16:09:59   unbound: [90583:0] info: 0.016384 0.032768 48
Jun 28 16:09:59   unbound: [90583:0] info: 0.008192 0.016384 8
Jun 28 16:09:59   unbound: [90583:0] info: 0.004096 0.008192 3
Jun 28 16:09:59   unbound: [90583:0] info: 0.002048 0.004096 2
Jun 28 16:09:59   unbound: [90583:0] info: 0.000000 0.000001 683
Jun 28 16:09:59   unbound: [90583:0] info: lower(secs) upper(secs) recursions
Jun 28 16:09:59   unbound: [90583:0] info: [25%]=0.105882 median[50%]=0.51871 [75%]=0.951444
Jun 28 16:09:59   unbound: [90583:0] info: histogram of recursion processing times
Jun 28 16:09:59   unbound: [90583:0] info: average recursion processing time 0.881232 sec
Jun 28 16:09:59   unbound: [90583:0] info: server stats for thread 2: requestlist max 36 avg 2.43476 exceeded 0 jostled 0
Jun 28 16:09:59   unbound: [90583:0] info: server stats for thread 2: 6779 queries, 3085 answers from cache, 3694 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Jun 28 16:09:59   unbound: [90583:0] info: 32.000000 64.000000 1

[william.anthony]

is there any relation with this issue and state table size?

mine increased to 80-98% when I opened the dashboard to restart unbound. after I restart, it decreased slowly to about 20%

[william.anthony]

Just info, I reverted the unbound to 1.6.8_2 this morning as pointed out from this thread, and no problem report from my user until now (04.26 PM)...

It's more than 8 hours without problem... ;D

[william.anthony]

maybe it's just coincidence... my issue is reappear...

[franco]

Hmmm, something is wrong but I'm not seeing why. Do you require Unbound or can you try to use Dnsmasq instead?


Cheers,
Franco

[william.anthony]

OK, I'll switch to dnsmasq temporarily.. Thanks.