unbound: unbound becoming unreliable and stops responding under certain conditions

Hello

Describe the bug

I’m frequently seeing unbound enter a state in which it will not respond reliably anymore. Once in this state, it will not recover on its own. This seems to happen directly after a restart or config reload with an element of chance.

I suspect this might be related to using either forward-tls-upstream, or having around 50k local-data entries for blocking malware domains. I can observe this issue on two separate but fairly similar OPNsense installs.

Symptoms once this bug is triggered:

  • The same query (even for a local-data record!) is rarely answered immediately, and usually only after 20 seconds or not at all in a seemingly random pattern.
  • unbound-control hangs indefinitely.
  • The unbound process is using 0-2% CPU while constantly in the sbwait state, as seen by top. (a properly functioning unbound is seen in the kqread state
  • unbound will not react to SIGTERM

To reproduce Steps to reproduce the behavior:

Starting unbound with the config below seems to be enough. There’s a roughly 1 in 10 chance it’ll trigger the bug after starting (but of course, never when you try to reproduce it 😦 ). The random nature also make a process of eliminiation difficult.

Expected behavior Fast and reliable responses to queries and unbound-control

System:

  • Unbound version: 1.16.2
  • OS: OPNsense 22.7 (FreeBSD 13.1)
  • unbound -V output:
Version 1.16.2

Configure line: --with-libexpat=/usr/local --with-ssl=/usr/local --enable-dnscrypt --disable-dnstap --with-libnghttp2 --enable-ecdsa --disable-event-api --enable-gost --with-libevent --with-pythonmodule=yes --with-pyunbound=yes ac_cv_path_SWIG=/usr/local/bin/swig LDFLAGS=-L/usr/local/lib --disable-subnet --disable-tfo-client --disable-tfo-server --with-pthreads --prefix=/usr/local --localstatedir=/var --mandir=/usr/local/man --infodir=/usr/local/share/info/ --build=amd64-portbld-freebsd13.1
Linked libs: libevent 2.1.12-stable (it uses kqueue), OpenSSL 1.1.1q  5 Jul 2022
Linked modules: dns64 python respip validator iterator
DNSCrypt feature available

Additional information

Unbound config 

unbound.conf:##########################
unbound.conf:# Unbound Configuration
unbound.conf:##########################
unbound.conf:##
unbound.conf:# Server configuration
unbound.conf:##
unbound.conf:server:
unbound.conf:chroot: /var/unbound
unbound.conf:username: unbound
unbound.conf:directory: /var/unbound
unbound.conf:pidfile: /var/run/unbound.pid
unbound.conf:root-hints: /var/unbound/root.hints
unbound.conf:use-syslog: yes
unbound.conf:port: 53
unbound.conf:verbosity: 1
unbound.conf:extended-statistics: no
unbound.conf:log-queries: no
unbound.conf:hide-identity: yes
unbound.conf:hide-version: yes
unbound.conf:harden-referral-path: no
unbound.conf:do-ip4: yes
unbound.conf:do-ip6: yes
unbound.conf:do-udp: yes
unbound.conf:do-tcp: yes
unbound.conf:do-daemonize: yes
unbound.conf:so-reuseport: yes
unbound.conf:module-config: "validator iterator"
unbound.conf:cache-max-ttl: 86400
unbound.conf:cache-min-ttl: 180
unbound.conf:harden-dnssec-stripped: no
unbound.conf:serve-expired: no
unbound.conf:outgoing-num-tcp: 10
unbound.conf:incoming-num-tcp: 10
unbound.conf:num-queries-per-thread: 4096
unbound.conf:outgoing-range: 8192
unbound.conf:infra-host-ttl: 900
unbound.conf:infra-cache-numhosts: 50000
unbound.conf:unwanted-reply-threshold: 0
unbound.conf:jostle-timeout: 200
unbound.conf:msg-cache-size: 250m
unbound.conf:rrset-cache-size: 500m
unbound.conf:num-threads: 4
unbound.conf:msg-cache-slabs: 8
unbound.conf:rrset-cache-slabs: 8
unbound.conf:infra-cache-slabs: 8
unbound.conf:key-cache-slabs: 8
unbound.conf:auto-trust-anchor-file: /var/unbound/root.key
unbound.conf:prefetch: yes
unbound.conf:prefetch-key: yes
unbound.conf:# Interface IP(s) to bind to
unbound.conf:interface: 0.0.0.0
unbound.conf:interface: ::
unbound.conf:interface-automatic: yes
unbound.conf:# DNS Rebinding
unbound.conf:# For DNS Rebinding prevention
unbound.conf:#
unbound.conf:# All these addresses are either private or should not be routable in the global IPv4 or IPv6 internet.
unbound.conf:#
unbound.conf:# IPv4 Addresses
unbound.conf:#
unbound.conf:private-address: 0.0.0.0/8       # Broadcast address
unbound.conf:private-address: 10.0.0.0/8
unbound.conf:private-address: 100.64.0.0/10
unbound.conf:private-address: 127.0.0.0/8     # Loopback Localhost
unbound.conf:private-address: 169.254.0.0/16
unbound.conf:private-address: 172.16.0.0/12
unbound.conf:private-address: 192.0.2.0/24    # Documentation network TEST-NET
unbound.conf:private-address: 192.168.0.0/16
unbound.conf:private-address: 198.18.0.0/15   # Used for testing inter-network communications
unbound.conf:private-address: 198.51.100.0/24 # Documentation network TEST-NET-2
unbound.conf:private-address: 203.0.113.0/24  # Documentation network TEST-NET-3
unbound.conf:private-address: 233.252.0.0/24  # Documentation network MCAST-TEST-NET
unbound.conf:#
unbound.conf:# IPv6 Addresses
unbound.conf:#
unbound.conf:private-address: ::1/128         # Loopback Localhost
unbound.conf:private-address: 2001:db8::/32   # Documentation network IPv6
unbound.conf:private-address: fc00::/8        # Unique local address (ULA) part of "fc00::/7", not defined yet
unbound.conf:private-address: fd00::/8        # Unique local address (ULA) part of "fc00::/7", "/48" prefix group
unbound.conf:private-address: fe80::/10       # Link-local address (LLA)
unbound.conf:# Private domains (DNS Rebinding)
unbound.conf:include: /var/unbound/private_domains.conf
unbound.conf:# Access lists
unbound.conf:include: /var/unbound/access_lists.conf
unbound.conf:# Static host entries
unbound.conf:include: /var/unbound/host_entries.conf
unbound.conf:# DHCP leases (if configured)
unbound.conf:include: /var/unbound/dhcpleases.conf
unbound.conf:# Custom includes
unbound.conf:include: /var/unbound/etc/*.conf
unbound.conf:remote-control:
unbound.conf:    control-enable: yes
unbound.conf:    control-interface: 127.0.0.1
unbound.conf:    control-port: 953
unbound.conf:    server-key-file: /var/unbound/unbound_server.key
unbound.conf:    server-cert-file: /var/unbound/unbound_server.pem
unbound.conf:    control-key-file: /var/unbound/unbound_control.key
unbound.conf:    control-cert-file: /var/unbound/unbound_control.pem
access_lists.conf:access-control: 127.0.0.1/8 allow
access_lists.conf:access-control: ::1/64 allow
access_lists.conf:access-control: 192.168.1.1/24 allow
access_lists.conf:access-control: 2001:*censored*/64 allow
access_lists.conf:access-control: fe80::*censored*/64 allow
access_lists.conf:access-control: 192.168.2.20/24 allow
access_lists.conf:access-control: 10.0.8.1/24 allow
access_lists.conf:access-control: *censored*/32 allow
access_lists.conf:access-control: *censored*/32 allow
access_lists.conf:access-control: 2001:*censored*/64 allow
dhcpleases.conf:local-data-ptr: "192.168.1.177 foo.domain.net"
dhcpleases.conf:local-data: "foo.domain.net IN A 192.168.1.177"
dhcpleases.conf:local-data-ptr: "192.168.1.100 bar.domain.net"
dhcpleases.conf:local-data: "bar.domain.net IN A 192.168.1.100"
dhcpleases.conf:local-data-ptr: "192.168.1.178 baz.domain.net"
dhcpleases.conf:local-data: "baz.domain.net IN A 192.168.1.178"
host_entries.conf:local-zone: "domain.net" transparent
host_entries.conf:local-data-ptr: "127.0.0.1 localhost"
host_entries.conf:local-data: "localhost A 127.0.0.1"
host_entries.conf:local-data: "localhost.domain.net A 127.0.0.1"
host_entries.conf:local-data-ptr: "::1 localhost"
host_entries.conf:local-data: "localhost AAAA ::1"
host_entries.conf:local-data: "localhost.domain.net AAAA ::1"
host_entries.conf:local-data-ptr: "192.168.1.1 OPNsense.domain.net"
host_entries.conf:local-data: "OPNsense.domain.net A 192.168.1.1"
host_entries.conf:local-data: "OPNsense A 192.168.1.1"
host_entries.conf:local-data-ptr: "2001:*censored* OPNsense.domain.net"
host_entries.conf:local-data: "OPNsense.domain.net AAAA 2001:*censored*"
host_entries.conf:local-data: "OPNsense AAAA 2001:*censored*"
host_entries.conf:local-data: "OPNsense.domain.net A 192.168.2.20"
host_entries.conf:local-data: "OPNsense A 192.168.2.20"
host_entries.conf:local-data: "OPNsense.domain.net A 10.0.8.1"
host_entries.conf:local-data: "OPNsense A 10.0.8.1"
host_entries.conf:local-data: "OPNsense.domain.net A *censored*"
host_entries.conf:local-data: "OPNsense A *censored*"
host_entries.conf:local-data: "OPNsense.domain.net A *censored*"
host_entries.conf:local-data: "OPNsense A *censored*"
host_entries.conf:local-data: "OPNsense.domain.net AAAA 2001:*censored*"
host_entries.conf:local-data: "OPNsense AAAA 2001:*censored*"
host_entries.conf:local-data-ptr: "151.106.9.30 archive.is"
host_entries.conf:local-data: "archive.is IN A 151.106.9.30"
host_entries.conf:local-data: "home.domain.net IN A 192.168.1.200"
host_entries.conf:local-data: "nextcloud.domain.net IN A 192.168.1.200"
host_entries.conf:local-data-ptr: "192.168.1.200 mach.domain.net"
host_entries.conf:local-data: "mach.domain.net IN A 192.168.1.200"
private_domains.conf:# Set private domains in case authoritative name server returns a Private IP address
etc/dot.conf:# Forward zones over TLS
etc/dot.conf:server:
etc/dot.conf:  tls-cert-bundle: /etc/ssl/cert.pem
etc/dot.conf:forward-zone:
etc/dot.conf:  name: "."
etc/dot.conf:  forward-tls-upstream: yes
etc/dot.conf:  forward-addr: 9.9.9.10@853#dns.quad9.net
etc/dot.conf:  forward-addr: 149.112.112.10@853#dns.quad9.net
etc/dot.conf:  forward-addr: 2620:fe::10@853#dns.quad9.net
etc/dot.conf:  forward-addr: 2620:fe::fe:10@853#dns.quad9.net
etc/miscellaneous.conf:server:
etc/dnsbl.conf:local-data: "scam.com A 0.0.0.0"
etc/dnsbl.conf:local-data: "malware.com A 0.0.0.0"
etc/dnsbl.conf:....
etc/dnsbl.conf:.... 50k more lines like this

Unbound log at log verbosity 1

Starting from when unbound started into a buggy condition. First timeouts were observed around 05:02, but might’ve been earlier too. Not much suspicious in here.

<164>1 2022-09-24T05:00:12+02:00 OPNsense.domain.net unbound 22595 - [meta sequenceId="1"] PTR record already exists for home.domain.net(192.168.1.200)
<164>1 2022-09-24T05:00:12+02:00 OPNsense.domain.net unbound 22595 - [meta sequenceId="2"] PTR record already exists for nextcloud.domain.net(192.168.1.200)
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="3"] [22675:0] info: service stopped (unbound 1.16.2).
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="4"] [22675:0] info: server stats for thread 0: 6171 queries, 4385 answers from cache, 1786 recursions, 172 prefetch, 0 rejected by ip ratelimiting
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="5"] [22675:0] info: server stats for thread 0: requestlist max 11 avg 0.773749 exceeded 0 jostled 0
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="6"] [22675:0] info: average recursion processing time 0.192220 sec
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="7"] [22675:0] info: histogram of recursion processing times
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="8"] [22675:0] info: [25%]=0.0485053 median[50%]=0.108102 [75%]=0.217228
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="9"] [22675:0] info: lower(secs) upper(secs) recursions
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="10"] [22675:0] info:    0.000000    0.000001 163
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="11"] [22675:0] info:    0.001024    0.002048 1
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="12"] [22675:0] info:    0.004096    0.008192 2
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="13"] [22675:0] info:    0.008192    0.016384 5
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="14"] [22675:0] info:    0.016384    0.032768 166
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="15"] [22675:0] info:    0.032768    0.065536 228
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="16"] [22675:0] info:    0.065536    0.131072 505
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="17"] [22675:0] info:    0.131072    0.262144 410
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="18"] [22675:0] info:    0.262144    0.524288 202
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="19"] [22675:0] info:    0.524288    1.000000 66
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="20"] [22675:0] info:    1.000000    2.000000 15
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="21"] [22675:0] info:    2.000000    4.000000 23
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="22"] [22675:0] info: server stats for thread 1: 6309 queries, 4507 answers from cache, 1802 recursions, 201 prefetch, 0 rejected by ip ratelimiting
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="23"] [22675:0] info: server stats for thread 1: requestlist max 9 avg 0.651523 exceeded 0 jostled 0
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="24"] [22675:0] info: average recursion processing time 0.179294 sec
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="25"] [22675:0] info: histogram of recursion processing times
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="26"] [22675:0] info: [25%]=0.0454248 median[50%]=0.105229 [75%]=0.211412
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="27"] [22675:0] info: lower(secs) upper(secs) recursions
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="28"] [22675:0] info:    0.000000    0.000001 156
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="29"] [22675:0] info:    0.002048    0.004096 1
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="30"] [22675:0] info:    0.004096    0.008192 4
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="31"] [22675:0] info:    0.008192    0.016384 3
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="32"] [22675:0] info:    0.016384    0.032768 205
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="33"] [22675:0] info:    0.032768    0.065536 211
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="34"] [22675:0] info:    0.065536    0.131072 530
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="35"] [22675:0] info:    0.131072    0.262144 394
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="36"] [22675:0] info:    0.262144    0.524288 223
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="37"] [22675:0] info:    0.524288    1.000000 47
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="38"] [22675:0] info:    1.000000    2.000000 9
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="39"] [22675:0] info:    2.000000    4.000000 19
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="40"] [22675:0] info: server stats for thread 2: 6199 queries, 4477 answers from cache, 1722 recursions, 244 prefetch, 0 rejected by ip ratelimiting
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="41"] [22675:0] info: server stats for thread 2: requestlist max 10 avg 0.630214 exceeded 0 jostled 0
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="42"] [22675:0] info: average recursion processing time 0.173002 sec
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="43"] [22675:0] info: histogram of recursion processing times
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="44"] [22675:0] info: [25%]=0.0458928 median[50%]=0.107432 [75%]=0.215045
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="45"] [22675:0] info: lower(secs) upper(secs) recursions
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="46"] [22675:0] info:    0.000000    0.000001 166
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="47"] [22675:0] info:    0.001024    0.002048 1
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="48"] [22675:0] info:    0.008192    0.016384 5
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="49"] [22675:0] info:    0.016384    0.032768 184
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="50"] [22675:0] info:    0.032768    0.065536 186
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="51"] [22675:0] info:    0.065536    0.131072 499
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="52"] [22675:0] info:    0.131072    0.262144 391
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="53"] [22675:0] info:    0.262144    0.524288 225
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="54"] [22675:0] info:    0.524288    1.000000 41
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="55"] [22675:0] info:    1.000000    2.000000 10
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="56"] [22675:0] info:    2.000000    4.000000 14
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="57"] [22675:0] info: server stats for thread 3: 6212 queries, 4441 answers from cache, 1771 recursions, 224 prefetch, 0 rejected by ip ratelimiting
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="58"] [22675:0] info: server stats for thread 3: requestlist max 9 avg 0.703759 exceeded 0 jostled 0
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="59"] [22675:0] info: average recursion processing time 0.199373 sec
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="60"] [22675:0] info: histogram of recursion processing times
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="61"] [22675:0] info: [25%]=0.0517788 median[50%]=0.111778 [75%]=0.229123
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="62"] [22675:0] info: lower(secs) upper(secs) recursions
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="63"] [22675:0] info:    0.000000    0.000001 153
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="64"] [22675:0] info:    0.001024    0.002048 1
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="65"] [22675:0] info:    0.008192    0.016384 6
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="66"] [22675:0] info:    0.016384    0.032768 176
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="67"] [22675:0] info:    0.032768    0.065536 184
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="68"] [22675:0] info:    0.065536    0.131072 518
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="69"] [22675:0] info:    0.131072    0.262144 388
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="70"] [22675:0] info:    0.262144    0.524288 241
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="71"] [22675:0] info:    0.524288    1.000000 68
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="72"] [22675:0] info:    1.000000    2.000000 17
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="73"] [22675:0] info:    2.000000    4.000000 17
<30>1 2022-09-24T05:00:13+02:00 OPNsense.domain.net unbound 22675 - [meta sequenceId="74"] [22675:0] info:    4.000000    8.000000 2
<29>1 2022-09-24T05:00:20+02:00 OPNsense.domain.net unbound 79082 - [meta sequenceId="75"] [79082:0] notice: init module 0: validator
<29>1 2022-09-24T05:00:20+02:00 OPNsense.domain.net unbound 79082 - [meta sequenceId="76"] [79082:0] notice: init module 1: iterator
<30>1 2022-09-24T05:00:20+02:00 OPNsense.domain.net unbound 79082 - [meta sequenceId="77"] [79082:0] info: start of service (unbound 1.16.2).
<30>1 2022-09-24T05:00:20+02:00 OPNsense.domain.net unbound 79082 - [meta sequenceId="78"] [79082:3] info: generate keytag query _ta-4f66. NULL IN
<30>1 2022-09-24T05:00:20+02:00 OPNsense.domain.net unbound 79082 - [meta sequenceId="79"] [79082:1] info: generate keytag query _ta-4f66. NULL IN
<164>1 2022-09-24T05:00:21+02:00 OPNsense.domain.net unbound 93326 - [meta sequenceId="80"] PTR record already exists for home.domain.net(192.168.1.200)
<164>1 2022-09-24T05:00:21+02:00 OPNsense.domain.net unbound 93326 - [meta sequenceId="81"] PTR record already exists for nextcloud.domain.net(192.168.1.200)
<164>1 2022-09-24T05:02:19+02:00 OPNsense.domain.net unbound 73584 - [meta sequenceId="1"] PTR record already exists for home.domain.net(192.168.1.200)
<164>1 2022-09-24T05:02:19+02:00 OPNsense.domain.net unbound 73584 - [meta sequenceId="2"] PTR record already exists for nextcloud.domain.net(192.168.1.200)
<164>1 2022-09-24T05:02:39+02:00 OPNsense.domain.net unbound 89805 - [meta sequenceId="3"] PTR record already exists for home.domain.net(192.168.1.200)
<164>1 2022-09-24T05:02:39+02:00 OPNsense.domain.net unbound 89805 - [meta sequenceId="4"] PTR record already exists for nextcloud.domain.net(192.168.1.200)
<30>1 2022-09-24T10:04:54+02:00 OPNsense.domain.net unbound 79082 - [meta sequenceId="1"] [79082:3] info: generate keytag query _ta-4f66. NULL IN

