Unbound errors in log file

[lar.hed]

This was fast ;D

Sorry folks, it still goes 100% CPU on one core.
Did a diff on the root.hints file - no difference at all.
The change for local gathering for statistics, seems to made no difference.

The Unbopund log (debug level this time):

Code Select Expand

2024-01-07T18:42:24 Notice unbound daemonize unbound dhcpd watcher.
2024-01-07T18:42:24 Informational unbound [37651:6] info: generate keytag query _ta-4f66. NULL IN
2024-01-07T18:42:24 Informational unbound [37651:0] info: start of service (unbound 1.19.0).
2024-01-07T18:42:24 Notice unbound [37651:0] notice: init module 2: iterator
2024-01-07T18:42:24 Notice unbound [37651:0] notice: init module 1: validator
2024-01-07T18:42:18 Informational unbound [37651:0] info: dnsbl_module: blocklist loaded. length is 3668143
2024-01-07T18:42:14 Informational unbound [37651:0] info: dnsbl_module: updating blocklist.
2024-01-07T18:42:14 Notice unbound [37651:0] notice: init module 0: python
2024-01-07T18:38:38 Informational unbound [85050:0] info: service stopped (unbound 1.19.0).
2024-01-07T18:28:13 Informational unbound [85050:4] info: generate keytag query _ta-4f66. NULL IN
2024-01-07T18:22:46 Informational unbound [85050:2] info: generate keytag query _ta-4f66. NULL IN
2024-01-07T18:14:47 Informational unbound [85050:6] info: generate keytag query _ta-4f66. NULL IN
2024-01-07T18:02:18 Notice unbound dhcpd entry changed Chromecast-Ultra.local @ 10.168.3.39.
2024-01-07T18:02:17 Notice unbound daemonize unbound dhcpd watcher.
2024-01-07T18:02:17 Informational unbound [85050:5] info: generate keytag query _ta-4f66. NULL IN
2024-01-07T18:02:17 Critical unbound [85050:3] fatal error: Could not initialize thread
2024-01-07T18:02:17 Informational unbound [85050:3] info: server stats for thread 3: requestlist max 0 avg 0 exceeded 0 jostled 0
2024-01-07T18:02:17 Informational unbound [85050:3] info: server stats for thread 3: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2024-01-07T18:02:17 Error unbound [85050:3] error: Could not set root or stub hints
2024-01-07T18:02:17 Warning unbound [85050:1] warning: root hints /root.hints:48 skipping type AAAA
2024-01-07T18:02:17 Informational unbound [85050:0] info: start of service (unbound 1.19.0).
2024-01-07T18:02:17 Error unbound [85050:3] error: reading root hints /root.hints 2:12: Syntax error, could not parse the RR's type
2024-01-07T18:02:17 Notice unbound [85050:0] notice: init module 2: iterator
2024-01-07T18:02:17 Notice unbound [85050:0] notice: init module 1: validator
2024-01-07T18:02:11 Informational unbound [85050:0] info: dnsbl_module: blocklist loaded. length is 3668143
2024-01-07T18:02:07 Informational unbound [85050:0] info: dnsbl_module: updating blocklist.
2024-01-07T18:02:07 Notice unbound [85050:0] notice: init module 0: python
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.524288 1.000000 2
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.262144 0.524288 19
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.131072 0.262144 204
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.065536 0.131072 51
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.032768 0.065536 209
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.016384 0.032768 11
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.008192 0.016384 4
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.004096 0.008192 16
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.002048 0.004096 19
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.001024 0.002048 1
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.000000 0.000001 50
2024-01-07T18:02:04 Informational unbound [28156:0] info: lower(secs) upper(secs) recursions
2024-01-07T18:02:04 Informational unbound [28156:0] info: [25%]=0.0399017 median[50%]=0.0628707 [75%]=0.181509
2024-01-07T18:02:04 Informational unbound [28156:0] info: histogram of recursion processing times
2024-01-07T18:02:04 Informational unbound [28156:0] info: average recursion processing time 0.106474 sec
2024-01-07T18:02:04 Informational unbound [28156:0] info: server stats for thread 7: requestlist max 2 avg 0.0733788 exceeded 0 jostled 0
2024-01-07T18:02:04 Informational unbound [28156:0] info: server stats for thread 7: 1272 queries, 686 answers from cache, 586 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.524288 1.000000 1
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.262144 0.524288 24
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.131072 0.262144 246
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.065536 0.131072 55
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.032768 0.065536 236
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.016384 0.032768 24
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.008192 0.016384 13
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.004096 0.008192 15
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.002048 0.004096 19
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.001024 0.002048 1
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.000000 0.000001 57
2024-01-07T18:02:04 Informational unbound [28156:0] info: lower(secs) upper(secs) recursions
2024-01-07T18:02:04 Informational unbound [28156:0] info: [25%]=0.0388426 median[50%]=0.0628285 [75%]=0.183421
2024-01-07T18:02:04 Informational unbound [28156:0] info: histogram of recursion processing times
2024-01-07T18:02:04 Informational unbound [28156:0] info: average recursion processing time 0.107350 sec
2024-01-07T18:02:04 Informational unbound [28156:0] info: server stats for thread 6: requestlist max 3 avg 0.0998553 exceeded 0 jostled 0
2024-01-07T18:02:04 Informational unbound [28156:0] info: server stats for thread 6: 1603 queries, 912 answers from cache, 691 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.524288 1.000000 2
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.262144 0.524288 27
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.131072 0.262144 225
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.065536 0.131072 47
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.032768 0.065536 204
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.016384 0.032768 21
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.008192 0.016384 6
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.004096 0.008192 10
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.002048 0.004096 14
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.000000 0.000001 53
2024-01-07T18:02:04 Informational unbound [28156:0] info: lower(secs) upper(secs) recursions
2024-01-07T18:02:04 Informational unbound [28156:0] info: [25%]=0.0405183 median[50%]=0.0649738 [75%]=0.190346
2024-01-07T18:02:04 Informational unbound [28156:0] info: histogram of recursion processing times
2024-01-07T18:02:04 Informational unbound [28156:0] info: average recursion processing time 0.112311 sec
2024-01-07T18:02:04 Informational unbound [28156:0] info: server stats for thread 5: requestlist max 2 avg 0.0901639 exceeded 0 jostled 0
2024-01-07T18:02:04 Informational unbound [28156:0] info: server stats for thread 5: 1286 queries, 676 answers from cache, 610 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.524288 1.000000 2
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.262144 0.524288 22
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.131072 0.262144 238
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.065536 0.131072 58
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.032768 0.065536 200
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.016384 0.032768 13
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.008192 0.016384 10
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.004096 0.008192 9
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.002048 0.004096 22
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.001024 0.002048 1
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.000000 0.000001 52
2024-01-07T18:02:04 Informational unbound [28156:0] info: lower(secs) upper(secs) recursions
2024-01-07T18:02:04 Informational unbound [28156:0] info: [25%]=0.040919 median[50%]=0.0728806 [75%]=0.189036
2024-01-07T18:02:04 Informational unbound [28156:0] info: histogram of recursion processing times
2024-01-07T18:02:04 Informational unbound [28156:0] info: average recursion processing time 0.111973 sec
2024-01-07T18:02:04 Informational unbound [28156:0] info: server stats for thread 4: requestlist max 2 avg 0.110048 exceeded 0 jostled 0
2024-01-07T18:02:04 Informational unbound [28156:0] info: server stats for thread 4: 1793 queries, 1166 answers from cache, 627 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.524288 1.000000 1
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.262144 0.524288 23
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.131072 0.262144 251
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.065536 0.131072 49
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.032768 0.065536 210
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.016384 0.032768 21
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.008192 0.016384 4
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.004096 0.008192 22
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.002048 0.004096 17
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.000000 0.000001 54
2024-01-07T18:02:04 Informational unbound [28156:0] info: lower(secs) upper(secs) recursions
2024-01-07T18:02:04 Informational unbound [28156:0] info: [25%]=0.0397897 median[50%]=0.0652239 [75%]=0.189558
2024-01-07T18:02:04 Informational unbound [28156:0] info: histogram of recursion processing times
2024-01-07T18:02:04 Informational unbound [28156:0] info: average recursion processing time 0.109149 sec
2024-01-07T18:02:04 Informational unbound [28156:0] info: server stats for thread 3: requestlist max 2 avg 0.0996933 exceeded 0 jostled 0
2024-01-07T18:02:04 Informational unbound [28156:0] info: server stats for thread 3: 1062 queries, 410 answers from cache, 652 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.262144 0.524288 21
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.131072 0.262144 215
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.065536 0.131072 58
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.032768 0.065536 219
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.016384 0.032768 10
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.008192 0.016384 7
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.004096 0.008192 12
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.002048 0.004096 16
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.001024 0.002048 1
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.000000 0.000001 50
2024-01-07T18:02:04 Informational unbound [28156:0] info: lower(secs) upper(secs) recursions
2024-01-07T18:02:04 Informational unbound [28156:0] info: [25%]=0.0411844 median[50%]=0.0639649 [75%]=0.182129
2024-01-07T18:02:04 Informational unbound [28156:0] info: histogram of recursion processing times
2024-01-07T18:02:04 Informational unbound [28156:0] info: average recursion processing time 0.106370 sec
2024-01-07T18:02:04 Informational unbound [28156:0] info: server stats for thread 2: requestlist max 2 avg 0.1 exceeded 0 jostled 0
2024-01-07T18:02:04 Informational unbound [28156:0] info: server stats for thread 2: 1277 queries, 667 answers from cache, 610 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2024-01-07T18:02:04 Informational unbound [28156:0] info: 1.000000 2.000000 1
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.262144 0.524288 28
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.131072 0.262144 261
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.065536 0.131072 56
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.032768 0.065536 205
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.016384 0.032768 20
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.008192 0.016384 3
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.004096 0.008192 11
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.002048 0.004096 19
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.001024 0.002048 5
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.000000 0.000001 52
2024-01-07T18:02:04 Informational unbound [28156:0] info: lower(secs) upper(secs) recursions
2024-01-07T18:02:04 Informational unbound [28156:0] info: [25%]=0.0415994 median[50%]=0.0836754 [75%]=0.19372
2024-01-07T18:02:04 Informational unbound [28156:0] info: histogram of recursion processing times
2024-01-07T18:02:04 Informational unbound [28156:0] info: average recursion processing time 0.116842 sec
2024-01-07T18:02:04 Informational unbound [28156:0] info: server stats for thread 1: requestlist max 2 avg 0.0996979 exceeded 0 jostled 0
2024-01-07T18:02:04 Informational unbound [28156:0] info: server stats for thread 1: 1586 queries, 924 answers from cache, 662 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.524288 1.000000 1
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.262144 0.524288 22
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.131072 0.262144 240
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.065536 0.131072 43
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.032768 0.065536 203
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.016384 0.032768 18
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.008192 0.016384 4
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.004096 0.008192 9
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.002048 0.004096 13
2024-01-07T18:02:04 Informational unbound [28156:0] info: 0.000000 0.000001 59
2024-01-07T18:02:04 Informational unbound [28156:0] info: lower(secs) upper(secs) recursions
2024-01-07T18:02:04 Informational unbound [28156:0] info: [25%]=0.0408389 median[50%]=0.065536 [75%]=0.191147
2024-01-07T18:02:04 Informational unbound [28156:0] info: histogram of recursion processing times
2024-01-07T18:02:04 Informational unbound [28156:0] info: average recursion processing time 0.114222 sec
2024-01-07T18:02:04 Informational unbound [28156:0] info: server stats for thread 0: requestlist max 3 avg 0.109477 exceeded 0 jostled 0
2024-01-07T18:02:04 Informational unbound [28156:0] info: server stats for thread 0: 1048 queries, 436 answers from cache, 612 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2024-01-07T18:02:04 Informational unbound [28156:0] info: service stopped (unbound 1.19.0).
2024-01-07T17:59:48 Informational unbound [28156:6] info: generate keytag query _ta-4f66. NULL IN

