[rac744] Logging for in-memory data source

src/lib/datasrc/logger.h

@@ -35,7 +35,9 @@ enum {
     /// \brief Trace basic operations
     DBG_TRACE_BASIC = 10,
     /// \brief Trace data changes and lookups as well
-    DBG_TRACE_DATA = 20
+    DBG_TRACE_DATA = 20,
+    /// \brief Detailed even about how the lookups happen
+    DBG_TRACE_DETAILED = 50
 };
 
 }

src/lib/datasrc/memory_datasrc.cc

@@ -24,6 +24,7 @@
 
 #include <datasrc/memory_datasrc.h>
 #include <datasrc/rbtree.h>
+#include <datasrc/logger.h>
 
 using namespace std;
 using namespace isc::dns;
@@ -94,6 +95,10 @@ struct MemoryZone::MemoryZoneImpl {
              l > origin_labels;
              --l, wname = wname.split(1)) {
             if (wname.isWildcard()) {
+                if (logger.isDebugEnabled(DBG_TRACE_DATA)) {
+                    logger.debug(DBG_TRACE_DATA, DATASRC_MEM_ADD_WILDCARD,
+                                 name.toText().c_str());
+                }
                 // Ensure a separate level exists for the "wildcarding" name,
                 // and mark the node as "wild".
                 DomainNode* node;
@@ -130,10 +135,14 @@ struct MemoryZone::MemoryZoneImpl {
             // (depending on how we support DNSSEC).  We should revisit it
             // at that point.
             if (!domain->empty()) {
+                logger.error(DATASRC_MEM_CNAME_TO_NONEMPTY,
+                             rrset->getName().toText().c_str());
                 isc_throw(AddError, "CNAME can't be added with other data for "
                           << rrset->getName());
             }
         } else if (domain->find(RRType::CNAME()) != domain->end()) {
+            logger.error(DATASRC_MEM_CNAME_COEXIST,
+                         rrset->getName().toText().c_str());
             isc_throw(AddError, "CNAME and " << rrset->getType() <<
                       " can't coexist for " << rrset->getName());
         }
@@ -151,6 +160,8 @@ struct MemoryZone::MemoryZoneImpl {
             (rrset->getType() == RRType::NS() &&
             domain->find(RRType::DNAME()) != domain->end())))
         {
+            logger.error(DATASRC_MEM_DNAME_NS,
+                         rrset->getName().toText().c_str());
             isc_throw(AddError, "DNAME can't coexist with NS in non-apex "
                 "domain " << rrset->getName());
         }
@@ -172,6 +183,9 @@ struct MemoryZone::MemoryZoneImpl {
             // XXX: this is not only for CNAME or DNAME. We should generalize
             // this code for all other "singleton RR types" (such as SOA) in a
             // separate task.
+            logger.error(DATASRC_MEM_SINGLETON,
+                         rrset->getName().toText().c_str(),
+                         rrset->getType().toText().c_str());
             isc_throw(AddError, "multiple RRs of singleton type for "
                       << rrset->getName());
         }
@@ -180,6 +194,9 @@ struct MemoryZone::MemoryZoneImpl {
         if (compare.getRelation() != NameComparisonResult::SUPERDOMAIN &&
             compare.getRelation() != NameComparisonResult::EQUAL)
         {
+            logger.error(DATASRC_MEM_OUT_OF_ZONE,
+                         rrset->getName().toText().c_str(),
+                         origin_.toText().c_str());
             isc_throw(OutOfZone, "The name " << rrset->getName() <<
                 " is not contained in zone " << origin_);
         }
@@ -194,10 +211,14 @@ struct MemoryZone::MemoryZoneImpl {
         // behavior.
         if (rrset->getName().isWildcard()) {
             if (rrset->getType() == RRType::NS()) {
+                logger.error(DATASRC_MEM_WILDCARD_NS,
+                             rrset->getName().toText().c_str());
                 isc_throw(AddError, "Invalid NS owner name (wildcard): " <<
                           rrset->getName());
             }
             if (rrset->getType() == RRType::DNAME()) {
+                logger.error(DATASRC_MEM_WILDCARD_DNAME,
+                             rrset->getName().toText().c_str());
                 isc_throw(AddError, "Invalid DNAME owner name (wildcard): " <<
                           rrset->getName());
             }
@@ -210,6 +231,12 @@ struct MemoryZone::MemoryZoneImpl {
      */
     // Implementation of MemoryZone::add
     result::Result add(const ConstRRsetPtr& rrset, DomainTree* domains) {
+        if (logger.isDebugEnabled(DBG_TRACE_DATA)) {
+            logger.debug(DBG_TRACE_DATA, DATASRC_MEM_ADD_RRSET,
+                         rrset->getName().toText().c_str(),
+                         rrset->getType().toText().c_str(),
+                         origin_.toText().c_str());
+        }
         // Sanitize input
         addValidation(rrset);
 
@@ -271,6 +298,9 @@ struct MemoryZone::MemoryZoneImpl {
     void addFromLoad(const ConstRRsetPtr& set, DomainTree* domains) {
             switch (add(set, domains)) {
                 case result::EXIST:
+                    logger.error(DATASRC_MEM_DUP_RRSET,
+                                 set->getName().toText().c_str(),
+                                 set->getType().toText().c_str());
                     isc_throw(dns::MasterLoadError, "Duplicate rrset: " <<
                         set->toText());
                 case result::SUCCESS:
@@ -307,6 +337,7 @@ struct MemoryZone::MemoryZoneImpl {
         const Domain::const_iterator foundDNAME(node.getData()->find(
             RRType::DNAME()));
         if (foundDNAME != node.getData()->end()) {
+            logger.debug(DBG_TRACE_DETAILED, DATASRC_MEM_DNAME_ENCOUNTERED);
             state->dname_node_ = &node;
             state->rrset_ = foundDNAME->second;
             // No more processing below the DNAME (RFC 2672, section 3
@@ -328,6 +359,8 @@ struct MemoryZone::MemoryZoneImpl {
                 return (false);
             }
 
+            logger.debug(DBG_TRACE_DETAILED, DATASRC_MEM_NS_ENCOUNTERED);
+
             // BIND 9 checks if this node is not the origin.  That's probably
             // because it can support multiple versions for dynamic updates
             // and IXFR, and it's possible that the callback is called at
@@ -363,6 +396,11 @@ struct MemoryZone::MemoryZoneImpl {
         rrset, bool rename)
     {
         if (rename) {
+            if (logger.isDebugEnabled(DBG_TRACE_DETAILED)) {
+                logger.debug(DBG_TRACE_DETAILED, DATASRC_MEM_RENAME,
+                             rrset->getName().toText().c_str(),
+                             name.toText().c_str());
+            }
             /*
              * We lose a signature here. But it would be wrong anyway, because
              * the name changed. This might turn out to be unimportant in
@@ -385,6 +423,10 @@ struct MemoryZone::MemoryZoneImpl {
     FindResult find(const Name& name, RRType type,
                     RRsetList* target, const FindOptions options) const
     {
+        if (logger.isDebugEnabled(DBG_TRACE_BASIC)) {
+            logger.debug(DBG_TRACE_BASIC, DATASRC_MEM_FIND,
+                         name.toText().c_str(), type.toText().c_str());
+        }
         // Get the node
         DomainNode* node(NULL);
         FindState state(options);
@@ -411,12 +453,20 @@ struct MemoryZone::MemoryZoneImpl {
                  * is NULL.
                  */
                 if (state.dname_node_ != NULL) {
+                    if (logger.isDebugEnabled(DBG_TRACE_DATA)) {
+                        logger.debug(DBG_TRACE_DATA, DATASRC_MEM_DNAME_FOUND,
+                                     state.rrset_->getName().toText().c_str());
+                    }
                     // We were traversing a DNAME node (and wanted to go
                     // lower below it), so return the DNAME
                     return (FindResult(DNAME, prepareRRset(name, state.rrset_,
                         rename)));
                 }
                 if (state.zonecut_node_ != NULL) {
+                    if (logger.isDebugEnabled(DBG_TRACE_DATA)) {
+                        logger.debug(DBG_TRACE_DATA, DATASRC_MEM_DELEG_FOUND,
+                                     state.rrset_->getName().toText().c_str());
+                    }
                     return (FindResult(DELEGATION, prepareRRset(name,
                         state.rrset_, rename)));
                 }
@@ -426,6 +476,7 @@ struct MemoryZone::MemoryZoneImpl {
                 // the zone but is empty.  Treat it as NXRRSET.
                 if (node_path.getLastComparisonResult().getRelation() ==
                     NameComparisonResult::SUPERDOMAIN) {
+                    logger.debug(DBG_TRACE_DATA, DATASRC_MEM_SUPER_STOP);
                     return (FindResult(NXRRSET, ConstRRsetPtr()));
                 }
 
@@ -463,6 +514,8 @@ struct MemoryZone::MemoryZoneImpl {
                     if (node_path.getLastComparisonResult().getRelation() ==
                         NameComparisonResult::COMMONANCESTOR && node_path.
                         getLastComparisonResult().getCommonLabels() > 1) {
+                        logger.debug(DBG_TRACE_DATA,
+                                     DATASRC_MEM_WILDCARD_CANCEL);
                         return (FindResult(NXDOMAIN, ConstRRsetPtr()));
                     }
                     Name wildcard(Name("*").concatenate(
@@ -485,6 +538,7 @@ struct MemoryZone::MemoryZoneImpl {
 
                 // fall through
             case DomainTree::NOTFOUND:
+                logger.debug(DBG_TRACE_DATA, DATASRC_MEM_NOTFOUND);
                 return (FindResult(NXDOMAIN, ConstRRsetPtr()));
             case DomainTree::EXACTMATCH: // This one is OK, handle it
                 break;
@@ -496,6 +550,7 @@ struct MemoryZone::MemoryZoneImpl {
         // If there is an exact match but the node is empty, it's equivalent
         // to NXRRSET.
         if (node->isEmpty()) {
+            logger.debug(DBG_TRACE_DATA, DATASRC_MEM_DOMAIN_EMPTY);
             return (FindResult(NXRRSET, ConstRRsetPtr()));
         }
 
@@ -506,6 +561,7 @@ struct MemoryZone::MemoryZoneImpl {
         if (node->getFlag(DomainNode::FLAG_CALLBACK) && node != origin_data_) {
             found = node->getData()->find(RRType::NS());
             if (found != node->getData()->end()) {
+                logger.debug(DBG_TRACE_DATA, DATASRC_MEM_EXACT_DELEGATION);
                 return (FindResult(DELEGATION, prepareRRset(name,
                     found->second, rename)));
             }
@@ -521,23 +577,27 @@ struct MemoryZone::MemoryZoneImpl {
                     boost::const_pointer_cast<RRset>(prepareRRset(name,
                     found->second, rename)));
             }
+            logger.debug(DBG_TRACE_DATA, DATASRC_MEM_ANY_SUCCESS);
             return (FindResult(SUCCESS, ConstRRsetPtr()));
         }
 
         found = node->getData()->find(type);
         if (found != node->getData()->end()) {
             // Good, it is here
+            logger.debug(DBG_TRACE_DATA, DATASRC_MEM_SUCCESS);
             return (FindResult(SUCCESS, prepareRRset(name, found->second,
                 rename)));
         } else {
             // Next, try CNAME.
             found = node->getData()->find(RRType::CNAME());
             if (found != node->getData()->end()) {
+                logger.debug(DBG_TRACE_DATA, DATASRC_MEM_CNAME);
                 return (FindResult(CNAME, prepareRRset(name, found->second,
                     rename)));
             }
         }
         // No exact match or CNAME.  Return NXRRSET.
+        logger.debug(DBG_TRACE_DATA, DATASRC_MEM_NXRRSET);
         return (FindResult(NXRRSET, ConstRRsetPtr()));
     }
 };
@@ -545,9 +605,19 @@ struct MemoryZone::MemoryZoneImpl {
 MemoryZone::MemoryZone(const RRClass& zone_class, const Name& origin) :
     impl_(new MemoryZoneImpl(zone_class, origin))
 {
+    if (logger.isDebugEnabled(DBG_TRACE_BASIC)) {
+        logger.debug(DBG_TRACE_BASIC, DATASRC_MEM_CREATE,
+                     origin.toText().c_str(),
+                     zone_class.toText().c_str());
+    }
 }
 
 MemoryZone::~MemoryZone() {
+    if (logger.isDebugEnabled(DBG_TRACE_BASIC)) {
+        logger.debug(DBG_TRACE_BASIC, DATASRC_MEM_DESTROY,
+                     getOrigin().toText().c_str(),
+                     getClass().toText().c_str());
+    }
     delete impl_;
 }
 
@@ -576,6 +646,11 @@ MemoryZone::add(const ConstRRsetPtr& rrset) {
 
 void
 MemoryZone::load(const string& filename) {
+    if (logger.isDebugEnabled(DBG_TRACE_BASIC)) {
+        logger.debug(DBG_TRACE_BASIC, DATASRC_MEM_LOAD,
+                     getOrigin().toText().c_str(),
+                     filename.c_str());
+    }
     // Load it into a temporary tree
     MemoryZoneImpl::DomainTree tmp;
     masterLoad(filename.c_str(), getOrigin(), getClass(),
@@ -588,6 +663,11 @@ MemoryZone::load(const string& filename) {
 
 void
 MemoryZone::swap(MemoryZone& zone) {
+    if (logger.isDebugEnabled(DBG_TRACE_DATA)) {
+        logger.debug(DBG_TRACE_BASIC, DATASRC_MEM_SWAP,
+                     getOrigin().toText().c_str(),
+                     zone.getOrigin().toText().c_str());
+    }
     std::swap(impl_, zone.impl_);
 }
 
@@ -628,6 +708,12 @@ MemoryDataSrc::addZone(ZonePtr zone) {
                   "Null pointer is passed to MemoryDataSrc::addZone()");
     }
 
+    if (logger.isDebugEnabled(DBG_TRACE_BASIC)) {
+        logger.debug(DBG_TRACE_BASIC, DATASRC_MEM_ADD_ZONE,
+                     zone->getOrigin().toText().c_str(),
+                     zone->getClass().toText().c_str());
+    }
+
     const result::Result result = impl_->zone_table.addZone(zone);
     if (result == result::SUCCESS) {
         ++impl_->zone_count;
@@ -637,6 +723,10 @@ MemoryDataSrc::addZone(ZonePtr zone) {
 
 MemoryDataSrc::FindResult
 MemoryDataSrc::findZone(const isc::dns::Name& name) const {
+    if (logger.isDebugEnabled(DBG_TRACE_DATA)) {
+        logger.debug(DBG_TRACE_DATA, DATASRC_MEM_FIND_ZONE,
+                     name.toText().c_str());
+    }
     return (FindResult(impl_->zone_table.findZone(name).code,
                        impl_->zone_table.findZone(name).zone));
 }

src/lib/datasrc/messagedef.mes

@@ -273,3 +273,136 @@ META_ADD_CLASS_MISMATCH Mismatch between classes '%s' and '%s'
 META_REMOVE Removing data source from meta data source
 + Debug information. We take a data source out of meta data source (probably
 + at shutdown or reconfiguration).
+
+MEM_ADD_WILDCARD Adding wildcards for '%s'
++ Debug information. We need some special marks above each * in wildcard name
++ in the in-memory data source. We are adding the marks for this name now.
+
+MEM_CNAME_TO_NONEMPTY Can't add CNAME to domain with other data in '%s'
++ Someone or something tried to add a CNAME into a domain that already contains
++ some other data. But the protocol forbids coexistence of CNAME with anything
++ (RFC 1034, section 3.6.2). This indicates a problem with provided data.
+
+MEM_CNAME_COEXIST Can't add data to CNAME in domain '%s'
++ This is the same problem as in MEM_CNAME_TO_NONEMPTY, but it happened the
++ other way around -- adding some outher data to CNAME.
+
+MEM_DNAME_NS DNAME and NS can't coexist in non-apex domain '%s'
++ It was requested for DNAME and NS records to be put into the same domain
++ which is not the apex (the top of the zone). This is forbidden by RFC
++ 2672, section 3. This indicates a problem with provided data.
+
+MEM_SINGLETON Trying to add multiple RRs for domain '%s' and type '%s'
++ Some resource types are singletons -- only one is allowed in a domain
++ (for example CNAME or SOA). This indicates a problem with provided data.
+
+MEM_OUT_OF_ZONE Domain '%s' doesn't belong to zone '%s'
++ It was attempted to add the domain into a zone that shouldn't have it
++ (eg. the domain is not subdomain of the zone origin). This indicates a
++ problem with provided data.
+
+MEM_WILDCARD_NS NS record in wildcard domain '%s'
++ We refuse to load NS record into a wildcard domain. It is'n explicitly
++ forbidden, but the protocol is ambiguous about how this should behave and
++ bind 9 refuses that as well. We don't like your zone, please describe it
++ using different tools.
+
+MEM_WILDCARD_DNAME DNAME record in wildcard domain '%s'
++ We refuse to load DNAME record into a wildcard domain. It is'n explicitly
++ forbidden, but the protocol is ambiguous about how this should behave and
++ bind 9 refuses that as well. We don't like your zone, please describe it
++ using different tools.
+
+MEM_ADD_RRSET Adding RRset '%s/%s' into zone '%s'
++ Debug information. We're adding an RRset to the zone of in-memory data
++ source.
+
+MEM_DUP_RRSET Duplicate rrset '%s/%s'
++ An RRset is being inserted into in-memory data source for a second time.
++ The original version must be removed first. Note that we don't support
++ loading master files where an RRset is split into multiple locations yet.
+
+MEM_DNAME_ENCOUNTERED Encountered a DNAME
++ Debug information. While searching for the requested domain, we encountered
++ a DNAME on the way. This may lead to redirection to a different domain and
++ stop the search.
+
+MEM_NS_ENCOUNTERED Encountered a NS
++ Debug information. While searching for the requested domain, we encountered
++ a NS on the way (a delegation). This may lead to stop of the search.
+
+MEM_RENAME Renaming rrset from '%s' to '%s'
++ Debug information. We generate an RRset from a different RRset (most probably
++ a wildcard). So we need to rename it to whatever the user asked for. In fact,
++ we can't rename RRset (it's not possible with our libraries), so we create
++ a new one and copy everything.
+
+MEM_FIND Find '%s/%s'
++ Debug information. We're going to search the in-memory data source to find
++ requestet RRset.
+
+MEM_DNAME_FOUND DNAME found at '%s'
++ Debug information. We found a DNAME instead of the requested record.
+
+MEM_DELEG_FOUND Delegation found at '%s'
++ Debug information. We found a delegation point above the requested record.
+
+MEM_SUPER_STOP Stopped at superdomain, domain is empty
++ Debug information. The search stopped at a superdomain of the requested
++ domain. The domain is a empty nonterminal, therefore we treat it as NXRRSET
++ case (eg. the domain exists, but it doesn't have the requested record type).
+
+MEM_WILDCARD_CANCEL Wildcard match canceled
++ Debug information. We reached a domain above wildcard, but there's something
++ below the requested domain. Therefore the wildcard doesn't apply here.
++ This behaviour is specified by RFC 1034, section 4.3.3
+
+MEM_NOTFOUND Requested domain not found
++ Debug information. The requested domain does not exist.
+
+MEM_DOMAIN_EMPTY Requested domain is empty
++ Debug information. The requested domain exists in the tree of domains, but
++ it is empty. Therefore it doesn't contain the requested resource type.
+
+MEM_EXACT_DELEGATION Delegation at the exact domain
++ Debug information. There's a NS record at the requested domain. This means
++ this zone is not authoritative for the requested domain, but a delegation
++ should be followed. The requested domain is an apex of some zone.
+
+MEM_ANY_SUCCESS ANY query successful
++ Debug information. The domain was found and we answer an ANY type query by
++ providing everything we found inside the domain.
+
+MEM_SUCCESS Query successful
++ Debug information. We found the record we searched for.
+
+MEM_CNAME CNAME at the domain
++ Debug information. The requested domain is an alias to a different domain,
++ returning the CNAME instead.
+
+MEM_NXRRSET No such type
++ Debug information. The domain exists, but it doesn't hold any record of the
++ requested type.
+
+MEM_CREATE Creating zone '%s' in '%s' class
++ Debug information. We're creating representation of a zone for the in-memory
++ data source.
+
+MEM_DESTROY Destroying zone '%s' in '%s' class
++ Debug information. We're destroying the representation of zone in the
++ in-memory data source.
+
+MEM_LOAD Loading zone '%s' from file '%s'
++ Debug information. We're loading the content of zone from a master file.
+
+MEM_SWAP Swapping contents of two zone representations ('%s' and '%s')
++ Debug information. We exchange contents of the zones. This is usual practice
++ to do some manipulation in exception-safe manner -- we prepare the new data
++ in a different zone object and when it works, we swap it with the old, then
++ we can safely destroy the old one.
+
+MEM_ADD_ZONE Adding zone '%s/%s'
++ Debug information. We're adding this zone into the in-memory data source.
+
+MEM_FIND_ZONE Looking for zone '%s'
++ Debug information. We're looking for a zone in the in-memory data source.