Validation failure of DNSSEC signed domain names

Zbynek_Michl · April 29, 2010, 1:11pm

Hello,

I am experiencing a problem with validation of signed domain names. When I start Unbound, validation works fine. But when I put resolver under extreme load (thousands queries per second), I get SERVFAIL reply on every correctly signed domain query after some time.

It is probably caching bug, because if I restart Unbound or wait some time, then Unbound responses correctly again.

Here is log of validating A type query for www.nic.cz when Unbound is in the "strange" state.

--- LOG ---
[1272541060] unbound[18734:1] debug: answer from the cache failed
[1272541060] unbound[18734:1] debug: udp request from ip4 127.0.0.1 port 45681 (len 16)
[1272541060] unbound[18734:1] debug: mesh_run: start
[1272541060] unbound[18734:1] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_new
[1272541060] unbound[18734:1] info: validator operate: query <www.nic.cz. A IN>
[1272541060] unbound[18734:1] debug: validator: pass to next module
[1272541060] unbound[18734:1] debug: mesh_run: validator module exit state is module_wait_module
[1272541060] unbound[18734:1] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass
[1272541060] unbound[18734:1] debug: process_request: new external request event
[1272541060] unbound[18734:1] debug: iter_handle processing q with state INIT REQUEST STATE
[1272541060] unbound[18734:1] info: resolving <www.nic.cz. A IN>
[1272541060] unbound[18734:1] debug: request has dependency depth of 0
[1272541060] unbound[18734:1] debug: cache delegation returns delegpt
[1272541060] unbound[18734:1] info: DelegationPoint<nic.cz.>: 3 names (0 missing), 6 addrs (0 result, 6 avail)
[1272541060] unbound[18734:1] info: a.ns.nic.cz. * A AAAA
[1272541060] unbound[18734:1] info: b.ns.nic.cz. * A AAAA
[1272541060] unbound[18734:1] info: d.ns.nic.cz. * A AAAA
[1272541060] unbound[18734:1] debug: ip6 2001:678:1::1 port 53 (len 28)
[1272541060] unbound[18734:1] debug: ip4 193.29.206.1 port 53 (len 16)
[1272541060] unbound[18734:1] debug: ip6 2001:678:10::1 port 53 (len 28)
[1272541060] unbound[18734:1] debug: ip4 194.0.13.1 port 53 (len 16)
[1272541060] unbound[18734:1] debug: ip6 2001:678:f::1 port 53 (len 28)
[1272541060] unbound[18734:1] debug: ip4 194.0.12.1 port 53 (len 16)
[1272541060] unbound[18734:1] debug: iter_handle processing q with state INIT REQUEST STATE (stage 2)
[1272541060] unbound[18734:1] info: resolving (init part 2): <www.nic.cz. A IN>
[1272541060] unbound[18734:1] debug: iter_handle processing q with state INIT REQUEST STATE (stage 3)
[1272541060] unbound[18734:1] info: resolving (init part 3): <www.nic.cz. A IN>
[1272541060] unbound[18734:1] debug: iter_handle processing q with state QUERY TARGETS STATE
[1272541060] unbound[18734:1] info: processQueryTargets: <www.nic.cz. A IN>
[1272541060] unbound[18734:1] debug: processQueryTargets: targetqueries 0, currentqueries 0
[1272541060] unbound[18734:1] info: DelegationPoint<nic.cz.>: 3 names (0 missing), 6 addrs (0 result, 6 avail)
[1272541060] unbound[18734:1] info: a.ns.nic.cz. * A AAAA
[1272541060] unbound[18734:1] info: b.ns.nic.cz. * A AAAA
[1272541060] unbound[18734:1] info: d.ns.nic.cz. * A AAAA
[1272541060] unbound[18734:1] debug: ip6 2001:678:1::1 port 53 (len 28)
[1272541060] unbound[18734:1] debug: ip4 193.29.206.1 port 53 (len 16)
[1272541060] unbound[18734:1] debug: ip6 2001:678:10::1 port 53 (len 28)
[1272541060] unbound[18734:1] debug: ip4 194.0.13.1 port 53 (len 16)
[1272541060] unbound[18734:1] debug: ip6 2001:678:f::1 port 53 (len 28)
[1272541060] unbound[18734:1] debug: ip4 194.0.12.1 port 53 (len 16)
[1272541060] unbound[18734:1] debug: attempt to get extra 3 targets
[1272541060] unbound[18734:1] debug: servselect ip4 194.0.12.1 port 53 (len 16)
[1272541060] unbound[18734:1] debug: rtt=8469 lost=0
[1272541060] unbound[18734:1] debug: servselect ip4 194.0.13.1 port 53 (len 16)
[1272541060] unbound[18734:1] debug: rtt=8389 lost=0
[1272541060] unbound[18734:1] debug: servselect ip4 193.29.206.1 port 53 (len 16)
[1272541060] unbound[18734:1] debug: rtt=60 lost=0
[1272541060] unbound[18734:1] debug: selrtt 60
[1272541060] unbound[18734:1] info: sending query: <www.nic.cz. A IN>
[1272541060] unbound[18734:1] debug: sending to target: <nic.cz.> 193.29.206.1#53
[1272541060] unbound[18734:1] debug: serviced query UDP timeout=60 msec
[1272541060] unbound[18734:1] debug: inserted new pending reply id=e60a
[1272541060] unbound[18734:1] debug: opened UDP if=0 port=8457
[1272541060] unbound[18734:1] debug: comm point start listening 19
[1272541060] unbound[18734:1] debug: mesh_run: iterator module exit state is module_wait_reply
[1272541060] unbound[18734:1] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 4717 recursion replies sent, 0 replies dropped, 0 states jostled out
[1272541060] unbound[18734:1] info: average recursion processing time 52.429515 sec
[1272541060] unbound[18734:1] info: histogram of recursion processing times
[1272541060] unbound[18734:1] info: [25%]=10.3537 median[50%]=24.2551 [75%]=26.5821
[1272541060] unbound[18734:1] info: lower(secs) upper(secs) recursions
[1272541060] unbound[18734:1] info: 0.000000 0.000001 1
[1272541060] unbound[18734:1] info: 0.004096 0.008192 5
[1272541060] unbound[18734:1] info: 0.008192 0.016384 4
[1272541060] unbound[18734:1] info: 0.016384 0.032768 2
[1272541060] unbound[18734:1] info: 0.032768 0.065536 7
[1272541060] unbound[18734:1] info: 0.065536 0.131072 3
[1272541060] unbound[18734:1] info: 0.131072 0.262144 8
[1272541060] unbound[18734:1] info: 0.262144 0.524288 19
[1272541060] unbound[18734:1] info: 0.524288 1.000000 84
[1272541060] unbound[18734:1] info: 1.000000 2.000000 128
[1272541060] unbound[18734:1] info: 2.000000 4.000000 144
[1272541060] unbound[18734:1] info: 4.000000 8.000000 366
[1272541060] unbound[18734:1] info: 8.000000 16.000000 207
[1272541060] unbound[18734:1] info: 16.000000 32.000000 311
[1272541060] unbound[18734:1] info: 32.000000 64.000000 1411
[1272541060] unbound[18734:1] info: 64.000000 128.000000 2017
[1272541060] unbound[18734:1] info: 0RDd mod1 rep <www.nic.cz. A IN>
[1272541060] unbound[18734:1] debug: cache memory msg=4456435 rrset=4455263 infra=36173 val=4267600
[1272541060] unbound[18734:1] debug: answer cb
[1272541060] unbound[18734:1] debug: Incoming reply id = e60a
[1272541060] unbound[18734:1] debug: Incoming reply addr = ip4 193.29.206.1 port 53 (len 16)
[1272541060] unbound[18734:1] debug: lookup size is 1 entries
[1272541060] unbound[18734:1] debug: received udp reply.
[1272541060] unbound[18734:1] debug: udp message[227:0] E60A8400000100010003000603777777036E696302637A0000010001C00C00010001000007080004D91FCD32C010000200010000070800070164026E73C010C010000200010000070800040161C03AC010000200010000070800040162C03AC04B00010001000007080004C2000C01C04B001C000100000708001020010678000F00000000000000000001C05B00010001000007080004C2000D01C05B001C000100000708001020010678001000000000000000000001C03800010001000007080004C11DCE01C038001C000100000708001020010678000100000000000000000001
[1272541060] unbound[18734:1] debug: outnet handle udp reply
[1272541060] unbound[18734:1] debug: measured roundtrip at 1 msec
[1272541060] unbound[18734:1] debug: svcd callbacks start
[1272541060] unbound[18734:1] debug: worker svcd callback for qstate 0x7f4c98ba1f20
[1272541060] unbound[18734:1] debug: mesh_run: start
[1272541060] unbound[18734:1] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
[1272541060] unbound[18734:1] info: iterator operate: query <www.nic.cz. A IN>
[1272541060] unbound[18734:1] debug: process_response: new external response event
[1272541060] unbound[18734:1] info: scrub for <nic.cz. NS IN>
[1272541060] unbound[18734:1] info: response for <www.nic.cz. A IN>
[1272541060] unbound[18734:1] info: reply from <nic.cz.> 193.29.206.1#53
[1272541060] unbound[18734:1] 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 d.ns.nic.cz.
nic.cz. 1800 IN NS a.ns.nic.cz.
nic.cz. 1800 IN NS b.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

