[master] Merge branch 'trac1280'

src/bin/xfrin/tests/xfrin_test.py

@@ -1318,6 +1318,14 @@ class TestAXFR(TestXfrinConnection):
         self.assertEqual(self.conn.do_xfrin(False), XFRIN_OK)
         self.assertFalse(self.conn._datasrc_client._journaling_enabled)
 
+        self.assertEqual(2, self.conn._transfer_stats.message_count)
+        self.assertEqual(2, self.conn._transfer_stats.axfr_rr_count)
+        self.assertEqual(0, self.conn._transfer_stats.ixfr_changeset_count)
+        self.assertEqual(0, self.conn._transfer_stats.ixfr_deletion_count)
+        self.assertEqual(0, self.conn._transfer_stats.ixfr_addition_count)
+        self.assertEqual(177, self.conn._transfer_stats.byte_count)
+        self.assertGreater(self.conn._transfer_stats.get_running_time(), 0)
+
     def test_do_xfrin_with_tsig(self):
         # use TSIG with a mock context.  we fake all verify results to
         # emulate successful verification.
@@ -1687,6 +1695,14 @@ class TestIXFRSession(TestXfrinConnection):
         self.assertEqual(TEST_ZONE_NAME, qmsg.get_question()[0].get_name())
         self.assertEqual(RRType.IXFR(), qmsg.get_question()[0].get_type())
 
+        self.assertEqual(1, self.conn._transfer_stats.message_count)
+        self.assertEqual(0, self.conn._transfer_stats.axfr_rr_count)
+        self.assertEqual(1, self.conn._transfer_stats.ixfr_changeset_count)
+        self.assertEqual(1, self.conn._transfer_stats.ixfr_deletion_count)
+        self.assertEqual(1, self.conn._transfer_stats.ixfr_addition_count)
+        self.assertEqual(188, self.conn._transfer_stats.byte_count)
+        self.assertGreater(self.conn._transfer_stats.get_running_time(), 0)
+
     def test_do_xfrin_fail(self):
         '''IXFR fails due to a protocol error.
 
@@ -1719,6 +1735,14 @@ class TestIXFRSession(TestXfrinConnection):
         self.conn.response_generator = create_response
         self.assertEqual(XFRIN_OK, self.conn.do_xfrin(False, RRType.IXFR()))
 
+        self.assertEqual(1, self.conn._transfer_stats.message_count)
+        self.assertEqual(0, self.conn._transfer_stats.axfr_rr_count)
+        self.assertEqual(0, self.conn._transfer_stats.ixfr_changeset_count)
+        self.assertEqual(0, self.conn._transfer_stats.ixfr_deletion_count)
+        self.assertEqual(0, self.conn._transfer_stats.ixfr_addition_count)
+        self.assertEqual(80, self.conn._transfer_stats.byte_count)
+        self.assertGreater(self.conn._transfer_stats.get_running_time(), 0)
+
 class TestXFRSessionWithSQLite3(TestXfrinConnection):
     '''Tests for XFR sessions using an SQLite3 DB.
 
@@ -2715,6 +2739,63 @@ class TestFormatting(unittest.TestCase):
         self.assertRaises(TypeError, format_addrinfo,
                                      (socket.AF_INET, "asdf", ()))
 
