[1455] log messages for all ddns prereq errors

also a bit of renaming of the extremely long methods

src/lib/python/isc/ddns/libddns_messages.mes

@@ -15,6 +15,80 @@
 # No namespace declaration - these constants go in the global namespace
 # of the libddns_messages python module.
 
+% LIBDDNS_PREREQ_FORMERR update client %1 for zone %2: Format error in prerequisite (%3). Non-zero TTL.
+The prerequisite with the given name, class and type is not well-formed.
+The specific prerequisite is shown. In this case, it has a non-zero TTL value.
+A FORMERR error response is sent to the client.
+
+% LIBDDNS_PREREQ_FORMERR_ANY update client %1 for zone %2: Format error in prerequisite (%3). Non-zero TTL or rdata found.
+The prerequisite with the given name, class and type is not well-formed.
+The specific prerequisite is shown. In this case, it either has a non-zero
+TTL value, or has rdata fields. A FORMERR error response is sent to the client.
+
+% LIBDDNS_PREREQ_FORMERR_CLASS update client %1 for zone %2: Format error in prerequisite (%3). Bad class.
+The prerequisite with the given name, class and type is not well-formed.
+The specific prerequisite is shown. In this case, the class of the
+prerequisite should either match the class of the zone in the Zone Section,
+or it should be ANY or NONE, and it is not. A FORMERR error response is sent
+to the client.
+
+% LIBDDNS_PREREQ_FORMERR_NONE update client %1 for zone %2: Format error in prerequisite (%3). Non-zero TTL or rdata found.
+The prerequisite with the given name, class and type is not well-formed.
+The specific prerequisite is shown. In this case, it either has a non-zero
+TTL value, or has rdata fields. A FORMERR error response is sent to the client.
+
+% LIBDDNS_PREREQ_NAME_IN_USE_FAILED update client %1 for zone %2: 'Name is in use' prerequisite not satisfied (%3), rcode: %4
+A DNS UPDATE prerequisite was not satisfied. The specific prerequisite that
+was not satisfied is shown. The client is sent an error response with the
+given rcode.
+In this case, the specific prerequisite is 'Name is in use'. From RFC2136:
+Name is in use.  At least one RR with a specified NAME (in
+the zone and class specified by the Zone Section) must exist.
+Note that this prerequisite is NOT satisfied by empty
+nonterminals.
+
+% LIBDDNS_PREREQ_NAME_NOT_IN_USE_FAILED update client %1 for zone %2: 'Name is not in use' (%3) prerequisite not satisfied, rcode: %4
+A DNS UPDATE prerequisite was not satisfied. The specific prerequisite that
+was not satisfied is shown. The client is sent an error response with the
+given rcode.
+In this case, the specific prerequisite is ''. From RFC2136:
+Name is not in use.  No RR of any type is owned by a
+specified NAME.  Note that this prerequisite IS satisfied by
+empty nonterminals.
+
+% LIBDDNS_PREREQ_NOTZONE update client %1 for zone %2: prerequisite not in zone (%3)
+A DNS UPDATE prerequisite has a name that does not appear to be inside
+the zone specified in the Zone section of the UPDATE message.
+The specific prerequisite is shown. A NOTZONE error response is sent to
+the client.
+
+% LIBDDNS_PREREQ_RRSET_DOES_NOT_EXIST_FAILED update client %1 for zone %2: 'RRset does not exist' (%3) prerequisite not satisfied, rcode: %4
+A DNS UPDATE prerequisite was not satisfied. The specific prerequisite that
+was not satisfied is shown. The client is sent an error response with the
+given rcode.
+In this case, the specific prerequisite is ''. From RFC2136:
+RRset does not exist.  No RRs with a specified NAME and TYPE
+(in the zone and class denoted by the Zone Section) can exist.
+
+% LIBDDNS_PREREQ_RRSET_EXISTS_FAILED update client %1 for zone %2: 'RRset exists (value independent)' (%3) prerequisite not satisfied, rcode: %4
+A DNS UPDATE prerequisite was not satisfied. The specific prerequisite that
+was not satisfied is shown. The client is sent an error response with the
+given rcode.
+In this case, the specific prerequisite is ''. From RFC2136:
+RRset exists (value dependent).  A set of RRs with a
+specified NAME and TYPE exists and has the same members
+with the same RDATAs as the RRset specified here in this
+Section.
+
+% LIBDDNS_PREREQ_RRSET_EXISTS_VAL_FAILED update client %1 for zone %2: 'RRset exists (value dependent)' (%3) prerequisite not satisfied, rcode: %4
+A DNS UPDATE prerequisite was not satisfied. The specific prerequisite that
+was not satisfied is shown. The client is sent an error response with the
+given rcode.
+In this case, the specific prerequisite is ''. From RFC2136:
+RRset exists (value independent).  At least one RR with a
+specified NAME and TYPE (in the zone and class specified by
+the Zone Section) must exist.
+
 % LIBDDNS_UPDATE_ERROR update client %1 for zone %2: %3
 Debug message.  An error is found in processing a dynamic update
 request.  This log message is used for general errors that are not
