Maintained by: NLnet Labs

[Unbound-users] Validation failure of DNSSEC signed domain names

Zbynek Michl
Fri Apr 30 11:49:26 CEST 2010


Here is another log of A www.nic.cz query. There are some blacklists which are 
probably reason of the bad validation.

Also I have find out that after 900 seconds when "strange state" starts is 
everything OK. Any connection with "dnssec-lameness" paragraph at 
<http://www.unbound.net/documentation/requirements.html>?

Cheers,
Zbynek

--- LOG ---
[1272618346] unbound[26422:2] info: validator operate: query <www.nic.cz. A IN>
[1272618346] unbound[26422:2] debug: validator: pass to next module
[1272618346] unbound[26422:2] debug: mesh_run: validator module exit state is 
module_wait_module
[1272618346] unbound[26422:2] debug: iterator[module 1] operate: 
extstate:module_state_initial event:module_event_pass
[1272618346] unbound[26422:2] debug: process_request: new external request event
[1272618346] unbound[26422:2] debug: iter_handle processing q with state INIT 
REQUEST STATE
[1272618346] unbound[26422:2] info: resolving <www.nic.cz. A IN>
[1272618346] unbound[26422:2] debug: request has dependency depth of 0
[1272618346] unbound[26422:2] debug: cache delegation returns delegpt
[1272618346] unbound[26422:2] info: DelegationPoint<cz.>: 5 names (0 missing), 
10 addrs (0 result, 10 avail)
[1272618346] unbound[26422:2] info:   f.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   d.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   c.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   b.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   a.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] debug:    ip6 2001:678:f::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 194.0.12.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:678:10::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 194.0.13.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2a01:40:1000::2 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 195.66.241.202 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:678:1::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 193.29.206.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:628:453:420::48 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 193.171.255.48 port 53 (len 16)
[1272618346] unbound[26422:2] debug: iter_handle processing q with state INIT 
REQUEST STATE (stage 2)
[1272618346] unbound[26422:2] info: resolving (init part 2):  <www.nic.cz. A IN>
[1272618346] unbound[26422:2] debug: iter_handle processing q with state INIT 
REQUEST STATE (stage 3)
[1272618346] unbound[26422:2] info: resolving (init part 3):  <www.nic.cz. A IN>
[1272618346] unbound[26422:2] debug: iter_handle processing q with state QUERY 
TARGETS STATE
[1272618346] unbound[26422:2] info: processQueryTargets: <www.nic.cz. A IN>
[1272618346] unbound[26422:2] debug: processQueryTargets: targetqueries 0, 
currentqueries 0
[1272618346] unbound[26422:2] info: DelegationPoint<cz.>: 5 names (0 missing), 
10 addrs (0 result, 10 avail)
[1272618346] unbound[26422:2] info:   f.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   d.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   c.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   b.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   a.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] debug:    ip6 2001:678:f::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 194.0.12.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:678:10::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 194.0.13.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2a01:40:1000::2 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 195.66.241.202 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:678:1::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 193.29.206.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:628:453:420::48 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 193.171.255.48 port 53 (len 16)
[1272618346] unbound[26422:2] debug: attempt to get extra 3 targets
[1272618346] unbound[26422:2] debug: servselect ip4 193.171.255.48 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=8898 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: servselect ip4 193.29.206.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=722 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: servselect ip4 195.66.241.202 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=1508 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: servselect ip4 194.0.13.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=8823 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: servselect ip4 194.0.12.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=1739 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: selrtt 120722
[1272618346] unbound[26422:2] debug: chase to dnssec lame server
[1272618346] unbound[26422:2] info: sending query: <www.nic.cz. A IN>
[1272618346] unbound[26422:2] debug: sending to target: <cz.> 193.29.206.1#53
[1272618346] unbound[26422:2] debug: serviced query UDP timeout=722 msec
[1272618346] unbound[26422:2] debug: inserted new pending reply id=3ef7
[1272618346] unbound[26422:2] debug: opened UDP if=0 port=56817
[1272618346] unbound[26422:2] debug: comm point start listening 13
[1272618346] unbound[26422:2] debug: mesh_run: iterator module exit state is 
module_wait_reply
[1272618346] unbound[26422:2] info: mesh_run: end 1 recursion states (1 with 
reply, 0 detached), 1 waiting replies, 6752 recursion replies sent, 0 replies 
dropped, 0 states jostled out
[1272618346] unbound[26422:2] info: average recursion processing time 38.779874 sec
[1272618346] unbound[26422:2] info: histogram of recursion processing times
[1272618346] unbound[26422:2] info: [25%]=1.88123 median[50%]=6.94849 [75%]=0.732824
[1272618346] unbound[26422:2] info: lower(secs) upper(secs) recursions
[1272618346] unbound[26422:2] info:    0.000000    0.000001 159
[1272618346] unbound[26422:2] info:    0.004096    0.008192 24
[1272618346] unbound[26422:2] info:    0.008192    0.016384 4
[1272618346] unbound[26422:2] info:    0.016384    0.032768 9
[1272618346] unbound[26422:2] info:    0.032768    0.065536 11
[1272618346] unbound[26422:2] info:    0.065536    0.131072 31
[1272618346] unbound[26422:2] info:    0.131072    0.262144 8
[1272618346] unbound[26422:2] info:    0.262144    0.524288 29
[1272618346] unbound[26422:2] info:    0.524288    1.000000 48
[1272618346] unbound[26422:2] info:    1.000000    2.000000 383
[1272618346] unbound[26422:2] info:    2.000000    4.000000 1044
[1272618346] unbound[26422:2] info:    4.000000    8.000000 1137
[1272618346] unbound[26422:2] info:    8.000000   16.000000 563
[1272618346] unbound[26422:2] info:   16.000000   32.000000 721
[1272618346] unbound[26422:2] info:   32.000000   64.000000 878
[1272618346] unbound[26422:2] info:   64.000000  128.000000 1310
[1272618346] unbound[26422:2] info:  128.000000  256.000000 393
[1272618346] unbound[26422:2] info: 0RDd mod1 rep <www.nic.cz. A IN>
[1272618346] unbound[26422:2] debug: cache memory msg=3570894 rrset=4428253 
infra=35743 val=4001591
[1272618346] unbound[26422:2] debug: answer cb
[1272618346] unbound[26422:2] debug: Incoming reply id = 3ef7
[1272618346] unbound[26422:2] debug: Incoming reply addr = ip4 193.29.206.1 port 
53 (len 16)
[1272618346] unbound[26422:2] debug: lookup size is 1 entries
[1272618346] unbound[26422:2] debug: received udp reply.
[1272618346] unbound[26422:2] debug: udp message[227:0] 
3EF78400000100010003000603777777036E696302637A0000010001C00C00010001000007080004D91FCD32C010000200010000070800070161026E73C010C010000200010000070800040162C03AC010000200010000070800040164C03AC03800010001000007080004C2000C01C038001C000100000708001020010678000F00000000000000000001C04B00010001000007080004C2000D01C04B001C000100000708001020010678001000000000000000000001C05B00010001000007080004C11DCE01C05B001C000100000708001020010678000100000000000000000001
[1272618346] unbound[26422:2] debug: outnet handle udp reply
[1272618346] unbound[26422:2] debug: measured roundtrip at 1 msec
[1272618346] unbound[26422:2] debug: svcd callbacks start
[1272618346] unbound[26422:2] debug: worker svcd callback for qstate 0x175e850
[1272618346] unbound[26422:2] debug: mesh_run: start
[1272618346] unbound[26422:2] debug: iterator[module 1] operate: 
extstate:module_wait_reply event:module_event_reply
[1272618346] unbound[26422:2] info: iterator operate: query <www.nic.cz. A IN>
[1272618346] unbound[26422:2] debug: process_response: new external response event
[1272618346] unbound[26422:2] info: scrub for <cz. NS IN>
[1272618346] unbound[26422:2] info: response for <www.nic.cz. A IN>
[1272618346] unbound[26422:2] info: reply from <cz.> 193.29.206.1#53
[1272618346] unbound[26422:2] info: incoming scrubbed packet: ;; ->>HEADER<<- 
opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr aa ; QUERY: 1, ANSWER: 1, AUTHORITY: 3, ADDITIONAL: 6
;; QUESTION SECTION:
;; www.nic.cz.	IN	A

;; ANSWER SECTION:
www.nic.cz.	1800	IN	A	217.31.205.50

;; AUTHORITY SECTION:
nic.cz.	1800	IN	NS	a.ns.nic.cz.
nic.cz.	1800	IN	NS	b.ns.nic.cz.
nic.cz.	1800	IN	NS	d.ns.nic.cz.

;; ADDITIONAL SECTION:
a.ns.nic.cz.	1800	IN	A	194.0.12.1
a.ns.nic.cz.	1800	IN	AAAA	2001:678:f::1
b.ns.nic.cz.	1800	IN	A	194.0.13.1
b.ns.nic.cz.	1800	IN	AAAA	2001:678:10::1
d.ns.nic.cz.	1800	IN	A	193.29.206.1
d.ns.nic.cz.	1800	IN	AAAA	2001:678:1::1

;; Query time: 0 msec
;; WHEN: Thu Jan  1 01:00:00 1970
;; MSG SIZE  rcvd: 227