+class TestXfrinTransferStats(unittest.TestCase):
+    def setUp(self):
+        self.stats = XfrinTransferStats()
+
+    def zero_check(self):
+        # Checks whether all counters are zero
+        self.assertEqual(0, self.stats.message_count)
+        self.assertEqual(0, self.stats.axfr_rr_count)
+        self.assertEqual(0, self.stats.byte_count)
+        self.assertEqual(0, self.stats.ixfr_changeset_count)
+        self.assertEqual(0, self.stats.ixfr_deletion_count)
+        self.assertEqual(0, self.stats.ixfr_addition_count)
+
+    def test_init(self):
+        self.zero_check()
+        self.assertIsNone(self.stats._end_time)
+
+    def test_get_running_time(self):
+        self.assertIsNone(self.stats._end_time)
+        runtime = self.stats.get_running_time()
+        self.assertIsNotNone(self.stats._end_time)
+        self.assertGreater(runtime, 0)
+        # make sure a second get does not change anything
+        runtime2 = self.stats.get_running_time()
+        self.assertEqual(runtime, runtime2)
+        # And that no counters have been modified
+        self.zero_check()
+
+    def test_bytes_per_second(self):
+        zbps = self.stats.get_bytes_per_second()
+        self.assertEqual(0, zbps)
+
+        self.stats._start_time = 1
+        self.stats._end_time = 2
+        self.stats.byte_count += 4
+        zbps = self.stats.get_bytes_per_second()
+        self.assertEqual(4, zbps)
+
+        self.stats._start_time = float(1)
+        self.stats._end_time = float(11)
+        self.assertEqual(10, self.stats.get_running_time())
+        self.stats.byte_count = 1234
+        zbps = self.stats.get_bytes_per_second()
+        self.assertEqual(123.4, zbps)
+
+        # if for some reason the runtime is 0, depending
+        # on whether bytes have actually been seen, bps is either
+        # 0 or 'infinite'
+        self.stats._end_time = self.stats._start_time
+        zbps = self.stats.get_bytes_per_second()
+        self.assertEqual(float("inf"), zbps)
+
+        self.stats.byte_count = 0
+        zbps = self.stats.get_bytes_per_second()
+        self.assertEqual(0, zbps)
+
+
 if __name__== "__main__":
     try:
         isc.log.resetUnitTestRootLogger()

src/bin/xfrin/xfrin.py.in

@@ -24,6 +24,7 @@ import struct
 import threading
 import socket
 import random
+import time
 from functools import reduce
 from optparse import OptionParser, OptionValueError
 from isc.config.ccsession import *
@@ -381,6 +382,7 @@ class XfrinIXFRDeleteSOA(XfrinState):
         conn._diff = Diff(conn._datasrc_client, conn._zone_name, False, True)
         conn._diff.delete_data(rr)
         self.set_xfrstate(conn, XfrinIXFRDelete())
+        conn.get_transfer_stats().ixfr_deletion_count += 1
         return True
 
 class XfrinIXFRDelete(XfrinState):
@@ -391,6 +393,7 @@ class XfrinIXFRDelete(XfrinState):
             self.set_xfrstate(conn, XfrinIXFRAddSOA())
             return False
         conn._diff.delete_data(rr)
+        conn.get_transfer_stats().ixfr_deletion_count += 1
         return True
 
 class XfrinIXFRAddSOA(XfrinState):
@@ -402,11 +405,14 @@ class XfrinIXFRAddSOA(XfrinState):
                                  ' RR is given in IXFRAddSOA state')
         conn._diff.add_data(rr)
         self.set_xfrstate(conn, XfrinIXFRAdd())
+        conn.get_transfer_stats().ixfr_addition_count += 1
         return True
 
 class XfrinIXFRAdd(XfrinState):
     def handle_rr(self, conn, rr):
         if rr.get_type() == RRType.SOA():
+            # This SOA marks the end of a difference sequence
+            conn.get_transfer_stats().ixfr_changeset_count += 1
             soa_serial = get_soa_serial(rr.get_rdata()[0])
             if soa_serial == conn._end_serial:
                 conn._diff.commit()
@@ -422,6 +428,7 @@ class XfrinIXFRAdd(XfrinState):
                 self.set_xfrstate(conn, XfrinIXFRDeleteSOA())
                 return False
         conn._diff.add_data(rr)
+        conn.get_transfer_stats().ixfr_addition_count += 1
         return True
 
 class XfrinIXFREnd(XfrinState):
@@ -462,6 +469,7 @@ class XfrinAXFR(XfrinState):
                             conn._end_serial, soa_serial)
 
             self.set_xfrstate(conn, XfrinAXFREnd())
