Maintained by: NLnet Labs

[Unbound-users] query signed RR fails for a while after unbound-control flush

Koh-ichi Ito
Thu Jan 15 07:10:36 CET 2009


Hello,

Thanks for HINFO case. Here's another one.

I experience the following problem.

- Query signed RR results NOERROR.
- Resign the zone on authoritative server.
- Query same RR results NOERROR.
- Invoke unbound-control flush.
- Query same RR results SERVFAIL.
- After some interval, I'm not sure but it may be $TTL of
  the zone, it results NOERROR again.

Though the following result is produced with stub-zone:
hack, same problem occurs on global domain, too.

What is wrong?

# zonedata before signing
$TTL 1m
@	IN	SOA	ns.example.jp. hostmaster.example.jp. (
			0	; overridden by dnssec-signzone
			15m
			10m
			4w
			15m)
$INCLUDE ksk.key
$INCLUDE zsk.key
	2m	NS	ns.example.jp.
ns	3m	A	10.2.0.18
foo	4m	A	10.20.30.40

# output of dig and unbound-control
Script started on Thu Jan 15 14:53:04 2009
kohi at vm1[1]% /usr/bin/su
Password:
vm1# dig @127.0.0.1 version.bind txt chaos

; <<>> DiG 9.4.2-P2 <<>> @127.0.0.1 version.bind txt chaos
; (1 server found)
;; global options:  printcmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 17415
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;version.bind.			CH	TXT

;; ANSWER SECTION:
version.bind.		0	CH	TXT	"unbound 1.2.0"

;; Query time: 0 msec
;; SERVER: 127.0.0.1#53(127.0.0.1)
;; WHEN: Thu Jan 15 14:53:32 2009
;; MSG SIZE  rcvd: 56

vm1# dig +dnssec @127.0.0.1 foo.example.jp

; <<>> DiG 9.4.2-P2 <<>> +dnssec @127.0.0.1 foo.example.jp
; (1 server found)
;; global options:  printcmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 14367
;; flags: qr rd ra ad; QUERY: 1, ANSWER: 2, AUTHORITY: 2, ADDITIONAL: 3

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 4096
;; QUESTION SECTION:
;foo.example.jp.			IN	A

;; ANSWER SECTION:
foo.example.jp.		240	IN	A	10.20.30.40
foo.example.jp.		240	IN	RRSIG	A 5 3 240 20090301044615 20090115044615 59520 example.jp. G93MjniWgY2rW2s375NbrBDOLrh0CqmH47BrxKTvX1ElqPyxrq7oE9Vu UJjDASLI1c03/i4Yj73w/Ubbb+SlXpqhcn37RsO5TryjU3y37aQBqZrB DZnFLNUY3pYu6Wci

;; AUTHORITY SECTION:
example.jp.		120	IN	NS	ns.example.jp.
example.jp.		120	IN	RRSIG	NS 5 2 120 20090301044615 20090115044615 59520 example.jp. fUWtaLmZlBEjEUgDA9wQcS0dJThrVDPNbaSfpD3xg4KoRLZlB4KJhh0D N1H/ou4RNtx4iwk66qVr4XFJJyNwz2NFQHIM0J5TF5oG43Yb/ynLGO+E U4h7pKQiuXoBcGEz

;; ADDITIONAL SECTION:
ns.example.jp.		180	IN	A	10.2.0.18
ns.example.jp.		180	IN	RRSIG	A 5 3 180 20090301044615 20090115044615 59520 example.jp. QwGJ9c5lsJCPgI8tswiVqCidX+n4bchBDttN3jPTjY0ddf1PCeeXNJQn mcH0WwamG6eC9nJu1jeSeHS5J07VoSAxadCbq15jn0SSI57cT5OT95i1 R5qWJPg6fT5u4dZM

;; Query time: 146 msec
;; SERVER: 127.0.0.1#53(127.0.0.1)
;; WHEN: Thu Jan 15 14:53:46 2009
;; MSG SIZE  rcvd: 506

	# It's O.K.
	# resign at the authoritative server.

vm1# dig +dnssec @127.0.0.1 foo.example.jp

; <<>> DiG 9.4.2-P2 <<>> +dnssec @127.0.0.1 foo.example.jp
; (1 server found)
;; global options:  printcmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 34057
;; flags: qr rd ra ad; QUERY: 1, ANSWER: 2, AUTHORITY: 2, ADDITIONAL: 3

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 4096
;; QUESTION SECTION:
;foo.example.jp.			IN	A

;; ANSWER SECTION:
foo.example.jp.		209	IN	A	10.20.30.40
foo.example.jp.		209	IN	RRSIG	A 5 3 240 20090301044615 20090115044615 59520 example.jp. G93MjniWgY2rW2s375NbrBDOLrh0CqmH47BrxKTvX1ElqPyxrq7oE9Vu UJjDASLI1c03/i4Yj73w/Ubbb+SlXpqhcn37RsO5TryjU3y37aQBqZrB DZnFLNUY3pYu6Wci