[1272541060] unbound[18734:1] debug: iter_handle processing q with state QUERY RESPONSE STATE
[1272541060] unbound[18734:1] info: query response was ANSWER
[1272541060] unbound[18734:1] debug: iter_handle processing q with state FINISHED RESPONSE STATE
[1272541060] unbound[18734:1] info: finishing processing for <www.nic.cz. A IN>
[1272541060] unbound[18734:1] debug: mesh_run: iterator module exit state is module_finished
[1272541060] unbound[18734:1] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone
[1272541060] unbound[18734:1] info: validator operate: query <www.nic.cz. A IN>
[1272541060] unbound[18734:1] debug: validator: nextmodule returned
[1272541060] unbound[18734:1] debug: val handle processing q with state VAL_INIT_STATE
[1272541060] unbound[18734:1] debug: validator classification positive
[1272541060] unbound[18734:1] info: no signer, using <www.nic.cz. TYPE0 CLASS0>
[1272541060] unbound[18734:1] debug: val handle processing q with state VAL_FINISHED_STATE
[1272541060] unbound[18734:1] info: validation failure <www.nic.cz. A IN>: key for validation www.nic.cz. is marked as invalid because of a previous validation failure <www.nic.cz. A IN>: no DNSSEC records from 193.29.206.1 for DS www.nic.cz. while building chain of trust
[1272541060] unbound[18734:1] debug: mesh_run: validator module exit state is module_finished
[1272541060] unbound[18734:1] debug: query took 0.001500 sec
[1272541060] unbound[18734:1] info: mesh_run: end 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 4718 recursion replies sent, 0 replies dropped, 0 states jostled out
[1272541060] unbound[18734:1] info: average recursion processing time 52.418403 sec
[1272541060] unbound[18734:1] info: histogram of recursion processing times
[1272541060] unbound[18734:1] info: [25%]=10.3151 median[50%]=24.2438 [75%]=26.5741
[1272541060] unbound[18734:1] info: lower(secs) upper(secs) recursions
[1272541060] unbound[18734:1] info: 0.000000 0.000001 1
[1272541060] unbound[18734:1] info: 0.001024 0.002048 1
[1272541060] unbound[18734:1] info: 0.004096 0.008192 5
[1272541060] unbound[18734:1] info: 0.008192 0.016384 4
[1272541060] unbound[18734:1] info: 0.016384 0.032768 2
[1272541060] unbound[18734:1] info: 0.032768 0.065536 7
[1272541060] unbound[18734:1] info: 0.065536 0.131072 3
[1272541060] unbound[18734:1] info: 0.131072 0.262144 8
[1272541060] unbound[18734:1] info: 0.262144 0.524288 19
[1272541060] unbound[18734:1] info: 0.524288 1.000000 84
[1272541060] unbound[18734:1] info: 1.000000 2.000000 128
[1272541060] unbound[18734:1] info: 2.000000 4.000000 144
[1272541060] unbound[18734:1] info: 4.000000 8.000000 366
[1272541060] unbound[18734:1] info: 8.000000 16.000000 207
[1272541060] unbound[18734:1] info: 16.000000 32.000000 311
[1272541060] unbound[18734:1] info: 32.000000 64.000000 1411
[1272541060] unbound[18734:1] info: 64.000000 128.000000 2017
[1272541060] unbound[18734:1] debug: cache memory msg=4456435 rrset=4455263 infra=36173 val=4267600
[1272541060] unbound[18734:1] debug: svcd callbacks end
[1272541060] unbound[18734:1] debug: close of port 8457
[1272541060] unbound[18734:1] debug: close fd 19
--- /LOG ---

