[issue] unbound restart / reboot need to long after update 139->141

giffft · 4 March 2020 23:27

Hello,

I use APU4 board and /etc/unbound/local.d/dns_blocklist with ~1,3Mio lines from block.energized.pro

When I had 139 it needed ~1 minutes for restart unbound (then was ready to type).
Now (141) IPFire takes ~20 minutes for restart unbound, after it was ready. Same with 142 testing. Reboot same ~20min
Both was clean install + cp dns_blocklist /etc/unbound/local.d/

/var/log/messages 139

Mar  4 22:28:03 ipfire unbound: [2919:0] info: service stopped (unbound 1.9.5).
Mar  4 22:28:03 ipfire unbound: [2919:0] info: server stats for thread 0: 4 queries, 1 answers from cache, 3 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Mar  4 22:28:03 ipfire unbound: [2919:0] info: server stats for thread 0: requestlist max 2 avg 0.666667 exceeded 0 jostled 0
Mar  4 22:28:03 ipfire unbound: [2919:0] info: average recursion processing time 0.103343 sec
Mar  4 22:28:03 ipfire unbound: [2919:0] info: histogram of recursion processing times
Mar  4 22:28:03 ipfire unbound: [2919:0] info: [25%]=0 median[50%]=0 [75%]=0
Mar  4 22:28:03 ipfire unbound: [2919:0] info: lower(secs) upper(secs) recursions
Mar  4 22:28:03 ipfire unbound: [2919:0] info:    0.016384    0.032768 1
Mar  4 22:28:03 ipfire unbound: [2919:0] info:    0.131072    0.262144 2
Mar  4 22:28:03 ipfire unbound: [2919:0] info: server stats for thread 1: 3 queries, 2 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Mar  4 22:28:03 ipfire unbound: [2919:0] info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
Mar  4 22:28:03 ipfire unbound: [2919:0] info: average recursion processing time 0.131203 sec
Mar  4 22:28:03 ipfire unbound: [2919:0] info: histogram of recursion processing times
Mar  4 22:28:03 ipfire unbound: [2919:0] info: [25%]=0 median[50%]=0 [75%]=0
Mar  4 22:28:03 ipfire unbound: [2919:0] info: lower(secs) upper(secs) recursions
Mar  4 22:28:03 ipfire unbound: [2919:0] info:    0.131072    0.262144 1
Mar  4 22:28:03 ipfire unbound: [2919:0] info: server stats for thread 2: 6 queries, 1 answers from cache, 5 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Mar  4 22:28:03 ipfire unbound: [2919:0] info: server stats for thread 2: requestlist max 0 avg 0 exceeded 0 jostled 0
Mar  4 22:28:03 ipfire unbound: [2919:0] info: average recursion processing time 0.107928 sec
Mar  4 22:28:03 ipfire unbound: [2919:0] info: histogram of recursion processing times
Mar  4 22:28:03 ipfire unbound: [2919:0] info: [25%]=6.25e-07 median[50%]=0.024576 [75%]=0.114688
Mar  4 22:28:03 ipfire unbound: [2919:0] info: lower(secs) upper(secs) recursions
Mar  4 22:28:03 ipfire unbound: [2919:0] info:    0.000000    0.000001 2
Mar  4 22:28:03 ipfire unbound: [2919:0] info:    0.016384    0.032768 1
Mar  4 22:28:03 ipfire unbound: [2919:0] info:    0.065536    0.131072 1
Mar  4 22:28:03 ipfire unbound: [2919:0] info:    0.262144    0.524288 1
Mar  4 22:28:03 ipfire unbound: [2919:0] info: server stats for thread 3: 2 queries, 2 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Mar  4 22:28:03 ipfire unbound: [2919:0] info: server stats for thread 3: requestlist max 0 avg 0 exceeded 0 jostled 0
Mar  4 22:28:32 ipfire unbound: [7099:0] notice: init module 0: validator
Mar  4 22:28:32 ipfire unbound: [7099:0] notice: init module 1: iterator
Mar  4 22:28:32 ipfire unbound: [7099:0] info: start of service (unbound 1.9.5).
Mar  4 22:28:32 ipfire unbound: [7099:1] info: generate keytag query _ta-4a5c-4f66. NULL IN
Mar  4 22:28:33 ipfire unbound: [7099:3] info: generate keytag query _ta-4a5c-4f66. NULL IN
Mar  4 22:28:59 ready in terminal

