Netgate Discussion Forum
    • Categories
    • Recent
    • Tags
    • Popular
    • Users
    • Search
    • Register
    • Login

    DNS Resolver

    Scheduled Pinned Locked Moved
    2.2 Snapshot Feedback and Problems - RETIRED
    44
    186
    127.7k
    Loading More Posts
    • Oldest to Newest
    • Newest to Oldest
    • Most Votes
    Reply
    • Reply as topic
    Log in to reply
    This topic has been deleted. Only users with topic management privileges can see it.
    • H
      hiwi
      last edited by

      @cmb:

      @hiwi:

      Today with build Fri Nov 21 01:58:53 CST 2014 I'm getting again 'fatal error: Could not read config file: /unbound.conf' with DHCP Registration checked.

      Can't seem to replicate that. How is your Unbound configured?

      With version '2.2-BETA (amd64) built on Fri Nov 21 08:16:06 CST 2014' unbound started directly after upgrade. After another reboot it didn't start with DHCP Registration ('Register DHCP leases in the DNS Resolver') on.

      1 Reply Last reply Reply Quote 0
      • C
        cmb
        last edited by

        What's in your resolver log? Re: config, how are all the settings under Services>DNS Resolver configured?

        1 Reply Last reply Reply Quote 0
        • H
          hiwi
          last edited by

          resolver.log

          Nov 21 23:04:26	unbound: [6842:0] fatal error: Could not read config file: /unbound.conf
