Unbound in 23.1.7: logger.py related crashes

[dinguz]

Is anybody else seeing these logger.py related crashes in unbound, starting with 23.1.7? I also notice it gets restarted very often while coming up. If I need to provide more info, please let me know.

Code: [Select]

Backgrounding unbound logging backend.
<163>1 2023-05-04T19:08:44+02:00 haanjdj.ddns.net unbound 84105 - [meta sequenceId="7"] Traceback (most recent call last):
<163>1 2023-05-04T19:08:44+02:00 haanjdj.ddns.net unbound 84105 - [meta sequenceId="8"]   File "/usr/local/opnsense/scripts/unbound/logg
er.py", line 122, in _sig
<163>1 2023-05-04T19:08:44+02:00 haanjdj.ddns.net unbound 84105 - [meta sequenceId="9"]     raise InterruptedError()
<163>1 2023-05-04T19:08:44+02:00 haanjdj.ddns.net unbound 84105 - [meta sequenceId="10"] InterruptedError
<163>1 2023-05-04T19:08:44+02:00 haanjdj.ddns.net unbound 84105 - [meta sequenceId="11"]
<163>1 2023-05-04T19:08:44+02:00 haanjdj.ddns.net unbound 84105 - [meta sequenceId="12"] The above exception was the direct cause of the
 following exception:
<163>1 2023-05-04T19:08:44+02:00 haanjdj.ddns.net unbound 84105 - [meta sequenceId="13"]
<163>1 2023-05-04T19:08:44+02:00 haanjdj.ddns.net unbound 84105 - [meta sequenceId="14"] Traceback (most recent call last):
<163>1 2023-05-04T19:08:44+02:00 haanjdj.ddns.net unbound 84105 - [meta sequenceId="15"]   File "/usr/local/opnsense/scripts/unbound/log
ger.py", line 239, in <module>
<163>1 2023-05-04T19:08:44+02:00 haanjdj.ddns.net unbound 84105 - [meta sequenceId="16"]     run(inputargs.pipe, inputargs.flush_interva
l)
<163>1 2023-05-04T19:08:44+02:00 haanjdj.ddns.net unbound 84105 - [meta sequenceId="17"]   File "/usr/local/opnsense/scripts/unbound/log
ger.py", line 223, in run
<163>1 2023-05-04T19:08:44+02:00 haanjdj.ddns.net unbound 84105 - [meta sequenceId="18"]     r.run_logger()
<163>1 2023-05-04T19:08:44+02:00 haanjdj.ddns.net unbound 84105 - [meta sequenceId="19"]   File "/usr/local/opnsense/scripts/unbound/log
ger.py", line 186, in run_logger
<163>1 2023-05-04T19:08:44+02:00 haanjdj.ddns.net unbound 84105 - [meta sequenceId="20"]     self._setup_db()
<163>1 2023-05-04T19:08:44+02:00 haanjdj.ddns.net unbound 84105 - [meta sequenceId="21"]   File "/usr/local/opnsense/scripts/unbound/log
ger.py", line 99, in _setup_db
<163>1 2023-05-04T19:08:44+02:00 haanjdj.ddns.net unbound 84105 - [meta sequenceId="22"]     db.connection.execute(
<163>1 2023-05-04T19:08:44+02:00 haanjdj.ddns.net unbound 84105 - [meta sequenceId="23"] RuntimeError: Query interrupted
<30>1 2023-05-04T19:08:44+02:00 haanjdj.ddns.net unbound 79968 - [meta sequenceId="24"] [79968:0] info: service stopped (unbound 1.17.1)
.

and

Code: [Select]

<30>1 2023-05-04T22:08:15+02:00 haanjdj.ddns.net unbound 43141 - [meta sequenceId="66"] [43141:0] info: start of service (unbound 1.17.1).
<30>1 2023-05-04T22:08:15+02:00 haanjdj.ddns.net unbound 43141 - [meta sequenceId="67"] [43141:1] info: dnsbl_module: attempting to open pipe
<30>1 2023-05-04T22:08:15+02:00 haanjdj.ddns.net unbound 43141 - [meta sequenceId="68"] [43141:1] info: dnsbl_module: no logging backend found.
<30>1 2023-05-04T22:08:15+02:00 haanjdj.ddns.net unbound 43141 - [meta sequenceId="69"] [43141:1] info: generate keytag query _ta-4f66. NULL IN
<165>1 2023-05-04T22:08:15+02:00 haanjdj.ddns.net unbound 90509 - [meta sequenceId="70"] daemonize unbound dhcpd watcher.
<165>1 2023-05-04T22:08:16+02:00 haanjdj.ddns.net unbound 92083 - [meta sequenceId="71"] Backgrounding unbound logging backend.
<165>1 2023-05-04T22:08:16+02:00 haanjdj.ddns.net unbound 92083 - [meta sequenceId="72"] Closing logger


[dinguz]

I have investigated this a bit further. The issue of unbound restarting very, very often has to do with DHCP registration. Apparently, unbound is being restarted with each DHCP lease that gets registered. As soon as this is disabled, unbound stays running.