[master] Merge branch 'trac2252'

src/bin/xfrin/b10-xfrin.xml

@@ -213,6 +213,132 @@ operation
 -->
 
   </refsect1>
+  <refsect1>
+    <title>STATISTICS DATA</title>
+
+    <para>
+      The statistics data collected by the <command>b10-xfrin</command>
+      daemon for <quote>Xfrin</quote> include:
+    </para>
+
+    <variablelist>
+
+      <varlistentry>
+        <term>zones</term>
+        <listitem><simpara>
+          A directory name of per-zone statistics
+          </simpara>
+          <variablelist>
+
+            <varlistentry>
+              <term><replaceable>zonename</replaceable></term>
+              <listitem><simpara>
+                An actual zone name or special zone name
+                <quote>_SERVER_</quote> representing the entire server.
+                Zone classes (e.g. IN, CH, and HS) are mixed and counted so
+                far. But these will be distinguished in future release.
+                </simpara>
+                <variablelist>
+
+                  <varlistentry>
+                    <term>soaoutv4</term>
+                    <listitem><simpara>
+                      Number of IPv4 SOA queries sent from Xfrin
+                    </simpara></listitem>
+                  </varlistentry>
+
+                  <varlistentry>
+                    <term>soaoutv6</term>
+                    <listitem><simpara>
+                      Number of IPv6 SOA queries sent from Xfrin
+                    </simpara></listitem>
+                  </varlistentry>
+
+                  <varlistentry>
+                    <term>axfrreqv4</term>
+                    <listitem><simpara>
+                      Number of IPv4 AXFR requests sent from Xfrin
+                    </simpara></listitem>
+                  </varlistentry>
+
+                  <varlistentry>
+                    <term>axfrreqv6</term>
+                    <listitem><simpara>
+                      Number of IPv6 AXFR requests sent from Xfrin
+                    </simpara></listitem>
+                  </varlistentry>
+
+                  <varlistentry>
+                    <term>ixfrreqv4</term>
+                    <listitem><simpara>
+                      Number of IPv4 IXFR requests sent from Xfrin
+                    </simpara></listitem>
+                  </varlistentry>
+
+                  <varlistentry>
+                    <term>ixfrreqv6</term>
+                    <listitem><simpara>
+                      Number of IPv6 IXFR requests sent from Xfrin
+                    </simpara></listitem>
+                  </varlistentry>
+
+                  <varlistentry>
+                    <term>xfrsuccess</term>
+                    <listitem><simpara>
+                      Number of zone transfer requests succeeded.
+                      These include the case where the zone turns
+                      out to be the latest as a result of an
+                      initial SOA query (and there is actually no
+                      AXFR or IXFR transaction).
+                    </simpara></listitem>
+                  </varlistentry>
+
+                  <varlistentry>
+                    <term>xfrfail</term>
+                    <listitem><simpara>
+                      Number of zone transfer requests failed
+                    </simpara></listitem>
+                  </varlistentry>
+
+                  <varlistentry>
+                    <term>last_axfr_duration</term>
+                    <listitem><simpara>
+                      Duration in seconds of the last successful AXFR.  0.0
+                      means no successful AXFR done or means a successful AXFR
+                      done in less than a microsecond.  If an AXFR is aborted
+                      due to some failure, this duration won't be updated.
+                    </simpara></listitem>
+                  </varlistentry>
+
+                  <varlistentry>
+                    <term>last_ixfr_duration</term>
+                    <listitem><simpara>
+                      Duration in seconds of the last successful IXFR.  0.0
+                      means no successful IXFR done or means a successful IXFR
+                      done in less than a microsecond.  If an IXFR is aborted
+                      due to some failure, this duration won't be updated.
+                    </simpara></listitem>
+                  </varlistentry>
+
+                </variablelist>
+              </listitem>
+            </varlistentry><!-- end of zonename -->
+
+          </variablelist>
+        </listitem>
+      </varlistentry><!-- end of zones -->
+
+    </variablelist>
+
+    <para>
+      In per-zone counters the special zone name <quote>_SERVER_</quote>
+      exists.
+      It doesn't mean a specific zone. It represents the entire server
+      and the counter value of this special zone is the total of the
+      same counter for all zones.
+    </para>
+
+  </refsect1>
 
 <!--
   <refsect1>

src/bin/xfrin/tests/xfrin_test.py

@@ -1,4 +1,4 @@
-# Copyright (C) 2009-2011  Internet Systems Consortium.
+# Copyright (C) 2009-2013  Internet Systems Consortium.
 #
 # Permission to use, copy, modify, and distribute this software for any
 # purpose with or without fee is hereby granted, provided that the above
@@ -19,6 +19,7 @@ import shutil
 import socket
 import sys
 import io
+from datetime import datetime
 from isc.testutils.tsigctx_mock import MockTSIGContext
 from isc.testutils.ccsession_mock import MockModuleCCSession
 from isc.testutils.rrset_utils import *
