Opened 8 years ago

Closed 5 years ago

#1222 closed defect (wontfix)

resolver problems with IPv6

Reported by: jreed Owned by:
Priority: high Milestone: DNS Outstanding Tasks
Component: resolver Version:
Keywords: Cc:
CVSS Scoring: Parent Tickets:
Sensitive: no Defect Severity: Very High
Sub-Project: DNS Feature Depending on Ticket:
Estimated Difficulty: 0 Add Hours to Ticket: 0
Total Hours: 0 Internal?: no

Description

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@new-host-3", "group": "ConfigManager", "instance": "*", "reply": 0, "seq": 8, "to": "4e68d3fd_4@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@new-host-3", "group": "ConfigManager", "instance": "*", "reply": 1, "seq": 9, "to": "4e68d3fd_4@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@new-host-3", "group": "ConfigManager", "instance": "*", "reply": 2, "seq": 10, "to": "4e68d3fd_4@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@new-host-3", "group": "ConfigManager", "instance": "*", "reply": 3, "seq": 11, "to": "4e68d3fd_4@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.)

Subtickets

Change History (4)

comment:2 Changed 8 years ago by shane

  • Milestone changed from New Tasks to Year 3 Task Backlog

comment:3 Changed 6 years ago by stephen

  • Milestone set to DNS Outstanding Tasks

comment:4 Changed 5 years ago by tomek

  • Resolution set to wontfix
  • Status changed from new to closed

DNS and BIND10 framework is outside of scope for Kea project.
The corresponding code has been removed from Kea git repository.
If you want to follow up on DNS or former BIND10 issues, see
http://bundy-dns.de project.

Closing ticket.

Note: See TracTickets for help on using tickets.