Unbound - restarted when interface wakes up? (is delay and BlackLists)

[lar.hed]

So here is the thing I for the moment don't get:

I earlier today turned on Unbound DNS BlackList, and checked them all. This used to work on my old OPNsense firewall (hardware broke on that one, so I building a new one).

So when enabled, BlackLists, I get a delay of 10-15 seconds before internet (DNS resolution) wakes up when I wake up my PC on the LAN interface. If I disable BlackLists, it works direct after I wake up my LAN connected PC.

Anyone know why this is?

[madj42]

It's possible the computer is trying to check something dns related that is being blocked by the backlists.  Have you checked to see if windows determines if you have internet access when the internet is not working?

[lar.hed]

Well I kind of got there also.

So I disables the WindowsSpy stuff (three lists) in the bottom, made no difference.
So then I disabled everything except the first one (AdAwayList) - this worked.

Will now work my way thru each and everyone of them to see when I hit the same issue again. I'll be back...

EDIT: Windows says I have internet access all the time - it is just DNS resolution that seems to fail...

EDIT (again): The current OPNsense hardware, since the previous one got h/w failure, sits inside another firewall that happens to run a few blacklists also...

[lar.hed]

Okay - a lot of testing later...

The delay could be related to some sort of volume of selected BlackLists....
Since I get longer and longer delay as more of the BlackLists get selected...

[lar.hed]

Why is Unbound restarted every time someone starts the PC connected to LAN interface is woken up?

The PC connected to that single interface, LAN, goes to sleep and then the traffic on that interface, LAN, stops. At that time nothing seems to happen in the log, however as soon as someone (most likly me) starts that only connected PC, Unbound restarts:

Code Select Expand

