pfSense Support Subscription

Author Topic: unbound error with 2.3.3.a.20161028.0718 & 2.3.3.a.20161029.1001  (Read 1849 times)

0 Members and 1 Guest are viewing this topic.

Offline RonpfS

  • Hero Member
  • *****
  • Posts: 684
  • Karma: +96/-2
    • View Profile
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

Code: [Select]
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

Code: [Select]
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.

2.3.5-RELEASE (amd64)
Intel Core2 Quad CPU Q8400 @ 2.66GHz 8GB
pfBlockerNG 2.1.2_1/Dev, suricata 4.0.1

Offline RonpfS

  • Hero Member
  • *****
  • Posts: 684
  • Karma: +96/-2
    • View Profile
Re: unbound error with 2.3.3.a.20161028.0718 & 2.3.3.a.20161029.1001
« Reply #1 on: November 09, 2016, 01:31:59 pm »
error: cannot chdir to directory: (No such file or directory)
Problem still persist with
Code: [Select]
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.
« Last Edit: November 09, 2016, 02:12:22 pm by RonpfS »
2.3.5-RELEASE (amd64)
Intel Core2 Quad CPU Q8400 @ 2.66GHz 8GB
pfBlockerNG 2.1.2_1/Dev, suricata 4.0.1

Offline phil.davis

  • Hero Member
  • *****
  • Posts: 4612
  • Karma: +550/-3
    • View Profile
    • International Nepal Fellowship
Re: unbound error with 2.3.3.a.20161028.0718 & 2.3.3.a.20161029.1001
« Reply #2 on: November 10, 2016, 03:30:54 pm »
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.
As the Greek philosopher Isosceles used to say, "There are 3 sides to every triangle."
If I helped you, then help someone else - buy someone a gift from the INF catalog http://secure.inf.org/gifts/usd/

Offline RonpfS

  • Hero Member
  • *****
  • Posts: 684
  • Karma: +96/-2
    • View Profile
Re: unbound error with 2.3.3.a.20161028.0718 & 2.3.3.a.20161029.1001
« Reply #3 on: November 10, 2016, 03:38:11 pm »
I don't follow 2.4 as my FW is I386  :-[

One odd thing is the 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.
2.3.5-RELEASE (amd64)
Intel Core2 Quad CPU Q8400 @ 2.66GHz 8GB
pfBlockerNG 2.1.2_1/Dev, suricata 4.0.1

Offline phil.davis

  • Hero Member
  • *****
  • Posts: 4612
  • Karma: +550/-3
    • View Profile
    • International Nepal Fellowship
Re: unbound error with 2.3.3.a.20161028.0718 & 2.3.3.a.20161029.1001
« Reply #4 on: November 10, 2016, 03:53:47 pm »
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
As the Greek philosopher Isosceles used to say, "There are 3 sides to every triangle."
If I helped you, then help someone else - buy someone a gift from the INF catalog http://secure.inf.org/gifts/usd/

Offline JorgeOliveira

  • Full Member
  • ***
  • Posts: 153
  • Karma: +24/-1
  • May the Triforce be with you...
    • View Profile
Re: unbound error with 2.3.3.a.20161028.0718 & 2.3.3.a.20161029.1001
« Reply #5 on: November 12, 2016, 04:38:44 pm »
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.
My views have absolutely no warranty express or implied. Always do your own research.

Offline RonpfS

  • Hero Member
  • *****
  • Posts: 684
  • Karma: +96/-2
    • View Profile
Re: unbound error with 2.3.3.a.20161028.0718 & 2.3.3.a.20161029.1001
« Reply #6 on: February 10, 2017, 12:56:35 pm »
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.

Code: [Select]
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).

2.3.5-RELEASE (amd64)
Intel Core2 Quad CPU Q8400 @ 2.66GHz 8GB
pfBlockerNG 2.1.2_1/Dev, suricata 4.0.1

Offline kpa

  • Hero Member
  • *****
  • Posts: 1186
  • Karma: +131/-6
    • View Profile
Re: unbound error with 2.3.3.a.20161028.0718 & 2.3.3.a.20161029.1001
« Reply #7 on: February 10, 2017, 01:07:21 pm »
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?

Offline RonpfS

  • Hero Member
  • *****
  • Posts: 684
  • Karma: +96/-2
    • View Profile
Re: unbound error with 2.3.3.a.20161028.0718 & 2.3.3.a.20161029.1001
« Reply #8 on: February 10, 2017, 01:11:40 pm »
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
« Last Edit: February 10, 2017, 01:20:37 pm by RonpfS »
2.3.5-RELEASE (amd64)
Intel Core2 Quad CPU Q8400 @ 2.66GHz 8GB
pfBlockerNG 2.1.2_1/Dev, suricata 4.0.1