[1272618346] unbound[26422:2] debug: iter_handle processing q with state QUERY 
RESPONSE STATE
[1272618346] unbound[26422:2] info: query response was ANSWER
[1272618346] unbound[26422:2] debug: iter_handle processing q with state 
FINISHED RESPONSE STATE
[1272618346] unbound[26422:2] info: finishing processing for <www.nic.cz. A IN>
[1272618346] unbound[26422:2] debug: mesh_run: iterator module exit state is 
module_finished
[1272618346] unbound[26422:2] debug: validator[module 0] operate: 
extstate:module_wait_module event:module_event_moddone
[1272618346] unbound[26422:2] info: validator operate: query <www.nic.cz. A IN>
[1272618346] unbound[26422:2] debug: validator: nextmodule returned
[1272618346] unbound[26422:2] debug: val handle processing q with state 
VAL_INIT_STATE
[1272618346] unbound[26422:2] debug: validator classification positive
[1272618346] unbound[26422:2] info: no signer, using <www.nic.cz. TYPE0 CLASS0>
[1272618346] unbound[26422:2] debug: val handle processing q with state 
VAL_FINDKEY_STATE
[1272618346] unbound[26422:2] info: validator: FindKey <www.nic.cz. A IN>
[1272618346] unbound[26422:2] info: current keyname <cz. DNSKEY IN>
[1272618346] unbound[26422:2] info: target keyname <www.nic.cz. DNSKEY IN>
[1272618346] unbound[26422:2] debug: striplab 1
[1272618346] unbound[26422:2] info: next keyname <nic.cz. DNSKEY IN>
[1272618346] unbound[26422:2] debug: No DS RRset
[1272618346] unbound[26422:2] info: generate request <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: mesh_run: validator module exit state is 
module_wait_subquery
[1272618346] unbound[26422:2] debug: validator[module 0] operate: 
extstate:module_state_initial event:module_event_pass
[1272618346] unbound[26422:2] info: validator operate: query <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: validator: pass to next module
[1272618346] unbound[26422:2] debug: mesh_run: validator module exit state is 
module_wait_module
[1272618346] unbound[26422:2] debug: iterator[module 1] operate: 
extstate:module_state_initial event:module_event_pass
[1272618346] unbound[26422:2] debug: process_request: new external request event
[1272618346] unbound[26422:2] debug: iter_handle processing q with state INIT 
REQUEST STATE
[1272618346] unbound[26422:2] info: resolving <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: request has dependency depth of 0
[1272618346] unbound[26422:2] debug: cache delegation returns delegpt
[1272618346] unbound[26422:2] info: DelegationPoint<cz.>: 5 names (0 missing), 
10 addrs (0 result, 10 avail)
[1272618346] unbound[26422:2] info:   f.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   d.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   c.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   b.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   a.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] debug:    ip6 2001:678:f::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 194.0.12.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:678:10::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 194.0.13.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2a01:40:1000::2 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 195.66.241.202 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:678:1::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 193.29.206.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:628:453:420::48 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 193.171.255.48 port 53 (len 16)
[1272618346] unbound[26422:2] debug: iter_handle processing q with state INIT 
REQUEST STATE (stage 2)
[1272618346] unbound[26422:2] info: resolving (init part 2):  <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: iter_handle processing q with state INIT 
REQUEST STATE (stage 3)
[1272618346] unbound[26422:2] info: resolving (init part 3):  <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: iter_handle processing q with state QUERY 
TARGETS STATE
[1272618346] unbound[26422:2] info: processQueryTargets: <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: processQueryTargets: targetqueries 0, 
currentqueries 0
[1272618346] unbound[26422:2] info: DelegationPoint<cz.>: 5 names (0 missing), 
10 addrs (0 result, 10 avail)
[1272618346] unbound[26422:2] info:   f.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   d.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   c.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   b.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   a.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] debug:    ip6 2001:678:f::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 194.0.12.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:678:10::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 194.0.13.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2a01:40:1000::2 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 195.66.241.202 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:678:1::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 193.29.206.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:628:453:420::48 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 193.171.255.48 port 53 (len 16)
[1272618346] unbound[26422:2] debug: attempt to get extra 3 targets
[1272618346] unbound[26422:2] debug: servselect ip4 193.171.255.48 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=8898 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: servselect ip4 193.29.206.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=661 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: servselect ip4 195.66.241.202 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=1508 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: servselect ip4 194.0.13.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=8823 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: servselect ip4 194.0.12.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=1739 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: selrtt 120661
[1272618346] unbound[26422:2] debug: chase to dnssec lame server
[1272618346] unbound[26422:2] info: sending query: <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: sending to target: <cz.> 193.29.206.1#53
[1272618346] unbound[26422:2] debug: serviced query UDP timeout=661 msec
[1272618346] unbound[26422:2] debug: inserted new pending reply id=ebee
[1272618346] unbound[26422:2] debug: opened UDP if=0 port=54893
[1272618346] unbound[26422:2] debug: comm point start listening 14
[1272618346] unbound[26422:2] debug: mesh_run: iterator module exit state is 
module_wait_reply
[1272618346] unbound[26422:2] info: mesh_run: end 2 recursion states (1 with 
reply, 0 detached), 1 waiting replies, 6752 recursion replies sent, 0 replies 
dropped, 0 states jostled out
[1272618346] unbound[26422:2] info: average recursion processing time 38.779874 sec
[1272618346] unbound[26422:2] info: histogram of recursion processing times
[1272618346] unbound[26422:2] info: [25%]=1.88123 median[50%]=6.94849 [75%]=0.732824
[1272618346] unbound[26422:2] info: lower(secs) upper(secs) recursions
[1272618346] unbound[26422:2] info:    0.000000    0.000001 159
[1272618346] unbound[26422:2] info:    0.004096    0.008192 24
[1272618346] unbound[26422:2] info:    0.008192    0.016384 4
[1272618346] unbound[26422:2] info:    0.016384    0.032768 9
[1272618346] unbound[26422:2] info:    0.032768    0.065536 11
[1272618346] unbound[26422:2] info:    0.065536    0.131072 31
[1272618346] unbound[26422:2] info:    0.131072    0.262144 8
[1272618346] unbound[26422:2] info:    0.262144    0.524288 29
[1272618346] unbound[26422:2] info:    0.524288    1.000000 48
[1272618346] unbound[26422:2] info:    1.000000    2.000000 383
[1272618346] unbound[26422:2] info:    2.000000    4.000000 1044
[1272618346] unbound[26422:2] info:    4.000000    8.000000 1137
[1272618346] unbound[26422:2] info:    8.000000   16.000000 563
[1272618346] unbound[26422:2] info:   16.000000   32.000000 721
[1272618346] unbound[26422:2] info:   32.000000   64.000000 878
[1272618346] unbound[26422:2] info:   64.000000  128.000000 1310
[1272618346] unbound[26422:2] info:  128.000000  256.000000 393
[1272618346] unbound[26422:2] info: 0RDCD mod1  <nic.cz. DS IN>
[1272618346] unbound[26422:2] info: 1RDdc mod0 rep <www.nic.cz. A IN>
[1272618346] unbound[26422:2] debug: cache memory msg=3570894 rrset=4428788 
infra=35743 val=4001591
[1272618346] unbound[26422:2] debug: svcd callbacks end
[1272618346] unbound[26422:2] debug: close of port 56817
[1272618346] unbound[26422:2] debug: close fd 13
[1272618346] unbound[26422:2] debug: answer cb
[1272618346] unbound[26422:2] debug: Incoming reply id = ebee
[1272618346] unbound[26422:2] debug: Incoming reply addr = ip4 193.29.206.1 port 
53 (len 16)
[1272618346] unbound[26422:2] debug: lookup size is 1 entries
[1272618346] unbound[26422:2] debug: received udp reply.
[1272618346] unbound[26422:2] debug: udp message[96:0] 
EBEE84100001000200000000036E696302637A00002B0001C00C002B00010000465000186D4B0501FF11E740A0254EC63C738A47E52ABF3AD91D8C43C00C002B0001000046500018EA0C0501144130216E45C4EC2BB8595E817916E8B060D87B
[1272618346] unbound[26422:2] debug: outnet handle udp reply
[1272618346] unbound[26422:2] debug: measured roundtrip at 1 msec
[1272618346] unbound[26422:2] debug: svcd callbacks start
[1272618346] unbound[26422:2] debug: worker svcd callback for qstate 0x7f43fd12a090
[1272618346] unbound[26422:2] debug: mesh_run: start
[1272618346] unbound[26422:2] debug: iterator[module 1] operate: 
extstate:module_wait_reply event:module_event_reply
[1272618346] unbound[26422:2] info: iterator operate: query <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: process_response: new external response event
[1272618346] unbound[26422:2] info: scrub for <cz. NS IN>
[1272618346] unbound[26422:2] info: response for <nic.cz. DS IN>
[1272618346] unbound[26422:2] info: reply from <cz.> 193.29.206.1#53
[1272618346] unbound[26422:2] info: incoming scrubbed packet: ;; ->>HEADER<<- 
opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr aa ; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 0
;; QUESTION SECTION:
;; nic.cz.	IN	DS

;; ANSWER SECTION:
nic.cz.	18000	IN	DS	27979 5 1 ff11e740a0254ec63c738a47e52abf3ad91d8c43 ; 
xuzoc-cunug-bimud-hafus-kezal-fidig-linyd-puzef-pukoc-tefug-fuxax
nic.cz.	18000	IN	DS	59916 5 1 144130216e45c4ec2bb8595e817916e8b060d87b ; 
xehag-casyd-curug-hyciv-supar-mikuh-vubul-nihov-misyk-bykal-rexux

;; AUTHORITY SECTION:

;; ADDITIONAL SECTION:

;; Query time: 0 msec
;; WHEN: Thu Jan  1 01:00:00 1970
;; MSG SIZE  rcvd: 96

