[1288] some logging improvements:

- log client's address (needed to update _guess_remote also)
- log xfr type (currently it's always 'AXFR', but we'll soon support IXFR)
- log the event of quote failure

src/bin/xfrout/tests/xfrout_test.py.in

@@ -91,6 +91,22 @@ class MockDataSrcClient:
             return soa_rrset
         return soa_rrset
 
+class MyCCSession(isc.config.ConfigData):
+    def __init__(self):
+        module_spec = isc.config.module_spec_from_file(
+            xfrout.SPECFILE_LOCATION)
+        ConfigData.__init__(self, module_spec)
+
+    def get_remote_config_value(self, module_name, identifier):
+        if module_name == "Auth" and identifier == "database_file":
+            return "initdb.file", False
+        else:
+            return "unknown", False
+
+# This constant dictionary stores all default configuration parameters
+# defined in the xfrout spec file.
+DEFAULT_CONFIG = MyCCSession().get_full_config()
+
 # We subclass the Session class we're testing here, only overriding a few
 # methods
 class MyXfroutSession(XfroutSession):
@@ -111,6 +127,7 @@ class Dbserver:
     def __init__(self):
         self._shutdown_event = threading.Event()
         self.transfer_counter = 0
+        self._max_transfers_out = DEFAULT_CONFIG['transfers_out']
     def get_db_file(self):
         return 'test.sqlite3'
     def increase_transfers_counter(self):
@@ -158,7 +175,9 @@ class TestXfroutSession(unittest.TestCase):
     def setUp(self):
         self.sock = MySocket(socket.AF_INET,socket.SOCK_STREAM)
         self.xfrsess = MyXfroutSession(self.sock, None, Dbserver(),
-                                       TSIGKeyRing(), ('127.0.0.1', 12345),
+                                       TSIGKeyRing(),
+                                       (socket.AF_INET, socket.SOCK_STREAM,
+                                        ('127.0.0.1', 12345)),
                                        # When not testing ACLs, simply accept
                                        isc.acl.dns.REQUEST_LOADER.load(
                                            [{"action": "ACCEPT"}]),
@@ -248,11 +267,13 @@ class TestXfroutSession(unittest.TestCase):
         rcode, msg = self.xfrsess._parse_query_message(self.mdata)
         self.assertEqual(rcode.to_text(), "NOERROR")
         # This should be dropped completely, therefore returning None
-        self.xfrsess._remote = ('192.0.2.1', 12345)
+        self.xfrsess._remote = (socket.AF_INET, socket.SOCK_STREAM,
+                                ('192.0.2.1', 12345))
         rcode, msg = self.xfrsess._parse_query_message(self.mdata)
         self.assertEqual(None, rcode)
         # This should be refused, therefore REFUSED
-        self.xfrsess._remote = ('192.0.2.2', 12345)
+        self.xfrsess._remote = (socket.AF_INET, socket.SOCK_STREAM,
+                                ('192.0.2.2', 12345))
         rcode, msg = self.xfrsess._parse_query_message(self.mdata)
         self.assertEqual(rcode.to_text(), "REFUSED")
 
@@ -261,7 +282,8 @@ class TestXfroutSession(unittest.TestCase):
 
         # If the TSIG check fails, it should not check ACL
         # (If it checked ACL as well, it would just drop the request)
-        self.xfrsess._remote = ('192.0.2.1', 12345)
+        self.xfrsess._remote = (socket.AF_INET, socket.SOCK_STREAM,
+                                ('192.0.2.1', 12345))
         self.xfrsess._tsig_key_ring = TSIGKeyRing()
         rcode, msg = self.xfrsess._parse_query_message(request_data)
         self.assertEqual(rcode.to_text(), "NOTAUTH")
@@ -299,19 +321,23 @@ class TestXfroutSession(unittest.TestCase):
                 {"action": "REJECT"}
         ]))
         # both matches
-        self.xfrsess._remote = ('192.0.2.1', 12345)
+        self.xfrsess._remote = (socket.AF_INET, socket.SOCK_STREAM,
+                                ('192.0.2.1', 12345))
         [rcode, msg] = self.xfrsess._parse_query_message(request_data)
         self.assertEqual(rcode.to_text(), "NOERROR")
         # TSIG matches, but address doesn't
-        self.xfrsess._remote = ('192.0.2.2', 12345)
+        self.xfrsess._remote = (socket.AF_INET, socket.SOCK_STREAM,
+                                ('192.0.2.2', 12345))
         [rcode, msg] = self.xfrsess._parse_query_message(request_data)
         self.assertEqual(rcode.to_text(), "REFUSED")
         # Address matches, but TSIG doesn't (not included)