@@ -46,4 +120,3 @@ that one of the prerequisites was not satisfied. The result code
 should give more information on what prerequisite type failed.
 If the result code is FORMERR, the prerequisite section was not well-formed.
 An error response with the given result code is sent back to the client.
-

src/lib/python/isc/ddns/logger.py

@@ -75,3 +75,25 @@ class ZoneFormatter:
         if self.__zname is None:
             return '(zone unknown/not determined)'
         return self.__zname.to_text(True) + '/' + self.__zclass.to_text()
+
+class RRsetFormatter:
+    """A utility class to convert rrsets to a short descriptive string.
+
+    This class is constructed with an rrset (isc.dns.RRset object).
+    Its text conversion method (__str__) converts it into a string
+    with only the name, class and type of the rrset.
+    This is used in logging so that the RRset can be identified, without
+    being completely printed, which would result in an unnecessary
+    multi-line message.
+
+    This class is designed to delay the conversion until it's explicitly
+    requested, so the conversion doesn't happen if the corresponding log
+    message is suppressed because of its log level.
+    """
+    def __init__(self, rrset):
+        self.__rrset = rrset
+
+    def __str__(self):
+        return self.__rrset.get_name().to_text() + " " +\
+               self.__rrset.get_class().to_text() + " " +\
+               self.__rrset.get_type().to_text()

src/lib/python/isc/ddns/session.py

@@ -16,7 +16,8 @@
 from isc.dns import *
 import isc.ddns.zone_config
 from isc.log import *
-from isc.ddns.logger import logger, ClientFormatter, ZoneFormatter
+from isc.ddns.logger import logger, ClientFormatter, ZoneFormatter,\
+                            RRsetFormatter
 from isc.log_messages.libddns_messages import *
 
 # Result codes for UpdateSession.handle()
@@ -126,9 +127,6 @@ class UpdateSession:
             prereq_result = self.__check_prerequisites(datasrc_client,
                                                        zname, zclass)
             if prereq_result != Rcode.NOERROR():
-                logger.info(LIBDDNS_UPDATE_PREREQUISITE_FAILED,
-                            ClientFormatter(self.__client_addr),
-                            zname, prereq_result)
                 self.__make_response(prereq_result)
                 return UPDATE_ERROR, zname, zclass
             # self.__check_update_acl()
@@ -195,7 +193,7 @@ class UpdateSession:
         self.__message.clear_section(SECTION_ZONE)
         self.__message.set_rcode(rcode)
 
-    def __check_prerequisite_rrset_exists(self, datasrc_client, rrset):
+    def __prereq_rrset_exists(self, datasrc_client, rrset):
         '''Check whether an rrset with the given name and type exists. Class,
            TTL, and Rdata (if any) of the given RRset are ignored.
            RFC2136 Section 2.4.1.
@@ -205,14 +203,15 @@ class UpdateSession:
                                    finder.NO_WILDCARD | finder.FIND_GLUE_OK)
         return result == finder.SUCCESS
 
-    def __check_prerequisite_rrset_exists_value(self, datasrc_client, rrset):
+    def __prereq_rrset_exists_value(self, datasrc_client, rrset):
         '''Check whether an rrset that matches name, type, and rdata(s) of the
            given rrset exists.
            RFC2136 Section 2.4.2
         '''
         _, finder = datasrc_client.find_zone(rrset.get_name())
         result, found_rrset, _ = finder.find(rrset.get_name(), rrset.get_type(),
-                                             finder.NO_WILDCARD | finder.FIND_GLUE_OK)
+                                             finder.NO_WILDCARD |
+                                             finder.FIND_GLUE_OK)
         if result == finder.SUCCESS and\
            rrset.get_name() == found_rrset.get_name() and\
            rrset.get_type() == found_rrset.get_type():
@@ -228,14 +227,14 @@ class UpdateSession:
             return len(found_rdata) == 0
         return False
 
-    def __check_prerequisite_rrset_does_not_exist(self, datasrc_client, rrset):
+    def __prereq_rrset_does_not_exist(self, datasrc_client, rrset):
         '''Check whether no rrsets with the same name and type as the given
            rrset exist.
            RFC2136 Section 2.4.3.
         '''
-        return not self.__check_prerequisite_rrset_exists(datasrc_client, rrset)
+        return not self.__prereq_rrset_exists(datasrc_client, rrset)
 
-    def __check_prerequisite_name_in_use(self, datasrc_client, rrset):
+    def __prereq_name_in_use(self, datasrc_client, rrset):
         '''Check whether the name of the given RRset is in use (i.e. has
            1 or more RRs).
            RFC2136 Section 2.4.4
