unbound dns stops sporadically

[superfox]

Hi community :-)

My unbound dns stops sporadically and then does not restart automatically. If I then start the service manually, it runs again for a while.

Versions

Code: [Select]


OPNsense 22.7.2-amd64
FreeBSD 13.1-RELEASE-p1
OpenSSL 1.1.1q 5 Jul 2022

unbound 1.16.2


What I have found so far:

System: Log Files: Backend

Code: [Select]


2022-08-31T12:43:49 Error configd.py [7b7b624c-2a32-4a1d-a8e5-4fa4875f837b] Script action stderr returned "b'pgrep: Cannot get process list (kvm_getprocs: No such process)'"
2022-08-31T12:43:49 Notice configd.py [7b7b624c-2a32-4a1d-a8e5-4fa4875f837b] request Unbound status
2022-08-31T12:43:46 Notice configd.py [7c06539d-ae9d-493f-a696-3567b07ca28b] system status
2022-08-31T12:43:46 Error configd.py [45b92ad9-45f4-41ea-ac69-5b73abb033c3] Script action failed with Command '/usr/local/opnsense/scripts/unbound/wrapper.py -s ' returned non-zero exit status 1. at Traceback (most recent call last): File "/usr/local/opnsense/service/modules/processhandler.py", line 482, in execute subprocess.check_call(script_command, env=self.config_environment, shell=True, File "/usr/local/lib/python3.9/subprocess.py", line 373, in check_call raise CalledProcessError(retcode, cmd) subprocess.CalledProcessError: Command '/usr/local/opnsense/scripts/unbound/wrapper.py -s ' returned non-zero exit status 1.
2022-08-31T12:43:45 Notice configd.py [45b92ad9-45f4-41ea-ac69-5b73abb033c3] loading stats
2022-08-31T12:43:45 Error configd.py [76f8a633-fc77-48c3-b780-22d35cd7f195] Script action stderr returned "b'pgrep: Cannot get process list (kvm_getprocs: No such process)'"
2022-08-31T12:43:45 Notice configd.py [76f8a633-fc77-48c3-b780-22d35cd7f195] request Unbound status
2022-08-31T12:43:44 Notice configd.py [167990da-81ff-4444-a836-64888bf0dc2b] system status
2022-08-31T12:43:44 Error configd.py [b91649df-08e7-4c7b-ab44-56f93c73e1a2] Script action stderr returned "b'pgrep: Cannot get process list (kvm_getprocs: No such process)'"
2022-08-31T12:43:44 Notice configd.py [b91649df-08e7-4c7b-ab44-56f93c73e1a2] request Unbound status
2022-08-31T12:42:59 Notice configd.py [ad177214-9b91-4306-ad14-07d52072d6af] system status
2022-08-31T12:42:59 Error configd.py [bd2096a6-cccf-402d-ae98-55dd7a89b814] Script action stderr returned "b'pgrep: Cannot get process list (kvm_getprocs: No such process)'"
2022-08-31T12:42:59 Notice configd.py [bd2096a6-cccf-402d-ae98-55dd7a89b814] request Unbound status
2022-08-31T12:42:58 Notice configd.py [040d5049-8d73-4d63-bf0d-5fa7567881e6] system status
2022-08-31T12:42:58 Error configd.py [680fff2f-f3d3-48cd-95d4-9dfdf5396b17] Script action stderr returned "b'pgrep: Cannot get process list (kvm_getprocs: No such process)'"
2022-08-31T12:42:58 Notice configd.py [680fff2f-f3d3-48cd-95d4-9dfdf5396b17] request Unbound status
2022-08-31T12:42:56 Notice configd.py [4e20584a-dc7d-450b-a923-1f6d4e857726] system status
2022-08-31T12:42:53 Notice configd.py [d7de2405-b080-4f7e-83b2-f2f7a4bbe062] system status
2022-08-31T12:42:41 Notice configd.py [1a26828b-555f-4d1a-9dc4-e79e253a3889] system status
2022-08-31T12:42:41 Error configd.py [c54d0619-d8db-4189-a815-1975b4d19194] Script action stderr returned "b'pgrep: Cannot get process list (kvm_getprocs: No such process)'"
2022-08-31T12:42:41 Notice configd.py [c54d0619-d8db-4189-a815-1975b4d19194] request Unbound status
2022-08-31T12:41:58 Notice configd.py [d6f3afb4-60f9-4c96-b62f-a37c3c768559] system status
2022-08-31T12:41:56 Notice configd.py [ea1acff8-5d8f-40f5-ab12-c07e3d4ea9f4] system status
2022-08-31T12:41:54 Notice configd.py [bae352de-b0e2-4039-8796-2b7f55eb15ed] system status
2022-08-31T12:41:52 Error configd.py [7f1af965-bf67-4b82-8daf-abba38ed3489] Script action stderr returned "b'pgrep: Cannot get process list (kvm_getprocs: No such process)'"
2022-08-31T12:41:52 Notice configd.py [7f1af965-bf67-4b82-8daf-abba38ed3489] request Unbound status
2022-08-31T12:41:52 Debug configd.py OPNsense/Unbound/* generated //usr/local/etc/unbound_dhcpd.conf
2022-08-31T12:41:52 Debug configd.py OPNsense/Unbound/* generated //var/unbound/root.hints
2022-08-31T12:41:52 Debug configd.py OPNsense/Unbound/* generated //usr/local/etc/unbound.opnsense.d/miscellaneous.conf
2022-08-31T12:41:52 Debug configd.py OPNsense/Unbound/* generated //usr/local/etc/unbound.opnsense.d/domainoverrides.conf
2022-08-31T12:41:52 Debug configd.py OPNsense/Unbound/* generated //var/unbound/private_domains.conf
2022-08-31T12:41:52 Debug configd.py OPNsense/Unbound/* generated //usr/local/etc/unbound.opnsense.d/dot.conf
2022-08-31T12:41:52 Debug configd.py OPNsense/Unbound/* generated //tmp/unbound-blocklists.conf
2022-08-31T12:41:52 Notice configd.py generate template container OPNsense/Unbound/core
2022-08-31T12:41:52 Notice configd.py [39d8922f-9fe9-454e-a070-05f62ef0f05a] generate template OPNsense/Unbound/*
2022-08-31T12:41:51 Notice configd.py [19c6d916-5719-4ab6-a209-21f3bdb615f2] Stopping Unbound
2022-08-31T12:41:50 Notice configd.py [c2a777f2-e762-4c13-87b6-f6a6600a3bf0] trigger config changed event
2022-08-31T12:41:44 Notice configd.py [961760b8-2ef5-4a60-881b-f3f361f1db58] system status
2022-08-31T12:41:43 Notice configd.py [39027822-e5fe-417f-8acc-73991a3607da] request Unbound status


Services: Unbound DNS: Log File

Code: [Select]


2022-08-31T12:41:51 Informational unbound [72587:0] info: 1.000000 2.000000 8
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.524288 1.000000 34
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.262144 0.524288 171
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.131072 0.262144 549
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.065536 0.131072 544
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.032768 0.065536 868
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.016384 0.032768 987
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.008192 0.016384 716
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.004096 0.008192 2
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.002048 0.004096 3
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.001024 0.002048 4
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.000512 0.001024 2
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.000000 0.000001 441
2022-08-31T12:41:51 Informational unbound [72587:0] info: lower(secs) upper(secs) recursions
2022-08-31T12:41:51 Informational unbound [72587:0] info: [25%]=0.0154029 median[50%]=0.0331266 [75%]=0.0924913
2022-08-31T12:41:51 Informational unbound [72587:0] info: histogram of recursion processing times
2022-08-31T12:41:51 Informational unbound [72587:0] info: average recursion processing time 0.073326 sec
2022-08-31T12:41:51 Informational unbound [72587:0] info: server stats for thread 3: requestlist max 19 avg 0.269115 exceeded 0 jostled 0
2022-08-31T12:41:51 Informational unbound [72587:0] info: server stats for thread 3: 4721 queries, 392 answers from cache, 4329 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2022-08-31T12:41:51 Informational unbound [72587:0] info: 1.000000 2.000000 8
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.524288 1.000000 27
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.262144 0.524288 180
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.131072 0.262144 568
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.065536 0.131072 485
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.032768 0.065536 857
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.016384 0.032768 996
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.008192 0.016384 727
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.004096 0.008192 6
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.002048 0.004096 5
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.001024 0.002048 3
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.000512 0.001024 1
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.000128 0.000256 1
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.000000 0.000001 426
2022-08-31T12:41:51 Informational unbound [72587:0] info: lower(secs) upper(secs) recursions
2022-08-31T12:41:51 Informational unbound [72587:0] info: [25%]=0.0152966 median[50%]=0.032439 [75%]=0.0919531
2022-08-31T12:41:51 Informational unbound [72587:0] info: histogram of recursion processing times
2022-08-31T12:41:51 Informational unbound [72587:0] info: average recursion processing time 0.073108 sec
2022-08-31T12:41:51 Informational unbound [72587:0] info: server stats for thread 2: requestlist max 20 avg 0.268531 exceeded 0 jostled 0
2022-08-31T12:41:51 Informational unbound [72587:0] info: server stats for thread 2: 4698 queries, 408 answers from cache, 4290 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2022-08-31T12:41:51 Informational unbound [72587:0] info: 2.000000 4.000000 1
2022-08-31T12:41:51 Informational unbound [72587:0] info: 1.000000 2.000000 6
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.524288 1.000000 36
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.262144 0.524288 175
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.131072 0.262144 533
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.065536 0.131072 504
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.032768 0.065536 844
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.016384 0.032768 925
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.008192 0.016384 730
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.004096 0.008192 5
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.002048 0.004096 1
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.001024 0.002048 1
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.000000 0.000001 457
2022-08-31T12:41:51 Informational unbound [72587:0] info: lower(secs) upper(secs) recursions
2022-08-31T12:41:51 Informational unbound [72587:0] info: [25%]=0.0148185 median[50%]=0.0325909 [75%]=0.0916074
2022-08-31T12:41:51 Informational unbound [72587:0] info: histogram of recursion processing times
2022-08-31T12:41:51 Informational unbound [72587:0] info: average recursion processing time 0.073665 sec
2022-08-31T12:41:51 Informational unbound [72587:0] info: server stats for thread 1: requestlist max 24 avg 0.227596 exceeded 0 jostled 0
2022-08-31T12:41:51 Informational unbound [72587:0] info: server stats for thread 1: 4638 queries, 420 answers from cache, 4218 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2022-08-31T12:41:51 Informational unbound [72587:0] info: 1.000000 2.000000 9
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.524288 1.000000 45
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.262144 0.524288 181
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.131072 0.262144 537
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.065536 0.131072 552
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.032768 0.065536 869
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.016384 0.032768 1003
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.008192 0.016384 747
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.004096 0.008192 7
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.002048 0.004096 1
2022-08-31T12:41:51 Informational unbound [72587:0] info: 0.000000 0.000001 442
2022-08-31T12:41:51 Informational unbound [72587:0] info: lower(secs) upper(secs) recursions
2022-08-31T12:41:51 Informational unbound [72587:0] info: [25%]=0.0153011 median[50%]=0.0327108 [75%]=0.0923381
2022-08-31T12:41:51 Informational unbound [72587:0] info: histogram of recursion processing times
2022-08-31T12:41:51 Informational unbound [72587:0] info: average recursion processing time 0.074328 sec
2022-08-31T12:41:51 Informational unbound [72587:0] info: server stats for thread 0: requestlist max 22 avg 0.307307 exceeded 0 jostled 0
2022-08-31T12:41:51 Informational unbound [72587:0] info: server stats for thread 0: 4835 queries, 442 answers from cache, 4393 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2022-08-31T12:41:51 Informational unbound [72587:0] info: service stopped (unbound 1.16.2).
2022-08-29T12:48:00 Informational unbound [72587:0] info: start of service (unbound 1.16.2).
2022-08-29T12:47:59 Notice unbound [72587:0] notice: init module 0: iterator



[superfox]

any idea?
anyone?

I have already tried this: reinstall unbound package via System - Firmware - Packages

Is there a way to reset the configuration and maybe temporary files of unbound, without returning whole opnsense to factory settings? 

[axsdenied]

At the time it stopped it shows, just before it, " trigger config changed event".  Do you know what that even could be?

[Fright]

@superfox
Hi!
can you share last errors from unbound and backend logs at the time when unbound stops please ?

[Mks]

Dear all,

I face the same issue "sporadically", meaning it is not reproducible.

Same issues in the log file like superfox:

Code: [Select]

configd.py [94f77089-fc31-40d6-ab3d-203ef6d6b25d] Script action failed with Command '/usr/local/opnsense/scripts/unbound/wrapper.py -s ' returned non-zero exit status 1. at Traceback (most recent call last): File "/usr/local/opnsense/service/modules/processhandler.py", line 482, in execute subprocess.check_call(script_command, env=self.config_environment, shell=True, File "/usr/local/lib/python3.9/subprocess.py", line 373, in check_call raise CalledProcessError(retcode, cmd) subprocess.CalledProcessError: Command '/usr/local/opnsense/scripts/unbound/wrapper.py -s ' returned non-zero exit status 1.

Code: [Select]

[0c15c94c-dc34-4e72-b2c6-a6bb1566925c] Script action stderr returned "b'pgrep: Cannot get process list (kvm_getprocs: No such process)'"
Any ideas or hints how to analyze the issue?

br

[abulafia]

config changes -> could this be an update / re-loading of DNSBL or a DCHP registration update?

[JRM99]

Same problem. Using current dev version of OPNsense for many months. A few days ago, unbound stopped and couldn't be restarted (using Services tab on the Dashboard). Thinking it was the dev version, I rolled back to OPNsense 22.7.7_1-amd64. Unbound stopped again this morning. I've disabled unbound and enabled dnsmasq which at this stage is more reliable. I can see nothing in the logs. But I will note that I automatically restart my 4G WAN modems each morning at 03:00:00 and 03:10:00 to reestablish the connections. Logs indicate unbound activity at these times but no errors (I don't know how to export the logs).

[franco]

Do you have an "interfaces" selected in the Unbound settings? Because it can have these counter-productive effects.


Cheers,
Franco

[dave]

Using the blocklist does it for me

Disabled everything except Threatfox IOC... no problems

[Mks]

Do you have an "interfaces" selected in the Unbound settings? Because it can have these counter-productive effects.

Do you mean under Unbound "General options" --> "Network Interfaces" if there are specific ones selected?

br

[franco]

Yes, there is "Network Interfaces" and "Outgoing Network Interfaces".


Cheers,
Franco

[JRM99]

Yes, there is "Network Interfaces" and "Outgoing Network Interfaces".

@franco. Hi. My unbound config defaults to "All (recommend)" for Network Interfaces and Outgoing Network Interfaces. Is this correct? I have two physical 4G modems configured as fail-over (WAN1 and WAN2) plus several OpenVPN connections, all of which are listed in the drop down.

[superfox]

At the time it stopped it shows, just before it, " trigger config changed event".  Do you know what that even could be?

nope, no idea what event that could be. How can i find more information about "config changing events"?

[superfox]

@superfox
Hi!
can you share last errors from unbound and backend logs at the time when unbound stops please ?

I already share the logs you mentioned in my initial (first) post. Or do you mean different logs?
If yes, where (in the menu) to find them exactly?
Thx!

[superfox]

Do you have an "interfaces" selected in the Unbound settings? Because it can have these counter-productive effects.


Cheers,
Franco

Under Services: Unbound DNS: General

"Network Interfaces"
I have selected two interfaces. One is the LAN interf. Second is a OVPN-client interf.

"Outgoing Network Interfaces"
None interface is selected, but it shows "All (recommended)".

Question is: Should i select an interface or better leave it unselected with "All (recommended)?