Nov 21 23:04:26	unbound: [6842:0] info: ignored infra-lame-ttl: 900 (option removed, use infra-host-ttl)
Nov 21 23:04:26	unbound: [6842:0] notice: Restart of unbound 1.4.22.
Nov 21 23:04:26	unbound: [6842:0] debug: cache memory msg=66072 rrset=66072 infra=2600 val=66280
Nov 21 23:04:26	unbound: [6842: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
Nov 21 23:04:26	unbound: [6842:0] info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
Nov 21 23:04:26	unbound: [6842:0] info: server stats for thread 1: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch
Nov 21 23:04:26	unbound: [6842:0] debug: cache memory msg=66072 rrset=66072 infra=2600 val=66280
Nov 21 23:04:26	unbound: [6842: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
Nov 21 23:04:26	unbound: [6842:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
Nov 21 23:04:26	unbound: [6842:0] info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch
Nov 21 23:04:26	unbound: [6842:0] info: service stopped (unbound 1.4.22).
Nov 21 23:04:26	unbound: [6842:0] debug: caught signal SIGHUP
Nov 21 23:04:26	unbound: [6842:1] debug: cache memory msg=66072 rrset=66072 infra=2600 val=66280
Nov 21 23:04:26	unbound: [6842:0] info: start of service (unbound 1.4.22).
Nov 21 23:04:26	unbound: [6842:0] debug: cache memory msg=66072 rrset=66072 infra=2600 val=66280
Nov 21 23:04:26	unbound: [6842:0] debug: target fetch policy for level 4 is 0
Nov 21 23:04:26	unbound: [6842:0] debug: target fetch policy for level 3 is 0
Nov 21 23:04:26	unbound: [6842:0] debug: target fetch policy for level 2 is 1
Nov 21 23:04:26	unbound: [6842:0] debug: target fetch policy for level 1 is 2
Nov 21 23:04:26	unbound: [6842:0] debug: target fetch policy for level 0 is 3
Nov 21 23:04:26	unbound: [6842:0] notice: init module 1: iterator
Nov 21 23:04:26	unbound: [6842:0] notice: init module 0: validator
Nov 21 23:04:26	unbound: [6842:0] debug: module config: "validator iterator"
Nov 21 23:04:26	unbound: [6842:0] debug: duplicate acl address ignored.
Nov 21 23:04:26	unbound: [6842:0] debug: drop user privileges, run as unbound
Nov 21 23:04:26	unbound: [6842:0] debug: chroot to /var/unbound
Nov 21 23:04:26	unbound: [6842:0] debug: chdir to /var/unbound
Nov 21 23:04:25	unbound: [87880:0] debug: switching log to stderr
Nov 21 23:04:25	unbound: [87880:0] debug: cache memory msg=66072 rrset=66072 infra=288782 val=149925
Nov 21 23:04:25	unbound: [87880:0] info: 1.000000 2.000000 7
Nov 21 23:04:25	unbound: [87880:0] info: 0.524288 1.000000 21
Nov 21 23:04:25	unbound: [87880:0] info: 0.262144 0.524288 62
Nov 21 23:04:25	unbound: [87880:0] info: 0.131072 0.262144 100
Nov 21 23:04:25	unbound: [87880:0] info: 0.065536 0.131072 50
Nov 21 23:04:25	unbound: [87880:0] info: 0.032768 0.065536 83
Nov 21 23:04:25	unbound: [87880:0] info: 0.016384 0.032768 176
Nov 21 23:04:25	unbound: [87880:0] info: 0.008192 0.016384 27
Nov 21 23:04:25	unbound: [87880:0] info: 0.004096 0.008192 1
Nov 21 23:04:25	unbound: [87880:0] info: 0.000000 0.000001 37
Nov 21 23:04:25	unbound: [87880:0] info: lower(secs) upper(secs) recursions
Nov 21 23:04:25	unbound: [87880:0] info: [25%]=0.0234589 median[50%]=0.0489546 [75%]=0.195297
Nov 21 23:04:25	unbound: [87880:0] info: histogram of recursion processing times
Nov 21 23:04:25	unbound: [87880:0] info: average recursion processing time 0.139959 sec
Nov 21 23:04:25	unbound: [87880:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 564 recursion replies sent, 0 replies dropped, 0 states jostled out
Nov 21 23:04:25	unbound: [87880:0] info: server stats for thread 1: requestlist max 14 avg 0.603774 exceeded 0 jostled 0
Nov 21 23:04:25	unbound: [87880:0] info: server stats for thread 1: 1688 queries, 1124 answers from cache, 564 recursions, 178 prefetch
Nov 21 23:04:25	unbound: [87880:0] debug: cache memory msg=66072 rrset=66072 infra=288782 val=149925
Nov 21 23:04:25	unbound: [87880:0] info: 1.000000 2.000000 1
Nov 21 23:04:25	unbound: [87880:0] info: 0.524288 1.000000 14
Nov 21 23:04:25	unbound: [87880:0] info: 0.262144 0.524288 30
Nov 21 23:04:25	unbound: [87880:0] info: 0.131072 0.262144 42
Nov 21 23:04:25	unbound: [87880:0] info: 0.065536 0.131072 28
Nov 21 23:04:25	unbound: [87880:0] info: 0.032768 0.065536 39
Nov 21 23:04:25	unbound: [87880:0] info: 0.016384 0.032768 52
Nov 21 23:04:25	unbound: [87880:0] info: 0.008192 0.016384 13
Nov 21 23:04:25	unbound: [87880:0] info: 0.004096 0.008192 1
Nov 21 23:04:25	unbound: [87880:0] info: 0.000000 0.000001 18
Nov 21 23:04:25	unbound: [87880:0] info: lower(secs) upper(secs) recursions
Nov 21 23:04:25	unbound: [87880:0] info: [25%]=0.0250486 median[50%]=0.0621752 [75%]=0.216893
Nov 21 23:04:25	unbound: [87880:0] info: histogram of recursion processing times
Nov 21 23:04:25	unbound: [87880:0] info: average recursion processing time 0.147787 sec
Nov 21 23:04:25	unbound: [87880:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 238 recursion replies sent, 0 replies dropped, 0 states jostled out
Nov 21 23:04:25	unbound: [87880:0] info: server stats for thread 0: requestlist max 40 avg 3.168 exceeded 0 jostled 0
Nov 21 23:04:25	unbound: [87880:0] info: server stats for thread 0: 548 queries, 310 answers from cache, 238 recursions, 12 prefetch
Nov 21 23:04:25	unbound: [87880:0] info: service stopped (unbound 1.4.22).
Nov 21 23:04:25	unbound: [87880:0] debug: caught signal SIGTERM
Nov 21 23:04:23	unbound: [87880:1] debug: cache memory msg=418824 rrset=714129 infra=288782 val=149925
Nov 21 23:04:23	unbound: [87880:1] info: validator operate: query cl4appf.com. A IN
Nov 21 23:04:23	unbound: [87880:1] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone
Nov 21 23:04:23	unbound: [87880:1] info: finishing processing for cl4appf.com. A IN
Nov 21 23:04:23	unbound: [87880:1] info: query response was ANSWER
Nov 21 23:04:23	unbound: [87880:1] info: reply from <cl4appf.com.> 78.140.168.56#53
Nov 21 23:04:23	unbound: [87880:1] info: response for cl4appf.com. A IN
Nov 21 23:04:23	unbound: [87880:1] info: sanitize: storing potential poison RRset: ns2.dcrmt.net. A IN
Nov 21 23:04:23	unbound: [87880:1] info: sanitize: storing potential poison RRset: ns1.dcrmt.net. A IN
Nov 21 23:04:23	unbound: [87880:1] info: iterator operate: query cl4appf.com. A IN
Nov 21 23:04:23	unbound: [87880:1] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
Nov 21 23:04:23	unbound: [87880:1] debug: cache memory msg=418824 rrset=714129 infra=288782 val=149925
Nov 21 23:04:23	unbound: [87880:1] info: Verified that unsigned response is INSECURE
Nov 21 23:04:23	unbound: [87880:1] info: validator operate: query cl4appf.com. AAAA IN
Nov 21 23:04:23	unbound: [87880:1] debug: validator[module 0] operate: extstate:module_wait_subquery event:module_event_pass
Nov 21 23:04:23	unbound: [87880:1] info: NSEC3s for the referral proved no DS.
Nov 21 23:04:23	unbound: [87880:1] info: validator operate: query cl4appf.com. DS IN
Nov 21 23:04:23	unbound: [87880:1] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone
Nov 21 23:04:23	unbound: [87880:1] info: finishing processing for cl4appf.com. DS IN
Nov 21 23:04:23	unbound: [87880:1] info: query response was nodata ANSWER
Nov 21 23:04:23	unbound: [87880:1] info: reply from <com.> 2001:503:a83e::2:30#53
Nov 21 23:04:23	unbound: [87880:1] info: response for cl4appf.com. DS IN
Nov 21 23:04:23	unbound: [87880:1] info: iterator operate: query cl4appf.com. DS IN
Nov 21 23:04:23	unbound: [87880:1] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
Nov 21 23:04:23	unbound: [87880:1] debug: cache memory msg=418824 rrset=714129 infra=288782 val=149925
Nov 21 23:04:23	unbound: [87880:1] debug: sending to target: <com.> 2001:503:a83e::2:30#53
Nov 21 23:04:23	unbound: [87880:1] info: sending query: cl4appf.com. DS IN
Nov 21 23:04:23	unbound: [87880:1] info: processQueryTargets: cl4appf.com. DS IN
Nov 21 23:04:23	unbound: [87880:1] info: resolving (init part 3): cl4appf.com. DS IN
Nov 21 23:04:23	unbound: [87880:1] info: resolving (init part 2): cl4appf.com. DS IN
Nov 21 23:04:23	unbound: [87880:1] info: resolving cl4appf.com. DS IN
Nov 21 23:04:23	unbound: [87880:1] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass
Nov 21 23:04:23	unbound: [87880:1] info: validator operate: query cl4appf.com. DS IN</com.></com.></cl4appf.com.>

          system.log

          Nov 21 23:04:26 zh01-rt02 dhcpleases: Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.
Nov 21 23:04:27 zh01-rt02 dhcpleases: Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.
Nov 21 23:04:29 zh01-rt02 dhcpleases: Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.
Nov 21 23:04:29 zh01-rt02 dhcpleases: kqueue error: unkown
Nov 21 23:04:29 zh01-rt02 dhcpleases: Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.

          Image with options is attached.

          ![Screenshot 2014-11-21 23.10.46.gif](/public/imported_attachments/1/Screenshot 2014-11-21 23.10.46.gif)
          ![Screenshot 2014-11-21 23.10.46.gif_thumb](/public/imported_attachments/1/Screenshot 2014-11-21 23.10.46.gif_thumb)

          1 Reply Last reply Reply Quote 0
          • D
            DiskWizard
            last edited by

            2.2-BETA (amd64)
            built on Sat Nov 22 01:52:19 CST 2014
            FreeBSD 10.1-RELEASE

            After today's upgrade Resolver "went to sleep", had to switch for DNS Forwarder.

            Oct 28 14:12:42 unbound: [23277:3] notice: sendto failed: No buffer space available

            I know, the date is wrong.

            1. GA-N3150M-D3P 8Gb RAM

            2. GA-C1037EN-EU 4GB RAM

            • 2,5 SATA III Solid State Drive SLIM S60
            1 Reply Last reply Reply Quote 0
            • C
              cmb
              last edited by

              @hiwi:

              Today with build Fri Nov 21 01:58:53 CST 2014 I'm getting again 'fatal error: Could not read config file: /unbound.conf' with DHCP Registration checked.

              That seems to be fixed after merging a pull request from wagonza yesterday. I found one system where I could replicate that, and after that change, I no longer could. There is a bug ticket on that issue. https://redmine.pfsense.org/issues/4036

              Others who could replicate that, are you seeing it on snapshots from the 23rd or newer?

              1 Reply Last reply Reply Quote 0
              • H
                hiwi
                last edited by

                @cmb:

                That seems to be fixed after merging a pull request from wagonza yesterday. I found one system where I could replicate that, and after that change, I no longer could. There is a bug ticket on that issue. https://redmine.pfsense.org/issues/4036

                Others who could replicate that, are you seeing it on snapshots from the 23rd or newer?

                The latest snapshot I can get is 'Sat Nov 22 01:52:19 CST 2014'.

                1 Reply Last reply Reply Quote 0
                • H
                  hiwi
                  last edited by

                  @cmb:

                  That seems to be fixed after merging a pull request from wagonza yesterday. I found one system where I could replicate that, and after that change, I no longer could. There is a bug ticket on that issue. https://redmine.pfsense.org/issues/4036

                  Others who could replicate that, are you seeing it on snapshots from the 23rd or newer?

                  With snapshot 'Mon Nov 24 02:33:34 CST 2014' my unbound problem is gone.

                  Thank You!

                  1 Reply Last reply Reply Quote 0
                  • H
                    Hugovsky
                    last edited by

                    Seems solved. It starts normally now.

                    2.2-BETA (amd64)
                    built on Mon Nov 24 02:33:34 CST 2014
                    FreeBSD 10.1-RELEASE

                    1 Reply Last reply Reply Quote 0
                    • H
                      Hugovsky
                      last edited by

                      well…. spoke to soon. Can't enable "Register DHCP leases in the DNS Resolver". It refuses to start again.

                      2.2-BETA (amd64)
                      built on Tue Nov 25 11:18:23 CST 2014
                      FreeBSD 10.1-RELEASE

                      1 Reply Last reply Reply Quote 0
                      • C
                        cmb
                        last edited by

                        @Hugovsky:

                        well…. spoke to soon. Can't enable "Register DHCP leases in the DNS Resolver". It refuses to start again.

                        and logs what?

                        1 Reply Last reply Reply Quote 0
                        • H
                          Hugovsky
                          last edited by

                          ups… sorry about that. There you go..

                          System log:

                          Nov 25 20:27:40 dhcpleases: Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.
                          Nov 25 20:27:40 dhcpleases: kqueue error: unkown
                          Nov 25 20:27:40 dhcpleases: Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.
                          Nov 25 20:27:39 dhcpleases: Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.

                          Unbound log:

                          Nov 25 20:29:40 unbound: [93575:0] fatal error: Could not read config file: /unbound.conf
                          Nov 25 20:29:40 unbound: [93575:0] notice: Restart of unbound 1.4.22.
                          Nov 25 20:29:40 unbound: [93575:0] info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
                          Nov 25 20:29:40 unbound: [93575:0] info: server stats for thread 1: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch
                          Nov 25 20:29:40 unbound: [93575:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
                          Nov 25 20:29:40 unbound: [93575:0] info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch
                          Nov 25 20:29:40 unbound: [93575:0] info: service stopped (unbound 1.4.22).
                          Nov 25 20:29:40 unbound: [93575:0] info: start of service (unbound 1.4.22).
                          Nov 25 20:29:40 unbound: [93575:0] notice: init module 1: iterator
                          Nov 25 20:29:40 unbound: [93575:0] notice: init module 0: validator

                          BUT, this is only try if I put includes in advanced config. With default config, I can start resolver with "Register DHCP leases in the DNS Resolver" set.

                          1 Reply Last reply Reply Quote 0
                          • C
                            cmb
                            last edited by

                            @Hugovsky:

                            BUT, this is only try if I put includes in advanced config. With default config, I can start resolver with "Register DHCP leases in the DNS Resolver" set.

                            Seems you're putting something invalid in there.

                            1 Reply Last reply Reply Quote 0
                            • H
                              Hugovsky
                              last edited by

                              @cmb:

                              @Hugovsky:

                              BUT, this is only try if I put includes in advanced config. With default config, I can start resolver with "Register DHCP leases in the DNS Resolver" set.

                              Seems you're putting something invalid in there.

                              server:
                              include: /conf/local-blocking-data.conf

                              1 Reply Last reply Reply Quote 0
                              • MikeV7896M
                                MikeV7896
                                last edited by

                                I just set up a new 2.2 installation… unbound appears to be running, but these entries appear in the log whenever the service is started. I do have the options to register DHCP leases and static DHCP entries checked.

                                Nov 25 19:15:29 unbound: [88622:0] error: cannot parse netblock: '/'
                                Nov 25 19:15:29 unbound: [88622:0] error: cannot parse access control: / allow
                                Nov 25 19:15:29 unbound: [88622:0] fatal error: Could not setup access control list

                                Also, the service IS running, but the Status > Services page shows it as stopped.

                                EDIT: Nope… it's not running. My computer is using the Google IPv6 DNS servers I put into pfSense, not the local resolver. I guess there's no way to have the router specify its own IPv6 address (even if it's link-local) for DNS to DHCP clients? I only know it's not running because my IP phone - which only supports IPv4 - can't resolve my VoIP provider hostname, and the only DNS server it has is the IPv4 LAN address of my box.

                                This appears to be caused by the fact that I'm not requesting an IPv6 address on my WAN interface, just a prefix. Since there's no address, there's nothing to put in the access_lists.conf file, resulting in a access-control: / allow line.

                                Bug 4046 created for this…

                                The S in IOT stands for Security

                                1 Reply Last reply Reply Quote 0
                                • C
                                  cmb
                                  last edited by

                                  @virgiliomi:

                                  This appears to be caused by the fact that I'm not requesting an IPv6 address on my WAN interface, just a prefix. Since there's no address, there's nothing to put in the access_lists.conf file, resulting in a access-control: / allow line.

                                  Pretty sure you have to be running an old version, that was fixed over a week ago.

                                  1 Reply Last reply Reply Quote 0
                                  • MikeV7896M
                                    MikeV7896
                                    last edited by

                                    @cmb:

                                    @virgiliomi:

                                    This appears to be caused by the fact that I'm not requesting an IPv6 address on my WAN interface, just a prefix. Since there's no address, there's nothing to put in the access_lists.conf file, resulting in a access-control: / allow line.

                                    Pretty sure you have to be running an old version, that was fixed over a week ago.

                                    2.2-BETA (amd64)
                                    built on Tue Nov 25 11:18:23 CST 2014

                                    The S in IOT stands for Security

                                    1 Reply Last reply Reply Quote 0
                                    • MikeV7896M
                                      MikeV7896
                                      last edited by

                                      I updated to the latest snapshot as of this morning (built on Thu Nov 27 00:15:05 CST 2014) and the above issue seems to be resolved. Now I run into something else. My computer (Win7) has both the IPv6 and v4 addresses of my box as DNS servers.  When I try to do nslookup, it appears that unbound is refusing queries to the IPv6 address, while queries via IPv4 go through no problem.

                                      > [internal hostname]
Server:  UnKnown
Address:  2601:8:a00:xxx:xxx:xxx:xxx:xxx

*** UnKnown can't find [internal hostname]: Query refused

> [external hostname]
Server:  UnKnown
Address:  2601:8:a00:xxx:xxx:xxx:xxx:xxx

*** UnKnown can't find [external hostname]: Query refused

> server 192.168.1.1
Default Server:  [192.168.1.1]
Address:  192.168.1.1

> [internal hostname]
Server:  [192.168.1.1]
Address:  192.168.1.1

Name:    [internal hostname]
Address:  192.168.1.108

> [external hostname]
Server:  [192.168.1.1]
Address:  192.168.1.1

Non-authoritative answer:
Name:    [external hostname]
Addresses:  [ip addresses]

                                      The S in IOT stands for Security

                                      1 Reply Last reply Reply Quote 0
                                      • C
                                        cmb
                                        last edited by

                                        @virgiliomi:

                                        When I try to do nslookup, it appears that unbound is refusing queries to the IPv6 address, while queries via IPv4 go through no problem.

                                        That was tightened up a bit recently. It generally seems fine. The biggest functional change is it skips IPv6 subnets that reside on an Internet connection (a static interface with a gateway specified under Interfaces>[interface name], or any dynamic connection type). Is the subnet in question on an interface that's an Internet connection? Or is treated like one because a gateway is chosen under Interfaces?

                                        1 Reply Last reply Reply Quote 0
                                        • MikeV7896M
                                          MikeV7896
                                          last edited by

                                          @cmb:

                                          @virgiliomi:

                                          When I try to do nslookup, it appears that unbound is refusing queries to the IPv6 address, while queries via IPv4 go through no problem.

                                          That was tightened up a bit recently. It generally seems fine. The biggest functional change is it skips IPv6 subnets that reside on an Internet connection (a static interface with a gateway specified under Interfaces>[interface name], or any dynamic connection type). Is the subnet in question on an interface that's an Internet connection? Or is treated like one because a gateway is chosen under Interfaces?

                                          No, it's actually my LAN interface, which has IPv6 as "Track Interface" (WAN, Prefix 0)… My WAN interface isn't obtaining an IPv6 address, just a /60 prefix.

                                          The S in IOT stands for Security

                                          1 Reply Last reply Reply Quote 0
                                          • C
                                            cmb
                                            last edited by

                                            @virgiliomi:

                                            No, it's actually my LAN interface, which has IPv6 as "Track Interface" (WAN, Prefix 0)… My WAN interface isn't obtaining an IPv6 address, just a /60 prefix.

                                            Ok I see what was happening there, that was fixed today. Should be good on tomorrow's snapshot, or gitsync now.

                                            1 Reply Last reply Reply Quote 0
                                            • First post
                                              Last post