Unbound package - Logging
-
Unbound doesn't seem as stable as a package. The package doesn't work on a 32-bit test box but works for the most part on a 64-bit production box if I ignore the unbound service restarts that happen at least once a day. To better understand why they're so different, I thought making comparisons between the unbound package and the stand-alone unbound service would be helpful in reaching a solution. It's called moaning now?
2014-01-26 06:37:53 Daemon.Info 192.168.2.1 Jan 26 06:37:53 unbound: [63663:0] info: service stopped (unbound 1.4.20). 2014-01-26 06:37:54 Daemon.Info 192.168.2.1 Jan 26 06:37:54 unbound: [63663:0] info: server stats for thread 0: 649 queries, 232 answers from cache, 417 recursions, 16 prefetch 2014-01-26 06:37:54 Daemon.Info 192.168.2.1 Jan 26 06:37:54 unbound: [63663:0] info: server stats for thread 0: requestlist max 11 avg 1.31409 exceeded 0 jostled 0 2014-01-26 06:37:54 Daemon.Info 192.168.2.1 Jan 26 06:37:54 unbound: [63663:0] info: average recursion processing time 0.082272 sec 2014-01-26 06:37:54 Daemon.Info 192.168.2.1 Jan 26 06:37:54 unbound: [63663:0] info: histogram of recursion processing times 2014-01-26 06:37:54 Daemon.Info 192.168.2.1 Jan 26 06:37:54 unbound: [63663:0] info: [25%]=0.025671 median[50%]=0.0479013 [75%]=0.0966887 2014-01-26 06:37:54 Daemon.Info 192.168.2.1 Jan 26 06:37:54 unbound: [63663:0] info: lower(secs) upper(secs) recursions 2014-01-26 06:37:54 Daemon.Info 192.168.2.1 Jan 26 06:37:54 unbound: [63663:0] info: 0.000000 0.000001 46 2014-01-26 06:37:54 Daemon.Info 192.168.2.1 Jan 26 06:37:54 unbound: [63663:0] info: 0.001024 0.002048 1 2014-01-26 06:37:54 Daemon.Info 192.168.2.1 Jan 26 06:37:54 unbound: [63663:0] info: 0.016384 0.032768 101 2014-01-26 06:37:54 Daemon.Info 192.168.2.1 Jan 26 06:37:54 unbound: [63663:0] info: 0.032768 0.065536 131 2014-01-26 06:37:54 Daemon.Info 192.168.2.1 Jan 26 06:37:54 unbound: [63663:0] info: 0.065536 0.131072 71 2014-01-26 06:37:54 Daemon.Info 192.168.2.1 Jan 26 06:37:54 unbound: [63663:0] info: 0.131072 0.262144 37 2014-01-26 06:37:54 Daemon.Info 192.168.2.1 Jan 26 06:37:54 unbound: [63663:0] info: 0.262144 0.524288 25 2014-01-26 06:37:54 Daemon.Info 192.168.2.1 Jan 26 06:37:54 unbound: [63663:0] info: 0.524288 1.000000 5 2014-01-26 06:37:54 Daemon.Info 192.168.2.1 Jan 26 06:37:54 unbound: [63663:0] info: server stats for thread 1: 139 queries, 48 answers from cache, 91 recursions, 4 prefetch 2014-01-26 06:37:54 Daemon.Info 192.168.2.1 Jan 26 06:37:54 unbound: [63663:0] info: server stats for thread 1: requestlist max 5 avg 0.410526 exceeded 0 jostled 0 2014-01-26 06:37:54 Daemon.Info 192.168.2.1 Jan 26 06:37:54 unbound: [63663:0] info: average recursion processing time 0.094866 sec 2014-01-26 06:37:54 Daemon.Info 192.168.2.1 Jan 26 06:37:54 unbound: [63663:0] info: histogram of recursion processing times 2014-01-26 06:37:54 Daemon.Info 192.168.2.1 Jan 26 06:37:54 unbound: [63663:0] info: [25%]=0.0297405 median[50%]=0.0511379 [75%]=0.101581 2014-01-26 06:37:54 Daemon.Info 192.168.2.1 Jan 26 06:37:54 unbound: [63663:0] info: lower(secs) upper(secs) recursions 2014-01-26 06:37:54 Daemon.Info 192.168.2.1 Jan 26 06:37:54 unbound: [63663:0] info: 0.000000 0.000001 4 2014-01-26 06:37:54 Daemon.Info 192.168.2.1 Jan 26 06:37:54 unbound: [63663:0] info: 0.016384 0.032768 23 2014-01-26 06:37:54 Daemon.Info 192.168.2.1 Jan 26 06:37:54 unbound: [63663:0] info: 0.032768 0.065536 33 2014-01-26 06:37:54 Daemon.Info 192.168.2.1 Jan 26 06:37:54 unbound: [63663:0] info: 0.065536 0.131072 15 2014-01-26 06:37:54 Daemon.Info 192.168.2.1 Jan 26 06:37:54 unbound: [63663:0] info: 0.131072 0.262144 6 2014-01-26 06:37:54 Daemon.Info 192.168.2.1 Jan 26 06:37:54 unbound: [63663:0] info: 0.262144 0.524288 9 2014-01-26 06:37:54 Daemon.Info 192.168.2.1 Jan 26 06:37:54 unbound: [63663:0] info: 0.524288 1.000000 1 2014-01-26 06:38:01 User.Error 192.168.2.1 Jan 26 06:38:01 php: servicewatchdog_cron.php: Service Watchdog detected service unbound stopped. Restarting unbound (Unbound is a validating, recursive, and caching DN...) 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: service stopped (unbound 1.4.20). 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: server stats for thread 0: 8980 queries, 3591 answers from cache, 5389 recursions, 285 prefetch 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: server stats for thread 0: requestlist max 13 avg 0.853366 exceeded 0 jostled 0 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: average recursion processing time 0.395473 sec 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: histogram of recursion processing times 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: [25%]=0.0220116 median[50%]=0.0314482 [75%]=0.0603143 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: lower(secs) upper(secs) recursions 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 0.000000 0.000001 504 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 0.000256 0.000512 1 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 0.000512 0.001024 2 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 0.001024 0.002048 3 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 0.002048 0.004096 2 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 0.004096 0.008192 9 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 0.008192 0.016384 23 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 0.016384 0.032768 2340 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 0.032768 0.065536 1379 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 0.065536 0.131072 517 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 0.131072 0.262144 358 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 0.262144 0.524288 169 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 0.524288 1.000000 34 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 1.000000 2.000000 6 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 2.000000 4.000000 5 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 4.000000 8.000000 1 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 16.000000 32.000000 4 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 32.000000 64.000000 31 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 64.000000 128.000000 3 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: server stats for thread 1: 4942 queries, 1892 answers from cache, 3050 recursions, 170 prefetch 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: server stats for thread 1: requestlist max 7 avg 0.408696 exceeded 0 jostled 0 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: average recursion processing time 0.398189 sec 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: histogram of recursion processing times 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: [25%]=0.0222939 median[50%]=0.031751 [75%]=0.0616897 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: lower(secs) upper(secs) recursions 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 0.000000 0.000001 277 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 0.001024 0.002048 1 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 0.002048 0.004096 1 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 0.004096 0.008192 2 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 0.008192 0.016384 5 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 0.016384 0.032768 1321 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 0.032768 0.065536 771 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 0.065536 0.131072 301 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 0.131072 0.262144 230 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 0.262144 0.524288 95 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 0.524288 1.000000 19 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 1.000000 2.000000 4 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 2.000000 4.000000 1 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 16.000000 32.000000 3 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: 32.000000 64.000000 19 2014-01-27 03:31:00 Daemon.Notice pfsense Jan 27 03:31:00 unbound: [2025:0] notice: Restart of unbound 1.4.20. 2014-01-27 03:31:00 Daemon.Warning pfsense Jan 27 03:31:00 unbound: [2025:0] warning: setrlimit: Operation not permitted 2014-01-27 03:31:00 Daemon.Warning pfsense Jan 27 03:31:00 unbound: [2025:0] warning: cannot increase max open fds from 11095 to 16458 2014-01-27 03:31:00 Daemon.Warning pfsense Jan 27 03:31:00 unbound: [2025:0] warning: continuing with less udp ports: 5512 2014-01-27 03:31:00 Daemon.Warning pfsense Jan 27 03:31:00 unbound: [2025:0] warning: increase ulimit or decrease threads, ports in config to remove this warning 2014-01-27 03:31:00 Daemon.Notice pfsense Jan 27 03:31:00 unbound: [2025:0] notice: init module 0: validator 2014-01-27 03:31:00 Daemon.Notice pfsense Jan 27 03:31:00 unbound: [2025:0] notice: init module 1: iterator 2014-01-27 03:31:00 Daemon.Info pfsense Jan 27 03:31:00 unbound: [2025:0] info: start of service (unbound 1.4.20). 2014-01-27 11:32:13 Daemon.Info pfsense Jan 27 11:32:14 unbound: [2025:0] info: service stopped (unbound 1.4.20). 2014-01-27 11:32:14 Daemon.Info pfsense Jan 27 11:32:14 unbound: [2025:0] info: server stats for thread 0: 68 queries, 20 answers from cache, 48 recursions, 4 prefetch 2014-01-27 11:32:14 Daemon.Info pfsense Jan 27 11:32:14 unbound: [2025:0] info: server stats for thread 0: requestlist max 2 avg 0.173077 exceeded 0 jostled 0 2014-01-27 11:32:14 Daemon.Info pfsense Jan 27 11:32:14 unbound: [2025:0] info: average recursion processing time 0.067424 sec 2014-01-27 11:32:14 Daemon.Info pfsense Jan 27 11:32:14 unbound: [2025:0] info: histogram of recursion processing times 2014-01-27 11:32:14 Daemon.Info pfsense Jan 27 11:32:14 unbound: [2025:0] info: [25%]=0.0227556 median[50%]=0.0352886 [75%]=0.065536 2014-01-27 11:32:14 Daemon.Info pfsense Jan 27 11:32:14 unbound: [2025:0] info: lower(secs) upper(secs) recursions 2014-01-27 11:32:14 Daemon.Info pfsense Jan 27 11:32:14 unbound: [2025:0] info: 0.000000 0.000001 5 2014-01-27 11:32:14 Daemon.Info pfsense Jan 27 11:32:14 unbound: [2025:0] info: 0.016384 0.032768 18 2014-01-27 11:32:14 Daemon.Info pfsense Jan 27 11:32:14 unbound: [2025:0] info: 0.032768 0.065536 13 2014-01-27 11:32:14 Daemon.Info pfsense Jan 27 11:32:14 unbound: [2025:0] info: 0.065536 0.131072 5 2014-01-27 11:32:14 Daemon.Info pfsense Jan 27 11:32:14 unbound: [2025:0] info: 0.131072 0.262144 5 2014-01-27 11:32:14 Daemon.Info pfsense Jan 27 11:32:14 unbound: [2025:0] info: 0.262144 0.524288 2 2014-01-27 11:32:14 Daemon.Info pfsense Jan 27 11:32:14 unbound: [2025:0] info: server stats for thread 1: 664 queries, 209 answers from cache, 455 recursions, 22 prefetch 2014-01-27 11:32:14 Daemon.Info pfsense Jan 27 11:32:14 unbound: [2025:0] info: server stats for thread 1: requestlist max 7 avg 1.01258 exceeded 0 jostled 0 2014-01-27 11:32:14 Daemon.Info pfsense Jan 27 11:32:14 unbound: [2025:0] info: average recursion processing time 0.074148 sec 2014-01-27 11:32:14 Daemon.Info pfsense Jan 27 11:32:14 unbound: [2025:0] info: histogram of recursion processing times 2014-01-27 11:32:14 Daemon.Info pfsense Jan 27 11:32:14 unbound: [2025:0] info: [25%]=0.0253615 median[50%]=0.0431843 [75%]=0.0786432 2014-01-27 11:32:14 Daemon.Info pfsense Jan 27 11:32:14 unbound: [2025:0] info: lower(secs) upper(secs) recursions 2014-01-27 11:32:14 Daemon.Info pfsense Jan 27 11:32:14 unbound: [2025:0] info: 0.000000 0.000001 32 2014-01-27 11:32:14 Daemon.Info pfsense Jan 27 11:32:14 unbound: [2025:0] info: 0.002048 0.004096 1 2014-01-27 11:32:14 Daemon.Info pfsense Jan 27 11:32:14 unbound: [2025:0] info: 0.008192 0.016384 1 2014-01-27 11:32:14 Daemon.Info pfsense Jan 27 11:32:14 unbound: [2025:0] info: 0.016384 0.032768 146 2014-01-27 11:32:14 Daemon.Info pfsense Jan 27 11:32:14 unbound: [2025:0] info: 0.032768 0.065536 151 2014-01-27 11:32:14 Daemon.Info pfsense Jan 27 11:32:14 unbound: [2025:0] info: 0.065536 0.131072 55 2014-01-27 11:32:14 Daemon.Info pfsense Jan 27 11:32:14 unbound: [2025:0] info: 0.131072 0.262144 45 2014-01-27 11:32:14 Daemon.Info pfsense Jan 27 11:32:14 unbound: [2025:0] info: 0.262144 0.524288 20 2014-01-27 11:32:14 Daemon.Info pfsense Jan 27 11:32:14 unbound: [2025:0] info: 0.524288 1.000000 5 2014-01-27 11:32:16 Daemon.Notice pfsense Jan 27 11:32:16 unbound: [95251:0] notice: init module 0: validator 2014-01-27 11:32:16 Daemon.Notice pfsense Jan 27 11:32:16 unbound: [95251:0] notice: init module 1: iterator 2014-01-27 11:32:16 Daemon.Info pfsense Jan 27 11:32:16 unbound: [95251:0] info: start of service (unbound 1.4.20). -
It seems too work for a lot of other users, granted they may not be configuring all the settings and fine tuning the knobs like your installation.
Its called 'moaning' because you go on a tangent about how its dumbed down, the package assumes too much by pre-configuring certain settings, how some settings don't work and getting existing packages working first before embarking on developing new packages. But yet provide nothing useful in terms of bugs logged nor patches.
Thanks though for the information that you have provided so far in this thread. As for the pre-configured settings which ones are incorrect? They were done right in the beginning of the package so some adjustments may be needed.
-
Sorry for using the term "dumbed down" rather than "simplified for new users", I suppose that sounds better. I would log bugs and patches if I understood the process. I've been using PfSense for about 5 months now so I'm a relatively new user.
On this issue I initially suggested that all native unbound commands be recognized by the GUI custom entry box such that they override the GUI setttings. Or if this is unacceptable, at least allow custom commands that are not configurable via the GUI. I could test every unbound command to see if it keeps the service from starting but that would take about a day. I'm sure someone more familiar could generate a list in a few minutes.
The bigger question is, "what's the goal"? What can and can't be done with the unbound package script. So far I'm seeing more interest in using command parameters to generate other command parameters. In other words, a continuation to keep it simple and automated, rather than improving the ability to troubleshoot performance issues should they arise. Maybe you can explain why the native commands weren't included in the package. Is it just the time and effort to provide features that may get little use?
As someone who had been using a stand-alone unbound service with only a script, surely you would expect some moaning when most of the script settings were rejected by PfSense. It would have been nice to drop in a well tested and stable script rather than use the automated package that restarts now and then. I may go back to a stand-alone service if I can't resolve the restarts.
Are there other 64-bit users seeing their unbound package perform unattended restarts? No idea how to troubleshoot this especially with many of the commands unrecognized. Fortunately the service restarts fairly quick so it doesn't seem to cause much disruption. However with each occurance the cache is cleared and has to begin rebuilding when the service starts making the package less effective. I don't save the cache because of the SSD and it adds too much time to a PfSense reboot.
Copyright 2025 Rubicon Communications LLC (Netgate). All rights reserved.