bind10-devel-20120119 outgoing zone transfer failure

Wed Feb 22 16:33:16 UTC 2012

I have a bind10-devel-20120119 server (host name nsb0, IPv6 address 2001:4870:20ca:158:14ff:7695:9632:e9ec) set up as a hidden master using a bind 9.9.0rc3 server (host name nsb0s, IPv6 address 2001:4870:20ca:158:383e:4365:e3fe:ef7e) as a slave for purposes of DNSSEC inline signing. The nsb0 log and Xfrout configuration are shown below. On initial setup, after I loaded the zones on nsb0, they were transferred successfully to nsb0s. Recently I tested a zone update by manually editing the jaspain.biz zone file on nsb0, incrementing its SOA serial number, adding some other records, and reloading it with b10-loadzone. Now I find that nsb0s is unable to transfer the updated zone.

Based on a packet capture with tcpdump, here's what is happening about once an hour as nsb0s continues to attempt to transfer the jaspain.biz zone:
1) nsb0s sends a UDP SOA query for jaspain.biz
2) nsb0 responds normally, including the incremented serial number
3) nsb0s opens a TCP session with nsb0 and sends an IXFR query for jaspain.biz
4) nsb0 responds with SERVFAIL
5) nsb0s closes the TCP session [FIN, ACK]
6) nsb0s opens a second TCP session with nsb0 and sends another SOA query for jaspain.biz
7) nsb0 responds normally, including the incremented serial number
8) nsb0 closes the TCP session [FIN, ACK]
9) nsb0s, using the same TCP session that it thinks is still open, sends an AXFR query for jaspain.biz
10) nsb0 responds with one or two TCP [RST] segments
11) The second TCP session is now dead with no zone transfer having taken place, and the whole process repeats about an hour later.

The problem seems to be at step 8 where nsb0 is closing the TCP session after responding to the SOA query, contrary to the expectations of nsb0s. I don't know for sure whether or not the DNS protocol allows for more than one query/response over a single TCP session, but bind9 seems to be designed that way.

If you think this is a bug in bind10, then hopefully this documents it well enough. On the other hand, if you think that bind9 is misbehaving, please let me know, and I will report this issue on the bind9 users list. Thanks. Jeff.

----------

Following are the related log entries from nsb0 for the latest transfer attempt:
2012-02-22 09:40:19.306 DEBUG [b10-auth.datasrc] DATASRC_QUERY_PROCESS processing query 'jaspain.biz./SOA' in the 'IN' class
2012-02-22 09:40:19.334 DEBUG [b10-xfrout.datasrc] DATASRC_SQLITE_NEWCONN SQLite3Database is being initialized
2012-02-22 09:40:19.334 DEBUG [b10-xfrout.datasrc] DATASRC_SQLITE_CONNOPEN Opening sqlite database file '/var/bind10-devel/zone.sqlite3'
2012-02-22 09:40:19.335 DEBUG [b10-xfrout.datasrc] DATASRC_SQLITE_NEWCONN SQLite3Database is being initialized
2012-02-22 09:40:19.336 DEBUG [b10-xfrout.datasrc] DATASRC_SQLITE_CONNOPEN Opening sqlite database file '/var/bind10-devel/zone.sqlite3'
2012-02-22 09:40:19.337 DEBUG [b10-xfrout.datasrc] DATASRC_SQLITE_DROPCONN SQLite3Database is being deinitialized
2012-02-22 09:40:19.337 DEBUG [b10-xfrout.datasrc] DATASRC_SQLITE_CONNCLOSE Closing sqlite database
2012-02-22 09:40:19.337 ERROR [b10-xfrout.xfrout] XFROUT_XFR_TRANSFER_CHECK_ERROR IXFR client [2001:4870:20ca:158:383e:4365:e3fe:ef7e]:60965: check for transfer of jaspain.biz/IN failed: Could not prepare SQLite statement: SELECT id FROM diffs WHERE zone_id=?1 AND version=?2 and OPERATION=?3 ORDER BY id ASC LIMIT 1: no such table: diffs
2012-02-22 09:40:19.337 INFO  [b10-xfrout.xfrout] XFROUT_XFR_TRANSFER_FAILED IXFR client [2001:4870:20ca:158:383e:4365:e3fe:ef7e]:60965: transfer of jaspain.biz/IN failed, rcode: SERVFAIL
2012-02-22 09:40:19.338 DEBUG [b10-xfrout.datasrc] DATASRC_SQLITE_DROPCONN SQLite3Database is being deinitialized
2012-02-22 09:40:19.338 DEBUG [b10-xfrout.datasrc] DATASRC_SQLITE_CONNCLOSE Closing sqlite database
2012-02-22 09:40:19.339 DEBUG [b10-auth.datasrc] DATASRC_QUERY_PROCESS processing query 'jaspain.biz./SOA' in the 'IN' class

Following is the Xfrout configuration for nsb0:
> config show all Xfrout
Xfrout/transfers_out    10      integer (default)
Xfrout/log_name "Xfrout"        string  (default)
Xfrout/log_file "/var/bind10-devel/log/Xfrout.log"      string  (default)
Xfrout/log_severity     "debug" string  (default)
Xfrout/log_versions     5       integer (default)
Xfrout/log_max_bytes    1048576 integer (default)
Xfrout/tsig_key_ring[0] "nsb0-nsb0s:gWxinWPIF9UpqB2seY+FV/UM/czMFY3q/4oEAkAKnd0=:hmac-sha256"   string
Xfrout/transfer_acl[0]  {"action": "REJECT"}    any
Xfrout/zone_config[0]/origin    "jaspain.biz"   string
Xfrout/zone_config[0]/class     "IN"    string  (default)
Xfrout/zone_config[0]/transfer_acl[0]   {"action": "ACCEPT", "from": "2001:4870:20ca:158:383e:4365:e3fe:ef7e", "key": "nsb0-nsb0s"}any
Xfrout/zone_config[1]/origin    "jaspain.info"  string
Xfrout/zone_config[1]/class     "IN"    string  (default)
Xfrout/zone_config[1]/transfer_acl[0]   {"action": "ACCEPT", "from": "2001:4870:20ca:158:383e:4365:e3fe:ef7e", "key": "nsb0-nsb0s"}any
Xfrout/zone_config[2]/origin    "jaspain.net"   string
Xfrout/zone_config[2]/class     "IN"    string  (default)
Xfrout/zone_config[2]/transfer_acl[0]   {"action": "ACCEPT", "from": "2001:4870:20ca:158:383e:4365:e3fe:ef7e", "key": "nsb0-nsb0s"}any
Xfrout/zone_config[3]/origin    "jaspain.us"    string
Xfrout/zone_config[3]/class     "IN"    string  (default)
Xfrout/zone_config[3]/transfer_acl[0]   {"action": "ACCEPT", "from": "2001:4870:20ca:158:383e:4365:e3fe:ef7e", "key": "nsb0-nsb0s"}any
Xfrout/zone_config[4]/origin    "jspain.us"     string
Xfrout/zone_config[4]/class     "IN"    string  (default)
Xfrout/zone_config[4]/transfer_acl[0]   {"action": "ACCEPT", "from": "2001:4870:20ca:158:383e:4365:e3fe:ef7e", "key": "nsb0-nsb0s"}any

Jeffry A. Spain
Network Administrator
Cincinnati Country Day School