Unbound crashing if blacklists enabled

[Ebeneezer]

Hi there,

After some researches, I haven't found any functionning fixes for my problem.
--> Unbound always end up crashing when blacklists are applied.

Only one error in logs : daemonize unbound dhcpd watcher.

Sometimes it starts and grab my blacklists, but when it does it's not blacklisting anything and blocked domains get resolved anyway.

Issue appeared after update.

Thanks to y'all

[chemlud]

Hi,

which blacklists are you trying to activate? Which update (previous, current version)?

[Ebeneezer]

Hi, thanks for your reply 

I'm running latest production version. I made a clean install to be sure everything is fine but same problem :
If Unbound doesn't hang on an error while starting, nothing gets blocked.

Here are Unbound's startup logs where blocklists (and any other interesting line ?) are visible :

Code: [Select]

2020-11-14T17:03:33 unbound[73481] blacklist download done in 67.20 seconds (639615 records)
2020-11-14T17:03:25 unbound[73481] blacklist download https://github.com/blocklistproject/Lists/blob/master/ransomware.txt (lines: 8827 exclude: 4160 black: 4419
2020-11-14T17:03:24 unbound[73481] blacklist download https://github.com/blocklistproject/Lists/blob/master/scam.txt (lines: 5909 exclude: 2702 black: 2958
2020-11-14T17:03:23 unbound[73481] blacklist download https://github.com/blocklistproject/Lists/blob/master/ads.txt (lines: 1059 exclude: 284 black: 538
2020-11-14T17:03:22 unbound[73481] blacklist download https://github.com/blocklistproject/Lists/blob/master/abuse.txt (lines: 1115 exclude: 311 black: 560
2020-11-14T17:03:22 unbound[73481] blacklist download https://github.com/blocklistproject/Lists/blob/master/tiktok.txt (lines: 1299 exclude: 397 black: 655
2020-11-14T17:03:21 unbound[73481] blacklist download https://github.com/blocklistproject/Lists/blob/master/tracking.txt (lines: 61478 exclude: 30486 black: 30744
2020-11-14T17:03:16 unbound[73481] blacklist download https://github.com/blocklistproject/Lists/blob/master/facebook.txt (lines: 9546 exclude: 4525 black: 4781
2020-11-14T17:03:15 unbound[73481] blacklist download https://raw.githubusercontent.com/jmdugan/blocklists/master/corporations/facebook/all (lines: 2098 exclude: 0 black: 2098
2020-11-14T17:03:15 unbound[73481] blacklist download http://pgl.yoyo.org/adservers/serverlist.php?hostformat=hosts&mimetype=plaintext (lines: 3573 exclude: 0 black: 3559
2020-11-14T17:03:14 unbound[73481] blacklist download https://raw.githubusercontent.com/crazy-max/WindowsSpyBlocker/master/data/hosts/extra.txt (lines: 243 exclude: 0 black: 237
2020-11-14T17:03:14 unbound[73481] blacklist download https://raw.githubusercontent.com/crazy-max/WindowsSpyBlocker/master/data/hosts/update.txt (lines: 537 exclude: 0 black: 531
2020-11-14T17:03:13 unbound[73481] blacklist download https://raw.githubusercontent.com/crazy-max/WindowsSpyBlocker/master/data/hosts/spy.txt (lines: 373 exclude: 0 black: 367
2020-11-14T17:03:13 unbound[73481] blacklist download https://raw.githubusercontent.com/StevenBlack/hosts/master/hosts (lines: 65904 exclude: 5 black: 59703
2020-11-14T17:03:09 unbound[73481] blacklist download https://s3.amazonaws.com/lists.disconnect.me/simple_tracking.txt (lines: 38 exclude: 0 black: 34
2020-11-14T17:03:08 unbound[73481] blacklist download https://s3.amazonaws.com/lists.disconnect.me/simple_ad.txt (lines: 2705 exclude: 0 black: 2701
2020-11-14T17:03:07 unbound[73481] blacklist download https://justdomains.github.io/blocklists/lists/nocoin-justdomains.txt (lines: 688 exclude: 0 black: 688
2020-11-14T17:03:07 unbound[73481] blacklist download https://justdomains.github.io/blocklists/lists/easyprivacy-justdomains.txt (lines: 7085 exclude: 0 black: 7085
2020-11-14T17:03:06 unbound[73481] blacklist download https://justdomains.github.io/blocklists/lists/easylist-justdomains.txt (lines: 17445 exclude: 0 black: 17445
2020-11-14T17:03:05 unbound[73481] blacklist download https://blocklistproject.github.io/Lists/tracking.txt (lines: 15082 exclude: 0 black: 15057
2020-11-14T17:03:04 unbound[73481] blacklist download https://blocklistproject.github.io/Lists/phishing.txt (lines: 189992 exclude: 0 black: 189968
2020-11-14T17:02:50 unbound[73481] blacklist download https://blocklistproject.github.io/Lists/facebook.txt (lines: 2115 exclude: 0 black: 2099
2020-11-14T17:02:50 unbound[73481] blacklist download https://blocklistproject.github.io/Lists/fraud.txt (lines: 196047 exclude: 0 black: 196025
2020-11-14T17:02:39 unbound[73481] blacklist download https://blocklistproject.github.io/Lists/ads.txt (lines: 154743 exclude: 2 black: 154687
2020-11-14T17:02:29 unbound[73481] blacklist download https://justdomains.github.io/blocklists/lists/adguarddns-justdomains.txt (lines: 37918 exclude: 0 black: 37918
2020-11-14T17:02:27 unbound[73481] blacklist download https://adaway.org/hosts.txt (lines: 13515 exclude: 2 black: 9286
2020-11-14T17:02:26 unbound[73481] blacklist download : exclude domains matching ^(?![a-zA-Z\d]).*|.*localhost$
2020-11-14T17:01:50 unbound[55058] blacklist download done in 0.00 seconds (0 records)
2020-11-14T17:00:09 unbound[82753] [82753:1] info: generate keytag query _ta-4f66. NULL IN
2020-11-14T17:00:07 unbound[82753] [82753:0] info: start of service (unbound 1.12.0).
2020-11-14T17:00:07 unbound[82753] [82753:0] notice: init module 1: iterator
2020-11-14T17:00:07 unbound[82753] [82753:0] notice: init module 0: validator
2020-11-14T16:59:57 unbound[34543] blacklist download done in 0.02 seconds (0 records)
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 32.000000 64.000000 3
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 16.000000 32.000000 9
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 8.000000 16.000000 4
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 4.000000 8.000000 4
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 2.000000 4.000000 6
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 1.000000 2.000000 14
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.524288 1.000000 23
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.262144 0.524288 37
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.131072 0.262144 59
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.065536 0.131072 72
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.032768 0.065536 119
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.016384 0.032768 140
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.008192 0.016384 2
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.002048 0.004096 3
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.000000 0.000001 17
2020-11-14T16:58:21 unbound[55085] [55085:0] info: lower(secs) upper(secs) recursions
2020-11-14T16:58:21 unbound[55085] [55085:0] info: [25%]=0.028789 median[50%]=0.058652 [75%]=0.19994
2020-11-14T16:58:21 unbound[55085] [55085:0] info: histogram of recursion processing times
2020-11-14T16:58:21 unbound[55085] [55085:0] info: average recursion processing time 0.931506 sec
2020-11-14T16:58:21 unbound[55085] [55085:0] info: server stats for thread 3: requestlist max 9 avg 0.583984 exceeded 0 jostled 0
2020-11-14T16:58:21 unbound[55085] [55085:0] info: server stats for thread 3: 1737 queries, 1225 answers from cache, 512 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 64.000000 128.000000 1
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 32.000000 64.000000 1
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 16.000000 32.000000 8
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 8.000000 16.000000 3
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 4.000000 8.000000 5
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 2.000000 4.000000 2
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 1.000000 2.000000 11
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.524288 1.000000 25
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.262144 0.524288 68
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.131072 0.262144 69
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.065536 0.131072 76
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.032768 0.065536 128
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.016384 0.032768 135
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.008192 0.016384 2
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.004096 0.008192 1
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.000000 0.000001 23
2020-11-14T16:58:21 unbound[55085] [55085:0] info: lower(secs) upper(secs) recursions
2020-11-14T16:58:21 unbound[55085] [55085:0] info: [25%]=0.0301587 median[50%]=0.062976 [75%]=0.2327
2020-11-14T16:58:21 unbound[55085] [55085:0] info: histogram of recursion processing times
2020-11-14T16:58:21 unbound[55085] [55085:0] info: average recursion processing time 0.805808 sec
2020-11-14T16:58:21 unbound[55085] [55085:0] info: server stats for thread 2: requestlist max 8 avg 0.732975 exceeded 0 jostled 0
2020-11-14T16:58:21 unbound[55085] [55085:0] info: server stats for thread 2: 1644 queries, 1086 answers from cache, 558 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 32.000000 64.000000 1
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 16.000000 32.000000 6
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 8.000000 16.000000 4
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 4.000000 8.000000 3
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 2.000000 4.000000 2
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 1.000000 2.000000 5
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.524288 1.000000 5
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.262144 0.524288 19
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.131072 0.262144 39
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.065536 0.131072 47
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.032768 0.065536 42
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.016384 0.032768 73
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.000000 0.000001 4
2020-11-14T16:58:21 unbound[55085] [55085:0] info: lower(secs) upper(secs) recursions
2020-11-14T16:58:21 unbound[55085] [55085:0] info: [25%]=0.0295136 median[50%]=0.0739023 [75%]=0.20333
2020-11-14T16:58:21 unbound[55085] [55085:0] info: histogram of recursion processing times
2020-11-14T16:58:21 unbound[55085] [55085:0] info: average recursion processing time 1.229330 sec
2020-11-14T16:58:21 unbound[55085] [55085:0] info: server stats for thread 1: requestlist max 3 avg 0.168 exceeded 0 jostled 0
2020-11-14T16:58:21 unbound[55085] [55085:0] info: server stats for thread 1: 597 queries, 347 answers from cache, 250 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 32.000000 64.000000 1
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 16.000000 32.000000 2
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 8.000000 16.000000 2
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 2.000000 4.000000 4
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 1.000000 2.000000 4
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.524288 1.000000 15
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.262144 0.524288 34
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.131072 0.262144 58
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.065536 0.131072 45
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.032768 0.065536 66
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.016384 0.032768 91
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.004096 0.008192 1
2020-11-14T16:58:21 unbound[55085] [55085:0] info: 0.000000 0.000001 7
2020-11-14T16:58:21 unbound[55085] [55085:0] info: lower(secs) upper(secs) recursions
2020-11-14T16:58:21 unbound[55085] [55085:0] info: [25%]=0.0297973 median[50%]=0.065536 [75%]=0.215817
2020-11-14T16:58:21 unbound[55085] [55085:0] info: histogram of recursion processing times
2020-11-14T16:58:21 unbound[55085] [55085:0] info: average recursion processing time 0.464253 sec
2020-11-14T16:58:21 unbound[55085] [55085:0] info: server stats for thread 0: requestlist max 5 avg 0.221212 exceeded 0 jostled 0
2020-11-14T16:58:21 unbound[55085] [55085:0] info: server stats for thread 0: 938 queries, 608 answers from cache, 330 recursions, 0 prefetch, 0 rejected by ip ratelimiting

