Revert unbound to 18.7.7 - not possible?

[franco]

I can create an account and post it there if you wish, but I am not very quick these days due to my day job.


Cheers,
Franco

[chemlud]

OK, I updated to 19.1.6 and killed unbound by opening Firefox (empty tab, the "Safebrowsing" stuff alone seems to be enough to kill unbound).

_________________

OPNsense 19.1.6
LibreSSL

Unbound 1.9.1

DNSSEc not enabled

Options:

Code Select Expand

ssl-upstream: yes
forward-zone:
name: "."
forward-addr: 46.182.19.48@853 #digitalcourage
forward-addr: 89.233.43.71@853 #FriDNS.dk
forward-addr: 149.112.112.112@853 #Quad9

________________

syslog

Code Select Expand

Apr 11 16:44:41 kernel: pid 29895 (unbound), uid 59: exited on signal 11

________________

unbound log set to level 5

Code Select Expand

Apr 11 16:44:41 unbound: [29895:2] debug: svcd callbacks end
Apr 11 16:44:41 unbound: [29895:2] debug: cache memory msg=141823 rrset=155964 infra=11115 val=0
Apr 11 16:44:41 unbound: [29895:2] info: 0.524288 1.000000 1
Apr 11 16:44:41 unbound: [29895:2] info: 0.262144 0.524288 2
Apr 11 16:44:41 unbound: [29895:2] info: 0.131072 0.262144 5
Apr 11 16:44:41 unbound: [29895:2] info: 0.065536 0.131072 1
Apr 11 16:44:41 unbound: [29895:2] info: lower(secs) upper(secs) recursions
Apr 11 16:44:41 unbound: [29895:2] info: [25%]=0.16384 median[50%]=0.222822 [75%]=0.360448
Apr 11 16:44:41 unbound: [29895:2] info: histogram of recursion processing times
Apr 11 16:44:41 unbound: [29895:2] info: average recursion processing time 0.232278 sec
Apr 11 16:44:41 unbound: [29895:2] info: mesh_run: end 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 9 recursion replies sent, 0 replies dropped, 0 states jostled out
Apr 11 16:44:41 unbound: [29895:2] debug: query took 0.278204 sec
Apr 11 16:44:41 unbound: [29895:2] debug: mesh_run: iterator module exit state is module_finished
Apr 11 16:44:41 unbound: [29895:2] debug: return error response SERVFAIL
Apr 11 16:44:41 unbound: [29895:2] debug: store error response in message cache
Apr 11 16:44:41 unbound: [29895:2] debug: configured stub or forward servers failed -- returning SERVFAIL
Apr 11 16:44:41 unbound: [29895:2] debug: No more query targets, attempting last resort
Apr 11 16:44:41 unbound: [29895:2] debug: attempt to get extra 3 targets
Apr 11 16:44:41 unbound: [29895:2] debug: ip4 46.182.19.48 port 853 (len 16)
Apr 11 16:44:41 unbound: [29895:2] debug: ip4 89.233.43.71 port 853 (len 16)
Apr 11 16:44:41 unbound: [29895:2] debug: ip4 149.112.112.112 port 853 (len 16)
Apr 11 16:44:41 unbound: [29895:2] info: DelegationPoint<.>: 0 names (0 missing), 3 addrs (0 result, 0 avail) parentNS
Apr 11 16:44:41 unbound: [29895:2] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 2
Apr 11 16:44:41 unbound: [29895:2] info: processQueryTargets: safebrowsing.googleapis.com. AAAA IN
Apr 11 16:44:41 unbound: [29895:2] debug: iter_handle processing q with state QUERY TARGETS STATE
Apr 11 16:44:41 unbound: [29895:2] info: error sending query to auth server ip4 89.233.43.71 port 853 (len 16)
Apr 11 16:44:41 unbound: [29895:2] debug: close fd 34
Apr 11 16:44:41 unbound: [29895:2] error: could not SSL_new crypto error:14FFF0E4:SSL routines:(UNKNOWN)SSL_internal:ssl ctx has no default ssl version
Apr 11 16:44:41 unbound: [29895:2] debug: tcp bound to src ip4 192.168.199.4 port 0 (len 16)
Apr 11 16:44:41 unbound: [29895:2] debug: dnssec status: not expected
Apr 11 16:44:41 unbound: [29895:2] debug: sending to target: <.> 89.233.43.71#853
Apr 11 16:44:41 unbound: [29895:2] info: sending query: safebrowsing.googleapis.com. AAAA IN
Apr 11 16:44:41 unbound: [29895:2] debug: selrtt 788
Apr 11 16:44:41 unbound: [29895:2] debug: rtt=788
Apr 11 16:44:41 unbound: [29895:2] debug: servselect ip4 89.233.43.71 port 853 (len 16)
Apr 11 16:44:41 unbound: [29895:2] debug: attempt to get extra 3 targets
Apr 11 16:44:41 unbound: [29895:2] debug: ip4 46.182.19.48 port 853 (len 16)
Apr 11 16:44:41 unbound: [29895:2] debug: ip4 89.233.43.71 port 853 (len 16)
Apr 11 16:44:41 unbound: [29895:2] debug: ip4 149.112.112.112 port 853 (len 16)
Apr 11 16:44:41 unbound: [29895:2] info: DelegationPoint<.>: 0 names (0 missing), 3 addrs (1 result, 0 avail) parentNS
Apr 11 16:44:41 unbound: [29895:2] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 2
Apr 11 16:44:41 unbound: [29895:2] info: processQueryTargets: safebrowsing.googleapis.com. AAAA IN
Apr 11 16:44:41 unbound: [29895:2] debug: iter_handle processing q with state QUERY TARGETS STATE
Apr 11 16:44:41 unbound: [29895:2] info: error sending query to auth server ip4 89.233.43.71 port 853 (len 16)
Apr 11 16:44:41 unbound: [29895:2] debug: close fd 34
Apr 11 16:44:41 unbound: [29895:2] error: could not SSL_new crypto error:14FFF0E4:SSL routines:(UNKNOWN)SSL_internal:ssl ctx has no default ssl version
Apr 11 16:44:41 unbound: [29895:2] debug: tcp bound to src ip4 192.168.199.4 port 0 (len 16)
Apr 11 16:44:41 unbound: [29895:2] debug: dnssec status: not expected
Apr 11 16:44:41 unbound: [29895:2] debug: sending to target: <.> 89.233.43.71#853
Apr 11 16:44:41 unbound: [29895:2] info: sending query: safebrowsing.googleapis.com. AAAA IN
...