[1272618346] unbound[26422:2] debug: iter_handle processing q with state QUERY 
RESPONSE STATE
[1272618346] unbound[26422:2] info: query response was ANSWER
[1272618346] unbound[26422:2] debug: iter_handle processing q with state 
FINISHED RESPONSE STATE
[1272618346] unbound[26422:2] info: finishing processing for <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: mesh_run: iterator module exit state is 
module_finished
[1272618346] unbound[26422:2] debug: validator[module 0] operate: 
extstate:module_wait_module event:module_event_moddone
[1272618346] unbound[26422:2] info: validator operate: query <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: validator: nextmodule returned
[1272618346] unbound[26422:2] debug: not validating response due to CD bit
[1272618346] unbound[26422:2] debug: mesh_run: validator module exit state is 
module_finished
[1272618346] unbound[26422:2] info: validator: inform_super, sub is <nic.cz. DS IN>
[1272618346] unbound[26422:2] info: super is <www.nic.cz. A IN>
[1272618346] unbound[26422:2] info: verify rrset <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: rrset failed to verify due to a lack of 
signatures
[1272618346] unbound[26422:2] debug: verify result: sec_status_bogus
[1272618346] unbound[26422:2] info: DS rrset in DS response did not verify
[1272618346] unbound[26422:2] debug: blacklist add ip4 193.29.206.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug: validator[module 0] operate: 
extstate:module_wait_subquery event:module_event_pass
[1272618346] unbound[26422:2] info: validator operate: query <www.nic.cz. A IN>
[1272618346] unbound[26422:2] debug: val handle processing q with state 
VAL_FINDKEY_STATE
[1272618346] unbound[26422:2] info: validator: FindKey <www.nic.cz. A IN>
[1272618346] unbound[26422:2] info: current keyname <cz. DNSKEY IN>
[1272618346] unbound[26422:2] info: target keyname <www.nic.cz. DNSKEY IN>
[1272618346] unbound[26422:2] debug: striplab 1
[1272618346] unbound[26422:2] info: next keyname <nic.cz. DNSKEY IN>
[1272618346] unbound[26422:2] debug: No DS RRset
[1272618346] unbound[26422:2] info: generate request <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: mesh_run: validator module exit state is 
module_wait_subquery
[1272618346] unbound[26422:2] debug: validator[module 0] operate: 
extstate:module_state_initial event:module_event_pass
[1272618346] unbound[26422:2] info: validator operate: query <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: validator: pass to next module
[1272618346] unbound[26422:2] debug: mesh_run: validator module exit state is 
module_wait_module
[1272618346] unbound[26422:2] debug: iterator[module 1] operate: 
extstate:module_state_initial event:module_event_pass
[1272618346] unbound[26422:2] debug: process_request: new external request event
[1272618346] unbound[26422:2] debug: iter_handle processing q with state INIT 
REQUEST STATE
[1272618346] unbound[26422:2] info: resolving <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: request has dependency depth of 0
[1272618346] unbound[26422:2] debug: cache blacklisted, going to the network
[1272618346] unbound[26422:2] debug: cache delegation returns delegpt
[1272618346] unbound[26422:2] info: DelegationPoint<cz.>: 5 names (0 missing), 
10 addrs (0 result, 10 avail)
[1272618346] unbound[26422:2] info:   f.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   d.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   c.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   b.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   a.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] debug:    ip6 2001:678:f::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 194.0.12.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:678:10::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 194.0.13.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2a01:40:1000::2 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 195.66.241.202 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:678:1::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 193.29.206.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:628:453:420::48 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 193.171.255.48 port 53 (len 16)
[1272618346] unbound[26422:2] debug: iter_handle processing q with state INIT 
REQUEST STATE (stage 2)
[1272618346] unbound[26422:2] info: resolving (init part 2):  <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: iter_handle processing q with state INIT 
REQUEST STATE (stage 3)
[1272618346] unbound[26422:2] info: resolving (init part 3):  <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: iter_handle processing q with state QUERY 
TARGETS STATE
[1272618346] unbound[26422:2] info: processQueryTargets: <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: processQueryTargets: targetqueries 0, 
currentqueries 0
[1272618346] unbound[26422:2] info: DelegationPoint<cz.>: 5 names (0 missing), 
10 addrs (0 result, 10 avail)
[1272618346] unbound[26422:2] info:   f.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   d.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   c.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   b.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   a.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] debug:    ip6 2001:678:f::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 194.0.12.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:678:10::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 194.0.13.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2a01:40:1000::2 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 195.66.241.202 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:678:1::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 193.29.206.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:628:453:420::48 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 193.171.255.48 port 53 (len 16)
[1272618346] unbound[26422:2] debug: attempt to get extra 3 targets
[1272618346] unbound[26422:2] debug: servselect ip4 193.171.255.48 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=8898 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: servselect ip4 193.29.206.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=602 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: servselect ip4 195.66.241.202 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=1508 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: servselect ip4 194.0.13.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=8823 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: servselect ip4 194.0.12.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=1739 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: selrtt 121508
[1272618346] unbound[26422:2] debug: chase to dnssec lame server
[1272618346] unbound[26422:2] info: sending query: <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: sending to target: <cz.> 194.0.12.1#53
[1272618346] unbound[26422:2] debug: serviced query UDP timeout=1739 msec
[1272618346] unbound[26422:2] debug: inserted new pending reply id=2e2c
[1272618346] unbound[26422:2] debug: opened UDP if=0 port=36539
[1272618346] unbound[26422:2] debug: comm point start listening 13
[1272618346] unbound[26422:2] debug: mesh_run: iterator module exit state is 
module_wait_reply
[1272618346] unbound[26422:2] info: mesh_run: end 2 recursion states (1 with 
reply, 0 detached), 1 waiting replies, 6752 recursion replies sent, 0 replies 
dropped, 0 states jostled out
[1272618346] unbound[26422:2] info: average recursion processing time 38.779874 sec
[1272618346] unbound[26422:2] info: histogram of recursion processing times
[1272618346] unbound[26422:2] info: [25%]=1.88123 median[50%]=6.94849 [75%]=0.732824
[1272618346] unbound[26422:2] info: lower(secs) upper(secs) recursions
[1272618346] unbound[26422:2] info:    0.000000    0.000001 159
[1272618346] unbound[26422:2] info:    0.004096    0.008192 24
[1272618346] unbound[26422:2] info:    0.008192    0.016384 4
[1272618346] unbound[26422:2] info:    0.016384    0.032768 9
[1272618346] unbound[26422:2] info:    0.032768    0.065536 11
[1272618346] unbound[26422:2] info:    0.065536    0.131072 31
[1272618346] unbound[26422:2] info:    0.131072    0.262144 8
[1272618346] unbound[26422:2] info:    0.262144    0.524288 29
[1272618346] unbound[26422:2] info:    0.524288    1.000000 48
[1272618346] unbound[26422:2] info:    1.000000    2.000000 383
[1272618346] unbound[26422:2] info:    2.000000    4.000000 1044
[1272618346] unbound[26422:2] info:    4.000000    8.000000 1137
[1272618346] unbound[26422:2] info:    8.000000   16.000000 563
[1272618346] unbound[26422:2] info:   16.000000   32.000000 721
[1272618346] unbound[26422:2] info:   32.000000   64.000000 878
[1272618346] unbound[26422:2] info:   64.000000  128.000000 1310
[1272618346] unbound[26422:2] info:  128.000000  256.000000 393
[1272618346] unbound[26422:2] info: 0RDCD mod1  <nic.cz. DS IN>
[1272618346] unbound[26422:2] info: 1RDdc mod0 rep <www.nic.cz. A IN>
[1272618346] unbound[26422:2] debug: cache memory msg=3570726 rrset=4429080 
infra=35743 val=4001591
[1272618346] unbound[26422:2] debug: svcd callbacks end
[1272618346] unbound[26422:2] debug: close of port 54893
[1272618346] unbound[26422:2] debug: close fd 14
[1272618346] unbound[26422:2] debug: answer cb
[1272618346] unbound[26422:2] debug: Incoming reply id = 2e2c
[1272618346] unbound[26422:2] debug: Incoming reply addr = ip4 194.0.12.1 port 
53 (len 16)
[1272618346] unbound[26422:2] debug: lookup size is 1 entries
[1272618346] unbound[26422:2] debug: received udp reply.
[1272618346] unbound[26422:2] debug: udp message[179:0] 
2E2C84100001000200050000036E696302637A00002B0001C00C002B0001000046500018EA0C0501144130216E45C4EC2BB8595E817916E8B060D87BC00C002B00010000465000186D4B0501FF11E740A0254EC63C738A47E52ABF3AD91D8C43C010000200010000465000070164026E73C00CC010000200010000465000040162C06EC010000200010000465000040166C06EC010000200010000465000040163C06EC010000200010000465000040161C06E
[1272618346] unbound[26422:2] debug: outnet handle udp reply
[1272618346] unbound[26422:2] debug: measured roundtrip at 1 msec
[1272618346] unbound[26422:2] debug: svcd callbacks start
[1272618346] unbound[26422:2] debug: worker svcd callback for qstate 0x7f43fd12a090
[1272618346] unbound[26422:2] debug: mesh_run: start
[1272618346] unbound[26422:2] debug: iterator[module 1] operate: 
extstate:module_wait_reply event:module_event_reply
[1272618346] unbound[26422:2] info: iterator operate: query <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: process_response: new external response event
[1272618346] unbound[26422:2] info: scrub for <cz. NS IN>
[1272618346] unbound[26422:2] info: response for <nic.cz. DS IN>
[1272618346] unbound[26422:2] info: reply from <cz.> 194.0.12.1#53
[1272618346] unbound[26422:2] info: incoming scrubbed packet: ;; ->>HEADER<<- 
opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr aa ; QUERY: 1, ANSWER: 2, AUTHORITY: 5, ADDITIONAL: 0
;; QUESTION SECTION:
;; nic.cz.	IN	DS

;; ANSWER SECTION:
nic.cz.	18000	IN	DS	59916 5 1 144130216e45c4ec2bb8595e817916e8b060d87b ; 
xehag-casyd-curug-hyciv-supar-mikuh-vubul-nihov-misyk-bykal-rexux
nic.cz.	18000	IN	DS	27979 5 1 ff11e740a0254ec63c738a47e52abf3ad91d8c43 ; 
xuzoc-cunug-bimud-hafus-kezal-fidig-linyd-puzef-pukoc-tefug-fuxax

;; AUTHORITY SECTION:
cz.	18000	IN	NS	d.ns.nic.cz.
cz.	18000	IN	NS	b.ns.nic.cz.
cz.	18000	IN	NS	f.ns.nic.cz.
cz.	18000	IN	NS	c.ns.nic.cz.
cz.	18000	IN	NS	a.ns.nic.cz.

;; ADDITIONAL SECTION:

;; Query time: 0 msec
;; WHEN: Thu Jan  1 01:00:00 1970
;; MSG SIZE  rcvd: 179

