After upgrade to 22.7.x unbound unexpectedly stops during boot

[billgertz]

Important notices

Before you add a new report, we ask you kindly to acknowledge the following:

• [x] I have read the contributing guide lines at https://github.com/opnsense/core/blob/master/CONTRIBUTING.md
• [x] I am convinced that my issue is new after having checked both open and closed issues at https://github.com/opnsense/core/issues?q=is%3Aissue

After upgrading to 22.7 unbound stops unexpectedly during autostart at boot time. Steps to reproduce the behavior:

1. Configure unbound with host overrides
2. Update to OPNSense 22.7 from OPNSense 22.1.10
3. Reboot the system

Expected behavior

Unbound should come up and stay up at boot time.

Describe alternatives you considered

Used solution from closed issue #2828 and setup a rc startup script in /usr/local/etc/rc.syshook.d/start/50-dnsrestarter:

#!/bin/sh
# Added since DNS plugin would not start after a system reboot see issue #2828 opnsense/core
/usr/local/sbin/pluginctl dns restart

The system boots without unbound/ DNS startup issues when rolled back to previous minor version 22.1.10 from VM snapshot.

Relevant log files

Without the above solution, ha-proxy (fails to start), and syslog-ng (stalls) show problems as unbound is not running:

<10>1 2022-09-16T10:35:41+02:00 opnsense.blockfish.net reboot 22455 - [meta sequenceId="1"] rebooted by admin.bill
<45>1 2022-09-16T10:35:41+02:00 opnsense.blockfish.net syslog-ng 16673 - [meta sequenceId="2"] syslog-ng shutting down; version='3.38.1'
<45>1 2022-09-16T10:36:36+02:00 opnsense.blockfish.net syslog-ng 10933 - [meta sequenceId="1"] syslog-ng starting up; version='3.38.1'
<13>1 2022-09-16T10:37:09+02:00 opnsense.blockfish.net dhcp6c 29641 - [meta sequenceId="2"] RTSOLD script - Starting dhcp6 client
<11>1 2022-09-16T10:37:09+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="3"] /usr/local/etc/rc.bootup: Device ovpns1 is not assigned, configuring late
<11>1 2022-09-16T10:37:09+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="4"] /usr/local/etc/rc.bootup: Device ovpnc2 is not assigned, configuring late
<13>1 2022-09-16T10:37:10+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="5"] plugins_configure early (1)
<13>1 2022-09-16T10:37:10+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="6"] plugins_configure early (execute task : openssh_configure_do(1))
<13>1 2022-09-16T10:37:10+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="7"] plugins_configure early (execute task : unbound_cache_flush(1))
<13>1 2022-09-16T10:37:10+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="8"] plugins_configure early (execute task : webgui_configure_do(1))
<11>1 2022-09-16T10:37:10+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="9"] /usr/local/etc/rc.bootup: ROUTING: entering configure using defaults
<11>1 2022-09-16T10:37:10+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="10"] /usr/local/etc/rc.bootup: ROUTING: IPv4 default gateway set to wan
<11>1 2022-09-16T10:37:10+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="11"] /usr/local/etc/rc.bootup: ROUTING: setting IPv4 default route to 10.70.0.254
<11>1 2022-09-16T10:37:10+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="12"] /usr/local/etc/rc.bootup: ROUTING: creating /tmp/xn1_defaultgw using '10.70.0.254'
<11>1 2022-09-16T10:37:10+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="13"] /usr/local/etc/rc.bootup: ROUTING: IPv6 default gateway set to wan
<11>1 2022-09-16T10:37:10+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="14"] /usr/local/etc/rc.bootup: ROUTING: skipping IPv6 default route
<13>1 2022-09-16T10:37:10+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="15"] plugins_configure dhcp (1)
<13>1 2022-09-16T10:37:10+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="16"] plugins_configure dhcp (execute task : dhcpd_dhcp_configure(1))
<13>1 2022-09-16T10:37:10+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="17"] plugins_configure dhcrelay (1)
<13>1 2022-09-16T10:37:10+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="18"] plugins_configure dhcrelay (execute task : dhcpd_dhcrelay_configure(1))
<13>1 2022-09-16T10:37:10+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="19"] plugins_configure dns (1)
<13>1 2022-09-16T10:37:10+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="20"] plugins_configure dns (execute task : dnsmasq_configure_do(1))
<13>1 2022-09-16T10:37:10+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="21"] plugins_configure dns (execute task : unbound_configure_do(1))
<11>1 2022-09-16T10:37:10+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="22"] /usr/local/etc/rc.bootup: warning: ignoring missing default tunable request: debug.pfftpproxy
<27>1 2022-09-16T10:37:10+02:00 opnsense.blockfish.net dhcp6c 29991 - [meta sequenceId="23"] transmit failed: Can't assign requested address
<13>1 2022-09-16T10:37:10+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="24"] plugins_configure monitor (1,,1)
<13>1 2022-09-16T10:37:10+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="25"] plugins_configure monitor (execute task : dpinger_configure_do(1,,1))
<11>1 2022-09-16T10:37:10+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="26"] /usr/local/etc/rc.bootup: Removing static route for monitor 212.121.121.207 via 10.70.0.254
<11>1 2022-09-16T10:37:10+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="27"] /usr/local/etc/rc.bootup: The DMZINTERNAL_SLAAC monitor address is empty, skipping.
<13>1 2022-09-16T10:37:11+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="28"] plugins_configure vpn (1)
<13>1 2022-09-16T10:37:11+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="29"] plugins_configure vpn (execute task : ipsec_configure_do(1))
<13>1 2022-09-16T10:37:13+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="30"] plugins_configure vpn (execute task : openvpn_configure_do(1))
<11>1 2022-09-16T10:37:13+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="31"] /usr/local/etc/rc.bootup: Resyncing OpenVPN instances.
<11>1 2022-09-16T10:37:13+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="32"] /usr/local/etc/rc.bootup: OpenVPN server 1 instance started on PID 271.
<13>1 2022-09-16T10:37:13+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="33"] plugins_configure bootup (1)
<13>1 2022-09-16T10:37:13+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="34"] plugins_configure bootup (execute task : igmpproxy_configure_do(1))
<13>1 2022-09-16T10:37:13+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="35"] plugins_configure bootup (execute task : ntpd_configure_do(1))
<13>1 2022-09-16T10:37:13+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="36"] plugins_configure bootup (execute task : opendns_configure_do(1))
<11>1 2022-09-16T10:37:13+02:00 opnsense.blockfish.net opnsense 3419 - [meta sequenceId="37"] /usr/local/etc/rc.newwanip: IP renewal deferred during boot on 'ovpns1'
<13>1 2022-09-16T10:37:13+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="38"] opendns response: good 92.66.136.145
<13>1 2022-09-16T10:37:13+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="39"] plugins_configure bootup (execute task : unbound_configure_do(1))
<11>1 2022-09-16T10:37:13+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="40"] /usr/local/etc/rc.bootup: warning: ignoring missing default tunable request: debug.pfftpproxy
<11>1 2022-09-16T10:37:14+02:00 opnsense.blockfish.net opnsense 35011 - [meta sequenceId="41"] /usr/local/etc/rc.newwanip: IPv4 renewal is starting on 'ovpns1'
<11>1 2022-09-16T10:37:14+02:00 opnsense.blockfish.net opnsense 35011 - [meta sequenceId="42"] /usr/local/etc/rc.newwanip: Interface '' (ovpns1) is disabled or empty, nothing to do.
<11>1 2022-09-16T10:37:14+02:00 opnsense.blockfish.net opnsense 37374 - [meta sequenceId="43"] /usr/local/etc/rc.routing_configure: ROUTING: entering configure using defaults
<11>1 2022-09-16T10:37:14+02:00 opnsense.blockfish.net opnsense 37374 - [meta sequenceId="44"] /usr/local/etc/rc.routing_configure: ROUTING: IPv4 default gateway set to wan
<11>1 2022-09-16T10:37:14+02:00 opnsense.blockfish.net opnsense 37374 - [meta sequenceId="45"] /usr/local/etc/rc.routing_configure: ROUTING: setting IPv4 default route to 10.70.0.254
<11>1 2022-09-16T10:37:14+02:00 opnsense.blockfish.net opnsense 37374 - [meta sequenceId="46"] /usr/local/etc/rc.routing_configure: ROUTING: keeping current default gateway '10.70.0.254'
<11>1 2022-09-16T10:37:14+02:00 opnsense.blockfish.net opnsense 37374 - [meta sequenceId="47"] /usr/local/etc/rc.routing_configure: ROUTING: IPv6 default gateway set to wan
<11>1 2022-09-16T10:37:14+02:00 opnsense.blockfish.net opnsense 37374 - [meta sequenceId="48"] /usr/local/etc/rc.routing_configure: ROUTING: skipping IPv6 default route
<13>1 2022-09-16T10:37:14+02:00 opnsense.blockfish.net opnsense 37374 - [meta sequenceId="49"] plugins_configure monitor (1,)
<13>1 2022-09-16T10:37:14+02:00 opnsense.blockfish.net opnsense 37374 - [meta sequenceId="50"] plugins_configure monitor (execute task : dpinger_configure_do(1,))
<11>1 2022-09-16T10:37:14+02:00 opnsense.blockfish.net opnsense 37374 - [meta sequenceId="51"] /usr/local/etc/rc.routing_configure: Removing static route for monitor 212.121.121.207 via 10.70.0.254
<11>1 2022-09-16T10:37:14+02:00 opnsense.blockfish.net opnsense 37374 - [meta sequenceId="52"] /usr/local/etc/rc.routing_configure: The DMZINTERNAL_SLAAC monitor address is empty, skipping.
<28>1 2022-09-16T10:37:14+02:00 opnsense.blockfish.net lldpd 35781 - [meta sequenceId="53"] unable to create /var/empty/etc directory: Operation not permitted
<28>1 2022-09-16T10:37:15+02:00 opnsense.blockfish.net radiusd 43662 - [meta sequenceId="54"] Ignoring "sql" (see raddb/mods-available/README.rst)
<28>1 2022-09-16T10:37:15+02:00 opnsense.blockfish.net radiusd 43662 - [meta sequenceId="55"] Ignoring "ldap" (see raddb/mods-available/README.rst)
<43>1 2022-09-16T10:39:27+02:00 opnsense.blockfish.net syslog-ng 10933 - [meta sequenceId="56"] Error resolving hostname with getaddrinfo(); host='graylog.blockfish.net', error='8', error_str='Name does not resolve'
<43>1 2022-09-16T10:39:27+02:00 opnsense.blockfish.net syslog-ng 10933 - [meta sequenceId="57"] Initiating connection failed, reconnecting; time_reopen='60'
<85>1 2022-09-16T10:40:00+02:00 opnsense.blockfish.net sudo 62192 - [meta sequenceId="58"] admin.bill : TTY=pts/0 ; PWD=/home/admin.bill ; USER=root ; COMMAND=/usr/bin/su -
<43>1 2022-09-16T10:41:41+02:00 opnsense.blockfish.net syslog-ng 10933 - [meta sequenceId="59"] Error resolving hostname with getaddrinfo(); host='graylog.blockfish.net', error='8', error_str='Name does not resolve'
<43>1 2022-09-16T10:41:41+02:00 opnsense.blockfish.net syslog-ng 10933 - [meta sequenceId="60"] Initiating connection failed, reconnecting; time_reopen='60'
<45>1 2022-09-16T10:42:48+02:00 opnsense.blockfish.net syslog-ng 10933 - [meta sequenceId="1"] Syslog connection established; fd='6', server='AF_INET(10.69.0.214:9514)', local='AF_INET(0.0.0.0:0)'
<13>1 2022-09-16T10:42:53+02:00 opnsense.blockfish.net root 84843 - [meta sequenceId="2"] /usr/local/etc/rc.d/haproxy: WARNING: failed precmd routine for haproxy
<45>1 2022-09-16T10:42:54+02:00 opnsense.blockfish.net syslog-ng 10933 - [meta sequenceId="1"] Configuration reload request received, reloading configuration;
<45>1 2022-09-16T10:42:54+02:00 opnsense.blockfish.net syslog-ng 10933 - [meta sequenceId="2"] Configuration reload finished;

When the 'forced' plugincrl start hook in /usr/local/etc/rc.syshook.d everything starts normally:

<10>1 2022-09-16T10:47:11+02:00 opnsense.blockfish.net reboot 74255 - [meta sequenceId="1"] rebooted by admin.bill
<45>1 2022-09-16T10:47:11+02:00 opnsense.blockfish.net syslog-ng 10933 - [meta sequenceId="2"] syslog-ng shutting down; version='3.38.1'
<45>1 2022-09-16T10:48:06+02:00 opnsense.blockfish.net syslog-ng 10458 - [meta sequenceId="1"] syslog-ng starting up; version='3.38.1'
<13>1 2022-09-16T10:48:39+02:00 opnsense.blockfish.net dhcp6c 31037 - [meta sequenceId="2"] RTSOLD script - Starting dhcp6 client
<11>1 2022-09-16T10:48:39+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="3"] /usr/local/etc/rc.bootup: Device ovpns1 is not assigned, configuring late
<11>1 2022-09-16T10:48:39+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="4"] /usr/local/etc/rc.bootup: Device ovpnc2 is not assigned, configuring late
<13>1 2022-09-16T10:48:39+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="5"] plugins_configure early (1)
<13>1 2022-09-16T10:48:39+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="6"] plugins_configure early (execute task : openssh_configure_do(1))
<13>1 2022-09-16T10:48:39+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="7"] plugins_configure early (execute task : unbound_cache_flush(1))
<13>1 2022-09-16T10:48:39+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="8"] plugins_configure early (execute task : webgui_configure_do(1))
<11>1 2022-09-16T10:48:39+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="9"] /usr/local/etc/rc.bootup: ROUTING: entering configure using defaults
<11>1 2022-09-16T10:48:39+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="10"] /usr/local/etc/rc.bootup: ROUTING: IPv4 default gateway set to wan
<11>1 2022-09-16T10:48:39+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="11"] /usr/local/etc/rc.bootup: ROUTING: setting IPv4 default route to 10.70.0.254
<11>1 2022-09-16T10:48:39+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="12"] /usr/local/etc/rc.bootup: ROUTING: creating /tmp/xn1_defaultgw using '10.70.0.254'
<11>1 2022-09-16T10:48:39+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="13"] /usr/local/etc/rc.bootup: ROUTING: IPv6 default gateway set to wan
<11>1 2022-09-16T10:48:39+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="14"] /usr/local/etc/rc.bootup: ROUTING: skipping IPv6 default route
<13>1 2022-09-16T10:48:39+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="15"] plugins_configure dhcp (1)
<13>1 2022-09-16T10:48:39+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="16"] plugins_configure dhcp (execute task : dhcpd_dhcp_configure(1))
<13>1 2022-09-16T10:48:39+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="17"] plugins_configure dhcrelay (1)
<13>1 2022-09-16T10:48:39+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="18"] plugins_configure dhcrelay (execute task : dhcpd_dhcrelay_configure(1))
<13>1 2022-09-16T10:48:39+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="19"] plugins_configure dns (1)
<13>1 2022-09-16T10:48:39+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="20"] plugins_configure dns (execute task : dnsmasq_configure_do(1))
<13>1 2022-09-16T10:48:39+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="21"] plugins_configure dns (execute task : unbound_configure_do(1))
<11>1 2022-09-16T10:48:39+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="22"] /usr/local/etc/rc.bootup: warning: ignoring missing default tunable request: debug.pfftpproxy
<27>1 2022-09-16T10:48:39+02:00 opnsense.blockfish.net dhcp6c 31897 - [meta sequenceId="23"] transmit failed: Can't assign requested address
<13>1 2022-09-16T10:48:40+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="24"] plugins_configure monitor (1,,1)
<13>1 2022-09-16T10:48:40+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="25"] plugins_configure monitor (execute task : dpinger_configure_do(1,,1))
<11>1 2022-09-16T10:48:40+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="26"] /usr/local/etc/rc.bootup: Removing static route for monitor 212.121.121.207 via 10.70.0.254
<11>1 2022-09-16T10:48:40+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="27"] /usr/local/etc/rc.bootup: The DMZINTERNAL_SLAAC monitor address is empty, skipping.
<13>1 2022-09-16T10:48:40+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="28"] plugins_configure vpn (1)
<13>1 2022-09-16T10:48:40+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="29"] plugins_configure vpn (execute task : ipsec_configure_do(1))
<13>1 2022-09-16T10:48:42+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="30"] plugins_configure vpn (execute task : openvpn_configure_do(1))
<11>1 2022-09-16T10:48:42+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="31"] /usr/local/etc/rc.bootup: Resyncing OpenVPN instances.
<11>1 2022-09-16T10:48:42+02:00 opnsense.blockfish.net opnsense 99133 - [meta sequenceId="32"] /usr/local/etc/rc.newwanip: IP renewal deferred during boot on 'ovpns1'
<11>1 2022-09-16T10:48:42+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="33"] /usr/local/etc/rc.bootup: OpenVPN server 1 instance started on PID 97375.
<13>1 2022-09-16T10:48:42+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="34"] plugins_configure bootup (1)
<13>1 2022-09-16T10:48:42+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="35"] plugins_configure bootup (execute task : igmpproxy_configure_do(1))
<13>1 2022-09-16T10:48:42+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="36"] plugins_configure bootup (execute task : ntpd_configure_do(1))
<13>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="37"] plugins_configure bootup (execute task : opendns_configure_do(1))
<13>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="38"] opendns response: good 92.66.136.145
<13>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="39"] plugins_configure bootup (execute task : unbound_configure_do(1))
<11>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net php 550 - [meta sequenceId="40"] /usr/local/etc/rc.bootup: warning: ignoring missing default tunable request: debug.pfftpproxy
<11>1 2022-09-16T10:48:44+02:00 opnsense.blockfish.net opnsense 32317 - [meta sequenceId="41"] /usr/local/etc/rc.newwanip: IPv4 renewal is starting on 'ovpns1'
<11>1 2022-09-16T10:48:44+02:00 opnsense.blockfish.net opnsense 32317 - [meta sequenceId="42"] /usr/local/etc/rc.newwanip: Interface '' (ovpns1) is disabled or empty, nothing to do.
<11>1 2022-09-16T10:48:44+02:00 opnsense.blockfish.net opnsense 35299 - [meta sequenceId="43"] /usr/local/etc/rc.routing_configure: ROUTING: entering configure using defaults
<11>1 2022-09-16T10:48:44+02:00 opnsense.blockfish.net opnsense 35299 - [meta sequenceId="44"] /usr/local/etc/rc.routing_configure: ROUTING: IPv4 default gateway set to wan
<11>1 2022-09-16T10:48:44+02:00 opnsense.blockfish.net opnsense 35299 - [meta sequenceId="45"] /usr/local/etc/rc.routing_configure: ROUTING: setting IPv4 default route to 10.70.0.254
<11>1 2022-09-16T10:48:44+02:00 opnsense.blockfish.net opnsense 35299 - [meta sequenceId="46"] /usr/local/etc/rc.routing_configure: ROUTING: keeping current default gateway '10.70.0.254'
<11>1 2022-09-16T10:48:44+02:00 opnsense.blockfish.net opnsense 35299 - [meta sequenceId="47"] /usr/local/etc/rc.routing_configure: ROUTING: IPv6 default gateway set to wan
<11>1 2022-09-16T10:48:44+02:00 opnsense.blockfish.net opnsense 35299 - [meta sequenceId="48"] /usr/local/etc/rc.routing_configure: ROUTING: skipping IPv6 default route
<13>1 2022-09-16T10:48:44+02:00 opnsense.blockfish.net opnsense 35299 - [meta sequenceId="49"] plugins_configure monitor (1,)
<13>1 2022-09-16T10:48:44+02:00 opnsense.blockfish.net opnsense 35299 - [meta sequenceId="50"] plugins_configure monitor (execute task : dpinger_configure_do(1,))
<11>1 2022-09-16T10:48:44+02:00 opnsense.blockfish.net opnsense 35299 - [meta sequenceId="51"] /usr/local/etc/rc.routing_configure: Removing static route for monitor 212.121.121.207 via 10.70.0.254
<11>1 2022-09-16T10:48:44+02:00 opnsense.blockfish.net opnsense 35299 - [meta sequenceId="52"] /usr/local/etc/rc.routing_configure: The DMZINTERNAL_SLAAC monitor address is empty, skipping.
<28>1 2022-09-16T10:48:44+02:00 opnsense.blockfish.net lldpd 17638 - [meta sequenceId="53"] unable to create /var/empty/etc directory: Operation not permitted
<28>1 2022-09-16T10:48:44+02:00 opnsense.blockfish.net radiusd 53102 - [meta sequenceId="54"] Ignoring "sql" (see raddb/mods-available/README.rst)
<28>1 2022-09-16T10:48:44+02:00 opnsense.blockfish.net radiusd 53102 - [meta sequenceId="55"] Ignoring "ldap" (see raddb/mods-available/README.rst)
<13>1 2022-09-16T10:48:45+02:00 opnsense.blockfish.net opnsense 4378 - [meta sequenceId="56"] plugins_configure dns (1,restart)
<13>1 2022-09-16T10:48:45+02:00 opnsense.blockfish.net opnsense 4378 - [meta sequenceId="57"] plugins_configure dns (execute task : dnsmasq_configure_do(1))
<13>1 2022-09-16T10:48:45+02:00 opnsense.blockfish.net opnsense 4378 - [meta sequenceId="58"] plugins_configure dns (execute task : unbound_configure_do(1))
<11>1 2022-09-16T10:48:45+02:00 opnsense.blockfish.net php 4378 - [meta sequenceId="59"] /usr/local/sbin/pluginctl: warning: ignoring missing default tunable request: debug.pfftpproxy
<45>1 2022-09-16T10:48:45+02:00 opnsense.blockfish.net syslog-ng 10458 - [meta sequenceId="1"] Syslog connection established; fd='23', server='AF_INET(10.69.0.214:9514)', local='AF_INET(0.0.0.0:0)'
<45>1 2022-09-16T10:48:45+02:00 opnsense.blockfish.net syslog-ng 10458 - [meta sequenceId="2"] Configuration reload request received, reloading configuration;
<45>1 2022-09-16T10:48:45+02:00 opnsense.blockfish.net syslog-ng 10458 - [meta sequenceId="3"] Configuration reload finished;

Environment

OPNsense 22.7 to 22.7.4 (amd64, OpenSSL) XCP-ng 8.2 LTS AMD Ryzen 9 3900X 12-Core Processor Network Realtek RTL8129

[swhite2]

What do the Unbound logs say?

[billgertz]

Good suggestion, however after examining the log I cannot tell why unbound is stopped. Nor can I tell if unbound stopped itself or was requested to stop via pluginctl.

I didn't see it the first time I scanned the log - something stops unbound. Only one other thing of note: warnings for PTR records that already exist. So here is the forced? stop at 10:48:43:

<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="150"] [80266:0] info: service stopped (unbound 1.16.2).

With the patch script in /usr/local/etc/rc.syshook.d you see the process kicked off a second time at 10:48:44:

<29>1 2022-09-16T10:48:44+02:00 opnsense.blockfish.net unbound 13176 - [meta sequenceId="192"] [13176:0] notice: init module 0: validator
<29>1 2022-09-16T10:48:44+02:00 opnsense.blockfish.net unbound 13176 - [meta sequenceId="193"] [13176:0] notice: init module 1: iterator
<30>1 2022-09-16T10:48:44+02:00 opnsense.blockfish.net unbound 13176 - [meta sequenceId="194"] [13176:0] info: start of service (unbound 1.16.2).
<165>1 2022-09-16T10:48:44+02:00 opnsense.blockfish.net unbound 24199 - [meta sequenceId="195"] daemonize unbound dhcpd watcher.

Here is the complete log with the PTR warnings edited out:

<29>1 2022-09-16T10:37:10+02:00 opnsense.blockfish.net unbound 81353 - [meta sequenceId="63"] [81353:0] notice: init module 0: validator
<29>1 2022-09-16T10:37:10+02:00 opnsense.blockfish.net unbound 81353 - [meta sequenceId="64"] [81353:0] notice: init module 1: iterator
<30>1 2022-09-16T10:37:10+02:00 opnsense.blockfish.net unbound 81353 - [meta sequenceId="65"] [81353:0] info: start of service (unbound 1.16.2).
<30>1 2022-09-16T10:37:10+02:00 opnsense.blockfish.net unbound 81353 - [meta sequenceId="66"] [81353:1] info: generate keytag query _ta-4f66. NULL IN
<165>1 2022-09-16T10:37:10+02:00 opnsense.blockfish.net unbound 83579 - [meta sequenceId="67"] daemonize unbound dhcpd watcher.
.
.
.
<164>1 2022-09-16T10:37:13+02:00 opnsense.blockfish.net unbound 550 - [meta sequenceId="69"] PTR record already exists for host.blockfish.net(xxx.xxx.xxx.xxx)
.
.
.
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="150"] [80266:0] info: service stopped (unbound 1.16.2).
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="151"] [80266:0] info: server stats for thread 0: 13 queries, 0 answers from cache, 13 recursions, 0 prefetch, 0 rejected by ip ratelimiting
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="152"] [80266:0] info: server stats for thread 0: requestlist max 6 avg 1.76923 exceeded 0 jostled 0
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="153"] [80266:0] info: average recursion processing time 0.019167 sec
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="154"] [80266:0] info: histogram of recursion processing times
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="155"] [80266:0] info: [25%]=0.008704 median[50%]=0.01536 [75%]=0.0253952
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="156"] [80266:0] info: lower(secs) upper(secs) recursions
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="157"] [80266:0] info:    0.004096    0.008192 3
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="158"] [80266:0] info:    0.008192    0.016384 4
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="159"] [80266:0] info:    0.016384    0.032768 5
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="160"] [80266:0] info:    0.065536    0.131072 1
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="161"] [80266:0] info: server stats for thread 1: 13 queries, 0 answers from cache, 13 recursions, 0 prefetch, 0 rejected by ip ratelimiting
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="162"] [80266:0] info: server stats for thread 1: requestlist max 5 avg 1.53846 exceeded 0 jostled 0
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="163"] [80266:0] info: average recursion processing time 0.022963 sec
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="164"] [80266:0] info: histogram of recursion processing times
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="165"] [80266:0] info: [25%]=0.01024 median[50%]=0.0232107 [75%]=0.0320853
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="166"] [80266:0] info: lower(secs) upper(secs) recursions
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="167"] [80266:0] info:    0.004096    0.008192 3
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="168"] [80266:0] info:    0.008192    0.016384 1
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="169"] [80266:0] info:    0.016384    0.032768 6
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="170"] [80266:0] info:    0.032768    0.065536 3
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="171"] [80266:0] info: server stats for thread 2: 8 queries, 0 answers from cache, 8 recursions, 0 prefetch, 0 rejected by ip ratelimiting
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="172"] [80266:0] info: server stats for thread 2: requestlist max 3 avg 0.75 exceeded 0 jostled 0
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="173"] [80266:0] info: average recursion processing time 0.026501 sec
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="174"] [80266:0] info: histogram of recursion processing times
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="175"] [80266:0] info: [25%]=0.012288 median[50%]=0.0218453 [75%]=0.032768
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="176"] [80266:0] info: lower(secs) upper(secs) recursions
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="177"] [80266:0] info:    0.004096    0.008192 1
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="178"] [80266:0] info:    0.008192    0.016384 2
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="179"] [80266:0] info:    0.016384    0.032768 3
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="180"] [80266:0] info:    0.032768    0.065536 2
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="181"] [80266:0] info: server stats for thread 3: 18 queries, 2 answers from cache, 16 recursions, 0 prefetch, 0 rejected by ip ratelimiting
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="182"] [80266:0] info: server stats for thread 3: requestlist max 7 avg 1.875 exceeded 0 jostled 0
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="183"] [80266:0] info: average recursion processing time 0.026760 sec
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="184"] [80266:0] info: histogram of recursion processing times
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="185"] [80266:0] info: [25%]=0.0109227 median[50%]=0.016384 [75%]=0.032768
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="186"] [80266:0] info: lower(secs) upper(secs) recursions
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="187"] [80266:0] info:    0.004096    0.008192 2
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="188"] [80266:0] info:    0.008192    0.016384 6
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="189"] [80266:0] info:    0.016384    0.032768 4
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="190"] [80266:0] info:    0.032768    0.065536 3
<30>1 2022-09-16T10:48:43+02:00 opnsense.blockfish.net unbound 80266 - [meta sequenceId="191"] [80266:0] info:    0.065536    0.131072 1
<29>1 2022-09-16T10:48:44+02:00 opnsense.blockfish.net unbound 13176 - [meta sequenceId="192"] [13176:0] notice: init module 0: validator
<29>1 2022-09-16T10:48:44+02:00 opnsense.blockfish.net unbound 13176 - [meta sequenceId="193"] [13176:0] notice: init module 1: iterator
<30>1 2022-09-16T10:48:44+02:00 opnsense.blockfish.net unbound 13176 - [meta sequenceId="194"] [13176:0] info: start of service (unbound 1.16.2).
<165>1 2022-09-16T10:48:44+02:00 opnsense.blockfish.net unbound 24199 - [meta sequenceId="195"] daemonize unbound dhcpd watcher.

[billgertz]

Anything else I should look for or turn on for deeper debugging? Currently all we can see is that unbound stops after loading all the overrides, no idea if unbound bailed or perhaps the daemon code is asking it to stop. The syslog message: service stopped (unbound 1.16.2).

The message seems to be be emitted from line 708 of opnsense/src/contrib/unbound/daemon/daemon.c:

#ifdef HAVE_SYSTEMD
	ret = sd_notify(0, "READY=1");
	if(ret <= 0 && getenv("NOTIFY_SOCKET"))
		fatal_exit("sd_notify failed %s: %s. Make sure that unbound has "
				"access/permission to use the socket presented by systemd.",
				getenv("NOTIFY_SOCKET"),
				(ret==0?"no $NOTIFY_SOCKET": strerror(-ret)));
#endif
	log_info("start of service (%s).", PACKAGE_STRING);
	worker_work(daemon->workers[0]);
#ifdef HAVE_SYSTEMD
	if (daemon->workers[0]->need_to_exit)
		sd_notify(0, "STOPPING=1");
	else
		sd_notify(0, "RELOADING=1");
#endif

708 log_info("service stopped (%s).", PACKAGE_STRING);

	/* we exited! a signal happened! Stop other threads */
	daemon_stop_others(daemon);

	/* Shutdown SHM */
	shm_main_shutdown(daemon);

	daemon->need_to_exit = daemon->workers[0]->need_to_exit;
}

[swhite2]

<45>1 2022-09-16T10:42:48+02:00 opnsense.blockfish.net syslog-ng 10933 - [meta sequenceId="1"] Syslog connection established; fd='6', server='AF_INET(10.69.0.214:9514)', local='AF_INET(0.0.0.0:0)'

It seems that a minute later DNS seems to be up. Wondering where the delay comes from. Can you confirm Unbound is indeed not running at a certain point in time after boot? e.g. ps -fax | grep unbound.

[billgertz]

It's up because I added a patch script as /usr/local/etc/rc.syshook.d/start/50-dnsrestarter to force (re)start unbound. I can confirm without this script that unbound is truly dead.

[billgertz]

Looks like paying close attention to the logs has revealed a corrupt unbound host override config file. But blow by painful blow here we go:

First, move the startup hack script out of the /usr/local/etc/rc.syshook.d/start directory:

root@opnsense:/usr/local/etc/rc.syshook.d/start # ls
10-newwanip	20-freebsd	25-syslog	50-dnsrestarter	50-frr		50-haproxy	50-xen		90-carp		90-cron		95-beep
root@opnsense:/usr/local/etc/rc.syshook.d/start # mv 50-dnsrestarter ~/
root@opnsense:/usr/local/etc/rc.syshook.d/start # ls
10-newwanip	20-freebsd	25-syslog	50-frr		50-haproxy	50-xen		90-carp		90-cron		95-beep
root@opnsense:/usr/local/etc/rc.syshook.d/start # 

Yes, unbound is definitely not running straight after the reboot:

root@opnsense:~ # ps -fax| grep unbound
 1226  0  S+    0:00.00 grep unbound
root@opnsense:~ # 

And here is the complete resolver log showing the odd startup and then halt:

<165>1 2022-10-05T07:53:57+02:00 opnsense.blockfish.net unbound 21155 - [meta sequenceId="1"] dhcpd expired android @ xxx.xxx.xxx.xxx
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="1"] PTR record already exists for host1.blockfish.info(<subnet_a>.25)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="2"] PTR record already exists for host2.blockfish.info(<subnet_a>.25)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="3"] PTR record already exists for host3.blockfish.info(<subnet_a>.25)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="4"] PTR record already exists for host4.blockfish.net(<subnet_a>.25)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="5"] PTR record already exists for host5.blockfish.net(<subnet_a>.25)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="6"] PTR record already exists for host6.blockfish.net(<subnet_a>.25)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="7"] PTR record already exists for host7.blockfish.net(<subnet_b>.199)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="8"] PTR record already exists for host8.blockfish.net(<subnet_b>.199)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="9"] PTR record already exists for host9.blockfish.net(<subnet_b>.199)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="10"] PTR record already exists for host10.blockfish.net(<subnet_b>.199)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="11"] PTR record already exists for host11.blockfish.net(<subnet_c>.225)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="12"] PTR record already exists for host12.blockfish.net(<subnet_c>.225)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="13"] PTR record already exists for host13.blockfish.net(<subnet_b>.200)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="14"] PTR record already exists for host14.blockfish.net(<subnet_c>.254)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="15"] PTR record already exists for host15.blockfish.net(<subnet_c>.253)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="16"] PTR record already exists for host16.blockfish.net(<subnet_c>.253)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="17"] PTR record already exists for host16.blockfish.net(<subnet_c>.253)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="18"] PTR record already exists for host16.blcokfish.net(<subnet_c>.253)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="19"] PTR record already exists for host17.blockfish.net(<subnet_b>.250)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="20"] PTR record already exists for host18.blockfish.net(<subnet_b>.250)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="21"] PTR record already exists for host19.blockfish.net(<subnet_b>.229)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="22"] PTR record already exists for host20.blockfish.net(<subnet_b>.233)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="23"] PTR record already exists for host21.blockfish.net(<subnet_b>.233)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="24"] PTR record already exists for host22.blockfish.net(<subnet_c>.111)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="25"] PTR record already exists for host23.blockfish.net(<subnet_c>112)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="26"] PTR record already exists for host24.blockfish.net(<subnet_c>.200)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="27"] PTR record already exists for host25.blockfish.net(<subnet_c>.220)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="28"] PTR record already exists for host26.blockfish.net(<subnet_c>.201)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="29"] PTR record already exists for host27.blockfish.net(<subnet_c>.202)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="30"] PTR record already exists for host28.blockfish.net(<subnet_a>.81)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="31"] PTR record already exists for host29.blockfish.net(<subnet_a>.81)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="32"] PTR record already exists for host30.blockfish.net(<subnet_a>.101)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="33"] PTR record already exists for host31.blockfish.net(<subnet_a>.101)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="34"] PTR record already exists for host32.blockfish.net(<subnet_a>.168)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="35"] PTR record already exists for host33.blockfish.info(<subnet_a>.168)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="36"] PTR record already exists for host34.blockfish.info(<subnet_a>.168)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="37"] PTR record already exists for host35.blockfish.info(<subnet_a>.204)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="38"] PTR record already exists for host36.blockfish.net(<subnet_c>.214)
<29>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="39"] [90919:0] notice: init module 0: validator
<29>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="40"] [90919:0] notice: init module 1: iterator
<30>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="41"] [90919:0] info: start of service (unbound 1.16.3).
<165>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 92673 - [meta sequenceId="42"] daemonize unbound dhcpd watcher.
<30>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="43"] [90919:3] info: generate keytag query _ta-4f66. NULL IN
<30>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="44"] [90919:2] info: generate keytag query _ta-4f66. NULL IN
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="45"] PTR record already exists for host1.blockfish.info(<subnet_a>.25)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="46"] PTR record already exists for host2.blockfish.info(<subnet_a>.25)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="47"] PTR record already exists for host3.blockfish.info(<subnet_a>.25)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="48"] PTR record already exists for host4.blockfish.net(<subnet_a>.25)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="49"] PTR record already exists for host5.blockfish.net(<subnet_a>.25)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="50"] PTR record already exists for host6.blockfish.net(<subnet_a>.25)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="51"] PTR record already exists for host7.blockfish.net(<subnet_b>.199)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="52"] PTR record already exists for host8.blockfish.net(<subnet_b>.199)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="53"] PTR record already exists for host9.blockfish.net(<subnet_b>.199)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="54"] PTR record already exists for host10.blockfish.net(<subnet_b>.199)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="55"] PTR record already exists for host11.blockfish.net(<subnet_c>.225)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="56"] PTR record already exists for host12.blockfish.net(<subnet_c>.225)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="57"] PTR record already exists for host13.blockfish.net(<subnet_b>.200)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="58"] PTR record already exists for host14.blockfish.net(<subnet_c>.254)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="59"] PTR record already exists for host15.blockfish.net(<subnet_c>.253)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="60"] PTR record already exists for host16.blockfish.net(<subnet_c>.253)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="61"] PTR record already exists for host16.blockfish.net(<subnet_c>.253)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="62"] PTR record already exists for host16.blcokfish.net(<subnet_c>.253)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="63"] PTR record already exists for host17.blockfish.net(<subnet_b>.250)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="64"] PTR record already exists for host18.blockfish.net(<subnet_b>.250)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="65"] PTR record already exists for host19.blockfish.net(<subnet_b>.229)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="66"] PTR record already exists for host20.blockfish.net(<subnet_b>.233)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="67"] PTR record already exists for host21.blockfish.net(<subnet_b>.233)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="68"] PTR record already exists for host22.blockfish.net(<subnet_c>.111)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="69"] PTR record already exists for host23.blockfish.net(<subnet_c>112)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="70"] PTR record already exists for host24.blockfish.net(<subnet_c>.200)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="71"] PTR record already exists for host25.blockfish.net(<subnet_c>.220)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="72"] PTR record already exists for host26.blockfish.net(<subnet_c>.201)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="73"] PTR record already exists for host27.blockfish.net(<subnet_c>.202)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="74"] PTR record already exists for host28.blockfish.net(<subnet_a>.81)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="75"] PTR record already exists for host29.blockfish.net(<subnet_a>.81)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="76"] PTR record already exists for host30.blockfish.net(<subnet_a>.101)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="77"] PTR record already exists for host31.blockfish.net(<subnet_a>.101)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="78"] PTR record already exists for host32.blockfish.net(<subnet_a>.168)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="79"] PTR record already exists for host33.blockfish.info(<subnet_a>.168)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="80"] PTR record already exists for host34.blockfish.info(<subnet_a>.168)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="81"] PTR record already exists for host35.blockfish.info(<subnet_a>.204)
<164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="82"] PTR record already exists for host36.blockfish.net(<subnet_c>.214)
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="83"] [90919:0] info: service stopped (unbound 1.16.3).
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="84"] [90919:0] info: server stats for thread 0: 20 queries, 0 answers from cache, 20 recursions, 0 prefetch, 0 rejected by ip ratelimiting
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="85"] [90919:0] info: server stats for thread 0: requestlist max 3 avg 0.45 exceeded 0 jostled 0
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="86"] [90919:0] info: average recursion processing time 0.016822 sec
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="87"] [90919:0] info: histogram of recursion processing times
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="88"] [90919:0] info: [25%]=0.00750933 median[50%]=0.0118329 [75%]=0.016384
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="89"] [90919:0] info: lower(secs) upper(secs) recursions
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="90"] [90919:0] info:    0.004096    0.008192 6
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="91"] [90919:0] info:    0.008192    0.016384 9
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="92"] [90919:0] info:    0.016384    0.032768 4
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="93"] [90919:0] info:    0.032768    0.065536 1
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="94"] [90919:0] info: server stats for thread 1: 10 queries, 1 answers from cache, 9 recursions, 0 prefetch, 0 rejected by ip ratelimiting
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="95"] [90919:0] info: server stats for thread 1: requestlist max 4 avg 1.11111 exceeded 0 jostled 0
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="96"] [90919:0] info: average recursion processing time 0.041405 sec
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="97"] [90919:0] info: histogram of recursion processing times
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="98"] [90919:0] info: [25%]=0.01536 median[50%]=0.022528 [75%]=0.029696
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="99"] [90919:0] info: lower(secs) upper(secs) recursions
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="100"] [90919:0] info:    0.008192    0.016384 2
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="101"] [90919:0] info:    0.016384    0.032768 4
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="102"] [90919:0] info:    0.131072    0.262144 1
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="103"] [90919:0] info: server stats for thread 2: 16 queries, 3 answers from cache, 13 recursions, 0 prefetch, 0 rejected by ip ratelimiting
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="104"] [90919:0] info: server stats for thread 2: requestlist max 1 avg 0.230769 exceeded 0 jostled 0
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="105"] [90919:0] info: average recursion processing time 0.034776 sec
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="106"] [90919:0] info: histogram of recursion processing times
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="107"] [90919:0] info: [25%]=0.009216 median[50%]=0.024576 [75%]=0.0518827
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="108"] [90919:0] info: lower(secs) upper(secs) recursions
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="109"] [90919:0] info:    0.002048    0.004096 1
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="110"] [90919:0] info:    0.004096    0.008192 2
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="111"] [90919:0] info:    0.008192    0.016384 2
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="112"] [90919:0] info:    0.016384    0.032768 3
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="113"] [90919:0] info:    0.032768    0.065536 3
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="114"] [90919:0] info:    0.065536    0.131072 2
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="115"] [90919:0] info: server stats for thread 3: 10 queries, 1 answers from cache, 9 recursions, 0 prefetch, 0 rejected by ip ratelimiting
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="116"] [90919:0] info: server stats for thread 3: requestlist max 3 avg 0.666667 exceeded 0 jostled 0
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="117"] [90919:0] info: average recursion processing time 0.031161 sec
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="118"] [90919:0] info: histogram of recursion processing times
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="119"] [90919:0] info: [25%]=0.007168 median[50%]=0.014336 [75%]=0.03072
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="120"] [90919:0] info: lower(secs) upper(secs) recursions
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="121"] [90919:0] info:    0.004096    0.008192 3
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="122"] [90919:0] info:    0.008192    0.016384 2
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="123"] [90919:0] info:    0.016384    0.032768 2
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="124"] [90919:0] info:    0.032768    0.065536 1
<30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="125"] [90919:0] info:    0.131072    0.262144 1

The host names and IP addresses have been somewhat anonymized. This detail is important as it is a lead on an underlying problem.

Noticed the bozo entries for host16 - so it seems the unbound override config file is hosed. Also noticed that hosts that alphabetize higher than don't appear in the Services > Unbound DNS > Overrides, Host Overrides tab.

And here is the corresponding system log:

<45>1 2022-10-05T14:06:31+02:00 opnsense.blockfish.net syslog-ng 10458 - [meta sequenceId="1"] Configuration reload request received, reloading configuration;
<45>1 2022-10-05T14:06:31+02:00 opnsense.blockfish.net syslog-ng 10458 - [meta sequenceId="2"] Configuration reload finished;
<147>1 2022-10-05T14:06:33+02:00 opnsense.blockfish.net config 22614 - [meta sequenceId="3"] [2022-10-05T14:06:33+02:00][ERROR] [OPNsense\Quagga\BGP:asnumber] invalid integer value{}
<147>1 2022-10-05T14:06:33+02:00 opnsense.blockfish.net config 22614 - [meta sequenceId="4"] [2022-10-05T14:06:33+02:00][ERROR] Model OPNsense\Quagga\BGP can't be saved, skip ( OPNsense\Phalcon\Filter\Validation\Exception: [OPNsense\Quagga\BGP:asnumber] invalid integer value{}
<147>1 2022-10-05T14:06:33+02:00 opnsense.blockfish.net config 22614 - [meta sequenceId="5"]  in /usr/local/opnsense/mvc/app/models/OPNsense/Base/BaseModel.php:583
<147>1 2022-10-05T14:06:33+02:00 opnsense.blockfish.net config 22614 - [meta sequenceId="6"] Stack trace:
<147>1 2022-10-05T14:06:33+02:00 opnsense.blockfish.net config 22614 - [meta sequenceId="7"] #0 /usr/local/opnsense/mvc/app/models/OPNsense/Base/BaseModel.php(706): OPNsense\Base\BaseModel->serializeToConfig()
<147>1 2022-10-05T14:06:33+02:00 opnsense.blockfish.net config 22614 - [meta sequenceId="8"] #1 /usr/local/opnsense/mvc/script/run_migrations.php(54): OPNsense\Base\BaseModel->runMigrations()
<147>1 2022-10-05T14:06:33+02:00 opnsense.blockfish.net config 22614 - [meta sequenceId="9"] #2 {main} )
<13>1 2022-10-05T14:06:34+02:00 opnsense.blockfish.net opnsense 21511 - [meta sequenceId="10"] (system local trust) skip intermediate certificate /CN=Fake LE Intermediate X1 from Fake LE Intermediate X1 (Let's Encrypt)
<13>1 2022-10-05T14:06:34+02:00 opnsense.blockfish.net opnsense 21511 - [meta sequenceId="11"] (system local trust) skip intermediate certificate /C=US/O=Let's Encrypt/CN=R3 from R3 (ACME Client)
<13>1 2022-10-05T14:06:34+02:00 opnsense.blockfish.net opnsense 21511 - [meta sequenceId="12"] (system local trust) skip intermediate certificate /C=US/O=Internet Security Research Group/CN=ISRG Root X1 from R3 (ACME Client)
<11>1 2022-10-05T14:06:34+02:00 opnsense.blockfish.net opnsense 21511 - [meta sequenceId="13"] /usr/local/etc/rc.configure_firmware: warning: ignoring missing default tunable request: debug.pfftpproxy
<45>1 2022-10-05T14:06:34+02:00 opnsense.blockfish.net syslog-ng 10458 - [meta sequenceId="1"] Configuration reload request received, reloading configuration;
<45>1 2022-10-05T14:06:34+02:00 opnsense.blockfish.net syslog-ng 10458 - [meta sequenceId="2"] Configuration reload finished;
<45>1 2022-10-05T14:07:03+02:00 opnsense.blockfish.net syslog-ng 10458 - [meta sequenceId="3"] syslog-ng shutting down; version='3.38.1'
<45>1 2022-10-05T14:07:59+02:00 opnsense.blockfish.net syslog-ng 11744 - [meta sequenceId="1"] syslog-ng starting up; version='3.38.1'
<13>1 2022-10-05T14:08:31+02:00 opnsense.blockfish.net dhcp6c 32461 - [meta sequenceId="2"] RTSOLD script - Starting dhcp6 client
<11>1 2022-10-05T14:08:31+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="3"] /usr/local/etc/rc.bootup: Device ovpns1 is not assigned, configuring late
<11>1 2022-10-05T14:08:31+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="4"] /usr/local/etc/rc.bootup: Device ovpnc2 is not assigned, configuring late
<13>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="5"] plugins_configure early (1)
<13>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="6"] plugins_configure early (execute task : openssh_configure_do(1))
<13>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="7"] plugins_configure early (execute task : unbound_cache_flush(1))
<13>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="8"] plugins_configure early (execute task : webgui_configure_do(1))
<11>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="9"] /usr/local/etc/rc.bootup: ROUTING: entering configure using defaults
<11>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="10"] /usr/local/etc/rc.bootup: ROUTING: IPv4 default gateway set to wan
<11>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="11"] /usr/local/etc/rc.bootup: ROUTING: setting IPv4 default route to xxx.xxx.xxx.xxx
<11>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="12"] /usr/local/etc/rc.bootup: ROUTING: creating /tmp/xn1_defaultgw using xxx.xxx.xxx.xxx
<11>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="13"] /usr/local/etc/rc.bootup: ROUTING: IPv6 default gateway set to wan
<11>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="14"] /usr/local/etc/rc.bootup: ROUTING: skipping IPv6 default route
<13>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="15"] plugins_configure dhcp (1)
<13>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="16"] plugins_configure dhcp (execute task : dhcpd_dhcp_configure(1))
<13>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="17"] plugins_configure dhcrelay (1)
<13>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="18"] plugins_configure dhcrelay (execute task : dhcpd_dhcrelay_configure(1))
<13>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="19"] plugins_configure dns (1)
<13>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="20"] plugins_configure dns (execute task : dnsmasq_configure_do(1))
<13>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="21"] plugins_configure dns (execute task : unbound_configure_do(1))
<11>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="22"] /usr/local/etc/rc.bootup: warning: ignoring missing default tunable request: debug.pfftpproxy
<27>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net dhcp6c 32679 - [meta sequenceId="23"] transmit failed: Can't assign requested address
<13>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="24"] plugins_configure monitor (1,,1)
<13>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="25"] plugins_configure monitor (execute task : dpinger_configure_do(1,,1))
<11>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="26"] /usr/local/etc/rc.bootup: Removing static route for monitor xxx.xxx.xxx.xxx via xxx.xxx.xxx.xxx
<11>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="27"] /usr/local/etc/rc.bootup: The DMZINTERNAL_SLAAC monitor address is empty, skipping.
<13>1 2022-10-05T14:08:33+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="28"] plugins_configure vpn (1)
<13>1 2022-10-05T14:08:33+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="29"] plugins_configure vpn (execute task : ipsec_configure_do(1))
<13>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="30"] plugins_configure vpn (execute task : openvpn_configure_do(1))
<11>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="31"] /usr/local/etc/rc.bootup: Resyncing OpenVPN instances.
<11>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="32"] /usr/local/etc/rc.bootup: OpenVPN server 1 instance started on PID 10902.
<13>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="33"] plugins_configure bootup (1)
<13>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="34"] plugins_configure bootup (execute task : igmpproxy_configure_do(1))
<13>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="35"] plugins_configure bootup (execute task : ntpd_configure_do(1))
<13>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="36"] plugins_configure bootup (execute task : opendns_configure_do(1))
<11>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net opnsense 14995 - [meta sequenceId="37"] /usr/local/etc/rc.newwanip: IP renewal deferred during boot on 'ovpns1'
<13>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="38"] opendns response: good 92.66.136.145
<13>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="39"] plugins_configure bootup (execute task : unbound_configure_do(1))
<11>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="40"] /usr/local/etc/rc.bootup: warning: ignoring missing default tunable request: debug.pfftpproxy
<11>1 2022-10-05T14:08:36+02:00 opnsense.blockfish.net opnsense 57032 - [meta sequenceId="41"] /usr/local/etc/rc.newwanip: IPv4 renewal is starting on 'ovpns1'
<11>1 2022-10-05T14:08:36+02:00 opnsense.blockfish.net opnsense 57032 - [meta sequenceId="42"] /usr/local/etc/rc.newwanip: Interface '' (ovpns1) is disabled or empty, nothing to do.
<11>1 2022-10-05T14:08:36+02:00 opnsense.blockfish.net opnsense 58172 - [meta sequenceId="43"] /usr/local/etc/rc.routing_configure: ROUTING: entering configure using defaults
<11>1 2022-10-05T14:08:36+02:00 opnsense.blockfish.net opnsense 58172 - [meta sequenceId="44"] /usr/local/etc/rc.routing_configure: ROUTING: IPv4 default gateway set to wan
<11>1 2022-10-05T14:08:36+02:00 opnsense.blockfish.net opnsense 58172 - [meta sequenceId="45"] /usr/local/etc/rc.routing_configure: ROUTING: setting IPv4 default route to 10.70.0.254
<11>1 2022-10-05T14:08:36+02:00 opnsense.blockfish.net opnsense 58172 - [meta sequenceId="46"] /usr/local/etc/rc.routing_configure: ROUTING: keeping current default gateway '10.70.0.254'
<11>1 2022-10-05T14:08:36+02:00 opnsense.blockfish.net opnsense 58172 - [meta sequenceId="47"] /usr/local/etc/rc.routing_configure: ROUTING: IPv6 default gateway set to wan
<11>1 2022-10-05T14:08:36+02:00 opnsense.blockfish.net opnsense 58172 - [meta sequenceId="48"] /usr/local/etc/rc.routing_configure: ROUTING: skipping IPv6 default route
<13>1 2022-10-05T14:08:36+02:00 opnsense.blockfish.net opnsense 58172 - [meta sequenceId="49"] plugins_configure monitor (1,)
<13>1 2022-10-05T14:08:36+02:00 opnsense.blockfish.net opnsense 58172 - [meta sequenceId="50"] plugins_configure monitor (execute task : dpinger_configure_do(1,))
<11>1 2022-10-05T14:08:36+02:00 opnsense.blockfish.net opnsense 58172 - [meta sequenceId="51"] /usr/local/etc/rc.routing_configure: Removing static route for monitor 212.121.121.207 via 10.70.0.254
<11>1 2022-10-05T14:08:36+02:00 opnsense.blockfish.net opnsense 58172 - [meta sequenceId="52"] /usr/local/etc/rc.routing_configure: The DMZINTERNAL_SLAAC monitor address is empty, skipping.
<28>1 2022-10-05T14:08:37+02:00 opnsense.blockfish.net lldpd 61160 - [meta sequenceId="53"] unable to create /var/empty/etc directory: Operation not permitted
<28>1 2022-10-05T14:08:37+02:00 opnsense.blockfish.net radiusd 68970 - [meta sequenceId="54"] Ignoring "sql" (see raddb/mods-available/README.rst)
<28>1 2022-10-05T14:08:37+02:00 opnsense.blockfish.net radiusd 68970 - [meta sequenceId="55"] Ignoring "ldap" (see raddb/mods-available/README.rst)
<43>1 2022-10-05T14:10:47+02:00 opnsense.blockfish.net syslog-ng 11744 - [meta sequenceId="56"] Error resolving hostname with getaddrinfo(); host='host.blockfish.net', error='8', error_str='Name does not resolve'
<43>1 2022-10-05T14:10:47+02:00 opnsense.blockfish.net syslog-ng 11744 - [meta sequenceId="57"] Initiating connection failed, reconnecting; time_reopen='60'
<43>1 2022-10-05T14:13:02+02:00 opnsense.blockfish.net syslog-ng 11744 - [meta sequenceId="1"] Error resolving hostname with getaddrinfo(); host='host.blockfish.net', error='8', error_str='Name does not resolve'
<43>1 2022-10-05T14:13:02+02:00 opnsense.blockfish.net syslog-ng 11744 - [meta sequenceId="2"] Initiating connection failed, reconnecting; time_reopen='60'
<85>1 2022-10-05T14:13:27+02:00 opnsense.blockfish.net sudo 65854 - [meta sequenceId="3"] admin.bill : TTY=pts/0 ; PWD=/home/admin.bill ; USER=root ; COMMAND=/usr/bin/su -
<43>1 2022-10-05T14:14:02+02:00 opnsense.blockfish.net syslog-ng 11744 - [meta sequenceId="4"] Error resolving hostname with getaddrinfo(); host='host.blockfish.net', error='8', error_str='Name does not resolve'
<43>1 2022-10-05T14:14:02+02:00 opnsense.blockfish.net syslog-ng 11744 - [meta sequenceId="5"] Initiating connection failed, reconnecting; time_reopen='60'
<43>1 2022-10-05T14:17:43+02:00 opnsense.blockfish.net syslog-ng 11744 - [meta sequenceId="1"] Error resolving hostname with getaddrinfo(); host='host.blockfish.net', error='8', error_str='Name does not resolve'
<43>1 2022-10-05T14:17:43+02:00 opnsense.blockfish.net syslog-ng 11744 - [meta sequenceId="2"] Initiating connection failed, reconnecting; time_reopen='60'
<13>1 2022-10-05T14:18:28+02:00 opnsense.blockfish.net root 56500 - [meta sequenceId="3"] /usr/local/etc/rc.d/haproxy: WARNING: failed precmd routine for haproxy
<43>1 2022-10-05T14:18:29+02:00 opnsense.blockfish.net syslog-ng 11744 - [meta sequenceId="1"] Error resolving hostname with getaddrinfo(); host='host.blockfish.net', error='8', error_str='Name does not resolve'
<43>1 2022-10-05T14:18:29+02:00 opnsense.blockfish.net syslog-ng 11744 - [meta sequenceId="2"] Initiating connection failed, reconnecting; time_reopen='60'
<45>1 2022-10-05T14:18:29+02:00 opnsense.blockfish.net syslog-ng 11744 - [meta sequenceId="3"] Configuration reload request received, reloading configuration;
<45>1 2022-10-05T14:18:29+02:00 opnsense.blockfish.net syslog-ng 11744 - [meta sequenceId="4"] Configuration reload finished;
<43>1 2022-10-05T14:21:03+02:00 opnsense.blockfish.net syslog-ng 11744 - [meta sequenceId="5"] Error resolving hostname with getaddrinfo(); host='host.blockfish.net', error='8', error_str='Name does not resolve'
<43>1 2022-10-05T14:21:03+02:00 opnsense.blockfish.net syslog-ng 11744 - [meta sequenceId="6"] Initiating connection failed, reconnecting; time_reopen='60'
<43>1 2022-10-05T14:22:24+02:00 opnsense.blockfish.net syslog-ng 11744 - [meta sequenceId="1"] Error resolving hostname with getaddrinfo(); host='host.blockfish.net', error='8', error_str='Name does not resolve'
<43>1 2022-10-05T14:22:24+02:00 opnsense.blockfish.net syslog-ng 11744 - [meta sequenceId="2"] Initiating connection failed, reconnecting; time_reopen='60'
<43>1 2022-10-05T14:23:24+02:00 opnsense.blockfish.net syslog-ng 11744 - [meta sequenceId="1"] Error resolving hostname with getaddrinfo(); host='host.blockfish.net', error='8', error_str='Name does not resolve'
<43>1 2022-10-05T14:23:24+02:00 opnsense.blockfish.net syslog-ng 11744 - [meta sequenceId="2"] Initiating connection failed, reconnecting; time_reopen='60'
<43>1 2022-10-05T14:25:04+02:00 opnsense.blockfish.net syslog-ng 11744 - [meta sequenceId="1"] Error resolving hostname with getaddrinfo(); host='host.blockfish.net', error='8', error_str='Name does not resolve'
<43>1 2022-10-05T14:25:04+02:00 opnsense.blockfish.net syslog-ng 11744 - [meta sequenceId="2"] Initiating connection failed, reconnecting; time_reopen='60'
<43>1 2022-10-05T14:26:25+02:00 opnsense.blockfish.net syslog-ng 11744 - [meta sequenceId="1"] Error resolving hostname with getaddrinfo(); host='host.blockfish.net', error='8', error_str='Name does not resolve'
<43>1 2022-10-05T14:26:25+02:00 opnsense.blockfish.net syslog-ng 11744 - [meta sequenceId="2"] Initiating connection failed, reconnecting; time_reopen='60'
<43>1 2022-10-05T14:27:25+02:00 opnsense.blockfish.net syslog-ng 11744 - [meta sequenceId="1"] Error resolving hostname with getaddrinfo(); host='host.blockfish.net', error='8', error_str='Name does not resolve'
<43>1 2022-10-05T14:27:25+02:00 opnsense.blockfish.net syslog-ng 11744 - [meta sequenceId="2"] Initiating connection failed, reconnecting; time_reopen='60'
<43>1 2022-10-05T14:29:05+02:00 opnsense.blockfish.net syslog-ng 11744 - [meta sequenceId="1"] Error resolving hostname with getaddrinfo(); host='host.blockfish.net', error='8', error_str='Name does not resolve'
<43>1 2022-10-05T14:29:05+02:00 opnsense.blockfish.net syslog-ng 11744 - [meta sequenceId="2"] Initiating connection failed, reconnecting; time_reopen='60'
<43>1 2022-10-05T14:30:25+02:00 opnsense.blockfish.net syslog-ng 11744 - [meta sequenceId="1"] Error resolving hostname with getaddrinfo(); host='host.blockfish.net', error='8', error_str='Name does not resolve'
<43>1 2022-10-05T14:30:25+02:00 opnsense.blockfish.net syslog-ng 11744 - [meta sequenceId="2"] Initiating connection failed, reconnecting; time_reopen='60'
<43>1 2022-10-05T14:31:45+02:00 opnsense.blockfish.net syslog-ng 11744 - [meta sequenceId="1"] Error resolving hostname with getaddrinfo(); host='host.blockfish.net', error='8', error_str='Name does not resolve'
<43>1 2022-10-05T14:31:45+02:00 opnsense.blockfish.net syslog-ng 11744 - [meta sequenceId="2"] Initiating connection failed, reconnecting; time_reopen='60'
root@opnsense:/var/log/system # 

Investigating how to clean up unbound config files from the cli.

[billgertz]