-        self.xfrsess._remote = ('192.0.2.1', 12345)
+        self.xfrsess._remote = (socket.AF_INET, socket.SOCK_STREAM,
+                                ('192.0.2.1', 12345))
         [rcode, msg] = self.xfrsess._parse_query_message(self.mdata)
         self.assertEqual(rcode.to_text(), "REFUSED")
         # Neither address nor TSIG matches
-        self.xfrsess._remote = ('192.0.2.2', 12345)
+        self.xfrsess._remote = (socket.AF_INET, socket.SOCK_STREAM,
+                                ('192.0.2.2', 12345))
         [rcode, msg] = self.xfrsess._parse_query_message(self.mdata)
         self.assertEqual(rcode.to_text(), "REFUSED")
 
@@ -675,19 +701,6 @@ class TestXfroutSession(unittest.TestCase):
         # and it should not have sent anything else
         self.assertEqual(0, len(self.sock.sendqueue))
 
-class MyCCSession(isc.config.ConfigData):
-    def __init__(self):
-        module_spec = isc.config.module_spec_from_file(
-            xfrout.SPECFILE_LOCATION)
-        ConfigData.__init__(self, module_spec)
-
-    def get_remote_config_value(self, module_name, identifier):
-        if module_name == "Auth" and identifier == "database_file":
-            return "initdb.file", False
-        else:
-            return "unknown", False
-
-
 class MyUnixSockServer(UnixSockServer):
     def __init__(self):
         self._shutdown_event = threading.Event()
@@ -705,23 +718,27 @@ class TestUnixSockServer(unittest.TestCase):
            file descriptor. This is needed, because we get only that one
            from auth."""
         # We test with UDP, as it can be "connected" without other
-        # endpoint
+        # endpoint.  Note that in the current implementation _guess_remote()
+        # unconditionally returns SOCK_STREAM.
         sock = socket.socket(socket.AF_INET, socket.SOCK_DGRAM)
         sock.connect(('127.0.0.1', 12345))
-        self.assertEqual(('127.0.0.1', 12345),
+        self.assertEqual((socket.AF_INET, socket.SOCK_STREAM,
+                          ('127.0.0.1', 12345)),
                          self.unix._guess_remote(sock.fileno()))
         if socket.has_ipv6:
             # Don't check IPv6 address on hosts not supporting them
             sock = socket.socket(socket.AF_INET6, socket.SOCK_DGRAM)
             sock.connect(('::1', 12345))
-            self.assertEqual(('::1', 12345, 0, 0),
+            self.assertEqual((socket.AF_INET6, socket.SOCK_STREAM,
+                              ('::1', 12345, 0, 0)),
                              self.unix._guess_remote(sock.fileno()))
             # Try when pretending there's no IPv6 support
             # (No need to pretend when there's really no IPv6)
             xfrout.socket.has_ipv6 = False
             sock = socket.socket(socket.AF_INET, socket.SOCK_DGRAM)
             sock.connect(('127.0.0.1', 12345))
-            self.assertEqual(('127.0.0.1', 12345),
+            self.assertEqual((socket.AF_INET, socket.SOCK_STREAM,
+                              ('127.0.0.1', 12345)),
                              self.unix._guess_remote(sock.fileno()))
             # Return it back
             xfrout.socket.has_ipv6 = True

src/bin/xfrout/xfrout.py.in

@@ -107,6 +107,28 @@ def format_zone_str(zone_name, zone_class):
     """
     return zone_name.to_text() + '/' + str(zone_class)
 
+# borrowed from xfrin.py @ #1298.
+def format_addrinfo(addrinfo):
+    """Helper function to format the addrinfo as a string of the form
+       <addr>:<port> (for IPv4) or [<addr>]:port (for IPv6). For unix domain
+       sockets, and unknown address families, it returns a basic string
+       conversion of the third element of the passed tuple.
+       Parameters:
+       addrinfo: a 3-tuple consisting of address family, socket type, and,
+                 depending on the family, either a 2-tuple with the address
+                 and port, or a filename
+    """
+    try:
+        if addrinfo[0] == socket.AF_INET:
+            return str(addrinfo[2][0]) + ":" + str(addrinfo[2][1])
+        elif addrinfo[0] == socket.AF_INET6:
+            return "[" + str(addrinfo[2][0]) + "]:" + str(addrinfo[2][1])
+        else:
+            return str(addrinfo[2])
+    except IndexError:
+        raise TypeError("addrinfo argument to format_addrinfo() does not "
+                        "appear to be consisting of (family, socktype, (addr, port))")
+
 def get_rrset_len(rrset):
     """Returns the wire length of the given RRset"""
     bytes = bytearray()