+        conn.get_transfer_stats().axfr_rr_count += 1
         # Yes, we've eaten this RR.
         return True
 
@@ -484,6 +492,55 @@ class XfrinAXFREnd(XfrinState):
         conn._diff.commit()
         return False
 
+class XfrinTransferStats:
+    """
+    This class keeps a record of transfer data for logging purposes.
+    It records number of messages, rrs, and bytes transfered, as well
+    as the start and end time. The start time is set upon instantiation of
+    this class. The end time is set the first time finalize(),
+    get_running_time(), or get_bytes_per_second() is called. The end time is
+    set only once; subsequent calls to any of these methods does not modify
+    it further.
+    All _count instance variables can be directly set as needed by the
+    class collecting these results.
+    """
+    def __init__(self):
+        self.message_count = 0
+        self.axfr_rr_count = 0
+        self.byte_count = 0
+        self.ixfr_changeset_count = 0;
+        self.ixfr_deletion_count = 0;
+        self.ixfr_addition_count = 0;
+        self._start_time = time.time()
+        self._end_time = None
+
+    def finalize(self):
+        """Sets the end time to time.time() if not done already."""
+        if self._end_time is None:
+            self._end_time = time.time()
+
+    def get_running_time(self):
+        """Calls finalize(), then returns the difference between creation
+           and finalization time"""
+        self.finalize()
+        return self._end_time - self._start_time
+
+    def get_bytes_per_second(self):
+        """Returns the number of bytes per second, based on the result of
+           get_running_time() and the value of bytes_count."""
+        runtime = self.get_running_time()
+        if runtime > 0.0:
+            return float(self.byte_count) / runtime
+        else:
+            # This should never happen, but if some clock is so
+            # off or reset in the meantime, we do need to return
+            # *something* (and not raise an error)
+            if self.byte_count == 0:
+                return 0.0
+            else:
+                return float("inf")
+
+
 class XfrinConnection(asyncore.dispatcher):
     '''Do xfrin in this class. '''
 
@@ -534,6 +591,10 @@ class XfrinConnection(asyncore.dispatcher):
         # easier tests (in normal case we always use the default)
         self._tsig_ctx_creator = lambda key : TSIGContext(key)
 
