[1280] keep and log [A|I]XFR data

depending on transfer type, different things are logged; in case of AXFR, log the number of RRs in the zone, in case of IXFR, log the number of changesets, and the number of deletions and additions. In both cases, run time, bytes, and bytes per second are logged as well.

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,27 @@ 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 on the transfer type, we log different status reports
+            if request_type == RRType.IXFR():
+                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_AXFR_TRANSFER_SUCCESS,
+                            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 +981,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,37 @@
 # 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_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_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_AXFR_TRANSFER_SUCCESS full transfer of zone %1 succeeded (messages: %2, records: %3, bytes: %4, run time: %5 seconds, %6 bytes/second)
+The AXFR transfer of the given zone was successful.
+The provided information contains the following values:
 
-% 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.
+messages: Number of overhead DNS messages in the transfer
 
-% 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.
+records: Number of Resource Records in the full transfer, excluding the
+final SOA record that marks the end of the AXFR.
 
-% 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.
+bytes: Full size of the transfer data on the wire.
 
-% 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.
+run time: Time (in seconds) the complete axfr took
 
-% 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.
+bytes/second: Transfer speed
 
-% XFRIN_XFR_TRANSFER_SUCCESS %1 transfer of zone %2 succeeded
-The XFR transfer of the given zone was successfully completed.
 
 % XFRIN_BAD_MASTER_ADDR_FORMAT bad format for master address: %1
 The given master address is not a valid IP address.
@@ -127,6 +72,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 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 +139,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
@@ -163,41 +156,86 @@ daemon will now shut down.
 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.