Have the whole resolver.log here, but much too big to paste it here. File size 95.4 MB....

[chemlud]

next event:

syslog:

Code Select Expand


Apr 11 18:47:23 kernel: -> pid: 46228 ppid: 1 p_pax: 0xa50<SEGVGUARD,ASLR,NOSHLIBRANDOM,NODISALLOWMAP32BIT>
Apr 11 18:47:23 kernel: [HBSD SEGVGUARD] [unbound (46228)] Suspension expired.
Apr 11 18:47:23 kernel: pid 46228 (unbound), uid 59: exited on signal 11

unbound log:

Code Select Expand

Apr 11 18:47:23 unbound: [46228:1] debug: comm point listen_for_rw 27 0
Apr 11 18:47:23 unbound: [46228:3] debug: cache memory msg=134543 rrset=140365 infra=11115 val=0
Apr 11 18:47:23 unbound: [46228:3] info: 0RDd mod0 rep ftp.de.debian.org. A IN
Apr 11 18:47:23 unbound: [46228:3] info: 0.524288 1.000000 1
Apr 11 18:47:23 unbound: [46228:3] info: 0.262144 0.524288 1
Apr 11 18:47:23 unbound: [46228:3] info: 0.131072 0.262144 3
Apr 11 18:47:23 unbound: [46228:3] info: lower(secs) upper(secs) recursions
Apr 11 18:47:23 unbound: [46228:3] info: [25%]=0.185685 median[50%]=0.240299 [75%]=0.458752
Apr 11 18:47:23 unbound: [46228:3] info: histogram of recursion processing times
Apr 11 18:47:23 unbound: [46228:3] info: average recursion processing time 0.319276 sec
Apr 11 18:47:23 unbound: [46228:3] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 5 recursion replies sent, 0 replies dropped, 0 states jostled out
Apr 11 18:47:23 unbound: [46228:3] debug: mesh_run: iterator module exit state is module_wait_reply
Apr 11 18:47:23 unbound: [46228:3] debug: comm point start listening 29
Apr 11 18:47:23 unbound: [46228:3] debug: tcp bound to src ip4 192.168.199.4 port 0 (len 16)
Apr 11 18:47:23 unbound: [46228:3] debug: dnssec status: not expected
Apr 11 18:47:23 unbound: [46228:3] debug: sending to target: <.> 149.112.112.112#853
Apr 11 18:47:23 unbound: [46228:3] info: sending query: ftp.de.debian.org. A IN
Apr 11 18:47:23 unbound: [46228:3] debug: selrtt 478
Apr 11 18:47:23 unbound: [46228:3] debug: rtt=581
Apr 11 18:47:23 unbound: [46228:3] debug: servselect ip4 149.112.112.112 port 853 (len 16)
Apr 11 18:47:23 unbound: [46228:3] debug: rtt=1155
Apr 11 18:47:23 unbound: [46228:3] debug: servselect ip4 89.233.43.71 port 853 (len 16)
Apr 11 18:47:23 unbound: [46228:3] debug: rtt=478
Apr 11 18:47:23 unbound: [46228:3] debug: servselect ip4 46.182.19.48 port 853 (len 16)
Apr 11 18:47:23 unbound: [46228:3] debug: attempt to get extra 3 targets
Apr 11 18:47:23 unbound: [46228:3] debug: ip4 46.182.19.48 port 853 (len 16)
Apr 11 18:47:23 unbound: [46228:3] debug: ip4 89.233.43.71 port 853 (len 16)
Apr 11 18:47:23 unbound: [46228:3] debug: ip4 149.112.112.112 port 853 (len 16)
Apr 11 18:47:23 unbound: [46228:3] info: DelegationPoint<.>: 0 names (0 missing), 3 addrs (0 result, 3 avail) parentNS
Apr 11 18:47:23 unbound: [46228:3] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
Apr 11 18:47:23 unbound: [46228:3] info: processQueryTargets: ftp.de.debian.org. A IN
Apr 11 18:47:23 unbound: [46228:3] debug: iter_handle processing q with state QUERY TARGETS STATE
Apr 11 18:47:23 unbound: [46228:3] debug: forwarding request
Apr 11 18:47:23 unbound: [46228:3] debug: request has dependency depth of 0
Apr 11 18:47:23 unbound: [46228:3] info: resolving ftp.de.debian.org. A IN
Apr 11 18:47:23 unbound: [46228:3] debug: iter_handle processing q with state INIT REQUEST STATE
Apr 11 18:47:23 unbound: [46228:3] debug: process_request: new external request event
Apr 11 18:47:23 unbound: [46228:3] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new
Apr 11 18:47:23 unbound: [46228:3] debug: mesh_run: start
Apr 11 18:47:23 unbound: [46228:3] debug: udp request from ip4 192.168.11.10 port 55142 (len 16)
Apr 11 18:47:23 unbound: [46228:3] debug: answer from the cache failed
Apr 11 18:47:23 unbound: [46228:0] debug: cache memory msg=134543 rrset=140365 infra=11115 val=0
Apr 11 18:47:23 unbound: [46228:0] info: 0RDd mod0 rep security.debian.org. AAAA IN
Apr 11 18:47:23 unbound: [46228:0] info: 0.262144 0.524288 2
Apr 11 18:47:23 unbound: [46228:0] info: 0.131072 0.262144 2
Apr 11 18:47:23 unbound: [46228:0] info: lower(secs) upper(secs) recursions
Apr 11 18:47:23 unbound: [46228:0] info: [25%]=0.196608 median[50%]=0.262144 [75%]=0.393216
Apr 11 18:47:23 unbound: [46228:0] info: histogram of recursion processing times
Apr 11 18:47:23 unbound: [46228:0] info: average recursion processing time 0.263320 sec
Apr 11 18:47:23 unbound: [46228:0] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 4 recursion replies sent, 0 replies dropped, 0 states jostled out
Apr 11 18:47:23 unbound: [46228:0] debug: mesh_run: iterator module exit state is module_wait_reply
Apr 11 18:47:23 unbound: [46228:0] debug: comm point start listening 28
Apr 11 18:47:23 unbound: [46228:0] debug: tcp bound to src ip4 192.168.199.4 port 0 (len 16)
Apr 11 18:47:23 unbound: [46228:0] debug: dnssec status: not expected
Apr 11 18:47:23 unbound: [46228:0] debug: sending to target: <.> 149.112.112.112#853
Apr 11 18:47:23 unbound: [46228:0] info: sending query: security.debian.org. AAAA IN
Apr 11 18:47:23 unbound: [46228:0] debug: selrtt 478
Apr 11 18:47:23 unbound: [46228:0] debug: rtt=581

[chemlud]

I installed 19.1.10 (libreSSL and unbound updates) and for the last 2-3 h DNS-over-TLS has been stable! :-)

[franco]

I wouldn't bet on that, but then again 2-3 hours is already a long time for this to be up and running.

Might have been Unbound 1.9.2 or just LibreSSL 2.9, either way that would be great. :)


Cheers,
Franco

[chemlud]

hmm, DNS was stable for about 22 hours, so I updated a "production system" and rebooted... looking fine so far! Hoping for the best... :-D

[franco]

I'm afraid to ask.... :)