Date: Wed, 6 Sep 2017 11:19:40 -0400 From: "James B. Byrne" <byrnejb@harte-lyne.ca> To: freebsd-questions@freebsd.org Subject: local_unbound stops resolving Message-ID: <fea1d9558be2a5cc125a07937451fc46.squirrel@webmail.harte-lyne.ca>
next in thread | raw e-mail | index | archive | help
The problem that I am having on my desktop FreeBSD-11.0p12 is still
with me and I have confirmed that the system time is correct. This
issue only arises with our own domain (harte-lyne.ca). Below are two
debug logs for the same query (drill inet02.hamilton.harte-lyne.ca).
The first is when the problem is exhibited. The second immediately
after local_unbound is restarted.
Before restart:
# drill inet02.hamilton.harte-lyne.ca
;; ->>HEADER<<- opcode: QUERY, rcode: SERVFAIL, id: 36528
;; flags: qr rd ra ; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0
;; QUESTION SECTION:
;; inet02.hamilton.harte-lyne.ca. IN A
. . .
;; Query time: 11 msec
;; SERVER: 127.0.0.1
;; WHEN: Wed Sep 6 11:05:15 2017
;; MSG SIZE rcvd: 47
Debug Log:
Sep 06 11:05:15 unbound[480:0] info: 127.0.0.1
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] debug: validator[module 0] operate:
extstate:module_state_initial event:module_event_new
Sep 06 11:05:15 unbound[480:0] info: validator operate: query
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] debug: iterator[module 1] operate:
extstate:module_state_initial event:module_event_pass
Sep 06 11:05:15 unbound[480:0] info: resolving
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: processQueryTargets:
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: sending query:
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] debug: sending to target: <.>
216.185.71.34#53
Sep 06 11:05:15 unbound[480:0] debug: cache memory msg=247278
rrset=366210 infra=3130 val=104617
Sep 06 11:05:15 unbound[480:0] debug: iterator[module 1] operate:
extstate:module_wait_reply event:module_event_reply
Sep 06 11:05:15 unbound[480:0] info: iterator operate: query
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: response for
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: reply from <.> 216.185.71.34#53
Sep 06 11:05:15 unbound[480:0] info: query response was ANSWER
Sep 06 11:05:15 unbound[480:0] info: finishing processing for
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] debug: validator[module 0] operate:
extstate:module_wait_module event:module_event_moddone
Sep 06 11:05:15 unbound[480:0] info: validator operate: query
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] debug: verify: could not find
appropriate key
Sep 06 11:05:15 unbound[480:0] info: validator: response has failed
ANSWER rrset: inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: Validate: message contains bad
rrsets
Sep 06 11:05:15 unbound[480:0] debug: iterator[module 1] operate:
extstate:module_finished event:module_event_pass
Sep 06 11:05:15 unbound[480:0] info: resolving
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: processQueryTargets:
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: sending query:
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] debug: sending to target: <.>
216.185.71.33#53
Sep 06 11:05:15 unbound[480:0] debug: cache memory msg=247278
rrset=366210 infra=3130 val=104617
Sep 06 11:05:15 unbound[480:0] debug: iterator[module 1] operate:
extstate:module_wait_reply event:module_event_reply
Sep 06 11:05:15 unbound[480:0] info: iterator operate: query
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: response for
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: reply from <.> 216.185.71.33#53
Sep 06 11:05:15 unbound[480:0] info: query response was ANSWER
Sep 06 11:05:15 unbound[480:0] info: finishing processing for
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] debug: validator[module 0] operate:
extstate:module_restart_next event:module_event_moddone
Sep 06 11:05:15 unbound[480:0] info: validator operate: query
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: validator operate: chased to .
TYPE0 CLASS0
Sep 06 11:05:15 unbound[480:0] debug: verify: could not find
appropriate key
Sep 06 11:05:15 unbound[480:0] info: validator: response has failed
ANSWER rrset: inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: Validate: message contains bad
rrsets
Sep 06 11:05:15 unbound[480:0] debug: iterator[module 1] operate:
extstate:module_finished event:module_event_pass
Sep 06 11:05:15 unbound[480:0] info: resolving
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: processQueryTargets:
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: sending query:
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] debug: sending to target: <.>
216.185.71.33#53
Sep 06 11:05:15 unbound[480:0] debug: cache memory msg=247278
rrset=366210 infra=3130 val=104617
Sep 06 11:05:15 unbound[480:0] debug: iterator[module 1] operate:
extstate:module_wait_reply event:module_event_reply
Sep 06 11:05:15 unbound[480:0] info: iterator operate: query
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: response for
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: reply from <.> 216.185.71.33#53
Sep 06 11:05:15 unbound[480:0] info: query response was ANSWER
Sep 06 11:05:15 unbound[480:0] info: finishing processing for
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] debug: validator[module 0] operate:
extstate:module_restart_next event:module_event_moddone
Sep 06 11:05:15 unbound[480:0] info: validator operate: query
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: validator operate: chased to .
TYPE0 CLASS0
Sep 06 11:05:15 unbound[480:0] debug: verify: could not find
appropriate key
Sep 06 11:05:15 unbound[480:0] info: validator: response has failed
ANSWER rrset: inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: Validate: message contains bad
rrsets
Sep 06 11:05:15 unbound[480:0] debug: iterator[module 1] operate:
extstate:module_finished event:module_event_pass
Sep 06 11:05:15 unbound[480:0] info: resolving
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: processQueryTargets:
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: sending query:
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] debug: sending to target: <.>
216.185.71.34#53
Sep 06 11:05:15 unbound[480:0] debug: cache memory msg=247278
rrset=366210 infra=3130 val=104617
Sep 06 11:05:15 unbound[480:0] debug: iterator[module 1] operate:
extstate:module_wait_reply event:module_event_reply
Sep 06 11:05:15 unbound[480:0] info: iterator operate: query
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: response for
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: reply from <.> 216.185.71.34#53
Sep 06 11:05:15 unbound[480:0] info: query response was ANSWER
Sep 06 11:05:15 unbound[480:0] info: finishing processing for
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] debug: validator[module 0] operate:
extstate:module_restart_next event:module_event_moddone
Sep 06 11:05:15 unbound[480:0] info: validator operate: query
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: validator operate: chased to .
TYPE0 CLASS0
Sep 06 11:05:15 unbound[480:0] debug: verify: could not find
appropriate key
Sep 06 11:05:15 unbound[480:0] info: validator: response has failed
ANSWER rrset: inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: Validate: message contains bad
rrsets
Sep 06 11:05:15 unbound[480:0] debug: iterator[module 1] operate:
extstate:module_finished event:module_event_pass
Sep 06 11:05:15 unbound[480:0] info: resolving
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: processQueryTargets:
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: sending query:
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] debug: sending to target: <.>
216.185.71.33#53
Sep 06 11:05:15 unbound[480:0] debug: cache memory msg=247278
rrset=366210 infra=3130 val=104617
Sep 06 11:05:15 unbound[480:0] debug: iterator[module 1] operate:
extstate:module_wait_reply event:module_event_reply
Sep 06 11:05:15 unbound[480:0] info: iterator operate: query
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: response for
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: reply from <.> 216.185.71.33#53
Sep 06 11:05:15 unbound[480:0] info: query response was ANSWER
Sep 06 11:05:15 unbound[480:0] info: finishing processing for
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] debug: validator[module 0] operate:
extstate:module_restart_next event:module_event_moddone
Sep 06 11:05:15 unbound[480:0] info: validator operate: query
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: validator operate: chased to .
TYPE0 CLASS0
Sep 06 11:05:15 unbound[480:0] debug: verify: could not find
appropriate key
Sep 06 11:05:15 unbound[480:0] info: validator: response has failed
ANSWER rrset: inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: Validate: message contains bad
rrsets
Sep 06 11:05:15 unbound[480:0] debug: iterator[module 1] operate:
extstate:module_finished event:module_event_pass
Sep 06 11:05:15 unbound[480:0] info: resolving
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: processQueryTargets:
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: sending query:
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] debug: sending to target: <.>
216.185.71.33#53
Sep 06 11:05:15 unbound[480:0] debug: cache memory msg=247278
rrset=366210 infra=3130 val=104617
Sep 06 11:05:15 unbound[480:0] debug: iterator[module 1] operate:
extstate:module_wait_reply event:module_event_reply
Sep 06 11:05:15 unbound[480:0] info: iterator operate: query
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: response for
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: reply from <.> 216.185.71.33#53
Sep 06 11:05:15 unbound[480:0] info: query response was ANSWER
Sep 06 11:05:15 unbound[480:0] info: finishing processing for
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] debug: validator[module 0] operate:
extstate:module_restart_next event:module_event_moddone
Sep 06 11:05:15 unbound[480:0] info: validator operate: query
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: validator operate: chased to .
TYPE0 CLASS0
Sep 06 11:05:15 unbound[480:0] debug: verify: could not find
appropriate key
Sep 06 11:05:15 unbound[480:0] info: validator: response has failed
ANSWER rrset: inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: Validate: message contains bad
rrsets
Sep 06 11:05:15 unbound[480:0] debug: cache memory msg=247278
rrset=366210 infra=3130 val=104617
After restart (succeeds):
# service local_unbound restart
Stopping local_unbound.
Waiting for PIDS: 480.
Starting local_unbound.
Waiting for nameserver to start... good
# drill inet02.hamilton.harte-lyne.ca
;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 56386
;; flags: qr rd ra ; QUERY: 1, ANSWER: 1, AUTHORITY: 4, ADDITIONAL: 4
;; QUESTION SECTION:
;; inet02.hamilton.harte-lyne.ca. IN A
;; ANSWER SECTION:
inet02.hamilton.harte-lyne.ca. 172800 IN A 216.185.71.22
. . .
;; Query time: 38 msec
;; SERVER: 127.0.0.1
;; WHEN: Wed Sep 6 11:07:38 2017
;; MSG SIZE rcvd: 207
Debug Log:
Sep 06 11:07:38 unbound[10564:0] info: 127.0.0.1
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:07:38 unbound[10564:0] debug: validator[module 0] operate:
extstate:module_state_initial event:module_event_new
Sep 06 11:07:38 unbound[10564:0] info: validator operate: query
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:07:38 unbound[10564:0] debug: iterator[module 1] operate:
extstate:module_state_initial event:module_event_pass
Sep 06 11:07:38 unbound[10564:0] info: resolving
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:07:38 unbound[10564:0] info: processQueryTargets:
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:07:38 unbound[10564:0] info: sending query:
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:07:38 unbound[10564:0] debug: sending to target: <.>
216.185.71.33#53
Sep 06 11:07:38 unbound[10564:0] debug: cache memory msg=66072
rrset=66072 infra=2881 val=66280
Sep 06 11:07:38 unbound[10564:0] debug: iterator[module 1] operate:
extstate:module_wait_reply event:module_event_reply
Sep 06 11:07:38 unbound[10564:0] info: iterator operate: query
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:07:38 unbound[10564:0] info: response for
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:07:38 unbound[10564:0] info: reply from <.> 216.185.71.33#53
Sep 06 11:07:38 unbound[10564:0] info: query response was ANSWER
Sep 06 11:07:38 unbound[10564:0] info: finishing processing for
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:07:38 unbound[10564:0] debug: validator[module 0] operate:
extstate:module_wait_module event:module_event_moddone
Sep 06 11:07:38 unbound[10564:0] info: validator operate: query
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:07:38 unbound[10564:0] info: prime trust anchor
Sep 06 11:07:38 unbound[10564:0] debug: validator[module 0] operate:
extstate:module_state_initial event:module_event_pass
Sep 06 11:07:38 unbound[10564:0] info: validator operate: query .
DNSKEY IN
Sep 06 11:07:38 unbound[10564:0] debug: iterator[module 1] operate:
extstate:module_state_initial event:module_event_pass
Sep 06 11:07:38 unbound[10564:0] info: resolving . DNSKEY IN
Sep 06 11:07:38 unbound[10564:0] info: processQueryTargets: . DNSKEY IN
Sep 06 11:07:38 unbound[10564:0] info: sending query: . DNSKEY IN
Sep 06 11:07:38 unbound[10564:0] debug: sending to target: <.>
216.185.71.33#53
Sep 06 11:07:38 unbound[10564:0] debug: cache memory msg=66399
rrset=68718 infra=2881 val=66280
Sep 06 11:07:38 unbound[10564:0] debug: iterator[module 1] operate:
extstate:module_wait_reply event:module_event_reply
Sep 06 11:07:38 unbound[10564:0] info: iterator operate: query .
DNSKEY IN
Sep 06 11:07:38 unbound[10564:0] info: response for . DNSKEY IN
Sep 06 11:07:38 unbound[10564:0] info: reply from <.> 216.185.71.33#53
Sep 06 11:07:38 unbound[10564:0] info: query response was ANSWER
Sep 06 11:07:38 unbound[10564:0] info: finishing processing for .
DNSKEY IN
Sep 06 11:07:38 unbound[10564:0] debug: validator[module 0] operate:
extstate:module_wait_module event:module_event_moddone
Sep 06 11:07:38 unbound[10564:0] info: validator operate: query .
DNSKEY IN
Sep 06 11:07:38 unbound[10564:0] info: validate keys with anchor(DS):
sec_status_secure
Sep 06 11:07:38 unbound[10564:0] info: Successfully primed trust
anchor . DNSKEY IN
Sep 06 11:07:38 unbound[10564:0] debug: validator[module 0] operate:
extstate:module_wait_subquery event:module_event_pass
Sep 06 11:07:38 unbound[10564:0] info: validator operate: query
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:07:38 unbound[10564:0] debug: validator[module 0] operate:
extstate:module_state_initial event:module_event_pass
Sep 06 11:07:38 unbound[10564:0] info: validator operate: query ca. DS IN
Sep 06 11:07:38 unbound[10564:0] debug: iterator[module 1] operate:
extstate:module_state_initial event:module_event_pass
Sep 06 11:07:38 unbound[10564:0] info: resolving ca. DS IN
Sep 06 11:07:38 unbound[10564:0] info: processQueryTargets: ca. DS IN
Sep 06 11:07:38 unbound[10564:0] info: sending query: ca. DS IN
Sep 06 11:07:38 unbound[10564:0] debug: sending to target: <.>
216.185.71.34#53
Sep 06 11:07:38 unbound[10564:0] debug: cache memory msg=66576
rrset=70034 infra=3130 val=67628
Sep 06 11:07:38 unbound[10564:0] debug: iterator[module 1] operate:
extstate:module_wait_reply event:module_event_reply
Sep 06 11:07:38 unbound[10564:0] info: iterator operate: query ca. DS IN
Sep 06 11:07:38 unbound[10564:0] info: response for ca. DS IN
Sep 06 11:07:38 unbound[10564:0] info: reply from <.> 216.185.71.34#53
Sep 06 11:07:38 unbound[10564:0] info: query response was ANSWER
Sep 06 11:07:38 unbound[10564:0] info: finishing processing for ca. DS IN
Sep 06 11:07:38 unbound[10564:0] debug: validator[module 0] operate:
extstate:module_wait_module event:module_event_moddone
Sep 06 11:07:38 unbound[10564:0] info: validator operate: query ca. DS IN
Sep 06 11:07:38 unbound[10564:0] info: validated DS ca. DS IN
Sep 06 11:07:38 unbound[10564:0] debug: validator[module 0] operate:
extstate:module_wait_subquery event:module_event_pass
Sep 06 11:07:38 unbound[10564:0] info: validator operate: query
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:07:38 unbound[10564:0] debug: validator[module 0] operate:
extstate:module_state_initial event:module_event_pass
Sep 06 11:07:38 unbound[10564:0] info: validator operate: query ca.
DNSKEY IN
Sep 06 11:07:38 unbound[10564:0] debug: iterator[module 1] operate:
extstate:module_state_initial event:module_event_pass
Sep 06 11:07:38 unbound[10564:0] info: resolving ca. DNSKEY IN
Sep 06 11:07:38 unbound[10564:0] info: processQueryTargets: ca. DNSKEY IN
Sep 06 11:07:38 unbound[10564:0] info: sending query: ca. DNSKEY IN
Sep 06 11:07:38 unbound[10564:0] debug: sending to target: <.>
216.185.71.33#53
Sep 06 11:07:38 unbound[10564:0] debug: cache memory msg=66756
rrset=70545 infra=3130 val=67628
Sep 06 11:07:38 unbound[10564:0] debug: iterator[module 1] operate:
extstate:module_wait_reply event:module_event_reply
Sep 06 11:07:38 unbound[10564:0] info: iterator operate: query ca.
DNSKEY IN
Sep 06 11:07:38 unbound[10564:0] info: response for ca. DNSKEY IN
Sep 06 11:07:38 unbound[10564:0] info: reply from <.> 216.185.71.33#53
Sep 06 11:07:38 unbound[10564:0] info: query response was ANSWER
Sep 06 11:07:38 unbound[10564:0] info: finishing processing for ca.
DNSKEY IN
Sep 06 11:07:38 unbound[10564:0] debug: validator[module 0] operate:
extstate:module_wait_module event:module_event_moddone
Sep 06 11:07:38 unbound[10564:0] info: validator operate: query ca.
DNSKEY IN
Sep 06 11:07:38 unbound[10564:0] info: validated DNSKEY ca. DNSKEY IN
Sep 06 11:07:38 unbound[10564:0] debug: validator[module 0] operate:
extstate:module_wait_subquery event:module_event_pass
Sep 06 11:07:38 unbound[10564:0] info: validator operate: query
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:07:38 unbound[10564:0] debug: validator[module 0] operate:
extstate:module_state_initial event:module_event_pass
Sep 06 11:07:38 unbound[10564:0] info: validator operate: query
harte-lyne.ca. DS IN
Sep 06 11:07:38 unbound[10564:0] debug: iterator[module 1] operate:
extstate:module_state_initial event:module_event_pass
Sep 06 11:07:38 unbound[10564:0] info: resolving harte-lyne.ca. DS IN
Sep 06 11:07:38 unbound[10564:0] info: processQueryTargets:
harte-lyne.ca. DS IN
Sep 06 11:07:38 unbound[10564:0] info: sending query: harte-lyne.ca.
DS IN
Sep 06 11:07:38 unbound[10564:0] debug: sending to target: <.>
216.185.71.34#53
Sep 06 11:07:38 unbound[10564:0] debug: cache memory msg=66936
rrset=71611 infra=3130 val=68726
Sep 06 11:07:38 unbound[10564:0] debug: iterator[module 1] operate:
extstate:module_wait_reply event:module_event_reply
Sep 06 11:07:38 unbound[10564:0] info: iterator operate: query
harte-lyne.ca. DS IN
Sep 06 11:07:38 unbound[10564:0] info: response for harte-lyne.ca. DS IN
Sep 06 11:07:38 unbound[10564:0] info: reply from <.> 216.185.71.34#53
Sep 06 11:07:38 unbound[10564:0] info: query response was ANSWER
Sep 06 11:07:38 unbound[10564:0] info: finishing processing for
harte-lyne.ca. DS IN
Sep 06 11:07:38 unbound[10564:0] debug: validator[module 0] operate:
extstate:module_wait_module event:module_event_moddone
Sep 06 11:07:38 unbound[10564:0] info: validator operate: query
harte-lyne.ca. DS IN
Sep 06 11:07:38 unbound[10564:0] info: validated DS harte-lyne.ca. DS IN
Sep 06 11:07:38 unbound[10564:0] debug: validator[module 0] operate:
extstate:module_wait_subquery event:module_event_pass
Sep 06 11:07:38 unbound[10564:0] info: validator operate: query
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:07:38 unbound[10564:0] debug: validator[module 0] operate:
extstate:module_state_initial event:module_event_pass
Sep 06 11:07:38 unbound[10564:0] info: validator operate: query
harte-lyne.ca. DNSKEY IN
Sep 06 11:07:38 unbound[10564:0] debug: iterator[module 1] operate:
extstate:module_state_initial event:module_event_pass
Sep 06 11:07:38 unbound[10564:0] info: resolving harte-lyne.ca. DNSKEY IN
Sep 06 11:07:38 unbound[10564:0] info: processQueryTargets:
harte-lyne.ca. DNSKEY IN
Sep 06 11:07:38 unbound[10564:0] info: sending query: harte-lyne.ca.
DNSKEY IN
Sep 06 11:07:38 unbound[10564:0] debug: sending to target: <.>
216.185.71.34#53
Sep 06 11:07:38 unbound[10564:0] debug: cache memory msg=67127
rrset=72108 infra=3130 val=68726
Sep 06 11:07:38 unbound[10564:0] debug: iterator[module 1] operate:
extstate:module_wait_reply event:module_event_reply
Sep 06 11:07:38 unbound[10564:0] info: iterator operate: query
harte-lyne.ca. DNSKEY IN
Sep 06 11:07:38 unbound[10564:0] info: response for harte-lyne.ca.
DNSKEY IN
Sep 06 11:07:38 unbound[10564:0] info: reply from <.> 216.185.71.34#53
Sep 06 11:07:38 unbound[10564:0] info: query response was ANSWER
Sep 06 11:07:38 unbound[10564:0] info: finishing processing for
harte-lyne.ca. DNSKEY IN
Sep 06 11:07:38 unbound[10564:0] debug: validator[module 0] operate:
extstate:module_wait_module event:module_event_moddone
Sep 06 11:07:38 unbound[10564:0] info: validator operate: query
harte-lyne.ca. DNSKEY IN
Sep 06 11:07:38 unbound[10564:0] info: validated DNSKEY harte-lyne.ca.
DNSKEY IN
Sep 06 11:07:38 unbound[10564:0] debug: validator[module 0] operate:
extstate:module_wait_subquery event:module_event_pass
Sep 06 11:07:38 unbound[10564:0] info: validator operate: query
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:07:38 unbound[10564:0] info: validate(positive):
sec_status_secure
Sep 06 11:07:38 unbound[10564:0] info: validation success
inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:07:38 unbound[10564:0] debug: cache memory msg=67318
rrset=73285 infra=3130 val=69935
The critical difference that I see is this:
Sep 06 11:05:15 unbound[480:0] debug: verify: could not find
appropriate key
Sep 06 11:05:15 unbound[480:0] info: validator: response has failed
ANSWER rrset: inet02.hamilton.harte-lyne.ca. A IN
Sep 06 11:05:15 unbound[480:0] info: Validate: message contains bad
rrsets
What key is unbound looking for; and why can it find it immediately
after a restart but not again later?
--
*** e-Mail is NOT a SECURE channel ***
Do NOT transmit sensitive data via e-Mail
Do NOT open attachments nor follow links sent by e-Mail
James B. Byrne mailto:ByrneJB@Harte-Lyne.ca
Harte & Lyne Limited http://www.harte-lyne.ca
9 Brockley Drive vox: +1 905 561 1241
Hamilton, Ontario fax: +1 905 561 0757
Canada L8E 3C3
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?fea1d9558be2a5cc125a07937451fc46.squirrel>