Unbound constantly restarting on 20.1

[awerner]

Describe the bug I stumbled upon the Unbound logfile showing restarts of unbound every 2-5s. I have already disabled DHCP registration of leases, IDS/IPS (https://forum.opnsense.org/index.php?topic=6373.0). Stopping unbound leads to immediate restart and back in the loop. Restarting the system did not help either. Interesting is that the process ID stays the same, so it is not really "Restart" as it seems.

Clients do not seem to have any issues using the resolver.

Screenshots

Relevant log files

Apr 20 09:31:36 leo unbound: [78982:0] notice: Restart of unbound 1.10.0. 
Apr 20 09:31:36 leo unbound: [78982:0] notice: init module 0: validator 
Apr 20 09:31:36 leo unbound: [78982:0] notice: init module 1: iterator 
Apr 20 09:31:37 leo unbound: [78982:0] info: start of service (unbound 1.10.0). 
Apr 20 09:31:37 leo unbound: [78982:1] info: generate keytag query _ta-4f66. NULL IN 
Apr 20 09:31:39 leo unbound: [78982:0] info: service stopped (unbound 1.10.0). 
Apr 20 09:31:39 leo unbound: [78982:0] info: server stats for thread 0: 1 queries, 1 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting 
Apr 20 09:31:39 leo unbound: [78982:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0 
Apr 20 09:31:39 leo unbound: [78982:0] info: server stats for thread 1: 8 queries, 0 answers from cache, 8 recursions, 0 prefetch, 0 rejected by ip ratelimiting 
Apr 20 09:31:39 leo unbound: [78982:0] info: server stats for thread 1: requestlist max 1 avg 0.25 exceeded 0 jostled 0 
Apr 20 09:31:39 leo unbound: [78982:0] info: average recursion processing time 0.120599 sec 
Apr 20 09:31:39 leo unbound: [78982:0] info: histogram of recursion processing times 
Apr 20 09:31:39 leo unbound: [78982:0] info: [25%]=0.08192 median[50%]=0.114688 [75%]=0.174763 
Apr 20 09:31:39 leo unbound: [78982:0] info: lower(secs) upper(secs) recursions 
Apr 20 09:31:39 leo unbound: [78982:0] info:    0.032768    0.065536 1 
Apr 20 09:31:39 leo unbound: [78982:0] info:    0.065536    0.131072 4 
Apr 20 09:31:39 leo unbound: [78982:0] info:    0.131072    0.262144 3 
Apr 20 09:31:39 leo unbound: [78982:0] info: server stats for thread 2: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting 
Apr 20 09:31:39 leo unbound: [78982:0] info: server stats for thread 2: requestlist max 0 avg 0 exceeded 0 jostled 0 
Apr 20 09:31:39 leo unbound: [78982:0] info: average recursion processing time 0.166671 sec 
Apr 20 09:31:39 leo unbound: [78982:0] info: histogram of recursion processing times 
Apr 20 09:31:39 leo unbound: [78982:0] info: [25%]=0 median[50%]=0 [75%]=0 
Apr 20 09:31:39 leo unbound: [78982:0] info: lower(secs) upper(secs) recursions 
Apr 20 09:31:39 leo unbound: [78982:0] info:    0.131072    0.262144 1 
Apr 20 09:31:39 leo unbound: [78982:0] info: server stats for thread 3: 2 queries, 0 answers from cache, 2 recursions, 0 prefetch, 0 rejected by ip ratelimiting 
Apr 20 09:31:39 leo unbound: [78982:0] info: server stats for thread 3: requestlist max 0 avg 0 exceeded 0 jostled 0 
Apr 20 09:31:39 leo unbound: [78982:0] info: average recursion processing time 0.448173 sec 
Apr 20 09:31:39 leo unbound: [78982:0] info: histogram of recursion processing times 
Apr 20 09:31:39 leo unbound: [78982:0] info: [25%]=0 median[50%]=0 [75%]=0 
Apr 20 09:31:39 leo unbound: [78982:0] info: lower(secs) upper(secs) recursions 
Apr 20 09:31:39 leo unbound: [78982:0] info:    0.131072    0.262144 1 
Apr 20 09:31:39 leo unbound: [78982:0] info:    0.524288    1.000000 1 
Apr 20 09:31:39 leo unbound: [78982:0] notice: Restart of unbound 1.10.0. 
Apr 20 09:31:39 leo unbound: [78982:0] notice: init module 0: validator 
Apr 20 09:31:39 leo unbound: [78982:0] notice: init module 1: iterator 
Apr 20 09:31:39 leo unbound: [78982:0] info: start of service (unbound 1.10.0). 

Environment

• OPNsense 20.1.4-amd64
• os-acme-client
• os-dyndns
• os-etpro-telemetry (IDS/IPS currently disabled)
• os-freeradius
• os-igmp-proxy (currently unused)
• os-lldpd
• os-netdata
• os-wireguard
• os-zabbix-agent
• os-zerotier (currently unused)

[AdSchellevis]

dhcp registration? I believe that asks for a "reload" of the service. a normal restart stops and starts the service.

[awerner]

@AdSchellevis I tried to triage the problem here by disabling all possibly related stuff. I'm now seeing /usr/local/bin/python3 /usr/local/opnsense/service/configd_ctl.py interface newipv6 igb0 running every other second. Disabling DHCP6 on igb0 immediatly solved the issue and brought the whole router load massively down. I'll investigate why the newipv6 is running so often, the addresses on igb0 are staying the same.

[AdSchellevis]

dmesg might provide some additional clues if its related to a devd event