The error that can be seen above is:

"info: no signer, using <www.nic.cz. TYPE0 CLASS0>"

and then

"info: validation failure <www.nic.cz. A IN>: key for validation www.nic.cz. is marked as invalid because of a previous validation failure <www.nic.cz. A IN>: no DNSSEC records from 193.29.206.1 for DS www.nic.cz. while building chain of trust"

Yes, because resolver should query 193.29.206.1 for DS nic.cz., not www.nic.cz.
So it seems, that Unbound can not parse signer's name from the appropriate RRSIG that is cached, because there is no Unbound's query for the RRSIG on the network at this time.

Regards,
Zbynek

Wouter · April 29, 2010, 2:29pm

Hi Zbynek,

Which version of unbound is this (1.4.4?)

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).

Can you do an unbound-control lookup nic.cz (when it is in the bad state) ?

I am experiencing a problem with validation of signed domain names. When
I start Unbound, validation works fine. But when I put resolver under
extreme load (thousands queries per second), I get SERVFAIL reply on
every correctly signed domain query after some time.

It is probably caching bug, because if I restart Unbound or wait some
time, then Unbound responses correctly again.

Here is log of validating A type query for www.nic.cz when Unbound is in
the "strange" state.

--- LOG ---

...

The error that can be seen above is:

"info: no signer, using <www.nic.cz. TYPE0 CLASS0>"

and then

"info: validation failure <www.nic.cz. A IN>: key for validation
www.nic.cz. is marked as invalid because of a previous validation
failure <www.nic.cz. A IN>: no DNSSEC records from 193.29.206.1 for DS
www.nic.cz. while building chain of trust"

Yes, because resolver should query 193.29.206.1 for DS nic.cz., not
www.nic.cz.
So it seems, that Unbound can not parse signer's name from the
appropriate RRSIG that is cached, because there is no Unbound's query
for the RRSIG on the network at this time.

The issue is that it gets no DNSSEC data for nic.cz. Assuming that is
normal, then the errors above are also normal, so its can parse the
RRSIG fine, but it just does not get one. What really happens is that
it gets no RRSIG and assumes this must be because www.nic.cz is an
unsigned subzone of nic.cz, and starts searching for that proof - a
query for the DS denial for it - but this also does not work.

Best regards,
Wouter

Zbynek_Michl · April 29, 2010, 3:56pm

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Hi Zbynek,

Which version of unbound is this (1.4.4?)

Yes, it is 1.4.4-1 from Debian unstable

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.

Can you do an unbound-control lookup nic.cz (when it is in the bad state) ?

In current state I get correct answer for A www.nic.cz, but SERVFAIL for AAAA www.nic.cz.