[lar.hed]

I got the first Monit message at 18.06 - for high Unbound CPU.

So from 18.02 to 18.06 something happened, and as far as I can say, I have nothing else from restart yesterday, so all this is buildup until high CPU. Killed the Unbound process and everything started it self by Monit...

[Fright]

Hi
so how many "generate template OPNsense/Unbound/*" messages in Backend log you see around 18:02
IMHO: now it realy looks like the 'root.hints'-error causes CPU load and indicates a race:
in 18:02 something (newwanip?) triggers graceful unbound restart.
for some reason templates reloads twice (or something calls unbound restart two times in a row)
18:02:07 - unbound starts. main thread ([85050:0])  is initialized succesfully.
18:02:17 - fourth thread ([85050:3]) getting error reading root.hints. and the problems begins: thread could not be initialized.

and I think it's a template update overlay.
the following errors (high cpu, py-module error because of logging queue etc) are the consequences of the first one.

Technically, the root hints error itself can be solved by simply transferring the copying of the roots file from the templates to the start script, but in my opinion this will only mask a possible race problem

I can try to make a debug patch (setting config lock on unbound reload to handle concurrency. and couple of debug syslog messages to catch possible interference) to confirm this theory if you are ready to try, but I warn you right away that @franco is unlikely to accept it  ;), so this is only for the sake of finding the reason.
do you want to continue with it?