I will next try starting into higher log verbosities. Right now it’s sitll running in the buggy state, so if anyone wants me to check something, let me know asap.

Also see opnsense/core#6041

Thanks!

About this issue

  • Original URL
  • State: closed
  • Created 2 years ago
  • Comments: 25 (7 by maintainers)

Most upvoted comments

Same here on opnsense 22.7.6 with unbound 1.16.3 on FreeBSD:13:amd64. It was hanging a couple of weeks ago, but I just restarted the system. Now unbound is not reacting again. unbound-control seems to hang as I don’t see any stats in the opnsense webui and several unbound-control processes seem to hang:

ps -aux | grep unbound
root             4517   0.0  0.0   13504  2040  -  I    07:04       0:00.03 /bin/sh /usr/local/opnsense/scripts/unbound/cache.sh dump
root             5069   0.0  0.3   23144 12204  -  I    07:04       0:00.03 /usr/local/sbin/unbound-control -c /var/unbound/unbound.conf dump_cache
root             6546   0.0  0.0   13504  2032  -  I    Fri07       0:00.03 /bin/sh /usr/local/opnsense/scripts/unbound/cache.sh dump
root             7211   0.0  0.3   23144 12204  -  I    Fri07       0:00.03 /usr/local/sbin/unbound-control -c /var/unbound/unbound.conf dump_cache
root            12031   0.0  0.1   13504  2124  -  I    13:37       0:00.04 /bin/sh /usr/local/opnsense/scripts/unbound/cache.sh dump
root            12785   0.0  0.3   23144 12368  -  I    13:37       0:00.03 /usr/local/sbin/unbound-control -c /var/unbound/unbound.conf dump_cache
root            25724   0.0  0.3   24000 12640  -  I    13:33       0:00.53 /usr/local/bin/python3 /usr/local/opnsense/scripts/unbound/wrapper.py -s (python3.9)
root            29603   0.0  0.3   23144 12368  -  I    13:33       0:00.04 /usr/local/sbin/unbound-control -c /var/unbound/unbound.conf stats_noreset
root            35130   0.0  0.3   24000 12640  -  I    13:34       0:00.47 /usr/local/bin/python3 /usr/local/opnsense/scripts/unbound/wrapper.py -s (python3.9)
root            37134   0.0  0.3   23144 12368  -  I    13:34       0:00.04 /usr/local/sbin/unbound-control -c /var/unbound/unbound.conf stats_noreset
root            50210   0.0  0.0   13504  2032  -  I    07:02       0:00.02 /bin/sh /usr/local/opnsense/scripts/unbound/cache.sh dump
root            51037   0.0  0.3   23144 12204  -  I    07:02       0:00.03 /usr/local/sbin/unbound-control -c /var/unbound/unbound.conf dump_cache
root            77647   0.0  0.0   13504  2032  -  I    07:04       0:00.04 /bin/sh /usr/local/opnsense/scripts/unbound/cache.sh dump
root            78238   0.0  0.3   23144 12204  -  I    07:04       0:00.03 /usr/local/sbin/unbound-control -c /var/unbound/unbound.conf dump_cache
root            78702   0.0  0.3   24000 12640  -  I    13:34       0:00.58 /usr/local/bin/python3 /usr/local/opnsense/scripts/unbound/wrapper.py -s (python3.9)
root            82675   0.0  0.0   12900  1904  -  Is   Fri07       0:00.01 /usr/local/bin/flock -n -E 0 -o /tmp/unbound_start.lock /usr/local/opnsense/scripts/unbound/start.s
root            82714   0.0  0.0   13504  2036  -  I    Fri07       0:00.01 /bin/sh /usr/local/opnsense/scripts/unbound/start.sh
unbound         84767   0.0  1.2   90188 50712  -  Is   Fri07       0:57.31 /usr/local/sbin/unbound -c /var/unbound/unbound.conf
root            84889   0.0  0.0   13504  2032  -  I    Fri07       0:00.01 /bin/sh /usr/local/opnsense/scripts/unbound/cache.sh load
root            86870   0.0  0.3   23144 12344  -  I    Fri07       0:00.13 /usr/local/sbin/unbound-control -c /var/unbound/unbound.conf load_cache
root            87685   0.0  0.3   23144 12368  -  I    13:34       0:00.04 /usr/local/sbin/unbound-control -c /var/unbound/unbound.conf stats_noreset
root            89081   0.0  0.0   13504  2032  -  I    Fri07       0:00.03 /bin/sh /usr/local/opnsense/scripts/unbound/cache.sh dump
root            90404   0.0  0.3   23144 12204  -  I    Fri07       0:00.03 /usr/local/sbin/unbound-control -c /var/unbound/unbound.conf dump_cache
root            27236   0.0  0.0   12748  1952  0  S+   13:54       0:00.01 grep unbound

