OPNsense Forum
Archive => 21.7 Legacy Series => Topic started by: Wendo on August 06, 2021, 11:05:53 pm
-
I just upgraded to 21.7.1 and Unbound now won't start from the GUI. However, going to the shell and running
unbound -c /var/unbound/unbound.conf
make it start no problem. There is nothing in the logs indicating any sort of issue on both the failed starts and the starts from the command line.
Can anyone point me in the right direction here? Even putting a -d on the command line doesn't show me any errors on start (probably because it starts successfully).
What command line does opnsense actually use to start Unbound?
Thanks
-
Does this help?
ps aux | grep unbound
root 10938 0.0 0.2 24220 14584 - Ss 22:09 0:04.29 /usr/local/bin/python3 /usr/local/opnsense/scripts/dns/unbound_dhcpd.py --domain home.arpa (python3.8)
unbound 16367 0.0 0.5 82980 41912 - Is 22:09 0:03.05 /usr/local/sbin/unbound -c /var/unbound/unbound.conf
-
Have you tried
unbound-checkconf
-
Ok, so no idea what was going on. I poked around with a couple of things (one of which was I was using the wrong config file when running it from command line. Then started getting can't bind, port in use even though it wasn't running (and neither was dnsmasq) and just said screw it and restarted (I'd done that before).
Anyway, after the restart it came up just fine *shrug*
-
I just upgraded to 21.7.1 and Unbound now won't start from the GUI. However, going to the shell and running
unbound -c /var/unbound/unbound.conf
make it start no problem. There is nothing in the logs indicating any sort of issue on both the failed starts and the starts from the command line.
I observed exactly the same problem after updating form 21.7 to 21.7.1. The config (checked with unbound-checkconf) and log files look ok. Even after a second reboot since the update I have to start the unbound process manually via the concole :'(.
Any hints?
BTW the whole startup process of my opnsense takes very long time (up to 15 minutes). But this is an issue which I have observed long time ago and unfortunately have not investigated yet.
-
I have noticed too, that a startup do take a very long time. Atleast, that is what I thought. However, I am able to SSH in to the firewall at a very early stage.
But to not wait for the web management to show up, I have often found myself executing
/usr/local/etc/rc.restart_webgui
And then everything looks fine.
-
Have you checked if the system time is correct, and ntp sync is working properly? In another thread someone reported time deviations leading to instability.
-
Have you checked if the system time is correct, and ntp sync is working properly? In another thread someone reported time deviations leading to instability.
Yes, both is fine. Maybe, some startup scripts weren't finished. I'll try to investigaste more, why the whole boot process takes long time.
-
Same issue here - unbound would not start automatically and the GUI button did not start it either. Working configuration imported from 21.1 and unbound-checkconf does not complain.
The GUI "start" button only generated the following unbound log entry:
2021-08-08T13:16:31 unbound[57542] daemonize unbound dhcpd watcher.
whereas running unbound -c /var/unbound/unbound.confcaused Unbound to start up fine.
Reboot did not solve the issue:
Initially, Unbound started up - GUI showed it as running and log entries seem to confirm startup, but then it died again:
2021-08-08T13:28:07 unbound[2474] daemonize unbound dhcpd watcher.
2021-08-08T13:28:05 unbound[2663] daemonize unbound dhcpd watcher.
2021-08-08T13:28:00 unbound[38473] daemonize unbound dhcpd watcher.
2021-08-08T13:27:52 unbound[60119] daemonize unbound dhcpd watcher.
2021-08-08T13:27:52 unbound[25826] [25826:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
2021-08-08T13:27:52 unbound[25826] [25826:0] info: server stats for thread 3: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-08-08T13:27:52 unbound[25826] [25826:0] info: server stats for thread 3: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-08-08T13:27:52 unbound[25826] [25826:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
2021-08-08T13:27:52 unbound[25826] [25826:0] info: server stats for thread 2: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-08-08T13:27:52 unbound[25826] [25826:0] info: server stats for thread 2: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-08-08T13:27:52 unbound[25826] [25826:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
2021-08-08T13:27:52 unbound[25826] [25826:0] info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-08-08T13:27:52 unbound[25826] [25826:0] info: server stats for thread 1: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-08-08T13:27:52 unbound[25826] [25826:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
2021-08-08T13:27:52 unbound[25826] [25826:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-08-08T13:27:52 unbound[25826] [25826:0] info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-08-08T13:27:51 unbound[25826] [25826:0] info: service stopped (unbound 1.13.1).
2021-08-08T13:27:51 unbound[25826] [25826:0] info: control cmd: dump_cache
2021-08-08T13:27:45 unbound[25826] [25826:0] info: start of service (unbound 1.13.1).
2021-08-08T13:27:45 unbound[25826] [25826:0] notice: init module 2: iterator
2021-08-08T13:27:45 unbound[25826] [25826:0] notice: init module 1: validator
2021-08-08T13:27:45 unbound[25826] [25826:0] notice: init module 0: dns64
2021-08-08T13:27:39 unbound[25826] [25826:0] notice: Restart of unbound 1.13.1.
2021-08-08T13:27:39 unbound[25826] [25826:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
2021-08-08T13:27:39 unbound[25826] [25826:0] info: server stats for thread 3: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-08-08T13:27:39 unbound[25826] [25826:0] info: server stats for thread 3: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-08-08T13:27:39 unbound[25826] [25826:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
2021-08-08T13:27:39 unbound[25826] [25826:0] info: server stats for thread 2: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-08-08T13:27:39 unbound[25826] [25826:0] info: server stats for thread 2: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-08-08T13:27:39 unbound[25826] [25826:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
2021-08-08T13:27:39 unbound[25826] [25826:0] info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-08-08T13:27:39 unbound[25826] [25826:0] info: server stats for thread 1: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-08-08T13:27:39 unbound[25826] [25826:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
2021-08-08T13:27:39 unbound[25826] [25826:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-08-08T13:27:39 unbound[25826] [25826:0] info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-08-08T13:27:38 unbound[25826] [25826:0] info: service stopped (unbound 1.13.1).
2021-08-08T13:27:38 unbound[25826] [25826:0] info: start of service (unbound 1.13.1).
2021-08-08T13:27:38 unbound[25826] [25826:0] notice: init module 2: iterator
2021-08-08T13:27:38 unbound[25826] [25826:0] notice: init module 1: validator
2021-08-08T13:27:38 unbound[25826] [25826:0] notice: init module 0: dns64
2021-08-08T13:27:31 unbound[66648] daemonize unbound dhcpd watcher.
2021-08-08T13:27:31 unbound[2967] [2967:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
2021-08-08T13:27:31 unbound[2967] [2967:0] info: server stats for thread 3: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-08-08T13:27:31 unbound[2967] [2967:0] info: server stats for thread 3: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-08-08T13:27:31 unbound[2967] [2967:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
2021-08-08T13:27:31 unbound[2967] [2967:0] info: server stats for thread 2: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-08-08T13:27:31 unbound[2967] [2967:0] info: server stats for thread 2: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-08-08T13:27:31 unbound[2967] [2967:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
2021-08-08T13:27:31 unbound[2967] [2967:0] info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-08-08T13:27:31 unbound[2967] [2967:0] info: server stats for thread 1: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-08-08T13:27:31 unbound[2967] [2967:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
2021-08-08T13:27:31 unbound[2967] [2967:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
2021-08-08T13:27:31 unbound[2967] [2967:0] info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2021-08-08T13:27:31 unbound[2967] [2967:0] info: service stopped (unbound 1.13.1).
2021-08-08T13:27:31 unbound[2967] [2967:0] info: control cmd: dump_cache
2021-08-08T13:27:19 unbound[2967] [2967:0] info: control cmd: list_local_data
2021-08-08T13:27:19 unbound[2967] [2967:0] info: start of service (unbound 1.13.1).
2021-08-08T13:27:19 unbound[2967] [2967:0] notice: init module 2: iterator
2021-08-08T13:27:19 unbound[2967] [2967:0] notice: init module 1: validator
2021-08-08T13:27:19 unbound[2967] [2967:0] notice: init module 0: dns64
2021-08-08T13:27:12 unbound[87717] daemonize unbound dhcpd watcher.
[*** REBOOT ***]
This recurs several times in the log, thereafter it is only the unbound[57542] daemonize unbound dhcpd watcher.
Manually starting unbound works.
Could this be an issue with Unbound having issues with running on a different port than 53 (I have adguard home running as general DNS server), even though Unbound does not complain about ports?
-
FYI, I have opened a bug on the issue tracker: https://github.com/opnsense/core/issues/5150
-
For me the issue was ' Enable DNS64 Support' was enabled.
-
Hey,
this issue with Unbound still persists in OPNsense 21.7.3_3.
Unound runs briefly and then stops/crashes after a few secs.
As somova pointed out on Github it looks like the problem is that the cache-load command of unbound hangs.
Any solution?
-
On Github somova has suspected that the problem could be related to the state reset for dial-up connections (which kills all network connections incl. loopback connections).
Because of this, I ran a few tests.
- Restart of OPNsense with WAN being connected:
unbound hangs on cache-load command
- Restart of OPNsense without WAN being connected:
unbound properly starts up
- Reconnecting WAN:
state reset kicks in, unbound restarts and hangs on cache-load command
Now disabling "Dynamic state reset" under Firewall -> Settings -> Advanced...
- Restart of OPNsense with WAN being connected:
unbound properly starts up
So, it could well be that somova is right in his assumption.
-
@glasi
sounds logical imho
can you please test one possible solution?
1.install pacth:
opnsense-patch -a kulikov-a fc86769(it just makes the system rule for the loopback interface stateless)
2.restart pf
3.try to reproduce the problem
thanks!
-
fc86769 looks reasonable if it solves the issue, nice
Cheers,
Franco
-
thanks) I hope this helps with this strange unbound-control behavior and then i can make a pr
-
@glasi
sounds logical imho
can you please test one possible solution?
Thanks for the patch. But, please don't do that. It's just another workaround. We should solve it by just resetting states of the WAN interface when the dynamic ip address changes. The topic was already discussed here (https://forum.opnsense.org/index.php?topic=8766.msg39248#msg39248).
Currently, I am experimenting with resetting states of expired/outdated PPPoE WAN IP only. This needs some more time and testing.
-
@schnipp
can't agree. imho this is not really a workaround. this, in principle, preserves localhost connections when manipulating states.
off-topic: if you want to reset the states by a specific interface, then imho this can be done with the command:
pfctl -i <ifname> -Fsor by ip as it is already done in rc.newwanip by default
but @glasi mentioned an "Reset all states when a dynamic IP address changes" option that is explicitly listed as resetting all states. so I just suggest excluding localhost from "all" )
-
@schnipp
[…] imho this is not really a workaround.
[…]
Of course it is. You try to solve a problem which neccessarily does not exist. The state reset function was implemented in the past due to my discussion referenced in #16 (https://forum.opnsense.org/index.php?topic=24264.msg120410#msg120410). The original problem was that in case the dynamic WAN IP changed the NAPT table was not updated and the source IPs of known connections where still translated to one which became invalid. This kind of traffic has been correctly filtered by the ISP and resulted in broken communication to the internet as long as an corresponding NAPT table entry exists. This problem can be solved by deleting all entries in the NAPT table belonging to the expired public IP address.
Currently, the state reset is improperly implemented because it resets also the states of internal connections which is not needed.
-
Let's please discuss patch vs. patch, not patch vs. opinion.
Thanks,
Franco
-
@franco
thanks)
@schnipp
(sorry, i'm not even sure (or rather convinced) that playing with states is the right choice for solving sip problems. perhaps it would be enough to adapt the rules parameters and pbx trunk settings. we could continue the conversation on https://forum.opnsense.org/index.php?topic=8766.0, but my reasoning will remain at the level of theory, since i have nowhere to test them in practice (there is no suitable environment))
-
I've tested the patch. So far the patch works and unbound does not hang on cache-load command any longer.
However, I'm not sure if we get any kind of side effects with this patch.
Interestingly, during my testing I figured out that I don't need the setting "Reset all states when a dynamic IP address changes" any longer. Historically, I had enabled this option to avoid any stale states which would lead to problems with my VoIP setup. I completely missed out that since OPNsense 21.1 WAN IP address changes are detected by rc.newwanip script and that states of the outdated IP will be removed from the state stable.
Regarding state killing I would like to add some more findings and suggestions in this thread https://forum.opnsense.org/index.php?topic=8766.0 (https://forum.opnsense.org/index.php?topic=8766.0).
-
I've tested the patch. So far the patch works and unbound does not hang on cache-load command any longer.
glad it works
However, I'm not sure if we get any kind of side effects with this patch
actually i would try to replace this rule with:
set skip on { lo0 }can’t think of any side effects from this yet.
just save resources on rules evaluations\states lookup and preserving internal communications when "all" states are reset.
@franco, what do you say to that?)
Regarding state killing I would like to add some more findings
it would be interesting
-
(sorry, i'm not even sure (or rather convinced) that playing with states is the right choice for solving sip problems. perhaps it would be enough to adapt the rules parameters and pbx trunk settings.
State reset has nothing to do with SIP. The connection problems ragarding SIP reported by my Fritzbox were only the trigger to start investigation. The issue itself resides at OSI Layer 3 and 4, thus all protocols on top of the transport layer are affected. The impact on classic HTTP connections is mainly unnoticed because such connections are often short lived due to omitted keep-alive during request-reply communication. Furthermore, in case of a timeout web browsers initiate new TCP connections which does not hit an invalid NAPT table entry because of dynamic source port selection.
we could continue the conversation on https://forum.opnsense.org/index.php?topic=8766.0, but my reasoning will remain at the level of theory, since i have nowhere to test them in practice (there is no suitable environment))
In my eyes we should start a new thread regarding the state reset discussion, but I'll have a look at it.
Let's please discuss patch vs. patch, not patch vs. opinion.
Of course, I fully agree. :)
-
Loopback rule was added for Squid which does IPv6 loopback communication with itself, which was broken by IPv6 block rule setting. Wether state is tracked or not is hardly relevant. It might only indicate the unbound-control is not fully capable of recovering...
Cheers,
Franco
-
@franco
unbound-control is not fully capable of recovering
looks like that. I just can't figure out why this should hangs up the unbound itself...
so what's the verdict?)
-move system_hosts_generate() call to the end of rc.newwanip?
-make "pass loopback" stateless?
-switch to "set skip on { lo0 }"?
-get rid of "ip_change_kill_states"? ;)
-
@franco
unbound-control is not fully capable of recovering
looks like that. I just can't figure out why this should hangs up the unbound itself...
It's only my assumption. It looks like unbound-control is faulty and has secondarily disclosed a bug in opnsense (as we are discussing). Normally, the tcp socket of unbound-control should run into a timeout. In this case the function of the caller either returns with an error code or the process gets singnaled by the kernel when the calling function is a blocking one. But unbound-control seems to hang infinitely.
-
State reset has nothing to do with SIP. The connection problems ragarding SIP reported by my Fritzbox were only the trigger to start investigation. The issue itself resides at OSI Layer 3 and 4, thus all protocols on top of the transport layer are affected. The impact on classic HTTP connections is mainly unnoticed because such connections are often short lived due to omitted keep-alive during request-reply communication.
The last sentence is wrong.
According to HTTP RFC, there is no need to specify "keep-alive" for HTTP/1.1 clients. Connection are always "keep-alive" unless marked with "close".
See https://datatracker.ietf.org/doc/html/rfc7230#section-6.3
HTTP/2 and later use another technique, but the result is the same: connections are persistent.
-
The last sentence is wrong.
According to HTTP RFC, there is no need to specify "keep-alive" for HTTP/1.1 clients. Connection are always "keep-alive" unless marked with "close".
Yes, it looks like there has been a change in the default value of this option. Thanks for this information. But, your argumentation is a little petty. The server still determines how long the connection is kept open. Modern Apache servers have a default value of 5 seconds. I did some tests (except the big CDN, and most of these sites closed the connection after 5 till 25 seconds of inactivity). Thus, this is still "short lived" :)
-
The last sentence is wrong.
According to HTTP RFC, there is no need to specify "keep-alive" for HTTP/1.1 clients. Connection are always "keep-alive" unless marked with "close".
Yes, it looks like there has been a change in the default value of this option. Thanks for this information. But, your argumentation is a little petty. The server still determines how long the connection is kept open. Modern Apache servers have a default value of 5 seconds. I did some tests (except the big CDN, and most of these sites closed the connection after 5 till 25 seconds of inactivity). Thus, this is still "short lived" :)
My note was only about HTTP defaults.
HTTP connections could be long-lived (if you downloading something huge) or short-lived (if you just open a web-page).
-
Raised github ticket: https://github.com/opnsense/core/issues/5367 (https://github.com/opnsense/core/issues/5367)