;; AUTHORITY SECTION:
example.jp.		89	IN	NS	ns.example.jp.
example.jp.		89	IN	RRSIG	NS 5 2 120 20090301044615 20090115044615 59520 example.jp. fUWtaLmZlBEjEUgDA9wQcS0dJThrVDPNbaSfpD3xg4KoRLZlB4KJhh0D N1H/ou4RNtx4iwk66qVr4XFJJyNwz2NFQHIM0J5TF5oG43Yb/ynLGO+E U4h7pKQiuXoBcGEz

;; ADDITIONAL SECTION:
ns.example.jp.		149	IN	A	10.2.0.18
ns.example.jp.		149	IN	RRSIG	A 5 3 180 20090301044615 20090115044615 59520 example.jp. QwGJ9c5lsJCPgI8tswiVqCidX+n4bchBDttN3jPTjY0ddf1PCeeXNJQn mcH0WwamG6eC9nJu1jeSeHS5J07VoSAxadCbq15jn0SSI57cT5OT95i1 R5qWJPg6fT5u4dZM

;; Query time: 0 msec
;; SERVER: 127.0.0.1#53(127.0.0.1)
;; WHEN: Thu Jan 15 14:54:17 2009
;; MSG SIZE  rcvd: 506

	# It' s still O.K.

vm1# /proj/unbound-1.2.0/sbin/unbound-control flush foo.example.jp
ok
vm1# dig +dnssec @127.0.0.1 foo.example.jp

; <<>> DiG 9.4.2-P2 <<>> +dnssec @127.0.0.1 foo.example.jp
; (1 server found)
;; global options:  printcmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 29411
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 4096
;; QUESTION SECTION:
;foo.example.jp.			IN	A

;; Query time: 2 msec
;; SERVER: 127.0.0.1#53(127.0.0.1)
;; WHEN: Thu Jan 15 14:54:46 2009
;; MSG SIZE  rcvd: 43

	# Oops!

vm1# sleep 60; dig +dnssec @127.0.0.1 foo.example.jp

; <<>> DiG 9.4.2-P2 <<>> +dnssec @127.0.0.1 foo.example.jp
; (1 server found)
;; global options:  printcmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 1711
;; flags: qr rd ra ad; QUERY: 1, ANSWER: 2, AUTHORITY: 2, ADDITIONAL: 3

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 4096
;; QUESTION SECTION:
;foo.example.jp.			IN	A

;; ANSWER SECTION:
foo.example.jp.		240	IN	A	10.20.30.40
foo.example.jp.		240	IN	RRSIG	A 5 3 240 20090301045359 20090115045359 16236 example.jp. ZZORs2cPenp0750acuVnQwA26Y1/dtm0HD2BWMdspX3fM5BhTcMlwp8j C88TU7Q5ifGc65/2c0bNjWFn+Nn6OfXIEWuFYYiKM3EZXLQxFZPxBWUD pBXyJ3U2THlmmM2l

;; AUTHORITY SECTION:
example.jp.		120	IN	NS	ns.example.jp.
example.jp.		120	IN	RRSIG	NS 5 2 120 20090301045359 20090115045359 16236 example.jp. lSma+vDcxytZoVU8qgtv1xvNKwg4PF53gUh8/Q38wM9C3jmHopwLOaRP x6d+8v/mbqM7TsFnI/XAIhKrV4v0DiuwsmgPy2/9oVGYFu0dnBuUt3Kw YeEJTEKGvbvYJQNe

;; ADDITIONAL SECTION:
ns.example.jp.		180	IN	A	10.2.0.18
ns.example.jp.		180	IN	RRSIG	A 5 3 180 20090301045359 20090115045359 16236 example.jp. O3i7lhtKVXw2l7KPsoy7ODRUFyYc8IrQlNAuNVYit+T9owBXQtl4CTsB 6FFeP1hjnRc0LiMLQOWhCitzPzz7kBJZCzpHgJnj6/NXXaex+B+crJLx Q4cDrtGqgFkmfQ9N

;; Query time: 3 msec
;; SERVER: 127.0.0.1#53(127.0.0.1)
;; WHEN: Thu Jan 15 14:56:01 2009
;; MSG SIZE  rcvd: 506

	# It comes back.

vm1# exit
exit
kohi at vm1[2]% exit

Script done on Thu Jan 15 14:56:05 2009


# output of unbound
Script started on Thu Jan 15 14:52:50 2009
kohi at vm1[1]% /usr/bin/su
Password:
vm1# /proj/unbound-1.2.0/sbin/unbound -dv
[1231998797] unbound[29635:0] notice: Start of unbound 1.2.0.
[1231998797] unbound[29635:0] notice: init module 0: validator
[1231998797] unbound[29635:0] notice: init module 1: iterator
[1231998797] unbound[29635:0] notice: openssl has no entropy, seeding with time and pid
[1231998797] unbound[29635:0] info: start of service (unbound 1.2.0).

	# invoke dig which results NOERROR