--- OUT ---
The following name servers are used for lookup of nic.cz.
;rrset 1107 3 1 11 4
nic.cz. 1107 IN NS d.ns.nic.cz.
nic.cz. 1107 IN NS b.ns.nic.cz.
nic.cz. 1107 IN NS a.ns.nic.cz.
nic.cz. 1107 IN RRSIG NS 5 2 1800 20100512080302 20100428080302 62837 nic.cz. Vey1LxxZh6bY7WJfUVJ2T4tMrP0hmPrT1sft19osJKp4AvIgrk9iyuGvSldh3la4m0fKJoZgnMqOOiwGQLeHWHdHUym4d5du9a0dZNfh4I/NOSK4GFwYENu98YLFLpc0dvCFRS54vzcoHriKmxgK+w04WF/j/pcCroi3xfHkWj8= ;{id = 62837}
;rrset 917 1 1 11 4
a.ns.nic.cz. 917 IN A 194.0.12.1
a.ns.nic.cz. 917 IN RRSIG A 5 4 1800 20100512080302 20100428080302 62837 nic.cz. RXwerdKvK5S4CpHnpHdJHd4mrRN2A5+gHKFrWiLx67igPaPjzshL/us1iRbP+gU5TIT6R509Dh0p97HKvcqKuI3N6QlfuMapsG9VZifom5ucoroOlRhLcXNOcXWhA9OFucVp5kw+Fumy2VxC5+kPGFQHQL8I397w3ZtYXwm92aU= ;{id = 62837}
;rrset 917 1 1 11 4
a.ns.nic.cz. 917 IN AAAA 2001:678:f::1
a.ns.nic.cz. 917 IN RRSIG AAAA 5 4 1800 20100512080302 20100428080302 62837 nic.cz. rCLjR880rjIZGicHHq63Gq5m+WfM0n2yn+aW92xpufryP5pEaYUftSflNU4BQBsi1cTNHG8w87/gH+td9Sqn7qf1yRnn77USbJO+l0dI29fSqhUc1xsAwGax4ngBFgu7XOiugK2rpjw6gkzbFm71ZjUIN/d29TCd3FSM/OQaMnQ= ;{id = 62837}
;rrset 917 1 1 11 4
b.ns.nic.cz. 917 IN A 194.0.13.1
b.ns.nic.cz. 917 IN RRSIG A 5 4 1800 20100512080302 20100428080302 62837 nic.cz. ZUMnD1hyOtW+QNimx+ciD9VpW6SgmSn38KByTF3m6NFqVZMYq1kflzB8O6yXUCZM7DJ2VjqyTmz29DjOdMPdjVCGbNfIsTw0DDQL0HJgbPdhpkBKnI5zB27uPa9c5a1/YHcK+U0mJS0jXQcHZ0ESAG5CaAeOA40wmPp6tWDYlwU= ;{id = 62837}
;rrset 917 1 1 11 4
b.ns.nic.cz. 917 IN AAAA 2001:678:10::1
b.ns.nic.cz. 917 IN RRSIG AAAA 5 4 1800 20100512080302 20100428080302 62837 nic.cz. MhzeMMl7CplPDCw2BGqDBynBWHahsBuZ+RJGAMUQZZnmi2HrOEIf3DIgpLLz0BPCV2iVII/vda+EXk6uLDrZOkRoEeNpnC6GEu9gSCPJic941B0dn6j8Tq8Aya/yrZULFcIczJR8Kol2BvFWonMN2nj8LXGyZJupW0Unj9ousyA= ;{id = 62837}
;rrset 917 1 1 11 4
d.ns.nic.cz. 917 IN A 193.29.206.1
d.ns.nic.cz. 917 IN RRSIG A 5 4 1800 20100512080302 20100428080302 62837 nic.cz. OKaPN50Vsl1ckhGJyLIdWChRtgFZ/oew2o45XqWSBGQAU8VPFGBrsUmUsPA+W6iOEHjEoojlI8g9M5/PvgfnkQT/LnaIy2r9Zc8gMy8RMHKpET60/Fxhq5PSddIrxNdBzb1+tt5jSAiLvVYvyZ1FBmRiSpRGixHPW7XTnY85Vyg= ;{id = 62837}
;rrset 917 1 1 11 4
d.ns.nic.cz. 917 IN AAAA 2001:678:1::1
d.ns.nic.cz. 917 IN RRSIG AAAA 5 4 1800 20100512080302 20100428080302 62837 nic.cz. RnjoxRNy/LNJgwH8P3WYuHM6aI6EK5wLPRxVXIHxVkM5+jZT4QlcHa7Nf3/Mrg3YcVeHRFj2J1VTFaw5NODh+OcgJyFU53+Q0Ay7GF0BxhpN9Sq8vPX80okCf+da2TA/FmbbFNOqaei0OgSSq2J12AwOluSMXK+suxOHHBkmdBY= ;{id = 62837}
Delegation with 3 names, of which 0 can be examined to query further addresses.
It provides 6 IP addresses.
2001:678:1::1 not in infra cache.
193.29.206.1 rtt 184 msec, 0 lost. noEDNS probed.
2001:678:10::1 not in infra cache.
194.0.13.1 rtt 3109 msec, 0 lost. noEDNS probed.
2001:678:f::1 not in infra cache.
194.0.12.1 rtt 1456 msec, 0 lost. noEDNS probed.
--- /OUT ---