@swhite2 Seem to have corrupted /var/unbound/host_entries.conf. It seems that the problem is not a problem with hosts that alphabetize higher than host16, rather only three aliases show. Tried stopping unbound, editing the file by hand to eliminate the bozo and duplicate entries for host16, and restarting. The host_entries.conf is regenerated and my edits are overwritten. What am I missing? Is there a shadow config file somewhere? By the way, host16 is supposed to be an alias but it does not show in the GUI Aliases list.

[swhite2]

@billgertz Does the GUI show all host overrides + relevant aliases? Is anything missing?

There is no use in editing the configuration files for Unbound by hand, the templating system generates these fresh with every single reconfigure of Unbound, as such manual changes are not persisted.

I think a useful test to determine why Unbound is failing to start is manually executing /usr/local/opnsense/scripts/unbound/start.sh and sharing the output.

[billgertz]

My GUI shows all of the host overrides but only three of the aliases. Found the config.xml file and can see the child nodes in aliases are all missing in the GUI except for the first three. I have verified all of the hosts child node host entries are listed in the GUI.

Tried a bit of troubleshooting based on a theory of corrupted alias records: I dropped all of the alias child nodes out of aliases. That is the file looked like this:

          .
          .
          .
          <domain>blockfish.net</domain>
          <rr>A</rr>
          <mxprio/>
          <mx/>
          <server>xxx.xxx.xxx.217</server>
          <description>Local Server</description>
        </host>
      </hosts>
      <aliases>
      </aliases>
      <domains/>
      <miscellaneous>
        <privatedomain/>
        <insecuredomain/>
      </miscellaneous>
    </unboundplus>
    .
    .
    .

Then rebooted the server. Found that dropping all of the aliases didn't fix the problem with unbound halting at startup.

I had a problem when adding the alias entries back with GUI. I have two domains: blockfish.net and blockfish.info. I had set an alias for mail in both domains (mail.blockfish.net and mail.blockfish.info) both pointing to different A records (.blockfish.net and .blockfish.info). Yet only the mail.blockfish.net (the first entry made and the first child node in aliases) is shown in the GUI.

With the original configuration - before dropping all the alias child nodes - the three aliases pointing to .blockfish.net are the only ones that show, everything else is missing from the GUI - about 33 other aliases. By the way, all of these aliases work just fine as I can ping successfully using any alias.

I've gone back to the original config.xml for rest of the diagnostics.

@swhite2: Here is the start.sh output as you requested using the original configuration:

root@opnsense:~ # /usr/local/opnsense/scripts/unbound/start.sh 
unbound-checkconf: no errors in /var/unbound/unbound.conf
cp: /usr/local/etc/unbound.opnsense.d/dnsbl.conf: No such file or directory
ok
root@opnsense:~ #

[swhite2]

@billgertz Given the fact that they are present in config.xml and you have connectivity, my only remaining conclusion is that you're not aware of the master-detail view in the GUI. Click on any host override and you'll see it's corresponding aliases change.

The output of start.sh shows that unbound is starting normally. If we're still certain it's killed after a reconfigure, try directly starting it and see what unbound reports: unbound -ddv -c /var/unbound/unbound.conf.

[billgertz]

@swhite2 Ah - that was the piece I was missing on the GUI mechanics. Thanks for clearing that up. It works as you describe!

Cleaned up the radius aliases successfully and confirmed that unbound restarted after applying the change.

Unbound restarts just fine after reconfiguring (hitting the apply button in the GUI). It's only after a reboot that it halts after starting. I've noticed it loads the /var/unbound/host_entries.conf file twice after a reboot (see the previous log posted here). Ater the second reload unbound is halted.

Here are the results of the starting unbound in verbose debug mode, btw the process stopped on its own after being up for a second or two:

root@opnsense:~ # unbound -ddv -c /var/unbound/unbound.conf
[1665062541] unbound[34265:0] notice: Start of unbound 1.16.3.
[1665062541] unbound[34265:0] notice: init module 0: validator
[1665062541] unbound[34265:0] notice: init module 1: iterator
[1665062541] unbound[34265:0] info: start of service (unbound 1.16.3).
[1665062542] unbound[34265:1] info: resolving gateway.discord.gg. A IN
[1665062542] unbound[34265:1] info: response for gateway.discord.gg. A IN
[1665062542] unbound[34265:1] info: reply from <.> 208.67.220.220#53
[1665062542] unbound[34265:1] info: query response was ANSWER
[1665062542] unbound[34265:1] info: prime trust anchor
[1665062542] unbound[34265:1] info: generate keytag query _ta-4f66. NULL IN
[1665062542] unbound[34265:1] info: resolving . DNSKEY IN
[1665062542] unbound[34265:1] info: resolving _ta-4f66. NULL IN
[1665062542] unbound[34265:1] info: response for _ta-4f66. NULL IN
[1665062542] unbound[34265:1] info: reply from <.> 208.67.222.222#53
[1665062542] unbound[34265:1] info: query response was NXDOMAIN ANSWER
[1665062542] unbound[34265:1] info: response for . DNSKEY IN
[1665062542] unbound[34265:1] info: reply from <.> 208.67.220.220#53
[1665062542] unbound[34265:1] info: query response was ANSWER
[1665062542] unbound[34265:1] info: validate keys with anchor(DS): sec_status_secure
[1665062542] unbound[34265:1] info: Successfully primed trust anchor . DNSKEY IN
[1665062542] unbound[34265:1] info: resolving gg. DS IN
[1665062542] unbound[34265:1] info: response for gg. DS IN
[1665062542] unbound[34265:1] info: reply from <.> 208.67.222.222#53
[1665062542] unbound[34265:1] info: query response was ANSWER
[1665062542] unbound[34265:1] info: validated DS gg. DS IN
[1665062542] unbound[34265:1] info: resolving gg. DNSKEY IN
[1665062542] unbound[34265:1] info: response for gg. DNSKEY IN
[1665062542] unbound[34265:1] info: reply from <.> 208.67.220.220#53
[1665062542] unbound[34265:1] info: query response was ANSWER
[1665062542] unbound[34265:1] info: validated DNSKEY gg. DNSKEY IN
[1665062542] unbound[34265:1] info: resolving discord.gg. DS IN
[1665062542] unbound[34265:1] info: response for discord.gg. DS IN
[1665062542] unbound[34265:1] info: reply from <.> 208.67.222.222#53
[1665062542] unbound[34265:1] info: query response was nodata ANSWER
[1665062542] unbound[34265:1] info: NSEC3s for the referral proved no DS.
[1665062542] unbound[34265:1] info: Verified that unsigned response is INSECURE
[1665062542] unbound[34265:1] info: resolving gateway.instagram.com. A IN
[1665062542] unbound[34265:2] info: resolving gateway.instagram.com.blockfish.net. A IN
[1665062542] unbound[34265:1] info: response for gateway.instagram.com. A IN
[1665062542] unbound[34265:1] info: reply from <.> 208.67.220.220#53
[1665062542] unbound[34265:1] info: query response was CNAME
[1665062542] unbound[34265:1] info: resolving gateway.instagram.com. A IN
[1665062542] unbound[34265:1] info: response for gateway.instagram.com. A IN
[1665062542] unbound[34265:1] info: reply from <.> 208.67.220.220#53
[1665062542] unbound[34265:1] info: query response was ANSWER
[1665062542] unbound[34265:1] info: resolving com. DS IN
[1665062542] unbound[34265:1] info: response for com. DS IN
[1665062542] unbound[34265:1] info: reply from <.> 208.67.220.220#53
[1665062542] unbound[34265:1] info: query response was ANSWER
[1665062542] unbound[34265:1] info: validated DS com. DS IN
[1665062542] unbound[34265:1] info: resolving com. DNSKEY IN
[1665062542] unbound[34265:1] info: response for com. DNSKEY IN
[1665062542] unbound[34265:1] info: reply from <.> 208.67.220.220#53
[1665062542] unbound[34265:1] info: query response was ANSWER
[1665062542] unbound[34265:1] info: validated DNSKEY com. DNSKEY IN
[1665062542] unbound[34265:1] info: resolving instagram.com. DS IN
[1665062542] unbound[34265:1] info: response for instagram.com. DS IN
[1665062542] unbound[34265:1] info: reply from <.> 208.67.222.222#53
[1665062542] unbound[34265:1] info: query response was nodata ANSWER
[1665062542] unbound[34265:1] info: NSEC3s for the referral proved no DS.
[1665062542] unbound[34265:1] info: Verified that unsigned response is INSECURE
.
.
.
Many, many, more DNS queries
.
.
.
[1665062543] unbound[34265:0] info: control cmd:  dump_cache
[1665062544] unbound[34265:0] info: service stopped (unbound 1.16.3).
[1665062544] unbound[34265:0] info: server stats for thread 0: 2 queries, 0 answers from cache, 2 recursions, 0 prefetch, 0 rejected by ip ratelimiting
[1665062544] unbound[34265:0] info: server stats for thread 0: requestlist max 1 avg 0.5 exceeded 0 jostled 0
[1665062544] unbound[34265:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 2 recursion replies sent, 0 replies dropped, 0 states jostled out
[1665062544] unbound[34265:0] info: average recursion processing time 0.049030 sec
[1665062544] unbound[34265:0] info: histogram of recursion processing times
[1665062544] unbound[34265:0] info: [25%]=0 median[50%]=0 [75%]=0
[1665062544] unbound[34265:0] info: lower(secs) upper(secs) recursions
[1665062544] unbound[34265:0] info:    0.016384    0.032768 1
[1665062544] unbound[34265:0] info:    0.065536    0.131072 1
[1665062544] unbound[34265:0] info: server stats for thread 1: 15 queries, 5 answers from cache, 10 recursions, 0 prefetch, 0 rejected by ip ratelimiting
[1665062544] unbound[34265:0] info: server stats for thread 1: requestlist max 6 avg 2.2 exceeded 0 jostled 0
[1665062544] unbound[34265:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 10 recursion replies sent, 0 replies dropped, 0 states jostled out
[1665062544] unbound[34265:0] info: average recursion processing time 0.057754 sec
[1665062544] unbound[34265:0] info: histogram of recursion processing times
[1665062544] unbound[34265:0] info: [25%]=0.0106496 median[50%]=0.0147456 [75%]=0.049152
[1665062544] unbound[34265:0] info: lower(secs) upper(secs) recursions
[1665062544] unbound[34265:0] info:    0.004096    0.008192 1
[1665062544] unbound[34265:0] info:    0.008192    0.016384 5
[1665062544] unbound[34265:0] info:    0.032768    0.065536 3
[1665062544] unbound[34265:0] info:    0.262144    0.524288 1
[1665062544] unbound[34265:0] info: server stats for thread 2: 12 queries, 4 answers from cache, 8 recursions, 0 prefetch, 0 rejected by ip ratelimiting
[1665062544] unbound[34265:0] info: server stats for thread 2: requestlist max 6 avg 2.75 exceeded 0 jostled 0
[1665062544] unbound[34265:0] info: mesh has 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 7 recursion replies sent, 0 replies dropped, 0 states jostled out
[1665062544] unbound[34265:0] info: average recursion processing time 0.028463 sec
[1665062544] unbound[34265:0] info: histogram of recursion processing times
[1665062544] unbound[34265:0] info: [25%]=0.014336 median[50%]=0.024576 [75%]=0.04096
[1665062544] unbound[34265:0] info: lower(secs) upper(secs) recursions
[1665062544] unbound[34265:0] info:    0.004096    0.008192 1
[1665062544] unbound[34265:0] info:    0.008192    0.016384 1
[1665062544] unbound[34265:0] info:    0.016384    0.032768 3
[1665062544] unbound[34265:0] info:    0.032768    0.065536 1
[1665062544] unbound[34265:0] info:    0.065536    0.131072 1
[1665062544] unbound[34265:0] info: server stats for thread 3: 8 queries, 0 answers from cache, 8 recursions, 0 prefetch, 0 rejected by ip ratelimiting
[1665062544] unbound[34265:0] info: server stats for thread 3: requestlist max 5 avg 1.5 exceeded 0 jostled 0
[1665062544] unbound[34265:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 8 recursion replies sent, 0 replies dropped, 0 states jostled out
[1665062544] unbound[34265:0] info: average recursion processing time 0.039993 sec
[1665062544] unbound[34265:0] info: histogram of recursion processing times
[1665062544] unbound[34265:0] info: [25%]=0.0218453 median[50%]=0.032768 [75%]=0.065536
[1665062544] unbound[34265:0] info: lower(secs) upper(secs) recursions
[1665062544] unbound[34265:0] info:    0.008192    0.016384 1
[1665062544] unbound[34265:0] info:    0.016384    0.032768 3
[1665062544] unbound[34265:0] info:    0.032768    0.065536 2
[1665062544] unbound[34265:0] info:    0.065536    0.131072 2

[billgertz]

@swhite2 It looks like the unbound first load of /var/unbound/host_entries.conf logged in the resolver log @2022-10-05T14:08:32: <164>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net unbound 554 - [meta sequenceId="1"] PTR record already exists for host1.blockfish.info(<subnet_a>.25)

Corresponds to the first call unbound_configure_do in the system log: <13>1 2022-10-05T14:08:32+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="21"] plugins_configure dns (execute task : unbound_configure_do(1))

The halt noted in the resolver log @2022-10-05T14:08:35: <30>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net unbound 90919 - [meta sequenceId="83"] [90919:0] info: service stopped (unbound 1.16.3).

Corresponds with the second unbound_configure_do call logged in system log: <13>1 2022-10-05T14:08:35+02:00 opnsense.blockfish.net php 554 - [meta sequenceId="39"] plugins_configure bootup (execute task : unbound_configure_do(1))

Why the double call (at plugins_configure dns and then again at plugins_cofigure bootup)? Is there a lead here somewhere or am I grasping at straws?

[billgertz]

@swhite Ok after tracing through the um, mindblowing, includes and indirection in the PHP code called by /usr/local/etc/rc.bootup I found a hack that eliminates the problem. I committed out the line that adds the first unbound_configure_do call:

plugins_configure('dhcp', true);
plugins_configure('dhcrelay', true);
/*
   plugins_configure('dns', true);
*/

plugins_configure('monitor', true, [null, true]);
filter_configure_sync(true);
plugins_configure('vpn', true);
plugins_configure('bootup', true);
rrd_configure(true, true);

Removed my hack to /usr/local/etc/rc.syshook.d/start directory:

root@opnsense:/usr/local/etc/rc.syshook.d/start # ls
10-newwanip	20-freebsd	25-syslog	50-dnsrestarter	50-frr		50-haproxy	50-xen		90-carp		90-cron		95-beep
root@opnsense:/usr/local/etc/rc.syshook.d/start # mv 50-dnsrestarter ~/
root@opnsense:/usr/local/etc/rc.syshook.d/start # ls
10-newwanip	20-freebsd	25-syslog	50-frr		50-haproxy	50-xen		90-carp		90-cron		95-beep
root@opnsense:/usr/local/etc/rc.syshook.d/start # 

And then rebooted.

Surprise, surprise unbound is running after boot:

root@opnsense:~ # ps -fax| grep unbound
 3659  -  Ss    0:00.75 /usr/local/bin/python3 /usr/local/opnsense/scripts/dhcp/unbound_watcher.py --domain blockfish.net (python3.9)
62830  -  Ss    0:00.23 /usr/local/sbin/unbound -c /var/unbound/unbound.conf
64743  0  S+    0:00.00 grep unbound
root@opnsense:~ # 

Fairly certain that a second call to unbound_configure_do is causing it to die. Can not tell you why but it does.

Any ideas why this would be?

I know I'm monkeying around with guts of opnsense bootup and don't know enough to suggest a fix as of yet.

[martin-huber]

We have the same problem: when rebooting the OpnSense machine, unbound is not running afterwards. We can see in the unbound logs (DEBUG level), that it is started, and stopped 1 second later again. We can see in syslog, that the "bootup" tries to start it, and then the "dns" tries to start it again.

We noticed a change in the implementation of unbound_configure_do in February, that puts the startup.sh of unbound into the background. We could imagine, that this is the reason for the observed behavior:

1. 'bootup' starts unbound, locks the execution of startup.sh
2. since this is done in the background, 'dns' get's the chance to restart it again
3. unbound_configure_do finds already a .pid file and kills the unbound process that currently is starting up
4. the 2nd "thread" cannot start another instance, since flock still might hold the lock

Could this be a plausible explanation ?

[billgertz]

@martin-huber @swhite Great to hear it's not just me. Too bad I wasted time chasing a corrupted unbound config file "rabbit."

It seems like a likely scenario with one minor observation in my case: the plugins_configure('dns', true); call is first followed by plugins_configure('bootup', true); (see log from previous post and code segment) but the logic still holds.

I'll look into it from my system and see if I can verify what is going on.

[fichtner]

This is sort of strange it would be hooked into bootup, trying to fix a race back when complexity with block lists wasn't available for sure... 35478a8f940

[martin-huber]

I don't exactly understand your last comment @fichtner ...

Maybe another addition / observation: we also tried the "comment" - workaround:

/*
   plugins_configure('dns', true);
*/

but it did not help for us.

This all might be related to the time, unbound takes to startup ? We have quite many overwrites ... Could it be, that the 3rd hook - the "local" startup, where unbound_configure_do would be executed again, then comes into the picture ?

[billgertz]

@martin-huber @swhite Oh wow - starting unbound with a start script that kills the process if it's already running. So a long startup time would make a mess, with the flock on the start script. BTW the only reference I can find for the the third hook is: rc.reload_all: plugins_configure('local', true); I guess this would be called when you ask OPNSense to reload from GUI somewhere? All I can find is Power Off or Reboot.

Digging through the logs there is unhappy consequence of disabling plugins_configure dns. It also disables the dnsmasq_configure_do. Compare the prepatch system log:

<13>1 2022-10-06T15:18:49+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="19"] plugins_configure dns (1)
<13>1 2022-10-06T15:18:49+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="20"] plugins_configure dns (execute task : dnsmasq_configure_do(1))
<13>1 2022-10-06T15:18:49+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="21"] plugins_configure dns (execute task : unbound_configure_do(1))
<11>1 2022-10-06T15:18:50+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="22"] /usr/local/etc/rc.bootup: warning: ignoring missing default tunable request: debug.pfftpproxy
<27>1 2022-10-06T15:18:50+02:00 opnsense.blockfish.net dhcp6c 48308 - [meta sequenceId="23"] transmit failed: Can't assign requested address
<13>1 2022-10-06T15:18:50+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="24"] plugins_configure monitor (1,,1)
<13>1 2022-10-06T15:18:50+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="25"] plugins_configure monitor (execute task : dpinger_configure_do(1,,1))
<11>1 2022-10-06T15:18:50+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="26"] /usr/local/etc/rc.bootup: Removing static route for monitor 212.121.121.207 via 10.70.0.254
<11>1 2022-10-06T15:18:50+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="27"] /usr/local/etc/rc.bootup: The DMZINTERNAL_SLAAC monitor address is empty, skipping.
<13>1 2022-10-06T15:18:50+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="28"] plugins_configure vpn (1)
<13>1 2022-10-06T15:18:50+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="29"] plugins_configure vpn (execute task : ipsec_configure_do(1))
<13>1 2022-10-06T15:18:52+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="30"] plugins_configure vpn (execute task : openvpn_configure_do(1))
<11>1 2022-10-06T15:18:52+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="31"] /usr/local/etc/rc.bootup: Resyncing OpenVPN instances.
<11>1 2022-10-06T15:18:52+02:00 opnsense.blockfish.net opnsense 56518 - [meta sequenceId="32"] /usr/local/etc/rc.newwanip: IP renewal deferred during boot on 'ovpns1'
<11>1 2022-10-06T15:18:52+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="33"] /usr/local/etc/rc.bootup: OpenVPN server 1 instance started on PID 54153.
<13>1 2022-10-06T15:18:52+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="34"] plugins_configure bootup (1)
<13>1 2022-10-06T15:18:52+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="35"] plugins_configure bootup (execute task : igmpproxy_configure_do(1))
<13>1 2022-10-06T15:18:52+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="36"] plugins_configure bootup (execute task : ntpd_configure_do(1))
<13>1 2022-10-06T15:18:52+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="37"] plugins_configure bootup (execute task : opendns_configure_do(1))
<13>1 2022-10-06T15:18:53+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="38"] opendns response: good 92.66.136.145
<13>1 2022-10-06T15:18:53+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="39"] plugins_configure bootup (execute task : unbound_configure_do(1))
<11>1 2022-10-06T15:18:53+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="40"] /usr/local/etc/rc.bootup: warning: ignoring missing default tunable request: debug.pfftpproxy