@@ -717,7 +718,7 @@ class TestXfrinConnection(unittest.TestCase):
         self.sock_map = {}
         self.conn = MockXfrinConnection(self.sock_map, TEST_ZONE_NAME,
                                         TEST_RRCLASS, None, threading.Event(),
-                                        TEST_MASTER_IPV4_ADDRINFO)
+                                        self._master_addrinfo)
         self.conn.init_socket()
         self.soa_response_params = {
             'questions': [example_soa_question],
@@ -749,6 +750,10 @@ class TestXfrinConnection(unittest.TestCase):
             os.remove(TEST_DB_FILE)
         xfrin.check_zone = self.__orig_check_zone
 
+    @property
+    def _master_addrinfo(self):
+        return TEST_MASTER_IPV4_ADDRINFO
+
     def __check_zone(self, name, rrclass, rrsets, callbacks):
         '''
         A mock function used instead of dns.check_zone.
@@ -1065,6 +1070,20 @@ class TestAXFR(TestXfrinConnection):
         self.assertRaises(XfrinProtocolError,
                           self.conn._handle_xfrin_responses)
 
+    def test_ipver_str(self):
+        addrs = (((socket.AF_INET, socket.SOCK_STREAM), 'v4'),
+                 ((socket.AF_INET6, socket.SOCK_STREAM), 'v6'),
+                 ((socket.AF_UNIX, socket.SOCK_STREAM), None))
+        for (info, ver) in addrs:
+            c = MockXfrinConnection({}, TEST_ZONE_NAME, RRClass.CH, None,
+                                    threading.Event(), info)
+            c.init_socket()
+            if ver is not None:
+                self.assertEqual(ver, c._get_ipver_str())
+            else:
+                self.assertRaises(ValueError, c._get_ipver_str)
+            c.close()
+
     def test_soacheck(self):
         # we need to defer the creation until we know the QID, which is
         # determined in _check_soa_serial(), so we use response_generator.
@@ -2104,6 +2123,187 @@ class TestXFRSessionWithSQLite3(TestXfrinConnection):
         self.assertFalse(self.record_exist(Name('dns01.example.com'),
                                            RRType.A))
 
+class TestStatisticsXfrinConn(TestXfrinConnection):
+    '''Test class based on TestXfrinConnection and including paramters
+    and methods related to statistics tests'''
+    def setUp(self):
+        super().setUp()
+        # clear all statistics counters before each test
+        self.conn._counters.clear_all()
+        # fake datetime
+        self.__orig_datetime = isc.statistics.counters.datetime
+        self.__orig_start_timer = isc.statistics.counters._start_timer
+        time1 = datetime(2000, 1, 1, 0, 0, 0, 0)
+        time2 = datetime(2000, 1, 1, 0, 0, 0, 1)
+        class FakeDateTime:
+            @classmethod
+            def now(cls): return time2
+        isc.statistics.counters.datetime = FakeDateTime
+        isc.statistics.counters._start_timer = lambda : time1
+        delta = time2 - time1
+        self._const_sec = round(delta.days * 86400 + delta.seconds +
+                                delta.microseconds * 1E-6, 6)
+        # List of statistics counter names and expected initial values
+        self.__name_to_counter = (('axfrreqv4', 0),
+                                 ('axfrreqv6', 0),
+                                 ('ixfrreqv4', 0),
+                                 ('ixfrreqv6', 0),
+                                 ('last_axfr_duration', 0.0),
+                                 ('last_ixfr_duration', 0.0),
+                                 ('soaoutv4', 0),
+                                 ('soaoutv6', 0),
+                                 ('xfrfail', 0),
+                                 ('xfrsuccess', 0))
+        self.__zones = 'zones'
+
+    def tearDown(self):
+        super().tearDown()
+        isc.statistics.counters.datetime = self.__orig_datetime
+        isc.statistics.counters._start_timer = self.__orig_start_timer
+
+    @property
+    def _ipver(self):
+        return 'v4'
+
+    def _check_init_statistics(self):
+        '''checks exception being raised if not incremented statistics
+        counter gotten'''
+        for (name, exp) in self.__name_to_counter:
+            self.assertRaises(isc.cc.data.DataNotFoundError,
+                              self.conn._counters.get, self.__zones,
+                              TEST_ZONE_NAME_STR, name)
+
+    def _check_updated_statistics(self, overwrite):
+        '''checks getting expect values after updating the pairs of
+        statistics counter name and value on to the "overwrite"
+        dictionary'''
+        name2count = dict(self.__name_to_counter)
+        name2count.update(overwrite)
+        for (name, exp) in name2count.items():
+            act = self.conn._counters.get(self.__zones,
+                                          TEST_ZONE_NAME_STR,
+                                          name)
+            msg = '%s is expected %s but actually %s' % (name, exp, act)
+            self.assertEqual(exp, act, msg=msg)
+
+class TestStatisticsXfrinAXFRv4(TestStatisticsXfrinConn):
+    '''Xfrin AXFR tests for IPv4 to check statistics counters'''
+    def test_soaout(self):
+        '''tests that an soaoutv4 or soaoutv6 counter is incremented
+        when an soa query succeeds'''
+        self.conn.response_generator = self._create_soa_response_data
+        self._check_init_statistics()
+        self.assertEqual(self.conn._check_soa_serial(), XFRIN_OK)
+        self._check_updated_statistics({'soaout' + self._ipver: 1})
+
+    def test_axfrreq_xfrsuccess_last_axfr_duration(self):
+        '''tests that axfrreqv4 or axfrreqv6 and xfrsuccess counters
+        and last_axfr_duration timer are incremented when xfr succeeds'''
+        self.conn.response_generator = self._create_normal_response_data
+        self._check_init_statistics()
+        self.assertEqual(self.conn.do_xfrin(False), XFRIN_OK)
+        self._check_updated_statistics({'axfrreq' + self._ipver: 1,
+                                        'xfrsuccess': 1,
+                                        'last_axfr_duration': self._const_sec})
+
+    def test_axfrreq_xfrsuccess_last_axfr_duration2(self):
+        '''tests that axfrreqv4 or axfrreqv6 and xfrsuccess counters
+        and last_axfr_duration timer are incremented when raising
+        XfrinZoneUptodate. The exception is treated as success.'''
+        def exception_raiser():
+            raise XfrinZoneUptodate()
+        self.conn._handle_xfrin_responses = exception_raiser
+        self._check_init_statistics()
+        self.assertEqual(self.conn.do_xfrin(False), XFRIN_OK)
+        self._check_updated_statistics({'axfrreq' + self._ipver: 1,
+                                        'xfrsuccess': 1,
+                                        'last_axfr_duration':
+                                            self._const_sec})
+
+    def test_axfrreq_xfrfail(self):
+        '''tests that axfrreqv4 or axfrreqv6 and xfrfail counters are
+        incremented even if some failure exceptions are expected to be
+        raised inside do_xfrin(): XfrinZoneError, XfrinProtocolError,
+        XfrinException, and Exception'''
+        self._check_init_statistics()
+        count = 0
+        for ex in [XfrinZoneError, XfrinProtocolError, XfrinException,
+                   Exception]:
+            def exception_raiser():
+                raise ex()
+            self.conn._handle_xfrin_responses = exception_raiser
+            self.assertEqual(self.conn.do_xfrin(False), XFRIN_FAIL)
+            count += 1
+            self._check_updated_statistics({'axfrreq' + self._ipver: count,
+                                            'xfrfail': count})
+
+class TestStatisticsXfrinIXFRv4(TestStatisticsXfrinConn):
+    '''Xfrin IXFR tests for IPv4 to check statistics counters'''
+    def test_ixfrreq_xfrsuccess_last_ixfr_duration(self):
+        '''tests that ixfrreqv4 or ixfrreqv6 and xfrsuccess counters
+        and last_ixfr_duration timer are incremented when xfr succeeds'''
+        def create_ixfr_response():
+            self.conn.reply_data = self.conn.create_response_data(
+                questions=[Question(TEST_ZONE_NAME, TEST_RRCLASS,
+                                    RRType.IXFR)],
+                answers=[soa_rrset, begin_soa_rrset, soa_rrset, soa_rrset])
+        self.conn.response_generator = create_ixfr_response
+        self._check_init_statistics()
+        self.assertEqual(XFRIN_OK, self.conn.do_xfrin(False, RRType.IXFR))
+        self._check_updated_statistics({'ixfrreq' + self._ipver: 1,
+                                        'xfrsuccess': 1,
+                                        'last_ixfr_duration':
+                                            self._const_sec})
+
+    def test_ixfrreq_xfrsuccess_last_ixfr_duration2(self):
+        '''tests that ixfrreqv4 or ixfrreqv6 and xfrsuccess counters
+        and last_ixfr_duration timer are incremented when raising
+        XfrinZoneUptodate. The exception is treated as success.'''
+        def exception_raiser():
+            raise XfrinZoneUptodate()
+        self.conn._handle_xfrin_responses = exception_raiser
+        self._check_init_statistics()
+        self.assertEqual(self.conn.do_xfrin(False, RRType.IXFR), XFRIN_OK)
+        self._check_updated_statistics({'ixfrreq' + self._ipver: 1,
+                                        'xfrsuccess': 1,
+                                        'last_ixfr_duration':
+                                            self._const_sec})
+
+    def test_ixfrreq_xfrfail(self):
+        '''tests that ixfrreqv4 or ixfrreqv6 and xfrfail counters are
+        incremented even if some failure exceptions are expected to be
+        raised inside do_xfrin(): XfrinZoneError, XfrinProtocolError,
+        XfrinException, and Exception'''
+        self._check_init_statistics()
+        count = 0
+        for ex in [XfrinZoneError, XfrinProtocolError, XfrinException,
+                   Exception]:
+            def exception_raiser():
+                raise ex()
+            self.conn._handle_xfrin_responses = exception_raiser
+            self.assertEqual(self.conn.do_xfrin(False, RRType.IXFR), XFRIN_FAIL)
+            count += 1
+            self._check_updated_statistics({'ixfrreq' + self._ipver: count,
+                                            'xfrfail': count})
+
+class TestStatisticsXfrinAXFRv6(TestStatisticsXfrinAXFRv4):
+    '''Same tests as TestStatisticsXfrinAXFRv4 for IPv6'''
+    @property
+    def _master_addrinfo(self):
+        return TEST_MASTER_IPV6_ADDRINFO
+    @property
+    def _ipver(self):
+        return 'v6'
+
+class TestStatisticsIXFRv6(TestStatisticsXfrinIXFRv4):
+    '''Same tests as TestStatisticsXfrinIXFRv4 for IPv6'''
+    @property
+    def _master_addrinfo(self):
+        return TEST_MASTER_IPV6_ADDRINFO
+    @property
+    def _ipver(self):
+        return 'v6'
+
 class TestXfrinRecorder(unittest.TestCase):
     def setUp(self):
         self.recorder = XfrinRecorder()
@@ -2512,6 +2712,14 @@ class TestXfrin(unittest.TestCase):
         self.assertEqual(self.xfr.config_handler({'transfers_in': 3})['result'][0], 0)
         self.assertEqual(self.xfr._max_transfers_in, 3)
 
+    def test_command_handler_getstats(self):
+        module_spec = isc.config.module_spec_from_file(
+            xfrin.SPECFILE_LOCATION)
+        ans = isc.config.parse_answer(
+            self.xfr.command_handler("getstats", None))
+        self.assertEqual(0, ans[0])
+        self.assertTrue(module_spec.validate_statistics(False, ans[1]))
+
     def _check_zones_config(self, config_given):
         if 'transfers_in' in config_given:
             self.assertEqual(config_given['transfers_in'],

src/bin/xfrin/xfrin.py.in

@@ -1,6 +1,6 @@
 #!@PYTHON@
 
-# Copyright (C) 2009-2011  Internet Systems Consortium.
+# Copyright (C) 2009-2013  Internet Systems Consortium.
 #
 # Permission to use, copy, modify, and distribute this software for any
 # purpose with or without fee is hereby granted, provided that the above
@@ -28,6 +28,7 @@ import time
 from functools import reduce
 from optparse import OptionParser, OptionValueError
 from isc.config.ccsession import *
+from isc.statistics import Counters
 from isc.notify import notify_out
 import isc.util.process
 from isc.datasrc import DataSourceClient, ZoneFinder
@@ -612,6 +613,7 @@ class XfrinConnection(asyncore.dispatcher):
         # keep a record of this specific transfer to log on success
         # (time, rr/s, etc)
         self._transfer_stats = XfrinTransferStats()
+        self._counters = Counters(SPECFILE_LOCATION)
 
     def init_socket(self):
         '''Initialize the underlyig socket.
@@ -891,6 +893,19 @@ class XfrinConnection(asyncore.dispatcher):
         # All okay, return it
         return soa
 
+    def _get_ipver_str(self):
+        """Returns a 'v4' or 'v6' string representing a IP version
+        depending on the socket family. This is for an internal use
+        only (except for tests). This is supported only for IP sockets.
+        It raises a ValueError exception on other address families.
+
+        """
+        if self.socket.family == socket.AF_INET:
+            return 'v4'
+        elif self.socket.family == socket.AF_INET6:
+            return 'v6'
+        raise ValueError("Invalid address family. "
+                         "This is supported only for IP sockets")
 
     def _check_soa_serial(self):
         '''Send SOA query and compare the local and remote serials.
@@ -902,6 +917,9 @@ class XfrinConnection(asyncore.dispatcher):
         '''
 
         self._send_query(RRType.SOA)
+        # count soaoutv4 or soaoutv6 requests
+        self._counters.inc('zones', self._zone_name.to_text(),
+                           'soaout' + self._get_ipver_str())
         data_len = self._get_request_response(2)
         msg_len = socket.htons(struct.unpack('H', data_len)[0])
         soa_response = self._get_request_response(msg_len)
@@ -931,9 +949,7 @@ class XfrinConnection(asyncore.dispatcher):
         try:
             ret = XFRIN_OK
             self._request_type = request_type
-            # Right now RRType.[IA]XFR().to_text() is 'TYPExxx', so we need
-            # to hardcode here.
-            req_str = 'IXFR' if request_type == RRType.IXFR else 'AXFR'
+            req_str = request_type.to_text()
             if check_soa:
                 self._check_soa_serial()
                 self.close()
@@ -941,7 +957,16 @@ class XfrinConnection(asyncore.dispatcher):
                 if not self.connect_to_master():
                     raise XfrinException('Unable to reconnect to master')
 
+            # start statistics timer
+            # Note: If the timer for the zone is already started but
+            # not yet stopped due to some error, the last start time
+            # is overwritten at this point.
+            self._counters.start_timer('zones', self._zone_name.to_text(),
+                                       'last_' + req_str.lower() + '_duration')
             logger.info(XFRIN_XFR_TRANSFER_STARTED, req_str, self.zone_str())
+            # An AXFR or IXFR is being requested.
+            self._counters.inc('zones', self._zone_name.to_text(),
+                               req_str.lower() + 'req' + self._get_ipver_str())
             self._send_query(self._request_type)
             self.__state = XfrinInitialSOA()
             self._handle_xfrin_responses()
@@ -968,7 +993,6 @@ class XfrinConnection(asyncore.dispatcher):
                             "%.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
             # of trying another primary server, etc, but for now we treat it
@@ -1004,11 +1028,21 @@ class XfrinConnection(asyncore.dispatcher):
                          self.zone_str(), str(e))
             ret = XFRIN_FAIL
         finally:
+            # A xfrsuccess or xfrfail counter is incremented depending on
+            # the result.
+            result = {XFRIN_OK: 'xfrsuccess', XFRIN_FAIL: 'xfrfail'}[ret]
+            self._counters.inc('zones', self._zone_name.to_text(), result)
+            # The started statistics timer is finally stopped only in
+            # a successful case.
+            if ret == XFRIN_OK:
+                self._counters.stop_timer('zones',
+                                          self._zone_name.to_text(),
+                                          'last_' + req_str.lower() +
+                                          '_duration')
             # Make sure any remaining transaction in the diff is closed
             # (if not yet - possible in case of xfr-level exception) as soon
             # as possible
             self._diff = None
-
         return ret
 
     def _check_response_header(self, msg):
@@ -1339,6 +1373,7 @@ class Xfrin:
         self._cc_setup()
         self.recorder = XfrinRecorder()
         self._shutdown_event = threading.Event()
+        self._counters = Counters(SPECFILE_LOCATION)
 
     def _cc_setup(self):
         '''This method is used only as part of initialization, but is
@@ -1484,6 +1519,7 @@ class Xfrin:
             th.join()
 
     def command_handler(self, command, args):
+        logger.debug(DBG_XFRIN_TRACE, XFRIN_RECEIVED_COMMAND, command)
         answer = create_answer(0)
         try:
             if command == 'shutdown':
@@ -1552,6 +1588,14 @@ class Xfrin:
                                        (False if command == 'retransfer' else True))
                 answer = create_answer(ret[0], ret[1])
 
+            # return statistics data to the stats daemon
+            elif command == "getstats":
+                # The log level is here set to debug in order to avoid
+                # that a log becomes too verbose. Because the
+                # b10-stats daemon is periodically asking to the
+                # b10-xfrin daemon.
+                answer = create_answer(0, self._counters.get_statistics())
+
             else:
                 answer = create_answer(1, 'unknown command: ' + command)
         except XfrinException as err:

src/bin/xfrin/xfrin.spec

@@ -94,6 +94,119 @@
           }
         ]
       }
+    ],
+    "statistics": [
+      {
+        "item_name": "zones",
+        "item_type": "named_set",
+        "item_optional": false,
+        "item_default": {
+          "_SERVER_" : {
+	    "soaoutv4": 0,
+	    "soaoutv6": 0,
+	    "axfrreqv4": 0,
+	    "axfrreqv6": 0,
+	    "ixfrreqv4": 0,
+	    "ixfrreqv6": 0,
+	    "xfrsuccess": 0,
+	    "xfrfail": 0,
+	    "last_ixfr_duration": 0.0,
+	    "last_axfr_duration": 0.0
+          }
+        },
+        "item_title": "Zone names",
+        "item_description": "A directory name of per-zone statistics",
+        "named_set_item_spec": {
+          "item_name": "zonename",
+          "item_type": "map",
+          "item_optional": false,
+          "item_default": {},
+          "item_title": "Zone name",
+          "item_description": "An actual zone name or special zone name _SERVER_ representing the entire server. Zone classes (e.g. IN, CH, and HS) are mixed and counted so far. But these will be distinguished in future release.",
+          "map_item_spec": [
+            {
+              "item_name": "soaoutv4",
+              "item_type": "integer",
+              "item_optional": false,
+              "item_default": 0,
+              "item_title": "SOAOutv4",
+              "item_description": "Number of IPv4 SOA queries sent from Xfrin"
+            },
+            {
+              "item_name": "soaoutv6",
+              "item_type": "integer",
+              "item_optional": false,
+              "item_default": 0,
+              "item_title": "SOAOutv6",
+              "item_description": "Number of IPv6 SOA queries sent from Xfrin"
+            },
+            {
+              "item_name": "axfrreqv4",
+              "item_type": "integer",
+              "item_optional": false,
+              "item_default": 0,
+              "item_title": "AXFRReqv4",
+              "item_description": "Number of IPv4 AXFR requests sent from Xfrin"
+            },
+            {
+              "item_name": "axfrreqv6",
+              "item_type": "integer",
+              "item_optional": false,
+              "item_default": 0,
+              "item_title": "AXFRReqv6",
+              "item_description": "Number of IPv6 AXFR requests sent from Xfrin"
+            },
+            {
+              "item_name": "ixfrreqv4",
+              "item_type": "integer",
+              "item_optional": false,
+              "item_default": 0,
+              "item_title": "IXFRReqv4",
+              "item_description": "Number of IPv4 IXFR requests sent from Xfrin"
+            },
+            {
+              "item_name": "ixfrreqv6",
+              "item_type": "integer",
+              "item_optional": false,
+              "item_default": 0,
+              "item_title": "IXFRReqv6",
+              "item_description": "Number of IPv6 IXFR requests sent from Xfrin"
+            },
+            {
+              "item_name": "xfrsuccess",
+              "item_type": "integer",
+              "item_optional": false,
+              "item_default": 0,
+              "item_title": "XfrSuccess",
+              "item_description": "Number of zone transfer requests succeeded. These include the case where the zone turns out to be the latest as a result of an initial SOA query (and there is actually no AXFR or IXFR transaction)."
+            },
+            {
+              "item_name": "xfrfail",
+              "item_type": "integer",
+              "item_optional": false,
+              "item_default": 0,
+              "item_title": "XfrFail",
+              "item_description": "Number of zone transfer requests failed"
+            },
+            {
+              "item_name": "last_axfr_duration",
+              "item_type": "real",
+              "item_optional": false,
+              "item_default": 0.0,
+              "item_title": "Last AXFR duration",
+              "item_description": "Duration in seconds of the last successful AXFR.  0.0 means no successful AXFR done or means a successful AXFR done in less than a microsecond.  If an AXFR is aborted due to some failure, this duration won't be updated."
+            },
+            {
+              "item_name": "last_ixfr_duration",
+              "item_type": "real",
+              "item_optional": false,
+              "item_default": 0.0,
+              "item_title": "Last IXFR duration",
+              "item_description": "Duration in seconds of the last successful IXFR.  0.0 means no successful IXFR done or means a successful IXFR done in less than a microsecond.  If an IXFR is aborted due to some failure, this duration won't be updated."
+            }
+          ]
+        }
+      }
     ]
   }
 }

src/bin/xfrin/xfrin_messages.mes

@@ -135,6 +135,9 @@ 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_RECEIVED_COMMAND received command: %1
+The xfrin daemon received a command on the command channel.
+
 % 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

src/lib/python/isc/statistics/counters.py

@@ -217,8 +217,8 @@ class Counters():
         zones/example.com./ixfrreqv6
         zones/example.com./xfrsuccess
         zones/example.com./xfrfail
-        zones/example.com./time_to_ixfr
-        zones/example.com./time_to_axfr
+        zones/example.com./last_ixfr_duration
+        zones/example.com./last_axfr_duration
         ixfr_running
         axfr_running
         socket/unixdomain/open
@@ -327,7 +327,9 @@ class Counters():
     def start_timer(self, *args):
         """Starts a timer which is identified by args and keeps it
         running until stop_timer() is called. It acquires a lock to
-        support multi-threaded use."""
+        support multi-threaded use. If the specified timer is already
+        started but not yet stopped, the last start time is
+        overwritten."""
         identifier = _concat(*args)
         with self._rlock:
             if self._disabled: return

src/lib/python/isc/statistics/tests/counters_test.py

@@ -197,7 +197,7 @@ class BaseTestCounters():
         # for per-zone counters
         for name in self.counters._zones_item_list:
             args = (self._perzone_prefix, TEST_ZONE_NAME_STR, name)
-            if name.find('time_to_') == 0:
+            if name.find('last_') == 0 and name.endswith('_duration'):
                 self.counters.start_timer(*args)
                 self.counters.stop_timer(*args)
                 self.assertGreaterEqual(self.counters.get(*args), 0.0)
@@ -278,7 +278,7 @@ class BaseTestCounters():
         # setting all counters to zero
         for name in self.counters._zones_item_list:
             args = (self._perzone_prefix, TEST_ZONE_NAME_STR, name)
-            if name.find('time_to_') == 0:
+            if name.find('last_') == 0 and name.endswith('_duration'):
                 zero = 0.0
             else:
                 zero = 0

src/lib/python/isc/statistics/tests/testdata/test_spec3.spec

@@ -19,8 +19,8 @@
 	    "ixfrreqv6": 0,
 	    "xfrsuccess": 0,
 	    "xfrfail": 0,
-	    "time_to_ixfr": 0.0,
-	    "time_to_axfr": 0.0
+	    "last_ixfr_duration": 0.0,
+	    "last_axfr_duration": 0.0
           }
         },
         "item_title": "Zone names",
@@ -98,20 +98,20 @@
               "item_description": "Number of zone transfer requests failed"
             },
             {
-              "item_name": "time_to_ixfr",
+              "item_name": "last_ixfr_duration",
               "item_type": "real",
               "item_optional": false,
               "item_default": 0.0,
-              "item_title": "Time to IXFR",
-              "item_description": "Elapsed time in seconds to do the last IXFR"
+              "item_title": "Last IXFR duration",
+              "item_description": "Duration of the last IXFR. 0.0 means no successful IXFR done."
             },
             {
-              "item_name": "time_to_axfr",
+              "item_name": "last_axfr_duration",
               "item_type": "real",
               "item_optional": false,
               "item_default": 0.0,
-              "item_title": "Time to AXFR",
-              "item_description": "Elapsed time in seconds to do the last AXFR"
+              "item_title": "Last AXFR duration",
+              "item_description": "Duration of the last AXFR. 0.0 means no successful AXFR done."
             }
           ]
         }

tests/lettuce/configurations/xfrin/retransfer_master.conf.orig

@@ -33,9 +33,6 @@
             "port": 47806
         } ]
     },
-    "Stats": {
-        "poll-interval": 1
-    },
     "Init": {
         "components": {
             "b10-auth": { "kind": "needed", "special": "auth" },

tests/lettuce/configurations/xfrin/retransfer_master_v4.conf.orig

@@ -0,0 +1,45 @@
+{
+    "version": 3,
+    "Logging": {
+        "loggers": [ {
+            "debuglevel": 99,
+            "severity": "DEBUG",
+            "name": "*"
+        } ]
+    },
+    "Auth": {
+        "database_file": "data/example.org.sqlite3",
+        "listen_on": [ {
+            "address": "127.0.0.1",
+            "port": 47809
+        } ]
+    },
+    "data_sources": {
+        "classes": {
+            "IN": [{
+                "type": "sqlite3",
+                "params": {
+                    "database_file": "data/example.org.sqlite3"
+                }
+            }]
+        }
+    },
+    "Xfrout": {
+        "zone_config": [ {
+            "origin": "example.org"
+        } ],
+        "also_notify": [ {
+            "address": "127.0.0.1",
+            "port": 47806
+        } ]
+    },
+    "Init": {
+        "components": {
+            "b10-auth": { "kind": "needed", "special": "auth" },
+            "b10-xfrout": { "address": "Xfrout", "kind": "dispensable" },
+            "b10-zonemgr": { "address": "Zonemgr", "kind": "dispensable" },
+            "b10-stats": { "address": "Stats", "kind": "dispensable" },
+            "b10-cmdctl": { "special": "cmdctl", "kind": "needed" }
+        }
+    }
+}

tests/lettuce/configurations/xfrin/retransfer_slave_notify.conf.orig

@@ -42,6 +42,7 @@
             "b10-auth": { "kind": "needed", "special": "auth" },
             "b10-xfrin": { "address": "Xfrin", "kind": "dispensable" },
             "b10-zonemgr": { "address": "Zonemgr", "kind": "dispensable" },
+            "b10-stats": { "address": "Stats", "kind": "dispensable" },
             "b10-cmdctl": { "special": "cmdctl", "kind": "needed" }
         }
     }

tests/lettuce/configurations/xfrin/retransfer_slave_notify_v4.conf

@@ -0,0 +1,49 @@
+{
+    "version": 3,
+    "Logging": {
+        "loggers": [ {
+            "debuglevel": 99,
+            "severity": "DEBUG",
+            "name": "*"
+        } ]
+    },
+    "Auth": {
+        "database_file": "data/xfrin-notify.sqlite3",
+        "listen_on": [ {
+            "address": "127.0.0.1",
+            "port": 47806
+        } ]
+    },
+    "data_sources": {
+        "classes": {
+            "IN": [{
+                "type": "sqlite3",
+                "params": {
+                    "database_file": "data/xfrin-notify.sqlite3"
+                }
+            }]
+        }
+    },
+    "Xfrin": {
+        "zones": [ {
+            "name": "example.org",
+            "master_addr": "127.0.0.1",
+            "master_port": 47809
+        } ]
+    },
+    "Zonemgr": {
+        "secondary_zones": [ {
+            "name": "example.org",
+            "class": "IN"
+        } ]
+    },
+    "Init": {
+        "components": {
+            "b10-auth": { "kind": "needed", "special": "auth" },
+            "b10-xfrin": { "address": "Xfrin", "kind": "dispensable" },
+            "b10-zonemgr": { "address": "Zonemgr", "kind": "dispensable" },
+            "b10-stats": { "address": "Stats", "kind": "dispensable" },
+            "b10-cmdctl": { "special": "cmdctl", "kind": "needed" }
+        }
+    }
+}

tests/lettuce/features/terrain/bind10_control.py

@@ -389,67 +389,6 @@ def query_statistics(step, statistics, name, cmdctl_port):
         % (port_str, name,\
                ' name=%s' % statistics if statistics else ''))
 
-def find_value(dictionary, key):
-    """A helper method. Recursively find a value corresponding to the
-    key of the dictionary and returns it. Returns None if the
-    dictionary is not dict type."""
-    if type(dictionary) is not dict:
-        return
-    if key in dictionary:
-        return dictionary[key]
-    else:
-        for v in dictionary.values():
-            return find_value(v, key)
-
-@step('the statistics counter (\S+)(?: in the category (\S+))?'+ \
-          '(?: for the zone (\S+))? should be' + \
-          '(?:( greater than| less than| between))? (\-?\d+)(?: and (\-?\d+))?')
-def check_statistics(step, counter, category, zone, gtltbt, number, upper):
-    """
-    check the output of bindctl for statistics of specified counter
-    and zone.
-    Parameters:
-    counter ('counter <counter>'): The counter name of statistics.
-    category ('category <category>', optional): The category of counter.
-    zone ('zone <zone>', optional): The zone name.
-    gtltbt (' greater than'|' less than'|' between', optional): greater than
-          <number> or less than <number> or between <number> and <upper>.
-    number ('<number>): The expect counter number. <number> is assumed
-          to be an unsigned integer.
-    upper ('<upper>, optional): The expect upper counter number when
-          using 'between'.
-    """
-    output = parse_bindctl_output_as_data_structure()
-    found = None
-    category_str = ""
-    zone_str = ""
-    depth = []
-    if category:
-        depth.insert(0, category)
-        category_str = " for category %s" % category
-    if zone:
-        depth.insert(0, zone)
-        zone_str = " for zone %s" % zone
-    for level in depth:
-        output = find_value(output, level)
-    found = find_value(output, counter)
-    assert found is not None, \
-        'Not found statistics counter %s%s%s' % \
-            (counter, category_str, zone_str)
-    msg = "Got %s, expected%s %s as counter %s%s" % \
-        (found, gtltbt, number, counter, zone_str)
-    if gtltbt and 'between' in gtltbt and upper:
-        msg = "Got %s, expected%s %s and %s as counter %s%s" % \
-            (found, gtltbt, number, upper, counter, zone_str)
-        assert int(number) <= int(found) \
-            and int(found) <= int(upper), msg
-    elif gtltbt and 'greater' in gtltbt:
-        assert int(found) > int(number), msg
-    elif gtltbt and 'less' in gtltbt:
-        assert int(found) < int(number), msg
-    else:
-        assert int(found) == int(number), msg
-
 @step('statistics counters are 0 in category (\S+)( except for the' + \
           ' following items)?')
 def check_statistics_items(step, category, has_except_for):
@@ -461,9 +400,14 @@ def check_statistics_items(step, category, has_except_for):
         with the multiline part.
 
     Expected values of items are taken from the multiline part of the step in
-    the scenario. The multiline part has two columns: item_name and item_value.
-    item_name is a relative name to category. item_value is an expected value
-    for item_name.
+    the scenario. The multiline part has at most four columns: item_name,
+    item_value, min_value, and max_value. item_name is a relative name
+    to category. item_value is an expected value for
+    item_name. min_value and max_value are expected to be used when
+    item_value cannot be specified to be item_value. min_value is the
+    minimum value in the expected range, and max_value is the maximum
+    value in the expected range. Values would be examined if they are
+    in columns corresponding to these.
     """
 
     def flatten(dictionary, prefix=''):
@@ -480,15 +424,55 @@ def check_statistics_items(step, category, has_except_for):
         # fetch step tables in the scnario as hashes
         for item in step.hashes:
             name = category+'.'+item['item_name']
-            value = item['item_value']
             assert stats.has_key(name), \
                 'Statistics item %s was not found' % (name)
             found = stats[name]
-            assert int(found) == int(value), \
-                'Statistics item %s has unexpected value %s (expect %s)' % \
+            if 'item_value' in item and item['item_value']:
+                value = item['item_value']
+                assert int(found) == int(value), \
+                    'Statistics item %s has unexpected value %s (expect %s)' % \
+                    (name, found, value)
+            if 'min_value' in item and item['min_value']:
+                value = item['min_value']
+                assert float(value) <= float(found), \
+                    'Statistics item %s has unexpected value %s (expect %s or greater than)' % \
+                    (name, found, value)
+            if 'max_value' in item and item['max_value']:
+                value = item['max_value']
+                assert float(found) <= float(value), \
+                    'Statistics item %s has unexpected value %s (expect %s or less than)' % \
                     (name, found, value)
             del(stats[name])
     for name, found in stats.items():
         assert int(found) == 0, \
             'Statistics item %s has unexpected value %s (expect %s)' % \
                 (name, found, 0)
+
+@step('check initial statistics(?:( not)? containing (\S+))? for (\S+)'
+      '( with cmdctl port \d+)?( except for the following items)?')
+def check_init_statistics(step, notv, string, name, cmdctl_port, has_except_for):
+    """Checks the initial statistics for the module. Also checks a
+    string is contained or not contained in them. Statistics counters
+      other than zero can follow below.
+    Parameters:
+    notv ('not'): reverse the check (fail if string is found)
+    string ('containing <string>') string to look for
+    name ('module <name>'): The name of the module (case sensitive!)
+    cmdctl_port ('with cmdctl port <portnr>', optional): cmdctl port to send
+                the command to.
+    has_except_for ('except for the following items'): checks values of items
+        with the multiline part.
+    """
+    query_str = 'query statistics of bind10 module ' + name
+    if cmdctl_port:
+        query_str = query_str + cmdctl_port
+    notcontain_str = 'last bindctl output should%s contain "%s"'
+    check_str = 'statistics counters are 0 in category .' + name
+    if has_except_for:
+        check_str = check_str + has_except_for + "\n" \
+            + step.represent_hashes()
+    step.given(query_str)
+    step.given(notcontain_str % (' not', 'error'))
+    if string is not None:
+        step.given(notcontain_str % (notv, string))
+    step.given(check_str)

tests/lettuce/features/terrain/terrain.py

@@ -68,6 +68,8 @@ copylist = [
      "configurations/ddns/noddns.config"],
     ["configurations/xfrin/retransfer_master.conf.orig",
      "configurations/xfrin/retransfer_master.conf"],
+    ["configurations/xfrin/retransfer_master_v4.conf.orig",
+     "configurations/xfrin/retransfer_master_v4.conf"],
     ["configurations/xfrin/retransfer_master_nons.conf.orig",
      "configurations/xfrin/retransfer_master_nons.conf"],
     ["configurations/xfrin/retransfer_slave.conf.orig",

tests/lettuce/features/xfrin_notify_handling.feature

@@ -1,5 +1,10 @@
 Feature: Xfrin incoming notify handling
-    Tests for Xfrin incoming notify handling.
+    Tests for Xfrin incoming notify handling. They also test
+    statistics counters incremented, which are related to notifying
+    and transferring by Xfrout and receiveing by Xfrin. Some cases are
+    considered: Transferring is done via IPv4 or IPv6 transport. A
+    transfer request from Xfrin is rejected by Xfrout. The master
+    server or slave server is unreachable.
 
     Scenario: Handle incoming notify
     Given I have bind10 running with configuration xfrin/retransfer_master.conf with cmdctl port 47804 as master
@@ -20,33 +25,125 @@ Feature: Xfrin incoming notify handling
     A query for www.example.org to [::1]:47806 should have rcode NXDOMAIN
 
     #
-    # Test for statistics
+    # Test1 for Xfrout statistics
+    #
+    check initial statistics not containing example.org for Xfrout with cmdctl port 47804 except for the following items
+      | item_name                | item_max | item_min |
+      | socket.unixdomain.open   |        1 |        0 |
+    # Note: .Xfrout.socket.unixdomain.open can be either expected to
+    # be 0 or 1 here.  The reason is: if b10-xfrout has started up and is
+    # ready for a request from b10-stats, then b10-stats does request
+    # to b10-xfrout and the value results in 1. Otherwise if
+    # b10-xfrout is starting and isn't yet ready, then b10-stats
+    # doesn't request to b10-xfrout and the value still remains to be the
+    # default value(0).
+
+    #
+    # Test2 for Xfrin statistics
+    #
+    check initial statistics not containing example.org for Xfrin
+
+    When I send bind10 with cmdctl port 47804 the command Xfrout notify example.org IN
+    Then wait for new master stderr message XFROUT_NOTIFY_COMMAND
+    Then wait for new bind10 stderr message AUTH_RECEIVED_NOTIFY
+    # From this point we can't reliably 'wait for new' because the ordering
+    # of logs from different processes is unpredictable.  But these
+    # should be okay in this case.
+    Then wait for bind10 stderr message ZONEMGR_RECEIVE_NOTIFY
+    Then wait for bind10 stderr message XFRIN_XFR_TRANSFER_STARTED
+    Then wait for bind10 stderr message XFRIN_TRANSFER_SUCCESS not XFRIN_XFR_PROCESS_FAILURE
+    Then wait for bind10 stderr message ZONEMGR_RECEIVE_XFRIN_SUCCESS
+    Then wait for master stderr message NOTIFY_OUT_REPLY_RECEIVED
+
+    A query for www.example.org to [::1]:47806 should have rcode NOERROR
+    # Make sure handling statistics command handling checked below is
+    # after this query
+    And wait for bind10 stderr message AUTH_SEND_NORMAL_RESPONSE
+
+    #
+    # Test3 for Xfrout statistics
     #
-    # check for initial statistics
+    # check statistics change
     #
+
+    # wait until the last stats requesting is finished
     When I query statistics zones of bind10 module Xfrout with cmdctl port 47804
+    # note that this does not 100% guarantee the stats updated Xfrout
+    # statistics.  But there doesn't seem to be a better log message that
+    # suggests this event.
+    wait for new master stderr message XFROUT_RECEIVED_GETSTATS_COMMAND
     last bindctl output should not contain "error"
-    last bindctl output should not contain "example.org."
-    Then the statistics counter notifyoutv4 for the zone _SERVER_ should be 0
-    Then the statistics counter notifyoutv6 for the zone _SERVER_ should be 0
-    Then the statistics counter xfrrej for the zone _SERVER_ should be 0
-    Then the statistics counter xfrreqdone for the zone _SERVER_ should be 0
-
-    When I query statistics ixfr_running of bind10 module Xfrout with cmdctl port 47804
-    Then the statistics counter ixfr_running should be 0
 
-    When I query statistics axfr_running of bind10 module Xfrout with cmdctl port 47804
-    Then the statistics counter axfr_running should be 0
+    When I query statistics zones of bind10 module Xfrout with cmdctl port 47804
+    The statistics counters are 0 in category .Xfrout.zones except for the following items
+      | item_name                | item_value |
+      | _SERVER_.notifyoutv6     |          1 |
+      | _SERVER_.xfrreqdone      |          1 |
+      | example.org..notifyoutv6 |          1 |
+      | example.org..xfrreqdone  |          1 |
 
     When I query statistics socket of bind10 module Xfrout with cmdctl port 47804
-    Then the statistics counter open should be between 0 and 1
-    Then the statistics counter openfail should be 0
-    Then the statistics counter close should be 0
-    Then the statistics counter bindfail should be 0
-    Then the statistics counter acceptfail should be 0
-    Then the statistics counter accept should be 0
-    Then the statistics counter senderr should be 0
-    Then the statistics counter recverr should be 0
+    The statistics counters are 0 in category .Xfrout.socket.unixdomain except for the following items
+      | item_name | item_value |
+      | open      |          1 |
+      | accept    |          1 |
+
+    #
+    # Test4 for Xfrin statistics
+    #
+    # check statistics change
+    #
+
+    # wait until the last stats requesting is finished
+    When I query statistics zones of bind10 module Xfrin with cmdctl
+    wait for new bind10 stderr message XFRIN_RECEIVED_COMMAND
+    last bindctl output should not contain "error"
+
+    When I query statistics zones of bind10 module Xfrin with cmdctl
+    The statistics counters are 0 in category .Xfrin.zones except for the following items
+      | item_name                       | item_value | min_value |
+      | _SERVER_.soaoutv6               |          1 |           |
+      | _SERVER_.axfrreqv6              |          1 |           |
+      | _SERVER_.xfrsuccess             |          1 |           |
+      | _SERVER_.last_axfr_duration     |            |       0.0 |
+      | example.org..soaoutv6           |          1 |           |
+      | example.org..axfrreqv6          |          1 |           |
+      | example.org..xfrsuccess         |          1 |           |
+      | example.org..last_axfr_duration |            |       0.0 |
+
+    #
+    # Test for handling incoming notify only in IPv4
+    #
+    Scenario: Handle incoming notify (IPv4)
+    Given I have bind10 running with configuration xfrin/retransfer_master_v4.conf with cmdctl port 47804 as master
+    And wait for master stderr message BIND10_STARTED_CC
+    And wait for master stderr message CMDCTL_STARTED
+    And wait for master stderr message AUTH_SERVER_STARTED
+    And wait for master stderr message XFROUT_STARTED
+    And wait for master stderr message ZONEMGR_STARTED
+    And wait for master stderr message STATS_STARTING
+
+    And I have bind10 running with configuration xfrin/retransfer_slave_notify_v4.conf
+    And wait for bind10 stderr message BIND10_STARTED_CC
+    And wait for bind10 stderr message CMDCTL_STARTED
+    And wait for bind10 stderr message AUTH_SERVER_STARTED
+    And wait for bind10 stderr message XFRIN_STARTED
+    And wait for bind10 stderr message ZONEMGR_STARTED
+
+    A query for www.example.org to 127.0.0.1:47806 should have rcode NXDOMAIN
+
+    #
+    # Test1 for Xfrout statistics
+    #
+    check initial statistics not containing example.org for Xfrout with cmdctl port 47804 except for the following items
+      | item_name                | item_max | item_min |
+      | socket.unixdomain.open   |        1 |        0 |
+    # Note: See above about .Xfrout.socket.unixdomain.open.
+
+    #
+    # Test2 for Xfrin statistics
+    #
+    check initial statistics not containing example.org for Xfrin
 
     When I send bind10 with cmdctl port 47804 the command Xfrout notify example.org IN
     Then wait for new master stderr message XFROUT_NOTIFY_COMMAND
@@ -60,43 +157,61 @@ Feature: Xfrin incoming notify handling
     Then wait for bind10 stderr message ZONEMGR_RECEIVE_XFRIN_SUCCESS
     Then wait for master stderr message NOTIFY_OUT_REPLY_RECEIVED
 
-    A query for www.example.org to [::1]:47806 should have rcode NOERROR
+    A query for www.example.org to 127.0.0.1:47806 should have rcode NOERROR
     # Make sure handling statistics command handling checked below is
     # after this query
     And wait for bind10 stderr message AUTH_SEND_NORMAL_RESPONSE
 
     #
-    # Test for statistics
+    # Test3 for Xfrout statistics
     #
-    # check for statistics change
+    # check statistics change
     #
 
     # wait until the last stats requesting is finished
+    When I query statistics zones of bind10 module Xfrout with cmdctl port 47804
     # note that this does not 100% guarantee the stats updated Xfrout
     # statistics.  But there doesn't seem to be a better log message that
     # suggests this event.
     wait for new master stderr message XFROUT_RECEIVED_GETSTATS_COMMAND
+    last bindctl output should not contain "error"
 
     When I query statistics zones of bind10 module Xfrout with cmdctl port 47804
-    last bindctl output should not contain "error"
-    Then the statistics counter notifyoutv4 for the zone _SERVER_ should be 0
-    Then the statistics counter notifyoutv4 for the zone example.org. should be 0
-    Then the statistics counter notifyoutv6 for the zone _SERVER_ should be 1
-    Then the statistics counter notifyoutv6 for the zone example.org. should be 1
-    Then the statistics counter xfrrej for the zone _SERVER_ should be 0
-    Then the statistics counter xfrrej for the zone example.org. should be 0
-    Then the statistics counter xfrreqdone for the zone _SERVER_ should be 1
-    Then the statistics counter xfrreqdone for the zone example.org. should be 1
+    The statistics counters are 0 in category .Xfrout.zones except for the following items
+      | item_name                | item_value |
+      | _SERVER_.notifyoutv4     |          1 |
+      | _SERVER_.xfrreqdone      |          1 |
+      | example.org..notifyoutv4 |          1 |
+      | example.org..xfrreqdone  |          1 |
 
     When I query statistics socket of bind10 module Xfrout with cmdctl port 47804
-    Then the statistics counter open should be 1
-    Then the statistics counter openfail should be 0
-    Then the statistics counter close should be 0
-    Then the statistics counter bindfail should be 0
-    Then the statistics counter acceptfail should be 0
-    Then the statistics counter accept should be 1
-    Then the statistics counter senderr should be 0
-    Then the statistics counter recverr should be 0
+    The statistics counters are 0 in category .Xfrout.socket.unixdomain except for the following items
+      | item_name | item_value |
+      | open      |          1 |
+      | accept    |          1 |
+
+    #
+    # Test4 for Xfrin statistics
+    #
+    # check statistics change
+    #
+
+    # wait until the last stats requesting is finished
+    When I query statistics zones of bind10 module Xfrin with cmdctl
+    wait for new bind10 stderr message XFRIN_RECEIVED_COMMAND
+    last bindctl output should not contain "error"
+
+    When I query statistics zones of bind10 module Xfrin with cmdctl
+    The statistics counters are 0 in category .Xfrin.zones except for the following items
+      | item_name                       | item_value | min_value |
+      | _SERVER_.soaoutv4               |          1 |           |
+      | _SERVER_.axfrreqv4              |          1 |           |
+      | _SERVER_.xfrsuccess             |          1 |           |
+      | _SERVER_.last_axfr_duration     |            |       0.0 |
+      | example.org..soaoutv4           |          1 |           |
+      | example.org..axfrreqv4          |          1 |           |
+      | example.org..xfrsuccess         |          1 |           |
+      | example.org..last_axfr_duration |            |       0.0 |
 
     #
     # Test for Xfr request rejected
@@ -120,33 +235,123 @@ Feature: Xfrin incoming notify handling
     A query for www.example.org to [::1]:47806 should have rcode NXDOMAIN
 
     #
-    # Test1 for statistics
+    # Test1 for Xfrout statistics
     #
-    # check for initial statistics
+    check initial statistics not containing example.org for Xfrout with cmdctl port 47804 except for the following items
+      | item_name                | item_max | item_min |
+      | socket.unixdomain.open   |        1 |        0 |
+    # Note: See above about .Xfrout.socket.unixdomain.open.
+
     #
+    # Test2 for Xfrin statistics
+    #
+    check initial statistics not containing example.org for Xfrin
+
+    #
+    # set transfer_acl rejection
+    # Local xfr requests from Xfrin module would be rejected here.
+    #
+    When I send bind10 the following commands with cmdctl port 47804
+    """
+    config set Xfrout/zone_config[0]/transfer_acl [{"action":  "REJECT", "from": "::1"}]
+    config commit
+    """
+    last bindctl output should not contain Error
+
+    When I send bind10 with cmdctl port 47804 the command Xfrout notify example.org IN
+    Then wait for new master stderr message XFROUT_NOTIFY_COMMAND
+    Then wait for new bind10 stderr message AUTH_RECEIVED_NOTIFY
+    # can't use 'wait for new' below.
+    Then wait for bind10 stderr message ZONEMGR_RECEIVE_NOTIFY
+    Then wait for bind10 stderr message XFRIN_XFR_TRANSFER_STARTED
+    Then wait for bind10 stderr message XFRIN_XFR_TRANSFER_PROTOCOL_VIOLATION not XFRIN_TRANSFER_SUCCESS
+    Then wait for bind10 stderr message ZONEMGR_RECEIVE_XFRIN_FAILED not ZONEMGR_RECEIVE_XFRIN_SUCCESS
+    Then wait for master stderr message NOTIFY_OUT_REPLY_RECEIVED
+
+    A query for www.example.org to [::1]:47806 should have rcode NXDOMAIN
+
+    #
+    # Test3 for Xfrout statistics
+    #
+    # check statistics change
+    #
+
+    # wait until the last stats requesting is finished
     When I query statistics zones of bind10 module Xfrout with cmdctl port 47804
+    wait for new master stderr message XFROUT_RECEIVED_GETSTATS_COMMAND
     last bindctl output should not contain "error"
-    last bindctl output should not contain "example.org."
-    Then the statistics counter notifyoutv4 for the zone _SERVER_ should be 0
-    Then the statistics counter notifyoutv6 for the zone _SERVER_ should be 0
-    Then the statistics counter xfrrej for the zone _SERVER_ should be 0
-    Then the statistics counter xfrreqdone for the zone _SERVER_ should be 0
-
-    When I query statistics ixfr_running of bind10 module Xfrout with cmdctl port 47804
-    Then the statistics counter ixfr_running should be 0
 
-    When I query statistics axfr_running of bind10 module Xfrout with cmdctl port 47804
-    Then the statistics counter axfr_running should be 0
+    When I query statistics zones of bind10 module Xfrout with cmdctl port 47804
+    The statistics counters are 0 in category .Xfrout.zones except for the following items
+      | item_name                | item_value | min_value | max_value |
+      | _SERVER_.notifyoutv6     |          1 |           |           |
+      | _SERVER_.xfrrej          |            |         1 |         3 |
+      | example.org..notifyoutv6 |          1 |           |           |
+      | example.org..xfrrej      |            |         1 |         3 |
+    # Note: The above rejection counters might sometimes be increased
+    # up to 3. See this for details
+    # http://git.bind10.isc.org/~tester/builder/BIND10-lettuce/20120918210000-MacOS/logs/lettuce.out
 
     When I query statistics socket of bind10 module Xfrout with cmdctl port 47804
-    Then the statistics counter open should be between 0 and 1
-    Then the statistics counter openfail should be 0
-    Then the statistics counter close should be 0
-    Then the statistics counter bindfail should be 0
-    Then the statistics counter acceptfail should be 0
-    Then the statistics counter accept should be 0
-    Then the statistics counter senderr should be 0
-    Then the statistics counter recverr should be 0
+    The statistics counters are 0 in category .Xfrout.socket.unixdomain except for the following items
+      | item_name | item_value |
+      | open      |          1 |
+      | accept    |          1 |
+
+    #
+    # Test4 for Xfrin statistics
+    #
+    # check statistics change
+    #
+
+    # wait until the last stats requesting is finished
+    When I query statistics zones of bind10 module Xfrin with cmdctl
+    wait for new bind10 stderr message XFRIN_RECEIVED_COMMAND
+    last bindctl output should not contain "error"
+
+    When I query statistics zones of bind10 module Xfrin with cmdctl
+    The statistics counters are 0 in category .Xfrin.zones except for the following items
+      | item_name              | item_value |
+      | _SERVER_.soaoutv6      |          1 |
+      | _SERVER_.axfrreqv6     |          1 |
+      | _SERVER_.xfrfail       |          1 |
+      | example.org..soaoutv6  |          1 |
+      | example.org..axfrreqv6 |          1 |
+      | example.org..xfrfail   |          1 |
+
+    #
+    # Test for Xfr request rejected in IPv4
+    #
+    Scenario: Handle incoming notify (XFR request rejected in IPv4)
+    Given I have bind10 running with configuration xfrin/retransfer_master_v4.conf with cmdctl port 47804 as master
+    And wait for master stderr message BIND10_STARTED_CC
+    And wait for master stderr message CMDCTL_STARTED
+    And wait for master stderr message AUTH_SERVER_STARTED
+    And wait for master stderr message XFROUT_STARTED
+    And wait for master stderr message ZONEMGR_STARTED
+    And wait for master stderr message STATS_STARTING
+
+    And I have bind10 running with configuration xfrin/retransfer_slave_notify_v4.conf
+    And wait for bind10 stderr message BIND10_STARTED_CC
+    And wait for bind10 stderr message CMDCTL_STARTED
+    And wait for bind10 stderr message AUTH_SERVER_STARTED
+    And wait for bind10 stderr message XFRIN_STARTED
+    And wait for bind10 stderr message ZONEMGR_STARTED
+
+    A query for www.example.org to 127.0.0.1:47806 should have rcode NXDOMAIN
+
+    #
+    # Test1 for Xfrout statistics
+    #
+    check initial statistics not containing example.org for Xfrout with cmdctl port 47804 except for the following items
+      | item_name                | item_max | item_min |
+      | socket.unixdomain.open   |        1 |        0 |
+    # Note: See above about .Xfrout.socket.unixdomain.open.
+
+    #
+    # Test2 for Xfrin statistics
+    #
+    check initial statistics not containing example.org for Xfrin
 
     #
     # set transfer_acl rejection
@@ -154,7 +359,7 @@ Feature: Xfrin incoming notify handling
     #
     When I send bind10 the following commands with cmdctl port 47804
     """
-    config set Xfrout/zone_config[0]/transfer_acl [{"action":  "REJECT", "from": "::1"}]
+    config set Xfrout/zone_config[0]/transfer_acl [{"action":  "REJECT", "from": "127.0.0.1"}]
     config commit
     """
     last bindctl output should not contain Error
@@ -169,39 +374,56 @@ Feature: Xfrin incoming notify handling
     Then wait for bind10 stderr message ZONEMGR_RECEIVE_XFRIN_FAILED not ZONEMGR_RECEIVE_XFRIN_SUCCESS
     Then wait for master stderr message NOTIFY_OUT_REPLY_RECEIVED
 
-    A query for www.example.org to [::1]:47806 should have rcode NXDOMAIN
+    A query for www.example.org to 127.0.0.1:47806 should have rcode NXDOMAIN
 
     #
-    # Test2 for statistics
+    # Test3 for Xfrout statistics
     #
-    # check for statistics change
+    # check statistics change
     #
 
+    When I query statistics zones of bind10 module Xfrout with cmdctl port 47804
     # wait until stats request at least after NOTIFY_OUT_REPLY_RECEIVED
     wait for new master stderr message XFROUT_RECEIVED_GETSTATS_COMMAND
+    last bindctl output should not contain "error"
 
     When I query statistics zones of bind10 module Xfrout with cmdctl port 47804
-    last bindctl output should not contain "error"
-    Then the statistics counter notifyoutv4 for the zone _SERVER_ should be 0
-    Then the statistics counter notifyoutv4 for the zone example.org. should be 0
-    Then the statistics counter notifyoutv6 for the zone _SERVER_ should be 1
-    Then the statistics counter notifyoutv6 for the zone example.org. should be 1
-    # The counts of rejection would be between 1 and 2. They are not
-    # fixed. It would depend on timing or the platform.
-    Then the statistics counter xfrrej for the zone _SERVER_ should be greater than 0
-    Then the statistics counter xfrrej for the zone example.org. should be greater than 0
-    Then the statistics counter xfrreqdone for the zone _SERVER_ should be 0
-    Then the statistics counter xfrreqdone for the zone example.org. should be 0
+    The statistics counters are 0 in category .Xfrout.zones except for the following items
+      | item_name                | item_value | min_value | max_value |
+      | _SERVER_.notifyoutv4     |          1 |           |           |
+      | _SERVER_.xfrrej          |            |         1 |         3 |
+      | example.org..notifyoutv4 |          1 |           |           |
+      | example.org..xfrrej      |            |         1 |         3 |
+    # Note: The above rejection counters might sometimes be increased
+    # up to 3. See this for details
+    # http://git.bind10.isc.org/~tester/builder/BIND10-lettuce/20120918210000-MacOS/logs/lettuce.out
 
     When I query statistics socket of bind10 module Xfrout with cmdctl port 47804
-    Then the statistics counter open should be 1
-    Then the statistics counter openfail should be 0
-    Then the statistics counter close should be 0
-    Then the statistics counter bindfail should be 0
-    Then the statistics counter acceptfail should be 0
-    Then the statistics counter accept should be 1
-    Then the statistics counter senderr should be 0
-    Then the statistics counter recverr should be 0
+    The statistics counters are 0 in category .Xfrout.socket.unixdomain except for the following items
+      | item_name | item_value |
+      | open      |          1 |
+      | accept    |          1 |
+
+    #
+    # Test4 for Xfrin statistics
+    #
+    # check statistics change
+    #
+
+    # wait until the last stats requesting is finished
+    When I query statistics zones of bind10 module Xfrin with cmdctl
+    wait for new bind10 stderr message XFRIN_RECEIVED_COMMAND
+    last bindctl output should not contain "error"
+
+    When I query statistics zones of bind10 module Xfrin with cmdctl
+    The statistics counters are 0 in category .Xfrin.zones except for the following items
+      | item_name              | item_value |
+      | _SERVER_.soaoutv4      |          1 |
+      | _SERVER_.axfrreqv4     |          1 |
+      | _SERVER_.xfrfail       |          1 |
+      | example.org..soaoutv4  |          1 |
+      | example.org..axfrreqv4 |          1 |
+      | example.org..xfrfail   |          1 |
 
     #
     # Test for unreachable slave
@@ -226,29 +448,21 @@ Feature: Xfrin incoming notify handling
     # check statistics change
     #
 
+    When I query statistics zones of bind10 module Xfrout with cmdctl port 47804
     # wait until stats request at least after NOTIFY_OUT_TIMEOUT
     wait for new master stderr message XFROUT_RECEIVED_GETSTATS_COMMAND
+    last bindctl output should not contain "error"
 
     When I query statistics zones of bind10 module Xfrout with cmdctl port 47804
-    last bindctl output should not contain "error"
-    Then the statistics counter notifyoutv4 for the zone _SERVER_ should be 0
-    Then the statistics counter notifyoutv4 for the zone example.org. should be 0
-    Then the statistics counter notifyoutv6 for the zone _SERVER_ should be greater than 0
-    Then the statistics counter notifyoutv6 for the zone example.org. should be greater than 0
-    Then the statistics counter xfrrej for the zone _SERVER_ should be 0
-    Then the statistics counter xfrrej for the zone example.org. should be 0
-    Then the statistics counter xfrreqdone for the zone _SERVER_ should be 0
-    Then the statistics counter xfrreqdone for the zone example.org. should be 0
+    The statistics counters are 0 in category .Xfrout.zones except for the following items
+      | item_name                | min_value | max_value |
+      | _SERVER_.notifyoutv6     |         1 |	       5 |
+      | example.org..notifyoutv6 |         1 |	       5 |
 
     When I query statistics socket of bind10 module Xfrout with cmdctl port 47804
-    Then the statistics counter open should be 1
-    Then the statistics counter openfail should be 0
-    Then the statistics counter close should be 0
-    Then the statistics counter bindfail should be 0
-    Then the statistics counter acceptfail should be 0
-    Then the statistics counter accept should be 0
-    Then the statistics counter senderr should be 0
-    Then the statistics counter recverr should be 0
+    The statistics counters are 0 in category .Xfrout.socket.unixdomain except for the following items
+      | item_name | item_value |
+      | open      |          1 |
 
     #
     # Test for NOTIFY that would result in NOTAUTH