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