[1272618346] unbound[26422:2] debug: iter_handle processing q with state QUERY 
RESPONSE STATE
[1272618346] unbound[26422:2] info: query response was ANSWER
[1272618346] unbound[26422:2] debug: iter_handle processing q with state 
FINISHED RESPONSE STATE
[1272618346] unbound[26422:2] info: finishing processing for <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: mesh_run: iterator module exit state is 
module_finished
[1272618346] unbound[26422:2] debug: validator[module 0] operate: 
extstate:module_wait_module event:module_event_moddone
[1272618346] unbound[26422:2] info: validator operate: query <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: validator: nextmodule returned
[1272618346] unbound[26422:2] debug: not validating response due to CD bit
[1272618346] unbound[26422:2] debug: mesh_run: validator module exit state is 
module_finished
[1272618346] unbound[26422:2] info: validator: inform_super, sub is <nic.cz. DS IN>
[1272618346] unbound[26422:2] info: super is <www.nic.cz. A IN>
[1272618346] unbound[26422:2] info: verify rrset <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: rrset failed to verify due to a lack of 
signatures
[1272618346] unbound[26422:2] debug: verify result: sec_status_bogus
[1272618346] unbound[26422:2] info: DS rrset in DS response did not verify
[1272618346] unbound[26422:2] debug: blacklist ip4 193.29.206.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug: blacklist add ip4 194.0.12.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug: validator[module 0] operate: 
extstate:module_wait_subquery event:module_event_pass
[1272618346] unbound[26422:2] info: validator operate: query <www.nic.cz. A IN>
[1272618346] unbound[26422:2] debug: val handle processing q with state 
VAL_FINDKEY_STATE
[1272618346] unbound[26422:2] info: validator: FindKey <www.nic.cz. A IN>
[1272618346] unbound[26422:2] info: current keyname <cz. DNSKEY IN>
[1272618346] unbound[26422:2] info: target keyname <www.nic.cz. DNSKEY IN>
[1272618346] unbound[26422:2] debug: striplab 1
[1272618346] unbound[26422:2] info: next keyname <nic.cz. DNSKEY IN>
[1272618346] unbound[26422:2] debug: No DS RRset
[1272618346] unbound[26422:2] info: generate request <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: mesh_run: validator module exit state is 
module_wait_subquery
[1272618346] unbound[26422:2] debug: validator[module 0] operate: 
extstate:module_state_initial event:module_event_pass
[1272618346] unbound[26422:2] info: validator operate: query <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: validator: pass to next module
[1272618346] unbound[26422:2] debug: mesh_run: validator module exit state is 
module_wait_module
[1272618346] unbound[26422:2] debug: iterator[module 1] operate: 
extstate:module_state_initial event:module_event_pass
[1272618346] unbound[26422:2] debug: process_request: new external request event
[1272618346] unbound[26422:2] debug: iter_handle processing q with state INIT 
REQUEST STATE
[1272618346] unbound[26422:2] info: resolving <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: request has dependency depth of 0
[1272618346] unbound[26422:2] debug: cache blacklisted, going to the network
[1272618346] unbound[26422:2] debug: cache delegation returns delegpt
[1272618346] unbound[26422:2] info: DelegationPoint<cz.>: 5 names (0 missing), 
10 addrs (0 result, 10 avail)
[1272618346] unbound[26422:2] info:   a.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   c.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   f.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   b.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   d.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] debug:    ip6 2001:678:1::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 193.29.206.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:678:10::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 194.0.13.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:628:453:420::48 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 193.171.255.48 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2a01:40:1000::2 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 195.66.241.202 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:678:f::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 194.0.12.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug: iter_handle processing q with state INIT 
REQUEST STATE (stage 2)
[1272618346] unbound[26422:2] info: resolving (init part 2):  <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: iter_handle processing q with state INIT 
REQUEST STATE (stage 3)
[1272618346] unbound[26422:2] info: resolving (init part 3):  <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: iter_handle processing q with state QUERY 
TARGETS STATE
[1272618346] unbound[26422:2] info: processQueryTargets: <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: processQueryTargets: targetqueries 0, 
currentqueries 0
[1272618346] unbound[26422:2] info: DelegationPoint<cz.>: 5 names (0 missing), 
10 addrs (0 result, 10 avail)
[1272618346] unbound[26422:2] info:   a.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   c.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   f.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   b.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   d.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] debug:    ip6 2001:678:1::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 193.29.206.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:678:10::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 194.0.13.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:628:453:420::48 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 193.171.255.48 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2a01:40:1000::2 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 195.66.241.202 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:678:f::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 194.0.12.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug: attempt to get extra 3 targets
[1272618346] unbound[26422:2] debug: servselect ip4 194.0.12.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=1739 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: servselect ip4 195.66.241.202 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=1508 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: servselect ip4 193.171.255.48 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=8898 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: servselect ip4 194.0.13.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=8823 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: servselect ip4 193.29.206.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=602 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: selrtt 121508
[1272618346] unbound[26422:2] debug: chase to dnssec lame server
[1272618346] unbound[26422:2] info: sending query: <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: sending to target: <cz.> 195.66.241.202#53
[1272618346] unbound[26422:2] debug: serviced query UDP timeout=1508 msec
[1272618346] unbound[26422:2] debug: inserted new pending reply id=0a5c
[1272618346] unbound[26422:2] debug: opened UDP if=0 port=14454
[1272618346] unbound[26422:2] debug: comm point start listening 14
[1272618346] unbound[26422:2] debug: mesh_run: iterator module exit state is 
module_wait_reply
[1272618346] unbound[26422:2] info: mesh_run: end 2 recursion states (1 with 
reply, 0 detached), 1 waiting replies, 6752 recursion replies sent, 0 replies 
dropped, 0 states jostled out
[1272618346] unbound[26422:2] info: average recursion processing time 38.779874 sec
[1272618346] unbound[26422:2] info: histogram of recursion processing times
[1272618346] unbound[26422:2] info: [25%]=1.88123 median[50%]=6.94849 [75%]=0.732824
[1272618346] unbound[26422:2] info: lower(secs) upper(secs) recursions
[1272618346] unbound[26422:2] info:    0.000000    0.000001 159
[1272618346] unbound[26422:2] info:    0.004096    0.008192 24
[1272618346] unbound[26422:2] info:    0.008192    0.016384 4
[1272618346] unbound[26422:2] info:    0.016384    0.032768 9
[1272618346] unbound[26422:2] info:    0.032768    0.065536 11
[1272618346] unbound[26422:2] info:    0.065536    0.131072 31
[1272618346] unbound[26422:2] info:    0.131072    0.262144 8
[1272618346] unbound[26422:2] info:    0.262144    0.524288 29
[1272618346] unbound[26422:2] info:    0.524288    1.000000 48
[1272618346] unbound[26422:2] info:    1.000000    2.000000 383
[1272618346] unbound[26422:2] info:    2.000000    4.000000 1044
[1272618346] unbound[26422:2] info:    4.000000    8.000000 1137
[1272618346] unbound[26422:2] info:    8.000000   16.000000 563
[1272618346] unbound[26422:2] info:   16.000000   32.000000 721
[1272618346] unbound[26422:2] info:   32.000000   64.000000 878
[1272618346] unbound[26422:2] info:   64.000000  128.000000 1310
[1272618346] unbound[26422:2] info:  128.000000  256.000000 393
[1272618346] unbound[26422:2] info: 0RDCD mod1  <nic.cz. DS IN>
[1272618346] unbound[26422:2] info: 1RDdc mod0 rep <www.nic.cz. A IN>
[1272618346] unbound[26422:2] debug: cache memory msg=3570750 rrset=4429080 
infra=35743 val=4001591
[1272618346] unbound[26422:2] debug: svcd callbacks end
[1272618346] unbound[26422:2] debug: close of port 36539
[1272618346] unbound[26422:2] debug: close fd 13
[1272618346] unbound[26422:2] debug: answer cb
[1272618346] unbound[26422:2] debug: Incoming reply id = 0a5c
[1272618346] unbound[26422:2] debug: Incoming reply addr = ip4 195.66.241.202 
port 53 (len 16)
[1272618346] unbound[26422:2] debug: lookup size is 1 entries
[1272618346] unbound[26422:2] debug: received udp reply.
[1272618346] unbound[26422:2] debug: udp message[179:0] 
0A5C84100001000200050000036E696302637A00002B0001C00C002B00010000465000186D4B0501FF11E740A0254EC63C738A47E52ABF3AD91D8C43C00C002B0001000046500018EA0C0501144130216E45C4EC2BB8595E817916E8B060D87BC010000200010000465000070166026E73C00CC010000200010000465000040163C06EC010000200010000465000040164C06EC010000200010000465000040162C06EC010000200010000465000040161C06E
[1272618346] unbound[26422:2] debug: outnet handle udp reply
[1272618346] unbound[26422:2] debug: measured roundtrip at 24 msec
[1272618346] unbound[26422:2] debug: svcd callbacks start
[1272618346] unbound[26422:2] debug: worker svcd callback for qstate 0x7f43fd12a090
[1272618346] unbound[26422:2] debug: mesh_run: start
[1272618346] unbound[26422:2] debug: iterator[module 1] operate: 
extstate:module_wait_reply event:module_event_reply
[1272618346] unbound[26422:2] info: iterator operate: query <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: process_response: new external response event
[1272618346] unbound[26422:2] info: scrub for <cz. NS IN>
[1272618346] unbound[26422:2] info: response for <nic.cz. DS IN>
[1272618346] unbound[26422:2] info: reply from <cz.> 195.66.241.202#53
[1272618346] unbound[26422:2] info: incoming scrubbed packet: ;; ->>HEADER<<- 
opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr aa ; QUERY: 1, ANSWER: 2, AUTHORITY: 5, ADDITIONAL: 0
;; QUESTION SECTION:
;; nic.cz.	IN	DS

;; ANSWER SECTION:
nic.cz.	18000	IN	DS	27979 5 1 ff11e740a0254ec63c738a47e52abf3ad91d8c43 ; 
xuzoc-cunug-bimud-hafus-kezal-fidig-linyd-puzef-pukoc-tefug-fuxax
nic.cz.	18000	IN	DS	59916 5 1 144130216e45c4ec2bb8595e817916e8b060d87b ; 
xehag-casyd-curug-hyciv-supar-mikuh-vubul-nihov-misyk-bykal-rexux

;; AUTHORITY SECTION:
cz.	18000	IN	NS	f.ns.nic.cz.
cz.	18000	IN	NS	c.ns.nic.cz.
cz.	18000	IN	NS	d.ns.nic.cz.
cz.	18000	IN	NS	b.ns.nic.cz.
cz.	18000	IN	NS	a.ns.nic.cz.