[chemlud]

Hmmm, I enabled "adaway" in the GUI and restarted Unbound. If I ping hosts from the list (https://adaway.org/hosts.txt) they resolve as 127.0.0.1. So: Working here as expected...

[hushcoden]

I can't access that adaway host file, did Kaspersky go deranged...

[chemlud]

Stop using Windows for anything serious like managing your networks/router/firewall... (and this Kaspersky stuff as well...) ;-)

[Ebeneezer]

No cigar ! Still investigating,

Looks like there is a mismatch between DHCPdV4's way of handling the leases and Unbound

-->  https://github.com/opnsense/core/issues/3478

This is leading me on some tracks. I'll tinker with those ideas today and I will keep you updated even if something fails, in case someone's running in the same problem.

[Ebeneezer]

Took a minute to look at my old logs before restoring my offending router.

--> looks like there still is that DHCP lease file issue as per the link I posted earlier.

So :
- Did a clean install,
- Partial restore of my previous configuration backup OMITING : DHCPdV4 and Unbound parameters,
- Forced refresh of DNSBL and PF's aliases,
- Single computer with hostname set to be grabed from DHCP from LAN <-- for testing purposes.

Right now everythings is working OK. I will keep an eye on logs and enable the rest of my network piece by piece including my home servers, combing each kink after each kink.

I'll keep you updated

[Ebeneezer]

Hi there !

Followup : Same problem happened atfer I applied last update.

Looks like Unbound with DNS blacklists + DHCPdV4 are'nt getting along...
I may post whatever log output that may help on the matter.

But I may first need to be pointed at a direction
Any dev here ?