swhite2
commented
2 years ago What do the Unbound logs say?
Closed billgertz closed 1 year ago
swhite2
commented
2 years ago What do the Unbound logs say?
billgertz
commented
2 years ago 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.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");
#endif708 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;
}<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
commented
2 years ago 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
commented
2 years ago 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 1The 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
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
commented
2 years ago @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
commented
2 years ago @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
commented
2 years ago 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:~ #@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
commented
2 years ago @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@swhite2 It looks like the unbound first load of _/var/unbound/hostentries.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_configuredo 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_configuredo 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 _pluginsconfigure dns and then again at _pluginscofigure bootup)? Is there a lead here somewhere or am I grasping at straws?
billgertz
commented
2 years ago @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_configuredo 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_configuredo 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
commented
2 years ago 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:
startup.shCould this be a plausible explanation ?
billgertz
commented
2 years ago @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
commented
2 years ago 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
commented
2 years ago 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
commented
2 years ago @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.pfftpproxyNotice 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
commented
2 years ago 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
commented
2 years ago @martin-huber @swhite Went ahead and disabled the pushing the unbound_configuredo 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
commented
2 years ago 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
commented
2 years ago @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 2But 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
commented
2 years ago 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
commented
2 years ago @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
commented
2 years ago Do you have any manual interface assignments in unbound settings? Especially for outgoing interfaces...
billgertz
commented
2 years ago @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
commented
2 years ago @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
commented
2 years ago 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
commented
2 years ago 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
commented
2 years ago @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.
billgertz
commented
2 years ago @fichtner @martin-huber I've edited unbound.inc to disable unbound_configure_do at dns instead of bootup:
function unbound_configure()
{
return array(
'bootup' => array('unbound_configure_do'),
/*
* disable unbound startup with dns
'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'),
);
}And then rebooted - everything seems to be fine. Looking through the system log doesn't show any problems, but with a test base of one this is hardly any proof:
<13>1 2022-10-07T18:00:44+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="15"] plugins_configure dhcp (1)
<13>1 2022-10-07T18:00:44+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="16"] plugins_configure dhcp (execute task : dhcpd_dhcp_configure(1))
<13>1 2022-10-07T18:00:44+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="17"] plugins_configure dhcrelay (1)
<13>1 2022-10-07T18:00:44+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="18"] plugins_configure dhcrelay (execute task : dhcpd_dhcrelay_configure(1))
<13>1 2022-10-07T18:00:44+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="19"] plugins_configure dns (1)
<13>1 2022-10-07T18:00:44+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="20"] plugins_configure dns (execute task : dnsmasq_configure_do(1))
<13>1 2022-10-07T18:00:44+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="21"] plugins_configure monitor (1,,1)
<13>1 2022-10-07T18:00:44+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="22"] plugins_configure monitor (execute task : dpinger_configure_do(1,,1))
<11>1 2022-10-07T18:00:44+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="23"] /usr/local/etc/rc.bootup: Removing static route for monitor 212.121.121.207 via 10.70.0.254
<11>1 2022-10-07T18:00:44+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="24"] /usr/local/etc/rc.bootup: The DMZINTERNAL_SLAAC monitor address is empty, skipping.
<27>1 2022-10-07T18:00:44+02:00 opnsense.blockfish.net dhcp6c 35812 - [meta sequenceId="25"] transmit failed: Can't assign requested address
<13>1 2022-10-07T18:00:44+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="26"] plugins_configure vpn (1)
<13>1 2022-10-07T18:00:44+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="27"] plugins_configure vpn (execute task : ipsec_configure_do(1))
<13>1 2022-10-07T18:00:46+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="28"] plugins_configure vpn (execute task : openvpn_configure_do(1))
<11>1 2022-10-07T18:00:46+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="29"] /usr/local/etc/rc.bootup: Resyncing OpenVPN instances.
<11>1 2022-10-07T18:00:46+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="30"] /usr/local/etc/rc.bootup: OpenVPN server 1 instance started on PID 86709.
<13>1 2022-10-07T18:00:46+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="31"] plugins_configure bootup (1)
<13>1 2022-10-07T18:00:46+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="32"] plugins_configure bootup (execute task : igmpproxy_configure_do(1))
<13>1 2022-10-07T18:00:46+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="33"] plugins_configure bootup (execute task : ntpd_configure_do(1))
<13>1 2022-10-07T18:00:47+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="34"] plugins_configure bootup (execute task : opendns_configure_do(1))
<11>1 2022-10-07T18:00:47+02:00 opnsense.blockfish.net opnsense 90630 - [meta sequenceId="35"] /usr/local/etc/rc.newwanip: IP renewal deferred during boot on 'ovpns1'
<13>1 2022-10-07T18:00:57+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="36"] opendns response: good 92.66.136.145
<13>1 2022-10-07T18:00:57+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="37"] plugins_configure bootup (execute task : unbound_configure_do(1))
<11>1 2022-10-07T18:00:57+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="38"] /usr/local/etc/rc.bootup: warning: ignoring missing default tunable request: debug.pfftpproxy
<11>1 2022-10-07T18:00:57+02:00 opnsense.blockfish.net opnsense 23748 - [meta sequenceId="39"] /usr/local/etc/rc.newwanip: IPv4 renewal is starting on 'ovpns1'
<11>1 2022-10-07T18:00:57+02:00 opnsense.blockfish.net opnsense 23748 - [meta sequenceId="40"] /usr/local/etc/rc.newwanip: Interface '' (ovpns1) is disabled or empty, nothing to do.I'm not sure what we try to do here: at some point we require DNS resolving capabilities and that's why 'dns' facility start exists. That's the first start of Unbound. 'bootup' facility is for boot-time services after all interfaces including VPNs are up, that means NTP and OpenDNS... And to fix the case of Unbound to be available on OpenVPN we need to restart Unbound here. That is the second start of the service.
As said before Unbound takes a long time to start and it should be investigated why first. Maybe the cache restore takes that long? How long does it take to restart Unbound anyway? It's super easy to measure and super helpful...
# killall unbound
# /usr/bin/time sh -x /usr/local/opnsense/scripts/unbound/start.shFrom the second command you can also see which command may take a long time/seems stuck.
Cheers, Franco
billgertz
commented
2 years ago @fichtner it's not taking a long time to start 20ms or so:
root@opnsense:/var/log # killall unbound
root@opnsense:/var/log # /usr/bin/time sh -x /usr/local/opnsense/scripts/unbound/start.sh
+ set -e
+ DOMAIN=''
+ /usr/local/sbin/unbound-checkconf /var/unbound/unbound.conf
unbound-checkconf: no errors in /var/unbound/unbound.conf
+ [ ! -f /var/unbound/unbound_control.key ]
+ find /var/unbound/etc -depth 1
+ rm -rf /var/unbound/etc/dot.conf
+ rm -rf /var/unbound/etc/miscellaneous.conf
+ rm -rf /var/unbound/etc/domainoverrides.conf
+ find /usr/local/etc/unbound.opnsense.d -depth 1 -name '*.conf'
+ cp /usr/local/etc/unbound.opnsense.d/dot.conf /var/unbound/etc/
+ cp /usr/local/etc/unbound.opnsense.d/miscellaneous.conf /var/unbound/etc/
+ cp /usr/local/etc/unbound.opnsense.d/domainoverrides.conf /var/unbound/etc/
+ cp /usr/local/etc/unbound.opnsense.d/dnsbl.conf /tmp/unbound_dnsbl.cache
cp: /usr/local/etc/unbound.opnsense.d/dnsbl.conf: No such file or directory
+ true
+ chown -R unbound:unbound /var/unbound
+ /usr/local/sbin/unbound -c /var/unbound/unbound.conf
+ /usr/local/opnsense/scripts/unbound/cache.sh load
zcat: can't stat: /var/unbound/cache.dump.gz: No such file or directory
+ [ -n '' ]
0.02 real 0.02 user 0.01 sys
root@opnsense:/var/log # ps -fax| grep unbound
22275 - Ss 0:02.30 /usr/local/bin/python3 /usr/local/opnsense/scripts/dhcp/unbound_watcher.py --domain blockfish.net (python3.9)
56775 - Ss 0:00.07 /usr/local/sbin/unbound -c /var/unbound/unbound.conf
58200 0 S+ 0:00.00 grep unboundCan you see if enabling "Flush DNS cache during reload" changes your observed behaviour during boot? Not sure why these are supposed to overlap if they don't take long to load at all.
billgertz
commented
2 years ago @fichtner @martin-huber Setting "Flush DNS cache during reload" did nothing to help.
Unbound is not running after reboot and the lock file didn't clear as expected:
root@opnsense:~ # ps -fax| grep unbound
63854 0 S+ 0:00.00 grep unbound
root@opnsense:~ # ls -la /tmp/unbound_start.lock
-rw-r--r-- 1 root wheel 0 Oct 10 12:36 /tmp/unbound_start.lock
root@opnsense:~ #The log files show the start at dns and bootup:
<10>1 2022-10-10T12:35:20+02:00 opnsense.blockfish.net reboot 96323 - [meta sequenceId="1"] rebooted by admin.bill
<45>1 2022-10-10T12:35:20+02:00 opnsense.blockfish.net syslog-ng 4946 - [meta sequenceId="2"] syslog-ng shutting down; version='3.38.1'
<45>1 2022-10-10T12:36:16+02:00 opnsense.blockfish.net syslog-ng 7223 - [meta sequenceId="1"] syslog-ng starting up; version='3.38.1'
<13>1 2022-10-10T12:36:49+02:00 opnsense.blockfish.net dhcp6c 17073 - [meta sequenceId="2"] RTSOLD script - Starting dhcp6 client
<11>1 2022-10-10T12:36:49+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="3"] /usr/local/etc/rc.bootup: Device ovpns1 is not assigned, configuring late
<11>1 2022-10-10T12:36:49+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="4"] /usr/local/etc/rc.bootup: Device ovpnc2 is not assigned, configuring late
<13>1 2022-10-10T12:36:49+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="5"] plugins_configure early (1)
<13>1 2022-10-10T12:36:49+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="6"] plugins_configure early (execute task : openssh_configure_do(1))
<13>1 2022-10-10T12:36:49+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="7"] plugins_configure early (execute task : unbound_cache_flush(1))
<13>1 2022-10-10T12:36:49+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="8"] plugins_configure early (execute task : webgui_configure_do(1))
<11>1 2022-10-10T12:36:50+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="9"] /usr/local/etc/rc.bootup: ROUTING: entering configure using defaults
<11>1 2022-10-10T12:36:50+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="10"] /usr/local/etc/rc.bootup: ROUTING: IPv4 default gateway set to wan
<11>1 2022-10-10T12:36:50+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="11"] /usr/local/etc/rc.bootup: ROUTING: setting IPv4 default route to 10.70.0.254
<11>1 2022-10-10T12:36:50+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="12"] /usr/local/etc/rc.bootup: ROUTING: creating /tmp/xn1_defaultgw using '10.70.0.254'
<11>1 2022-10-10T12:36:50+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="13"] /usr/local/etc/rc.bootup: ROUTING: IPv6 default gateway set to wan
<11>1 2022-10-10T12:36:50+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="14"] /usr/local/etc/rc.bootup: ROUTING: skipping IPv6 default route
<13>1 2022-10-10T12:36:50+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="15"] plugins_configure dhcp (1)
<13>1 2022-10-10T12:36:50+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="16"] plugins_configure dhcp (execute task : dhcpd_dhcp_configure(1))
<13>1 2022-10-10T12:36:50+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="17"] plugins_configure dhcrelay (1)
<13>1 2022-10-10T12:36:50+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="18"] plugins_configure dhcrelay (execute task : dhcpd_dhcrelay_configure(1))
<13>1 2022-10-10T12:36:50+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="19"] plugins_configure dns (1)
<13>1 2022-10-10T12:36:50+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="20"] plugins_configure dns (execute task : dnsmasq_configure_do(1))
<13>1 2022-10-10T12:36:50+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="21"] plugins_configure dns (execute task : unbound_configure_do(1))
<11>1 2022-10-10T12:36: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-10T12:36:50+02:00 opnsense.blockfish.net dhcp6c 17197 - [meta sequenceId="23"] transmit failed: Can't assign requested address
<13>1 2022-10-10T12:36:50+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="24"] plugins_configure monitor (1,,1)
<13>1 2022-10-10T12:36: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-10T12:36: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-10T12:36: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-10T12:36:50+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="28"] plugins_configure vpn (1)
<13>1 2022-10-10T12:36:50+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="29"] plugins_configure vpn (execute task : ipsec_configure_do(1))
<11>1 2022-10-10T12:36:52+02:00 opnsense.blockfish.net opnsense 53069 - [meta sequenceId="30"] /usr/local/etc/rc.newwanip: IP renewal deferred during boot on 'ovpns1'
<11>1 2022-10-10T12:36:53+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="31"] /usr/local/etc/rc.bootup: OpenVPN server 1 instance started on PID 52343.
<13>1 2022-10-10T12:36:53+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="32"] plugins_configure bootup (1)
<13>1 2022-10-10T12:36:53+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="33"] plugins_configure bootup (execute task : igmpproxy_configure_do(1))
<13>1 2022-10-10T12:36:53+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="34"] plugins_configure bootup (execute task : ntpd_configure_do(1))
<13>1 2022-10-10T12:36:53+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="35"] plugins_configure bootup (execute task : opendns_configure_do(1))
<13>1 2022-10-10T12:36:53+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="36"] opendns response: good 92.66.136.145
<13>1 2022-10-10T12:36:53+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="37"] plugins_configure bootup (execute task : unbound_configure_do(1))
<11>1 2022-10-10T12:36:53+02:00 opnsense.blockfish.net php 551 - [meta sequenceId="38"] /usr/local/etc/rc.bootup: warning: ignoring missing default tunable request: debug.pfftpproxy
<11>1 2022-10-10T12:36:54+Also noticed with an earlier reboot using my hacked version of /usr/local/etc/inc/plugins.inc.d/unbound.inc the lock didn't clear:
root@opnsense:/usr/local/etc/inc/plugins.inc.d # ls -la /tmp/unbound_start.lock
-rw-r--r-- 1 root wheel 0 Oct 10 12:04 /tmp/unbound_start.lock
root@opnsense:/usr/local/etc/inc/plugins.inc.d # Going back to my hacked version.
fichtner
commented
2 years ago I'm suspecting a setup issue that prevents unbound from starting up quickly at boot time. Debugging this later when the system is up (DHCP running and IPs assigned) is then not conclusive. As per your report unbound must take a long time to start for the second restart to kill the first start and still hold the lock of start.sh.
billgertz
commented
2 years ago Can't we verify that unbound is taking a long time start? Why would unbound be started but the lock file uncleared when only calling unbound_configure_do just once? If that were the case then the start process by mwexecf_bg should still be running, no? I can see on my system it is not:
root@opnsense:~ # ls -la /tmp/unbound_start.lock
-rw-r--r-- 1 root wheel 0 Oct 10 12:48 /tmp/unbound_start.lock
root@opnsense:~ # ps -fax | grep unbound
6603 - Ss 0:01.23 /usr/local/bin/python3 /usr/local/opnsense/scripts/dhcp/unbound_watcher.py --domain blockfish.net (python3.9)
93247 - Ss 0:01.07 /usr/local/sbin/unbound -c /var/unbound/unbound.conf
61226 0 S+ 0:00.00 grep unbound
root@opnsense:~ # ps -fax | grep flock
61333 0 S+ 0:00.00 grep flock
root@opnsense:~ # ps -fax | grep start
44003 - Is 0:00.00 sshd: /usr/local/sbin/sshd [listener] 0 of 10-100 startups (sshd)
94915 0 S+ 0:00.00 grep start
root@opnsense:~ # Any ideas or am I off base?
jo-krk
commented
2 years ago Hi, I'm posting on behalf of @martin-huber , as we're administrating the same machine. "Flush DNS cache during reload" was and still is enabled. Time to start:
root@opnsense:~ # killall unbound
root@opnsense:~ # time sh -x /usr/local/opnsense/scripts/unbound/start.sh
+ set -e
+ DOMAIN=''
+ /usr/local/sbin/unbound-checkconf /var/unbound/unbound.conf
unbound-checkconf: no errors in /var/unbound/unbound.conf
+ [ ! -f /var/unbound/unbound_control.key ]
+ find /var/unbound/etc -depth 1
+ rm -rf /var/unbound/etc/dot.conf
+ rm -rf /var/unbound/etc/miscellaneous.conf
+ rm -rf /var/unbound/etc/domainoverrides.conf
+ find /usr/local/etc/unbound.opnsense.d -depth 1 -name '*.conf'
+ cp /usr/local/etc/unbound.opnsense.d/dot.conf /var/unbound/etc/
+ cp /usr/local/etc/unbound.opnsense.d/miscellaneous.conf /var/unbound/etc/
+ cp /usr/local/etc/unbound.opnsense.d/domainoverrides.conf /var/unbound/etc/
+ cp /usr/local/etc/unbound.opnsense.d/dnsbl.conf /tmp/unbound_dnsbl.cache
cp: /usr/local/etc/unbound.opnsense.d/dnsbl.conf: No such file or directory
+ true
+ chown -R unbound:unbound /var/unbound
+ /usr/local/sbin/unbound -c /var/unbound/unbound.conf
+ /usr/local/opnsense/scripts/unbound/cache.sh load
zcat: can't stat: /var/unbound/cache.dump.gz: No such file or directory
+ [ -n '' ]
0.015u 0.015s 0:00.03 66.6% 494+230k 9+0io 1pf+0w@fichtner @martin-huber So modded /usr/local/opnsense/scripts/unbound/start.sh to get a crude time measurement:
.
.
.
# HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
# LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY
# OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
# SUCH DAMAGE.
set -e
# prepare and startup unbound, so we can easily background it
DOMAIN=${1}
time_ms=$( python3 -c'import time; print(time.time())' )
echo $time_ms >> /tmp/unbound_is_starting
# if the root.key file is missing or damaged, run unbound-anchor
if ! /usr/local/sbin/unbound-checkconf /var/unbound/unbound.conf 2> /dev/null; then
# unbound-anchor has undefined behaviour if file is corrupted, start clean
rm -f /var/unbound/root.key
# if we are in forwarding mode, prefer to use the configured system nameservers
if [ -s /var/unbound/resolv.conf.root ]; then
OPT_RESOLVE="-Rf /var/unbound/resolv.conf.root"
fi
# unbound-anchor exits with 1 on failover, since we would still like to start unbound,
# always let this succeed
chroot -u unbound -g unbound / /usr/local/sbin/unbound-anchor -a /var/unbound/root.key ${OPT_RESOLVE} || true
fi
if [ ! -f /var/unbound/unbound_control.key ]; then
chroot -u unbound -g unbound / /usr/local/sbin/unbound-control-setup -d /var/unbound
fi
for FILE in $(find /var/unbound/etc -depth 1); do
rm -rf ${FILE}
done
for FILE in $(find /usr/local/etc/unbound.opnsense.d -depth 1 -name '*.conf'); do
cp ${FILE} /var/unbound/etc/
done
# preload the blocklist cache so the dnsbl hook can properly diff on it
cp /usr/local/etc/unbound.opnsense.d/dnsbl.conf /tmp/unbound_dnsbl.cache || true
chown -R unbound:unbound /var/unbound
/usr/local/sbin/unbound -c /var/unbound/unbound.conf
/usr/local/opnsense/scripts/unbound/cache.sh load
if [ -n "${DOMAIN}" ]; then
/usr/local/opnsense/scripts/dhcp/unbound_watcher.py --domain ${DOMAIN}
fi
time_ms=$( python3 -c'import time; print(time.time())' )
echo $time_ms >> /tmp/unbound_has_startedYeah it uses python3 to get time to ms, but it gives some basic time to start:
root@opnsense:/tmp # ls -ls unbound*
1 -rw-rw-rwT 1 root wheel 0 Oct 11 11:26 unbound-blocklists.conf
1 -rw-r--r-- 1 root wheel 18 Oct 11 11:26 unbound_has_started
1 -rw-r--r-- 1 root wheel 19 Oct 11 11:26 unbound_is_starting
1 -rw-r--r-- 1 root wheel 0 Oct 11 11:26 unbound_start.lock
root@opnsense:/tmp # cat unbound_is_starting
1665480387.3431606
root@opnsense:/tmp # cat unbound_has_started
1665480387.465371
root@opnsense:/tmp # So that's about 122ms including the second python load time. That's not what I would call a long time - and the file lock is still there after start. Am I missing something? I'll rerun with my hack to /usr/local/etc/inc/plugins.inc.d/unbound.inc removed and get the run times for both calls to _unbound_configuredo.
fichtner
commented
2 years ago file lock is still there after start
Can we agree to the fact that the lock file is there, but it's actually unlocked?
To assess the fact that it's locked you'd need to start it like this and see if the script executes or not
# /usr/local/bin/flock -n -E 0 -o /tmp/unbound_start.lock sh -x /usr/local/opnsense/scripts/unbound/start.sh@fichtner Hacked on the unbound.inc to record the time just before kicking off in the unbound start.sh script:
.
.
.
if (isset($config['unbound']['regdhcp'])) {
$domain = $config['system']['domain'];
if (isset($config['unbound']['regdhcpdomain'])) {
$domain = $config['unbound']['regdhcpdomain'];
}
}
file_put_contents('/tmp/unbound_call_start',strval(microtime(true))."\n",FILE_APPEND);
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";
}
}Got this as the relative times:
root@opnsense:~ # cd /tmp
root@opnsense:/tmp # ls unbound_*
unbound_call_start unbound_has_started unbound_is_starting unbound_start.lock
root@opnsense:/tmp # cat unbound_call_start
1665497780.2652
1665497783.5184
root@opnsense:/tmp # cat unbound_is_starting
1665497780.2867491
1665497783.542388
root@opnsense:/tmp # cat unbound_has_started
1665497780.3817894
root@opnsense:/tmp # /usr/local/bin/flock -n -E 0 -o /tmp/unbound_start.lock sh -x /usr/local/opnsense/scripts/unbound/start.sh
+ set -e
+ DOMAIN=''
+ python3 '-cimport time; print(time.time())'
+ time_ms=1665498015.1669087
+ echo 1665498015.1669087
+ /usr/local/sbin/unbound-checkconf /var/unbound/unbound.conf
unbound-checkconf: no errors in /var/unbound/unbound.conf
+ [ ! -f /var/unbound/unbound_control.key ]
+ find /var/unbound/etc -depth 1
+ rm -rf /var/unbound/etc/dot.conf
+ rm -rf /var/unbound/etc/miscellaneous.conf
+ rm -rf /var/unbound/etc/domainoverrides.conf
+ find /usr/local/etc/unbound.opnsense.d -depth 1 -name '*.conf'
+ cp /usr/local/etc/unbound.opnsense.d/dot.conf /var/unbound/etc/
+ cp /usr/local/etc/unbound.opnsense.d/miscellaneous.conf /var/unbound/etc/
+ cp /usr/local/etc/unbound.opnsense.d/domainoverrides.conf /var/unbound/etc/
+ cp /usr/local/etc/unbound.opnsense.d/dnsbl.conf /tmp/unbound_dnsbl.cache
cp: /usr/local/etc/unbound.opnsense.d/dnsbl.conf: No such file or directory
+ true
+ chown -R unbound:unbound /var/unbound
+ /usr/local/sbin/unbound -c /var/unbound/unbound.conf
+ /usr/local/opnsense/scripts/unbound/cache.sh load
zcat: can't stat: /var/unbound/cache.dump.gz: No such file or directory
+ [ -n '' ]
+ python3 '-cimport time; print(time.time())'
+ time_ms=1665498015.2160425
+ echo 1665498015.2160425
root@opnsense:/tmp # ps -fax| grep unbound
17972 - Ss 0:00.07 /usr/local/sbin/unbound -c /var/unbound/unbound.conf
66223 0 S+ 0:00.00 grep unboundSo the lock file is there but it is unlocked. These debug files have only one or two entries - meaning _unbound_configuredo is only called twice. Putting the timeline together:
| call_start | is_starting | has_started |
|---|---|---|
| 1665497780.2652 | 1665497780.2868 | 1665497780.3818 |
| 1665497783.5184 | 1665497783.5423 | nothing recorded |
So the flock is not preventing the start.sh script from being called the second time. There is another problem causing the script to bail starting or before starting unbound.
billgertz
commented
2 years ago @fichtner here are the details of the resolver.log with verbosity cranked up to 5 showing the shutdown during the second call to start.sh:
<164>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 557 - [meta sequenceId="11393"] PTR record already exists for auth.blockfish.info(10.31.10.238)
<164>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 557 - [meta sequenceId="11394"] PTR record already exists for graylog.blockfish.net(10.69.0.214)
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11395"] [53971:2] debug: timeout udp
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11396"] [53971:2] debug: try edns1xx0 <blockfish.info.> 208.67.222.222#53
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11397"] [53971:2] debug: EDNS lookup known=1 vs=0
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11398"] [53971:2] debug: serviced query UDP timeout=50 msec
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11399"] [53971:2] debug: inserted new pending reply id=9bd7
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11400"] [53971:2] debug: opened UDP if=0 port=19926
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11401"] [53971:2] debug: comm point start listening 78 (-1 msec)
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11402"] [53971:2] debug: close of port 15800
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11403"] [53971:2] debug: comm_point_close of 74: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11404"] [53971:2] debug: close fd 74
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11405"] [53971:2] debug: answer cb
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11406"] [53971:2] debug: Incoming reply id = 9bd7
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11407"] [53971:2] debug: Incoming reply addr = ip4 208.67.222.222 port 53 (len 16)
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11408"] [53971:2] debug: lookup size is 1 entries
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11409"] [53971:2] debug: received udp reply.
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11410"] [53971:2] debug: udp message[1051:0] 9BD78390000100060000000109626C6F636B6669736804696E666F0000300001C00C00300001000147F500880100030703010001AA65E16D8152FA6E77610416AB4F255EF000D5F2B74D1CA28E620F3C98FC37A61651E9FC01381A9C09A130524ACF7D38846B2B5D60512934CAF445F5ED4FD219B782B76BAFBE5B0C5C8760950A24B6D25557742F94E49473FFCC081074D25EC162167BB0A3284294C9EDBD3CDFFF64875D381466E9DA4201B78E7D3667A6CEE1C00C00300001000147F500880100030803010001AE006C4E6A402C3A973F6EF4142384B53925AEDE51D49B76B0333C4DFA083C826D5287B88D5127D97EA1416BB1DDDF2DCC05991AAFE8B902
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11411"] [53971:2] debug: udp message[1051:256] FCA665F42F6D48F94F35B26193F6BA98E8D838A6F58FD8C60CF23B9F595357DF35048269407CDD6F88F0CC322D7C9101CFBDD640042C50C52C72623A5DF3F16181E228F188F7568FC00C00300001000147F500440100030DE58531B01BF839D4A73D32E8C9877295CC23A916108EEF3B4BF189DE37800C982981EF5FF8161B50718798DF2CE17D57BEBAB923B42EC3F4CCCE5C65C9C83B3DC00C00300001000147F501080101030703010001CBB5B659E80134CE9B8CA0DFEEBD4F7E518FAB0E283FF772EE9DC82FE0174322E63951CB2A5210F3860C85A748687D76CE2AE1A401E255785B0E2598F0B8CEB7F3173E3C86BB1176E7906EBAA0EEF07FD0DBC12D
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11412"] [53971:2] debug: udp message[1051:512] 9CDCDAFDD762D44F9B5192149783E8967F1099B2C6BDD232EE0B20A682E3C98FAC2D1BDB4DB2BDF31AB5CC7387C66FCB9E405208E4EA94B0D8CA11B7D456A06635A6B1D62746D487EA092FC926A9EB2104BC51B3F9704FF4FD903CCF648E6545AB79EE1B7F80A490E48E7779F17DF4E2D34F9F1DAC1BA3B53C0CFDB5A6B7A6F2EDCBE0C92F430990B7DAF5880BB0ED663E80C2DC03A2D53294F6A3BC38BC7E3C05F5AF9D405F188ED42428F7C00C00300001000147F501080101030803010001CA9BA290A3971B55C72945DB87D8C5723B04DA0FBD1D177CC3FA5A720E24A4060261B6B68A1644D62CF7E39E8ED8A138624391B47950F70BD2FB9D0C1600D42E
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11413"] [53971:2] debug: udp message[1051:768] A910815DEF750E760F51FBCA6C00EAFD1F3AD0468443EB7EBAB114EBA9DC757964F7E2FF873CD546A683DD863D58167EDE3B88B72293682920C9F933CF39954FAC8A88D0AEB179B920817E6FB55CA468CB713AD144924BAF391DF47676D32765863A6781D53F818C4163BA902B349C52DA58BD6D113315551678674480094A1155F21ACB7B7D79359C0DA51463DA567BB3562C5EAD4CBC080E36FFFF1507286EF8EBD86EDC48DB8693E9E2D275A1D26D0AB5EF8FE3AEAEE22FFB699627F655A3C00C00300001000147F500440101030DD99E7F33685B82EA9F093B8FD106505819249252A4F4A6EBC6DF45BF1ED5E92CCC3C361225F5877906C0C9CC58D1F9AA
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11414"] [53971:2] debug: udp message[1051:1024] C41561068B4C8C2ED69433D02F42A4300000291000000080000000
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11415"] [53971:2] debug: outnet handle udp reply
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11416"] [53971:2] debug: measured roundtrip at 7 msec
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11417"] [53971:2] debug: initiate TCP query EDNS
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11418"] [53971:2] debug: pending_tcp_query
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11419"] [53971:2] debug: reuse_tcp_find
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11420"] [53971:2] debug: reuse_tcp_find: num reuse streams 2
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11421"] [53971:2] debug: reuse_tcp_find check inexact match
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11422"] [53971:2] debug: pending_tcp_query: found reuse 208.67.222.222#53 fd 76
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11423"] [53971:2] debug: pending_tcp_query: reuse, store
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11424"] [53971:2] debug: comm point stop listening 76
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11425"] [53971:2] debug: outnet_tcp_take_query_setup: setup packet to write len 43 timeout 3000 msec
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11426"] [53971:2] debug: comm point start listening 76 (-1 msec)
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11427"] [53971:2] debug: startlistening 76 mode rw
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11428"] [53971:2] debug: close of port 19926
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11429"] [53971:2] debug: comm_point_close of 78: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11430"] [53971:2] debug: close fd 78
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11431"] [53971:2] debug: comm point stop listening 76
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11432"] [53971:2] debug: outnettcp cb
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11433"] [53971:2] debug: outnet tcp pkt was written event
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11434"] [53971:2] debug: outnet tcp writes done, wait
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11435"] [53971:2] debug: comm point stop listening 76
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11436"] [53971:2] debug: reuse_tcp_setup_timeout 208.67.222.222#53 fd 76
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11437"] [53971:2] debug: comm point start listening 76 (60000 msec)
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11438"] [53971:2] debug: startlistening 76 mode r
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11439"] [53971:2] debug: Reading tcp query of length 1765
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11440"] [53971:2] debug: comm point stop listening 76
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11441"] [53971:2] debug: outnettcp cb
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11442"] [53971:2] debug: reuse_tcp_insert 208.67.222.222#53 fd 76
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11443"] [53971:2] debug: outnet tcp callback query err 0 buflen 1765
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11444"] [53971:2] debug: svcd callbacks start
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11445"] [53971:2] debug: worker svcd callback for qstate 0x805d34110
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11446"] [53971:2] debug: mesh_run: start
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11447"] [53971:2] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11448"] [53971:2] info: iterator operate: query blockfish.info. DNSKEY IN
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11449"] [53971:2] debug: process_response: new external response event
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11450"] [53971:2] info: scrub for . NS IN
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11451"] [53971:2] info: response for blockfish.info. DNSKEY IN
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11452"] [53971:2] info: reply from <.> 208.67.222.222#53
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11453"] [53971:2] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr rd ra ; QUERY: 1, ANSWER: 9, AUTHORITY: 0, ADDITIONAL: 0
;; QUESTION SECTION:
blockfish.info. IN DNSKEY
;; ANSWER SECTION:
blockfish.info. 85619 IN DNSKEY 256 3 13 5YUxsBv4OdSnPTLoyYdylcwjqRYQju87S/GJ3jeADJgpge9f+BYbUHGHmN8s4X1Xvrq5I7Quw/TMzlxlycg7PQ== ;{id = 5475 (zsk), size = 256b}
blockfish.info. 85619 IN DNSKEY 257 3 7 AwEAAcu1tlnoATTOm4yg3+69T35Rj6sOKD/3cu6dyC/gF0Mi5jlRyypSEPOGDIWnSGh9ds4q4aQB4lV4Ww4lmPC4zrfzFz48hrsRdueQbrqg7vB/0NvBLZzc2v3XYtRPm1GSFJeD6JZ/EJmyxr3SMu4LIKaC48mPrC0b202yvfMatcxzh8Zvy55AUgjk6pSw2MoRt9RWoGY1prHWJ0bUh+oJL8kmqeshBLxRs/lwT/T9kDzPZI5lRat57ht/gKSQ5I53efF99OLTT58drBujtTwM/bWmt6by7cvgyS9DCZC32vWIC7DtZj6AwtwDotUylPajvDi8fjwF9a+dQF8YjtQkKPc= ;{id = 49104 (ksk), size = 2048b}
blockfish.info. 85619 IN DNSKEY 257 3 8 AwEAAcqbopCjlxtVxylF24fYxXI7BNoPvR0XfMP6WnIOJKQGAmG2tooWRNYs9+OejtihOGJDkbR5UPcL0vudDBYA1C6pEIFd73UOdg9R+8psAOr9HzrQRoRD6366sRTrqdx1eWT34v+HPNVGpoPdhj1YFn7eO4i3IpNoKSDJ+TPPOZVPrIqI0K6xebkggX5vtVykaMtxOtFEkkuvOR30dnbTJ2WGOmeB1T+BjEFjupArNJxS2li9bREzFVUWeGdEgAlKEVXyGst7fXk1nA2lFGPaVnuzVixerUy8CA42//8VByhu+OvYbtxI24aT6eLSdaHSbQq174/jrq7iL/tplif2VaM= ;{id = 15547 (ksk), size = 2048b}
blockfish.info. 85619 IN DNSKEY 257 3 13 2Z5/M2hbguqfCTuP0QZQWBkkklKk9Kbrxt9Fvx7V6SzMPDYSJfWHeQbAycxY0fmqxBVhBotMjC7WlDPQL0KkMA== ;{id = 15692 (ksk), size = 256b}
blockfish.info. 85619 IN DNSKEY 256 3 7 AwEAAapl4W2BUvpud2EEFqtPJV7wANXyt00coo5iDzyY/DemFlHp/AE4GpwJoTBSSs99OIRrK11gUSk0yvRF9e1P0hm3grdrr75bDFyHYJUKJLbSVVd0L5TklHP/zAgQdNJewWIWe7CjKEKUye29PN//ZIddOBRm6dpCAbeOfTZnps7h ;{id = 59585 (zsk), size = 1024b}
blockfish.info. 85619 IN DNSKEY 256 3 8 AwEAAa4AbE5qQCw6lz9u9BQjhLU5Ja7eUdSbdrAzPE36CDyCbVKHuI1RJ9l+oUFrsd3fLcwFmRqv6LkC/KZl9C9tSPlPNbJhk/a6mOjYOKb1j9jGDPI7n1lTV981BIJpQHzdb4jwzDItfJEBz73WQAQsUMUscmI6XfPxYYHiKPGI91aP ;{id = 31134 (zsk), size = 1024b}
blockfish.info. 85619 IN RRSIG DNSKEY 7 2 86400 20221101000000 20221001220404 49104 blockfish.info. rYRTyEsIKzsIi7Eml1w4AbnhzuCenSG0amseXXBDwYS0a8E1n6bzkky2G2TBc+QLrl9VKqO3pAuTdQ6crnASM1gwjjHznpAQwMRQK4V2zY/D0CMAY/wVTE5gCw4XAGzER2Mxj1UUU7SLZqXrq1hSEwsw/U3G/Aftpc2b1YSqjv+KdYu3FIJSFHVj7nAAnyllNWOUnahybmh1HfQ3lwKNwzFi5aiRzw1/FkDjbI8Wr1p5pn1zpzpovdSun+Q4Btg1254h78Y2y7A4C8HInfipufB4Vk33b/gIp/jwsiyj4j2u4pffOEn2gRmqfv0gvv6PCSdCi+YiuLUgqPbtL6sN+Q== ;{id = 49104}
blockfish.info. 85619 IN RRSIG DNSKEY 8 2 86400 20221101000000 20221001220404 15547 blockfish.info. KllBegia99bGgNF7kJj1I3dUa6Lqcb6s15l6cQ+OKDHcgiBoTkk3hdw+Vwsmd1jZ+ld/R8TpUtY1irloPh/hilxErSJ4zxgnI7ap1KX0xWCabgD4BFHGiFLiD/wf0pKL/hH24GLHWWs8tqpFCYyhdm6LAUYNyxO3hdvhps++vIzfFnVuuac1zLkOFOBClD3xdtv3RSvhRJHLbqAzhqtAZKaRzljm2QZYlfaQdEmtudsbrEBbxaIgfQ+AQXNyeMGaSuRMe8+4i3HRbM8z4Z528nFXhhgUaZdGa1NbvTUkRngfn9l3GdL90ArfRwvXV6haP8eRzS83x2vfG9Jz+IJk5g== ;{id = 15547}
blockfish.info. 85619 IN RRSIG DNSKEY 13 2 86400 20221101000000 20221001220404 15692 blockfish.info. jtYKeT5pIdAcjJWOLRYg7vXdaf5fn8U5nlSlnRNPVT13UTlcjBb/pMpllnHoCpjSbTD8uQ/JqDgDCzTefVm66Q== ;{id = 15692}
;; AUTHORITY SECTION:
;; ADDITIONAL SECTION:
;; MSG SIZE rcvd: 1754
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11454"] [53971:2] debug: iter_handle processing q with state QUERY RESPONSE STATE
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11455"] [53971:2] info: query response was ANSWER
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11456"] [53971:2] debug: iter_handle processing q with state FINISHED RESPONSE STATE
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11457"] [53971:2] info: finishing processing for blockfish.info. DNSKEY IN
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11458"] [53971:2] debug: mesh_run: iterator module exit state is module_finished
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11459"] [53971:2] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11460"] [53971:2] info: validator operate: query blockfish.info. DNSKEY IN
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11461"] [53971:2] debug: validator: nextmodule returned
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11462"] [53971:2] debug: not validating response, is valrec(validation recursion lookup)
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11463"] [53971:2] debug: mesh_run: validator module exit state is module_finished
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11464"] [53971:2] info: validator: inform_super, sub is blockfish.info. DNSKEY IN
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11465"] [53971:2] info: super is lb._dns-sd._udp.blockfish.info. PTR IN
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11466"] [53971:2] debug: attempt DS match algo 13 keytag 15692
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11467"] [53971:2] debug: DS match digest ok, trying signature
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11468"] [53971:2] debug: DS matched DNSKEY.
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11469"] [53971:2] info: validated DNSKEY blockfish.info. DNSKEY IN
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11470"] [53971:2] debug: validator[module 0] operate: extstate:module_wait_subquery event:module_event_pass
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11471"] [53971:2] info: validator operate: query lb._dns-sd._udp.blockfish.info. PTR IN
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11472"] [53971:2] debug: val handle processing q with state VAL_FINDKEY_STATE
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11473"] [53971:2] info: validator: FindKey lb._dns-sd._udp.blockfish.info. PTR IN
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11474"] [53971:2] debug: val handle processing q with state VAL_VALIDATE_STATE
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11475"] [53971:2] info: verify rrset blockfish.info. SOA IN
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11476"] [53971:2] debug: verify sig 59585 7
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11477"] [53971:2] debug: verify result: sec_status_secure
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11478"] [53971:2] info: verify rrset kgmihbndu70f1guup6vp043jn9nemojv.blockfish.info. NSEC3 IN
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11479"] [53971:2] debug: verify sig 59585 7
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11480"] [53971:2] debug: verify result: sec_status_secure
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11481"] [53971:2] info: verify rrset ootn7j3ke882mkajj617p7eqhtgbthtf.blockfish.info. NSEC3 IN
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11482"] [53971:2] debug: verify sig 59585 7
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11483"] [53971:2] debug: verify result: sec_status_secure
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11484"] [53971:2] info: verify rrset r2eg5f24se693cgl7svff9bu9fvrn369.blockfish.info. NSEC3 IN
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11485"] [53971:2] debug: verify sig 59585 7
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11486"] [53971:2] debug: verify result: sec_status_secure
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11487"] [53971:2] debug: Validating a nxdomain response
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11488"] [53971:2] debug: nsec3: keysize 256 bits, max iterations 150
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11489"] [53971:2] info: start nsec3 nameerror proof, zone blockfish.info. TYPE0 CLASS0
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11490"] [53971:2] info: ce candidate blockfish.info. TYPE0 CLASS0
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11491"] [53971:2] info: nsec3 nameerror: proven ce= blockfish.info. TYPE0 CLASS0
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11492"] [53971:2] debug: successfully validated NAME ERROR response.
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11493"] [53971:2] info: validate(nxdomain): sec_status_secure
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11494"] [53971:2] debug: val handle processing q with state VAL_FINISHED_STATE
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11495"] [53971:2] info: validation success lb._dns-sd._udp.blockfish.info. PTR IN
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11496"] [53971:2] debug: mesh_run: validator module exit state is module_finished
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11497"] [53971:2] debug: query took 0.224461 sec
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11498"] [53971:2] info: mesh_run: end 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 8 recursion replies sent, 0 replies dropped, 0 states jostled out
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11499"] [53971:2] info: average recursion processing time 0.062816 sec
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11500"] [53971:2] info: histogram of recursion processing times
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11501"] [53971:2] info: [25%]=0.016384 median[50%]=0.049152 [75%]=0.065536
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11502"] [53971:2] info: lower(secs) upper(secs) recursions
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11503"] [53971:2] info: 0.008192 0.016384 2
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11504"] [53971:2] info: 0.032768 0.065536 4
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11505"] [53971:2] info: 0.065536 0.131072 1
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11506"] [53971:2] info: 0.131072 0.262144 1
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11507"] [53971:2] debug: cache memory msg=154843 rrset=182248 infra=11364 val=149985
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11508"] [53971:2] debug: svcd callbacks end
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11509"] [53971:2] debug: serviced_delete
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11510"] [53971:2] debug: outnet_tcp_cb reuse after cb
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11511"] [53971:2] debug: outnet_tcp_cb reuse after cb: keep it
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11512"] [53971:2] debug: reuse_tcp_setup_readtimeout 208.67.222.222#53 fd 76
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11513"] [53971:2] debug: comm point stop listening 76
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11514"] [53971:2] debug: comm point start listening 76 (60000 msec)
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11515"] [53971:2] debug: startlistening 76 mode r
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11516"] [53971:3] debug: using localzone blockfish.net. transparent
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11517"] [53971:3] debug: using localzone blockfish.net. transparent
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11518"] [53971:0] info: service stopped (unbound 1.16.3).
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11519"] [53971:0] debug: stop threads
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11520"] [53971:1] debug: got control cmd quit
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11521"] [53971:0] debug: join 1
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11522"] [53971:3] debug: got control cmd quit
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11523"] [53971:2] debug: got control cmd quit
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11524"] [53971:0] debug: join success 1
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11525"] [53971:0] debug: join 2
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11526"] [53971:0] debug: join success 2
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11527"] [53971:0] debug: join 3
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11528"] [53971:0] debug: join success 3
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11529"] [53971:0] debug: cleanup.
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11530"] [53971:0] debug: comm_point_close of 60: event_del
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11531"] [53971:0] info: server stats for thread 0: 12 queries, 1 answers from cache, 11 recursions, 0 prefetch, 0 rejected by ip ratelimiting
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11532"] [53971:0] info: server stats for thread 0: requestlist max 3 avg 0.818182 exceeded 0 jostled 0
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11533"] [53971:0] info: mesh has 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 10 recursion replies sent, 0 replies dropped, 0 states jostled out
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11534"] [53971:0] info: average recursion processing time 0.182573 sec
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11535"] [53971:0] info: histogram of recursion processing times
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11536"] [53971:0] info: [25%]=0.012288 median[50%]=0.0436907 [75%]=0.098304
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11537"] [53971:0] info: lower(secs) upper(secs) recursions
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11538"] [53971:0] info: 0.000000 0.000001 1
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11539"] [53971:0] info: 0.004096 0.008192 1
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11540"] [53971:0] info: 0.008192 0.016384 1
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11541"] [53971:0] info: 0.016384 0.032768 1
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11542"] [53971:0] info: 0.032768 0.065536 3
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11543"] [53971:0] info: 0.065536 0.131072 1
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11544"] [53971:0] info: 0.131072 0.262144 1
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11545"] [53971:0] info: 1.000000 2.000000 1
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11546"] [53971:0] debug: cache memory msg=132120 rrset=132120 infra=11364 val=149985
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11547"] [53971:0] debug: serviced_delete
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11548"] [53971:0] debug: serviced_delete: TCP
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11549"] [53971:0] debug: serviced_delete: tcpreusekeep
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11550"] [53971:0] debug: reuse_tcp_remove_serviced_keep
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11551"] [53971:0] debug: reuse_tcp_remove_serviced_keep: in use by other queries
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11552"] [53971:0] debug: comm_point_close of 4: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11553"] [53971:0] debug: comm_point_close of 5: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11554"] [53971:0] debug: comm_point_close of 6: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11555"] [53971:0] debug: comm_point_close of 7: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11556"] [53971:0] debug: comm_point_close of 8: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11557"] [53971:0] debug: comm_point_close of 9: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11558"] [53971:0] debug: comm_point_close of 10: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11559"] [53971:0] debug: comm_point_close of 11: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11560"] [53971:0] debug: comm_point_close of 12: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11561"] [53971:0] debug: comm_point_close of 13: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11562"] [53971:0] debug: comm_point_close of 14: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11563"] [53971:0] debug: comm_point_close of 15: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11564"] [53971:0] debug: comm_point_close of 16: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11565"] [53971:0] debug: comm_point_close of 17: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11566"] [53971:0] debug: decommission_pending_tcp
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11567"] [53971:0] debug: reuse_tcp_remove_tree_list
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11568"] [53971:0] debug: comm_point_close of 77: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11569"] [53971:0] debug: close fd 77
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11570"] [53971:0] debug: comm_point_close of 62: event_del
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11571"] [53971: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-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11572"] [53971:0] info: server stats for thread 1: requestlist max 6 avg 1.76923 exceeded 0 jostled 0
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11573"] [53971:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 13 recursion replies sent, 0 replies dropped, 0 states jostled out
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11574"] [53971:0] info: average recursion processing time 0.038827 sec
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11575"] [53971:0] info: histogram of recursion processing times
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11576"] [53971:0] info: [25%]=0.02048 median[50%]=0.0444709 [75%]=0.0596846
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11577"] [53971:0] info: lower(secs) upper(secs) recursions
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11578"] [53971:0] info: 0.004096 0.008192 2
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11579"] [53971:0] info: 0.008192 0.016384 1
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11580"] [53971:0] info: 0.016384 0.032768 1
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11581"] [53971:0] info: 0.032768 0.065536 7
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11582"] [53971:0] info: 0.065536 0.131072 2
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11583"] [53971:0] debug: cache memory msg=132120 rrset=132120 infra=11364 val=149985
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11584"] [53971:0] debug: comm_point_close of 18: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11585"] [53971:0] debug: comm_point_close of 19: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11586"] [53971:0] debug: comm_point_close of 20: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11587"] [53971:0] debug: comm_point_close of 21: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11588"] [53971:0] debug: comm_point_close of 22: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11589"] [53971:0] debug: comm_point_close of 23: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11590"] [53971:0] debug: comm_point_close of 24: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11591"] [53971:0] debug: comm_point_close of 25: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11592"] [53971:0] debug: comm_point_close of 26: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11593"] [53971:0] debug: comm_point_close of 27: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11594"] [53971:0] debug: comm_point_close of 28: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11595"] [53971:0] debug: comm_point_close of 29: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11596"] [53971:0] debug: comm_point_close of 30: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11597"] [53971:0] debug: comm_point_close of 31: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11598"] [53971:0] debug: comm_point_close of 64: event_del
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11599"] [53971:0] info: server stats for thread 2: 10 queries, 2 answers from cache, 8 recursions, 0 prefetch, 0 rejected by ip ratelimiting
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11600"] [53971:0] info: server stats for thread 2: requestlist max 2 avg 0.375 exceeded 0 jostled 0
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11601"] [53971: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
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11602"] [53971:0] info: average recursion processing time 0.062816 sec
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11603"] [53971:0] info: histogram of recursion processing times
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11604"] [53971:0] info: [25%]=0.016384 median[50%]=0.049152 [75%]=0.065536
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11605"] [53971:0] info: lower(secs) upper(secs) recursions
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11606"] [53971:0] info: 0.008192 0.016384 2
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11607"] [53971:0] info: 0.032768 0.065536 4
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11608"] [53971:0] info: 0.065536 0.131072 1
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11609"] [53971:0] info: 0.131072 0.262144 1
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11610"] [53971:0] debug: cache memory msg=132120 rrset=132120 infra=11364 val=149985
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11611"] [53971:0] debug: comm_point_close of 32: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11612"] [53971:0] debug: comm_point_close of 33: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11613"] [53971:0] debug: comm_point_close of 34: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11614"] [53971:0] debug: comm_point_close of 35: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11615"] [53971:0] debug: comm_point_close of 36: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11616"] [53971:0] debug: comm_point_close of 37: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11617"] [53971:0] debug: comm_point_close of 38: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11618"] [53971:0] debug: comm_point_close of 39: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11619"] [53971:0] debug: comm_point_close of 40: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11620"] [53971:0] debug: comm_point_close of 41: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11621"] [53971:0] debug: comm_point_close of 42: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11622"] [53971:0] debug: comm_point_close of 43: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11623"] [53971:0] debug: comm_point_close of 44: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11624"] [53971:0] debug: comm_point_close of 45: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11625"] [53971:0] debug: decommission_pending_tcp
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11626"] [53971:0] debug: reuse_tcp_remove_tree_list
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11627"] [53971:0] debug: comm_point_close of 76: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11628"] [53971:0] debug: close fd 76
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11629"] [53971:0] debug: decommission_pending_tcp
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11630"] [53971:0] debug: reuse_tcp_remove_tree_list
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11631"] [53971:0] debug: comm_point_close of 75: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11632"] [53971:0] debug: close fd 75
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11633"] [53971:0] debug: comm_point_close of 66: event_del
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11634"] [53971:0] info: server stats for thread 3: 13 queries, 3 answers from cache, 10 recursions, 0 prefetch, 0 rejected by ip ratelimiting
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11635"] [53971:0] info: server stats for thread 3: requestlist max 4 avg 1 exceeded 0 jostled 0
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11636"] [53971: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
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11637"] [53971:0] info: average recursion processing time 0.035857 sec
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11638"] [53971:0] info: histogram of recursion processing times
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11639"] [53971:0] info: [25%]=0.012288 median[50%]=0.0393216 [75%]=0.0557056
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11640"] [53971:0] info: lower(secs) upper(secs) recursions
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11641"] [53971:0] info: 0.004096 0.008192 2
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11642"] [53971:0] info: 0.008192 0.016384 1
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11643"] [53971:0] info: 0.016384 0.032768 1
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11644"] [53971:0] info: 0.032768 0.065536 5
<30>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11645"] [53971:0] info: 0.065536 0.131072 1
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11646"] [53971:0] debug: cache memory msg=132120 rrset=132120 infra=11364 val=149985
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11647"] [53971:0] debug: comm_point_close of 46: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11648"] [53971:0] debug: comm_point_close of 47: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11649"] [53971:0] debug: comm_point_close of 48: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11650"] [53971:0] debug: comm_point_close of 49: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11651"] [53971:0] debug: comm_point_close of 50: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11652"] [53971:0] debug: comm_point_close of 51: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11653"] [53971:0] debug: comm_point_close of 52: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11654"] [53971:0] debug: comm_point_close of 53: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11655"] [53971:0] debug: comm_point_close of 54: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11656"] [53971:0] debug: comm_point_close of 55: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11657"] [53971:0] debug: comm_point_close of 56: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11658"] [53971:0] debug: comm_point_close of 57: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11659"] [53971:0] debug: comm_point_close of 58: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11660"] [53971:0] debug: comm_point_close of 59: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11661"] [53971:0] debug: comm_point_close of 68: event_del
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11662"] [53971:0] debug: Exit cleanup.
<31>1 2022-10-11T18:43:32+02:00 opnsense.blockfish.net unbound 53971 - [meta sequenceId="11663"] [53971:0] debug: switching log to stderr@fichtner Couldn't leave well enough alone. Missing the foo for having the flock call redirect sh -x start.sh to a log file so hacked in the equivalent of print statements to get an idea of where we're dying.
You were right - it appears to die on the second call to unbound. The log files I have seem to show it die after starting unbound for the second time. Looking at the time recorded the calls in the system log are at:
This shows that unbound does start the second time and the quits. Why, I have no idea as start.sh isn't called a third time from _unbound_configuredo for a "graceful" process close. If it were we would have a third entry in _isstarting in the previous debug run.
The system/latest.log:
<13>1 2022-10-12T13:41:51+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="17"] plugins_configure dhcrelay (1)
<13>1 2022-10-12T13:41:51+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="18"] plugins_configure dhcrelay (execute task : dhcpd_dhcrelay_configure(1))
<13>1 2022-10-12T13:41:51+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="19"] plugins_configure dns (1)
<13>1 2022-10-12T13:41:51+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="20"] plugins_configure dns (execute task : dnsmasq_configure_do(1))
<13>1 2022-10-12T13:41:51+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="21"] plugins_configure dns (execute task : unbound_configure_do(1))
<11>1 2022-10-12T13:41:51+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="22"] /usr/local/etc/rc.bootup: warning: ignoring missing default tunable request: debug.pfftpproxy
<27>1 2022-10-12T13:41:51+02:00 opnsense.blockfish.net dhcp6c 67073 - [meta sequenceId="23"] transmit failed: Can't assign requested address
<13>1 2022-10-12T13:41:51+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="24"] plugins_configure monitor (1,,1)
<13>1 2022-10-12T13:41:51+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="25"] plugins_configure monitor (execute task : dpinger_configure_do(1,,1))
<11>1 2022-10-12T13:41:51+02:00 opnsense.blockfish.net php 557 - [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-12T13:41:51+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="27"] /usr/local/etc/rc.bootup: The DMZINTERNAL_SLAAC monitor address is empty, skipping.
<13>1 2022-10-12T13:41:52+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="28"] plugins_configure vpn (1)
<13>1 2022-10-12T13:41:52+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="29"] plugins_configure vpn (execute task : ipsec_configure_do(1))
<13>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="30"] plugins_configure vpn (execute task : openvpn_configure_do(1))
<11>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="31"] /usr/local/etc/rc.bootup: Resyncing OpenVPN instances.
<11>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="32"] /usr/local/etc/rc.bootup: OpenVPN server 1 instance started on PID 13899.
<13>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="33"] plugins_configure bootup (1)
<13>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="34"] plugins_configure bootup (execute task : igmpproxy_configure_do(1))
<13>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="35"] plugins_configure bootup (execute task : ntpd_configure_do(1))
<13>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="36"] plugins_configure bootup (execute task : opendns_configure_do(1))
<11>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net opnsense 20572 - [meta sequenceId="37"] /usr/local/etc/rc.newwanip: IP renewal deferred during boot on 'ovpns1'
<13>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="38"] opendns response: good 92.66.136.145
<13>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="39"] plugins_configure bootup (execute task : unbound_configure_do(1))
<11>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="40"] /usr/local/etc/rc.bootup: warning: ignoring missing default tunable request: debug.pfftpproxyAnd the lightly edited log from resolver/latest.log:
<164>1 2022-10-12T13:41:51+02:00 opnsense.blockfish.net unbound 557 - many PTR record already exists info notices
.
.
.
<29>1 2022-10-12T13:41:51+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="38"] [74299:0] notice: init module 0: validator
<29>1 2022-10-12T13:41:51+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="39"] [74299:0] notice: init module 1: iterator
<30>1 2022-10-12T13:41:51+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="40"] [74299:0] info: start of service (unbound 1.16.3).
<165>1 2022-10-12T13:41:51+02:00 opnsense.blockfish.net unbound 79333 - [meta sequenceId="41"] daemonize unbound dhcpd watcher.
<30>1 2022-10-12T13:41:52+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="42"] [74299:0] info: generate keytag query _ta-4f66. NULL IN
.
.
.
<164>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 557 - Many PTR record already exists info notices
.
.
.
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="80"] [74299:0] info: service stopped (unbound 1.16.3).
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="81"] [74299:0] info: server stats for thread 0: 20 queries, 4 answers from cache, 16 recursions, 0 prefetch, 0 rejected by ip ratelimiting
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="82"] [74299:0] info: server stats for thread 0: requestlist max 2 avg 0.4375 exceeded 0 jostled 0
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="83"] [74299:0] info: average recursion processing time 0.037885 sec
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="84"] [74299:0] info: histogram of recursion processing times
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="85"] [74299:0] info: [25%]=0.00936229 median[50%]=0.0140434 [75%]=0.032768
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="86"] [74299:0] info: lower(secs) upper(secs) recursions
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="87"] [74299:0] info: 0.004096 0.008192 3
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="88"] [74299:0] info: 0.008192 0.016384 7
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="89"] [74299:0] info: 0.016384 0.032768 2
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="90"] [74299:0] info: 0.032768 0.065536 1
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="91"] [74299:0] info: 0.065536 0.131072 2
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="92"] [74299:0] info: 0.131072 0.262144 1
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="93"] [74299: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-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="94"] [74299:0] info: server stats for thread 1: requestlist max 5 avg 1.66667 exceeded 0 jostled 0
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="95"] [74299:0] info: average recursion processing time 0.019601 sec
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="96"] [74299:0] info: histogram of recursion processing times
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="97"] [74299:0] info: [25%]=0.007168 median[50%]=0.014336 [75%]=0.03072
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="98"] [74299:0] info: lower(secs) upper(secs) recursions
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="99"] [74299:0] info: 0.004096 0.008192 3
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="100"] [74299:0] info: 0.008192 0.016384 2
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="101"] [74299:0] info: 0.016384 0.032768 2
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="102"] [74299:0] info: 0.032768 0.065536 2
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="103"] [74299:0] info: server stats for thread 2: 19 queries, 4 answers from cache, 15 recursions, 0 prefetch, 0 rejected by ip ratelimiting
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="104"] [74299:0] info: server stats for thread 2: requestlist max 3 avg 0.8 exceeded 0 jostled 0
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="105"] [74299:0] info: average recursion processing time 0.030075 sec
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="106"] [74299:0] info: histogram of recursion processing times
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="107"] [74299:0] info: [25%]=0.0170667 median[50%]=0.0259413 [75%]=0.038912
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="108"] [74299:0] info: lower(secs) upper(secs) recursions
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="109"] [74299:0] info: 0.008192 0.016384 3
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="110"] [74299:0] info: 0.016384 0.032768 6
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="111"] [74299:0] info: 0.032768 0.065536 4
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="112"] [74299:0] info: server stats for thread 3: 18 queries, 3 answers from cache, 15 recursions, 0 prefetch, 0 rejected by ip ratelimiting
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="113"] [74299:0] info: server stats for thread 3: requestlist max 2 avg 0.6 exceeded 0 jostled 0
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="114"] [74299:0] info: average recursion processing time 0.027761 sec
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="115"] [74299:0] info: histogram of recursion processing times
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="116"] [74299:0] info: [25%]=0.01024 median[50%]=0.0212992 [75%]=0.0354987
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="117"] [74299:0] info: lower(secs) upper(secs) recursions
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="118"] [74299:0] info: 0.004096 0.008192 3
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="119"] [74299:0] info: 0.008192 0.016384 3
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="120"] [74299:0] info: 0.016384 0.032768 5
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="121"] [74299:0] info: 0.032768 0.065536 3
<30>1 2022-10-12T13:41:54+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="122"] [74299:0] info: 0.065536 0.131072 1For whatever reason the table wouldn't render in the last post. So here is the timeline for the last debug run:
| start.sh run | is_starting | after_anchor | after_contolkey | after_preloadblcache | after_chown | after_unboundbin | after_cacheload | has_started |
|---|---|---|---|---|---|---|---|---|
| first | 1665574911.662 | 1665574911.683 | 1665574911.694 | 1665574911.710 | 1665574911.722 | 1665574911.749 | 1665574911.760 | 1665574911.831 |
| second | 1665574914.890 | 1665574914.916 | 1665574914.938 | 1665574914.960 | 1665574914.972 | no record | no record | no record |
Noticed that the second run is missing the following log notices that were in the first:
<29>1 2022-10-12T13:41:51+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="38"] [74299:0] notice: init module 0: validator
<29>1 2022-10-12T13:41:51+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="39"] [74299:0] notice: init module 1: iterator
<30>1 2022-10-12T13:41:51+02:00 opnsense.blockfish.net unbound 74299 - [meta sequenceId="40"] [74299:0] info: start of service (unbound 1.16.3).
<165>1 2022-10-12T13:41:51+02:00 opnsense.blockfish.net unbound 79333 - [meta sequenceId="41"] daemonize unbound dhcpd watcher.Are the first two of these log entries a consequence of the following line in the /var/unbound/unbound.conf config file that turns on DNSSEC validation?
module-config: "validator iterator"@fichtner Could we have an incomplete or corrupt unbound.conf at the second run that is supposed to be generated by unbound.inc? Confirmed that a process kill (killall unbound) does not cause a reload as the PTR record already exists messages don't show up in the log, rather just a simple info: service stopped (unbound 1.16.3). Any ideas?
billgertz
commented
2 years ago @fichtner There are differences between the unbound.conf files from the first and second calls to unbound_configure_do:
root@opnsense:/var/unbound # diff unbound.conf.first unbound.conf.second
16c16,20
< include: /var/unbound/advanced.conf
---
> verbosity: 1
> extended-statistics: no
> log-queries: no
> hide-identity: no
> hide-version: no
24a29,42
> cache-max-ttl: 86400
> cache-min-ttl: 0
> harden-dnssec-stripped: no
> serve-expired: no
> outgoing-num-tcp: 10
> incoming-num-tcp: 10
> num-queries-per-thread: 4096
> outgoing-range: 8192
> infra-host-ttl: 900
> infra-cache-numhosts: 10000
> unwanted-reply-threshold: 0
> jostle-timeout: 200
> msg-cache-size: 4m
> rrset-cache-size: 8m
29a48
>
32a52,53
> prefetch: no
> prefetch-key: no
root@opnsense:/var/unbound #Is this supposed to be this way?
Added a single line to copy the config file just before starting unbound:
set -e
# prepare and startup unbound, so we can easily background it
DOMAIN=${1}
time_ms=$( python3 -c'import time; print(time.time())' )
echo $time_ms >> /tmp/unbound_is_starting
# if the root.key file is missing or damaged, run unbound-anchor
if ! /usr/local/sbin/unbound-checkconf /var/unbound/unbound.conf 2> /dev/null; then
# unbound-anchor has undefined behaviour if file is corrupted, start clean
rm -f /var/unbound/root.key
# if we are in forwarding mode, prefer to use the configured system nameservers
if [ -s /var/unbound/resolv.conf.root ]; then
OPT_RESOLVE="-Rf /var/unbound/resolv.conf.root"
fi
# unbound-anchor exits with 1 on failover, since we would still like to start unbound,
# always let this succeed
chroot -u unbound -g unbound / /usr/local/sbin/unbound-anchor -a /var/unbound/root.key ${OPT_RESOLVE} || true
fi
time_ms=$( python3 -c'import time; print(time.time())' )
echo $time_ms >> /tmp/unbound_after_anchor
if [ ! -f /var/unbound/unbound_control.key ]; then
chroot -u unbound -g unbound / /usr/local/sbin/unbound-control-setup -d /var/unbound
fi
time_ms=$( python3 -c'import time; print(time.time())' )
echo $time_ms >> /tmp/unbound_after_contolkey
for FILE in $(find /var/unbound/etc -depth 1); do
rm -rf ${FILE}
done
for FILE in $(find /usr/local/etc/unbound.opnsense.d -depth 1 -name '*.conf'); do
cp ${FILE} /var/unbound/etc/
done
# preload the blocklist cache so the dnsbl hook can properly diff on it
cp /usr/local/etc/unbound.opnsense.d/dnsbl.conf /tmp/unbound_dnsbl.cache || true
time_ms=$( python3 -c'import time; print(time.time())' )
echo $time_ms >> /tmp/unbound_after_preloadblcache
chown -R unbound:unbound /var/unbound
time_ms=$( python3 -c'import time; print(time.time())' )
echo $time_ms >> /tmp/unbound_after_chown
cat /var/unbound/unbound.conf >> /tmp/unbound.conf
/usr/local/sbin/unbound -c /var/unbound/unbound.conf
time_ms=$( python3 -c'import time; print(time.time())' )
echo $time_ms >> /tmp/unbound_after_unboundbin
/usr/local/opnsense/scripts/unbound/cache.sh load
time_ms=$( python3 -c'import time; print(time.time())' )
echo $time_ms >> /tmp/unbound_after_cacheload
if [ -n "${DOMAIN}" ]; then
/usr/local/opnsense/scripts/dhcp/unbound_watcher.py --domain ${DOMAIN}
fi
time_ms=$( python3 -c'import time; print(time.time())' )
echo $time_ms >> /tmp/unbound_has_startedLooks like you updated to 22.7.6 which now has /var/unbound/advanced.conf in place :)
I don't mind looking at this more closely, but I don't have a lot of time at the moment and no clue how to reproduce. This will take a while...
Cheers, Franco
billgertz
commented
2 years ago Ah, indeed I did. I'm out of bandwidth too. Would you suggest a fresh install using a backup of the config.xml (er backup of the opnsense config) as a next step (when I get time)?
In the meantime, I've gone back to knocking out the unbound_configure_do added to the action list for the configure dns stage. Things work - it's enough for now.
erikschwalbe
commented
2 years ago Hi, I'm posting on behalf of @martin-huber , as we're administrating the same machine. Yesterday we did some additional tests regarding the unbound problem. We did all the tests on the latest opnsense version (22.7.6). At the end we figured out, that if we disable the OpenVPN server in UNBOUND Network interfaces the UNBOUND service starts without a problem during a opnsense startup. We use OpenVpn server with a ldap backend. Ldap server is configured in Opnsense -> System -> Access -> Servers via DNS name. Could it be, that Unbound is not starting because the ldap server is not reachable. @billgertz I saw that you also configured a OpenVpn server on your machine. Perhaps you can double check. Thanks, Erik
billgertz
commented
2 years ago @martin-huber @fichtner @erikschwalbe Hurrah! You have found the likely cause.
I can confirm that after disabling the OpenVPN server interface in Services > Unbound DNS > General > Network Interfaces, Unbound is running after reboot.
Don't think it has to do with Unbound unable to resolve an address for the OpenVPN LDAP server as the fix is just removing an interface that unbound listens to DNS requests. At least that's my understanding. In my case I'm not using LDAP for authentication in the OpenVPN server config. Although I started down the path of adding an LDAP server, but haven't imported users yet. OpenVPN authenticates successfully to internal users.
The system logs show that Unbound was started twice at dns and bootup as expected:
<11>1 2022-10-17T13:53:05+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="14"] /usr/local/etc/rc.bootup: ROUTING: skipping IPv6 default route
<13>1 2022-10-17T13:53:05+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="15"] plugins_configure dhcp (1)
<13>1 2022-10-17T13:53:05+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="16"] plugins_configure dhcp (execute task : dhcpd_dhcp_configure(1))
<13>1 2022-10-17T13:53:05+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="17"] plugins_configure dhcrelay (1)
<13>1 2022-10-17T13:53:05+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="18"] plugins_configure dhcrelay (execute task : dhcpd_dhcrelay_configure(1))
<13>1 2022-10-17T13:53:05+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="19"] plugins_configure dns (1)
<13>1 2022-10-17T13:53:05+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="20"] plugins_configure dns (execute task : dnsmasq_configure_do(1))
<13>1 2022-10-17T13:53:05+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="21"] plugins_configure dns (execute task : unbound_configure_do(1))
<11>1 2022-10-17T13:53:05+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="22"] /usr/local/etc/rc.bootup: warning: ignoring missing default tunable request: debug.pfftpproxy
<27>1 2022-10-17T13:53:05+02:00 opnsense.blockfish.net dhcp6c 59549 - [meta sequenceId="23"] transmit failed: Can't assign requested address
<13>1 2022-10-17T13:53:05+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="24"] plugins_configure monitor (1,,1)
<13>1 2022-10-17T13:53:05+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="25"] plugins_configure monitor (execute task : dpinger_configure_do(1,,1))
<11>1 2022-10-17T13:53:05+02:00 opnsense.blockfish.net php 557 - [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-17T13:53:05+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="27"] /usr/local/etc/rc.bootup: The DMZINTERNAL_SLAAC monitor address is empty, skipping.
<13>1 2022-10-17T13:53:05+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="28"] plugins_configure vpn (1)
<13>1 2022-10-17T13:53:05+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="29"] plugins_configure vpn (execute task : ipsec_configure_do(1))
<13>1 2022-10-17T13:53:07+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="30"] plugins_configure vpn (execute task : openvpn_configure_do(1))
<11>1 2022-10-17T13:53:07+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="31"] /usr/local/etc/rc.bootup: Resyncing OpenVPN instances.
<11>1 2022-10-17T13:53:07+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="32"] /usr/local/etc/rc.bootup: OpenVPN server 1 instance started on PID 85257.
<13>1 2022-10-17T13:53:07+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="33"] plugins_configure bootup (1)
<13>1 2022-10-17T13:53:07+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="34"] plugins_configure bootup (execute task : igmpproxy_configure_do(1))
<13>1 2022-10-17T13:53:07+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="35"] plugins_configure bootup (execute task : ntpd_configure_do(1))
<13>1 2022-10-17T13:53:07+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="36"] plugins_configure bootup (execute task : opendns_configure_do(1))
<11>1 2022-10-17T13:53:07+02:00 opnsense.blockfish.net opnsense 93111 - [meta sequenceId="37"] /usr/local/etc/rc.newwanip: IP renewal deferred during boot on 'ovpns1'
<13>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="38"] opendns response: good 92.66.136.145
<13>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="39"] plugins_configure bootup (execute task : unbound_configure_do(1))
<11>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net php 557 - [meta sequenceId="40"] /usr/local/etc/rc.bootup: warning: ignoring missing default tunable request: debug.pfftpproxy
<11>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net opnsense 54688 - [meta sequenceId="41"] /usr/local/etc/rc.newwanip: IPv4 renewal is starting on 'ovpns1'
<11>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net opnsense 54688 - [meta sequenceId="42"] /usr/local/etc/rc.newwanip: Interface '' (ovpns1) is disabled or empty, nothing to do.
<11>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net opnsense 58341 - [meta sequenceId="43"] /usr/local/etc/rc.routing_configure: ROUTING: entering configure using defaults
<11>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net opnsense 58341 - [meta sequenceId="44"] /usr/local/etc/rc.routing_configure: ROUTING: IPv4 default gateway set to wan
<11>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net opnsense 58341 - [meta sequenceId="45"] /usr/local/etc/rc.routing_configure: ROUTING: setting IPv4 default route to 10.70.0.254
<11>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net opnsense 58341 - [meta sequenceId="46"] /usr/local/etc/rc.routing_configure: ROUTING: keeping current default gateway '10.70.0.254'
<11>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net opnsense 58341 - [meta sequenceId="47"] /usr/local/etc/rc.routing_configure: ROUTING: IPv6 default gateway set to wan
<11>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net opnsense 58341 - [meta sequenceId="48"] /usr/local/etc/rc.routing_configure: ROUTING: skipping IPv6 default route
<13>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net opnsense 58341 - [meta sequenceId="49"] plugins_configure monitor (1,)
<13>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net opnsense 58341 - [meta sequenceId="50"] plugins_configure monitor (execute task : dpinger_configure_do(1,))The resolver log shows that unbound is stopped and then restarted with the DNSSEC validator and initiator showing loaded twice as expected:
.
.
.
<29>1 2022-10-17T13:53:05+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="38"] [51958:0] notice: init module 0: validator
<29>1 2022-10-17T13:53:05+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="39"] [51958:0] notice: init module 1: iterator
.
.
.
<29>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 46722 - [meta sequenceId="124"] [46722:0] notice: init module 0: validator
<29>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 46722 - [meta sequenceId="125"] [46722:0] notice: init module 1: iteratorThe lightly edited resolver log for the successful boot:
.
.
.
<164>1 2022-10-17T13:53:05+02:00 opnsense.blockfish.net unbound 557 - [meta sequenceId="1" to "37"] Many "PTR record already exists" messages
.
.
.
<29>1 2022-10-17T13:53:05+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="38"] [51958:0] notice: init module 0: validator
<29>1 2022-10-17T13:53:05+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="39"] [51958:0] notice: init module 1: iterator
<30>1 2022-10-17T13:53:05+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="40"] [51958:0] info: start of service (unbound 1.16.3).
<165>1 2022-10-17T13:53:05+02:00 opnsense.blockfish.net unbound 55180 - [meta sequenceId="41"] daemonize unbound dhcpd watcher.
<30>1 2022-10-17T13:53:05+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="42"] [51958:2] info: generate keytag query _ta-4f66. NULL IN
<30>1 2022-10-17T13:53:05+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="43"] [51958:1] info: generate keytag query _ta-4f66. NULL IN
<30>1 2022-10-17T13:53:05+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="44"] [51958:0] info: generate keytag query _ta-4f66. NULL IN
<30>1 2022-10-17T13:53:05+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="45"] [51958:3] info: generate keytag query _ta-4f66. NULL IN
.
.
.
<164>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 557 - [meta sequenceId="46" to "82"] Many "PTR record already exists" messages
.
.
.
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="83"] [51958:0] info: service stopped (unbound 1.16.3).
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="84"] [51958:0] info: server stats for thread 0: 11 queries, 0 answers from cache, 11 recursions, 0 prefetch, 0 rejected by ip ratelimiting
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="85"] [51958:0] info: server stats for thread 0: requestlist max 4 avg 1 exceeded 0 jostled 0
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="86"] [51958:0] info: average recursion processing time 0.079837 sec
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="87"] [51958:0] info: histogram of recursion processing times
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="88"] [51958:0] info: [25%]=0.03072 median[50%]=0.0764587 [75%]=0.141995
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="89"] [51958:0] info: lower(secs) upper(secs) recursions
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="90"] [51958:0] info: 0.008192 0.016384 1
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="91"] [51958:0] info: 0.016384 0.032768 2
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="92"] [51958:0] info: 0.032768 0.065536 2
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="93"] [51958:0] info: 0.065536 0.131072 3
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="94"] [51958:0] info: 0.131072 0.262144 3
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="95"] [51958:0] info: server stats for thread 1: 9 queries, 0 answers from cache, 9 recursions, 0 prefetch, 0 rejected by ip ratelimiting
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="96"] [51958:0] info: server stats for thread 1: requestlist max 4 avg 1.22222 exceeded 0 jostled 0
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="97"] [51958:0] info: average recursion processing time 0.095058 sec
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="98"] [51958:0] info: histogram of recursion processing times
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="99"] [51958:0] info: [25%]=0.028672 median[50%]=0.147456 [75%]=0.2048
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="100"] [51958:0] info: lower(secs) upper(secs) recursions
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="101"] [51958:0] info: 0.004096 0.008192 1
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="102"] [51958:0] info: 0.016384 0.032768 1
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="103"] [51958:0] info: 0.065536 0.131072 1
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="104"] [51958:0] info: 0.131072 0.262144 4
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="105"] [51958:0] info: server stats for thread 2: 10 queries, 0 answers from cache, 10 recursions, 0 prefetch, 0 rejected by ip ratelimiting
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="106"] [51958:0] info: server stats for thread 2: requestlist max 5 avg 1.5 exceeded 0 jostled 0
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="107"] [51958:0] info: average recursion processing time 0.090035 sec
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="108"] [51958:0] info: histogram of recursion processing times
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="109"] [51958:0] info: [25%]=0.0150187 median[50%]=0.152917 [75%]=0.207531
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="110"] [51958:0] info: lower(secs) upper(secs) recursions
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="111"] [51958:0] info: 0.008192 0.016384 3
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="112"] [51958:0] info: 0.016384 0.032768 1
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="113"] [51958:0] info: 0.131072 0.262144 6
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="114"] [51958:0] info: server stats for thread 3: 10 queries, 0 answers from cache, 10 recursions, 0 prefetch, 0 rejected by ip ratelimiting
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="115"] [51958:0] info: server stats for thread 3: requestlist max 4 avg 1.3 exceeded 0 jostled 0
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="116"] [51958:0] info: average recursion processing time 0.082078 sec
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="117"] [51958:0] info: histogram of recursion processing times
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="118"] [51958:0] info: [25%]=0.013312 median[50%]=0.144179 [75%]=0.203162
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="119"] [51958:0] info: lower(secs) upper(secs) recursions
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="120"] [51958:0] info: 0.004096 0.008192 1
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="121"] [51958:0] info: 0.008192 0.016384 2
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="122"] [51958:0] info: 0.032768 0.065536 1
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 51958 - [meta sequenceId="123"] [51958:0] info: 0.131072 0.262144 5
<29>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 46722 - [meta sequenceId="124"] [46722:0] notice: init module 0: validator
<29>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 46722 - [meta sequenceId="125"] [46722:0] notice: init module 1: iterator
<30>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 46722 - [meta sequenceId="126"] [46722:0] info: start of service (unbound 1.16.3).
<165>1 2022-10-17T13:53:08+02:00 opnsense.blockfish.net unbound 60590 - [meta sequenceId="127"] daemonize unbound dhcpd watcher.
<30>1 2022-10-17T13:53:09+02:00 opnsense.blockfish.net unbound 46722 - [meta sequenceId="128"] [46722:1] info: generate keytag query _ta-4f66. NULL IN| Run times also appear normal for the start.sh debugging: start.sh run | is_starting | after_anchor | after_contolkey | after_preloadblcache | after_chown | after_unboundbin | after_cacheload | has_started |
|---|---|---|---|---|---|---|---|---|
| first | 1666007585.325 | 1666007585.347 | 1666007585.358 | 1666007585.374 | 1666007585.390 | 1666007585.409 | 1666007585.423 | 1666007585.523 |
| second | 1666007588.629 | 1666007588.647 | 1666007588.668 | 1666007588.690 | 1666007588.702 | 1666007588.725 | 1666007588.758 | 1666007588.836 |
Important notices
Before you add a new report, we ask you kindly to acknowledge the following:
After upgrading to 22.7 unbound stops unexpectedly during autostart at boot time. Steps to reproduce the behavior:
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:
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:
When the 'forced' plugincrl start hook in /usr/local/etc/rc.syshook.d everything starts normally:
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