2020-12-07T06:37:00 unbound[19877] [19877:1] info: generate keytag query _ta-4f66. NULL IN
2020-12-07T06:37:00 unbound[19877] [19877:2] info: generate keytag query _ta-4f66. NULL IN
2020-12-07T06:37:00 unbound[19877] [19877:3] info: generate keytag query _ta-4f66. NULL IN
2020-12-07T06:37:00 unbound[19877] [19877:0] info: start of service (unbound 1.12.0).
2020-12-07T06:37:00 unbound[19877] [19877:0] notice: init module 1: iterator
2020-12-07T06:37:00 unbound[19877] [19877:0] notice: init module 0: validator
2020-12-07T06:36:19 unbound[19877] [19877:0] notice: Restart of unbound 1.12.0.
2020-12-07T06:36:19 unbound[19877] [19877:0] info: 0.032768 0.065536 2
2020-12-07T06:36:19 unbound[19877] [19877:0] info: 0.008192 0.016384 2
2020-12-07T06:36:19 unbound[19877] [19877:0] info: lower(secs) upper(secs) recursions
2020-12-07T06:36:19 unbound[19877] [19877:0] info: [25%]=0.012288 median[50%]=0.016384 [75%]=0.049152
2020-12-07T06:36:19 unbound[19877] [19877:0] info: histogram of recursion processing times
2020-12-07T06:36:19 unbound[19877] [19877:0] info: average recursion processing time 0.029205 sec
2020-12-07T06:36:19 unbound[19877] [19877:0] info: server stats for thread 7: requestlist max 0 avg 0 exceeded 0 jostled 0
2020-12-07T06:36:19 unbound[19877] [19877:0] info: server stats for thread 7: 25 queries, 21 answers from cache, 4 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2020-12-07T06:36:19 unbound[19877] [19877:0] info: 0.016384 0.032768 1
2020-12-07T06:36:19 unbound[19877] [19877:0] info: lower(secs) upper(secs) recursions
2020-12-07T06:36:19 unbound[19877] [19877:0] info: [25%]=0 median[50%]=0 [75%]=0
2020-12-07T06:36:19 unbound[19877] [19877:0] info: histogram of recursion processing times
2020-12-07T06:36:19 unbound[19877] [19877:0] info: average recursion processing time 0.030775 sec
2020-12-07T06:36:19 unbound[19877] [19877:0] info: server stats for thread 6: requestlist max 0 avg 0 exceeded 0 jostled 0
2020-12-07T06:36:19 unbound[19877] [19877:0] info: server stats for thread 6: 13 queries, 12 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2020-12-07T06:36:19 unbound[19877] [19877:0] info: server stats for thread 5: requestlist max 0 avg 0 exceeded 0 jostled 0
2020-12-07T06:36:19 unbound[19877] [19877:0] info: server stats for thread 5: 2 queries, 2 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2020-12-07T06:36:19 unbound[19877] [19877:0] info: server stats for thread 4: requestlist max 0 avg 0 exceeded 0 jostled 0
2020-12-07T06:36:19 unbound[19877] [19877:0] info: server stats for thread 4: 3 queries, 3 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2020-12-07T06:36:19 unbound[19877] [19877:0] info: 0.131072 0.262144 1
2020-12-07T06:36:19 unbound[19877] [19877:0] info: 0.008192 0.016384 1
2020-12-07T06:36:19 unbound[19877] [19877:0] info: lower(secs) upper(secs) recursions
2020-12-07T06:36:19 unbound[19877] [19877:0] info: [25%]=0 median[50%]=0 [75%]=0
2020-12-07T06:36:19 unbound[19877] [19877:0] info: histogram of recursion processing times
2020-12-07T06:36:19 unbound[19877] [19877:0] info: average recursion processing time 0.087900 sec
2020-12-07T06:36:19 unbound[19877] [19877:0] info: server stats for thread 3: requestlist max 0 avg 0 exceeded 0 jostled 0
2020-12-07T06:36:19 unbound[19877] [19877:0] info: server stats for thread 3: 7 queries, 5 answers from cache, 2 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2020-12-07T06:36:19 unbound[19877] [19877:0] info: 0.016384 0.032768 2
2020-12-07T06:36:19 unbound[19877] [19877:0] info: 0.008192 0.016384 1
2020-12-07T06:36:19 unbound[19877] [19877:0] info: 0.000000 0.000001 1
2020-12-07T06:36:19 unbound[19877] [19877:0] info: lower(secs) upper(secs) recursions
2020-12-07T06:36:19 unbound[19877] [19877:0] info: [25%]=1e-06 median[50%]=0.016384 [75%]=0.024576
2020-12-07T06:36:19 unbound[19877] [19877:0] info: histogram of recursion processing times
2020-12-07T06:36:19 unbound[19877] [19877:0] info: average recursion processing time 0.010952 sec
2020-12-07T06:36:19 unbound[19877] [19877:0] info: server stats for thread 2: requestlist max 0 avg 0 exceeded 0 jostled 0
2020-12-07T06:36:19 unbound[19877] [19877:0] info: server stats for thread 2: 12 queries, 8 answers from cache, 4 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2020-12-07T06:36:19 unbound[19877] [19877:0] info: 0.131072 0.262144 1
2020-12-07T06:36:19 unbound[19877] [19877:0] info: 0.065536 0.131072 1
2020-12-07T06:36:19 unbound[19877] [19877:0] info: 0.032768 0.065536 1
2020-12-07T06:36:19 unbound[19877] [19877:0] info: 0.016384 0.032768 1
2020-12-07T06:36:19 unbound[19877] [19877:0] info: lower(secs) upper(secs) recursions
2020-12-07T06:36:19 unbound[19877] [19877:0] info: [25%]=0.032768 median[50%]=0.065536 [75%]=0.131072
2020-12-07T06:36:19 unbound[19877] [19877:0] info: histogram of recursion processing times
2020-12-07T06:36:19 unbound[19877] [19877:0] info: average recursion processing time 0.082588 sec
2020-12-07T06:36:19 unbound[19877] [19877:0] info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
2020-12-07T06:36:19 unbound[19877] [19877:0] info: server stats for thread 1: 9 queries, 5 answers from cache, 4 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2020-12-07T06:36:19 unbound[19877] [19877:0] info: 0.262144 0.524288 1
2020-12-07T06:36:19 unbound[19877] [19877:0] info: 0.016384 0.032768 1
2020-12-07T06:36:19 unbound[19877] [19877:0] info: 0.000000 0.000001 1
2020-12-07T06:36:19 unbound[19877] [19877:0] info: lower(secs) upper(secs) recursions
2020-12-07T06:36:19 unbound[19877] [19877:0] info: [25%]=0 median[50%]=0 [75%]=0
2020-12-07T06:36:19 unbound[19877] [19877:0] info: histogram of recursion processing times
2020-12-07T06:36:19 unbound[19877] [19877:0] info: average recursion processing time 0.174345 sec
2020-12-07T06:36:19 unbound[19877] [19877:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
2020-12-07T06:36:19 unbound[19877] [19877:0] info: server stats for thread 0: 10 queries, 7 answers from cache, 3 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2020-12-07T06:36:19 unbound[19877] [19877:0] info: service stopped (unbound 1.12.0).

Now since Unbound decides to restart, for what evere reason, the DNS resolution will not be available since well it may have started, but it for sure takes a while to process the BlackLists that are active - the more BlackList - the longer the process time (logical, although with 8 cores i7 as CPU well...).

So why is Unbound restarted then? It's not like I added an interface - I just resumed operation on the LAN interface...?

[Fright]

is DHCP registration enabled on unbound?

[lar.hed]

is DHCP registration enabled on unbound?

Yes.

[Fright]

yes

so. unbound needs to re-read config with new entry after dhcp-client address registration.
and the larger the file with dnsbl records, the longer it takes to start

[lar.hed]

yes

so. unbound needs to re-reade config with new entry after dhcp-client address registration.
and the larger the file dnsbl records, the longer it takes to start

So what you are saying is that I need to turn off, disable, DHCP registration within Unbound to stop this? I'll give it a try.

[Fright]

disable, DHCP registration within Unbound to stop this?

yes. or use less dnsbl-s
if you don't have many hosts to register, you can try to solve this with Overrides and dhcp reservations

[lar.hed]

disable, DHCP registration within Unbound to stop this?

yes. or use less dnsbl-s
if you don't have many hosts to register, you can try to solve this with Overrides and dhcp reservations

No.

Made no difference at all, still get Unbound restart.

The thing is here, since Unbound handles all DNS requests, all ports so to speak goes down when a interface that has had no traffic (PC/Server is power off or just sleeping) triggers a restart of Unbound. Even without any blacklists enabled this still happens. And you do get downtime. With blacklists it is just much worse.

[Fright]

The thing is here, since Unbound handles all DNS requests, all ports so to speak goes down when a interface that has had no traffic (PC/Server is power off or just sleeping) triggers a restart of Unbound. Even without any blacklists enabled this still happens. And you do get downtime. With blacklists it is just much worse.

did not understand the idea

Even without any blacklists enabled this still happens

if DHCP Registration enabled this will happen when the client receives the lease. it will just be faster if the dnsbl list is small or disabled

[lar.hed]

Under Unbound -> General settings:

DHCP Registration is disabled
DHCP Static Mappings is disabled
Network Interfaces is (for the moment) LAN and WORK
Outgoing Network Interfaces (for the moment) WAN_FTTH and WAN_LTE (failover)

And yes Unbound is enabled.

No matter what status BlackLists are in (enabled or disabled), Unbound will restart no matter what when for example LAN interface wakes up.

Since i have 8 ports available (only 4 used so far, I am still building my new OPNsense), when I will enable the last 4 I will also connect a lot more stuff that will need DNS resolution. Some of them might go into powersave and when it wakes up, I guess Unbound will be triggered to reboot. Just as when the now PC connected to LAN port wakes up.

This will interupt DNS service since Unbound is unavailable.

On my other firewall, which happens to use Unbound also - this does not happen, and well that Unbound installation runs a lot of block lists also. No interruption at all.

Also my previous OPNsense box, I don't remember this to happening so it feels like something new (to me at least).

[Fright]

some of them might go into powersave and when it wakes up, I guess Unbound will be triggered to reboot.

sorry. didn't know about powersave.
yes. it triggers restart afaik

[lar.hed]

Okay - So no matter how I try to solve this, if a host / server / what ever goes into powersave / turned off - and then power on again, the end result is that Unbound will restart.

I think this is the third thing I might not have solved this way.