BIND 10 #1222: resolver problems with IPv6
BIND 10 Development
do-not-reply at isc.org
Thu Sep 8 14:47:32 UTC 2011
#1222: resolver problems with IPv6
---------------------------------+-----------------------------------------
Reporter: jreed | Owner:
Type: defect | Status: new
Priority: critical | Milestone: New Tasks
Component: resolver | Keywords:
Sensitive: 0 | Defect Severity: Very High
Sub-Project: DNS | Feature Depending on Ticket:
Estimated Difficulty: 0 | Add Hours to Ticket: 0
Total Hours: 0 | Internal?: 0
---------------------------------+-----------------------------------------
I often have SERVFAILs when some nameservers are AAAA. But sometime later
queries are successful. For example:
{{{
$ time dig @127.0.0.1 bind10.isc.org
; <<>> DiG 9.5.0-P2 <<>> @127.0.0.1 bind10.isc.org
; (1 server found)
;; global options: printcmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 18552
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0
;; QUESTION SECTION:
;bind10.isc.org. IN A
;; Query time: 4023 msec
;; SERVER: 127.0.0.1#53(127.0.0.1)
;; WHEN: Thu Sep 8 09:41:12 2011
;; MSG SIZE rcvd: 32
4.04s real 0.01s user 0.00s system
$ time dig @127.0.0.1 bind10.isc.org
; <<>> DiG 9.5.0-P2 <<>> @127.0.0.1 bind10.isc.org
; (1 server found)
;; global options: printcmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 12394
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 8, ADDITIONAL: 13
;; QUESTION SECTION:
;bind10.isc.org. IN A
;; ANSWER SECTION:
bind10.isc.org. 3600 IN A 149.20.48.40
;; AUTHORITY SECTION:
isc.org. 86396 IN NS sfba.sns-pb.isc.org.
isc.org. 86396 IN NS ns.isc.afilias-nst.info.
isc.org. 86396 IN NS ams.sns-pb.isc.org.
isc.org. 86396 IN NS ord.sns-pb.isc.org.
bind10.isc.org. 3600 IN NS ord.sns-pb.isc.org.
bind10.isc.org. 3600 IN NS n10.isc.org.
bind10.isc.org. 3600 IN NS ams.sns-pb.isc.org.
bind10.isc.org. 3600 IN NS sfba.sns-pb.isc.org.
;; ADDITIONAL SECTION:
ams.sns-pb.isc.org. 86396 IN A 199.6.1.30
ams.sns-pb.isc.org. 86396 IN AAAA 2001:500:60::30
ord.sns-pb.isc.org. 86396 IN A 199.6.0.30
ord.sns-pb.isc.org. 86396 IN AAAA 2001:500:71::30
sfba.sns-pb.isc.org. 86396 IN A 149.20.64.3
sfba.sns-pb.isc.org. 86396 IN AAAA 2001:4f8:0:2::19
ams.sns-pb.isc.org. 7200 IN A 199.6.1.30
ams.sns-pb.isc.org. 7200 IN AAAA 2001:500:60::30
n10.isc.org. 7200 IN A 149.20.48.59
ord.sns-pb.isc.org. 7200 IN A 199.6.0.30
ord.sns-pb.isc.org. 7200 IN AAAA 2001:500:71::30
sfba.sns-pb.isc.org. 7200 IN A 149.20.64.3
sfba.sns-pb.isc.org. 7200 IN AAAA 2001:4f8:0:2::19
;; Query time: 2151 msec
;; SERVER: 127.0.0.1#53(127.0.0.1)
;; WHEN: Thu Sep 8 09:41:14 2011
;; MSG SIZE rcvd: 487
2.17s real 0.00s user 0.00s system
}}}
And the logging:
{{{
2011-09-08 09:41:00.019 INFO [b10-boss.boss] BIND10_STARTING starting
BIND10: bind10 20110223 (BIND 10 20110809)
2011-09-08 09:41:00.025 INFO [b10-boss.boss] BIND10_SOCKCREATOR_INIT
initializing socket creator parser
2011-09-08 09:41:00.031 INFO [b10-boss.boss] BIND10_STARTING_PROCESS
starting process b10-msgq
2011-09-08 09:41:00.258 INFO [b10-boss.boss] BIND10_STARTING_PROCESS
starting process b10-cfgmgr
2011-09-08 09:41:01.267 INFO [b10-boss.boss] BIND10_STARTING_PROCESS
starting process ccsession
2011-09-08 09:41:01.296 INFO [b10-boss.boss]
BIND10_READING_BOSS_CONFIGURATION reading boss configuration
2011-09-08 09:41:01.296 INFO [b10-boss.boss]
BIND10_CONFIGURATION_START_AUTH start authoritative server: False
2011-09-08 09:41:01.296 INFO [b10-boss.boss]
BIND10_CONFIGURATION_START_RESOLVER start resolver: True
2011-09-08 09:41:01.297 INFO [b10-boss.boss] BIND10_STARTING_PROCESS
starting process b10-resolver
2011-09-08 09:41:01.304 2011-09-08 09:41:01.345INFO INFO [ b10-boss.boss
[] b10-resolver.resolverBIND10_STARTING_PROCESS starting process
b10-stats]
RESOLVER_STARTING starting resolver with command line 'b10-resolver -v'
2011-09-08 09:41:01.3532011-09-08 09:41:01.354 INFODEBUG [
[b10-resolver.resolverb10-boss.boss] ] RESOLVER_CREATED main resolver
object createdBIND10_STARTING_PROCESS starting process b10-stats-httpd
2011-09-08 09:41:01.449 2011-09-08 09:41:01.455DEBUG
[INFOb10-resolver.cache ] CACHE_RESOLVER_INIT initializing resolver cache
for class IN
[b10-boss.boss] BIND10_STARTING_PROCESS starting process b10-cmdctl
2011-09-08 09:41:01.532 DEBUG [b10-resolver.cache] CACHE_RRSET_INIT
initializing RRset cache for 20000 RRsets of class IN
2011-09-08 09:41:01.533 DEBUG [b10-resolver.cache] CACHE_RRSET_INIT
initializing RRset cache for 10000 RRsets of class IN
2011-09-08 09:41:01.534 DEBUG [b10-resolver.cache] CACHE_MESSAGES_INIT
initialized message cache for 10000 messages of class IN
2011-09-08 09:41:01.537 DEBUG [b10-resolver.cache]
CACHE_RESOLVER_UPDATE_MSG updating message for ./NS/IN
2011-09-08 09:41:01.537 DEBUG [b10-resolver.cache] CACHE_MESSAGES_UPDATE
updating message entry ./NS/IN
2011-09-08 09:41:01.538 DEBUG [b10-resolver.cache] CACHE_RRSET_UPDATE
updating RRset ./NS/IN in the cache
2011-09-08 09:41:01.539 DEBUG [b10-resolver.cache] CACHE_RRSET_LOOKUP
looking up ./NS/IN in RRset cache
2011-09-08 09:41:01.540 DEBUG [b10-resolver.cache] CACHE_RRSET_NOT_FOUND
no RRset found for ./NS/IN in cache
2011-09-08 09:41:01.540 DEBUG [b10-resolver.cache] CACHE_RRSET_UPDATE
updating RRset l.root-servers.net./A/IN in the cache
2011-09-08 09:41:01.540 DEBUG [b10-resolver.cache] CACHE_RRSET_LOOKUP
looking up l.root-servers.net./A/IN in RRset cache
2011-09-08 09:41:01.540 DEBUG [b10-resolver.cache] CACHE_RRSET_NOT_FOUND
no RRset found for l.root-servers.net./A/IN in cache
2011-09-08 09:41:01.541 DEBUG [b10-resolver.cache] CACHE_RRSET_UPDATE
updating RRset l.root-servers.net./AAAA/IN in the cache
2011-09-08 09:41:01.541 DEBUG [b10-resolver.cache] CACHE_RRSET_LOOKUP
looking up l.root-servers.net./AAAA/IN in RRset cache
2011-09-08 09:41:01.541 DEBUG [b10-resolver.cache] CACHE_RRSET_NOT_FOUND
no RRset found for l.root-servers.net./AAAA/IN in cache
2011-09-08 09:41:01.541 DEBUG [b10-resolver.cache]
CACHE_RESOLVER_UPDATE_RRSET updating RRset for ./NS/IN
2011-09-08 09:41:01.542 DEBUG [b10-resolver.cache] CACHE_LOCALZONE_UPDATE
updating local zone element at key .2
2011-09-08 09:41:01.542 DEBUG [b10-resolver.cache] CACHE_RRSET_UPDATE
updating RRset ./NS/IN in the cache
2011-09-08 09:41:01.542 DEBUG [b10-resolver.cache] CACHE_RRSET_LOOKUP
looking up ./NS/IN in RRset cache
2011-09-08 09:41:01.542 DEBUG [b10-resolver.cache] CACHE_RRSET_REMOVE_OLD
removing old RRset for ./NS/IN to make space for new one
2011-09-08 09:41:01.544 DEBUG [b10-resolver.cache]
CACHE_RESOLVER_UPDATE_RRSET updating RRset for l.root-servers.net./A/IN
2011-09-08 09:41:01.544 DEBUG [b10-resolver.cache] CACHE_LOCALZONE_UPDATE
updating local zone element at key l.root-servers.net.1
2011-09-08 09:41:01.544 DEBUG [b10-resolver.cache] CACHE_RRSET_UPDATE
updating RRset l.root-servers.net./A/IN in the cache
2011-09-08 09:41:01.544 DEBUG [b10-resolver.cache] CACHE_RRSET_LOOKUP
looking up l.root-servers.net./A/IN in RRset cache
2011-09-08 09:41:01.544 DEBUG [b10-resolver.cache] CACHE_RRSET_REMOVE_OLD
removing old RRset for l.root-servers.net./A/IN to make space for new one
2011-09-08 09:41:01.545 INFO [b10-boss.boss] BIND10_STARTUP_COMPLETE BIND
10 started
2011-09-08 09:41:01.546 DEBUG [b10-resolver.cache]
CACHE_RESOLVER_UPDATE_RRSET updating RRset for l.root-servers.net./AAAA/IN
2011-09-08 09:41:01.546 DEBUG [b10-resolver.cache] CACHE_LOCALZONE_UPDATE
updating local zone element at key l.root-servers.net.28
2011-09-08 09:41:01.546 DEBUG [b10-resolver.cache] CACHE_RRSET_UPDATE
updating RRset l.root-servers.net./AAAA/IN in the cache
2011-09-08 09:41:01.546 DEBUG [b10-resolver.cache] CACHE_RRSET_LOOKUP
looking up l.root-servers.net./AAAA/IN in RRset cache
2011-09-08 09:41:01.546 DEBUG [b10-resolver.cache] CACHE_RRSET_REMOVE_OLD
removing old RRset for l.root-servers.net./AAAA/IN to make space for new
one
2011-09-08 09:41:01.546 DEBUG [b10-resolver.resolver]
RESOLVER_SERVICE_CREATED service object created
2011-09-08 09:41:01.548 DEBUG [b10-resolver.cc] CC_ESTABLISH trying to
establish connection with message queue daemon at
/home/reed/work/isc/bind10-install/var/bind10-devel/msgq_socket
2011-09-08 09:41:01.606 DEBUG [b10-resolver.cc] CC_ESTABLISHED
successfully connected to message queue daemon
2011-09-08 09:41:01.616 DEBUG [b10-resolver.cc] CC_SUBSCRIBE subscribing
to communication group Resolver
2011-09-08 09:41:01.616 DEBUG [b10-resolver.cc] CC_GROUP_SEND sending
message '{ "command": [ "module_spec", { "commands": [ { "command_args": [
], "command_description": "Shut down recursive DNS server",
"command_name": "shutdown" } ], "config_data": [ { "item_default": 2000,
"item_name": "timeout_query", "item_optional": false, "item_type":
"integer" }, { "item_default": 4000, "item_name": "timeout_client",
"item_optional": false, "item_type": "integer" }, { "item_default": 30000,
"item_name": "timeout_lookup", "item_optional": false, "item_type":
"integer" }, { "item_default": 3, "item_name": "retries", "item_optional":
false, "item_type": "integer" }, { "item_default": [ ], "item_name":
"forward_addresses", "item_optional": true, "item_type": "list",
"list_item_spec": { "item_default": { }, "item_name": "address",
"item_optional": false, "item_type": "map", "map_item_spec": [ {
"item_default": "::1", "item_name": "address", "item_optional": false,
"item_type": "string" }, { "item_default": 53, "item_name": "port",
"item_optional": false, "item_type": "integer" } ] } }, { "item_default":
[ ], "item_name": "root_addresses", "item_optional": true, "item_type":
"list", "list_item_spec": { "item_default": { }, "item_name": "address",
"item_optional": false, "item_type": "map", "map_item_spec": [ {
"item_default": "::1", "item_name": "address", "item_optional": false,
"item_type": "string" }, { "item_default": 53, "item_name": "port",
"item_optional": false, "item_type": "integer" } ] } }, { "item_default":
[ { "address": "::1", "port": 53 }, { "address": "127.0.0.1", "port": 53 }
], "item_name": "listen_on", "item_optional": false, "item_type": "list",
"list_item_spec": { "item_default": { }, "item_name": "address",
"item_optional": false, "item_type": "map", "map_item_spec": [ {
"item_default": "::1", "item_name": "address", "item_optional": false,
"item_type": "string" }, { "item_default": 53, "item_name": "port",
"item_optional": false, "item_type": "integer" } ] } }, { "item_default":
[ { "action": "ACCEPT", "from": "127.0.0.1" }, { "action": "ACCEPT",
"from": "::1" } ], "item_name": "query_acl", "item_optional": false,
"item_type": "list", "list_item_spec": { "item_default": { },
"item_name": "rule", "item_optional": false, "item_type": "map",
"map_item_spec": [ { "item_default": "", "item_name": "action",
"item_optional": false, "item_type": "string" }, { "item_default": "",
"item_name": "from", "item_optional": false, "item_type": "string" } ] } }
], "module_description": "Recursive service", "module_name": "Resolver" }
] }' to group 'ConfigManager'
2011-09-08 09:41:01.616 DEBUG [b10-resolver.cc] CC_GROUP_RECEIVE trying to
receive a message
2011-09-08 09:41:01.712 DEBUG [b10-resolver.cc] CC_GROUP_RECEIVED message
arrived ('{ "from": "4e68d3fc_2 at new-host-3", "group": "ConfigManager",
"instance": "*", "reply": 0, "seq": 8, "to": "4e68d3fd_4 at new-host-3",
"type": "send" }', '{ "result": [ 0 ] }')
2011-09-08 09:41:01.712 DEBUG [b10-resolver.cc] CC_GROUP_SEND sending
message '{ "command": [ "get_config", { "module_name": "Resolver" } ] }'
to group 'ConfigManager'
2011-09-08 09:41:01.712 DEBUG [b10-resolver.cc] CC_GROUP_RECEIVE trying to
receive a message
2011-09-08 09:41:01.717 DEBUG [b10-resolver.cc] CC_GROUP_RECEIVED message
arrived ('{ "from": "4e68d3fc_2 at new-host-3", "group": "ConfigManager",
"instance": "*", "reply": 1, "seq": 9, "to": "4e68d3fd_4 at new-host-3",
"type": "send" }', '{ "result": [ 0, { "listen_on": [ { "address": "::1",
"port": 53 }, { "address": "0.0.0.0", "port": 53 } ], "query_acl": [ {
"action": "ACCEPT", "from": "any4" }, { "action": "ACCEPT", "from": "::1"
} ] } ] }')
2011-09-08 09:41:01.717 DEBUG [b10-resolver.resolver]
RESOLVER_CONFIG_UPDATED configuration updated: { "listen_on": [ {
"address": "::1", "port": 53 }, { "address": "0.0.0.0", "port": 53 } ],
"query_acl": [ { "action": "ACCEPT", "from": "any4" }, { "action":
"ACCEPT", "from": "::1" } ] }
2011-09-08 09:41:01.718 DEBUG [b10-resolver.server_common]
SRVCOMM_SET_LISTEN setting addresses to listen to
2011-09-08 09:41:01.718 DEBUG [b10-resolver.server_common]
SRVCOMM_ADDRESS_VALUE address to set: ::1#53
2011-09-08 09:41:01.718 DEBUG [b10-resolver.server_common]
SRVCOMM_ADDRESS_VALUE address to set: 0.0.0.0#53
2011-09-08 09:41:01.719 INFO [b10-resolver.resolver]
RESOLVER_SET_QUERY_ACL query ACL is configured
2011-09-08 09:41:01.719 DEBUG [b10-resolver.resolver] RESOLVER_QUERY_SETUP
query setup
2011-09-08 09:41:01.719 DEBUG [b10-resolver.cc] CC_GROUP_SEND sending
message '{ "command": [ "get_module_spec", { "module_name": "Logging" } ]
}' to group 'ConfigManager'
2011-09-08 09:41:01.719 DEBUG [b10-resolver.cc] CC_GROUP_RECEIVE trying to
receive a message
2011-09-08 09:41:01.725 DEBUG [b10-resolver.cc] CC_GROUP_RECEIVED message
arrived ('{ "from": "4e68d3fc_2 at new-host-3", "group": "ConfigManager",
"instance": "*", "reply": 2, "seq": 10, "to": "4e68d3fd_4 at new-host-3",
"type": "send" }', '{ "result": [ 0, { "commands": [ ], "config_data": [
{ "item_default": [ ], "item_name": "loggers", "item_optional": false,
"item_type": "list", "list_item_spec": { "item_default": { },
"item_name": "logger", "item_optional": false, "item_type": "map",
"map_item_spec": [ { "item_default": "", "item_name": "name",
"item_optional": false, "item_type": "string" }, { "item_default": "INFO",
"item_name": "severity", "item_optional": false, "item_type": "string" },
{ "item_default": 0, "item_name": "debuglevel", "item_optional": false,
"item_type": "integer" }, { "item_default": false, "item_name":
"additive", "item_optional": false, "item_type": "boolean" }, {
"item_default": [ ], "item_name": "output_options", "item_optional":
false, "item_type": "list", "list_item_spec": { "item_default": { },
"item_name": "output_option", "item_optional": false, "item_type": "map",
"map_item_spec": [ { "item_default": "console", "item_name":
"destination", "item_optional": false, "item_type": "string" }, {
"item_default": "stdout", "item_name": "output", "item_optional": false,
"item_type": "string" }, { "item_default": false, "item_name": "flush",
"item_optional": false, "item_type": "boolean" }, { "item_default": 0,
"item_name": "maxsize", "item_optional": false, "item_type": "integer" },
{ "item_default": 0, "item_name": "maxver", "item_optional": false,
"item_type": "integer" } ] } } ] } } ], "module_description": "Logging
options", "module_name": "Logging" } ] }')
2011-09-08 09:41:01.725 DEBUG [b10-resolver.cc] CC_GROUP_SEND sending
message '{ "command": [ "get_config", { "module_name": "Logging" } ] }' to
group 'ConfigManager'
2011-09-08 09:41:01.725 DEBUG [b10-resolver.cc] CC_GROUP_RECEIVE trying to
receive a message
2011-09-08 09:41:01.727 DEBUG [b10-resolver.cc] CC_GROUP_RECEIVED message
arrived ('{ "from": "4e68d3fc_2 at new-host-3", "group": "ConfigManager",
"instance": "*", "reply": 3, "seq": 11, "to": "4e68d3fd_4 at new-host-3",
"type": "send" }', '{ "result": [ 0, { "loggers": [ { "debuglevel": 99,
"name": "", "output_options": [ { "flush": true } ] } ] } ] }')
2011-09-08 09:41:01.728 INFO [b10-resolver.resolver] RESOLVER_RECURSIVE
running in recursive mode
2011-09-08 09:41:01.728 WARN [b10-resolver.resolver]
RESOLVER_NO_ROOT_ADDRESS no root addresses available
2011-09-08 09:41:01.728 INFO [b10-resolver.resolver]
RESOLVER_SET_QUERY_ACL query ACL is configured
2011-09-08 09:41:01.728 INFO [b10-resolver.resolver] RESOLVER_STARTED
resolver started
2011-09-08 09:41:01.908 DEBUG [b10-stats-httpd.stats-httpd]
STATHTTPD_STARTING_CC_SESSION starting cc session
2011-09-08 09:41:02.028 INFO [b10-stats-httpd.stats-httpd]
STATHTTPD_STARTED listening on 127.0.0.1#8000
2011-09-08 09:41:02.034 INFO [b10-stats-httpd.stats-httpd]
STATHTTPD_CLOSING closing 127.0.0.1#8000
2011-09-08 09:41:02.036 INFO [b10-stats-httpd.stats-httpd]
STATHTTPD_STARTED listening on 127.0.0.1#8000
2011-09-08 09:41:08.850 ERROR [b10-resolver.asiolink] ASIODNS_SEND_DATA
error 65 sending data using UDP to 2001:500:71::30(53)
2011-09-08 09:41:10.853 ERROR [b10-resolver.asiolink] ASIODNS_SEND_DATA
error 65 sending data using UDP to 2001:500:3::42(53)
2011-09-08 09:41:10.853 ERROR [b10-resolver.asiolink] ASIODNS_SEND_DATA
error 65 sending data using UDP to 2001:500:3::42(53)
2011-09-08 09:41:10.853 ERROR [b10-resolver.asiolink] ASIODNS_SEND_DATA
error 65 sending data using UDP to 2001:500:71::30(53)
2011-09-08 09:41:12.793 ERROR [b10-resolver.asiolink] ASIODNS_SEND_DATA
error 65 sending data using UDP to 2001:4f8:0:2::19(53)
2011-09-08 09:41:12.958 ERROR [b10-resolver.asiolink] ASIODNS_SEND_DATA
error 65 sending data using UDP to 2001:500:6::79(53)
2011-09-08 09:41:12.961 ERROR [b10-resolver.asiolink] ASIODNS_SEND_DATA
error 65 sending data using UDP to 2001:500:a::79(53)
2011-09-08 09:41:14.864 ERROR [b10-resolver.nsas] NSAS_INVALID_RESPONSE
queried for ns.isc.afilias-nst.info. but got invalid response
2011-09-08 09:41:14.864 ERROR [b10-resolver.nsas] NSAS_INVALID_RESPONSE
queried for ns.isc.afilias-nst.info. but got invalid response
}}}
(By the way, I thought at debuglevel 99 it would show my query also.)
--
Ticket URL: <http://bind10.isc.org/ticket/1222>
BIND 10 Development <http://bind10.isc.org>
BIND 10 Development
More information about the bind10-tickets
mailing list