;; ADDITIONAL SECTION:

;; Query time: 0 msec
;; WHEN: Thu Jan  1 01:00:00 1970
;; MSG SIZE  rcvd: 179

[1272618346] unbound[26422:2] debug: iter_handle processing q with state QUERY 
RESPONSE STATE
[1272618346] unbound[26422:2] info: query response was ANSWER
[1272618346] unbound[26422:2] debug: iter_handle processing q with state 
FINISHED RESPONSE STATE
[1272618346] unbound[26422:2] info: finishing processing for <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: mesh_run: iterator module exit state is 
module_finished
[1272618346] unbound[26422:2] debug: validator[module 0] operate: 
extstate:module_wait_module event:module_event_moddone
[1272618346] unbound[26422:2] info: validator operate: query <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: validator: nextmodule returned
[1272618346] unbound[26422:2] debug: not validating response due to CD bit
[1272618346] unbound[26422:2] debug: mesh_run: validator module exit state is 
module_finished
[1272618346] unbound[26422:2] info: validator: inform_super, sub is <nic.cz. DS IN>
[1272618346] unbound[26422:2] info: super is <www.nic.cz. A IN>
[1272618346] unbound[26422:2] info: verify rrset <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: rrset failed to verify due to a lack of 
signatures
[1272618346] unbound[26422:2] debug: verify result: sec_status_bogus
[1272618346] unbound[26422:2] info: DS rrset in DS response did not verify
[1272618346] unbound[26422:2] debug: blacklist ip4 194.0.12.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug: blacklist ip4 193.29.206.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug: blacklist add ip4 195.66.241.202 port 53 
(len 16)
[1272618346] unbound[26422:2] debug: validator[module 0] operate: 
extstate:module_wait_subquery event:module_event_pass
[1272618346] unbound[26422:2] info: validator operate: query <www.nic.cz. A IN>
[1272618346] unbound[26422:2] debug: val handle processing q with state 
VAL_FINDKEY_STATE
[1272618346] unbound[26422:2] info: validator: FindKey <www.nic.cz. A IN>
[1272618346] unbound[26422:2] info: current keyname <cz. DNSKEY IN>
[1272618346] unbound[26422:2] info: target keyname <www.nic.cz. DNSKEY IN>
[1272618346] unbound[26422:2] debug: striplab 1
[1272618346] unbound[26422:2] info: next keyname <nic.cz. DNSKEY IN>
[1272618346] unbound[26422:2] debug: No DS RRset
[1272618346] unbound[26422:2] info: generate request <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: mesh_run: validator module exit state is 
module_wait_subquery
[1272618346] unbound[26422:2] debug: validator[module 0] operate: 
extstate:module_state_initial event:module_event_pass
[1272618346] unbound[26422:2] info: validator operate: query <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: validator: pass to next module
[1272618346] unbound[26422:2] debug: mesh_run: validator module exit state is 
module_wait_module
[1272618346] unbound[26422:2] debug: iterator[module 1] operate: 
extstate:module_state_initial event:module_event_pass
[1272618346] unbound[26422:2] debug: process_request: new external request event
[1272618346] unbound[26422:2] debug: iter_handle processing q with state INIT 
REQUEST STATE
[1272618346] unbound[26422:2] info: resolving <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: request has dependency depth of 0
[1272618346] unbound[26422:2] debug: cache blacklisted, going to the network
[1272618346] unbound[26422:2] debug: cache delegation returns delegpt
[1272618346] unbound[26422:2] info: DelegationPoint<cz.>: 5 names (0 missing), 
10 addrs (0 result, 10 avail)
[1272618346] unbound[26422:2] info:   a.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   b.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   d.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   c.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   f.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] debug:    ip6 2001:628:453:420::48 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 193.171.255.48 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2a01:40:1000::2 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 195.66.241.202 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:678:1::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 193.29.206.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:678:10::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 194.0.13.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:678:f::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 194.0.12.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug: iter_handle processing q with state INIT 
REQUEST STATE (stage 2)
[1272618346] unbound[26422:2] info: resolving (init part 2):  <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: iter_handle processing q with state INIT 
REQUEST STATE (stage 3)
[1272618346] unbound[26422:2] info: resolving (init part 3):  <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: iter_handle processing q with state QUERY 
TARGETS STATE
[1272618346] unbound[26422:2] info: processQueryTargets: <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: processQueryTargets: targetqueries 0, 
currentqueries 0
[1272618346] unbound[26422:2] info: DelegationPoint<cz.>: 5 names (0 missing), 
10 addrs (0 result, 10 avail)
[1272618346] unbound[26422:2] info:   a.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   b.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   d.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   c.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   f.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] debug:    ip6 2001:628:453:420::48 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 193.171.255.48 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2a01:40:1000::2 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 195.66.241.202 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:678:1::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 193.29.206.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:678:10::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 194.0.13.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:678:f::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 194.0.12.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug: attempt to get extra 3 targets
[1272618346] unbound[26422:2] debug: servselect ip4 194.0.12.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=1739 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: servselect ip4 194.0.13.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=8823 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: servselect ip4 193.29.206.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=602 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: servselect ip4 195.66.241.202 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=1482 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: servselect ip4 193.171.255.48 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=8898 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: selrtt 128823
[1272618346] unbound[26422:2] debug: chase to dnssec lame server
[1272618346] unbound[26422:2] info: sending query: <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: sending to target: <cz.> 193.171.255.48#53
[1272618346] unbound[26422:2] debug: serviced query UDP timeout=8898 msec
[1272618346] unbound[26422:2] debug: inserted new pending reply id=cf7d
[1272618346] unbound[26422:2] debug: opened UDP if=0 port=53264
[1272618346] unbound[26422:2] debug: comm point start listening 13
[1272618346] unbound[26422:2] debug: mesh_run: iterator module exit state is 
module_wait_reply
[1272618346] unbound[26422:2] info: mesh_run: end 2 recursion states (1 with 
reply, 0 detached), 1 waiting replies, 6752 recursion replies sent, 0 replies 
dropped, 0 states jostled out
[1272618346] unbound[26422:2] info: average recursion processing time 38.779874 sec
[1272618346] unbound[26422:2] info: histogram of recursion processing times
[1272618346] unbound[26422:2] info: [25%]=1.88123 median[50%]=6.94849 [75%]=0.732824
[1272618346] unbound[26422:2] info: lower(secs) upper(secs) recursions
[1272618346] unbound[26422:2] info:    0.000000    0.000001 159
[1272618346] unbound[26422:2] info:    0.004096    0.008192 24
[1272618346] unbound[26422:2] info:    0.008192    0.016384 4
[1272618346] unbound[26422:2] info:    0.016384    0.032768 9
[1272618346] unbound[26422:2] info:    0.032768    0.065536 11
[1272618346] unbound[26422:2] info:    0.065536    0.131072 31
[1272618346] unbound[26422:2] info:    0.131072    0.262144 8
[1272618346] unbound[26422:2] info:    0.262144    0.524288 29
[1272618346] unbound[26422:2] info:    0.524288    1.000000 48
[1272618346] unbound[26422:2] info:    1.000000    2.000000 383
[1272618346] unbound[26422:2] info:    2.000000    4.000000 1044
[1272618346] unbound[26422:2] info:    4.000000    8.000000 1137
[1272618346] unbound[26422:2] info:    8.000000   16.000000 563
[1272618346] unbound[26422:2] info:   16.000000   32.000000 721
[1272618346] unbound[26422:2] info:   32.000000   64.000000 878
[1272618346] unbound[26422:2] info:   64.000000  128.000000 1310
[1272618346] unbound[26422:2] info:  128.000000  256.000000 393
[1272618346] unbound[26422:2] info: 0RDCD mod1  <nic.cz. DS IN>
[1272618346] unbound[26422:2] info: 1RDdc mod0 rep <www.nic.cz. A IN>
[1272618346] unbound[26422:2] debug: cache memory msg=3570750 rrset=4429080 
infra=35743 val=4001591
[1272618346] unbound[26422:2] debug: svcd callbacks end
[1272618346] unbound[26422:2] debug: close of port 14454
[1272618346] unbound[26422:2] debug: close fd 14
[1272618346] unbound[26422:2] debug: answer cb
[1272618346] unbound[26422:2] debug: Incoming reply id = cf7d
[1272618346] unbound[26422:2] debug: Incoming reply addr = ip4 193.171.255.48 
port 53 (len 16)
[1272618346] unbound[26422:2] debug: lookup size is 1 entries
[1272618346] unbound[26422:2] debug: received udp reply.
[1272618346] unbound[26422:2] debug: udp message[317:0] 
CF7D84000001000200050006036E696302637A00002B0001036E696302637A00002B00010000465000186D4B0501FF11E740A0254EC63C738A47E52ABF3AD91D8C43C018002B0001000046500018EA0C0501144130216E45C4EC2BB8595E817916E8B060D87BC01C000200010000465000070161026E73C018C01C000200010000465000040162C074C01C000200010000465000040163C074C01C000200010000465000040164C074C01C000200010000465000040166C074C07200010001000046500004C2000C01C08500010001000046500004C2000D01C0A500010001000046500004C11DCE01C072001C000100004650001020010678000F0000000000
[1272618346] unbound[26422:2] debug: udp message[317:256] 
0000000001C085001C000100004650001020010678001000000000000000000001C0A5001C000100004650001020010678000100000000000000000001
[1272618346] unbound[26422:2] debug: outnet handle udp reply
[1272618346] unbound[26422:2] debug: measured roundtrip at 9 msec
[1272618346] unbound[26422:2] debug: svcd callbacks start
[1272618346] unbound[26422:2] debug: worker svcd callback for qstate 0x7f43fd12a090
[1272618346] unbound[26422:2] debug: mesh_run: start
[1272618346] unbound[26422:2] debug: iterator[module 1] operate: 
extstate:module_wait_reply event:module_event_reply
[1272618346] unbound[26422:2] info: iterator operate: query <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: process_response: new external response event
[1272618346] unbound[26422:2] info: scrub for <cz. NS IN>
[1272618346] unbound[26422:2] info: response for <nic.cz. DS IN>
[1272618346] unbound[26422:2] info: reply from <cz.> 193.171.255.48#53
[1272618346] unbound[26422:2] info: incoming scrubbed packet: ;; ->>HEADER<<- 
opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr aa ; QUERY: 1, ANSWER: 2, AUTHORITY: 5, ADDITIONAL: 6
;; QUESTION SECTION:
;; nic.cz.	IN	DS