[1231998826] unbound[29635:0] info: resolving <foo.example.jp. A IN>
[1231998826] unbound[29635:0] info: priming . IN NS
[1231998826] unbound[29635:0] info: response for <. NS IN>
[1231998826] unbound[29635:0] info: reply from <.> 192.203.230.10#53
[1231998826] unbound[29635:0] info: query response was ANSWER
[1231998826] unbound[29635:0] info: priming successful for <. NS IN>
[1231998826] unbound[29635:0] info: use stub <example.jp. NS IN>
[1231998826] unbound[29635:0] info: response for <foo.example.jp. A IN>
[1231998826] unbound[29635:0] info: reply from <example.jp.> 10.2.0.18#53
[1231998826] unbound[29635:0] info: query response was ANSWER
[1231998826] unbound[29635:0] info: prime trust anchor
[1231998826] unbound[29635:0] info: resolving <example.jp. DNSKEY IN>
[1231998826] unbound[29635:0] info: use stub <example.jp. NS IN>
[1231998826] unbound[29635:0] info: response for <example.jp. DNSKEY IN>
[1231998826] unbound[29635:0] info: reply from <example.jp.> 10.2.0.18#53
[1231998826] unbound[29635:0] info: query response was ANSWER
[1231998826] unbound[29635:0] info: validate keys with anchor(DNSKEY): sec_status_secure
[1231998826] unbound[29635:0] info: Successfully primed trust anchor <example.jp. DNSKEY IN>
[1231998826] unbound[29635:0] info: validate(positive): sec_status_secure
[1231998826] unbound[29635:0] info: validation success <foo.example.jp. A IN>

	# resign at the authoritative server

	# invoke dig once here, which results NOERROR,
	# but no explanation is generated with single -v

	# unbound-control flush

[1231998876] unbound[29635:0] info: control cmd:  flush foo.example.jp

	# invoke dig which results SERVFAIL

[1231998886] unbound[29635:0] info: resolving <foo.example.jp. A IN>
[1231998886] unbound[29635:0] info: use stub <example.jp. NS IN>
[1231998886] unbound[29635:0] info: response for <foo.example.jp. A IN>
[1231998886] unbound[29635:0] info: reply from <example.jp.> 10.2.0.18#53
[1231998886] unbound[29635:0] info: query response was ANSWER
[1231998886] unbound[29635:0] info: Validate: message contains bad rrsets

	# approx 1min interval
	# invoke dig which results NOERROR

[1231998961] unbound[29635:0] info: resolving <foo.example.jp. A IN>
[1231998961] unbound[29635:0] info: use stub <example.jp. NS IN>
[1231998961] unbound[29635:0] info: response for <foo.example.jp. A IN>
[1231998961] unbound[29635:0] info: reply from <example.jp.> 10.2.0.18#53
[1231998961] unbound[29635:0] info: query response was ANSWER
[1231998961] unbound[29635:0] info: prime trust anchor
[1231998961] unbound[29635:0] info: resolving <example.jp. DNSKEY IN>
[1231998961] unbound[29635:0] info: use stub <example.jp. NS IN>
[1231998961] unbound[29635:0] info: response for <example.jp. DNSKEY IN>
[1231998961] unbound[29635:0] info: reply from <example.jp.> 10.2.0.18#53
[1231998961] unbound[29635:0] info: query response was ANSWER
[1231998961] unbound[29635:0] info: validate keys with anchor(DNSKEY): sec_status_secure
[1231998961] unbound[29635:0] info: Successfully primed trust anchor <example.jp. DNSKEY IN>
[1231998961] unbound[29635:0] info: validate(positive): sec_status_secure
[1231998961] unbound[29635:0] info: validation success <foo.example.jp. A IN>
^C[1231998967] unbound[29635:0] info: service stopped (unbound 1.2.0).
[1231998967] unbound[29635:0] info: server stats for thread 0: 5 queries, 2 answers from cache, 3 recursions
[1231998967] unbound[29635:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0
[1231998967] unbound[29635:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 3 recursion replies sent, 0 replies dropped, 0 states jostled out
[1231998967] unbound[29635:0] info: average recursion processing time 0.049181 sec
[1231998967] unbound[29635:0] info: histogram of recursion processing times
[1231998967] unbound[29635:0] info: [25%]=0 median[50%]=0 [75%]=0
[1231998967] unbound[29635:0] info: lower(secs) upper(secs) recursions
[1231998967] unbound[29635:0] info:    0.001024    0.002048 2
[1231998967] unbound[29635:0] info:    0.131072    0.262144 1
vm1# exit
exit
kohi at vm1[2]% exit

Script done on Thu Jan 15 14:56:09 2009


Thanks in advance.

						Koh-ichi Ito