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

Zbynek Michl zbynek.michl at nic.cz
Fri Apr 30 16:32:51 UTC 2010 

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

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

More information about the Unbound-users mailing list