From owner-freebsd-net@freebsd.org Sat Oct 13 10:12:21 2018 Return-Path: Delivered-To: freebsd-net@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id 59BAF10C1BA4 for ; Sat, 13 Oct 2018 10:12:21 +0000 (UTC) (envelope-from des@des.no) Received: from smtp.des.no (smtp.des.no [194.63.250.102]) by mx1.freebsd.org (Postfix) with ESMTP id DFA5273B16 for ; Sat, 13 Oct 2018 10:12:20 +0000 (UTC) (envelope-from des@des.no) Received: from next.des.no (smtp.des.no [194.63.250.102]) by smtp.des.no (Postfix) with ESMTP id 161B38190; Sat, 13 Oct 2018 10:12:20 +0000 (UTC) Received: by next.des.no (Postfix, from userid 1001) id E627A10093; Sat, 13 Oct 2018 12:12:19 +0200 (CEST) From: =?utf-8?Q?Dag-Erling_Sm=C3=B8rgrav?= To: Eugene Grosbein Cc: freebsd-net Subject: Re: DNS KSK rollover, local_unbound and 11.2-STABLE In-Reply-To: (Eugene Grosbein's message of "Sat, 13 Oct 2018 15:00:33 +0700") References: <5BC046FB.9080906@grosbein.net> <861s8uaodn.fsf@next.des.no> User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/26.1 (berkeley-unix) Date: Sat, 13 Oct 2018 12:12:19 +0200 Message-ID: <86ftxa2m0s.fsf@next.des.no> MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="=-=-=" X-BeenThere: freebsd-net@freebsd.org X-Mailman-Version: 2.1.27 Precedence: list List-Id: Networking and TCP/IP with FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Sat, 13 Oct 2018 10:12:21 -0000 --=-=-= Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable Here's the thing though, I am unable to reproduce the issue in 11.2-RELEASE (see attached log). Can you send me this tarball: # tar zcf unbound.tgz /etc/resolv.conf /var/unbound and also tell me which variables are set, i.e. the output from: # grep -r unbound /etc/rc.conf* DES --=20 Dag-Erling Sm=C3=B8rgrav - des@des.no --=-=-= Content-Type: text/plain Content-Disposition: attachment; filename=local_unbound-112p3.log # uname -a FreeBSD next.des.no 11.2-RELEASE-p3 FreeBSD 11.2-RELEASE-p3 #0: Thu Sep 6 07:14:16 UTC 2018 root@amd64-builder.daemonology.net:/usr/obj/usr/src/sys/GENERIC amd64 # cat >/etc/rc.conf.d/local_unbound <: 0 names (0 missing), 1 addrs (0 result, 1 avail) parentNS [1539425001] unbound[10562:0] debug: cache memory msg=66072 rrset=66072 infra=2632 val=66280 [1539425001] unbound[10562:0] info: start of service (unbound 1.5.10). [1539425001] unbound[10562:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_new [1539425001] unbound[10562:0] info: validator operate: query . DNSKEY IN [1539425001] unbound[10562:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass [1539425001] unbound[10562:0] info: resolving . DNSKEY IN [1539425001] unbound[10562:0] info: processQueryTargets: . DNSKEY IN [1539425001] unbound[10562:0] info: sending query: . DNSKEY IN [1539425001] unbound[10562:0] debug: sending to target: <.> 192.168.144.1#53 [1539425001] unbound[10562:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply [1539425001] unbound[10562:0] info: iterator operate: query . DNSKEY IN [1539425001] unbound[10562:0] info: response for . DNSKEY IN [1539425001] unbound[10562:0] info: reply from <.> 192.168.144.1#53 [1539425001] unbound[10562:0] info: query response was ANSWER [1539425001] unbound[10562:0] info: finishing processing for . DNSKEY IN [1539425001] unbound[10562:0] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone [1539425001] unbound[10562:0] info: validator operate: query . DNSKEY IN [1539425001] unbound[10562:0] info: prime trust anchor [1539425001] unbound[10562:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_pass [1539425001] unbound[10562:0] info: validator operate: query . DNSKEY IN [1539425001] unbound[10562:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass [1539425001] unbound[10562:0] info: resolving . DNSKEY IN [1539425001] unbound[10562:0] info: finishing processing for . DNSKEY IN [1539425001] unbound[10562:0] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone [1539425001] unbound[10562:0] info: validator operate: query . DNSKEY IN [1539425001] unbound[10562:0] info: validate keys with anchor(DS): sec_status_secure [1539425001] unbound[10562:0] info: Successfully primed trust anchor . DNSKEY IN [1539425001] unbound[10562:0] debug: validator[module 0] operate: extstate:module_wait_subquery event:module_event_pass [1539425001] unbound[10562:0] info: validator operate: query . DNSKEY IN [1539425001] unbound[10562:0] info: validate(positive): sec_status_secure [1539425001] unbound[10562:0] info: validation success . DNSKEY IN [1539425001] unbound[10562:0] debug: cache memory msg=66249 rrset=67388 infra=2881 val=67628 [1539425012] unbound[10562:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_new [1539425012] unbound[10562:0] info: validator operate: query www.freebsd.org. A IN [1539425012] unbound[10562:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass [1539425012] unbound[10562:0] info: resolving www.freebsd.org. A IN [1539425012] unbound[10562:0] info: processQueryTargets: www.freebsd.org. A IN [1539425012] unbound[10562:0] info: sending query: www.freebsd.org. A IN [1539425012] unbound[10562:0] debug: sending to target: <.> 192.168.144.1#53 [1539425012] unbound[10562:0] debug: cache memory msg=66249 rrset=67388 infra=2881 val=67628 [1539425012] unbound[10562:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply [1539425012] unbound[10562:0] info: iterator operate: query www.freebsd.org. A IN [1539425012] unbound[10562:0] info: sanitize: removing extraneous answer RRset: wfe0.nyi.freebsd.org. A IN [1539425012] unbound[10562:0] info: response for www.freebsd.org. A IN [1539425012] unbound[10562:0] info: reply from <.> 192.168.144.1#53 [1539425012] unbound[10562:0] info: query response was CNAME [1539425012] unbound[10562:0] info: resolving www.freebsd.org. A IN [1539425012] unbound[10562:0] info: processQueryTargets: www.freebsd.org. A IN [1539425012] unbound[10562:0] info: sending query: wfe0.nyi.freebsd.org. A IN [1539425012] unbound[10562:0] debug: sending to target: <.> 192.168.144.1#53 [1539425012] unbound[10562:0] debug: cache memory msg=66249 rrset=68510 infra=2881 val=67628 [1539425012] unbound[10562:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply [1539425012] unbound[10562:0] info: iterator operate: query www.freebsd.org. A IN [1539425012] unbound[10562:0] info: iterator operate: chased to wfe0.nyi.freebsd.org. A IN [1539425012] unbound[10562:0] info: response for www.freebsd.org. A IN [1539425012] unbound[10562:0] info: reply from <.> 192.168.144.1#53 [1539425012] unbound[10562:0] info: query response was ANSWER [1539425012] unbound[10562:0] info: finishing processing for www.freebsd.org. A IN [1539425012] unbound[10562:0] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone [1539425012] unbound[10562:0] info: validator operate: query www.freebsd.org. A IN [1539425012] unbound[10562:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_pass [1539425012] unbound[10562:0] info: validator operate: query org. DS IN [1539425012] unbound[10562:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass [1539425012] unbound[10562:0] info: resolving org. DS IN [1539425012] unbound[10562:0] info: processQueryTargets: org. DS IN [1539425012] unbound[10562:0] info: sending query: org. DS IN [1539425012] unbound[10562:0] debug: sending to target: <.> 192.168.144.1#53 [1539425012] unbound[10562:0] debug: cache memory msg=66712 rrset=69019 infra=2881 val=67628 [1539425012] unbound[10562:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply [1539425012] unbound[10562:0] info: iterator operate: query org. DS IN [1539425012] unbound[10562:0] info: response for org. DS IN [1539425012] unbound[10562:0] info: reply from <.> 192.168.144.1#53 [1539425012] unbound[10562:0] info: query response was ANSWER [1539425012] unbound[10562:0] info: finishing processing for org. DS IN [1539425012] unbound[10562:0] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone [1539425012] unbound[10562:0] info: validator operate: query org. DS IN [1539425012] unbound[10562:0] info: validated DS org. DS IN [1539425012] unbound[10562:0] debug: validator[module 0] operate: extstate:module_wait_subquery event:module_event_pass [1539425012] unbound[10562:0] info: validator operate: query www.freebsd.org. A IN [1539425012] unbound[10562:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_pass [1539425012] unbound[10562:0] info: validator operate: query org. DNSKEY IN [1539425012] unbound[10562:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass [1539425012] unbound[10562:0] info: resolving org. DNSKEY IN [1539425012] unbound[10562:0] info: processQueryTargets: org. DNSKEY IN [1539425012] unbound[10562:0] info: sending query: org. DNSKEY IN [1539425012] unbound[10562:0] debug: sending to target: <.> 192.168.144.1#53 [1539425012] unbound[10562:0] debug: cache memory msg=66893 rrset=69581 infra=2881 val=67628 [1539425012] unbound[10562:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply [1539425012] unbound[10562:0] info: iterator operate: query org. DNSKEY IN [1539425012] unbound[10562:0] info: response for org. DNSKEY IN [1539425012] unbound[10562:0] info: reply from <.> 192.168.144.1#53 [1539425012] unbound[10562:0] info: query response was ANSWER [1539425012] unbound[10562:0] info: finishing processing for org. DNSKEY IN [1539425012] unbound[10562:0] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone [1539425012] unbound[10562:0] info: validator operate: query org. DNSKEY IN [1539425012] unbound[10562:0] info: validated DNSKEY org. DNSKEY IN [1539425012] unbound[10562:0] debug: validator[module 0] operate: extstate:module_wait_subquery event:module_event_pass [1539425012] unbound[10562:0] info: validator operate: query www.freebsd.org. A IN [1539425012] unbound[10562:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_pass [1539425012] unbound[10562:0] info: validator operate: query freebsd.org. DS IN [1539425012] unbound[10562:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass [1539425012] unbound[10562:0] info: resolving freebsd.org. DS IN [1539425012] unbound[10562:0] info: processQueryTargets: freebsd.org. DS IN [1539425012] unbound[10562:0] info: sending query: freebsd.org. DS IN [1539425012] unbound[10562:0] debug: sending to target: <.> 192.168.144.1#53 [1539425012] unbound[10562:0] debug: cache memory msg=67074 rrset=71421 infra=2881 val=69500 [1539425012] unbound[10562:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply [1539425012] unbound[10562:0] info: iterator operate: query freebsd.org. DS IN [1539425012] unbound[10562:0] info: response for freebsd.org. DS IN [1539425012] unbound[10562:0] info: reply from <.> 192.168.144.1#53 [1539425012] unbound[10562:0] info: query response was ANSWER [1539425012] unbound[10562:0] info: finishing processing for freebsd.org. DS IN [1539425012] unbound[10562:0] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone [1539425012] unbound[10562:0] info: validator operate: query freebsd.org. DS IN [1539425012] unbound[10562:0] info: validated DS freebsd.org. DS IN [1539425012] unbound[10562:0] debug: validator[module 0] operate: extstate:module_wait_subquery event:module_event_pass [1539425012] unbound[10562:0] info: validator operate: query www.freebsd.org. A IN [1539425012] unbound[10562:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_pass [1539425012] unbound[10562:0] info: validator operate: query freebsd.org. DNSKEY IN [1539425012] unbound[10562:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass [1539425012] unbound[10562:0] info: resolving freebsd.org. DNSKEY IN [1539425012] unbound[10562:0] info: processQueryTargets: freebsd.org. DNSKEY IN [1539425012] unbound[10562:0] info: sending query: freebsd.org. DNSKEY IN [1539425012] unbound[10562:0] debug: sending to target: <.> 192.168.144.1#53 [1539425012] unbound[10562:0] debug: cache memory msg=67263 rrset=71817 infra=2881 val=69500 [1539425012] unbound[10562:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply [1539425012] unbound[10562:0] info: iterator operate: query freebsd.org. DNSKEY IN [1539425012] unbound[10562:0] info: response for freebsd.org. DNSKEY IN [1539425012] unbound[10562:0] info: reply from <.> 192.168.144.1#53 [1539425012] unbound[10562:0] info: query response was ANSWER [1539425012] unbound[10562:0] info: finishing processing for freebsd.org. DNSKEY IN [1539425012] unbound[10562:0] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone [1539425012] unbound[10562:0] info: validator operate: query freebsd.org. DNSKEY IN [1539425012] unbound[10562:0] info: validated DNSKEY freebsd.org. DNSKEY IN [1539425012] unbound[10562:0] debug: validator[module 0] operate: extstate:module_wait_subquery event:module_event_pass [1539425012] unbound[10562:0] info: validator operate: query www.freebsd.org. A IN [1539425012] unbound[10562:0] info: validate(cname): sec_status_secure [1539425012] unbound[10562:0] info: validate(positive): sec_status_secure [1539425012] unbound[10562:0] info: validation success www.freebsd.org. A IN [1539425012] unbound[10562:0] debug: cache memory msg=67452 rrset=72867 infra=2881 val=70582 [1539425012] unbound[10562:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_new [1539425012] unbound[10562:0] info: validator operate: query wfe0.nyi.freebsd.org. AAAA IN [1539425012] unbound[10562:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass [1539425012] unbound[10562:0] info: resolving wfe0.nyi.freebsd.org. AAAA IN [1539425012] unbound[10562:0] info: processQueryTargets: wfe0.nyi.freebsd.org. AAAA IN [1539425012] unbound[10562:0] info: sending query: wfe0.nyi.freebsd.org. AAAA IN [1539425012] unbound[10562:0] debug: sending to target: <.> 192.168.144.1#53 [1539425012] unbound[10562:0] debug: cache memory msg=67452 rrset=72867 infra=2881 val=70582 [1539425012] unbound[10562:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply [1539425012] unbound[10562:0] info: iterator operate: query wfe0.nyi.freebsd.org. AAAA IN [1539425012] unbound[10562:0] info: response for wfe0.nyi.freebsd.org. AAAA IN [1539425012] unbound[10562:0] info: reply from <.> 192.168.144.1#53 [1539425012] unbound[10562:0] info: query response was ANSWER [1539425012] unbound[10562:0] info: finishing processing for wfe0.nyi.freebsd.org. AAAA IN [1539425012] unbound[10562:0] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone [1539425012] unbound[10562:0] info: validator operate: query wfe0.nyi.freebsd.org. AAAA IN [1539425012] unbound[10562:0] info: validate(positive): sec_status_secure [1539425012] unbound[10562:0] info: validation success wfe0.nyi.freebsd.org. AAAA IN [1539425012] unbound[10562:0] debug: cache memory msg=67674 rrset=73388 infra=2881 val=70582 [1539425012] unbound[10562:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_new [1539425012] unbound[10562:0] info: validator operate: query wfe0.nyi.freebsd.org. MX IN [1539425012] unbound[10562:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass [1539425012] unbound[10562:0] info: resolving wfe0.nyi.freebsd.org. MX IN [1539425012] unbound[10562:0] info: processQueryTargets: wfe0.nyi.freebsd.org. MX IN [1539425012] unbound[10562:0] info: sending query: wfe0.nyi.freebsd.org. MX IN [1539425012] unbound[10562:0] debug: sending to target: <.> 192.168.144.1#53 [1539425012] unbound[10562:0] debug: cache memory msg=67674 rrset=73388 infra=2881 val=70582 [1539425012] unbound[10562:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply [1539425012] unbound[10562:0] info: iterator operate: query wfe0.nyi.freebsd.org. MX IN [1539425012] unbound[10562:0] info: response for wfe0.nyi.freebsd.org. MX IN [1539425012] unbound[10562:0] info: reply from <.> 192.168.144.1#53 [1539425012] unbound[10562:0] info: query response was ANSWER [1539425012] unbound[10562:0] info: finishing processing for wfe0.nyi.freebsd.org. MX IN [1539425012] unbound[10562:0] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone [1539425012] unbound[10562:0] info: validator operate: query wfe0.nyi.freebsd.org. MX IN [1539425012] unbound[10562:0] info: validate(positive): sec_status_secure [1539425012] unbound[10562:0] info: validation success wfe0.nyi.freebsd.org. MX IN [1539425012] unbound[10562:0] debug: cache memory msg=67896 rrset=73896 infra=2881 val=70582 ^C[1539425016] unbound[10562:0] info: service stopped (unbound 1.5.10). [1539425016] unbound[10562:0] info: server stats for thread 0: 3 queries, 0 answers from cache, 3 recursions, 0 prefetch [1539425016] unbound[10562:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0 [1539425016] unbound[10562:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 3 recursion replies sent, 0 replies dropped, 0 states jostled out [1539425016] unbound[10562:0] info: average recursion processing time 0.016123 sec [1539425016] unbound[10562:0] info: histogram of recursion processing times [1539425016] unbound[10562:0] info: [25%]=0 median[50%]=0 [75%]=0 [1539425016] unbound[10562:0] info: lower(secs) upper(secs) recursions [1539425016] unbound[10562:0] info: 0.001024 0.002048 2 [1539425016] unbound[10562:0] info: 0.032768 0.065536 1 [1539425016] unbound[10562:0] debug: cache memory msg=66072 rrset=66072 infra=2881 val=70582 [1539425016] unbound[10562:0] debug: switching log to stderr # cat /var/unbound/root.key ; autotrust trust anchor file ;;id: . 1 ;;last_queried: 1539425001 ;;Sat Oct 13 12:03:21 2018 ;;last_success: 1539425001 ;;Sat Oct 13 12:03:21 2018 ;;next_probe_time: 1539464948 ;;Sat Oct 13 23:09:08 2018 ;;query_failed: 0 ;;query_interval: 43200 ;;retry_time: 8640 . 144357 IN DNSKEY 257 3 8 AwEAAaz/tAm8yTn4Mfeh5eyI96WSVexTBAvkMgJzkKTOiW1vkIbzxeF3+/4RgWOq7HrxRixHlFlExOLAJr5emLvN7SWXgnLh4+B5xQlNVz8Og8kvArMtNROxVQuCaSnIDdD5LKyWbRd2n9WGe2R8PzgCmr3EgVLrjyBxWezF0jLHwVN8efS3rCj/EWgvIWgb9tarpVUDK/b58Da+sqqls3eNbuv7pr+eoZG+SrDK6nWeL3c6H5Apxz7LjVc1uTIdsIXxuOLYA4/ilBmSVIzuDWfdRUfhHdY6+cn8HFRm+2hM8AnXGXws9555KrUB5qihylGa8subX2Nn6UwNR1AkUTV74bU= ;{id = 20326 (ksk), size = 2048b} ;;state=2 [ VALID ] ;;count=0 ;;lastchange=1539425001 ;;Sat Oct 13 12:03:21 2018 . 144357 IN DNSKEY 257 3 8 AwEAAagAIKlVZrpC6Ia7gEzahOR+9W29euxhJhVVLOyQbSEW0O8gcCjFFVQUTf6v58fLjwBd0YI0EzrAcQqBGCzh/RStIoO8g0NfnfL2MTJRkxoXbfDaUeVPQuYEhg37NZWAJQ9VnMVDxP/VHL496M/QZxkjf5/Efucp2gaDX6RS6CXpoY68LsvPVjR0ZSwzz1apAzvN9dlzEheX7ICJBBtuA6G3LQpzW5hOA2hzCTMjJPJ8LbqF6dsV6DoBQzgul0sGIcGOYl7OyQdXfZ57relSQageu+ipAdTTJ25AsRTAoub8ONGcLmqrAmRLKBP1dfwhYB4N7knNnulqQxA+Uk1ihz0= ;{id = 19036 (ksk), size = 2048b} ;;state=1 [ ADDPEND ] ;;count=1 ;;lastchange=1539425001 ;;Sat Oct 13 12:03:21 2018 --=-=-=--