/var/log/messages 141

Mar  4 23:54:48 ipfire unbound: [4558:0] info: service stopped (unbound 1.9.6).
Mar  4 23:54:48 ipfire unbound: [4558:0] info: server stats for thread 0: 2 queries, 1 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Mar  4 23:54:48 ipfire unbound: [4558:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
Mar  4 23:54:48 ipfire unbound: [4558:0] info: average recursion processing time 0.582765 sec
Mar  4 23:54:48 ipfire unbound: [4558:0] info: histogram of recursion processing times
Mar  4 23:54:48 ipfire unbound: [4558:0] info: [25%]=0 median[50%]=0 [75%]=0
Mar  4 23:54:48 ipfire unbound: [4558:0] info: lower(secs) upper(secs) recursions
Mar  4 23:54:48 ipfire unbound: [4558:0] info:    0.524288    1.000000 1
Mar  4 23:54:48 ipfire unbound: [4558:0] info: server stats for thread 1: 3 queries, 2 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Mar  4 23:54:48 ipfire unbound: [4558:0] info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
Mar  4 23:54:48 ipfire unbound: [4558:0] info: average recursion processing time 0.274197 sec
Mar  4 23:54:48 ipfire unbound: [4558:0] info: histogram of recursion processing times
Mar  4 23:54:48 ipfire unbound: [4558:0] info: [25%]=0 median[50%]=0 [75%]=0
Mar  4 23:54:48 ipfire unbound: [4558:0] info: lower(secs) upper(secs) recursions
Mar  4 23:54:48 ipfire unbound: [4558:0] info:    0.262144    0.524288 1
Mar  4 23:54:48 ipfire unbound: [4558:0] info: server stats for thread 2: 2 queries, 2 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Mar  4 23:54:48 ipfire unbound: [4558:0] info: server stats for thread 2: requestlist max 0 avg 0 exceeded 0 jostled 0
Mar  4 23:54:48 ipfire unbound: [4558:0] info: server stats for thread 3: 1 queries, 1 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Mar  4 23:54:48 ipfire unbound: [4558:0] info: server stats for thread 3: requestlist max 0 avg 0 exceeded 0 jostled 0
Mar  4 23:55:06 ipfire kernel: DROP_INPUT IN=red0 OUT= MAC=xxx SRC=192.168.50.1 DST=224.0.0.1 LEN=36 TOS=0x00 PREC=0x00 TTL=1 ID=0 DF PROTO=2 
Mar  4 23:55:18 ipfire unbound: [4946:0] notice: init module 0: validator
Mar  4 23:55:18 ipfire unbound: [4946:0] notice: init module 1: iterator
Mar  4 23:55:18 ipfire unbound: [4946:0] info: start of service (unbound 1.9.6).
Mar  4 23:56:11 ipfire kernel: perf: interrupt took too long (3143 > 3132), lowering kernel.perf_event_max_sample_rate to 63600
Mar  4 23:57:11 ipfire kernel: DROP_INPUT IN=red0 OUT= MAC=xxxx SRC=192.168.50.1 DST=224.0.0.1 LEN=36 TOS=0x00 PREC=0x00 TTL=1 ID=0 DF PROTO=2 
Mar  4 23:59:16 ipfire kernel: DROP_INPUT IN=red0 OUT= MAC=xxx SRC=192.168.50.1 DST=224.0.0.1 LEN=36 TOS=0x00 PREC=0x00 TTL=1 ID=0 DF PROTO=2 
Mar  4 23:59:47 ipfire kernel: perf: interrupt took too long (4163 > 3928), lowering kernel.perf_event_max_sample_rate to 48000
Mar  5 00:00:41 ipfire dhcpd: DHCPREQUEST for 192.168.200.46 from xxx (PC) via green0
Mar  5 00:00:41 ipfire dhcpd: DHCPACK on 192.168.200.46 to xxx (PC) via green0
Mar  5 00:01:21 ipfire kernel: DROP_INPUT IN=red0 OUT= MAC=xxx SRC=192.168.50.1 DST=224.0.0.1 LEN=36 TOS=0x00 PREC=0x00 TTL=1 ID=0 DF PROTO=2 
Mar  5 00:03:26 ipfire kernel: DROP_INPUT IN=red0 OUT= MAC=xxx SRC=192.168.50.1 DST=224.0.0.1 LEN=36 TOS=0x00 PREC=0x00 TTL=1 ID=0 DF PROTO=2 
Mar  5 00:05:31 ipfire kernel: DROP_INPUT IN=red0 OUT= MAC=xxx SRC=192.168.50.1 DST=224.0.0.1 LEN=36 TOS=0x00 PREC=0x00 TTL=1 ID=0 DF PROTO=2 
Mar  5 00:07:36 ipfire kernel: DROP_INPUT IN=red0 OUT= MAC=xxx SRC=192.168.50.1 DST=224.0.0.1 LEN=36 TOS=0x00 PREC=0x00 TTL=1 ID=0 DF PROTO=2 
Mar  5 00:08:37 ipfire kernel: perf: interrupt took too long (5213 > 5203), lowering kernel.perf_event_max_sample_rate to 38100
Mar  5 00:09:41 ipfire kernel: DROP_INPUT IN=red0 OUT= MAC=xxx SRC=192.168.50.1 DST=224.0.0.1 LEN=36 TOS=0x00 PREC=0x00 TTL=1 ID=0 DF PROTO=2 
Mar  5 00:11:46 ipfire kernel: DROP_INPUT IN=red0 OUT= MAC=xxx SRC=192.168.50.1 DST=224.0.0.1 LEN=36 TOS=0x00 PREC=0x00 TTL=1 ID=0 DF PROTO=2 
Mar  5 00:12:54 ready in terminal

busy

jayjay73 · 21 March 2020 22:54

Exactly the same problem for me but with a different architecture (x86).
When starting, unbound launches sequentially lots of processes like these:

unbound-control local_zone_remove bing.com

and each one needs a few seconds to finish.

psyops · 23 March 2020 20:22

I’d updated 2 days ago and experienced the same Problem. My Blocklist is not that long (~120000 Entrys). I also have Problems with several URLs like e.g. de.wikipedia.org or the ntp.org servers. I just cant ping them and the systemlog contains a lot of resolve errors. I use the both google dns 8.8.8.8 8.8.4.4, which never caused Problems in the past.

jayjay73 · 25 March 2020 12:25

It seems that calling “unbound-control” is very slow when you have a blocklist (even a few thousands).

Can’t it be better to replace all calls to unbound-control in a config files, like I did before safesearch was implemented in ipfire, like this:

server:
local-data: “www.google.com A 216.239.38.120”
local-data: “www.google.ad A 216.239.38.120”
local-data: “www.google.ae A 216.239.38.120”
…

hjkl · 30 June 2022 13:56

Same here - blocklist has a big list and it takes dozens of minutes for unbound to go through this start section

local domain for domain in ${google_tlds[@]}; do unbound-control local_zone_remove "${domain}" done >/dev/null

wc /etc/unbound/local.d/blocklist.conf
  454811  1364445 22758027 /etc/unbound/local.d/blocklist.conf