;; ANSWER SECTION:
nic.cz.	18000	IN	DS	27979 5 1 ff11e740a0254ec63c738a47e52abf3ad91d8c43 ; 
xuzoc-cunug-bimud-hafus-kezal-fidig-linyd-puzef-pukoc-tefug-fuxax
nic.cz.	18000	IN	DS	59916 5 1 144130216e45c4ec2bb8595e817916e8b060d87b ; 
xehag-casyd-curug-hyciv-supar-mikuh-vubul-nihov-misyk-bykal-rexux

;; AUTHORITY SECTION:
cz.	18000	IN	NS	a.ns.nic.cz.
cz.	18000	IN	NS	b.ns.nic.cz.
cz.	18000	IN	NS	c.ns.nic.cz.
cz.	18000	IN	NS	d.ns.nic.cz.
cz.	18000	IN	NS	f.ns.nic.cz.

;; ADDITIONAL SECTION:
a.ns.nic.cz.	18000	IN	A	194.0.12.1
b.ns.nic.cz.	18000	IN	A	194.0.13.1
d.ns.nic.cz.	18000	IN	A	193.29.206.1
a.ns.nic.cz.	18000	IN	AAAA	2001:678:f::1
b.ns.nic.cz.	18000	IN	AAAA	2001:678:10::1
d.ns.nic.cz.	18000	IN	AAAA	2001:678:1::1

;; Query time: 0 msec
;; WHEN: Thu Jan  1 01:00:00 1970
;; MSG SIZE  rcvd: 311

[1272618346] unbound[26422:2] debug: iter_handle processing q with state QUERY 
RESPONSE STATE
[1272618346] unbound[26422:2] info: query response was ANSWER
[1272618346] unbound[26422:2] debug: iter_handle processing q with state 
FINISHED RESPONSE STATE
[1272618346] unbound[26422:2] info: finishing processing for <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: mesh_run: iterator module exit state is 
module_finished
[1272618346] unbound[26422:2] debug: validator[module 0] operate: 
extstate:module_wait_module event:module_event_moddone
[1272618346] unbound[26422:2] info: validator operate: query <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: validator: nextmodule returned
[1272618346] unbound[26422:2] debug: not validating response due to CD bit
[1272618346] unbound[26422:2] debug: mesh_run: validator module exit state is 
module_finished
[1272618346] unbound[26422:2] info: validator: inform_super, sub is <nic.cz. DS IN>
[1272618346] unbound[26422:2] info: super is <www.nic.cz. A IN>
[1272618346] unbound[26422:2] info: verify rrset <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: rrset failed to verify due to a lack of 
signatures
[1272618346] unbound[26422:2] debug: verify result: sec_status_bogus
[1272618346] unbound[26422:2] info: DS rrset in DS response did not verify
[1272618346] unbound[26422:2] debug: blacklist ip4 195.66.241.202 port 53 (len 16)
[1272618346] unbound[26422:2] debug: blacklist ip4 194.0.12.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug: blacklist ip4 193.29.206.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug: blacklist add ip4 193.171.255.48 port 53 
(len 16)
[1272618346] unbound[26422:2] debug: validator[module 0] operate: 
extstate:module_wait_subquery event:module_event_pass
[1272618346] unbound[26422:2] info: validator operate: query <www.nic.cz. A IN>
[1272618346] unbound[26422:2] debug: val handle processing q with state 
VAL_FINDKEY_STATE
[1272618346] unbound[26422:2] info: validator: FindKey <www.nic.cz. A IN>
[1272618346] unbound[26422:2] info: current keyname <cz. DNSKEY IN>
[1272618346] unbound[26422:2] info: target keyname <www.nic.cz. DNSKEY IN>
[1272618346] unbound[26422:2] debug: striplab 1
[1272618346] unbound[26422:2] info: next keyname <nic.cz. DNSKEY IN>
[1272618346] unbound[26422:2] debug: No DS RRset
[1272618346] unbound[26422:2] info: generate request <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: mesh_run: validator module exit state is 
module_wait_subquery
[1272618346] unbound[26422:2] debug: validator[module 0] operate: 
extstate:module_state_initial event:module_event_pass
[1272618346] unbound[26422:2] info: validator operate: query <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: validator: pass to next module
[1272618346] unbound[26422:2] debug: mesh_run: validator module exit state is 
module_wait_module
[1272618346] unbound[26422:2] debug: iterator[module 1] operate: 
extstate:module_state_initial event:module_event_pass
[1272618346] unbound[26422:2] debug: process_request: new external request event
[1272618346] unbound[26422:2] debug: iter_handle processing q with state INIT 
REQUEST STATE
[1272618346] unbound[26422:2] info: resolving <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: request has dependency depth of 0
[1272618346] unbound[26422:2] debug: cache blacklisted, going to the network
[1272618346] unbound[26422:2] debug: cache delegation returns delegpt
[1272618346] unbound[26422:2] info: DelegationPoint<cz.>: 5 names (0 missing), 
10 addrs (0 result, 10 avail)
[1272618346] unbound[26422:2] info:   f.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   d.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   c.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   b.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   a.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] debug:    ip6 2001:678:f::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 194.0.12.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:678:10::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 194.0.13.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2a01:40:1000::2 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 195.66.241.202 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:678:1::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 193.29.206.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:628:453:420::48 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 193.171.255.48 port 53 (len 16)
[1272618346] unbound[26422:2] debug: iter_handle processing q with state INIT 
REQUEST STATE (stage 2)
[1272618346] unbound[26422:2] info: resolving (init part 2):  <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: iter_handle processing q with state INIT 
REQUEST STATE (stage 3)
[1272618346] unbound[26422:2] info: resolving (init part 3):  <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: iter_handle processing q with state QUERY 
TARGETS STATE
[1272618346] unbound[26422:2] info: processQueryTargets: <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: processQueryTargets: targetqueries 0, 
currentqueries 0
[1272618346] unbound[26422:2] info: DelegationPoint<cz.>: 5 names (0 missing), 
10 addrs (0 result, 10 avail)
[1272618346] unbound[26422:2] info:   f.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   d.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   c.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   b.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   a.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] debug:    ip6 2001:678:f::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 194.0.12.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:678:10::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 194.0.13.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2a01:40:1000::2 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 195.66.241.202 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:678:1::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 193.29.206.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:628:453:420::48 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 193.171.255.48 port 53 (len 16)
[1272618346] unbound[26422:2] debug: attempt to get extra 3 targets
[1272618346] unbound[26422:2] debug: servselect ip4 193.171.255.48 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=8223 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: servselect ip4 193.29.206.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=602 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: servselect ip4 195.66.241.202 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=1482 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: servselect ip4 194.0.13.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=8823 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: servselect ip4 194.0.12.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=1739 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: selrtt 128823
[1272618346] unbound[26422:2] debug: chase to dnssec lame server
[1272618346] unbound[26422:2] info: sending query: <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: sending to target: <cz.> 194.0.13.1#53
[1272618346] unbound[26422:2] debug: serviced query UDP timeout=8823 msec
[1272618346] unbound[26422:2] debug: inserted new pending reply id=4783
[1272618346] unbound[26422:2] debug: opened UDP if=0 port=42311
[1272618346] unbound[26422:2] debug: comm point start listening 14
[1272618346] unbound[26422:2] debug: mesh_run: iterator module exit state is 
module_wait_reply
[1272618346] unbound[26422:2] info: mesh_run: end 2 recursion states (1 with 
reply, 0 detached), 1 waiting replies, 6752 recursion replies sent, 0 replies 
dropped, 0 states jostled out
[1272618346] unbound[26422:2] info: average recursion processing time 38.779874 sec
[1272618346] unbound[26422:2] info: histogram of recursion processing times
[1272618346] unbound[26422:2] info: [25%]=1.88123 median[50%]=6.94849 [75%]=0.732824
[1272618346] unbound[26422:2] info: lower(secs) upper(secs) recursions
[1272618346] unbound[26422:2] info:    0.000000    0.000001 159
[1272618346] unbound[26422:2] info:    0.004096    0.008192 24
[1272618346] unbound[26422:2] info:    0.008192    0.016384 4
[1272618346] unbound[26422:2] info:    0.016384    0.032768 9
[1272618346] unbound[26422:2] info:    0.032768    0.065536 11
[1272618346] unbound[26422:2] info:    0.065536    0.131072 31
[1272618346] unbound[26422:2] info:    0.131072    0.262144 8
[1272618346] unbound[26422:2] info:    0.262144    0.524288 29
[1272618346] unbound[26422:2] info:    0.524288    1.000000 48
[1272618346] unbound[26422:2] info:    1.000000    2.000000 383
[1272618346] unbound[26422:2] info:    2.000000    4.000000 1044
[1272618346] unbound[26422:2] info:    4.000000    8.000000 1137
[1272618346] unbound[26422:2] info:    8.000000   16.000000 563
[1272618346] unbound[26422:2] info:   16.000000   32.000000 721
[1272618346] unbound[26422:2] info:   32.000000   64.000000 878
[1272618346] unbound[26422:2] info:   64.000000  128.000000 1310
[1272618346] unbound[26422:2] info:  128.000000  256.000000 393
[1272618346] unbound[26422:2] info: 0RDCD mod1  <nic.cz. DS IN>
[1272618346] unbound[26422:2] info: 1RDdc mod0 rep <www.nic.cz. A IN>
[1272618346] unbound[26422:2] debug: cache memory msg=3570894 rrset=4429080 
infra=35743 val=4001591
[1272618346] unbound[26422:2] debug: svcd callbacks end
[1272618346] unbound[26422:2] debug: close of port 53264
[1272618346] unbound[26422:2] debug: close fd 13
[1272618346] unbound[26422:2] debug: answer cb
[1272618346] unbound[26422:2] debug: Incoming reply id = 4783
[1272618346] unbound[26422:2] debug: Incoming reply addr = ip4 194.0.13.1 port 
53 (len 16)
[1272618346] unbound[26422:2] debug: lookup size is 1 entries
[1272618346] unbound[26422:2] debug: received udp reply.
[1272618346] unbound[26422:2] debug: udp message[317:0] 
478384000001000200050006036E696302637A00002B0001036E696302637A00002B00010000465000186D4B0501FF11E740A0254EC63C738A47E52ABF3AD91D8C43C018002B0001000046500018EA0C0501144130216E45C4EC2BB8595E817916E8B060D87BC01C000200010000465000070161026E73C018C01C000200010000465000040162C074C01C000200010000465000040163C074C01C000200010000465000040164C074C01C000200010000465000040166C074C07200010001000046500004C2000C01C08500010001000046500004C2000D01C0A500010001000046500004C11DCE01C072001C000100004650001020010678000F0000000000
[1272618346] unbound[26422:2] debug: udp message[317:256] 
0000000001C085001C000100004650001020010678001000000000000000000001C0A5001C000100004650001020010678000100000000000000000001
[1272618346] unbound[26422:2] debug: outnet handle udp reply
[1272618346] unbound[26422:2] debug: measured roundtrip at 42 msec
[1272618346] unbound[26422:2] debug: svcd callbacks start
[1272618346] unbound[26422:2] debug: worker svcd callback for qstate 0x7f43fd12a090
[1272618346] unbound[26422:2] debug: mesh_run: start
[1272618346] unbound[26422:2] debug: iterator[module 1] operate: 
extstate:module_wait_reply event:module_event_reply
[1272618346] unbound[26422:2] info: iterator operate: query <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: process_response: new external response event
[1272618346] unbound[26422:2] info: scrub for <cz. NS IN>
[1272618346] unbound[26422:2] info: response for <nic.cz. DS IN>
[1272618346] unbound[26422:2] info: reply from <cz.> 194.0.13.1#53
[1272618346] unbound[26422:2] info: incoming scrubbed packet: ;; ->>HEADER<<- 
opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr aa ; QUERY: 1, ANSWER: 2, AUTHORITY: 5, ADDITIONAL: 6
;; QUESTION SECTION:
;; nic.cz.	IN	DS

