Unbound error with 2.3.3.a.20161028.0718 & 2.3.3.a.20161029.1001
-
Yesterday I went from 2.3.3.a.20161005.2017 to 2.3.3.a.20161028.0718, I got 2 new errors. Today I went to 2.3.3.a.20161029.1001, same errors.
One is from unbound error: cannot chdir to directory: (No such file or directory)
This is the log from the latest snapshot 2.3.3.a.20161029.1001:
Reboot, Restart unbound (to get it to log reloads), start pfBlockerNG DNSBLOct 29 13:38:10 unbound 72932:0 info: start of service (unbound 1.5.10). Oct 29 13:38:10 unbound 72932:0 notice: init module 1: iterator Oct 29 13:38:10 unbound 72932:0 notice: init module 0: validator Oct 29 13:37:30 unbound 72932:0 error: cannot chdir to directory: (No such file or directory) Oct 29 13:37:30 unbound 72932:0 notice: Restart of unbound 1.5.10. Oct 29 13:37:30 unbound 72932:0 info: 1.000000 2.000000 1 Oct 29 13:37:30 unbound 72932:0 info: 0.262144 0.524288 1 Oct 29 13:37:30 unbound 72932:0 info: 0.131072 0.262144 1 Oct 29 13:37:30 unbound 72932:0 info: 0.065536 0.131072 3 Oct 29 13:37:30 unbound 72932:0 info: 0.032768 0.065536 1 Oct 29 13:37:30 unbound 72932:0 info: 0.016384 0.032768 1 Oct 29 13:37:30 unbound 72932:0 info: 0.000000 0.000001 1 Oct 29 13:37:30 unbound 72932:0 info: lower(secs) upper(secs) recursions Oct 29 13:37:30 unbound 72932:0 info: [25%]=0.04096 median[50%]=0.098304 [75%]=0.229376 Oct 29 13:37:30 unbound 72932:0 info: histogram of recursion processing times Oct 29 13:37:30 unbound 72932:0 info: average recursion processing time 0.221956 sec Oct 29 13:37:30 unbound 72932:0 info: server stats for thread 1: requestlist max 3 avg 0.777778 exceeded 0 jostled 0 Oct 29 13:37:30 unbound 72932:0 info: server stats for thread 1: 17 queries, 8 answers from cache, 9 recursions, 0 prefetch Oct 29 13:37:30 unbound 72932:0 info: 0.524288 1.000000 1 Oct 29 13:37:30 unbound 72932:0 info: 0.262144 0.524288 2 Oct 29 13:37:30 unbound 72932:0 info: 0.131072 0.262144 2 Oct 29 13:37:30 unbound 72932:0 info: 0.065536 0.131072 4 Oct 29 13:37:30 unbound 72932:0 info: 0.032768 0.065536 2 Oct 29 13:37:30 unbound 72932:0 info: 0.016384 0.032768 1 Oct 29 13:37:30 unbound 72932:0 info: 0.000000 0.000001 2 Oct 29 13:37:30 unbound 72932:0 info: lower(secs) upper(secs) recursions Oct 29 13:37:30 unbound 72932:0 info: [25%]=0.04096 median[50%]=0.098304 [75%]=0.229376 Oct 29 13:37:30 unbound 72932:0 info: histogram of recursion processing times Oct 29 13:37:30 unbound 72932:0 info: average recursion processing time 0.182787 sec Oct 29 13:37:30 unbound 72932:0 info: server stats for thread 0: requestlist max 1 avg 0.357143 exceeded 0 jostled 0 Oct 29 13:37:30 unbound 72932:0 info: server stats for thread 0: 32 queries, 18 answers from cache, 14 recursions, 0 prefetch Oct 29 13:37:30 unbound 72932:0 info: service stopped (unbound 1.5.10). Oct 29 13:33:52 unbound 72932:0 info: start of service (unbound 1.5.10). Oct 29 13:33:52 unbound 72932:0 notice: init module 1: iterator Oct 29 13:33:52 unbound 72932:0 notice: init module 0: validator Oct 29 13:32:44 unbound 22812:0 info: start of service (unbound 1.5.10). Oct 29 13:32:43 unbound 22812:0 notice: init module 1: iterator Oct 29 13:32:43 unbound 22812:0 notice: init module 0: validator Oct 29 13:25:19 unbound 76730:0 info: start of service (unbound 1.5.10). Oct 29 13:25:19 unbound 76730:0 notice: init module 1: iterator Oct 29 13:25:19 unbound 76730:0 notice: init module 0: validator Oct 29 13:25:19 unbound 76730:0 error: cannot chdir to directory: (No such file or directory) Oct 29 13:25:19 unbound 76730:0 notice: Restart of unbound 1.5.10. Oct 29 13:25:19 unbound 76730:0 info: 1.000000 2.000000 3 Oct 29 13:25:19 unbound 76730:0 info: 0.524288 1.000000 15 Oct 29 13:25:19 unbound 76730:0 info: 0.262144 0.524288 36 Oct 29 13:25:19 unbound 76730:0 info: 0.131072 0.262144 45 Oct 29 13:25:19 unbound 76730:0 info: 0.065536 0.131072 35 Oct 29 13:25:19 unbound 76730:0 info: 0.032768 0.065536 32 Oct 29 13:25:19 unbound 76730:0 info: 0.016384 0.032768 52 Oct 29 13:25:19 unbound 76730:0 info: 0.000000 0.000001 7 Oct 29 13:25:19 unbound 76730:0 info: lower(secs) upper(secs) recursions Oct 29 13:25:19 unbound 76730:0 info: [25%]=0.0319015 median[50%]=0.105794 [75%]=0.25559 Oct 29 13:25:19 unbound 76730:0 info: histogram of recursion processing times Oct 29 13:25:19 unbound 76730:0 info: average recursion processing time 0.189299 sec Oct 29 13:25:19 unbound 76730:0 info: server stats for thread 1: requestlist max 19 avg 0.829876 exceeded 0 jostled 0 Oct 29 13:25:19 unbound 76730:0 info: server stats for thread 1: 851 queries, 626 answers from cache, 225 recursions, 16 prefetch Oct 29 13:25:19 unbound 76730:0 info: 2.000000 4.000000 2 Oct 29 13:25:19 unbound 76730:0 info: 1.000000 2.000000 3 Oct 29 13:25:19 unbound 76730:0 info: 0.524288 1.000000 44 Oct 29 13:25:19 unbound 76730:0 info: 0.262144 0.524288 66 Oct 29 13:25:19 unbound 76730:0 info: 0.131072 0.262144 83 Oct 29 13:25:19 unbound 76730:0 info: 0.065536 0.131072 138 Oct 29 13:25:19 unbound 76730:0 info: 0.032768 0.065536 99 Oct 29 13:25:19 unbound 76730:0 info: 0.016384 0.032768 98 Oct 29 13:25:19 unbound 76730:0 info: 0.008192 0.016384 2 Oct 29 13:25:19 unbound 76730:0 info: 0.004096 0.008192 1 Oct 29 13:25:19 unbound 76730:0 info: 0.000000 0.000001 98 Oct 29 13:25:19 unbound 76730:0 info: lower(secs) upper(secs) recursions Oct 29 13:25:19 unbound 76730:0 info: [25%]=0.0259971 median[50%]=0.0745591 [75%]=0.19345 Oct 29 13:25:19 unbound 76730:0 info: histogram of recursion processing times Oct 29 13:25:19 unbound 76730:0 info: average recursion processing time 0.157708 sec Oct 29 13:25:19 unbound 76730:0 info: server stats for thread 0: requestlist max 28 avg 2.51445 exceeded 0 jostled 0 Oct 29 13:25:19 unbound 76730:0 info: server stats for thread 0: 2749 queries, 2115 answers from cache, 634 recursions, 58 prefetch Oct 29 08:28:44 unbound 76730:0 info: start of service (unbound 1.5.10).
The other is with pfBlockerNG/DNSBL Can't assign requested address
Oct 29 13:38:18 check_reload_status Syncing firewall Oct 29 13:38:17 php-fpm 87487 /pkg_edit.php: The command '/sbin/ifconfig 're0' delete '10.10.10.1'' returned exit code '1', the output was 'ifconfig: ioctl (SIOCDIFADDR): Can't assign requested address' Oct 29 13:38:17 check_reload_status Syncing firewall Oct 29 13:38:16 check_reload_status Syncing firewall Oct 29 13:36:49 php-fpm 87487 [pfBlockerNG] Starting cron process. Oct 29 13:36:22 check_reload_status Syncing firewall Oct 29 13:36:21 php-fpm 14886 /pkg_edit.php: The command '/sbin/ifconfig 're0' delete '10.10.10.1'' returned exit code '1', the output was 'ifconfig: ioctl (SIOCDIFADDR): Can't assign requested address' Oct 29 13:36:20 php-fpm 14886 [pfBlockerNG] Starting cron process. Oct 29 13:36:20 php-fpm 14886 /pkg_edit.php: End of portal.pfsense.org configuration backup (success). Oct 29 13:36:16 php-fpm 14886 /pkg_edit.php: Beginning https://portal.pfsense.org configuration backup. Oct 29 13:32:51 check_reload_status Reloading filter Oct 29 13:32:51 check_reload_status Reloading filter Oct 29 13:32:51 php-fpm 500 /rc.start_packages: The command '/sbin/ifconfig 're0' delete '10.10.10.1'' returned exit code '1', the output was 'ifconfig: ioctl (SIOCDIFADDR): Can't assign requested address' Oct 29 13:32:50 php-fpm 500 [pfBlockerNG] Starting cron process.
-
error: cannot chdir to directory: (No such file or directory)
Problem still persist with2.3.3-DEVELOPMENT (i386) built on Wed Nov 09 08:58:02 CST 2016 FreeBSD 10.3-RELEASE-p12
So is the 2.3.3-DEVELOPMENT branch still active ? I haven't see anythings new in the branch since 2.3.2_p1 was released.
-
I reminded the devs about a couple of items in the last few days that needed to be cherry-picked. Their intention is to continue cherry-picking from master back t RELENG_2_3 for anything that is a fix or obvious/easy change. So 2.3.3-DEVELOPMENT snapshots should have fixed bugs like 2.4-BETA.
If you can point out something fixed in master that is missing from RELENG_2_3, I'm sure they will be happy to back-port it.
-
I don't follow 2.4 as my FW is I386 :-[
One odd thing is the [b]All open issues currently target 2.3.3 in https://forum.pfsense.org/index.php?topic=115852.0 point to https://redmine.pfsense.org/projects/pfsense/issues?query_id=51 and return Error 404.
-
The custom queries on the front redmine page have changed to have mostly ones for 2.4 - so I guess that "query_id=51" no longer exists.
This one says it is 2.3.x All Open Regressions https://redmine.pfsense.org/projects/pfsense/issues?query_id=61 -
Seems like I am going to stick with Oct 27th 0433 snapshot for time being until this is confirmed fixed. Been running it in production with no troubles at all.
-
Updated to:
2.3.3-DEVELOPMENT (i386)
built on Fri Feb 10 07:43:51 CST 2017
FreeBSD 10.3-RELEASE-p16And the error message is still present in the log
This log is from the update to latest DEV @12:25, then I started pfBlockerNG @12:45, followed by a restart of Unbound @13:03, as it doesn't log pfBlockerNG restart after reboot, then I did a Force Reload of pfBlockerNG @13:20.Feb 10 13:23:19 unbound 35968:0 info: start of service (unbound 1.6.0). Feb 10 13:23:19 unbound 35968:0 notice: init module 1: iterator Feb 10 13:23:19 unbound 35968:0 notice: init module 0: validator Feb 10 13:22:59 unbound 35968:0 error: cannot chdir to directory: (No such file or directory) Feb 10 13:22:59 unbound 35968:0 notice: Restart of unbound 1.6.0. Feb 10 13:22:59 unbound 35968:0 info: 4.000000 8.000000 1 Feb 10 13:22:59 unbound 35968:0 info: 2.000000 4.000000 10 Feb 10 13:22:59 unbound 35968:0 info: 1.000000 2.000000 18 Feb 10 13:22:59 unbound 35968:0 info: 0.524288 1.000000 37 Feb 10 13:22:59 unbound 35968:0 info: 0.262144 0.524288 65 Feb 10 13:22:59 unbound 35968:0 info: 0.131072 0.262144 84 Feb 10 13:22:59 unbound 35968:0 info: 0.065536 0.131072 110 Feb 10 13:22:59 unbound 35968:0 info: 0.032768 0.065536 112 Feb 10 13:22:59 unbound 35968:0 info: 0.016384 0.032768 121 Feb 10 13:22:59 unbound 35968:0 info: 0.008192 0.016384 1 Feb 10 13:22:59 unbound 35968:0 info: 0.000000 0.000001 44 Feb 10 13:22:59 unbound 35968:0 info: lower(secs) upper(secs) recursions Feb 10 13:22:59 unbound 35968:0 info: [25%]=0.0307031 median[50%]=0.0795369 [75%]=0.231326 Feb 10 13:22:59 unbound 35968:0 info: histogram of recursion processing times Feb 10 13:22:59 unbound 35968:0 info: average recursion processing time 0.228656 sec Feb 10 13:22:59 unbound 35968:0 info: server stats for thread 1: requestlist max 23 avg 1.54695 exceeded 0 jostled 0 Feb 10 13:22:59 unbound 35968:0 info: server stats for thread 1: 1066 queries, 463 answers from cache, 603 recursions, 4 prefetch Feb 10 13:22:59 unbound 35968:0 info: 1.000000 2.000000 4 Feb 10 13:22:59 unbound 35968:0 info: 0.524288 1.000000 18 Feb 10 13:22:59 unbound 35968:0 info: 0.262144 0.524288 10 Feb 10 13:22:59 unbound 35968:0 info: 0.131072 0.262144 15 Feb 10 13:22:59 unbound 35968:0 info: 0.065536 0.131072 23 Feb 10 13:22:59 unbound 35968:0 info: 0.032768 0.065536 14 Feb 10 13:22:59 unbound 35968:0 info: 0.016384 0.032768 14 Feb 10 13:22:59 unbound 35968:0 info: 0.000000 0.000001 2 Feb 10 13:22:59 unbound 35968:0 info: lower(secs) upper(secs) recursions Feb 10 13:22:59 unbound 35968:0 info: [25%]=0.0538331 median[50%]=0.122524 [75%]=0.445645 Feb 10 13:22:59 unbound 35968:0 info: histogram of recursion processing times Feb 10 13:22:59 unbound 35968:0 info: average recursion processing time 0.285551 sec Feb 10 13:22:59 unbound 35968:0 info: server stats for thread 0: requestlist max 19 avg 1.46535 exceeded 0 jostled 0 Feb 10 13:22:59 unbound 35968:0 info: server stats for thread 0: 317 queries, 217 answers from cache, 100 recursions, 1 prefetch Feb 10 13:22:57 unbound 35968:0 info: service stopped (unbound 1.6.0). Feb 10 13:02:58 unbound 35968:0 info: start of service (unbound 1.6.0). Feb 10 13:02:58 unbound 35968:0 notice: init module 1: iterator Feb 10 13:02:58 unbound 35968:0 notice: init module 0: validator Feb 10 12:39:24 unbound 17016:0 info: start of service (unbound 1.6.0). Feb 10 12:39:23 unbound 17016:0 notice: init module 1: iterator Feb 10 12:39:23 unbound 17016:0 notice: init module 0: validator Feb 10 12:39:12 kernel unbound: 1.5.10 -> 1.6.0 [pfSense] Feb 10 12:28:07 unbound 50228:0 info: start of service (unbound 1.5.10). Feb 10 12:28:07 unbound 50228:0 notice: init module 1: iterator Feb 10 12:28:07 unbound 50228:0 notice: init module 0: validator Feb 10 12:28:07 unbound 50228:0 error: cannot chdir to directory: (No such file or directory) Feb 10 12:28:07 unbound 50228:0 notice: Restart of unbound 1.5.10. Feb 10 12:28:07 unbound 50228:0 info: 4.000000 8.000000 7 Feb 10 12:28:07 unbound 50228:0 info: 2.000000 4.000000 20 Feb 10 12:28:07 unbound 50228:0 info: 1.000000 2.000000 63 Feb 10 12:28:07 unbound 50228:0 info: 0.524288 1.000000 96 Feb 10 12:28:07 unbound 50228:0 info: 0.262144 0.524288 136 Feb 10 12:28:07 unbound 50228:0 info: 0.131072 0.262144 143 Feb 10 12:28:07 unbound 50228:0 info: 0.065536 0.131072 155 Feb 10 12:28:07 unbound 50228:0 info: 0.032768 0.065536 90 Feb 10 12:28:07 unbound 50228:0 info: 0.016384 0.032768 73 Feb 10 12:28:07 unbound 50228:0 info: 0.008192 0.016384 1 Feb 10 12:28:07 unbound 50228:0 info: 0.004096 0.008192 1 Feb 10 12:28:07 unbound 50228:0 info: 0.000000 0.000001 53 Feb 10 12:28:07 unbound 50228:0 info: lower(secs) upper(secs) recursions Feb 10 12:28:07 unbound 50228:0 info: [25%]=0.0624412 median[50%]=0.173235 [75%]=0.478991 Feb 10 12:28:07 unbound 50228:0 info: histogram of recursion processing times Feb 10 12:28:07 unbound 50228:0 info: average recursion processing time 0.407273 sec Feb 10 12:28:07 unbound 50228:0 info: server stats for thread 1: requestlist max 35 avg 1.8479 exceeded 0 jostled 0 Feb 10 12:28:07 unbound 50228:0 info: server stats for thread 1: 1687 queries, 849 answers from cache, 838 recursions, 43 prefetch Feb 10 12:28:07 unbound 50228:0 info: 4.000000 8.000000 6 Feb 10 12:28:07 unbound 50228:0 info: 2.000000 4.000000 18 Feb 10 12:28:07 unbound 50228:0 info: 1.000000 2.000000 20 Feb 10 12:28:07 unbound 50228:0 info: 0.524288 1.000000 34 Feb 10 12:28:07 unbound 50228:0 info: 0.262144 0.524288 33 Feb 10 12:28:07 unbound 50228:0 info: 0.131072 0.262144 54 Feb 10 12:28:07 unbound 50228:0 info: 0.065536 0.131072 45 Feb 10 12:28:07 unbound 50228:0 info: 0.032768 0.065536 28 Feb 10 12:28:07 unbound 50228:0 info: 0.016384 0.032768 15 Feb 10 12:28:07 unbound 50228:0 info: 0.000000 0.000001 12 Feb 10 12:28:07 unbound 50228:0 info: lower(secs) upper(secs) recursions Feb 10 12:28:07 unbound 50228:0 info: [25%]=0.08192 median[50%]=0.209958 [75%]=0.688688 Feb 10 12:28:07 unbound 50228:0 info: histogram of recursion processing times Feb 10 12:28:07 unbound 50228:0 info: average recursion processing time 0.606296 sec Feb 10 12:28:07 unbound 50228:0 info: server stats for thread 0: requestlist max 10 avg 0.538182 exceeded 0 jostled 0 Feb 10 12:28:07 unbound 50228:0 info: server stats for thread 0: 412 queries, 147 answers from cache, 265 recursions, 10 prefetch Feb 10 12:28:05 unbound 50228:0 info: service stopped (unbound 1.5.10). Feb 10 08:25:26 unbound 50228:0 info: start of service (unbound 1.5.10).
-
I'm getting the same error message in the logs but it doesn't prevent unbound from starting on my system. It looks like it's just a cosmetic glitch related to the chroot functionality. Is it a real problem for you or does Unbound work for you properly?
-
In regards to the chdir, it is also present in the 2.4 from what I read https://forum.pfsense.org/index.php?topic=124158.0, but unbound works fine.
In regards to logging restart on reboot, it's just annoying and I restart unbound on each reboot as I don't reboot often.
Another post on the same issue : https://forum.pfsense.org/index.php?topic=123554