[lar.hed]

Well no don't make that debug patch 8)

Here is the Backend log part that is relevant (timewise - nothing is filtered):

Code Select Expand

2024-01-07T18:05:07 Informational configd.py message 4dd90b66-4d22-4b19-92ff-b1d1e1531650 [] returned {"status": "ok"}
2024-01-07T18:05:05 Notice configd.py [4dd90b66-4d22-4b19-92ff-b1d1e1531650] refresh url table aliases
2024-01-07T18:05:05 Debug configd.py OPNsense/Filter generated //usr/local/etc/filter_geoip.conf
2024-01-07T18:05:05 Debug configd.py OPNsense/Filter generated //usr/local/etc/filter_tables.conf
2024-01-07T18:05:05 Notice configd.py generate template container OPNsense/Filter
2024-01-07T18:05:05 Notice configd.py [199b3cd4-e735-4ad9-a83f-d268c00c96b8] generate template OPNsense/Filter
2024-01-07T18:05:05 Notice configd.py [95daef78-b6ce-4fb6-9737-0bf1bc0eeb6f] request pf current overall table record count and table-entries limit
2024-01-07T18:05:05 Notice configd.py [f869e948-9749-48b9-b397-becc20eb0d58] Reloading filter
2024-01-07T18:05:05 Notice configd.py [a4bad4e9-0f00-4676-8628-bbae07dbab33] Linkup stopping igb2
2024-01-07T18:02:09 Informational configd.py message ea12181a-83c5-41d2-a835-a458a224f9dd [] returned {"status": "ok"}
2024-01-07T18:02:07 Notice configd.py [ea12181a-83c5-41d2-a835-a458a224f9dd] refresh url table aliases
2024-01-07T18:02:07 Debug configd.py OPNsense/Filter generated //usr/local/etc/filter_geoip.conf
2024-01-07T18:02:07 Debug configd.py OPNsense/Filter generated //usr/local/etc/filter_tables.conf
2024-01-07T18:02:07 Notice configd.py generate template container OPNsense/Filter
2024-01-07T18:02:07 Notice configd.py [13a450cc-6921-4ddc-9dd8-730900ce344c] generate template OPNsense/Filter
2024-01-07T18:02:07 Notice configd.py [df6da6c6-02e0-498b-a2d0-30d658c6e5bf] request pf current overall table record count and table-entries limit
2024-01-07T18:02:07 Notice configd.py [ba3697d2-4f99-4685-83cf-7024ebdb853d] Reloading filter
2024-01-07T18:02:07 Debug configd.py OPNsense/Unbound/* generated //var/unbound/dnsbl_module.py
2024-01-07T18:02:07 Debug configd.py OPNsense/Unbound/* generated //usr/local/etc/unbound_dhcpd.conf
2024-01-07T18:02:07 Debug configd.py OPNsense/Unbound/* generated //var/unbound/root.hints
2024-01-07T18:02:07 Debug configd.py OPNsense/Unbound/* generated //usr/local/etc/unbound.opnsense.d/domainoverrides.conf
2024-01-07T18:02:07 Debug configd.py OPNsense/Unbound/* generated //var/unbound/private_domains.conf
2024-01-07T18:02:07 Debug configd.py OPNsense/Unbound/* generated //usr/local/etc/unbound.opnsense.d/dot.conf
2024-01-07T18:02:07 Debug configd.py OPNsense/Unbound/* generated //usr/local/etc/unbound.opnsense.d/safesearch.conf
2024-01-07T18:02:07 Debug configd.py OPNsense/Unbound/* generated //usr/local/etc/unbound/unbound-blocklists.conf
2024-01-07T18:02:07 Debug configd.py OPNsense/Unbound/* generated //var/unbound/advanced.conf
2024-01-07T18:02:07 Debug configd.py OPNsense/Unbound/* generated //usr/local/etc/unbound.opnsense.d/access_lists.conf
2024-01-07T18:02:06 Notice configd.py generate template container OPNsense/Unbound/core
2024-01-07T18:02:06 Notice configd.py [845009ff-3d47-4a02-8ecb-31dae814a7f4] generate template OPNsense/Unbound/*
2024-01-07T18:02:04 Notice configd.py [8bff90af-0236-4591-aecb-c8eee9a2d294] Unbound cache dump
2024-01-07T18:02:04 Notice configd.py [4d9a903a-6cc2-483d-8a35-87a314696807] IPsec list legacy VirtualTunnelInterfaces
2024-01-07T18:02:03 Notice configd.py [b30542a5-be9f-45e7-b97b-5c11196af383] IPsec list legacy VirtualTunnelInterfaces
2024-01-07T18:02:03 Notice configd.py [d45e17ac-cd7d-4729-ab0e-772a2f94a385] IPsec list legacy VirtualTunnelInterfaces
2024-01-07T18:02:03 Notice configd.py [e7629d0f-173b-467e-be24-09bedb725278] IPsec list legacy VirtualTunnelInterfaces
2024-01-07T18:02:03 Notice configd.py [6cea4525-a359-4cf3-bf50-41823acbc6c3] IPsec list legacy VirtualTunnelInterfaces
2024-01-07T18:02:03 Notice configd.py [4d13d470-26fa-4614-9961-74f7b0c5fa2d] IPsec list legacy VirtualTunnelInterfaces
2024-01-07T18:02:03 Notice configd.py [2939037b-d524-4f65-b0b7-629a7f30c203] IPsec list legacy VirtualTunnelInterfaces
2024-01-07T18:02:03 Notice configd.py [4d3a183f-26b3-4ab2-b735-fa99667799c8] show system routing table
2024-01-07T18:02:03 Notice configd.py [7dd72e10-23ef-47e7-853e-ea3d4377d3da] IPsec list legacy VirtualTunnelInterfaces
2024-01-07T18:02:03 Notice configd.py [78cb954e-a948-4d41-960d-85f31c64dc3c] Linkup starting igb2
2024-01-07T18:01:00 Informational configd.py message b9bb91cc-09f0-49db-95cc-c4276d0d8252 [] returned OK
2024-01-07T18:01:00 Notice configd.py [b9bb91cc-09f0-49db-95cc-c4276d0d8252] Archive syslog files

Regarding roots.hint - since the files are 100% identical I can not see that as an issue at all. Also do remember that Unbound 1.04 worked without hickups, 1.08 "Unbound Plus" has this challenge.

I agree on your thoughts, all the things that happens are results of something else - it is not the 100% CPU on one core and so on - that is just the result of something else going wrong direction. I can use them, high CPU and high temp, as triggers in Monit to restart - but that is just a workaround kind of....

The igbd2 interface is where my PC (the one I write this on) is attached to. It goes up/down when start/stopping the PC. And in this case I think I had been working on the PC for a while, went away and it could have got into stand by maybe. However I would like to point out that this issue I have happens even when no one is home... So even though it may or may not be connected - it is well not that easy I think. I might also point into this thread where I had issues after the upgrade that started all - it got a thing about the igb2 issue:
https://forum.opnsense.org/index.php?topic=36807.msg180150#msg180150

It seems I go round and round on the same challenges: Unbound and link up/down - it is a bit of a challenge?

[lar.hed]

I guess I will regret this at a later date:

I think, after going over Unbound and FreeBSD issues, that this is actually an OS challenge. So I will have my bandaid running (high CPU on Unbound, kill Unbound and restart - it is by default the wrong solution I think, but I do not think we will find any OPNsense thingi to solve this, so it is what it is), and hope that when OPNsense comes out with next version of FreeBSD, this challenge will just go away by it self.

The alternative, for me, is to remove Unbound from the setup - and find other ways for DoT, DNSSEC, BlockLists and more things that Unbound can do...

[enpassant]

I have been watching this thread for a bit. Some of the challenges you are experiencing, lar.hed, are similar to a case I just resolved. You might take a look at this thread to see if it's helpful. Not sure... it might be helpful:

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

[lar.hed]

Thanks for your tip enpassant.

I do notice one difference (well I have an i7 8550U CPU, while you use the i5 version) and that is you are using ZFS - I use UFS. Might not be that big a thing, except for my current theories of OS challenge deep down. I know it is a bit of a long shot, but when OPNsense gets FreeBSD 14.1-Relese sometime in the future we will know 8)

I will "any day now" reinstall and move to ZFS my self - I need the ability to roll back new versions of OPNsense - and see what and if something changes. In the end I would very much like to get Unbound to work. Just changing to another plugin/software might remove my challenges, but it has not solve the challenge, so I prefer to not change Unbound. And I do like Unbound from earlier year. And please remember that Unbound worked before I got 23.7.xxxxx with the exact same config. So No I will not give up on Unbound - this most likely is not an Unbound thing, it is more of a symptom....

[enpassant]

Unbound started failing for me around the same time as your failure. I do think that these issues are related, so we will "wait and see." I wish you the best in getting it resolved. Try to hang in there. My experience is that you are one setting change away from your resolution. Be well!

[CJ]

I don't think it's an OS challenge as it's working for plenty of folks.  I have DoT, DNSSEC Support, and Blocklists all enabled on my Unbound and it's working just fine.  Zero issues with excessive cpu load or hanging.  I am running ZFS but I don't think that would be a factor.

I know it's a huge pain, but it may be worthwhile to do a clean install and then slowly add things back in.  Hopefully that will allow you to pinpoint the problem.  Additionally, it's a good chance to switch over to ZFS, which I would recommend over running UFS. :)

[lar.hed]

I don't think it's an OS challenge as it's working for plenty of folks.  I have DoT, DNSSEC Support, and Blocklists all enabled on my Unbound and it's working just fine.  Zero issues with excessive cpu load or hanging.  I am running ZFS but I don't think that would be a factor.

You are most likely correct, as I wrote I might have to regret that statement - however there are some things I do not like with UFS (which is the FS I choose to run) which from time to time have it challenges on other installations I have knowledge about. But I never thought ZFS was an option with just one disc - so well, my misstake.

I know it's a huge pain, but it may be worthwhile to do a clean install and then slowly add things back in.  Hopefully that will allow you to pinpoint the problem.  Additionally, it's a good chance to switch over to ZFS, which I would recommend over running UFS. :)

Well that is most likely happen within 24 hours since I decided anyway to move to ZFS - so it will be a "bonus" with a clean install. Hmmm or are you saying a clean install and NO restore of backup file (which is more or less what I intended to do)? and build EVERYthing from ground up? Now THAT is a heck of a lot more work....

[CJ]

You are most likely correct, as I wrote I might have to regret that statement - however there are some things I do not like with UFS (which is the FS I choose to run) which from time to time have it challenges on other installations I have knowledge about. But I never thought ZFS was an option with just one disc - so well, my misstake.

There are some things you lose out on when using only one disk with ZFS, but it's still beneficial over UFS.  Keep in mind that your memory usage will increase as ZFS will use some of it for a cache.  I'm not sure what OPNsense has it tuned for but my usage doubled.  Although I'm still only using 2G out of the 8G in the system.

Well that is most likely happen within 24 hours since I decided anyway to move to ZFS - so it will be a "bonus" with a clean install. Hmmm or are you saying a clean install and NO restore of backup file (which is more or less what I intended to do)? and build EVERYthing from ground up? Now THAT is a heck of a lot more work....

Yes.  Not using the config file and doing things manually is what I'm recommending.  I don't know your setup so I can't speak to the amount of work it would entail, but it would be the best method for accurately determining the source of the issue.

Depending on what you have and your time constraints, you may try doing selective imports of the config.  Either import just the Unbound section and see if that causes problems by itself, or manually configure Unbound only, then once you confirm it's working correctly, slowly import sections until you recreate the issue.

[lar.hed]

So I did a clean re-install of OPNsense, this time on ZFS, and then did a full restore of config file (way to many firewall rules to rewrite everything). It has now been up for 50 hours, and counting. No Unbound 100% CPU core thingi, however Unbound decided to just vansih in one point, and Monit script for checking if Unbound is running restarted Unbound. But this was NOT due to 100% CPU - it was something else....

Code Select Expand

2024-01-14T11:38:30 Notice unbound daemonize unbound dhcpd watcher.
2024-01-14T11:38:30 Notice unbound [44346:0] notice: init module 2: iterator
2024-01-14T11:38:30 Notice unbound [44346:0] notice: init module 1: validator
2024-01-14T11:38:30 Notice unbound [44346:0] notice: init module 0: python
2024-01-14T11:37:59 Notice unbound dhcpd entry changed Galaxy-Tab-S7.local @ 10.168.3.34.
2024-01-14T11:37:54 Notice unbound daemonize unbound dhcpd watcher.
2024-01-14T11:37:54 Critical unbound [93074:4] fatal error: Could not initialize thread
2024-01-14T11:37:54 Critical unbound [93074:1] fatal error: Could not initialize thread
2024-01-14T11:37:54 Error unbound [93074:1] error: Could not set root or stub hints
2024-01-14T11:37:54 Error unbound [93074:1] error: reading root hints /root.hints 34:29: Syntax error, could not parse the RR's class
2024-01-14T11:37:54 Error unbound [93074:4] error: Could not set root or stub hints
2024-01-14T11:37:54 Error unbound [93074:4] error: reading root hints /root.hints 2:16: Syntax error, could not parse the RR's type
2024-01-14T11:37:54 Notice unbound [93074:0] notice: init module 2: iterator
2024-01-14T11:37:54 Notice unbound [93074:0] notice: init module 1: validator
2024-01-14T11:37:54 Notice unbound [93074:0] notice: init module 0: python

Is this the root.hints stuff that some have run into?

[lar.hed]

So just a moment ago I got the same 100% CPU stuff again, so running UFS vs ZFS seems of course not to matter at all. Here is the relevant part of Unbound log - any ideas? or comments?

Code Select Expand

2024-01-16T19:32:02 Informational unbound [63234:7] info: generate keytag query _ta-4f66. NULL IN
2024-01-16T19:32:02 Notice unbound daemonize unbound dhcpd watcher.
2024-01-16T19:32:01 Informational unbound [63234:0] info: start of service (unbound 1.19.0).
2024-01-16T19:32:01 Notice unbound [63234:0] notice: init module 2: iterator
2024-01-16T19:32:01 Notice unbound [63234:0] notice: init module 1: validator
2024-01-16T19:32:01 Notice unbound [63234:0] notice: init module 0: python
2024-01-16T19:26:48 Informational unbound [79537:3] info: generate keytag query _ta-4f66. NULL IN
2024-01-16T19:26:47 Notice unbound daemonize unbound dhcpd watcher.
2024-01-16T19:26:47 Critical unbound [79537:1] fatal error: Could not initialize thread
2024-01-16T19:26:47 Informational unbound [79537:0] info: start of service (unbound 1.19.0).
2024-01-16T19:26:47 Informational unbound [79537:1] info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
2024-01-16T19:26:47 Informational unbound [79537:1] info: server stats for thread 1: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2024-01-16T19:26:47 Error unbound [79537:1] error: Could not set root or stub hints
2024-01-16T19:26:47 Error unbound [79537:1] error: reading root hints /root.hints 2:37: Syntax error, could not parse the RR's type
2024-01-16T19:26:47 Notice unbound [79537:0] notice: init module 2: iterator
2024-01-16T19:26:47 Notice unbound [79537:0] notice: init module 1: validator
2024-01-16T19:26:47 Notice unbound [79537:0] notice: init module 0: python
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.262144 0.524288 4
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.131072 0.262144 13
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.065536 0.131072 23
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.032768 0.065536 26
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.016384 0.032768 4
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.008192 0.016384 3
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.004096 0.008192 10
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.002048 0.004096 4
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.000000 0.000001 1
2024-01-16T19:26:46 Informational unbound [71805:0] info: lower(secs) upper(secs) recursions
2024-01-16T19:26:46 Informational unbound [71805:0] info: [25%]=0.032768 median[50%]=0.0604948 [75%]=0.116825
2024-01-16T19:26:46 Informational unbound [71805:0] info: histogram of recursion processing times
2024-01-16T19:26:46 Informational unbound [71805:0] info: average recursion processing time 0.085532 sec
2024-01-16T19:26:46 Informational unbound [71805:0] info: server stats for thread 7: requestlist max 2 avg 0.170455 exceeded 0 jostled 0
2024-01-16T19:26:46 Informational unbound [71805:0] info: server stats for thread 7: 94 queries, 6 answers from cache, 88 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.262144 0.524288 2
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.131072 0.262144 15
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.065536 0.131072 9
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.032768 0.065536 24
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.016384 0.032768 3
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.008192 0.016384 2
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.004096 0.008192 2
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.002048 0.004096 2
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.000000 0.000001 1
2024-01-16T19:26:46 Informational unbound [71805:0] info: lower(secs) upper(secs) recursions
2024-01-16T19:26:46 Informational unbound [71805:0] info: [25%]=0.0395947 median[50%]=0.0600747 [75%]=0.148548
2024-01-16T19:26:46 Informational unbound [71805:0] info: histogram of recursion processing times
2024-01-16T19:26:46 Informational unbound [71805:0] info: average recursion processing time 0.094048 sec
2024-01-16T19:26:46 Informational unbound [71805:0] info: server stats for thread 6: requestlist max 1 avg 0.1 exceeded 0 jostled 0
2024-01-16T19:26:46 Informational unbound [71805:0] info: server stats for thread 6: 71 queries, 11 answers from cache, 60 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.262144 0.524288 3
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.131072 0.262144 16
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.065536 0.131072 9
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.032768 0.065536 20
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.016384 0.032768 7
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.008192 0.016384 2
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.004096 0.008192 3
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.002048 0.004096 2
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.000000 0.000001 5
2024-01-16T19:26:46 Informational unbound [71805:0] info: lower(secs) upper(secs) recursions
2024-01-16T19:26:46 Informational unbound [71805:0] info: [25%]=0.0275017 median[50%]=0.0565248 [75%]=0.149504
2024-01-16T19:26:46 Informational unbound [71805:0] info: histogram of recursion processing times
2024-01-16T19:26:46 Informational unbound [71805:0] info: average recursion processing time 0.088550 sec
2024-01-16T19:26:46 Informational unbound [71805:0] info: server stats for thread 5: requestlist max 2 avg 0.223881 exceeded 0 jostled 0
2024-01-16T19:26:46 Informational unbound [71805:0] info: server stats for thread 5: 79 queries, 12 answers from cache, 67 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.262144 0.524288 1
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.131072 0.262144 13
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.065536 0.131072 9
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.032768 0.065536 19
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.016384 0.032768 4
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.008192 0.016384 4
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.004096 0.008192 4
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.002048 0.004096 2
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.000000 0.000001 6
2024-01-16T19:26:46 Informational unbound [71805:0] info: lower(secs) upper(secs) recursions
2024-01-16T19:26:46 Informational unbound [71805:0] info: [25%]=0.01536 median[50%]=0.0517389 [75%]=0.120149
2024-01-16T19:26:46 Informational unbound [71805:0] info: histogram of recursion processing times
2024-01-16T19:26:46 Informational unbound [71805:0] info: average recursion processing time 0.082014 sec
2024-01-16T19:26:46 Informational unbound [71805:0] info: server stats for thread 4: requestlist max 2 avg 0.112903 exceeded 0 jostled 0
2024-01-16T19:26:46 Informational unbound [71805:0] info: server stats for thread 4: 69 queries, 7 answers from cache, 62 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.262144 0.524288 4
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.131072 0.262144 19
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.065536 0.131072 12
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.032768 0.065536 31
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.016384 0.032768 4
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.008192 0.016384 5
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.004096 0.008192 6
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.000000 0.000001 6
2024-01-16T19:26:46 Informational unbound [71805:0] info: lower(secs) upper(secs) recursions
2024-01-16T19:26:46 Informational unbound [71805:0] info: [25%]=0.0335608 median[50%]=0.0565512 [75%]=0.139695
2024-01-16T19:26:46 Informational unbound [71805:0] info: histogram of recursion processing times
2024-01-16T19:26:46 Informational unbound [71805:0] info: average recursion processing time 0.087598 sec
2024-01-16T19:26:46 Informational unbound [71805:0] info: server stats for thread 3: requestlist max 2 avg 0.218391 exceeded 0 jostled 0
2024-01-16T19:26:46 Informational unbound [71805:0] info: server stats for thread 3: 93 queries, 6 answers from cache, 87 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.262144 0.524288 3
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.131072 0.262144 15
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.065536 0.131072 13
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.032768 0.065536 27
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.016384 0.032768 9
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.008192 0.016384 6
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.004096 0.008192 1
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.001024 0.002048 1
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.000000 0.000001 6
2024-01-16T19:26:46 Informational unbound [71805:0] info: lower(secs) upper(secs) recursions
2024-01-16T19:26:46 Informational unbound [71805:0] info: [25%]=0.0277618 median[50%]=0.0540065 [75%]=0.119729
2024-01-16T19:26:46 Informational unbound [71805:0] info: histogram of recursion processing times
2024-01-16T19:26:46 Informational unbound [71805:0] info: average recursion processing time 0.081742 sec
2024-01-16T19:26:46 Informational unbound [71805:0] info: server stats for thread 2: requestlist max 1 avg 0.185185 exceeded 0 jostled 0
2024-01-16T19:26:46 Informational unbound [71805:0] info: server stats for thread 2: 347 queries, 266 answers from cache, 81 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.262144 0.524288 1
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.131072 0.262144 20
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.065536 0.131072 16
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.032768 0.065536 22
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.016384 0.032768 3
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.008192 0.016384 3
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.004096 0.008192 2
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.000000 0.000001 2
2024-01-16T19:26:46 Informational unbound [71805:0] info: lower(secs) upper(secs) recursions
2024-01-16T19:26:46 Informational unbound [71805:0] info: [25%]=0.0435665 median[50%]=0.075776 [75%]=0.155648
2024-01-16T19:26:46 Informational unbound [71805:0] info: histogram of recursion processing times
2024-01-16T19:26:46 Informational unbound [71805:0] info: average recursion processing time 0.101185 sec
2024-01-16T19:26:46 Informational unbound [71805:0] info: server stats for thread 1: requestlist max 1 avg 0.101449 exceeded 0 jostled 0
2024-01-16T19:26:46 Informational unbound [71805:0] info: server stats for thread 1: 81 queries, 12 answers from cache, 69 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.262144 0.524288 2
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.131072 0.262144 21
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.065536 0.131072 12
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.032768 0.065536 19
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.016384 0.032768 7
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.008192 0.016384 2
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.004096 0.008192 4
2024-01-16T19:26:46 Informational unbound [71805:0] info: 0.002048 0.004096 1
2024-01-16T19:26:46 Informational unbound [71805:0] info: lower(secs) upper(secs) recursions
2024-01-16T19:26:46 Informational unbound [71805:0] info: [25%]=0.0379419 median[50%]=0.0709973 [75%]=0.168521
2024-01-16T19:26:46 Informational unbound [71805:0] info: histogram of recursion processing times
2024-01-16T19:26:46 Informational unbound [71805:0] info: average recursion processing time 0.099173 sec
2024-01-16T19:26:46 Informational unbound [71805:0] info: server stats for thread 0: requestlist max 2 avg 0.235294 exceeded 0 jostled 0
2024-01-16T19:26:46 Informational unbound [71805:0] info: server stats for thread 0: 84 queries, 16 answers from cache, 68 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2024-01-16T19:26:46 Informational unbound [71805:0] info: service stopped (unbound 1.19.0).
2024-01-16T19:00:44 Informational unbound [71805:2] info: generate keytag query _ta-4f66. NULL IN
2024-01-16T19:00:43 Notice unbound daemonize unbound dhcpd watcher.
2024-01-16T19:00:43 Informational unbound [71805:0] info: start of service (unbound 1.19.0).
2024-01-16T19:00:43 Notice unbound [71805:0] notice: init module 2: iterator
2024-01-16T19:00:43 Notice unbound [71805:0] notice: init module 1: validator
2024-01-16T19:00:43 Notice unbound [71805:0] notice: init module 0: python
2024-01-16T19:00:43 Informational unbound [37599:0] info: 4.000000 8.000000 2
2024-01-16T19:00:43 Informational unbound [37599:0] info: 2.000000 4.000000 1
2024-01-16T19:00:43 Informational unbound [37599:0] info: 1.000000 2.000000 1
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.524288 1.000000 1
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.262144 0.524288 19
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.131072 0.262144 217
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.065536 0.131072 121
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.032768 0.065536 260
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.016384 0.032768 117
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.008192 0.016384 56
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.004096 0.008192 77
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.002048 0.004096 38
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.001024 0.002048 6
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.000512 0.001024 1
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.000000 0.000001 99
2024-01-16T19:00:43 Informational unbound [37599:0] info: lower(secs) upper(secs) recursions
2024-01-16T19:00:43 Informational unbound [37599:0] info: [25%]=0.0130194 median[50%]=0.0471355 [75%]=0.124031
2024-01-16T19:00:43 Informational unbound [37599:0] info: histogram of recursion processing times
2024-01-16T19:00:43 Informational unbound [37599:0] info: average recursion processing time 0.088653 sec
2024-01-16T19:00:43 Informational unbound [37599:0] info: server stats for thread 7: requestlist max 5 avg 0.364173 exceeded 0 jostled 0
2024-01-16T19:00:43 Informational unbound [37599:0] info: server stats for thread 7: 1374 queries, 358 answers from cache, 1016 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.524288 1.000000 2
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.262144 0.524288 27
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.131072 0.262144 221
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.065536 0.131072 123
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.032768 0.065536 272
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.016384 0.032768 130
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.008192 0.016384 56
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.004096 0.008192 80
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.002048 0.004096 36
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.001024 0.002048 8
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.000128 0.000256 1
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.000000 0.000001 99
2024-01-16T19:00:43 Informational unbound [37599:0] info: lower(secs) upper(secs) recursions
2024-01-16T19:00:43 Informational unbound [37599:0] info: [25%]=0.0140069 median[50%]=0.0469233 [75%]=0.123746
2024-01-16T19:00:43 Informational unbound [37599:0] info: histogram of recursion processing times
2024-01-16T19:00:43 Informational unbound [37599:0] info: average recursion processing time 0.075034 sec
2024-01-16T19:00:43 Informational unbound [37599:0] info: server stats for thread 6: requestlist max 4 avg 0.393365 exceeded 0 jostled 0
2024-01-16T19:00:43 Informational unbound [37599:0] info: server stats for thread 6: 1696 queries, 641 answers from cache, 1055 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2024-01-16T19:00:43 Informational unbound [37599:0] info: 1.000000 2.000000 1
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.524288 1.000000 2
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.262144 0.524288 33
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.131072 0.262144 258
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.065536 0.131072 134
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.032768 0.065536 303
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.016384 0.032768 141
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.008192 0.016384 72
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.004096 0.008192 80
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.002048 0.004096 53
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.001024 0.002048 3
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.000512 0.001024 2
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.000064 0.000128 1
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.000000 0.000001 141
2024-01-16T19:00:43 Informational unbound [37599:0] info: lower(secs) upper(secs) recursions
2024-01-16T19:00:43 Informational unbound [37599:0] info: [25%]=0.0111502 median[50%]=0.0456373 [75%]=0.125203
2024-01-16T19:00:43 Informational unbound [37599:0] info: histogram of recursion processing times
2024-01-16T19:00:43 Informational unbound [37599:0] info: average recursion processing time 0.075539 sec
2024-01-16T19:00:43 Informational unbound [37599:0] info: server stats for thread 5: requestlist max 3 avg 0.370915 exceeded 0 jostled 0
2024-01-16T19:00:43 Informational unbound [37599:0] info: server stats for thread 5: 1631 queries, 407 answers from cache, 1224 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.524288 1.000000 2
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.262144 0.524288 31
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.131072 0.262144 224
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.065536 0.131072 125
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.032768 0.065536 252
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.016384 0.032768 119
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.008192 0.016384 59
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.004096 0.008192 85
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.002048 0.004096 38
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.001024 0.002048 1
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.000512 0.001024 4
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.000032 0.000064 1
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.000000 0.000001 129
2024-01-16T19:00:43 Informational unbound [37599:0] info: lower(secs) upper(secs) recursions
2024-01-16T19:00:43 Informational unbound [37599:0] info: [25%]=0.00951105 median[50%]=0.0456411 [75%]=0.125567
2024-01-16T19:00:43 Informational unbound [37599:0] info: histogram of recursion processing times
2024-01-16T19:00:43 Informational unbound [37599:0] info: average recursion processing time 0.076967 sec
2024-01-16T19:00:43 Informational unbound [37599:0] info: server stats for thread 4: requestlist max 4 avg 0.4 exceeded 0 jostled 0
2024-01-16T19:00:43 Informational unbound [37599:0] info: server stats for thread 4: 1668 queries, 598 answers from cache, 1070 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.524288 1.000000 2
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.262144 0.524288 30
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.131072 0.262144 204
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.065536 0.131072 93
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.032768 0.065536 247
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.016384 0.032768 107
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.008192 0.016384 55
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.004096 0.008192 87
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.002048 0.004096 40
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.001024 0.002048 4
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.000512 0.001024 3
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.000256 0.000512 1
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.000128 0.000256 1
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.000016 0.000032 1
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.000000 0.000001 131
2024-01-16T19:00:43 Informational unbound [37599:0] info: lower(secs) upper(secs) recursions
2024-01-16T19:00:43 Informational unbound [37599:0] info: [25%]=0.00741517 median[50%]=0.0424525 [75%]=0.120149
2024-01-16T19:00:43 Informational unbound [37599:0] info: histogram of recursion processing times
2024-01-16T19:00:43 Informational unbound [37599:0] info: average recursion processing time 0.073688 sec
2024-01-16T19:00:43 Informational unbound [37599:0] info: server stats for thread 3: requestlist max 3 avg 0.366435 exceeded 0 jostled 0
2024-01-16T19:00:43 Informational unbound [37599:0] info: server stats for thread 3: 1369 queries, 362 answers from cache, 1007 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.262144 0.524288 25
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.131072 0.262144 251
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.065536 0.131072 110
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.032768 0.065536 274
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.016384 0.032768 112
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.008192 0.016384 64
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.004096 0.008192 70
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.002048 0.004096 52
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.001024 0.002048 1
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.000512 0.001024 3
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.000256 0.000512 2
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.000128 0.000256 1
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.000000 0.000001 127
2024-01-16T19:00:43 Informational unbound [37599:0] info: lower(secs) upper(secs) recursions
2024-01-16T19:00:43 Informational unbound [37599:0] info: [25%]=0.010368 median[50%]=0.0464014 [75%]=0.132639
2024-01-16T19:00:43 Informational unbound [37599:0] info: histogram of recursion processing times
2024-01-16T19:00:43 Informational unbound [37599:0] info: average recursion processing time 0.075480 sec
2024-01-16T19:00:43 Informational unbound [37599:0] info: server stats for thread 2: requestlist max 4 avg 0.411172 exceeded 0 jostled 0
2024-01-16T19:00:43 Informational unbound [37599:0] info: server stats for thread 2: 1732 queries, 640 answers from cache, 1092 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.262144 0.524288 24
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.131072 0.262144 231
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.065536 0.131072 104
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.032768 0.065536 266
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.016384 0.032768 132
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.008192 0.016384 64
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.004096 0.008192 78
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.002048 0.004096 53
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.001024 0.002048 4
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.000512 0.001024 4
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.000128 0.000256 1
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.000000 0.000001 99
2024-01-16T19:00:43 Informational unbound [37599:0] info: lower(secs) upper(secs) recursions
2024-01-16T19:00:43 Informational unbound [37599:0] info: [25%]=0.01152 median[50%]=0.0444709 [75%]=0.12477
2024-01-16T19:00:43 Informational unbound [37599:0] info: histogram of recursion processing times
2024-01-16T19:00:43 Informational unbound [37599:0] info: average recursion processing time 0.073098 sec
2024-01-16T19:00:43 Informational unbound [37599:0] info: server stats for thread 1: requestlist max 3 avg 0.401887 exceeded 0 jostled 0
2024-01-16T19:00:43 Informational unbound [37599:0] info: server stats for thread 1: 1433 queries, 373 answers from cache, 1060 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.262144 0.524288 26
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.131072 0.262144 240
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.065536 0.131072 132
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.032768 0.065536 272
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.016384 0.032768 112
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.008192 0.016384 54
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.004096 0.008192 92
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.002048 0.004096 39
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.001024 0.002048 4
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.000512 0.001024 3
2024-01-16T19:00:43 Informational unbound [37599:0] info: 0.000000 0.000001 134
2024-01-16T19:00:43 Informational unbound [37599:0] info: lower(secs) upper(secs) recursions
2024-01-16T19:00:43 Informational unbound [37599:0] info: [25%]=0.00895052 median[50%]=0.0467426 [75%]=0.125611
2024-01-16T19:00:43 Informational unbound [37599:0] info: histogram of recursion processing times
2024-01-16T19:00:43 Informational unbound [37599:0] info: average recursion processing time 0.074082 sec
2024-01-16T19:00:43 Informational unbound [37599:0] info: server stats for thread 0: requestlist max 4 avg 0.382671 exceeded 0 jostled 0
2024-01-16T19:00:43 Informational unbound [37599:0] info: server stats for thread 0: 1454 queries, 346 answers from cache, 1108 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2024-01-16T19:00:43 Informational unbound [37599:0] info: service stopped (unbound 1.19.0).
2024-01-16T18:53:15 Informational unbound [37599:3] info: generate keytag query _ta-4f66. NULL IN
2024-01-16T18:53:15 Informational unbound [37599:5] info: generate keytag query _ta-4f66. NULL IN
2024-01-16T18:00:20 Informational unbound [37599:5] info: generate keytag query _ta-4f66. NULL IN
2024-01-16T17:03:33 Informational unbound [37599:2] info: generate keytag query _ta-4f66. NULL IN
2024-01-16T16:38:50 Informational unbound [37599:5] info: generate keytag query _ta-4f66. NULL IN

Note: /var/unbound/root.hints is identical to /usr/local/opnsense/service/templates/OPNsense/Unbound/core/root.min.hints - although do note that the Unbound process was killed -9 and the restarted.

[cookiemonster]

I for one fail to see why the choice of filesystem would have an impact unless there were unclean shutdowns that could corrupt files, something UFS is not as good dealing with.
At least you moved to ZFS, so all in all is better. Restoring config just brought the problem across if is config-related though.
My suggestion still is to use Unbound on its own. No blocklists, no whitelists and no DoT. Let it run for a few days to see if it re-occurs the 100% cpu. And if you must have them, move them to AdGuardHome. Ideally not, and introduce the additions one at the time over time.

[lar.hed]

Oh, I see I need to do one major clarification: I did not move to ZFS (from UFS) to solve this Unbound challenge!

I did that move to be able to do snapshots ( https://forum.opnsense.org/index.php?topic=25540.msg122731 ) so that what happened to me, when I upgraded from a fully functioning OPNsense with a fully working Unbound to 23.7.x version which killed Unbound, is possible to recover from. As well known OPNsense can only backup the config file. Even if one happen to have an old config file, there is just nu way to download an old version with old versions of plugins (se below) to get that old config to work again. It is a one-way road with OPNsense. So to get around that I first thought I go ProxMox route (just to never figure out how to configure (use) my 8 networks ports with my somewhat odd setup) - but I then remembered (I used to work as Unix SysAdmin and DBA) I should be able to do snapshot. UFS snapshot is not included in OPNsense, however ZFS has what is needed included in OPNsense distribution. And from now I will be able to get a snapshot backup solution - I just need a stable OPNsense/Unbound.

Plugins: I currently only have CrowdSec and UDP Broadcast Relay as the only plugins. I would like to keep plugins at as few as ever possible. And this is only due to the fact that one can never (at least not any easy way) download an old version onto a new verison of OPNsense or something. One either runs latest&greatest or one does not do upgrades on working versions (read: Do a snapshot before any upgrade to be able to go back). This is a very harsh and hard way to solve problems. But it is either that or Monit scripts that restarts everything when it get stuck into something. Neither solution is perfect. BandId kind of solution, both they are...

When it comes to AdGuardHome: It would either be a plugin over external source, or a stand alone installation on a pi, or one could then opt for a pi-hole also. Either solution of the three are adding complexity. I do prefer a simpler, as in fewer, option.

Also, Unbound worked prior to 23.7 - and it seems to work for other people. Even with blocklists.

And then for the idea that I have that this is an OS thingi: I have this odd feeling that it is a memory issue. I have this since roots.hints file is never changed from what I can see. Even so thet roots file is part of the challenge. From the latest log I can see that it at 19.00 or so seems to download something, and restarts (19:00:43 first and last row of 19.00.43). That restart seems to stop since at 19:26:46 It stops again. Why is that?

And this is when it's gets fuggly... The 19:26 is the high CPU I kill-9 - So what ever reason that started at 19:00:43, is the reason I get 100% CPU. Now I have a Monit script that kills this and restarts it again.

This restart, the 2nd within 33 minutes or so, this one get's the root or stub error. It workd half o hour ago, but not this time. AND when my Monit script kills -9 and then restarts Unbound, it just works again.

So the restart at 19:00:43 is the reason this goes wrong. I just can not find WHY it does the restart at 19:00:43. We find out that - we find the challenge.