;; ANSWER SECTION:
nic.cz.	18000	IN	DS	27979 5 1 ff11e740a0254ec63c738a47e52abf3ad91d8c43 ; 
xuzoc-cunug-bimud-hafus-kezal-fidig-linyd-puzef-pukoc-tefug-fuxax
nic.cz.	18000	IN	DS	59916 5 1 144130216e45c4ec2bb8595e817916e8b060d87b ; 
xehag-casyd-curug-hyciv-supar-mikuh-vubul-nihov-misyk-bykal-rexux

;; AUTHORITY SECTION:
cz.	18000	IN	NS	a.ns.nic.cz.
cz.	18000	IN	NS	b.ns.nic.cz.
cz.	18000	IN	NS	c.ns.nic.cz.
cz.	18000	IN	NS	d.ns.nic.cz.
cz.	18000	IN	NS	f.ns.nic.cz.

;; ADDITIONAL SECTION:
a.ns.nic.cz.	18000	IN	A	194.0.12.1
b.ns.nic.cz.	18000	IN	A	194.0.13.1
d.ns.nic.cz.	18000	IN	A	193.29.206.1
a.ns.nic.cz.	18000	IN	AAAA	2001:678:f::1
b.ns.nic.cz.	18000	IN	AAAA	2001:678:10::1
d.ns.nic.cz.	18000	IN	AAAA	2001:678:1::1

;; Query time: 0 msec
;; WHEN: Thu Jan  1 01:00:00 1970
;; MSG SIZE  rcvd: 311

[1272618346] unbound[26422:2] debug: iter_handle processing q with state QUERY 
RESPONSE STATE
[1272618346] unbound[26422:2] info: query response was ANSWER
[1272618346] unbound[26422:2] debug: iter_handle processing q with state 
FINISHED RESPONSE STATE
[1272618346] unbound[26422:2] info: finishing processing for <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: mesh_run: iterator module exit state is 
module_finished
[1272618346] unbound[26422:2] debug: validator[module 0] operate: 
extstate:module_wait_module event:module_event_moddone
[1272618346] unbound[26422:2] info: validator operate: query <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: validator: nextmodule returned
[1272618346] unbound[26422:2] debug: not validating response due to CD bit
[1272618346] unbound[26422:2] debug: mesh_run: validator module exit state is 
module_finished
[1272618346] unbound[26422:2] info: validator: inform_super, sub is <nic.cz. DS IN>
[1272618346] unbound[26422:2] info: super is <www.nic.cz. A IN>
[1272618346] unbound[26422:2] info: verify rrset <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: rrset failed to verify due to a lack of 
signatures
[1272618346] unbound[26422:2] debug: verify result: sec_status_bogus
[1272618346] unbound[26422:2] info: DS rrset in DS response did not verify
[1272618346] unbound[26422:2] debug: blacklist ip4 193.171.255.48 port 53 (len 16)
[1272618346] unbound[26422:2] debug: blacklist ip4 195.66.241.202 port 53 (len 16)
[1272618346] unbound[26422:2] debug: blacklist ip4 194.0.12.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug: blacklist ip4 193.29.206.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug: blacklist add ip4 194.0.13.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug: validator[module 0] operate: 
extstate:module_wait_subquery event:module_event_pass
[1272618346] unbound[26422:2] info: validator operate: query <www.nic.cz. A IN>
[1272618346] unbound[26422:2] debug: val handle processing q with state 
VAL_FINDKEY_STATE
[1272618346] unbound[26422:2] info: validator: FindKey <www.nic.cz. A IN>
[1272618346] unbound[26422:2] info: current keyname <cz. DNSKEY IN>
[1272618346] unbound[26422:2] info: target keyname <www.nic.cz. DNSKEY IN>
[1272618346] unbound[26422:2] debug: striplab 1
[1272618346] unbound[26422:2] info: next keyname <nic.cz. DNSKEY IN>
[1272618346] unbound[26422:2] debug: No DS RRset
[1272618346] unbound[26422:2] info: generate request <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: mesh_run: validator module exit state is 
module_wait_subquery
[1272618346] unbound[26422:2] debug: validator[module 0] operate: 
extstate:module_state_initial event:module_event_pass
[1272618346] unbound[26422:2] info: validator operate: query <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: validator: pass to next module
[1272618346] unbound[26422:2] debug: mesh_run: validator module exit state is 
module_wait_module
[1272618346] unbound[26422:2] debug: iterator[module 1] operate: 
extstate:module_state_initial event:module_event_pass
[1272618346] unbound[26422:2] debug: process_request: new external request event
[1272618346] unbound[26422:2] debug: iter_handle processing q with state INIT 
REQUEST STATE
[1272618346] unbound[26422:2] info: resolving <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: request has dependency depth of 0
[1272618346] unbound[26422:2] debug: cache blacklisted, going to the network
[1272618346] unbound[26422:2] debug: cache delegation returns delegpt
[1272618346] unbound[26422:2] info: DelegationPoint<cz.>: 5 names (0 missing), 
10 addrs (0 result, 10 avail)
[1272618346] unbound[26422:2] info:   f.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   d.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   c.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   b.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   a.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] debug:    ip6 2001:678:f::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 194.0.12.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:678:10::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 194.0.13.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2a01:40:1000::2 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 195.66.241.202 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:678:1::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 193.29.206.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:628:453:420::48 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 193.171.255.48 port 53 (len 16)
[1272618346] unbound[26422:2] debug: iter_handle processing q with state INIT 
REQUEST STATE (stage 2)
[1272618346] unbound[26422:2] info: resolving (init part 2):  <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: iter_handle processing q with state INIT 
REQUEST STATE (stage 3)
[1272618346] unbound[26422:2] info: resolving (init part 3):  <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: iter_handle processing q with state QUERY 
TARGETS STATE
[1272618346] unbound[26422:2] info: processQueryTargets: <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: processQueryTargets: targetqueries 0, 
currentqueries 0
[1272618346] unbound[26422:2] info: DelegationPoint<cz.>: 5 names (0 missing), 
10 addrs (0 result, 10 avail)
[1272618346] unbound[26422:2] info:   f.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   d.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   c.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   b.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] info:   a.ns.nic.cz. * A AAAA
[1272618346] unbound[26422:2] debug:    ip6 2001:678:f::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 194.0.12.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:678:10::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 194.0.13.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2a01:40:1000::2 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 195.66.241.202 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:678:1::1 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 193.29.206.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    ip6 2001:628:453:420::48 port 53 (len 28)
[1272618346] unbound[26422:2] debug:    ip4 193.171.255.48 port 53 (len 16)
[1272618346] unbound[26422:2] debug: attempt to get extra 3 targets
[1272618346] unbound[26422:2] debug: servselect ip4 193.171.255.48 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=8223 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: servselect ip4 193.29.206.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=602 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: servselect ip4 195.66.241.202 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=1482 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: servselect ip4 194.0.13.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=8143 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: servselect ip4 194.0.12.1 port 53 (len 16)
[1272618346] unbound[26422:2] debug:    rtt=1739 lost=0 DNSSEC_LAME
[1272618346] unbound[26422:2] debug: selrtt 480602
[1272618346] unbound[26422:2] debug: chase to blacklisted dnssec lame server
[1272618346] unbound[26422:2] info: sending query: <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: sending to target: <cz.> 193.29.206.1#53
[1272618346] unbound[26422:2] debug: serviced query UDP timeout=602 msec
[1272618346] unbound[26422:2] debug: inserted new pending reply id=fd69
[1272618346] unbound[26422:2] debug: opened UDP if=0 port=55119
[1272618346] unbound[26422:2] debug: comm point start listening 13
[1272618346] unbound[26422:2] debug: mesh_run: iterator module exit state is 
module_wait_reply
[1272618346] unbound[26422:2] info: mesh_run: end 2 recursion states (1 with 
reply, 0 detached), 1 waiting replies, 6752 recursion replies sent, 0 replies 
dropped, 0 states jostled out
[1272618346] unbound[26422:2] info: average recursion processing time 38.779874 sec
[1272618346] unbound[26422:2] info: histogram of recursion processing times
[1272618346] unbound[26422:2] info: [25%]=1.88123 median[50%]=6.94849 [75%]=0.732824
[1272618346] unbound[26422:2] info: lower(secs) upper(secs) recursions
[1272618346] unbound[26422:2] info:    0.000000    0.000001 159
[1272618346] unbound[26422:2] info:    0.004096    0.008192 24
[1272618346] unbound[26422:2] info:    0.008192    0.016384 4
[1272618346] unbound[26422:2] info:    0.016384    0.032768 9
[1272618346] unbound[26422:2] info:    0.032768    0.065536 11
[1272618346] unbound[26422:2] info:    0.065536    0.131072 31
[1272618346] unbound[26422:2] info:    0.131072    0.262144 8
[1272618346] unbound[26422:2] info:    0.262144    0.524288 29
[1272618346] unbound[26422:2] info:    0.524288    1.000000 48
[1272618346] unbound[26422:2] info:    1.000000    2.000000 383
[1272618346] unbound[26422:2] info:    2.000000    4.000000 1044
[1272618346] unbound[26422:2] info:    4.000000    8.000000 1137
[1272618346] unbound[26422:2] info:    8.000000   16.000000 563
[1272618346] unbound[26422:2] info:   16.000000   32.000000 721
[1272618346] unbound[26422:2] info:   32.000000   64.000000 878
[1272618346] unbound[26422:2] info:   64.000000  128.000000 1310
[1272618346] unbound[26422:2] info:  128.000000  256.000000 393
[1272618346] unbound[26422:2] info: 0RDCD mod1  <nic.cz. DS IN>
[1272618346] unbound[26422:2] info: 1RDdc mod0 rep <www.nic.cz. A IN>
[1272618346] unbound[26422:2] debug: cache memory msg=3570894 rrset=4429080 
infra=35743 val=4001591
[1272618346] unbound[26422:2] debug: svcd callbacks end
[1272618346] unbound[26422:2] debug: close of port 42311
[1272618346] unbound[26422:2] debug: close fd 14
[1272618346] unbound[26422:2] debug: answer cb
[1272618346] unbound[26422:2] debug: Incoming reply id = fd69
[1272618346] unbound[26422:2] debug: Incoming reply addr = ip4 193.29.206.1 port 
53 (len 16)
[1272618346] unbound[26422:2] debug: lookup size is 1 entries
[1272618346] unbound[26422:2] debug: received udp reply.
[1272618346] unbound[26422:2] debug: udp message[96:0] 
FD6984100001000200000000036E696302637A00002B0001C00C002B0001000046500018EA0C0501144130216E45C4EC2BB8595E817916E8B060D87BC00C002B00010000465000186D4B0501FF11E740A0254EC63C738A47E52ABF3AD91D8C43
[1272618346] unbound[26422:2] debug: outnet handle udp reply
[1272618346] unbound[26422:2] debug: measured roundtrip at 1 msec
[1272618346] unbound[26422:2] debug: svcd callbacks start
[1272618346] unbound[26422:2] debug: worker svcd callback for qstate 0x7f43fd12a090
[1272618346] unbound[26422:2] debug: mesh_run: start
[1272618346] unbound[26422:2] debug: iterator[module 1] operate: 
extstate:module_wait_reply event:module_event_reply
[1272618346] unbound[26422:2] info: iterator operate: query <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: process_response: new external response event
[1272618346] unbound[26422:2] info: scrub for <cz. NS IN>
[1272618346] unbound[26422:2] info: response for <nic.cz. DS IN>
[1272618346] unbound[26422:2] info: reply from <cz.> 193.29.206.1#53
[1272618346] unbound[26422:2] info: incoming scrubbed packet: ;; ->>HEADER<<- 
opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr aa ; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 0
;; QUESTION SECTION:
;; nic.cz.	IN	DS

