Unbound ipv6 problems anyone?



  • The snapshot is Sun Jul 09 02:22:35 CDT 2017. At the moment, it's still working properly. nslookup returns a result and dig will return the a and aaaa records using either ipv4 or ipv6. My linux box is also working properly. All unbound settings are default. The log level is 1 so apparently, that's the default. I bumped it up to 2. It generates a lot more messages. Nothing that appears to be erroneous.



  • I updated to the latest snapshot and found that the problem returned after the reboot. With unbound logging at 2, there are a lot of messages including some errors (error sending query to auth server <ipv6 address="">port 53).

    Here are the contents of the log in reverse chronological order (newest first). If you scroll down to the bottom, you will see the errors.

    Jul 10 13:02:49	unbound	18407:1	info: validation success wpad.localdomain. AAAA IN
    Jul 10 13:02:49	unbound	18407:1	info: validate(nxdomain): sec_status_secure
    Jul 10 13:02:49	unbound	18407:1	info: query response was NXDOMAIN ANSWER
    Jul 10 13:02:49	unbound	18407:1	info: reply from <.> 2001:7fd::1#53
    Jul 10 13:02:49	unbound	18407:1	info: response for wpad.localdomain. AAAA IN
    Jul 10 13:02:49	unbound	18407:0	info: validation success wpad.localdomain. A IN
    Jul 10 13:02:49	unbound	18407:0	info: validate(nxdomain): sec_status_secure
    Jul 10 13:02:49	unbound	18407:0	info: query response was NXDOMAIN ANSWER
    Jul 10 13:02:49	unbound	18407:0	info: reply from <.> 2001:500:2f::f#53
    Jul 10 13:02:49	unbound	18407:0	info: response for wpad.localdomain. A IN
    Jul 10 13:02:49	unbound	18407:0	info: resolving wpad.localdomain. A IN
    Jul 10 13:02:49	unbound	18407:1	info: resolving wpad.localdomain. AAAA IN
    Jul 10 13:02:49	unbound	18407:1	info: Verified that unsigned response is INSECURE
    Jul 10 13:02:49	unbound	18407:1	info: NSEC3s for the referral proved no DS.
    Jul 10 13:02:49	unbound	18407:1	info: Verified that unsigned response is INSECURE
    Jul 10 13:02:49	unbound	18407:1	info: NSEC3s for the referral proved no DS.
    Jul 10 13:02:49	unbound	18407:1	info: validated DNSKEY net. DNSKEY IN
    Jul 10 13:02:49	unbound	18407:1	info: validated DNSKEY net. DNSKEY IN
    Jul 10 13:02:49	unbound	18407:1	info: query response was ANSWER
    Jul 10 13:02:49	unbound	18407:1	info: reply from <net.> 192.31.80.30#53
    Jul 10 13:02:49	unbound	18407:1	info: response for net. DNSKEY IN
    Jul 10 13:02:49	unbound	18407:0	info: Verified that unsigned response is INSECURE
    Jul 10 13:02:49	unbound	18407:0	info: NSEC3s for the referral proved no DS.
    Jul 10 13:02:49	unbound	18407:0	info: Verified that unsigned response is INSECURE
    Jul 10 13:02:49	unbound	18407:0	info: NSEC3s for the referral proved no DS.
    Jul 10 13:02:49	unbound	18407:0	info: validated DNSKEY net. DNSKEY IN
    Jul 10 13:02:49	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:49	unbound	18407:0	info: reply from <net.> 2001:503:39c1::30#53
    Jul 10 13:02:49	unbound	18407:0	info: response for net. DNSKEY IN
    Jul 10 13:02:49	unbound	18407:1	info: validated DS net. DS IN
    Jul 10 13:02:49	unbound	18407:1	info: query response was ANSWER
    Jul 10 13:02:49	unbound	18407:1	info: reply from <c-msedge.net.> 13.107.4.2#53
    Jul 10 13:02:49	unbound	18407:1	info: response for ipv6.msftconnecttest.com. AAAA IN
    Jul 10 13:02:49	unbound	18407:1	info: resolving net. DNSKEY IN
    Jul 10 13:02:49	unbound	18407:1	info: validated DS net. DS IN
    Jul 10 13:02:49	unbound	18407:1	info: query response was nodata ANSWER
    Jul 10 13:02:49	unbound	18407:1	info: reply from <c-msedge.net.> 13.107.4.2#53
    Jul 10 13:02:49	unbound	18407:1	info: response for ipv6.msftconnecttest.com. A IN
    Jul 10 13:02:49	unbound	18407:0	info: resolving net. DNSKEY IN
    Jul 10 13:02:49	unbound	18407:0	info: validated DS net. DS IN
    Jul 10 13:02:49	unbound	18407:0	info: Verified that unsigned response is INSECURE
    Jul 10 13:02:49	unbound	18407:0	info: NSEC3s for the referral proved no DS.
    Jul 10 13:02:49	unbound	18407:0	info: query response was nodata ANSWER
    Jul 10 13:02:49	unbound	18407:0	info: reply from <c-msedge.net.> 13.107.4.1#53
    Jul 10 13:02:49	unbound	18407:0	info: response for ipv6.msftconnecttest.com. A IN
    Jul 10 13:02:49	unbound	18407:0	info: query response was nodata ANSWER
    Jul 10 13:02:49	unbound	18407:0	info: reply from <c-msedge.net.> 13.107.4.2#53
    Jul 10 13:02:49	unbound	18407:0	info: response for ns2.c-msedge.net. AAAA IN
    Jul 10 13:02:49	unbound	18407:0	info: query response was nodata ANSWER
    Jul 10 13:02:49	unbound	18407:0	info: reply from <c-msedge.net.> 13.107.4.2#53
    Jul 10 13:02:49	unbound	18407:0	info: response for ns1.c-msedge.net. AAAA IN
    Jul 10 13:02:49	unbound	18407:1	info: query response was nodata ANSWER
    Jul 10 13:02:49	unbound	18407:1	info: reply from <c-msedge.net.> 13.107.4.2#53
    Jul 10 13:02:49	unbound	18407:1	info: response for ns1.c-msedge.net. AAAA IN
    Jul 10 13:02:49	unbound	18407:1	info: resolving ns2.c-msedge.net. AAAA IN
    Jul 10 13:02:49	unbound	18407:1	info: resolving ipv6.msftconnecttest.com. AAAA IN
    Jul 10 13:02:49	unbound	18407:1	info: query response was CNAME
    Jul 10 13:02:49	unbound	18407:1	info: reply from <c-msedge.net.> 13.107.4.2#53
    Jul 10 13:02:49	unbound	18407:1	info: response for ipv6.msftconnecttest.com. AAAA IN
    Jul 10 13:02:49	unbound	18407:1	info: query response was nodata ANSWER
    Jul 10 13:02:49	unbound	18407:1	info: reply from <c-msedge.net.> 13.107.4.1#53
    Jul 10 13:02:49	unbound	18407:1	info: response for ns2.c-msedge.net. AAAA IN
    Jul 10 13:02:49	unbound	18407:1	info: resolving ipv6.msftconnecttest.com. A IN
    Jul 10 13:02:49	unbound	18407:1	info: resolving ipv6.msftconnecttest.com. A IN
    Jul 10 13:02:49	unbound	18407:1	info: query response was CNAME
    Jul 10 13:02:49	unbound	18407:1	info: reply from <msedge.net.> 204.79.197.2#53
    Jul 10 13:02:49	unbound	18407:1	info: response for ipv6.msftconnecttest.com. A IN
    Jul 10 13:02:49	unbound	18407:0	info: resolving ipv6.msftconnecttest.com. A IN
    Jul 10 13:02:49	unbound	18407:0	info: query response was CNAME
    Jul 10 13:02:49	unbound	18407:0	info: reply from <c-msedge.net.> 13.107.4.2#53
    Jul 10 13:02:49	unbound	18407:0	info: response for ipv6.msftconnecttest.com. A IN
    Jul 10 13:02:49	unbound	18407:1	info: resolving ns1.c-msedge.net. AAAA IN
    Jul 10 13:02:49	unbound	18407:0	info: resolving ns1.c-msedge.net. AAAA IN
    Jul 10 13:02:49	unbound	18407:1	info: resolving ns2.c-msedge.net. AAAA IN
    Jul 10 13:02:49	unbound	18407:0	info: resolving ns2.c-msedge.net. AAAA IN
    Jul 10 13:02:49	unbound	18407:1	info: query response was REFERRAL
    Jul 10 13:02:49	unbound	18407:1	info: reply from <net.> 2001:503:39c1::30#53
    Jul 10 13:02:49	unbound	18407:1	info: response for ipv6.msftconnecttest.com. AAAA IN
    Jul 10 13:02:49	unbound	18407:1	info: resolving ns1.msedge.net. AAAA IN
    Jul 10 13:02:49	unbound	18407:1	info: resolving ns3.msedge.net. AAAA IN
    Jul 10 13:02:49	unbound	18407:1	info: resolving ns2.msedge.net. AAAA IN
    Jul 10 13:02:49	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:49	unbound	18407:0	info: reply from <net.> 2001:500:856e::30#53
    Jul 10 13:02:49	unbound	18407:0	info: response for ipv6.msftconnecttest.com. A IN
    Jul 10 13:02:49	unbound	18407:1	info: query response was REFERRAL
    Jul 10 13:02:49	unbound	18407:1	info: reply from <net.> 2001:503:d2d::30#53
    Jul 10 13:02:49	unbound	18407:1	info: response for ipv6.msftconnecttest.com. A IN
    Jul 10 13:02:49	unbound	18407:1	info: query response was nodata ANSWER
    Jul 10 13:02:49	unbound	18407:1	info: reply from <msedge.net.> 204.79.197.1#53
    Jul 10 13:02:49	unbound	18407:1	info: response for ns1.msedge.net. AAAA IN
    Jul 10 13:02:49	unbound	18407:1	info: query response was nodata ANSWER
    Jul 10 13:02:49	unbound	18407:1	info: reply from <msedge.net.> 204.79.197.1#53
    Jul 10 13:02:49	unbound	18407:1	info: response for ns3.msedge.net. AAAA IN
    Jul 10 13:02:49	unbound	18407:0	info: query response was nodata ANSWER
    Jul 10 13:02:49	unbound	18407:0	info: reply from <msedge.net.> 131.253.21.1#53
    Jul 10 13:02:49	unbound	18407:0	info: response for ns1.msedge.net. AAAA IN
    Jul 10 13:02:49	unbound	18407:1	info: query response was nodata ANSWER
    Jul 10 13:02:49	unbound	18407:1	info: reply from <msedge.net.> 204.79.197.2#53
    Jul 10 13:02:49	unbound	18407:1	info: response for ns4.msedge.net. AAAA IN
    Jul 10 13:02:49	unbound	18407:0	info: query response was nodata ANSWER
    Jul 10 13:02:49	unbound	18407:1	info: query response was nodata ANSWER
    Jul 10 13:02:49	unbound	18407:1	info: reply from <msedge.net.> 131.253.21.2#53
    Jul 10 13:02:49	unbound	18407:1	info: response for ns2.msedge.net. AAAA IN
    Jul 10 13:02:49	unbound	18407:0	info: reply from <msedge.net.> 131.253.21.2#53
    Jul 10 13:02:49	unbound	18407:0	info: response for ns4.msedge.net. AAAA IN
    Jul 10 13:02:49	unbound	18407:0	info: query response was nodata ANSWER
    Jul 10 13:02:49	unbound	18407:0	info: reply from <msedge.net.> 204.79.197.2#53
    Jul 10 13:02:49	unbound	18407:0	info: response for ns2.msedge.net. AAAA IN
    Jul 10 13:02:49	unbound	18407:0	info: resolving ipv6.msftconnecttest.com. A IN
    Jul 10 13:02:49	unbound	18407:0	info: query response was CNAME
    Jul 10 13:02:49	unbound	18407:0	info: reply from <msedge.net.> 131.253.21.2#53
    Jul 10 13:02:49	unbound	18407:0	info: response for ipv6.msftconnecttest.com. A IN
    Jul 10 13:02:49	unbound	18407:1	info: resolving ipv6.msftconnecttest.com. AAAA IN
    Jul 10 13:02:49	unbound	18407:0	info: query response was nodata ANSWER
    Jul 10 13:02:49	unbound	18407:1	info: query response was CNAME
    Jul 10 13:02:49	unbound	18407:1	info: reply from <msedge.net.> 131.253.21.2#53
    Jul 10 13:02:49	unbound	18407:1	info: response for ipv6.msftconnecttest.com. AAAA IN
    Jul 10 13:02:49	unbound	18407:0	info: reply from <msedge.net.> 131.253.21.2#53
    Jul 10 13:02:49	unbound	18407:0	info: response for ns3.msedge.net. AAAA IN
    Jul 10 13:02:49	unbound	18407:1	info: resolving ns4.msedge.net. AAAA IN
    Jul 10 13:02:49	unbound	18407:1	info: resolving ns1.msedge.net. AAAA IN
    Jul 10 13:02:49	unbound	18407:0	info: resolving ns1.msedge.net. AAAA IN
    Jul 10 13:02:49	unbound	18407:1	info: resolving ns3.msedge.net. AAAA IN
    Jul 10 13:02:49	unbound	18407:0	info: resolving ns4.msedge.net. AAAA IN
    Jul 10 13:02:49	unbound	18407:1	info: resolving ns2.msedge.net. AAAA IN
    Jul 10 13:02:49	unbound	18407:0	info: resolving ns2.msedge.net. AAAA IN
    Jul 10 13:02:49	unbound	18407:1	info: query response was REFERRAL
    Jul 10 13:02:49	unbound	18407:1	info: reply from <net.> 2001:500:d937::30#53
    Jul 10 13:02:49	unbound	18407:1	info: response for ipv6.msftconnecttest.com. AAAA IN
    Jul 10 13:02:49	unbound	18407:0	info: resolving ns3.msedge.net. AAAA IN
    Jul 10 13:02:49	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:49	unbound	18407:1	info: resolving ipv6.msftconnecttest.com. A IN
    Jul 10 13:02:49	unbound	18407:0	info: reply from <net.> 2001:503:231d::2:30#53
    Jul 10 13:02:49	unbound	18407:0	info: response for ipv6.msftconnecttest.com. A IN
    Jul 10 13:02:49	unbound	18407:1	info: query response was CNAME
    Jul 10 13:02:49	unbound	18407:1	info: reply from <msftconnecttest.com.> 208.84.2.53#53
    Jul 10 13:02:49	unbound	18407:1	info: response for ipv6.msftconnecttest.com. A IN
    Jul 10 13:02:48	unbound	18407:1	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:1	info: reply from <com.> 192.41.162.30#53
    Jul 10 13:02:48	unbound	18407:1	info: response for ipv6.msftconnecttest.com. A IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving ipv6.msftconnecttest.com. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was CNAME
    Jul 10 13:02:48	unbound	18407:0	info: reply from <msftconnecttest.com.> 2620:0:34::53#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ipv6.msftconnecttest.com. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <pch.net.> 2620:0:872::231:3#53
    Jul 10 13:02:48	unbound	18407:0	info: response for anyns.pch.net. A IN
    Jul 10 13:02:48	unbound	18407:1	info: resolving ipv6.msftconnecttest.com. AAAA IN
    Jul 10 13:02:48	unbound	18407:1	info: query response was CNAME
    Jul 10 13:02:48	unbound	18407:1	info: reply from <msftconnecttest.com.> 193.221.113.53#53
    Jul 10 13:02:48	unbound	18407:1	info: response for ipv6.msftconnecttest.com. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <com.> 192.55.83.30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ipv6.msftconnecttest.com. A IN
    Jul 10 13:02:48	unbound	18407:1	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:1	info: reply from <com.> 2001:500:d937::30#53
    Jul 10 13:02:48	unbound	18407:1	info: response for ipv6.msftconnecttest.com. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was nodata ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <g.ntpns.org.> 89.36.18.22#53
    Jul 10 13:02:48	unbound	18407:0	info: response for g.ntpns.org. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was nodata ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <edu-servers.net.> 2001:500:126::30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for c.edu-servers.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:1	info: resolving ipv6.msftconnecttest.com. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was nodata ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <pool.ntp.org.> 94.242.223.210#53
    Jul 10 13:02:48	unbound	18407:0	info: response for 0.pfsense.pool.ntp.org. AAAA IN
    Jul 10 13:02:48	unbound	18407:1	info: resolving ipv6.msftconnecttest.com. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving ipv6.msftconnecttest.com. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <nstld.com.> 2001:500:127::30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for av2.nstld.com. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <g.ntpns.org.> 207.171.17.42#53
    Jul 10 13:02:48	unbound	18407:0	info: response for g.ntpns.org. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was nodata ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <edu-servers.net.> 192.42.178.30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for f.edu-servers.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was nodata ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <edu-servers.net.> 192.82.133.30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for d.edu-servers.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was nodata ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <edu-servers.net.> 192.82.134.30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for a.edu-servers.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <bitnames.com.> 2a01:608:ffff:a011::200#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns-g2.bitnames.com. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was nodata ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <lightlink.com.> 64.57.176.2#53
    Jul 10 13:02:48	unbound	18407:0	info: response for light.lightlink.com. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <bitnames.com.> 94.242.223.200#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns1.eu.bitnames.com. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <ntpns.org.> 107.170.182.174#53
    Jul 10 13:02:48	unbound	18407:0	info: response for g.ntpns.org. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <nstld.com.> 2001:500:127::30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for av2.nstld.com. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was nodata ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <iecc.com.> 64.57.176.2#53
    Jul 10 13:02:48	unbound	18407:0	info: response for sdn.iecc.com. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <nstld.com.> 192.42.177.30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for av3.nstld.com. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <bitnames.com.> 2001:500:90:1::20#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns2.us.bitnames.com. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <nstld.com.> 2001:500:126::30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for av3.nstld.com. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <com.> 192.54.112.30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns2.us.bitnames.com. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <bitnames.com.> 92.243.1.21#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns1.eu.bitnames.com. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <bitnames.com.> 207.171.3.21#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns-g2.bitnames.com. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <ntpns.org.> 208.78.70.20#53
    Jul 10 13:02:48	unbound	18407:0	info: response for b.ntpns.org. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <pch.net.> 2001:418:3f4::5#53
    Jul 10 13:02:48	unbound	18407:0	info: response for anyns.pch.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <ntpns.org.> 2001:500:94:1::20#53
    Jul 10 13:02:48	unbound	18407:0	info: response for g.ntpns.org. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <ntpns.org.> 204.13.251.20#53
    Jul 10 13:02:48	unbound	18407:0	info: response for b.ntpns.org. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <com.> 192.52.178.30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for av2.nstld.com. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <ntpns.org.> 2607:f238:2::53:21#53
    Jul 10 13:02:48	unbound	18407:0	info: response for d.ntpns.org. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving ns4.p20.dynect.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving ns2.p20.dynect.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving b.ntpns.org. A IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving ns4.p20.dynect.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving ns2.p20.dynect.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving ns2.us.bitnames.com. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving g.ntpns.org. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving g.ntpns.org. A IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving b.ntpns.org. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving 0.pfsense.pool.ntp.org. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: Verified that unsigned response is INSECURE
    Jul 10 13:02:48	unbound	18407:0	info: NSEC3s for the referral proved no DS.
    Jul 10 13:02:48	unbound	18407:0	info: validated DNSKEY org. DNSKEY IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <org.> 199.19.53.1#53
    Jul 10 13:02:48	unbound	18407:0	info: response for org. DNSKEY IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was nodata ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <dynamicnetworkservices.net.> 108.59.165.1#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns4.dynamicnetworkservices.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <bitnames.com.> 208.78.70.20#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns1.us.bitnames.com. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <udel.edu.> 128.175.13.17#53
    Jul 10 13:02:48	unbound	18407:0	info: response for dns1.udel.edu. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <com.> 192.54.112.30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns-g2.bitnames.com. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <com.> 192.52.178.30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for light.lightlink.com. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <com.> 2001:503:d2d::30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns1.us.bitnames.com. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <com.> 192.5.6.30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for av3.nstld.com. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <com.> 192.54.112.30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for sdn.iecc.com. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <bitnames.com.> 2607:f238:2::53:21#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns1.us.bitnames.com. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <net.> 2001:503:d2d::30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns4.dynamicnetworkservices.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <ntpns.org.> 204.13.250.20#53
    Jul 10 13:02:48	unbound	18407:0	info: response for c.ntpns.org. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was nodata ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <dynect.net.> 2a02:e180:8::1#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns4.p20.dynect.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <net.> 192.26.92.30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for anyns.pch.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <net.> 192.48.79.30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for d.edu-servers.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <dynect.net.> 2600:2000:1000::21#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns3.p20.dynect.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <ntpns.org.> 204.13.250.20#53
    Jul 10 13:02:48	unbound	18407:0	info: response for c.ntpns.org. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <ntpns.org.> 204.13.251.20#53
    Jul 10 13:02:48	unbound	18407:0	info: response for e.ntpns.org. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <org.> 2001:500:b::1#53
    Jul 10 13:02:48	unbound	18407:0	info: response for e.ntpns.org. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was nodata ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <udel.edu.> 2607:f470:1002::2:3#53
    Jul 10 13:02:48	unbound	18407:0	info: response for dns2.udel.edu. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was nodata ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <udel.edu.> 2607:f470:1003::3:c#53
    Jul 10 13:02:48	unbound	18407:0	info: response for dns1.udel.edu. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <org.> 2001:500:e::1#53
    Jul 10 13:02:48	unbound	18407:0	info: response for c.ntpns.org. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <com.> 192.26.92.30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns1.us.bitnames.com. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <net.> 192.5.6.30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for a.edu-servers.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving org. DNSKEY IN
    Jul 10 13:02:48	unbound	18407:0	info: validated DS org. DS IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <pool.ntp.org.> 173.255.139.202#53
    Jul 10 13:02:48	unbound	18407:0	info: response for 0.pfsense.pool.ntp.org. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <com.> 192.31.80.30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns-g2.bitnames.com. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <com.> 192.42.93.30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns1.eu.bitnames.com. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <org.> 2001:500:b::1#53
    Jul 10 13:02:48	unbound	18407:0	info: response for c.ntpns.org. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was nodata ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <bitnames.com.> 204.13.250.20#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns2.us.bitnames.com. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was nodata ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <dynamicnetworkservices.net.> 108.59.165.1#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns2.dynamicnetworkservices.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <com.> 192.35.51.30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for av2.nstld.com. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <edu.> 192.35.51.30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for dns1.udel.edu. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <ntpns.org.> 204.61.216.4#53
    Jul 10 13:02:48	unbound	18407:0	info: response for d.ntpns.org. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <ntpns.org.> 208.78.71.20#53
    Jul 10 13:02:48	unbound	18407:0	info: response for f.ntpns.org. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <com.> 2001:503:39c1::30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns2.us.bitnames.com. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <ntpns.org.> 208.78.71.20#53
    Jul 10 13:02:48	unbound	18407:0	info: response for i.ntpns.org. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <ntpns.org.> 204.13.251.20#53
    Jul 10 13:02:48	unbound	18407:0	info: response for h.ntpns.org. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <ntpns.org.> 208.78.71.20#53
    Jul 10 13:02:48	unbound	18407:0	info: response for f.ntpns.org. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <ntpns.org.> 208.78.71.20#53
    Jul 10 13:02:48	unbound	18407:0	info: response for h.ntpns.org. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <ntpns.org.> 204.61.216.4#53
    Jul 10 13:02:48	unbound	18407:0	info: response for i.ntpns.org. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <org.> 199.19.57.1#53
    Jul 10 13:02:48	unbound	18407:0	info: response for d.ntpns.org. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <net.> 192.55.83.30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns2.dynamicnetworkservices.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <iecc.com.> 72.249.171.254#53
    Jul 10 13:02:48	unbound	18407:0	info: response for sdn.iecc.com. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <dynect.net.> 208.78.71.136#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns1.p20.dynect.net. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <com.> 2001:502:8cc::30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for av3.nstld.com. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <dynect.net.> 208.78.71.136#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns1.p20.dynect.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <com.> 2001:502:8cc::30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns1.eu.bitnames.com. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <dynect.net.> 204.13.250.136#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns2.p20.dynect.net. A IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving f.ntpns.org. A IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving ns2.us.bitnames.com. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving i.ntpns.org. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving ns2.us.bitnames.com. A IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving h.ntpns.org. A IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving f.ntpns.org. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving i.ntpns.org. A IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving h.ntpns.org. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <ntpns.org.> 208.78.71.20#53
    Jul 10 13:02:48	unbound	18407:0	info: response for e.ntpns.org. A IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving av3.nstld.com. A IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving av3.nstld.com. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <net.> 192.55.83.30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for c.edu-servers.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving ns1.eu.bitnames.com. A IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving ns1.p20.dynect.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving ns1.p20.dynect.net. A IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving ns1.eu.bitnames.com. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <dynect.net.> 204.13.251.136#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns3.p20.dynect.net. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <net.> 2001:502:8cc::30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for anyns.pch.net. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <dynect.net.> 162.88.61.21#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns4.p20.dynect.net. A IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving ns3.p20.dynect.net. A IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving anyns.pch.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving anyns.pch.net. A IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving ns3.p20.dynect.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was nodata ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <dynect.net.> 2001:500:90:1::136#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns2.p20.dynect.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <net.> 2001:500:d937::30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns4.p20.dynect.net. A IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving dns2.udel.edu. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <edu.> 192.35.51.30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for dns1.udel.edu. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving ns2.p20.dynect.net. A IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving ns2.p20.dynect.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <org.> 2001:500:c::1#53
    Jul 10 13:02:48	unbound	18407:0	info: response for e.ntpns.org. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <everett.org.> 66.220.13.230#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns2.everett.org. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:48	unbound	18407:0	info: reply from <everett.org.> 66.220.13.230#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns1.everett.org. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving av2.nstld.com. A IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving av2.nstld.com. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <net.> 2001:502:8cc::30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for f.edu-servers.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving light.lightlink.com. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <com.> 2001:502:7094::30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for sdn.iecc.com. A IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving ns1.us.bitnames.com. A IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving ns-g2.bitnames.com. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving ns-g2.bitnames.com. A IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving ns1.us.bitnames.com. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <org.> 2001:500:40::1#53
    Jul 10 13:02:48	unbound	18407:0	info: response for d.ntpns.org. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving a.edu-servers.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving f.edu-servers.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <.> 192.33.4.12#53
    Jul 10 13:02:48	unbound	18407:0	info: response for dns1.udel.edu. A IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving sdn.iecc.com. A IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving sdn.iecc.com. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving ns2.everett.org. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <org.> 199.19.54.1#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns1.everett.org. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving c.ntpns.org. A IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving e.ntpns.org. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving e.ntpns.org. A IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving d.ntpns.org. A IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving d.ntpns.org. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving c.ntpns.org. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <ntp.org.> 66.220.13.229#53
    Jul 10 13:02:48	unbound	18407:0	info: response for 0.pfsense.pool.ntp.org. A IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving ns2.dynamicnetworkservices.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving ns4.dynamicnetworkservices.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <net.> 2001:503:d414::30#53
    Jul 10 13:02:48	unbound	18407:0	info: response for ns4.p20.dynect.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving c.edu-servers.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving d.edu-servers.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <.> 192.5.5.241#53
    Jul 10 13:02:48	unbound	18407:0	info: response for dns1.udel.edu. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving ns4.p20.dynect.net. A IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving dns1.udel.edu. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving dns1.udel.edu. A IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving ns4.p20.dynect.net. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving ns1.everett.org. AAAA IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <org.> 2001:500:c::1#53
    Jul 10 13:02:48	unbound	18407:0	info: response for 0.pfsense.pool.ntp.org. A IN
    Jul 10 13:02:48	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:48	unbound	18407:0	info: reply from <.> 2001:dc3::35#53
    Jul 10 13:02:48	unbound	18407:0	info: response for 0.pfsense.pool.ntp.org. A IN
    Jul 10 13:02:48	unbound	18407:0	info: resolving 0.pfsense.pool.ntp.org. A IN
    Jul 10 13:02:36	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:36	unbound	18407:0	info: reply from <msft.net.> 208.76.45.53#53
    Jul 10 13:02:36	unbound	18407:0	info: response for ns2.msft.net. A IN
    Jul 10 13:02:36	unbound	18407:0	info: error sending query to auth server 2620:0:37::53 port 53
    Jul 10 13:02:36	unbound	18407:0	info: error sending query to auth server 2620:0:32::53 port 53
    Jul 10 13:02:36	unbound	18407:0	info: error sending query to auth server 2620:0:34::53 port 53
    Jul 10 13:02:36	unbound	18407:0	info: error sending query to auth server 2620:0:37::53 port 53
    Jul 10 13:02:36	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:36	unbound	18407:0	info: reply from <net.> 192.41.162.30#53
    Jul 10 13:02:36	unbound	18407:0	info: response for ns2.msft.net. A IN
    Jul 10 13:02:36	unbound	18407:0	info: Verified that unsigned response is INSECURE
    Jul 10 13:02:36	unbound	18407:0	info: NSEC3s for the referral proved no DS.
    Jul 10 13:02:36	unbound	18407:0	info: Verified that unsigned response is INSECURE
    Jul 10 13:02:36	unbound	18407:0	info: NSEC3s for the referral proved no DS.
    Jul 10 13:02:36	unbound	18407:0	info: validated DNSKEY com. DNSKEY IN
    Jul 10 13:02:36	unbound	18407:0	info: validated DNSKEY com. DNSKEY IN
    Jul 10 13:02:36	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:36	unbound	18407:0	info: reply from <com.> 192.12.94.30#53
    Jul 10 13:02:36	unbound	18407:0	info: response for com. DNSKEY IN
    Jul 10 13:02:36	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:36	unbound	18407:0	info: reply from <msft.net.> 208.76.45.53#53
    Jul 10 13:02:36	unbound	18407:0	info: response for ns4.msft.net. AAAA IN
    Jul 10 13:02:36	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:36	unbound	18407:0	info: reply from <msft.net.> 193.221.113.53#53
    Jul 10 13:02:36	unbound	18407:0	info: response for ns2.msft.net. AAAA IN
    Jul 10 13:02:36	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:36	unbound	18407:0	info: reply from <msft.net.> 193.221.113.53#53
    Jul 10 13:02:36	unbound	18407:0	info: response for ns3.msft.net. AAAA IN
    Jul 10 13:02:36	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:36	unbound	18407:0	info: reply from <msft.net.> 208.76.45.53#53
    Jul 10 13:02:36	unbound	18407:0	info: response for ns3.msft.net. A IN
    Jul 10 13:02:36	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:36	unbound	18407:0	info: reply from <msft.net.> 208.84.2.53#53
    Jul 10 13:02:36	unbound	18407:0	info: response for ns1.msft.net. A IN
    Jul 10 13:02:36	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:36	unbound	18407:0	info: reply from <msft.net.> 208.76.45.53#53
    Jul 10 13:02:36	unbound	18407:0	info: response for ns1.msft.net. AAAA IN
    Jul 10 13:02:36	unbound	18407:0	info: validated DS com. DS IN
    Jul 10 13:02:36	unbound	18407:0	info: query response was nodata ANSWER
    Jul 10 13:02:36	unbound	18407:0	info: reply from <msftncsi.com.> 208.76.45.53#53
    Jul 10 13:02:36	unbound	18407:0	info: response for dns.msftncsi.com. AAAA IN
    Jul 10 13:02:36	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:36	unbound	18407:0	info: reply from <net.> 192.48.79.30#53
    Jul 10 13:02:36	unbound	18407:0	info: response for ns3.msft.net. AAAA IN
    Jul 10 13:02:36	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:36	unbound	18407:0	info: reply from <net.> 192.54.112.30#53
    Jul 10 13:02:36	unbound	18407:0	info: response for ns4.msft.net. AAAA IN
    Jul 10 13:02:36	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:36	unbound	18407:0	info: reply from <net.> 192.5.6.30#53
    Jul 10 13:02:36	unbound	18407:0	info: response for ns2.msft.net. AAAA IN
    Jul 10 13:02:36	unbound	18407:0	info: error sending query to auth server 2620:0:32::53 port 53
    Jul 10 13:02:36	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:36	unbound	18407:0	info: reply from <net.> 192.52.178.30#53
    Jul 10 13:02:36	unbound	18407:0	info: response for ns3.msft.net. A IN
    Jul 10 13:02:36	unbound	18407:0	info: error sending query to auth server 2001:500:d937::30 port 53
    Jul 10 13:02:36	unbound	18407:0	info: error sending query to auth server 2001:501:b1f9::30 port 53
    Jul 10 13:02:36	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:36	unbound	18407:0	info: reply from <.> 198.41.0.4#53
    Jul 10 13:02:36	unbound	18407:0	info: response for ns2.msft.net. A IN
    Jul 10 13:02:36	unbound	18407:0	info: error sending query to auth server 2620:0:30::53 port 53
    Jul 10 13:02:36	unbound	18407:0	info: resolving ns1.msft.net. A IN
    Jul 10 13:02:36	unbound	18407:0	info: resolving ns1.msft.net. AAAA IN
    Jul 10 13:02:36	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:36	unbound	18407:0	info: reply from <msft.net.> 208.84.2.53#53
    Jul 10 13:02:36	unbound	18407:0	info: response for ns4.msft.net. A IN
    Jul 10 13:02:36	unbound	18407:0	info: error sending query to auth server 2001:503:231d::2:30 port 53
    Jul 10 13:02:36	unbound	18407:0	info: resolving com. DNSKEY IN
    Jul 10 13:02:36	unbound	18407:0	info: validated DS com. DS IN
    Jul 10 13:02:36	unbound	18407:0	info: Successfully primed trust anchor . DNSKEY IN
    Jul 10 13:02:36	unbound	18407:0	info: validate keys with anchor(DS): sec_status_secure
    Jul 10 13:02:35	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:35	unbound	18407:0	info: reply from <.> 192.33.4.12#53
    Jul 10 13:02:35	unbound	18407:0	info: response for . DNSKEY IN
    Jul 10 13:02:35	unbound	18407:0	info: error sending query to auth server 2620:0:32::53 port 53
    Jul 10 13:02:35	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:35	unbound	18407:0	info: reply from <net.> 192.33.14.30#53
    Jul 10 13:02:35	unbound	18407:0	info: response for ns4.msft.net. A IN
    Jul 10 13:02:35	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:35	unbound	18407:0	info: reply from <.> 198.97.190.53#53
    Jul 10 13:02:35	unbound	18407:0	info: response for ns2.msft.net. AAAA IN
    Jul 10 13:02:35	unbound	18407:0	info: error sending query to auth server 2001:500:2d::d port 53
    Jul 10 13:02:35	unbound	18407:0	info: resolving . DNSKEY IN
    Jul 10 13:02:35	unbound	18407:0	info: prime trust anchor
    Jul 10 13:02:35	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:35	unbound	18407:0	info: reply from <google.com.> 216.239.38.10#53
    Jul 10 13:02:35	unbound	18407:0	info: response for clients4.google.com. A IN
    Jul 10 13:02:35	unbound	18407:0	info: query response was nodata ANSWER
    Jul 10 13:02:35	unbound	18407:0	info: reply from <google.com.> 216.239.36.10#53
    Jul 10 13:02:35	unbound	18407:0	info: response for ns1.google.com. AAAA IN
    Jul 10 13:02:35	unbound	18407:0	info: query response was nodata ANSWER
    Jul 10 13:02:35	unbound	18407:0	info: reply from <google.com.> 216.239.36.10#53
    Jul 10 13:02:35	unbound	18407:0	info: response for ns4.google.com. AAAA IN
    Jul 10 13:02:35	unbound	18407:0	info: resolving ns3.google.com. AAAA IN
    Jul 10 13:02:35	unbound	18407:0	info: resolving clients4.google.com. A IN
    Jul 10 13:02:35	unbound	18407:0	info: query response was CNAME
    Jul 10 13:02:35	unbound	18407:0	info: reply from <google.com.> 216.239.36.10#53
    Jul 10 13:02:35	unbound	18407:0	info: response for clients4.google.com. A IN
    Jul 10 13:02:35	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:35	unbound	18407:0	info: reply from <.> 192.112.36.4#53
    Jul 10 13:02:35	unbound	18407:0	info: response for ns4.msft.net. AAAA IN
    Jul 10 13:02:35	unbound	18407:0	info: error sending query to auth server 2001:503:83eb::30 port 53
    Jul 10 13:02:35	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:35	unbound	18407:0	info: reply from <.> 199.7.83.42#53
    Jul 10 13:02:35	unbound	18407:0	info: response for ns4.msft.net. A IN
    Jul 10 13:02:35	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:35	unbound	18407:0	info: reply from <.> 199.7.83.42#53
    Jul 10 13:02:35	unbound	18407:0	info: response for ns3.msft.net. AAAA IN
    Jul 10 13:02:35	unbound	18407:0	info: query response was nodata ANSWER
    Jul 10 13:02:35	unbound	18407:0	info: reply from <google.com.> 216.239.34.10#53
    Jul 10 13:02:35	unbound	18407:0	info: response for ns2.google.com. AAAA IN
    Jul 10 13:02:35	unbound	18407:0	info: query response was nodata ANSWER
    Jul 10 13:02:35	unbound	18407:0	info: reply from <google.com.> 216.239.38.10#53
    Jul 10 13:02:35	unbound	18407:0	info: response for ns3.google.com. AAAA IN
    Jul 10 13:02:35	unbound	18407:0	info: resolving ns2.google.com. AAAA IN
    Jul 10 13:02:35	unbound	18407:0	info: resolving ns1.google.com. AAAA IN
    Jul 10 13:02:35	unbound	18407:0	info: resolving ns4.google.com. AAAA IN
    Jul 10 13:02:35	unbound	18407:0	info: resolving ns3.google.com. AAAA IN
    Jul 10 13:02:35	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:35	unbound	18407:0	info: reply from <com.> 192.55.83.30#53
    Jul 10 13:02:35	unbound	18407:0	info: response for clients4.google.com. A IN
    Jul 10 13:02:35	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:35	unbound	18407:0	info: reply from <.> 199.7.91.13#53
    Jul 10 13:02:35	unbound	18407:0	info: response for ns3.msft.net. A IN
    Jul 10 13:02:35	unbound	18407:0	info: error sending query to auth server 2001:7fe::53 port 53
    Jul 10 13:02:35	unbound	18407:0	info: error sending query to auth server 2001:503:ba3e::2:30 port 53
    Jul 10 13:02:35	unbound	18407:0	info: resolving ns2.msft.net. A IN
    Jul 10 13:02:35	unbound	18407:0	info: error sending query to auth server 2001:500:12::d0d port 53
    Jul 10 13:02:35	unbound	18407:0	info: error sending query to auth server 2001:500:1::53 port 53
    Jul 10 13:02:35	unbound	18407:0	info: resolving ns4.msft.net. AAAA IN
    Jul 10 13:02:35	unbound	18407:0	info: error sending query to auth server 2001:500:2::c port 53
    Jul 10 13:02:35	unbound	18407:0	info: resolving ns4.msft.net. A IN
    Jul 10 13:02:35	unbound	18407:0	info: resolving ns3.msft.net. A IN
    Jul 10 13:02:35	unbound	18407:0	info: resolving ns3.msft.net. AAAA IN
    Jul 10 13:02:35	unbound	18407:0	info: error sending query to auth server 2001:500:2::c port 53
    Jul 10 13:02:35	unbound	18407:0	info: error sending query to auth server 2001:7fd::1 port 53
    Jul 10 13:02:35	unbound	18407:0	info: error sending query to auth server 2001:7fe::53 port 53
    Jul 10 13:02:35	unbound	18407:0	info: resolving ns2.msft.net. AAAA IN
    Jul 10 13:02:35	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:35	unbound	18407:0	info: reply from <com.> 192.33.14.30#53
    Jul 10 13:02:35	unbound	18407:0	info: response for dns.msftncsi.com. AAAA IN
    Jul 10 13:02:35	unbound	18407:0	info: resolving clients4.google.com. A IN
    Jul 10 13:02:35	unbound	18407:0	info: error sending query to auth server 2001:501:b1f9::30 port 53
    Jul 10 13:02:35	unbound	18407:0	info: error sending query to auth server 2001:503:231d::2:30 port 53
    Jul 10 13:02:35	unbound	18407:0	info: error sending query to auth server 2001:502:1ca1::30 port 53
    Jul 10 13:02:35	unbound	18407:0	info: error sending query to auth server 2001:503:39c1::30 port 53
    Jul 10 13:02:35	unbound	18407:0	info: query response was REFERRAL
    Jul 10 13:02:35	unbound	18407:0	info: reply from <.> 202.12.27.33#53
    Jul 10 13:02:35	unbound	18407:0	info: response for dns.msftncsi.com. AAAA IN
    Jul 10 13:02:35	unbound	18407:0	info: error sending query to auth server 2001:503:c27::2:30 port 53
    Jul 10 13:02:35	unbound	18407:0	info: error sending query to auth server 2001:500:a8::e port 53
    Jul 10 13:02:35	unbound	18407:0	info: priming successful for . NS IN
    Jul 10 13:02:35	unbound	18407:0	info: query response was ANSWER
    Jul 10 13:02:35	unbound	18407:0	info: reply from <.> 192.58.128.30#53
    Jul 10 13:02:35	unbound	18407:0	info: response for . NS IN
    Jul 10 13:02:35	unbound	18407:0	info: error sending query to auth server 2001:7fe::53 port 53
    Jul 10 13:02:35	unbound	18407:0	info: error sending query to auth server 2001:7fe::53 port 53
    Jul 10 13:02:35	unbound	18407:0	info: error sending query to auth server 2001:7fe::53 port 53
    Jul 10 13:02:35	unbound	18407:0	info: error sending query to auth server 2001:500:2f::f port 53
    Jul 10 13:02:35	unbound	18407:0	info: priming . IN NS
    Jul 10 13:02:35	unbound	18407:0	info: resolving dns.msftncsi.com. AAAA IN
    Jul 10 13:02:35	unbound	18407:0	info: start of service (unbound 1.6.3).
    Jul 10 13:02:35	unbound	18407:0	notice: init module 1: iterator
    Jul 10 13:02:35	unbound	18407:0	notice: init module 0: validator</com.></com.></google.com.></google.com.></google.com.></google.com.></google.com.></google.com.></net.></msft.net.></net.></net.></net.></net.></msftncsi.com.></msft.net.></msft.net.></msft.net.></msft.net.></msft.net.></msft.net.></com.></net.></msft.net.></org.></net.></ntp.org.></org.></org.></com.></net.></everett.org.></everett.org.></org.></edu.></net.></dynect.net.></dynect.net.></net.></dynect.net.></net.></ntpns.org.></dynect.net.></com.></dynect.net.></com.></dynect.net.></iecc.com.></net.></org.></ntpns.org.></ntpns.org.></ntpns.org.></ntpns.org.></ntpns.org.></com.></ntpns.org.></ntpns.org.></edu.></com.></dynamicnetworkservices.net.></bitnames.com.></org.></com.></com.></pool.ntp.org.></net.></com.></org.></udel.edu.></udel.edu.></org.></ntpns.org.></ntpns.org.></dynect.net.></net.></net.></dynect.net.></ntpns.org.></net.></bitnames.com.></com.></com.></com.></com.></com.></udel.edu.></bitnames.com.></dynamicnetworkservices.net.></org.></ntpns.org.></com.></ntpns.org.></ntpns.org.></pch.net.></ntpns.org.></bitnames.com.></bitnames.com.></com.></nstld.com.></bitnames.com.></nstld.com.></iecc.com.></nstld.com.></ntpns.org.></bitnames.com.></lightlink.com.></bitnames.com.></edu-servers.net.></edu-servers.net.></edu-servers.net.></g.ntpns.org.></nstld.com.></pool.ntp.org.></edu-servers.net.></g.ntpns.org.></com.></com.></msftconnecttest.com.></pch.net.></msftconnecttest.com.></com.></msftconnecttest.com.></net.></net.></msedge.net.></msedge.net.></msedge.net.></msedge.net.></msedge.net.></msedge.net.></msedge.net.></msedge.net.></msedge.net.></msedge.net.></net.></net.></net.></c-msedge.net.></msedge.net.></c-msedge.net.></c-msedge.net.></c-msedge.net.></c-msedge.net.></c-msedge.net.></c-msedge.net.></c-msedge.net.></c-msedge.net.></net.></net.>
    

    I restarted unbound and nslookup and dig are working.

    Here are the log messages from the restart. There are no errors.

    Jul 10 13:11:01	unbound	85831:1	info: query response was ANSWER
    Jul 10 13:11:01	unbound	85831:1	info: reply from <netgate.com.> 2610:1c1:3::108#53
    Jul 10 13:11:01	unbound	85831:1	info: response for files00.netgate.com. AAAA IN
    Jul 10 13:11:01	unbound	85831:1	info: resolving files00.netgate.com. AAAA IN
    Jul 10 13:11:01	unbound	85831:1	info: Verified that unsigned response is INSECURE
    Jul 10 13:11:01	unbound	85831:1	info: NSEC3s for the referral proved no DS.
    Jul 10 13:11:01	unbound	85831:1	info: query response was ANSWER
    Jul 10 13:11:01	unbound	85831:1	info: reply from <netgate.com.> 2610:160:11:3::6#53
    Jul 10 13:11:01	unbound	85831:1	info: response for files00.netgate.com. A IN
    Jul 10 13:11:01	unbound	85831:0	info: query response was nodata ANSWER
    Jul 10 13:11:01	unbound	85831:0	info: reply from <google.com.> 216.239.32.10#53
    Jul 10 13:11:01	unbound	85831:0	info: response for ns3.google.com. AAAA IN
    Jul 10 13:11:01	unbound	85831:0	info: query response was ANSWER
    Jul 10 13:11:01	unbound	85831:0	info: reply from <google.com.> 216.239.34.10#53
    Jul 10 13:11:01	unbound	85831:0	info: response for google.com. AAAA IN
    Jul 10 13:11:01	unbound	85831:0	info: query response was nodata ANSWER
    Jul 10 13:11:01	unbound	85831:0	info: reply from <google.com.> 216.239.36.10#53
    Jul 10 13:11:01	unbound	85831:0	info: response for ns1.google.com. AAAA IN
    Jul 10 13:11:01	unbound	85831:0	info: resolving ns2.google.com. AAAA IN
    Jul 10 13:11:01	unbound	85831:0	info: resolving ns4.google.com. AAAA IN
    Jul 10 13:11:01	unbound	85831:0	info: resolving google.com. AAAA IN
    Jul 10 13:11:01	unbound	85831:0	info: Verified that unsigned response is INSECURE
    Jul 10 13:11:01	unbound	85831:0	info: NSEC3s for the referral proved no DS.
    Jul 10 13:11:01	unbound	85831:0	info: validated DNSKEY com. DNSKEY IN
    Jul 10 13:11:01	unbound	85831:0	info: query response was ANSWER
    Jul 10 13:11:01	unbound	85831:0	info: reply from <com.> 2001:503:39c1::30#53
    Jul 10 13:11:01	unbound	85831:0	info: response for com. DNSKEY IN
    Jul 10 13:11:01	unbound	85831:0	info: query response was nodata ANSWER
    Jul 10 13:11:01	unbound	85831:0	info: reply from <google.com.> 216.239.34.10#53
    Jul 10 13:11:01	unbound	85831:0	info: response for ns4.google.com. AAAA IN
    Jul 10 13:11:01	unbound	85831:0	info: resolving com. DNSKEY IN
    Jul 10 13:11:01	unbound	85831:0	info: validated DS com. DS IN
    Jul 10 13:11:01	unbound	85831:0	info: query response was ANSWER
    Jul 10 13:11:01	unbound	85831:0	info: reply from <google.com.> 216.239.34.10#53
    Jul 10 13:11:01	unbound	85831:0	info: response for google.com. A IN
    Jul 10 13:11:01	unbound	85831:0	info: query response was nodata ANSWER
    Jul 10 13:11:01	unbound	85831:0	info: reply from <google.com.> 216.239.38.10#53
    Jul 10 13:11:01	unbound	85831:0	info: response for ns2.google.com. AAAA IN
    Jul 10 13:11:01	unbound	85831:1	info: resolving files00.netgate.com. A IN
    Jul 10 13:11:01	unbound	85831:1	info: Verified that unsigned response is INSECURE
    Jul 10 13:11:01	unbound	85831:1	info: NSEC3s for the referral proved no DS.
    Jul 10 13:11:01	unbound	85831:1	info: query response was ANSWER
    Jul 10 13:11:01	unbound	85831:1	info: reply from <pfsense.org.> 192.207.126.6#53
    Jul 10 13:11:01	unbound	85831:1	info: response for _https._tcp.beta.pfsense.org. SRV IN
    Jul 10 13:11:01	unbound	85831:0	info: resolving ns1.google.com. AAAA IN
    Jul 10 13:11:01	unbound	85831:0	info: resolving ns4.google.com. AAAA IN
    Jul 10 13:11:01	unbound	85831:0	info: resolving ns3.google.com. AAAA IN
    Jul 10 13:11:01	unbound	85831:0	info: resolving ns2.google.com. AAAA IN
    Jul 10 13:11:01	unbound	85831:0	info: query response was REFERRAL
    Jul 10 13:11:01	unbound	85831:0	info: reply from <com.> 192.55.83.30#53
    Jul 10 13:11:01	unbound	85831:0	info: response for google.com. A IN
    Jul 10 13:11:01	unbound	85831:1	info: resolving _https._tcp.beta.pfsense.org. SRV IN
    Jul 10 13:11:01	unbound	85831:0	info: resolving google.com. A IN
    Jul 10 13:11:01	unbound	85831:0	info: validation success google.com.localdomain. AAAA IN
    Jul 10 13:11:01	unbound	85831:0	info: validate(nxdomain): sec_status_secure
    Jul 10 13:11:01	unbound	85831:0	info: query response was NXDOMAIN ANSWER
    Jul 10 13:11:01	unbound	85831:0	info: reply from <.> 2001:500:a8::e#53
    Jul 10 13:11:01	unbound	85831:0	info: response for google.com.localdomain. AAAA IN
    Jul 10 13:11:01	unbound	85831:0	info: resolving google.com.localdomain. AAAA IN
    Jul 10 13:11:01	unbound	85831:0	info: validation success google.com.localdomain. A IN
    Jul 10 13:11:01	unbound	85831:0	info: validate(nxdomain): sec_status_secure
    Jul 10 13:11:01	unbound	85831:0	info: query response was NXDOMAIN ANSWER
    Jul 10 13:11:01	unbound	85831:0	info: reply from <.> 192.5.5.241#53
    Jul 10 13:11:01	unbound	85831:0	info: response for google.com.localdomain. A IN
    Jul 10 13:11:01	unbound	85831:0	info: resolving google.com.localdomain. A IN
    Jul 10 13:10:52	unbound	85831:0	info: Verified that unsigned response is INSECURE
    Jul 10 13:10:52	unbound	85831:0	info: NSEC3s for the referral proved no DS.
    Jul 10 13:10:52	unbound	85831:0	info: Verified that unsigned response is INSECURE
    Jul 10 13:10:52	unbound	85831:0	info: NSEC3s for the referral proved no DS.
    Jul 10 13:10:52	unbound	85831:0	info: validated DNSKEY org. DNSKEY IN
    Jul 10 13:10:52	unbound	85831:0	info: validated DNSKEY org. DNSKEY IN
    Jul 10 13:10:52	unbound	85831:0	info: query response was ANSWER
    Jul 10 13:10:52	unbound	85831:0	info: reply from <org.> 2001:500:e::1#53
    Jul 10 13:10:52	unbound	85831:0	info: response for org. DNSKEY IN
    Jul 10 13:10:52	unbound	85831:0	info: resolving org. DNSKEY IN
    Jul 10 13:10:52	unbound	85831:0	info: validated DS org. DS IN
    Jul 10 13:10:52	unbound	85831:0	info: validated DS org. DS IN
    Jul 10 13:10:52	unbound	85831:0	info: Successfully primed trust anchor . DNSKEY IN
    Jul 10 13:10:52	unbound	85831:0	info: validate keys with anchor(DS): sec_status_secure
    Jul 10 13:10:52	unbound	85831:1	info: resolving org. DNSKEY IN
    Jul 10 13:10:52	unbound	85831:1	info: validated DS org. DS IN
    Jul 10 13:10:52	unbound	85831:1	info: validated DS org. DS IN
    Jul 10 13:10:52	unbound	85831:1	info: Successfully primed trust anchor . DNSKEY IN
    Jul 10 13:10:52	unbound	85831:1	info: validate keys with anchor(DS): sec_status_secure
    Jul 10 13:10:52	unbound	85831:0	info: Successfully primed trust anchor . DNSKEY IN
    Jul 10 13:10:52	unbound	85831:0	info: validate keys with anchor(DS): sec_status_secure
    Jul 10 13:10:52	unbound	85831:1	info: Successfully primed trust anchor . DNSKEY IN
    Jul 10 13:10:52	unbound	85831:1	info: validate keys with anchor(DS): sec_status_secure
    Jul 10 13:10:52	unbound	85831:0	info: query response was ANSWER
    Jul 10 13:10:52	unbound	85831:0	info: reply from <.> 198.97.190.53#53
    Jul 10 13:10:52	unbound	85831:0	info: response for . DNSKEY IN
    Jul 10 13:10:52	unbound	85831:1	info: query response was ANSWER
    Jul 10 13:10:52	unbound	85831:1	info: reply from <.> 2001:500:12::d0d#53
    Jul 10 13:10:52	unbound	85831:1	info: response for . DNSKEY IN
    Jul 10 13:10:51	unbound	85831:1	info: query response was nodata ANSWER
    Jul 10 13:10:51	unbound	85831:1	info: reply from <netgate.com.> 2610:160:11:3::6#53
    Jul 10 13:10:51	unbound	85831:1	info: response for ns1.netgate.com. AAAA IN
    Jul 10 13:10:51	unbound	85831:0	info: prime trust anchor
    Jul 10 13:10:51	unbound	85831:0	info: query response was ANSWER
    Jul 10 13:10:51	unbound	85831:0	info: reply from <pfsense.org.> 162.208.119.38#53
    Jul 10 13:10:51	unbound	85831:0	info: response for forum.pfsense.org. A IN
    Jul 10 13:10:51	unbound	85831:1	info: query response was ANSWER
    Jul 10 13:10:51	unbound	85831:1	info: reply from <netgate.com.> 192.207.126.6#53
    Jul 10 13:10:51	unbound	85831:1	info: response for ns1.netgate.com. A IN
    Jul 10 13:10:51	unbound	85831:1	info: prime trust anchor
    Jul 10 13:10:51	unbound	85831:1	info: query response was ANSWER
    Jul 10 13:10:51	unbound	85831:1	info: reply from <pfsense.org.> 162.208.119.38#53
    Jul 10 13:10:51	unbound	85831:1	info: response for forum.pfsense.org. AAAA IN
    Jul 10 13:10:51	unbound	85831:0	info: resolving . DNSKEY IN
    Jul 10 13:10:51	unbound	85831:0	info: prime trust anchor
    Jul 10 13:10:51	unbound	85831:0	info: query response was ANSWER
    Jul 10 13:10:51	unbound	85831:0	info: reply from <pfsense.org.> 2610:1c1:3::108#53
    Jul 10 13:10:51	unbound	85831:0	info: response for forum.pfsense.org. AAAA IN
    Jul 10 13:10:51	unbound	85831:1	info: resolving . DNSKEY IN
    Jul 10 13:10:51	unbound	85831:1	info: prime trust anchor
    Jul 10 13:10:51	unbound	85831:1	info: query response was ANSWER
    Jul 10 13:10:51	unbound	85831:1	info: reply from <pfsense.org.> 162.208.119.38#53
    Jul 10 13:10:51	unbound	85831:1	info: response for forum.pfsense.org. A IN
    Jul 10 13:10:51	unbound	85831:1	info: query response was nodata ANSWER
    Jul 10 13:10:51	unbound	85831:1	info: reply from <netgate.com.> 192.207.126.6#53
    Jul 10 13:10:51	unbound	85831:1	info: response for ns2.netgate.com. AAAA IN
    Jul 10 13:10:51	unbound	85831:1	info: query response was REFERRAL
    Jul 10 13:10:51	unbound	85831:1	info: reply from <com.> 2001:500:856e::30#53
    Jul 10 13:10:51	unbound	85831:1	info: response for ns1.netgate.com. AAAA IN
    Jul 10 13:10:51	unbound	85831:1	info: query response was REFERRAL
    Jul 10 13:10:51	unbound	85831:1	info: reply from <com.> 192.55.83.30#53
    Jul 10 13:10:51	unbound	85831:1	info: response for ns1.netgate.com. A IN
    Jul 10 13:10:51	unbound	85831:0	info: query response was REFERRAL
    Jul 10 13:10:51	unbound	85831:0	info: reply from <org.> 2001:500:c::1#53
    Jul 10 13:10:51	unbound	85831:0	info: response for forum.pfsense.org. A IN
    Jul 10 13:10:51	unbound	85831:1	info: query response was ANSWER
    Jul 10 13:10:51	unbound	85831:1	info: reply from <netgate.com.> 2610:160:11:3::6#53
    Jul 10 13:10:51	unbound	85831:1	info: response for ns2.netgate.com. A IN
    Jul 10 13:10:51	unbound	85831:0	info: query response was REFERRAL
    Jul 10 13:10:51	unbound	85831:0	info: reply from <org.> 199.249.112.1#53
    Jul 10 13:10:51	unbound	85831:0	info: response for forum.pfsense.org. AAAA IN
    Jul 10 13:10:51	unbound	85831:0	info: query response was REFERRAL
    Jul 10 13:10:51	unbound	858</org.></netgate.com.></org.></com.></com.></netgate.com.></pfsense.org.></pfsense.org.></pfsense.org.></netgate.com.></pfsense.org.></netgate.com.></org.></com.></pfsense.org.></google.com.></google.com.></google.com.></com.></google.com.></google.com.></google.com.></netgate.com.></netgate.com.>
    ```</ipv6>


  • Another test. I rebooted, found nslookup not working, restarted unbound and nslookup was working. So it seems to be related to rebooting, not necessarily the snapshot.


  • LAYER 8 Global Moderator

    Its possible your ipv6 is not coming up as fast as your ipv4?  Your dhcp with tracking on your interfaces?  Or maybe your ipv6 is changing on reboot?

    I looked into my error - doh!  Not my lan interface, my wan.. Which has no ipv6 on it so yeah makes sense why the error.  Changed it to no bind to link-local on wan and no more log spam ;)



  • @johnpoz:

    Its possible your ipv6 is not coming up as fast as your ipv4?  Your dhcp with tracking on your interfaces?  Or maybe your ipv6 is changing on reboot?

    I looked into my error - doh!  Not my lan interface, my wan.. Which has no ipv6 on it so yeah makes sense why the error.  Changed it to no bind to link-local on wan and no more log spam ;)

    It's definitely repeatable that the problem occurs after reboot and persists until unbound is restarted.

    I cleared the logs and rebooted. unbound and dhcp6c appear to be starting up concurrently. Maybe this is the problem.

    Here are log messages from unbound from after reboot to the first error:

    Jul 11 09:51:18	unbound	16498:1	info: error sending query to auth server 2001:500:84::b port 53
    Jul 11 09:51:18	unbound	16498:1	info: error sending query to auth server 2001:500:84::b port 53
    Jul 11 09:51:18	unbound	16498:1	info: priming . IN NS
    Jul 11 09:51:18	unbound	16498:1	info: resolving localdomain.localdomain. A IN
    Jul 11 09:51:18	unbound	16498:0	info: priming . IN NS
    Jul 11 09:51:18	unbound	16498:0	info: resolving localdomain.localdomain. AAAA IN
    Jul 11 09:51:14	unbound	16498:0	info: start of service (unbound 1.6.3).
    Jul 11 09:51:14	unbound	16498:0	notice: init module 1: iterator
    Jul 11 09:51:14	unbound	16498:0	notice: init module 0: validator
    

    Here are the first log messages from dhcp6c:

    Jul 11 09:51:15	dhcp6c	9281	add an address 2001:569:74c0:da00:215:5dff:fe5c:e21e/64 on hn0
    Jul 11 09:51:15	dhcp6c	9281	dhcp6c Received REQUEST
    Jul 11 09:51:15	dhcp6c	9281	Sending Request
    Jul 11 09:51:14	dhcp6c	9281	Sending Solicit
    Jul 11 09:51:13	dhcp6c	9249	skip opening control port
    Jul 11 09:51:13	dhcp6c	9249	failed initialize control message authentication
    Jul 11 09:51:13	dhcp6c	9249	failed to open /usr/local/etc/dhcp6cctlkey: No such file or directory
    


  • I should have added that my isp requires dhcpv6 solicit before RA.



  • I updated to the latest snapshot from today and after the reboot, the nslookup / dig problem was back. After restarting unbound, nslookup and dig worked properly. It seems to be a solid problem that restarting unbound is required after a reboot. This time, there were no errors in the log. Since most users do not require the do not wait for RA flag, possibly that's why this is occurring on my system. Are there any tests I should do or log info that I should post? Is this a bug?



  • I think it can be related to https://forum.pfsense.org/index.php?topic=133129.0 not directly but somehow…
    I don't see any other changes regarding unbound last days.



  • @w0w:

    I think it can be related to https://forum.pfsense.org/index.php?topic=133129.0 not directly but somehow…
    I don't see any other changes regarding unbound last days.

    This has been going on for more than a month, so it's not just from the past few days.



  • not on latest snapshot but am using 2.4, no issues with ipv6 lookups using unbound resolver.



  • I just updated and for the first time in a long time, nslookup and dig both worked without restarting unbound. However, I rebooted again to see if it would stick and unfortunately, both were broken again until after I restarted unbound.



  • I suggest you examine your logs to look for indicators of whats going on.

    In unbound settings, disable options to bind to specific interfaces (so it binds to everything) as that can cause the problem you are reporting, basically it starts before ipv6 is up so doesnt bind to it.



  • I noticed watching the console while the system was rebooting that unbound starts well before dhcpv6. I am using the do not wait for RA setting, so PD does not happen until dhcp6c starts. That may be a problem, because dhcp6c and unbound are starting almost concurrently, as you can see from the log messages (in reverse chronological order).

    All of the unbound settings are default. I have not enabled any options to bind to specific interfaces.

    Here are the first few log messages from unbound after booting (note error messages):

    Jul 18 18:44:30	unbound	23934:1	info: query response was ANSWER
    Jul 18 18:44:30	unbound	23934:1	info: reply from <.> 192.33.4.12#53
    Jul 18 18:44:30	unbound	23934:1	info: response for . DNSKEY IN
    Jul 18 18:44:30	unbound	23934:1	info: resolving . DNSKEY IN
    Jul 18 18:44:30	unbound	23934:1	info: prime trust anchor
    Jul 18 18:44:30	unbound	23934:1	info: query response was NXDOMAIN ANSWER
    Jul 18 18:44:30	unbound	23934:1	info: reply from <.> 192.33.4.12#53
    Jul 18 18:44:30	unbound	23934:1	info: response for localdomain. AAAA IN
    Jul 18 18:44:30	unbound	23934:1	info: priming successful for . NS IN
    Jul 18 18:44:30	unbound	23934:1	info: query response was ANSWER
    Jul 18 18:44:30	unbound	23934:1	info: reply from <.> 192.36.148.17#53
    Jul 18 18:44:30	unbound	23934:1	info: response for . NS IN
    Jul 18 18:44:29	unbound	23934:1	info: error sending query to auth server 2001:500:84::b port 53
    Jul 18 18:44:29	unbound	23934:1	info: error sending query to auth server 2001:500:1::53 port 53
    Jul 18 18:44:29	unbound	23934:1	info: error sending query to auth server 2001:500:2f::f port 53
    Jul 18 18:44:29	unbound	23934:1	info: priming . IN NS
    Jul 18 18:44:29	unbound	23934:1	info: resolving localdomain. AAAA IN
    Jul 18 18:44:27	unbound	23934:0	info: start of service (unbound 1.6.3).
    Jul 18 18:44:27	unbound	23934:0	notice: init module 1: iterator
    Jul 18 18:44:27	unbound	23934:0	notice: init module 0: validator
    

    Here are the first few log messages from dhcp after booting:

    Jul 18 18:44:28	dhcp6c	12378	add an address 2001:a:b:c:215:5dff:fe5c:e21e/64 on hn0
    Jul 18 18:44:28	dhcp6c	12378	dhcp6c Received REQUEST
    Jul 18 18:44:27	dhcp6c	12378	Sending Request
    Jul 18 18:44:26	dhcp6c	12378	Sending Solicit
    Jul 18 18:44:25	dhcp6c	12058	skip opening control port
    Jul 18 18:44:25	dhcp6c	12058	failed initialize control message authentication
    Jul 18 18:44:25	dhcp6c	12058	failed to open /usr/local/etc/dhcp6cctlkey: No such file or directory
    Jul 18 18:44:22	dhclient		Creating resolv.conf
    Jul 18 18:44:22	dhclient		/sbin/route add default 154.20.116.1
    Jul 18 18:44:22	dhclient		Adding new routes to interface: hn1
    Jul 18 18:44:22	dhclient		New Routers (hn1): 154.20.116.1
    Jul 18 18:44:22	dhclient		New Broadcast Address (hn1): 154.20.119.255
    Jul 18 18:44:22	dhclient		New Subnet Mask (hn1): 255.255.252.0
    Jul 18 18:44:22	dhclient		New IP Address (hn1): 154.20.118.8
    Jul 18 18:44:22	dhclient		ifconfig hn1 inet 154.20.118.8 netmask 255.255.252.0 broadcast 154.20.119.255
    Jul 18 18:44:22	dhclient		Starting add_new_address()
    Jul 18 18:44:22	dhclient		REBOOT
    Jul 18 18:44:22	dhclient		PREINIT
    

    Here are the first few log messages from unbound after restarting unbound (note no error messages):

    Jul 18 18:47:35	unbound	90108:1	info: query response was REFERRAL
    Jul 18 18:47:35	unbound	90108:1	info: reply from <.> 198.97.190.53#53
    Jul 18 18:47:35	unbound	90108:1	info: response for ns1.netgate.com. AAAA IN
    Jul 18 18:47:35	unbound	90108:1	info: query response was REFERRAL
    Jul 18 18:47:35	unbound	90108:1	info: reply from <.> 2001:7fd::1#53
    Jul 18 18:47:35	unbound	90108:1	info: response for ns1.netgate.com. A IN
    Jul 18 18:47:34	unbound	90108:1	info: query response was REFERRAL
    Jul 18 18:47:34	unbound	90108:1	info: reply from <.> 2001:500:12::d0d#53
    Jul 18 18:47:34	unbound	90108:1	info: response for ns2.netgate.com. A IN
    Jul 18 18:47:34	unbound	90108:1	info: resolving ns1.netgate.com. A IN
    Jul 18 18:47:34	unbound	90108:1	info: resolving ns2.netgate.com. AAAA IN
    Jul 18 18:47:34	unbound	90108:1	info: resolving ns2.netgate.com. A IN
    Jul 18 18:47:34	unbound	90108:1	info: resolving ns1.netgate.com. AAAA IN
    Jul 18 18:47:34	unbound	90108:1	info: query response was REFERRAL
    Jul 18 18:47:34	unbound	90108:1	info: reply from <org.> 2001:500:e::1#53
    Jul 18 18:47:34	unbound	90108:1	info: response for _https._tcp.beta.pfsense.org. SRV IN
    Jul 18 18:47:34	unbound	90108:1	info: query response was REFERRAL
    Jul 18 18:47:34	unbound	90108:1	info: reply from <.> 192.5.5.241#53
    Jul 18 18:47:34	unbound	90108:1	info: response for _https._tcp.beta.pfsense.org. SRV IN
    Jul 18 18:47:34	unbound	90108:1	info: priming successful for . NS IN
    Jul 18 18:47:34	unbound	90108:1	info: query response was ANSWER
    Jul 18 18:47:34	unbound	90108:1	info: reply from <.> 2001:500:12::d0d#53
    Jul 18 18:47:34	unbound	90108:1	info: response for . NS IN
    Jul 18 18:47:34	unbound	90108:1	info: priming . IN NS
    Jul 18 18:47:34	unbound	90108:1	info: resolving _https._tcp.beta.pfsense.org. SRV IN
    Jul 18 18:47:32	unbound	90108:0	info: start of service (unbound 1.6.3).
    Jul 18 18:47:32	unbound	90108:0	notice: init module 1: iterator
    Jul 18 18:47:32	unbound	90108:0	notice: init module 0: validator</org.>
    


  • It would not be difficult to force Unbound to restart on a valid update from dhcp6c, the changes implemented a while back means that it's now possible to differentiate between an a refresh or new lease. However, Chris was having a lot of issues with unbound that I think are now fine and I am not sure if an Unbound restart on a new lease might bring his problems back.

    If you like, I can have a look and send out a patch to you and Chris to see if it works for both of you.

    The other option is a flag to enable or disable an unbound restart on a new ipv6 lease.

    Thoughts.



  • please no :)

    unbound restarting on every dhcp6 renew is crazy.

    As long as the renew keeps the same prefix/ip I dont see why unbound would have a problem.

    Martin I will test the patch tho.  As I expect a new lease wont be triggered on a renew, as long as you also exclude a rebind.



  • :) I did not intend to restart it on a renew or rebind, that would be silly.



  • yeah I know you will find a solution that works for everyone, email me when ready with the patch I will test no problem. :)

    Your optional flag seems a good idea.



  • I'll try and find time tomorrow… if I can stop playing Elite Dangerous :o



  • Something else is afoot here. I have rebooted multiple times, using dhcp6 before RA, and I cannot make it fall over.

    Bimmer, is it possible that sometimes there is a slow response from your ISP for the v6 lease, hence the 'sometimes' its OK?

    It maybe that if that is the case that there is a bit of a catch 22 going on, in that rc.newwanipv6 cannot restart unbound as it's still in the booting up process. Also, and I've not delved into that bit of the code before, unbound is being killed and restarted, if already running, rather than a SIGHUP; I need to study that a bit more to see if there is a reason for that.

    • note *

    Having studied and read Jimp's note that unbound should be killed then that answers that question. Whilst there is already work going on in this area I will not mess with it, too many cooks….



  • Sorry for the slow response. I've been away all week… I'll try running wireshark to see what's happening. I suspect it will the same as it always was. I have a suspicion this problem has been present all along, but I haven't noticed it because unbound was getting restarted so often. Possibly now that it's not getting restarted, the problem is visible. That would explain why I didn't notice it before recently, along with the other changes.



  • I captured icmpv6 and dhcpv6 packets with wireshark during a reboot. Everything appears the way it always has. There are no significant delays in any of the replies.




  • I created bug #7750 "unbound refuses ipv6 queries after reboot" for this issue.



  • I just did another reboot to capture log info. It's consistent that unbound starts before the PD process has completed.

    Aug 2 13:12:15	dhcp6c	11947	add an address 2001:*:*:*:215:5dff:fe5c:e21e/64 on hn0
    Aug 2 13:12:15	dhcp6c	11947	dhcp6c Received REQUEST
    Aug 2 13:12:15	dhcp6c	11947	Sending Request
    Aug 2 13:12:14	dhcp6c	11947	Sending Solicit
    Aug 2 13:12:13	dhcp6c	11867	skip opening control port
    Aug 2 13:12:13	dhcp6c	11867	failed initialize control message authentication
    Aug 2 13:12:13	dhcp6c	11867	failed to open /usr/local/etc/dhcp6cctlkey: No such file or directory
    
    Aug 2 13:12:27	unbound	24093:1	info: response for . NS IN
    Aug 2 13:12:27	unbound	24093:1	info: priming . IN NS
    Aug 2 13:12:27	unbound	24093:1	info: resolving ipv6.msftconnecttest.com. A IN
    Aug 2 13:12:27	unbound	24093:1	info: priming . IN NS
    Aug 2 13:12:27	unbound	24093:1	info: resolving ipv6.msftconnecttest.com. AAAA IN
    Aug 2 13:12:27	unbound	24093:1	info: priming . IN NS
    Aug 2 13:12:27	unbound	24093:1	info: resolving 0.pfsense.pool.ntp.org. A IN
    Aug 2 13:12:14	unbound	24093:0	info: start of service (unbound 1.6.3).
    Aug 2 13:12:14	unbound	24093:0	notice: init module 1: iterator
    Aug 2 13:12:14	unbound	24093:0	notice: init module 0: validator
    


  • I've been trying to recreate this, as I'm also on Telus using dhcp6c before RA, but so far no luck, if I reboot from an upgrade or otherwise, everything still works fine. For curiosity sake, I even looked to see when my unbound is starting and it happens after I get my prefix. I'm running on the latest 2.4 snapshot. I'm in AB on FTTH with the T3200M bridged to port1 with a bare metal install on an SG-2440.

    
    Aug 2 17:10:24 	dhcp6c 	23456 	dhcp6c Received REQUEST
    Aug 2 17:10:24 	dhcp6c 	23456 	nameserver[0] 2001:568:ff09:10c::53
    Aug 2 17:10:24 	dhcp6c 	23456 	nameserver[1] 2001:568:ff09:10b::122
    Aug 2 17:10:24 	dhcp6c 	23456 	make an IA: PD-0
    Aug 2 17:10:24 	dhcp6c 	23456 	create a prefix 2001:56a:73d0:3c00::/56 pltime=140733193402432, vltime=14700
    Aug 2 17:10:24 	dhcp6c 	23456 	add an address 2001:56a:73d0:3c01:208:a3ff:fe0a:5ad6/64 on igb1_vlan101
    Aug 2 17:10:24 	dhcp6c 	23456 	executes /var/etc/dhcp6c_wan_dhcp6withoutra_script.sh 
    
    Aug 2 17:10:29 	unbound 	48227:0 	notice: init module 0: validator
    Aug 2 17:10:29 	unbound 	48227:0 	notice: init module 1: iterator
    Aug 2 17:10:29 	unbound 	48227:0 	info: start of service (unbound 1.6.3). 
    Aug 2 17:10:30 	unbound 	48227:0 	info: resolving s.youtube.com. A IN 
    


  • That's really strange. Your dhcp6c is running well ahead of mine, relative to unbound.

    I was on a T2200H but just switched to a T3200M. I didn't expect it would make any difference and it didn't.

    All unbound settings are default.

    I've tried a clean install in a fresh VM (running on hyper-v), but that didn't make any difference either.

    ![Capture 1.PNG_thumb](/public/imported_attachments/1/Capture 1.PNG_thumb)
    ![Capture 1.PNG](/public/imported_attachments/1/Capture 1.PNG)
    ![Capture 2.PNG](/public/imported_attachments/1/Capture 2.PNG)
    ![Capture 2.PNG_thumb](/public/imported_attachments/1/Capture 2.PNG_thumb)



  • I enabled dhcp debug mode to see if there would be any earlier messages.

    Here are the first messages (newest at the top):

    Aug 2 18:09:14	dhcp6c	11792	failed initialize control message authentication
    Aug 2 18:09:14	dhcp6c	11792	failed to open /usr/local/etc/dhcp6cctlkey: No such file or directory
    Aug 2 18:09:14	dhcp6c	11792	extracted an existing DUID from /var/db/dhcp6c_duid: 00:01:00:01:20:d5:a4:23:00:15:5d:5c:e2:1e
    

    Here are the last messages:

    Aug 2 18:09:19	dhcp6c	11840	got an expected reply, sleeping.
    Aug 2 18:09:19	dhcp6c	11840	removing server (ID: 00:03:00:01:0c:a4:02:29:50:01)
    Aug 2 18:09:19	dhcp6c	11840	removing an event on hn1, state=REQUEST
    Aug 2 18:09:19	dhcp6c	11840	script "/var/etc/dhcp6c_wan_dhcp6withoutra_script.sh" terminated
    Aug 2 18:09:19	dhcp6c		dhcp6c REQUEST on hn1 - running rc.newwanipv6
    Aug 2 18:09:17	dhcp6c	11840	executes /var/etc/dhcp6c_wan_dhcp6withoutra_script.sh
    Aug 2 18:09:17	dhcp6c	11840	add an address 2001:*:*:*:215:5dff:fe5c:e21e/64 on hn0
    Aug 2 18:09:17	dhcp6c	11840	create a prefix 2001:*:*:*::/56 pltime=140733193402432, vltime=14700
    Aug 2 18:09:17	dhcp6c	11840	make an IA: PD-0
    Aug 2 18:09:17	dhcp6c	11840	nameserver[1] 2001:568:ff09:10b::122
    Aug 2 18:09:17	dhcp6c	11840	nameserver[0] 2001:568:ff09:10a::55
    Aug 2 18:09:17	dhcp6c	11840	dhcp6c Received REQUEST
    

    Here are the first unbound messages:

    Aug 2 18:09:16	unbound	24030:0	info: start of service (unbound 1.6.3).
    Aug 2 18:09:16	unbound	24030:0	notice: init module 1: iterator
    Aug 2 18:09:16	unbound	24030:0	notice: init module 0: validator
    


  • It would appear that something is odd with your system Bimmer, otherwise Chris and Ned over here would be suffering also, and they are not having any issues.

    Time for you and Scott to do some comparisons :)

    So, let's start with the basics, Scott, what are you running pfSense  on?



  • @marjohn56:

    It would appear that something is odd with your system Bimmer, otherwise Chris and Ned over here would be suffering also, and they are not having any issues.

    Time for you and Scott to do some comparisons :)

    So, let's start with the basics, Scott, what are you running pfSense  on?

    Something is strange, that's for sure.

    Do you notice these messages in the dhcp log? They are the very first dhcp6c messages

    Aug 3 13:38:05	dhcp6c	10883	failed initialize control message authentication
    Aug 3 13:38:05	dhcp6c	10883	failed to open /usr/local/etc/dhcp6cctlkey: No such file or directory
    Aug 3 13:38:05	dhcp6c	10883	extracted an existing DUID from /var/db/dhcp6c_duid: 00:01:00:01:20:d5:a4:23:00:15:5d:5c:e2:1e
    Aug 3 13:38:02	dhclient		Creating resolv.conf
    

    I'm wondering if perhaps they are slowing down the execution of dhcp6c.



  • @marjohn56:

    So, let's start with the basics, Scott, what are you running pfSense  on?

    I'm running it on an official pfSense (Negate) SG-2440 appliance.

    @bimmerdriver:

    Do you notice these messages in the dhcp log? They are the very first dhcp6c messages

    I believe I have these messages in my log too, I will confirm and post when I get home from work.



  • Ignore those messages, they are in everyone's log and have been since day one. dhcp6c is looking for the a key that does not exist and will not exist as pfSense does not use that method of control, it's just noise in the log. I could stop it but it really is nothing.



  • @marjohn56:

    Ignore those messages, they are in everyone's log and have been since day one. dhcp6c is looking for the a key that does not exist and will not exist as pfSense does not use that method of control, it's just noise in the log. I could stop it but it really is nothing.

    If they are normal, I don't care that they are there. I was just wondering if dhcp6c was blocking momentarily because of some issue.



  • @scott83:

    @marjohn56:

    So, let's start with the basics, Scott, what are you running pfSense  on?

    I'm running it on an official pfSense (Negate) SG-2440 appliance.

    I'm running on a hyper-v server. The guest has 2000 MB of RAM and 2 processors. It's basically idling. The server is lightly loaded.

    @scott83:

    @bimmerdriver:

    Do you notice these messages in the dhcp log? They are the very first dhcp6c messages

    I believe I have these messages in my log too, I will confirm and post when I get home from work.

    It sounds like they are a non-issue.



  • @marjohn56:

    It would appear that something is odd with your system Bimmer, otherwise Chris and Ned over here would be suffering also, and they are not having any issues.

    Here is some further info that makes me wonder why dhcp6c and unbound messages start to appear in the log around the same time during the reboot. Not clear what is happening during the "Configuring WAN interface…done." phase, but it's a few steps before unbound is started, yet dhcp6c is only barely into the startup phase by the time unbound is starting.

    ![pfsense console.PNG](/public/imported_attachments/1/pfsense console.PNG)
    ![pfsense console.PNG_thumb](/public/imported_attachments/1/pfsense console.PNG_thumb)



  • And here are a few more log messages from general:

    Aug 4 09:19:22	php-fpm	291	/rc.newwanipv6: Removing static route for monitor fe80::ea4:2ff:fe29:5001 and adding a new route through fe80::ea4:2ff:fe29:5001%hn1
    Aug 4 09:19:22	php-fpm	291	/rc.newwanipv6: ROUTING: setting IPv6 default route to fe80::ea4:2ff:fe29:5001%hn1
    Aug 4 09:19:22	php-fpm	291	/rc.newwanipv6: ROUTING: setting default route to 154.20.116.1
    Aug 4 09:19:22	php-fpm	291	/rc.newwanipv6: rc.newwanipv6: on (IP address: fe80::215:5dff:fe5c:e21d%hn1) (interface: wan) (real interface: hn1).
    Aug 4 09:19:22	php-fpm	291	/rc.newwanipv6: rc.newwanipv6: Info: starting on hn1.
    Aug 4 09:19:21	rtsold		Received RA specifying route fe80::ea4:2ff:fe29:5001 for interface wan(hn1)
    Aug 4 09:19:17	kernel		done.
    Aug 4 09:19:16	php-cgi		rc.bootup: ROUTING: setting default route to 154.20.116.1
    Aug 4 09:19:16	kernel		.done.
    Aug 4 09:19:15	kernel		pflog0: promiscuous mode enabled
    Aug 4 09:19:15	php-cgi		rc.bootup: Resyncing OpenVPN instances.
    Aug 4 09:19:15	kernel		hn0: link state changed to UP
    Aug 4 09:19:15	check_reload_status		Linkup starting hn0
    Aug 4 09:19:15	php-cgi		rc.bootup: Starting dhcp6 client for interface wan hn1 in DHCP6 without RA mode
    

    The first unbound log message appeared at 09:19:17.



  • scrapped my post as you already said its defaults, I would follow the advice given and compare ipv6 settings.



  • I'm using the same ipv6 settings that I've been using for months which are correct for my ISP. The only variable is whether or not to send a prefix hint and that makes no difference. Without the other settings are they are, the PD process will not complete.

    I had thought this was a new problem since the other recent changes to unbound, but I restarted my 2.3.4 system and noticed it does the same thing. As I said before, I think this slipped through the cracks before because unbound used to restart so often on its own. However, when I rebooted my 2.3.4 system, I checked nslookup google.com immediately after booting and it failed. After restarting unbound, it worked.

    Unless someone has another explanation, this problem appears to be caused by unbound starting before the PD process is complete.



  • I did a couple more packet captures with wireshark, two reboots from the 2.3.4 system and two from the 2.4 beta system.

    The 2.3.4 system took 2.34 seconds and 1.36 seconds. The 2.4 beta system took 4.84 seconds both times.

    Both systems have identical WAN ipv6 settings. It's interesting to notice that pfsense 2.3.4 appears to send the RS after sending the second dhcp request before the reply is received, rather than apparently waiting for the reply as pfsense 2.4 beta does. I have never noticed this behaviour before. It could be a coincidence.

    You can see that the link-local address of the edge router is the same in both cases, so any difference is from pfsense, not the edge router.



    ![2.4 B.PNG](/public/imported_attachments/1/2.4 B.PNG)
    ![2.4 B.PNG_thumb](/public/imported_attachments/1/2.4 B.PNG_thumb)



  • When I get some time to play I'll put something together for you. Don't know when that will be as real work is exceptionally busy at the moment.



  • I've issued a PR for this.



  • I installed the PR and I'm happy to confirm that it works perfectly.

    So you can see it in action, here are some log messages:

    Aug 11 10:23:32	php-cgi		rc.bootup: sync unbound done.
    Aug 11 10:23:31	php-cgi		rc.bootup: dhcp6 init complete. Continuing
    Aug 11 10:23:30	php-fpm	291	/rc.newwanipv6: Removing static route for monitor fe80::ea4:2ff:fe29:5001 and adding a new route through fe80::ea4:2ff:fe29:5001%hn1
    Aug 11 10:23:30	php-fpm	291	/rc.newwanipv6: ROUTING: setting IPv6 default route to fe80::ea4:2ff:fe29:5001%hn1
    Aug 11 10:23:30	php-fpm	291	/rc.newwanipv6: ROUTING: setting default route to *.*.116.1
    Aug 11 10:23:30	php-fpm	291	/rc.newwanipv6: rc.newwanipv6: on (IP address: fe80::215:5dff:fe5c:e21d%hn1) (interface: wan) (real interface: hn1).
    Aug 11 10:23:30	php-fpm	291	/rc.newwanipv6: rc.newwanipv6: Info: starting on hn1.
    Aug 11 10:23:30	php-cgi		rc.bootup: Unbound start waiting on dhcp6c.
    Aug 11 10:23:29	rtsold		Received RA specifying route fe80::ea4:2ff:fe29:5001 for interface wan(hn1)
    Aug 11 10:23:29	php-cgi		rc.bootup: Unbound start waiting on dhcp6c.
    Aug 11 10:23:28	php-cgi		rc.bootup: Unbound start waiting on dhcp6c.
    Aug 11 10:23:27	php-cgi		rc.bootup: Unbound start waiting on dhcp6c.
    Aug 11 10:23:33	php-cgi		rc.bootup: Unbound start waiting on dhcp6c.
    Aug 11 10:23:32	php-cgi		rc.bootup: Unbound start waiting on dhcp6c.
    Aug 11 10:23:31	php-cgi		rc.bootup: Unbound start waiting on dhcp6c.
    Aug 11 10:23:31	php-cgi		rc.bootup: ROUTING: setting default route to 154.20.116.1
    Aug 11 10:23:30	php-cgi		rc.bootup: Resyncing OpenVPN instances.
    Aug 11 10:23:30	kernel		hn0: link state changed to UP
    Aug 11 10:23:30	check_reload_status		Linkup starting hn0
    Aug 11 10:23:30	php-cgi		rc.bootup: Starting dhcp6 client for interface wan hn1 in DHCP6 without RA mode
    Aug 11 10:23:28	php-fpm	291	/rc.newwanip: rc.newwanip: on (IP address: *.*.118.8) (interface: WAN[wan]) (real interface: hn1).
    Aug 11 10:23:28	php-fpm	291	/rc.newwanip: rc.newwanip: Info: starting on hn1.
    Aug 11 10:23:27	php-cgi		rc.bootup: Accept router advertisements on interface hn1
    Aug 11 10:23:27	php-cgi		rc.bootup: calling interface_dhcpv6_configure.
    Aug 11 10:23:27	check_reload_status		rc.newwanip starting hn1
    

    Thank you very much for fixing this problem.


Log in to reply