+        # keep a record of this specific transfer to log on success
+        # (time, rr/s, etc)
+        self._transfer_stats = XfrinTransferStats()
+
     def init_socket(self):
         '''Initialize the underlyig socket.
 
@@ -599,6 +660,11 @@ class XfrinConnection(asyncore.dispatcher):
     def get_xfrstate(self):
         return self.__state
 
+    def get_transfer_stats(self):
+        """Returns the transfer stats object, used to measure transfer time,
+           and number of messages/records/bytes transfered."""
+        return self._transfer_stats
+
     def zone_str(self):
         '''A convenience function for logging to include zone name and class'''
         return format_zone_str(self._zone_name, self._rrclass)
@@ -823,7 +889,29 @@ class XfrinConnection(asyncore.dispatcher):
             self._send_query(self._request_type)
             self.__state = XfrinInitialSOA()
             self._handle_xfrin_responses()
-            logger.info(XFRIN_XFR_TRANSFER_SUCCESS, req_str, self.zone_str())
+            # Depending what data was found, we log different status reports
+            # (In case of an AXFR-style IXFR, print the 'AXFR' message)
+            if self._transfer_stats.axfr_rr_count == 0:
+                logger.info(XFRIN_IXFR_TRANSFER_SUCCESS,
+                            self.zone_str(),
+                            self._transfer_stats.message_count,
+                            self._transfer_stats.ixfr_changeset_count,
+                            self._transfer_stats.ixfr_deletion_count,
+                            self._transfer_stats.ixfr_addition_count,
+                            self._transfer_stats.byte_count,
+                            "%.3f" % self._transfer_stats.get_running_time(),
+                            "%.f" % self._transfer_stats.get_bytes_per_second()
+                           )
+            else:
+                logger.info(XFRIN_TRANSFER_SUCCESS,
+                            req_str,
+                            self.zone_str(),
+                            self._transfer_stats.message_count,
+                            self._transfer_stats.axfr_rr_count,
+                            self._transfer_stats.byte_count,
+                            "%.3f" % self._transfer_stats.get_running_time(),
+                            "%.f" % self._transfer_stats.get_bytes_per_second()
+                           )
 
         except XfrinZoneUptodate:
             # Eventually we'll probably have to treat this case as a trigger
@@ -895,9 +983,11 @@ class XfrinConnection(asyncore.dispatcher):
         while read_next_msg:
             data_len = self._get_request_response(2)
             msg_len = socket.htons(struct.unpack('H', data_len)[0])
+            self._transfer_stats.byte_count += msg_len + 2
             recvdata = self._get_request_response(msg_len)
             msg = Message(Message.PARSE)
             msg.from_wire(recvdata, Message.PRESERVE_ORDER)
+            self._transfer_stats.message_count += 1
 
             # TSIG related checks, including an unexpected signed response
             self._check_response_tsig(msg, recvdata)

src/bin/xfrin/xfrin_messages.mes

@@ -15,92 +15,21 @@
 # No namespace declaration - these constants go in the global namespace
 # of the xfrin messages python module.
 
-% XFRIN_ZONE_CREATED Zone %1 not found in the given data source, newly created
-On starting an xfrin session, it is identified that the zone to be
-transferred is not found in the data source.  This can happen if a
-secondary DNS server first tries to perform AXFR from a primary server
-without creating the zone image beforehand (e.g. by b10-loadzone).  As
-of this writing the xfrin process provides backward compatible
-behavior to previous versions: creating a new one in the data source
-not to surprise existing users too much.  This is probably not a good
-idea, however, in terms of who should be responsible for managing
-zones at a higher level.  In future it is more likely that a separate
-zone management framework is provided, and the situation where the
-given zone isn't found in xfrout will be treated as an error.
-
-% XFRIN_ZONE_NO_SOA Zone %1 does not have SOA
-On starting an xfrin session, it is identified that the zone to be
-transferred does not have an SOA RR in the data source.  This is not
-necessarily an error; if a secondary DNS server first tries to perform
-transfer from a primary server, the zone can be empty, and therefore
-doesn't have an SOA.  Subsequent AXFR will fill in the zone; if the
-attempt is IXFR it will fail in query creation.
-
-% XFRIN_ZONE_MULTIPLE_SOA Zone %1 has %2 SOA RRs
-On starting an xfrin session, it is identified that the zone to be
-transferred has multiple SOA RRs.  Such a zone is broken, but could be
-accidentally configured especially in a data source using "non
-captive" backend database.  The implementation ignores entire SOA RRs
-and tries to continue processing as if the zone were empty.  This
-means subsequent AXFR can succeed and possibly replace the zone with
-valid content, but an IXFR attempt will fail.
-
-% XFRIN_ZONE_SERIAL_AHEAD Serial number (%1) for %2 received from master %3 < ours (%4)
-The response to an SOA query prior to xfr indicated that the zone's
-SOA serial at the primary server is smaller than that of the xfrin
-client.  This is not necessarily an error especially if that
-particular primary server is another secondary server which hasn't got
-the latest version of the zone.  But if the primary server is known to
-be the real source of the zone, some unexpected inconsistency may have
-happened, and you may want to take a closer look.  In this case xfrin
-doesn't perform subsequent zone transfer.
-
-% XFRIN_XFR_OTHER_FAILURE %1 transfer of zone %2 failed: %3
-The XFR transfer for the given zone has failed due to a problem outside
-of the xfrin module.  Possible reasons are a broken DNS message or failure
-in database connection.  The error is shown in the log message.
-
-% XFRIN_XFR_TRANSFER_PROTOCOL_ERROR %1 transfer of zone %2 with %3 failed: %4
-The XFR transfer for the given zone has failed due to a protocol
-error, such as an unexpected response from the primary server.  The
-error is shown in the log message.  It may be because the primary
-server implementation is broken or (although less likely) there was
-some attack attempt, but it can also happen due to configuration
-mismatch such as the remote server does not have authority for the
-zone any more but the local configuration hasn't been updated.  So it
-is recommended to check the primary server configuration.
-
-% XFRIN_XFR_TRANSFER_FAILURE %1 transfer of zone %2 with %3 failed: %4
-The XFR transfer for the given zone has failed due to an internal error.
-The error is shown in the log message.
-
-% XFRIN_XFR_TRANSFER_FALLBACK falling back from IXFR to AXFR for %1
-The IXFR transfer of the given zone failed. This might happen in many cases,
-such that the remote server doesn't support IXFR, we don't have the SOA record
-(or the zone at all), we are out of sync, etc. In many of these situations,
-AXFR could still work. Therefore we try that one in case it helps.
-
-% XFRIN_XFR_PROCESS_FAILURE %1 transfer of zone %2/%3 failed: %4
-An XFR session failed outside the main protocol handling.  This
-includes an error at the data source level at the initialization
-phase, unexpected failure in the network connection setup to the
-master server, or even more unexpected failure due to unlikely events
-such as memory allocation failure.  Details of the error are shown in
-the log message.  In general, these errors are not really expected
-ones, and indicate an installation error or a program bug.  The
-session handler thread tries to clean up all intermediate resources
-even on these errors, but it may be incomplete.  So, if this log
-message continuously appears, system resource consumption should be
-checked, and you may even want to disable the corresponding transfers.
-You may also want to file a bug report if this message appears so
-often.
-
-% XFRIN_XFR_TRANSFER_STARTED %1 transfer of zone %2 started
-A connection to the master server has been made, the serial value in
-the SOA record has been checked, and a zone transfer has been started.
-
-% XFRIN_XFR_TRANSFER_SUCCESS %1 transfer of zone %2 succeeded
-The XFR transfer of the given zone was successfully completed.
+% XFRIN_AXFR_INCONSISTENT_SOA AXFR SOAs are inconsistent for %1: %2 expected, %3 received
+The serial fields of the first and last SOAs of AXFR (including AXFR-style
+IXFR) are not the same.  According to RFC 5936 these two SOAs must be the
+"same" (not only for the serial), but it is still not clear what the
+receiver should do if this condition does not hold.  There was a discussion
+about this at the IETF dnsext wg:
+http://www.ietf.org/mail-archive/web/dnsext/current/msg07908.html
+and the general feeling seems that it would be better to reject the
+transfer if a mismatch is detected.  On the other hand, also as noted
+in that email thread, neither BIND 9 nor NSD performs any comparison
+on the SOAs.  For now, we only check the serials (ignoring other fields)
+and only leave a warning log message when a mismatch is found.  If it
+turns out to happen with a real world primary server implementation
+and that server actually feeds broken data (e.g. mixed versions of
+zone), we can consider a stricter action.
 
 % XFRIN_BAD_MASTER_ADDR_FORMAT bad format for master address: %1
 The given master address is not a valid IP address.
@@ -127,6 +56,58 @@ error is given in the log message.
 There was an error opening a connection to the master. The error is
 shown in the log message.
 
+% XFRIN_GOT_INCREMENTAL_RESP got incremental response for %1
+In an attempt of IXFR processing, the begenning SOA of the first difference
+(following the initial SOA that specified the final SOA for all the
+differences) was found.  This means a connection for xfrin tried IXFR
+and really aot a response for incremental updates.
+
+% XFRIN_GOT_NONINCREMENTAL_RESP got nonincremental response for %1
+Non incremental transfer was detected at the "first data" of a transfer,
+which is the RR following the initial SOA.  Non incremental transfer is
+either AXFR or AXFR-style IXFR.  In the latter case, it means that
+in a response to IXFR query the first data is not SOA or its SOA serial
+is not equal to the requested SOA serial.
+
+% XFRIN_IMPORT_DNS error importing python DNS module: %1
+There was an error importing the python DNS module pydnspp. The most
+likely cause is a PYTHONPATH problem.
+
+% XFRIN_IXFR_TRANSFER_SUCCESS incremental IXFR transfer of zone %1 succeeded (messages: %2, changesets: %3, deletions: %4, additions: %5, bytes: %6, run time: %7 seconds, %8 bytes/second)
+The IXFR transfer for the given zone was successful.
+The provided information contains the following values:
+
+messages: Number of overhead DNS messages in the transfer.
+
+changesets: Number of difference sequences.
+
+deletions: Number of Resource Records deleted by all the changesets combined,
+including the SOA records.
+
+additions: Number of Resource Records added by all the changesets combined,
+including the SOA records.
+
+bytes: Full size of the transfer data on the wire.
+
+run time: Time (in seconds) the complete ixfr took.
+
+bytes/second: Transfer speed.
+
+Note that there is no cross-checking of additions and deletions; if the same
+RR gets added and deleted in multiple changesets, it is counted each time;
+therefore, for each changeset, there should at least be 1 deletion and 1
+addition (the updated SOA record).
+
+% XFRIN_IXFR_UPTODATE IXFR requested serial for %1 is %2, master has %3, not updating
+The first SOA record in an IXFR response indicates the zone's serial
+at the primary server is not newer than the client's.  This is
+basically unexpected event because normally the client first checks
+the SOA serial by an SOA query, but can still happen if the transfer
+is manually invoked or (although unlikely) there is a rapid change at
+the primary server between the SOA and IXFR queries.  The client
+implementation confirms the whole response is this single SOA, and
+aborts the transfer just like a successful case.
+
 % XFRIN_MSGQ_SEND_ERROR error while contacting %1 and %2
 There was a problem sending a message to the xfrout module or the
 zone manager. This most likely means that the msgq daemon has quit or
@@ -142,10 +123,6 @@ from does not match the master address in the Xfrin configuration. The notify
 is ignored. This may indicate that the configuration for the master is wrong,
 that a wrong machine is sending notifies, or that fake notifies are being sent.
 
-% XFRIN_IMPORT_DNS error importing python DNS module: %1
-There was an error importing the python DNS module pydnspp. The most
-likely cause is a PYTHONPATH problem.
-
 % XFRIN_RETRANSFER_UNKNOWN_ZONE got notification to retransfer unknown zone %1
 There was an internal command to retransfer the given zone, but the
 zone is not known to the system. This may indicate that the configuration
@@ -159,45 +136,105 @@ An informational message, this is output when the resolver starts up.
 There was a keyboard interrupt signal to stop the xfrin daemon. The
 daemon will now shut down.
 
+% XFRIN_TRANSFER_SUCCESS full %1 transfer of zone %2 succeeded (messages: %3, records: %4, bytes: %5, run time: %6 seconds, %7 bytes/second)
+The AXFR transfer of the given zone was successful.
+The provided information contains the following values:
+
+messages: Number of overhead DNS messages in the transfer
+
+records: Number of Resource Records in the full transfer, excluding the
+final SOA record that marks the end of the AXFR.
+
+bytes: Full size of the transfer data on the wire.
+
+run time: Time (in seconds) the complete axfr took
+
+bytes/second: Transfer speed
+
 % XFRIN_UNKNOWN_ERROR unknown error: %1
 An uncaught exception was raised while running the xfrin daemon. The
 exception message is printed in the log message.
 
-% XFRIN_IXFR_UPTODATE IXFR requested serial for %1 is %2, master has %3, not updating
-The first SOA record in an IXFR response indicates the zone's serial
-at the primary server is not newer than the client's.  This is
-basically unexpected event because normally the client first checks
-the SOA serial by an SOA query, but can still happen if the transfer
-is manually invoked or (although unlikely) there is a rapid change at
-the primary server between the SOA and IXFR queries.  The client
-implementation confirms the whole response is this single SOA, and
-aborts the transfer just like a successful case.
+% XFRIN_XFR_OTHER_FAILURE %1 transfer of zone %2 failed: %3
+The XFR transfer for the given zone has failed due to a problem outside
+of the xfrin module.  Possible reasons are a broken DNS message or failure
+in database connection.  The error is shown in the log message.
 
-% XFRIN_GOT_INCREMENTAL_RESP got incremental response for %1
-In an attempt of IXFR processing, the begenning SOA of the first difference
-(following the initial SOA that specified the final SOA for all the
-differences) was found.  This means a connection for xfrin tried IXFR
-and really aot a response for incremental updates.
+% XFRIN_XFR_PROCESS_FAILURE %1 transfer of zone %2/%3 failed: %4
+An XFR session failed outside the main protocol handling.  This
+includes an error at the data source level at the initialization
+phase, unexpected failure in the network connection setup to the
+master server, or even more unexpected failure due to unlikely events
+such as memory allocation failure.  Details of the error are shown in
+the log message.  In general, these errors are not really expected
+ones, and indicate an installation error or a program bug.  The
+session handler thread tries to clean up all intermediate resources
+even on these errors, but it may be incomplete.  So, if this log
+message continuously appears, system resource consumption should be
+checked, and you may even want to disable the corresponding transfers.
+You may also want to file a bug report if this message appears so
+often.
 
-% XFRIN_GOT_NONINCREMENTAL_RESP got nonincremental response for %1
-Non incremental transfer was detected at the "first data" of a transfer,
-which is the RR following the initial SOA.  Non incremental transfer is
-either AXFR or AXFR-style IXFR.  In the latter case, it means that
-in a response to IXFR query the first data is not SOA or its SOA serial
-is not equal to the requested SOA serial.
+% XFRIN_XFR_TRANSFER_FAILURE %1 transfer of zone %2 with %3 failed: %4
+The XFR transfer for the given zone has failed due to an internal error.
+The error is shown in the log message.
 
-% XFRIN_AXFR_INCONSISTENT_SOA AXFR SOAs are inconsistent for %1: %2 expected, %3 received
-The serial fields of the first and last SOAs of AXFR (including AXFR-style
-IXFR) are not the same.  According to RFC 5936 these two SOAs must be the
-"same" (not only for the serial), but it is still not clear what the
-receiver should do if this condition does not hold.  There was a discussion
-about this at the IETF dnsext wg:
-http://www.ietf.org/mail-archive/web/dnsext/current/msg07908.html
-and the general feeling seems that it would be better to reject the
-transfer if a mismatch is detected.  On the other hand, also as noted
-in that email thread, neither BIND 9 nor NSD performs any comparison
-on the SOAs.  For now, we only check the serials (ignoring other fields)
-and only leave a warning log message when a mismatch is found.  If it
-turns out to happen with a real world primary server implementation
-and that server actually feeds broken data (e.g. mixed versions of
-zone), we can consider a stricter action.
+% XFRIN_XFR_TRANSFER_FALLBACK falling back from IXFR to AXFR for %1
+The IXFR transfer of the given zone failed. This might happen in many cases,
+such that the remote server doesn't support IXFR, we don't have the SOA record
+(or the zone at all), we are out of sync, etc. In many of these situations,
+AXFR could still work. Therefore we try that one in case it helps.
+
+% XFRIN_XFR_TRANSFER_PROTOCOL_ERROR %1 transfer of zone %2 with %3 failed: %4
+The XFR transfer for the given zone has failed due to a protocol
+error, such as an unexpected response from the primary server.  The
+error is shown in the log message.  It may be because the primary
+server implementation is broken or (although less likely) there was
+some attack attempt, but it can also happen due to configuration
+mismatch such as the remote server does not have authority for the
+zone any more but the local configuration hasn't been updated.  So it
+is recommended to check the primary server configuration.
+
+% XFRIN_XFR_TRANSFER_STARTED %1 transfer of zone %2 started
+A connection to the master server has been made, the serial value in
+the SOA record has been checked, and a zone transfer has been started.
+
+% XFRIN_ZONE_CREATED Zone %1 not found in the given data source, newly created
+On starting an xfrin session, it is identified that the zone to be
+transferred is not found in the data source.  This can happen if a
+secondary DNS server first tries to perform AXFR from a primary server
+without creating the zone image beforehand (e.g. by b10-loadzone).  As
+of this writing the xfrin process provides backward compatible
+behavior to previous versions: creating a new one in the data source
+not to surprise existing users too much.  This is probably not a good
+idea, however, in terms of who should be responsible for managing
+zones at a higher level.  In future it is more likely that a separate
+zone management framework is provided, and the situation where the
+given zone isn't found in xfrout will be treated as an error.
+
+% XFRIN_ZONE_MULTIPLE_SOA Zone %1 has %2 SOA RRs
+On starting an xfrin session, it is identified that the zone to be
+transferred has multiple SOA RRs.  Such a zone is broken, but could be
+accidentally configured especially in a data source using "non
+captive" backend database.  The implementation ignores entire SOA RRs
+and tries to continue processing as if the zone were empty.  This
+means subsequent AXFR can succeed and possibly replace the zone with
+valid content, but an IXFR attempt will fail.
+
+% XFRIN_ZONE_NO_SOA Zone %1 does not have SOA
+On starting an xfrin session, it is identified that the zone to be
+transferred does not have an SOA RR in the data source.  This is not
+necessarily an error; if a secondary DNS server first tries to perform
+transfer from a primary server, the zone can be empty, and therefore
+doesn't have an SOA.  Subsequent AXFR will fill in the zone; if the
+attempt is IXFR it will fail in query creation.
+
+% XFRIN_ZONE_SERIAL_AHEAD Serial number (%1) for %2 received from master %3 < ours (%4)
+The response to an SOA query prior to xfr indicated that the zone's
+SOA serial at the primary server is smaller than that of the xfrin
+client.  This is not necessarily an error especially if that
+particular primary server is another secondary server which hasn't got
+the latest version of the zone.  But if the primary server is known to
+be the real source of the zone, some unexpected inconsistency may have
+happened, and you may want to take a closer look.  In this case xfrin
+doesn't perform subsequent zone transfer.

tests/lettuce/features/xfrin_bind10.feature

@@ -7,5 +7,5 @@ Feature: Xfrin
     A query for www.example.org should have rcode REFUSED
     Wait for bind10 stderr message CMDCTL_STARTED
     When I send bind10 the command Xfrin retransfer example.org IN 127.0.0.1 47807
-    Then wait for new bind10 stderr message XFRIN_XFR_TRANSFER_SUCCESS not XFRIN_XFR_PROCESS_FAILURE
+    Then wait for new bind10 stderr message XFRIN_TRANSFER_SUCCESS not XFRIN_XFR_PROCESS_FAILURE
     A query for www.example.org should have rcode NOERROR

tests/system/ixfr/in-2/tests.sh

@@ -54,7 +54,7 @@ then
     exit 1
 fi
 
-grep XFRIN_XFR_TRANSFER_SUCCESS nsx2/bind10.run | grep IXFR > /dev/null
+grep XFRIN_IXFR_TRANSFER_SUCCESS nsx2/bind10.run | grep IXFR > /dev/null
 if [ $? -ne 0 ];
 then
     echo "R:$CLIENT_NAME FAIL no 'IXFR successful' message in the BIND 10 log"