;; ANSWER SECTION:
nic.cz.	18000	IN	DS	59916 5 1 144130216e45c4ec2bb8595e817916e8b060d87b ; 
xehag-casyd-curug-hyciv-supar-mikuh-vubul-nihov-misyk-bykal-rexux
nic.cz.	18000	IN	DS	27979 5 1 ff11e740a0254ec63c738a47e52abf3ad91d8c43 ; 
xuzoc-cunug-bimud-hafus-kezal-fidig-linyd-puzef-pukoc-tefug-fuxax

;; AUTHORITY SECTION:

;; ADDITIONAL SECTION:

;; Query time: 0 msec
;; WHEN: Thu Jan  1 01:00:00 1970
;; MSG SIZE  rcvd: 96

[1272618346] unbound[26422:2] debug: iter_handle processing q with state QUERY 
RESPONSE STATE
[1272618346] unbound[26422:2] info: query response was ANSWER
[1272618346] unbound[26422:2] debug: iter_handle processing q with state 
FINISHED RESPONSE STATE
[1272618346] unbound[26422:2] info: finishing processing for <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: mesh_run: iterator module exit state is 
module_finished
[1272618346] unbound[26422:2] debug: validator[module 0] operate: 
extstate:module_wait_module event:module_event_moddone
[1272618346] unbound[26422:2] info: validator operate: query <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: validator: nextmodule returned
[1272618346] unbound[26422:2] debug: not validating response due to CD bit
[1272618346] unbound[26422:2] debug: mesh_run: validator module exit state is 
module_finished
[1272618346] unbound[26422:2] info: validator: inform_super, sub is <nic.cz. DS IN>
[1272618346] unbound[26422:2] info: super is <www.nic.cz. A IN>
[1272618346] unbound[26422:2] info: verify rrset <nic.cz. DS IN>
[1272618346] unbound[26422:2] debug: rrset failed to verify due to a lack of 
signatures
[1272618346] unbound[26422:2] debug: verify result: sec_status_bogus
[1272618346] unbound[26422:2] info: DS rrset in DS response did not verify
[1272618346] unbound[26422:2] debug: validator[module 0] operate: 
extstate:module_wait_subquery event:module_event_pass
[1272618346] unbound[26422:2] info: validator operate: query <www.nic.cz. A IN>
[1272618346] unbound[26422:2] debug: val handle processing q with state 
VAL_VALIDATE_STATE
[1272618346] unbound[26422:2] info: Could not establish a chain of trust to keys 
for <nic.cz. DNSKEY IN>
[1272618346] unbound[26422:2] debug: val handle processing q with state 
VAL_FINISHED_STATE
[1272618346] unbound[26422:2] info: validation failure <www.nic.cz. A IN>: no 
signatures from 193.29.206.1 for DS nic.cz. while building chain of trust
[1272618346] unbound[26422:2] debug: mesh_run: validator module exit state is 
module_finished
[1272618346] unbound[26422:2] debug: query took 0.081936 sec
[1272618346] unbound[26422:2] info: mesh_run: end 0 recursion states (0 with 
reply, 0 detached), 0 waiting replies, 6753 recursion replies sent, 0 replies 
dropped, 0 states jostled out
[1272618346] unbound[26422:2] info: average recursion processing time 38.774144 sec
[1272618346] unbound[26422:2] info: histogram of recursion processing times
[1272618346] unbound[26422:2] info: [25%]=1.87979 median[50%]=6.94139 [75%]=0.720611
[1272618346] unbound[26422:2] info: lower(secs) upper(secs) recursions
[1272618346] unbound[26422:2] info:    0.000000    0.000001 159
[1272618346] unbound[26422:2] info:    0.004096    0.008192 24
[1272618346] unbound[26422:2] info:    0.008192    0.016384 4
[1272618346] unbound[26422:2] info:    0.016384    0.032768 9
[1272618346] unbound[26422:2] info:    0.032768    0.065536 11
[1272618346] unbound[26422:2] info:    0.065536    0.131072 32
[1272618346] unbound[26422:2] info:    0.131072    0.262144 8
[1272618346] unbound[26422:2] info:    0.262144    0.524288 29
[1272618346] unbound[26422:2] info:    0.524288    1.000000 48
[1272618346] unbound[26422:2] info:    1.000000    2.000000 383
[1272618346] unbound[26422:2] info:    2.000000    4.000000 1044
[1272618346] unbound[26422:2] info:    4.000000    8.000000 1137
[1272618346] unbound[26422:2] info:    8.000000   16.000000 563
[1272618346] unbound[26422:2] info:   16.000000   32.000000 721
[1272618346] unbound[26422:2] info:   32.000000   64.000000 878
[1272618346] unbound[26422:2] info:   64.000000  128.000000 1310
[1272618346] unbound[26422:2] info:  128.000000  256.000000 393
[1272618346] unbound[26422:2] debug: cache memory msg=3570726 rrset=4429080 
infra=35743 val=4001589
[1272618346] unbound[26422:2] debug: svcd callbacks end
[1272618346] unbound[26422:2] debug: close of port 55119
[1272618346] unbound[26422:2] debug: close fd 13
[1272618346] unbound[26422:2] debug: answer from the cache failed
[1272618346] unbound[26422:2] debug: udp request from ip4 127.0.0.1 port 52101 
(len 16)
[1272618346] unbound[26422:2] debug: mesh_run: start
[1272618346] unbound[26422:2] debug: validator[module 0] operate: 
extstate:module_state_initial event:module_event_new
--- /LOG ---

On 29.4.2010 19:21, Zbynek Michl wrote:
> On 29.4.2010 17:56, Zbynek Michl wrote:
>>> I have just made fixes to svn trunk that may help in this case. But
>>> they may not be sufficient to help you here (its about looking in the
>>> key cache to see if nic.cz needs DNSSEC).
>>
>> Ok, thanks, I will try the latest trunk version.
>
> Hmm, r2106 experiences the same issue :(
>
> It seems that there is no exact change between correct/incorrect
> validation in the one time point. On the start there are all answers
> correct, and when I am trying more and more (different in a few cycles)
> requests, then there are more and more incorrect answers. And in some
> time point all answers are incorrect from the resolver until cache is
> flushed (probably).
>
> Regards,
> Zbynek