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 DNSBL

    Oct 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 with

    2.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-p16

    And 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