From owner-freebsd-questions@freebsd.org Wed Sep 6 15:27:11 2017 Return-Path: Delivered-To: freebsd-questions@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id 6AB7AE07FC0 for ; Wed, 6 Sep 2017 15:27:11 +0000 (UTC) (envelope-from byrnejb@harte-lyne.ca) Received: from inet08.hamilton.harte-lyne.ca (inet08.hamilton.harte-lyne.ca [216.185.71.28]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client CN "inet08.hamilton.harte-lyne.ca", Issuer "CA_HLL_ISSUER_2016" (not verified)) by mx1.freebsd.org (Postfix) with ESMTPS id B6C6976353 for ; Wed, 6 Sep 2017 15:27:10 +0000 (UTC) (envelope-from byrnejb@harte-lyne.ca) Received: from localhost (localhost [127.0.0.1]) by inet08.hamilton.harte-lyne.ca (Postfix) with ESMTP id C1A7E62088 for ; Wed, 6 Sep 2017 11:19:49 -0400 (EDT) X-Virus-Scanned: amavisd-new at harte-lyne.ca Received: from inet08.hamilton.harte-lyne.ca ([127.0.0.1]) by localhost (inet08.hamilton.harte-lyne.ca [127.0.0.1]) (amavisd-new, port 10024) with ESMTP id nCOT2TbMGCOg for ; Wed, 6 Sep 2017 11:19:40 -0400 (EDT) Received: from webmail.harte-lyne.ca (inet04.hamilton.harte-lyne.ca [216.185.71.24]) (using TLSv1 with cipher ECDHE-RSA-AES256-SHA (256/256 bits)) (Client did not present a certificate) by inet08.hamilton.harte-lyne.ca (Postfix) with ESMTPSA id 606736029A for ; Wed, 6 Sep 2017 11:19:40 -0400 (EDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=harte-lyne.ca; s=dkim_hll; t=1504711180; bh=MRNUI0FmTYcJXF9AGaluHFR541jhcfbYX/Nomi2bkPk=; h=Date:Subject:From:To:Reply-To; b=rrNXByNNXWeKO7rMnS81o8JPemHzVP6eyTqEZcPlfR1Oop78Uoa+tryo3xChH9B/t l2ZGp+hN9O1H95Nyt7hQY37SejMQGaitxjEylQA+ecWfGcsfEkcT0GmftWYeFhlifk qI+DA6IM31MHm1iw3k+yrRjvlL9ivBq7Yi3WxVprI1DZ+vTAk6QaD9KTUYnCTO8RkT IhlCLCY82Hvj4o9guiVcGtSMWqZs0hI3990wR98/r3Gx32sXaqFXEk4I/xNeVocMjF cmf14TqNuhDniTI28HqwmC2tV4P85Owhor5/EmpVlBgAtAC308GQQda0qE9SfnhULZ YICLFpIpQXw8Q== Received: from 216.185.71.44 (SquirrelMail authenticated user byrnejb_hll) by webmail.harte-lyne.ca with HTTP; Wed, 6 Sep 2017 11:19:40 -0400 Message-ID: Date: Wed, 6 Sep 2017 11:19:40 -0400 Subject: local_unbound stops resolving From: "James B. Byrne" To: freebsd-questions@freebsd.org Reply-To: byrnejb@harte-lyne.ca User-Agent: SquirrelMail/1.4.22-5.el6 MIME-Version: 1.0 Content-Type: text/plain;charset=iso-8859-1 Content-Transfer-Encoding: 8bit X-Priority: 3 (Normal) Importance: Normal X-BeenThere: freebsd-questions@freebsd.org X-Mailman-Version: 2.1.23 Precedence: list List-Id: User questions List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Wed, 06 Sep 2017 15:27:11 -0000 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