with the post-patch log at startup:

<13>1 2022-10-06T18:07:19+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="15"] plugins_configure dhcp (1)
<13>1 2022-10-06T18:07:19+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="16"] plugins_configure dhcp (execute task : dhcpd_dhcp_configure(1))
<13>1 2022-10-06T18:07:19+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="17"] plugins_configure dhcrelay (1)
<13>1 2022-10-06T18:07:19+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="18"] plugins_configure dhcrelay (execute task : dhcpd_dhcrelay_configure(1))
<13>1 2022-10-06T18:07:19+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="19"] plugins_configure monitor (1,,1)
<13>1 2022-10-06T18:07:19+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="20"] plugins_configure monitor (execute task : dpinger_configure_do(1,,1))
<11>1 2022-10-06T18:07:19+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="21"] /usr/local/etc/rc.bootup: Removing static route for monitor 212.121.121.207 via 10.70.0.254
<11>1 2022-10-06T18:07:19+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="22"] /usr/local/etc/rc.bootup: The DMZINTERNAL_SLAAC monitor address is empty, skipping.
<27>1 2022-10-06T18:07:19+02:00 opnsense.blockfish.net dhcp6c 51773 - [meta sequenceId="23"] transmit failed: Can't assign requested address
<13>1 2022-10-06T18:07:19+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="24"] plugins_configure vpn (1)
<13>1 2022-10-06T18:07:19+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="25"] plugins_configure vpn (execute task : ipsec_configure_do(1))
<13>1 2022-10-06T18:07:21+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="26"] plugins_configure vpn (execute task : openvpn_configure_do(1))
<11>1 2022-10-06T18:07:21+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="27"] /usr/local/etc/rc.bootup: Resyncing OpenVPN instances.
<11>1 2022-10-06T18:07:21+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="28"] /usr/local/etc/rc.bootup: OpenVPN server 1 instance started on PID 35806.
<13>1 2022-10-06T18:07:21+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="29"] plugins_configure bootup (1)
<13>1 2022-10-06T18:07:21+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="30"] plugins_configure bootup (execute task : igmpproxy_configure_do(1))
<13>1 2022-10-06T18:07:21+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="31"] plugins_configure bootup (execute task : ntpd_configure_do(1))
<13>1 2022-10-06T18:07:21+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="32"] plugins_configure bootup (execute task : opendns_configure_do(1))
<11>1 2022-10-06T18:07:21+02:00 opnsense.blockfish.net opnsense 41067 - [meta sequenceId="33"] /usr/local/etc/rc.newwanip: IP renewal deferred during boot on 'ovpns1'
<13>1 2022-10-06T18:07:32+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="34"] opendns response: good 92.66.136.145
<13>1 2022-10-06T18:07:32+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="35"] plugins_configure bootup (execute task : unbound_configure_do(1))
<11>1 2022-10-06T18:07:32+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="36"] /usr/local/etc/rc.bootup: warning: ignoring missing default tunable request: debug.pfftpproxy

Notice that configure_dnsmasq_do is no longer called. This will need fixing at a deeper level perhaps in /usr/local/etc/inc/plugins.inc.d/unbound.inc?

[fichtner]

I suppose that makes https://github.com/opnsense/core/blob/054a7ee8348fda7b49c3ce32150ed6ab13606d53/src/etc/inc/plugins.inc.d/unbound.inc#L364 the culprit, it should adhere to locking logic that is used around start.sh perhaps

[billgertz]

@martin-huber @swhite Went ahead and disabled the pushing the unbound_configure_do to the action? array in /usr/local/etc/inc/plugins.inc.d/unbound.inc:

function unbound_configure()
{
    return array(
/*
 * disable unbound startup with bootup
        'bootup' => array('unbound_configure_do'),
*/
        'dns' => array('unbound_configure_do'),
        'early' => array('unbound_cache_flush'),
        'hosts' => array('unbound_hosts_generate:0'),
        'local' => array('unbound_configure_do'),
        'newwanip' => array('unbound_configure_do:2'),
    );
}

Rebooted system and confirmed that configiure_dnsmasq_do is now being called:

<13>1 2022-10-07T13:03:20+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="15"] plugins_configure dhcp (1)
<13>1 2022-10-07T13:03:20+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="16"] plugins_configure dhcp (execute task : dhcpd_dhcp_configure(1))
<13>1 2022-10-07T13:03:20+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="17"] plugins_configure dhcrelay (1)
<13>1 2022-10-07T13:03:20+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="18"] plugins_configure dhcrelay (execute task : dhcpd_dhcrelay_configure(1))
<13>1 2022-10-07T13:03:20+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="19"] plugins_configure dns (1)
<13>1 2022-10-07T13:03:20+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="20"] plugins_configure dns (execute task : dnsmasq_configure_do(1))
<13>1 2022-10-07T13:03:20+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="21"] plugins_configure dns (execute task : unbound_configure_do(1))
<27>1 2022-10-07T13:03:21+02:00 opnsense.blockfish.net dhcp6c 62057 - [meta sequenceId="22"] transmit failed: Can't assign requested address
<11>1 2022-10-07T13:03:21+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="23"] /usr/local/etc/rc.bootup: warning: ignoring missing default tunable request: debug.pfftpproxy
<13>1 2022-10-07T13:03:21+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="24"] plugins_configure monitor (1,,1)
<13>1 2022-10-07T13:03:21+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="25"] plugins_configure monitor (execute task : dpinger_configure_do(1,,1))
<11>1 2022-10-07T13:03:21+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="26"] /usr/local/etc/rc.bootup: Removing static route for monitor 212.121.121.207 via 10.70.0.254
<11>1 2022-10-07T13:03:21+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="27"] /usr/local/etc/rc.bootup: The DMZINTERNAL_SLAAC monitor address is empty, skipping.
<13>1 2022-10-07T13:03:21+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="28"] plugins_configure vpn (1)
<13>1 2022-10-07T13:03:21+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="29"] plugins_configure vpn (execute task : ipsec_configure_do(1))
<13>1 2022-10-07T13:03:23+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="30"] plugins_configure vpn (execute task : openvpn_configure_do(1))
<11>1 2022-10-07T13:03:23+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="31"] /usr/local/etc/rc.bootup: Resyncing OpenVPN instances.
<11>1 2022-10-07T13:03:23+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="32"] /usr/local/etc/rc.bootup: OpenVPN server 1 instance started on PID 96567.
<13>1 2022-10-07T13:03:23+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="33"] plugins_configure bootup (1)
<13>1 2022-10-07T13:03:23+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="34"] plugins_configure bootup (execute task : igmpproxy_configure_do(1))
<13>1 2022-10-07T13:03:23+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="35"] plugins_configure bootup (execute task : ntpd_configure_do(1))
<13>1 2022-10-07T13:03:23+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="36"] plugins_configure bootup (execute task : opendns_configure_do(1))
<11>1 2022-10-07T13:03:23+02:00 opnsense.blockfish.net opnsense 2644 - [meta sequenceId="37"] /usr/local/etc/rc.newwanip: IP renewal deferred during boot on 'ovpns1'

My system booted more quickly and is working properly after boot with unbound running as it should:

root@opnsense:/var/log/system # ps -fax |grep unbound
55706  -  Ss    0:00.31 /usr/local/sbin/unbound -c /var/unbound/unbound.conf
59341  -  Ss    0:00.85 /usr/local/bin/python3 /usr/local/opnsense/scripts/dhcp/unbound_watcher.py --domain blockfish.net (python3.9)
39862  0  S+    0:00.00 grep unbound
root@opnsense:/var/log/system #

Not sure if this a kosher "fix" or a horrible "hack". Need someone who understands the intent of the double call in rc.bootup to unbound_configure_do to make tha judgement. Can someone help with this, please?

[fichtner]

It indicates that the first start is ok, but two subsequent starts during boot are not, which is very likely due to the backgrounding of start.sh and opportunistically killing unbound before starting it a second time.

The problem here though is that it seems to enter a state unbound cannot recover from which is a bit odd, more or less indicating unbound takes too long to start up in the first place to react to the SIGTERM gracefully.

[billgertz]

@fichtner @martin-huber I'm not sure the problem lies with unbound but rather with the start.sh flock. Could it be that the call in /usr/local/etc/inc/plugins.inc.d/unbound.inc to mwexecf_bg starts with a blocking (-n) lock:

    unbound_generate_config();
 
    killbypid('/var/run/unbound_dhcpd.pid', 'TERM', true);
    killbypid('/var/run/unbound.pid', 'TERM', true);
  
    if (!unbound_enabled()) {
        return;
    }
 
    if ($verbose) {
        echo 'Starting Unbound DNS...';
        flush();
    }
 
    if (isset($config['unbound']['regdhcp'])) {
        $domain = $config['system']['domain'];
        if (isset($config['unbound']['regdhcpdomain'])) {
            $domain = $config['unbound']['regdhcpdomain'];
        }
    }

    mwexecf_bg('/usr/local/bin/flock -n -E 0 -o /tmp/unbound_start.lock /usr/local/opnsense/scripts/unbound/start.sh %s', [$domain]);
 
    if ($verbose) {
        echo "done.\n";
    }

As @martin-huber suggested if the start.sh is still locked since unbound is still starting up. The flock will return an error inside mwexec_bg rather than a process to background. Unfortunately, the current unbound process was already killed. As you say the process kill bypasses a lock check of any sort.

I suggest what we are seeing in the logs reflect this - that the process is simply ended:

[1665062543] unbound[34265:0] info: control cmd:  dump_cache
[1665062544] unbound[34265:0] info: service stopped (unbound 1.16.3).
[1665062544] unbound[34265:0] info: server stats for thread 0: 2 queries, 0 answers from cache, 2 recursions, 0 prefetch, 0 rejected by ip ratelimiting
[1665062544] unbound[34265:0] info: server stats for thread 0: requestlist max 1 avg 0.5 exceeded 0 jostled 0
[1665062544] unbound[34265:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 2 recursion replies sent, 0 replies dropped, 0 states jostled out
[1665062544] unbound[34265:0] info: average recursion processing time 0.049030 sec
[1665062544] unbound[34265:0] info: histogram of recursion processing times
[1665062544] unbound[34265:0] info: [25%]=0 median[50%]=0 [75%]=0
[1665062544] unbound[34265:0] info: lower(secs) upper(secs) recursions
[1665062544] unbound[34265:0] info:    0.016384    0.032768 1
[1665062544] unbound[34265:0] info:    0.065536    0.131072 1
[1665062544] unbound[34265:0] info: server stats for thread 1: 15 queries, 5 answers from cache, 10 recursions, 0 prefetch, 0 rejected by ip ratelimiting
[1665062544] unbound[34265:0] info: server stats for thread 1: requestlist max 6 avg 2.2 exceeded 0 jostled 0
[1665062544] unbound[34265:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 10 recursion replies sent, 0 replies dropped, 0 states jostled out
[1665062544] unbound[34265:0] info: average recursion processing time 0.057754 sec
[1665062544] unbound[34265:0] info: histogram of recursion processing times
[1665062544] unbound[34265:0] info: [25%]=0.0106496 median[50%]=0.0147456 [75%]=0.049152
[1665062544] unbound[34265:0] info: lower(secs) upper(secs) recursions
[1665062544] unbound[34265:0] info:    0.004096    0.008192 1
[1665062544] unbound[34265:0] info:    0.008192    0.016384 5
[1665062544] unbound[34265:0] info:    0.032768    0.065536 3
[1665062544] unbound[34265:0] info:    0.262144    0.524288 1
[1665062544] unbound[34265:0] info: server stats for thread 2: 12 queries, 4 answers from cache, 8 recursions, 0 prefetch, 0 rejected by ip ratelimiting
[1665062544] unbound[34265:0] info: server stats for thread 2: requestlist max 6 avg 2.75 exceeded 0 jostled 0
[1665062544] unbound[34265:0] info: mesh has 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 7 recursion replies sent, 0 replies dropped, 0 states jostled out
[1665062544] unbound[34265:0] info: average recursion processing time 0.028463 sec
[1665062544] unbound[34265:0] info: histogram of recursion processing times
[1665062544] unbound[34265:0] info: [25%]=0.014336 median[50%]=0.024576 [75%]=0.04096
[1665062544] unbound[34265:0] info: lower(secs) upper(secs) recursions
[1665062544] unbound[34265:0] info:    0.004096    0.008192 1
[1665062544] unbound[34265:0] info:    0.008192    0.016384 1
[1665062544] unbound[34265:0] info:    0.016384    0.032768 3
[1665062544] unbound[34265:0] info:    0.032768    0.065536 1
[1665062544] unbound[34265:0] info:    0.065536    0.131072 1
[1665062544] unbound[34265:0] info: server stats for thread 3: 8 queries, 0 answers from cache, 8 recursions, 0 prefetch, 0 rejected by ip ratelimiting
[1665062544] unbound[34265:0] info: server stats for thread 3: requestlist max 5 avg 1.5 exceeded 0 jostled 0
[1665062544] unbound[34265:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 8 recursion replies sent, 0 replies dropped, 0 states jostled out
[1665062544] unbound[34265:0] info: average recursion processing time 0.039993 sec
[1665062544] unbound[34265:0] info: histogram of recursion processing times
[1665062544] unbound[34265:0] info: [25%]=0.0218453 median[50%]=0.032768 [75%]=0.065536
[1665062544] unbound[34265:0] info: lower(secs) upper(secs) recursions
[1665062544] unbound[34265:0] info:    0.008192    0.016384 1
[1665062544] unbound[34265:0] info:    0.016384    0.032768 3
[1665062544] unbound[34265:0] info:    0.032768    0.065536 2
[1665062544] unbound[34265:0] info:    0.065536    0.131072 2

But I still don't understand what we are pushing unbound_configure_do to both dns and bootup. If a second go in bootup isn't necessary why is it there?

[fichtner]

There isn't a lot to understand. start.sh is locked from the first run still while unbound is attempted to be started a second time in order to latch on to VPN connections as per previous ticket. The second call, however, simply stops the first unbound and start.sh skips start because still locked. All because unbound is taking too much time to load, why it was backgrounded in the first place...

[billgertz]

@fichtner @martin-huber so we are in agreement. So what is the answer? Checking the lock status before pressing in for the kill and restart, unlocking then pressing forward, or something else? With an effective return no error buried in the flock call (-E 0) mwexecf_bg won't report a problem.

I really don't have a weird unbound environment with only 36 overrides and 43 aliases. I pretty sure others are getting bitten by this problem.

[fichtner]

Do you have any manual interface assignments in unbound settings? Especially for outgoing interfaces...

[billgertz]

@fichtner Yep, using an external firewall so the Internal DMZ is the WAN (external) interface. Don't need or want DMZ devices looking inbound for DNS.

Haven't assigned Advanced > Outgoing Network Interfaces though -that's at the default of "All (recommended)"

[billgertz]

@fichtner Could we move the killbypid calls into the start.sh script as killall -c calls? So at least it won't get us into the state where we just killed unbound but can't start a new process? Then perhaps we could call flock with a slight wait time (5 to 10 seconds)?

[fichtner]

A bit ironic seeing the OpenVPN server there and directly requiring https://github.com/opnsense/core/issues/2828 which causes this.

Unfortunately this isn't really an easy fix. Suppose that starting Unbound only once or an extra third time will workaround this "gracefully".

[martin-huber]

The question is: does it need to be restarted again, to circumvent that OpenVPN problem ? Why is it attempted to be restarted 2-3 times (if it would be quick enough to making the start and releasing the flock) ? (still the open question, if 'local' again would try to restart it again).

What would happen, if it only is started once, lately ? Does OpenVPN on the one hand depend on a running Unbound, but on the other hand its existence changes Unbounds behaviour ?

[billgertz]

@fichtner So #2828 is needed to solve the openvpn issue. But is it really necessary for unbound_configure_do be called twice? As the behaviour is hardwired, why add an unbound_configure_do to plugins_configure dns and bootup? Would it hurt anything to have unbound_configure_do called moments later only in bootup?

Which probably means that we need to know if monitor and vpn need DNS working in order to boot correctly (see rc.bootup):

plugins_configure('dhcp', true);
plugins_configure('dhcrelay', true);
plugins_configure('dns', true);

plugins_configure('monitor', true, [null, true]);
filter_configure_sync(true);
plugins_configure('vpn', true);
plugins_configure('bootup', true);
rrd_configure(true, true);

If so then can the startup sequence be reordered?

Still would suggest moving unbound process kill into the start.sh so we at least avoid the lock problem.