Regards,
Zbynek

Zbynek_Michl · April 29, 2010, 5:21pm

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

Zbynek_Michl · April 30, 2010, 9:49am

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 ---

Zbynek_Michl · April 30, 2010, 4:32pm

So in the "strange" state the resolver does not send queries with DO bit, thus does not receive RRSIG for query type and therefore it can not validate result. Then the remote authoritative server (who sent answer without RRSIG) is added to the blacklist.

In the log (complete version has been sent in previous mail):

Request for DS nic.cz is sent to 194.0.12.1 (without DO bit), replied DS is not validated due to missing its RRSIG and 194.0.12.1 is blacklisted.

Regards,
Zbynek

Wouter · May 4, 2010, 8:48am

Hi Zbynek,

Can you try with the svn trunk r2107? I have made a bugfix which may
help, it stops unbound from disabling its dnssec expectation after it
has seen a response fail without rrsigs. This could turn into a long
causation chain: dnssec expectation lost, therefore EDNS backoff
possible (with timeouts happening), therefore EDNS backoff stored in
cache, stopping it from sending DO bits (and a bug fixed in r2106 where
this fact got 'stuck' into the cache).

After discussion with my colleague I think this fix may help... The
evidence you kindly provided supports the hypothesis and this fix should
stop it from failing continuously (but a single query still fails).

Also, I believe there to be some trouble with your setup, which is
causing unbound to have slower turnaround; can you email me (offlist if
you want) your configuration (unbound.conf and what is your ulimit(open
files) for unbound, did you compile with libevent) ? I think this
slower turnaround exists because you have that failing query.

Best regards,
Wouter

Zbynek_Michl · May 5, 2010, 11:51am

Hi Wouter,

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Hi Zbynek,

Can you try with the svn trunk r2107? I have made a bugfix which may
help, it stops unbound from disabling its dnssec expectation after it
has seen a response fail without rrsigs. This could turn into a long
causation chain: dnssec expectation lost, therefore EDNS backoff
possible (with timeouts happening), therefore EDNS backoff stored in
cache, stopping it from sending DO bits (and a bug fixed in r2106 where
this fact got 'stuck' into the cache).

Still the same The only difference is when "strange" state occurs then replies for DNSSEC queries which I never tried before are OK, but those I have already been tried are still SERVFAILed.

After discussion with my colleague I think this fix may help... The
evidence you kindly provided supports the hypothesis and this fix should
stop it from failing continuously (but a single query still fails).

Also, I believe there to be some trouble with your setup, which is
causing unbound to have slower turnaround; can you email me (offlist if
you want) your configuration (unbound.conf and what is your ulimit(open
files) for unbound, did you compile with libevent) ? I think this
slower turnaround exists because you have that failing query.

Yes, Unbound is compiled with libevent.

# ulimit -n
32768

This is my config for testing purposes:

--- CONFIG ---

Zbynek_Michl · May 5, 2010, 12:58pm

Hmm, so I used optimalization according to documentation <http://www.unbound.net/documentation/howto_optimise.html> and it seems that Unbound works fine right now I am going to do some more tests.

Thanks,
Zbynek

Ondrej_Sury · May 10, 2010, 1:48pm

Wouter,

it is still worrying me that "optimizing" configuration could be used
to circumvent SERVFAILs. It still seems to me that something deeper is
still involved, because it causes only signed domains to fail.
Unsigned domains and domains not in cache are still ok.

Could you please look at this bug further? Since we are able to
repeatedly reproduce this bug, it should not be impossible to trace it
further down.

Ondrej

Wouter · May 26, 2010, 11:59am

Hi Ondrej,

Just a minute before I was to post I had made fixes in svn trunk to
limit such problems due to config trouble, Zbynek said he optimised and
that setting also alleviated the problem.

So, bugfix in svn, workaround is to use the optimise HOWTO on
unbound.net. Let me know if testing reveals more.

Best regards,
Wouter