I have 38 local-data configured (so not as many as @haarp ) and the first time it failed I had 3 TLS forwarders configured. I switched this to a local dnscrypt running on the same system.

I tried to SIGTERM it, waited over 5 minutes and then SIGKILLed it:

 # kill -15 84767
 # ps -aux | grep 84767
unbound         84767   0.0  1.2   90188 50712  -  Is   Fri07       0:57.35 /usr/local/sbin/unbound -c /var/unbound/unbound.conf
root            13326   0.0  0.0   12748  1952  0  S+   13:57       0:00.01 grep 84767
 # ps -aux | grep 84767
unbound         84767   0.0  1.2   90188 50724  -  Is   Fri07       0:57.60 /usr/local/sbin/unbound -c /var/unbound/unbound.conf
root            60583   0.0  0.0   12748  1952  0  S+   14:03       0:00.01 grep 84767
 # kill -9 84767
 # ps -aux | grep 84767
root             2805   0.0  0.0   12748  1952  0  S+   14:04       0:00.01 grep 84767
 # ps -aux | grep unbound
unbound          5687   3.5  1.1   90188 44984  -  Ss   14:04       0:00.52 /usr/local/sbin/unbound -c /var/unbound/unbound.conf
root            78973   0.0  0.0   12748  1952  0  S+   14:04       0:00.01 grep unbound

All the unbound-control processes went away and the new process responds normal again. Let me know if/how I can gather more info now or when the next hang occurs (might take a couple of weeks again)

+1
dicer on Oct 29, 2022
Read more comments on GitHub
← unbound: Service Failed with 'timeout'
unbound: unbound client not returning A record that is valid with every other dns client, hex and binary output from server with analysis provided →