Date: Sat, 13 Oct 2018 12:12:19 +0200 From: =?utf-8?Q?Dag-Erling_Sm=C3=B8rgrav?= <des@des.no> To: Eugene Grosbein <eugen@grosbein.net> Cc: freebsd-net <freebsd-net@freebsd.org> Subject: Re: DNS KSK rollover, local_unbound and 11.2-STABLE Message-ID: <86ftxa2m0s.fsf@next.des.no> In-Reply-To: <d3f2d5cb-20a2-6868-55ae-9dd5181d997a@grosbein.net> (Eugene Grosbein's message of "Sat, 13 Oct 2018 15:00:33 %2B0700") References: <5BC046FB.9080906@grosbein.net> <861s8uaodn.fsf@next.des.no> <d3f2d5cb-20a2-6868-55ae-9dd5181d997a@grosbein.net>
next in thread | previous in thread | raw e-mail | index | archive | help
--=-=-=
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 <<EOF
local_unbound_enable="YES"
EOF
# find /var/unbound -type f
# cat /etc/resolv.conf
# Generated by resolvconf
search des.no
nameserver 192.168.144.1
# service local_unbound setup
Performing initial setup.
Extracting forwarders from /etc/resolv.conf.
/var/unbound/forward.conf created
/var/unbound/lan-zones.conf created
/var/unbound/control.conf created
/var/unbound/unbound.conf created
/etc/resolvconf.conf not modified
original /etc/resolv.conf saved as /etc/resolv.conf.20181013.120252
# service local_unbound anchor
# cat /var/unbound/root.key
; created by unbound-anchor on Sat Oct 13 12:03:07 2018
. IN DS 19036 8 2 49AAC11D7B6F6446702E54A1607371607A1A41855200FD2CE1CDDE32F24E8FB5
. IN DS 20326 8 2 E06D44B80B8F1D39A95C0B0D7C65D08458E880409BBC683457104237C7F8EC8D
# /usr/sbin/unbound -ddvv
[1539425001] unbound[10562:0] notice: Start of unbound 1.5.10.
[1539425001] unbound[10562:0] debug: chdir to /var/unbound
[1539425001] unbound[10562:0] debug: chroot to /var/unbound
[1539425001] unbound[10562:0] debug: drop user privileges, run as unbound
[1539425001] unbound[10562:0] debug: switching log to stderr
[1539425001] unbound[10562:0] debug: module config: "validator iterator"
[1539425001] unbound[10562:0] notice: init module 0: validator
[1539425001] unbound[10562:0] notice: init module 1: iterator
[1539425001] unbound[10562:0] debug: target fetch policy for level 0 is 3
[1539425001] unbound[10562:0] debug: target fetch policy for level 1 is 2
[1539425001] unbound[10562:0] debug: target fetch policy for level 2 is 1
[1539425001] unbound[10562:0] debug: target fetch policy for level 3 is 0
[1539425001] unbound[10562:0] debug: target fetch policy for level 4 is 0
[1539425001] unbound[10562:0] debug: Forward zone server list:
[1539425001] unbound[10562:0] info: DelegationPoint<.>: 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
--=-=-=--
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?86ftxa2m0s.fsf>