@@ -249,12 +248,12 @@ class UpdateSession:
             return True
         return False
 
-    def __check_prerequisite_name_not_in_use(self, datasrc_client, rrset):
+    def __prereq_name_not_in_use(self, datasrc_client, rrset):
         '''Check whether the name of the given RRset is not in use (i.e. does
            not exist at all, or is an empty nonterminal.
            RFC2136 Section 2.4.5.
         '''
-        return not self.__check_prerequisite_name_in_use(datasrc_client, rrset)
+        return not self.__prereq_name_in_use(datasrc_client, rrset)
 
     def __check_prerequisites(self, datasrc_client, zname, zclass):
         '''Check the prerequisites section of the UPDATE Message.
@@ -264,36 +263,86 @@ class UpdateSession:
             relation = rrset.get_name().compare(zname).get_relation()
             if relation != NameComparisonResult.SUBDOMAIN and\
                relation != NameComparisonResult.EQUAL:
-                return NOTZONE
+                logger.info(LIBDDNS_PREREQ_NOTZONE,
+                            ClientFormatter(self.__client_addr),
+                            ZoneFormatter(zname, zclass),
+                            RRsetFormatter(rrset))
+                return Rcode.NOTZONE()
 
             # Algorithm taken from RFC2136 Section 3.2
             if rrset.get_class() == RRClass.ANY():
                 if rrset.get_ttl().get_value() != 0 or\
                    rrset.get_rdata_count() != 0:
+                    logger.info(LIBDDNS_PREREQ_FORMERR_ANY,
+                                ClientFormatter(self.__client_addr),
+                                ZoneFormatter(zname, zclass),
+                                RRsetFormatter(rrset))
                     return Rcode.FORMERR()
                 elif rrset.get_type() == RRType.ANY():
-                    if not self.__check_prerequisite_name_in_use(datasrc_client, rrset):
-                        return Rcode.NXDOMAIN()
+                    if not self.__prereq_name_in_use(datasrc_client,
+                                                     rrset):
+                        rcode = Rcode.NXDOMAIN()
+                        logger.info(LIBDDNS_PREREQ_NAME_IN_USE_FAILED,
+                                    ClientFormatter(self.__client_addr),
+                                    ZoneFormatter(zname, zclass),
+                                    RRsetFormatter(rrset), rcode)
+                        return rcode
                 else:
-                    if not self.__check_prerequisite_rrset_exists(datasrc_client, rrset):
-                        return Rcode.NXRRSET()
+                    if not self.__prereq_rrset_exists(datasrc_client, rrset):
+                        rcode = Rcode.NXRRSET()
+                        logger.info(LIBDDNS_PREREQ_RRSET_EXISTS_FAILED,
+                                    ClientFormatter(self.__client_addr),
+                                    ZoneFormatter(zname, zclass),
+                                    RRsetFormatter(rrset), rcode)
+                        return rcode
             elif rrset.get_class() == RRClass.NONE():
                 if rrset.get_ttl().get_value() != 0 or\
                    rrset.get_rdata_count() != 0:
+                    logger.info(LIBDDNS_PREREQ_FORMERR_NONE,
+                                ClientFormatter(self.__client_addr),
+                                ZoneFormatter(zname, zclass),
+                                RRsetFormatter(rrset))
                     return Rcode.FORMERR()
                 elif rrset.get_type() == RRType.ANY():
-                    if not self.__check_prerequisite_name_not_in_use(datasrc_client, rrset):
-                        return Rcode.YXDOMAIN()
+                    if not self.__prereq_name_not_in_use(datasrc_client,
+                                                         rrset):
+                        rcode = Rcode.YXDOMAIN()
+                        logger.info(LIBDDNS_PREREQ_NAME_NOT_IN_USE_FAILED,
+                                    ClientFormatter(self.__client_addr),
+                                    ZoneFormatter(zname, zclass),
+                                    RRsetFormatter(rrset), rcode)
+                        return rcode
                 else:
-                    if not self.__check_prerequisite_rrset_does_not_exist(datasrc_client, rrset):
-                        return Rcode.YXRRSET()
+                    if not self.__prereq_rrset_does_not_exist(datasrc_client,
+                                                              rrset):
+                        rcode = Rcode.YXRRSET()
+                        logger.info(LIBDDNS_PREREQ_RRSET_DOES_NOT_EXIST_FAILED,
+                                    ClientFormatter(self.__client_addr),
+                                    ZoneFormatter(zname, zclass),
+                                    RRsetFormatter(rrset), rcode)
+                        return rcode
             elif rrset.get_class() == zclass:
                 if rrset.get_ttl().get_value() != 0:
+                    logger.info(LIBDDNS_PREREQ_FORMERR,
+                                ClientFormatter(self.__client_addr),
+                                ZoneFormatter(zname, zclass),
+                                RRsetFormatter(rrset))
                     return Rcode.FORMERR()
                 else:
-                    if not self.__check_prerequisite_rrset_exists_value(datasrc_client, rrset):
-                        return Rcode.NXRRSET()
+                    if not self.__prereq_rrset_exists_value(datasrc_client,
+                                                            rrset):
+                        rcode = Rcode.NXRRSET()
+                        logger.info(LIBDDNS_PREREQ_RRSET_EXISTS_VAL_FAILED,
+                                    ClientFormatter(self.__client_addr),
+                                    ZoneFormatter(zname, zclass),
+                                    RRsetFormatter(rrset), rcode)
+                        return rcode
             else:
+                logger.info(LIBDDNS_PREREQ_FORMERR_CLASS,
+                            ClientFormatter(self.__client_addr),
+                            ZoneFormatter(zname, zclass),
+                            RRsetFormatter(rrset))
                 return Rcode.FORMERR()
 
+        # All prerequisites are satisfied
         return Rcode.NOERROR()

src/lib/python/isc/ddns/tests/session_tests.py

@@ -160,7 +160,7 @@ class SessionTest(unittest.TestCase):
            test code cleaner).
         '''
         self.assertEqual(expected,
-            self.__session._UpdateSession__check_prerequisite_rrset_exists(
+            self.__session._UpdateSession__prereq_rrset_exists(
                             client, rrset))
 
     def __check_prerequisite_exists_value(self, expected, client, rrset):
@@ -169,8 +169,7 @@ class SessionTest(unittest.TestCase):
         '''
         self.assertEqual(expected,
             self.__session.
-                 _UpdateSession__check_prerequisite_rrset_exists_value(client,
-                                                                       rrset))
+                 _UpdateSession__prereq_rrset_exists_value(client, rrset))
 
     def __check_prerequisite_does_not_exist(self, expected, client, rrset):
         '''Similar to __check_prerequisite_exists(), but for checking
@@ -178,8 +177,7 @@ class SessionTest(unittest.TestCase):
         '''
         self.assertEqual(expected,
             self.__session.
-                _UpdateSession__check_prerequisite_rrset_does_not_exist(client,
-                                                                        rrset))
+                _UpdateSession__prereq_rrset_does_not_exist(client, rrset))
 
     def __check_prerequisite_name_in_use(self, expected, client, rrset):
         '''Similar to __check_prerequisite_exists(), but for checking
@@ -187,8 +185,7 @@ class SessionTest(unittest.TestCase):
         '''
         self.assertEqual(expected,
             self.__session.
-                 _UpdateSession__check_prerequisite_name_in_use(client,
-                                                                rrset))
+                 _UpdateSession__prereq_name_in_use(client, rrset))
 
     def __check_prerequisite_name_not_in_use(self, expected, client, rrset):
         '''Similar to __check_prerequisite_exists(), but for checking
@@ -196,8 +193,7 @@ class SessionTest(unittest.TestCase):
         '''
         self.assertEqual(expected,
             self.__session.
-                 _UpdateSession__check_prerequisite_name_not_in_use(client,
-                                                                    rrset))
+                 _UpdateSession__prereq_name_not_in_use(client, rrset))
 
     def test_check_prerequisite_exists(self):
         # Basic existence checks