@@ -124,6 +146,7 @@ class XfroutSession():
         self._tsig_ctx = None
         self._tsig_len = 0
         self._remote = remote
+        self._request_type = 'AXFR' # could be IXFR when we support it
         self._acl = default_acl
         self._zone_config = zone_config
         self.ClientClass = client_class # parameterize this for testing
@@ -208,14 +231,16 @@ class XfroutSession():
         zone_class = msg.get_question()[0].get_class()
         acl = self._get_transfer_acl(zone_name, zone_class)
         acl_result = acl.execute(
-            isc.acl.dns.RequestContext(self._remote, msg.get_tsig_record()))
+            isc.acl.dns.RequestContext(self._remote[2], msg.get_tsig_record()))
         if acl_result == DROP:
-            logger.info(XFROUT_QUERY_DROPPED, zone_name, zone_class,
-                        self._remote[0], self._remote[1])
+            logger.info(XFROUT_QUERY_DROPPED, self._request_type,
+                        format_addrinfo(self._remote),
+                        format_zone_str(zone_name, zone_class))
             return None, None
         elif acl_result == REJECT:
-            logger.info(XFROUT_QUERY_REJECTED, zone_name, zone_class,
-                        self._remote[0], self._remote[1])
+            logger.info(XFROUT_QUERY_REJECTED, self._request_type,
+                        format_addrinfo(self._remote),
+                        format_zone_str(zone_name, zone_class))
             return Rcode.REFUSED(), msg
 
         return rcode, msg
@@ -308,8 +333,6 @@ class XfroutSession():
         if self._soa is None or self._soa.get_rdata_count() != 1:
             return Rcode.SERVFAIL()
 
-        #TODO, check allow_transfer
-
         return Rcode.NOERROR()
 
 
@@ -324,6 +347,9 @@ class XfroutSession():
             return self._reply_query_with_error_rcode(msg, sock_fd,
                                                       Rcode.FORMERR())
         elif not quota_ok:
+            logger.warn(XFROUT_QUERY_QUOTA_EXCCEEDED, self._request_type,
+                        format_addrinfo(self._remote),
+                        self._server._max_transfers_out)
             return self._reply_query_with_error_rcode(msg, sock_fd,
                                                       Rcode.REFUSED())
 
@@ -335,16 +361,20 @@ class XfroutSession():
         # TODO: we should also include class in the check
         rcode_ = self._check_xfrout_available(zone_name)
         if rcode_ != Rcode.NOERROR():
-            logger.info(XFROUT_AXFR_TRANSFER_FAILED, zone_str, rcode_)
+            logger.info(XFROUT_AXFR_TRANSFER_FAILED, self._request_type,
+                        format_addrinfo(self._remote), zone_str, rcode_)
             return self._reply_query_with_error_rcode(msg, sock_fd, rcode_)
 
         try:
-            logger.info(XFROUT_AXFR_TRANSFER_STARTED, zone_str)
+            logger.info(XFROUT_AXFR_TRANSFER_STARTED, self._request_type,
+                        format_addrinfo(self._remote), zone_str)
             self._reply_xfrout_query(msg, sock_fd)
         except Exception as err:
-            logger.error(XFROUT_AXFR_TRANSFER_ERROR, zone_str, err)
+            logger.error(XFROUT_AXFR_TRANSFER_ERROR, self._request_type,
+                    format_addrinfo(self._remote), zone_str, err)
             pass
-        logger.info(XFROUT_AXFR_TRANSFER_DONE, zone_str)
+        logger.info(XFROUT_AXFR_TRANSFER_DONE, self._request_type,
+                    format_addrinfo(self._remote), zone_str)
 
     def _clear_message(self, msg):
         qid = msg.get_qid()
@@ -536,9 +566,12 @@ class UnixSockServer(socketserver_mixin.NoPollMixIn,
         t.start()
 
     def _guess_remote(self, sock_fd):
-        """
-           Guess remote address and port of the socket. The sock_fd must be a
-           socket
+        """Guess remote address and port of the socket.
+
+        The sock_fd must be a file descriptor of a socket.
+        This method retuns a 3-tuple consisting of address family,
+        socket type, and a 2-tuple with the address (string) and port (int).
+
         """
         # This uses a trick. If the socket is IPv4 in reality and we pretend
         # it to be IPv6, it returns IPv4 address anyway. This doesn't seem
@@ -550,7 +583,16 @@ class UnixSockServer(socketserver_mixin.NoPollMixIn,
             # To make it work even on hosts without IPv6 support
             # (Any idea how to simulate this in test?)
             sock = socket.fromfd(sock_fd, socket.AF_INET, socket.SOCK_STREAM)
-        return sock.getpeername()
+        peer = sock.getpeername()
+
+        # Identify the correct socket family.  Due to the above "trick",
+        # we cannot simply use sock.family.
+        family = socket.AF_INET6
+        try:
+            socket.inet_pton(socket.AF_INET6, peer[0])
+        except socket.error:
+            family = socket.AF_INET
+        return (family, socket.SOCK_STREAM, peer)
 
     def finish_request(self, sock_fd, request_data):
         '''Finish one request by instantiating RequestHandlerClass.

src/bin/xfrout/xfrout_messages.mes

@@ -15,17 +15,17 @@
 # No namespace declaration - these constants go in the global namespace
 # of the xfrout messages python module.
 
-% XFROUT_AXFR_TRANSFER_DONE transfer of %1 complete
+% XFROUT_AXFR_TRANSFER_DONE %1 client %2: transfer of %3 complete
 The transfer of the given zone has been completed successfully, or was
 aborted due to a shutdown event.
 
-% XFROUT_AXFR_TRANSFER_ERROR error transferring zone %1/%2: %3
+% XFROUT_AXFR_TRANSFER_ERROR %1 client %2: error transferring zone %3: %4
 An uncaught exception was encountered while sending the response to
 an AXFR query. The error message of the exception is included in the
 log message, but this error most likely points to incomplete exception
 handling in the code.
 
-% XFROUT_AXFR_TRANSFER_FAILED transfer of %1 failed, rcode: %2
+% XFROUT_AXFR_TRANSFER_FAILED %1 client %2: transfer of %3 failed, rcode: %4
 A transfer out for the given zone failed. An error response is sent
 to the client. The given rcode is the rcode that is set in the error
 response. This is either NOTAUTH (we are not authoritative for the
@@ -36,7 +36,7 @@ Xfrout/max_transfers_out, has been reached).
 # Still a TODO, but when implemented, REFUSED can also mean
 # the client is not allowed to transfer the zone
 
-% XFROUT_AXFR_TRANSFER_STARTED transfer of zone %1 has started
+% XFROUT_AXFR_TRANSFER_STARTED %1 client %2: transfer of zone %3 has started
 A transfer out of the given zone has started.
 
 % XFROUT_BAD_TSIG_KEY_STRING bad TSIG key string: %1
@@ -106,16 +106,27 @@ in the log message, but at this point no specific information other
 than that could be given. This points to incomplete exception handling
 in the code.
 
-% XFROUT_QUERY_DROPPED request to transfer %1/%2 to [%3]:%4 dropped
-The xfrout process silently dropped a request to transfer zone to given host.
-This is required by the ACLs. The %1 and %2 represent the zone name and class,
-the %3 and %4 the IP address and port of the peer requesting the transfer.
+% XFROUT_QUERY_DROPPED %1 client %2: request to transfer %3 dropped
+The xfrout process silently dropped a request to transfer zone to
+given host.  This is required by the ACLs.  The %2 represents the IP
+address and port of the peer requesting the transfer, and the %3
+represents the zone name and class.
 
-% XFROUT_QUERY_REJECTED request to transfer %1/%2 to [%3]:%4 rejected
+% XFROUT_QUERY_REJECTED %1 client %2: request to transfer %3 rejected
 The xfrout process rejected (by REFUSED rcode) a request to transfer zone to
-given host. This is because of ACLs. The %1 and %2 represent the zone name and
-class, the %3 and %4 the IP address and port of the peer requesting the
-transfer.
+given host. This is because of ACLs.  The %2 represents the IP
+address and port of the peer requesting the transfer, and the %3
+represents the zone name and class.
+
+% XFROUT_QUERY_QUOTA_EXCCEEDED %1 client %2: request denied due to quota (%3)
+The xfr request was rejected because the server was already handling
+the maximum number of allowable transfers as specified in the transfers_out
+configuration parameter, which is also shown in the log message.  The
+request was immediately responded and terminated with an RCODE of REFUSED.
+This can happen for a busy xfrout server, and you may want to increase
+this parameter; if the server is being too busy due to requests from
+unexpected clients you may want to restrict the legitimate clients
+with ACL.
 
 % XFROUT_RECEIVE_FILE_DESCRIPTOR_ERROR error receiving the file descriptor for an XFR connection
 There was an error receiving the file descriptor for the transfer