BIND 10 master, updated. c05781723ac006e4d193d9181bf46ccec998a5b0 Merge branch 'work/log/cache'

BIND 10 source code commits bind10-changes at lists.isc.org
Thu Jul 7 14:32:20 UTC 2011


The branch, master has been updated
       via  c05781723ac006e4d193d9181bf46ccec998a5b0 (commit)
       via  3ac41521c2a1cbc43e3b6e0979eee46b6c45fa63 (commit)
       via  d77fde1d390e921740df739699dc03b48777f81a (commit)
       via  0042b37bdc4e3929faf3d2b7862dd79979d60aa0 (commit)
       via  756a7d1a0816670445219db901364074b79f158a (commit)
       via  1a915fef55d9902cb4e0c5d077e9c602101419dc (commit)
       via  dbe54369eb40d9ba95b8fd77859a243f076b5966 (commit)
       via  46e6d4b1702e5c30c8bcd33e7fc73733872bc620 (commit)
       via  612a96ab3eea34e232fd97e834599745401b73eb (commit)
       via  b9755c94e619471f8d9769c7c0d230c1e40b9584 (commit)
       via  a91e1274bc7cd044b9e6c254a100a0aff73dcc2b (commit)
      from  7203d4203cddbb6bf930586e2f3fba183ca12140 (commit)

Those revisions listed above that are new to this repository have
not appeared on any other notification email; so we list those
revisions in full, below.

- Log -----------------------------------------------------------------
commit c05781723ac006e4d193d9181bf46ccec998a5b0
Merge: 7203d4203cddbb6bf930586e2f3fba183ca12140 3ac41521c2a1cbc43e3b6e0979eee46b6c45fa63
Author: Michal 'vorner' Vaner <michal.vaner at nic.cz>
Date:   Thu Jul 7 16:26:10 2011 +0200

    Merge branch 'work/log/cache'

-----------------------------------------------------------------------

Summary of changes:
 src/lib/cache/Makefile.am            |   11 +++-
 src/lib/cache/cache_messages.mes     |  148 ++++++++++++++++++++++++++++++++++
 src/lib/cache/local_zone_data.cc     |    4 +
 src/lib/{datasrc => cache}/logger.cc |    6 +-
 src/lib/{datasrc => cache}/logger.h  |   14 ++--
 src/lib/cache/message_cache.cc       |   20 +++++
 src/lib/cache/message_cache.h        |    2 +-
 src/lib/cache/message_entry.cc       |    5 +-
 src/lib/cache/resolver_cache.cc      |   32 +++++++
 src/lib/cache/rrset_cache.cc         |   27 ++++++-
 src/lib/cache/tests/run_unittests.cc |    4 +
 11 files changed, 256 insertions(+), 17 deletions(-)
 create mode 100644 src/lib/cache/cache_messages.mes
 copy src/lib/{datasrc => cache}/logger.cc (90%)
 copy src/lib/{datasrc => cache}/logger.h (76%)

-----------------------------------------------------------------------
diff --git a/src/lib/cache/Makefile.am b/src/lib/cache/Makefile.am
index bfbe24a..9871a5e 100644
--- a/src/lib/cache/Makefile.am
+++ b/src/lib/cache/Makefile.am
@@ -31,5 +31,14 @@ libcache_la_SOURCES  += cache_entry_key.h cache_entry_key.cc
 libcache_la_SOURCES  += rrset_copy.h rrset_copy.cc
 libcache_la_SOURCES  += local_zone_data.h local_zone_data.cc
 libcache_la_SOURCES  += message_utility.h message_utility.cc
+libcache_la_SOURCES  += logger.h logger.cc
+nodist_libcache_la_SOURCES = cache_messages.cc cache_messages.h
 
-CLEANFILES = *.gcno *.gcda
+BUILT_SOURCES = cache_messages.cc cache_messages.h
+
+cache_messages.cc cache_messages.h: cache_messages.mes
+	$(top_builddir)/src/lib/log/compiler/message $(top_srcdir)/src/lib/cache/cache_messages.mes
+
+CLEANFILES = *.gcno *.gcda cache_messages.cc cache_messages.h
+
+EXTRA_DIST = cache_messages.mes
diff --git a/src/lib/cache/cache_messages.mes b/src/lib/cache/cache_messages.mes
new file mode 100644
index 0000000..2a68cc2
--- /dev/null
+++ b/src/lib/cache/cache_messages.mes
@@ -0,0 +1,148 @@
+# Copyright (C) 2010  Internet Systems Consortium, Inc. ("ISC")
+#
+# Permission to use, copy, modify, and/or distribute this software for any
+# purpose with or without fee is hereby granted, provided that the above
+# copyright notice and this permission notice appear in all copies.
+#
+# THE SOFTWARE IS PROVIDED "AS IS" AND ISC DISCLAIMS ALL WARRANTIES WITH
+# REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY
+# AND FITNESS.  IN NO EVENT SHALL ISC BE LIABLE FOR ANY SPECIAL, DIRECT,
+# INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER RESULTING FROM
+# LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF CONTRACT, NEGLIGENCE
+# OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
+# PERFORMANCE OF THIS SOFTWARE.
+
+$NAMESPACE isc::cache
+
+% CACHE_ENTRY_MISSING_RRSET missing RRset to generate message for %1
+The cache tried to generate the complete answer message. It knows the structure
+of the message, but some of the RRsets to be put there are not in cache (they
+probably expired already). Therefore it pretends the message was not found.
+
+% CACHE_LOCALZONE_FOUND found entry with key %1 in local zone data
+Debug message, noting that the requested data was successfully found in the
+local zone data of the cache.
+
+% CACHE_LOCALZONE_UNKNOWN entry with key %1 not found in local zone data
+Debug message. The requested data was not found in the local zone data.
+
+% CACHE_LOCALZONE_UPDATE updating local zone element at key %1
+Debug message issued when there's update to the local zone section of cache.
+
+% CACHE_MESSAGES_DEINIT deinitialized message cache
+Debug message. It is issued when the server deinitializes the message cache.
+
+% CACHE_MESSAGES_EXPIRED found an expired message entry for %1 in the message cache
+Debug message. The requested data was found in the message cache, but it
+already expired. Therefore the cache removes the entry and pretends it found
+nothing.
+
+% CACHE_MESSAGES_FOUND found a message entry for %1 in the message cache
+Debug message. We found the whole message in the cache, so it can be returned
+to user without any other lookups.
+
+% CACHE_MESSAGES_INIT initialized message cache for %1 messages of class %2
+Debug message issued when a new message cache is issued. It lists the class
+of messages it can hold and the maximum size of the cache.
+
+% CACHE_MESSAGES_REMOVE removing old instance of %1/%2/%3 first
+Debug message. This may follow CACHE_MESSAGES_UPDATE and indicates that, while
+updating, the old instance is being removed prior of inserting a new one.
+
+% CACHE_MESSAGES_UNCACHEABLE not inserting uncacheable message %1/%2/%3
+Debug message, noting that the given message can not be cached. This is because
+there's no SOA record in the message. See RFC 2308 section 5 for more
+information.
+
+% CACHE_MESSAGES_UNKNOWN no entry for %1 found in the message cache
+Debug message. The message cache didn't find any entry for the given key.
+
+% CACHE_MESSAGES_UPDATE updating message entry %1/%2/%3
+Debug message issued when the message cache is being updated with a new
+message. Either the old instance is removed or, if none is found, new one
+is created.
+
+% CACHE_RESOLVER_DEEPEST looking up deepest NS for %1/%2
+Debug message. The resolver cache is looking up the deepest known nameserver,
+so the resolution doesn't have to start from the root.
+
+% CACHE_RESOLVER_INIT_INFO initializing resolver cache for class %1
+Debug message, the resolver cache is being created for this given class. The
+difference from CACHE_RESOLVER_INIT is only in different format of passed
+information, otherwise it does the same.
+
+% CACHE_RESOLVER_INIT initializing resolver cache for class %1
+Debug message. The resolver cache is being created for this given class.
+
+% CACHE_RESOLVER_LOCAL_MSG message for %1/%2 found in local zone data
+Debug message. The resolver cache found a complete message for the user query
+in the zone data.
+
+% CACHE_RESOLVER_LOCAL_RRSET RRset for %1/%2 found in local zone data
+Debug message. The resolver cache found a requested RRset in the local zone
+data.
+
+% CACHE_RESOLVER_LOOKUP_MSG looking up message in resolver cache for %1/%2
+Debug message. The resolver cache is trying to find a message to answer the
+user query.
+
+% CACHE_RESOLVER_LOOKUP_RRSET looking up RRset in resolver cache for %1/%2
+Debug message. The resolver cache is trying to find an RRset (which usually
+originates as internally from resolver).
+
+% CACHE_RESOLVER_NO_QUESTION answer message for %1/%2 has empty question section
+The cache tried to fill in found data into the response message. But it
+discovered the message contains no question section, which is invalid.
+This is likely a programmer error, please submit a bug report.
+
+% CACHE_RESOLVER_UNKNOWN_CLASS_MSG no cache for class %1
+Debug message. While trying to lookup a message in the resolver cache, it was
+discovered there's no cache for this class at all. Therefore no message is
+found.
+
+% CACHE_RESOLVER_UNKNOWN_CLASS_RRSET no cache for class %1
+Debug message. While trying to lookup an RRset in the resolver cache, it was
+discovered there's no cache for this class at all. Therefore no data is found.
+
+% CACHE_RESOLVER_UPDATE_MSG updating message for %1/%2/%3
+Debug message. The resolver is updating a message in the cache.
+
+% CACHE_RESOLVER_UPDATE_RRSET updating RRset for %1/%2/%3
+Debug message. The resolver is updating an RRset in the cache.
+
+% CACHE_RESOLVER_UPDATE_UNKNOWN_CLASS_MSG no cache for class %1
+Debug message. While trying to insert a message into the cache, it was
+discovered that there's no cache for the class of message. Therefore
+the message will not be cached.
+
+% CACHE_RESOLVER_UPDATE_UNKNOWN_CLASS_RRSET no cache for class %1
+Debug message. While trying to insert an RRset into the cache, it was
+discovered that there's no cache for the class of the RRset. Therefore
+the message will not be cached.
+
+% CACHE_RRSET_EXPIRED found expired RRset %1/%2/%3
+Debug message. The requested data was found in the RRset cache. However, it is
+expired, so the cache removed it and is going to pretend nothing was found.
+
+% CACHE_RRSET_INIT initializing RRset cache for %2 RRsets of class %1
+Debug message. The RRset cache to hold at most this many RRsets for the given
+class is being created.
+
+% CACHE_RRSET_LOOKUP looking up %1/%2/%3 in RRset cache
+Debug message. The resolver is trying to look up data in the RRset cache.
+
+% CACHE_RRSET_NOT_FOUND no RRset found for %1/%2/%3
+Debug message which can follow CACHE_RRSET_LOOKUP. This means the data is not
+in the cache.
+
+% CACHE_RRSET_REMOVE_OLD removing old RRset for %1/%2/%3 to make space for new one
+Debug message which can follow CACHE_RRSET_UPDATE. During the update, the cache
+removed an old instance of the RRset to replace it with the new one.
+
+% CACHE_RRSET_UNTRUSTED not replacing old RRset for %1/%2/%3, it has higher trust level
+Debug message which can follow CACHE_RRSET_UPDATE. The cache already holds the
+same RRset, but from more trusted source, so the old one is kept and new one
+ignored.
+
+% CACHE_RRSET_UPDATE updating RRset %1/%2/%3 in the cache
+Debug message. The RRset is updating its data with this given RRset.
diff --git a/src/lib/cache/local_zone_data.cc b/src/lib/cache/local_zone_data.cc
index 61ce35a..13d1d75 100644
--- a/src/lib/cache/local_zone_data.cc
+++ b/src/lib/cache/local_zone_data.cc
@@ -16,6 +16,7 @@
 #include "local_zone_data.h"
 #include "cache_entry_key.h"
 #include "rrset_copy.h"
+#include "logger.h"
 
 using namespace std;
 using namespace isc::dns;
@@ -33,8 +34,10 @@ LocalZoneData::lookup(const isc::dns::Name& name,
     string key = genCacheEntryName(name, type);
     RRsetMapIterator iter = rrsets_map_.find(key);
     if (iter == rrsets_map_.end()) {
+        LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_LOCALZONE_UNKNOWN).arg(key);
         return (RRsetPtr());
     } else {
+        LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_LOCALZONE_FOUND).arg(key);
         return (iter->second);
     }
 }
@@ -43,6 +46,7 @@ void
 LocalZoneData::update(const isc::dns::RRset& rrset) {
     //TODO Do we really need to recreate the rrset again?
     string key = genCacheEntryName(rrset.getName(), rrset.getType());
+    LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_LOCALZONE_UPDATE).arg(key);
     RRset* rrset_copy = new RRset(rrset.getName(), rrset.getClass(),
                                   rrset.getType(), rrset.getTTL());
 
diff --git a/src/lib/cache/logger.cc b/src/lib/cache/logger.cc
new file mode 100644
index 0000000..f4b0f25
--- /dev/null
+++ b/src/lib/cache/logger.cc
@@ -0,0 +1,23 @@
+// Copyright (C) 2011  Internet Systems Consortium, Inc. ("ISC")
+//
+// Permission to use, copy, modify, and/or distribute this software for any
+// purpose with or without fee is hereby granted, provided that the above
+// copyright notice and this permission notice appear in all copies.
+//
+// THE SOFTWARE IS PROVIDED "AS IS" AND ISC DISCLAIMS ALL WARRANTIES WITH
+// REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY
+// AND FITNESS.  IN NO EVENT SHALL ISC BE LIABLE FOR ANY SPECIAL, DIRECT,
+// INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER RESULTING FROM
+// LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF CONTRACT, NEGLIGENCE
+// OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
+// PERFORMANCE OF THIS SOFTWARE.
+
+#include <cache/logger.h>
+
+namespace isc {
+namespace cache {
+
+isc::log::Logger logger("cache");
+
+}
+}
diff --git a/src/lib/cache/logger.h b/src/lib/cache/logger.h
new file mode 100644
index 0000000..8159ed4
--- /dev/null
+++ b/src/lib/cache/logger.h
@@ -0,0 +1,44 @@
+// Copyright (C) 2011  Internet Systems Consortium, Inc. ("ISC")
+//
+// Permission to use, copy, modify, and/or distribute this software for any
+// purpose with or without fee is hereby granted, provided that the above
+// copyright notice and this permission notice appear in all copies.
+//
+// THE SOFTWARE IS PROVIDED "AS IS" AND ISC DISCLAIMS ALL WARRANTIES WITH
+// REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY
+// AND FITNESS.  IN NO EVENT SHALL ISC BE LIABLE FOR ANY SPECIAL, DIRECT,
+// INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER RESULTING FROM
+// LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF CONTRACT, NEGLIGENCE
+// OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
+// PERFORMANCE OF THIS SOFTWARE.
+
+#ifndef __DATASRC_LOGGER_H
+#define __DATASRC_LOGGER_H
+
+#include <log/macros.h>
+#include <cache/cache_messages.h>
+
+/// \file logger.h
+/// \brief Cache library global logger
+///
+/// This holds the logger for the cache library. It is a private header
+/// and should not be included in any publicly used header, only in local
+/// cc files.
+
+namespace isc {
+namespace cache {
+
+/// \brief The logger for this library
+extern isc::log::Logger logger;
+
+enum {
+    /// \brief Trace basic operations
+    DBG_TRACE_BASIC = 10,
+    /// \brief Trace data operations
+    DBG_TRACE_DATA = 40,
+};
+
+}
+}
+
+#endif
diff --git a/src/lib/cache/message_cache.cc b/src/lib/cache/message_cache.cc
index 816ffe3..e141bb5 100644
--- a/src/lib/cache/message_cache.cc
+++ b/src/lib/cache/message_cache.cc
@@ -1,6 +1,7 @@
 // Copyright (C) 2010  Internet Systems Consortium, Inc. ("ISC")
 //
 // Permission to use, copy, modify, and/or distribute this software for any
+//
 // purpose with or without fee is hereby granted, provided that the above
 // copyright notice and this permission notice appear in all copies.
 //
@@ -20,6 +21,7 @@
 #include "message_cache.h"
 #include "message_utility.h"
 #include "cache_entry_key.h"
+#include "logger.h"
 
 namespace isc {
 namespace cache {
@@ -39,11 +41,14 @@ MessageCache::MessageCache(const RRsetCachePtr& rrset_cache,
     message_lru_((3 * cache_size),
                   new HashDeleter<MessageEntry>(message_table_))
 {
+    LOG_DEBUG(logger, DBG_TRACE_BASIC, CACHE_MESSAGES_INIT).arg(cache_size).
+        arg(RRClass(message_class));
 }
 
 MessageCache::~MessageCache() {
     // Destroy all the message entries in the cache.
     message_lru_.clear();
+    LOG_DEBUG(logger, DBG_TRACE_BASIC, CACHE_MESSAGES_DEINIT);
 }
 
 bool
@@ -57,26 +62,38 @@ MessageCache::lookup(const isc::dns::Name& qname,
     if(msg_entry) {
         // Check whether the message entry has expired.
        if (msg_entry->getExpireTime() > time(NULL)) {
+            LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_MESSAGES_FOUND).
+                arg(entry_name);
             message_lru_.touch(msg_entry);
             return (msg_entry->genMessage(time(NULL), response));
         } else {
             // message entry expires, remove it from hash table and lru list.
+            LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_MESSAGES_EXPIRED).
+                arg(entry_name);
             message_table_.remove(entry_key);
             message_lru_.remove(msg_entry);
             return (false);
        }
     }
 
+    LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_MESSAGES_UNKNOWN).arg(entry_name);
     return (false);
 }
 
 bool
 MessageCache::update(const Message& msg) {
     if (!canMessageBeCached(msg)){
+        LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_MESSAGES_UNCACHEABLE).
+            arg((*msg.beginQuestion())->getName()).
+            arg((*msg.beginQuestion())->getType()).
+            arg((*msg.beginQuestion())->getClass());
         return (false);
     }
 
     QuestionIterator iter = msg.beginQuestion();
+    LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_MESSAGES_UPDATE).
+        arg((*iter)->getName()).arg((*iter)->getType()).
+        arg((*iter)->getClass());
     std::string entry_name = genCacheEntryName((*iter)->getName(),
                                                (*iter)->getType());
     HashKey entry_key = HashKey(entry_name, RRClass(message_class_));
@@ -88,6 +105,9 @@ MessageCache::update(const Message& msg) {
     // add the message entry, maybe there is one way to touch it once.
     MessageEntryPtr old_msg_entry = message_table_.get(entry_key);
     if (old_msg_entry) {
+        LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_MESSAGES_REMOVE).
+            arg((*iter)->getName()).arg((*iter)->getType()).
+            arg((*iter)->getClass());
         message_lru_.remove(old_msg_entry);
     }
 
diff --git a/src/lib/cache/message_cache.h b/src/lib/cache/message_cache.h
index 979b814..44d7fd1 100644
--- a/src/lib/cache/message_cache.h
+++ b/src/lib/cache/message_cache.h
@@ -39,7 +39,7 @@ private:
     MessageCache& operator=(const MessageCache& source);
 public:
     /// \param rrset_cache The cache that stores the RRsets that the
-    ///        message entry will points to
+    ///        message entry will point to
     /// \param cache_size The size of message cache.
     /// \param message_class The class of the message cache
     /// \param negative_soa_cache The cache that stores the SOA record
diff --git a/src/lib/cache/message_entry.cc b/src/lib/cache/message_entry.cc
index de4ea89..d9560a6 100644
--- a/src/lib/cache/message_entry.cc
+++ b/src/lib/cache/message_entry.cc
@@ -20,6 +20,7 @@
 #include "message_entry.h"
 #include "message_utility.h"
 #include "rrset_cache.h"
+#include "logger.h"
 
 using namespace isc::dns;
 using namespace std;
@@ -64,7 +65,7 @@ static uint32_t MAX_UINT32 = numeric_limits<uint32_t>::max();
 // tunable.  Values of one to three hours have been found to work well
 // and would make sensible a default.  Values exceeding one day have
 // been found to be problematic. (sec 5, RFC2308)
-// The default value is 3 hourse (10800 seconds)
+// The default value is 3 hours (10800 seconds)
 // TODO:Give an option to let user configure
 static uint32_t MAX_NEGATIVE_CACHE_TTL = 10800;
 
@@ -142,6 +143,8 @@ MessageEntry::genMessage(const time_t& time_now,
         // has expired, if it is, return false.
         vector<RRsetEntryPtr> rrset_entry_vec;
         if (false == getRRsetEntries(rrset_entry_vec, time_now)) {
+            LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_ENTRY_MISSING_RRSET).
+                arg(entry_name_);
             return (false);
         }
 
diff --git a/src/lib/cache/resolver_cache.cc b/src/lib/cache/resolver_cache.cc
index 6602f79..57935c0 100644
--- a/src/lib/cache/resolver_cache.cc
+++ b/src/lib/cache/resolver_cache.cc
@@ -17,6 +17,7 @@
 #include "resolver_cache.h"
 #include "dns/message.h"
 #include "rrset_cache.h"
+#include "logger.h"
 #include <string>
 #include <algorithm>
 
@@ -29,6 +30,7 @@ namespace cache {
 ResolverClassCache::ResolverClassCache(const RRClass& cache_class) :
     cache_class_(cache_class)
 {
+    LOG_DEBUG(logger, DBG_TRACE_BASIC, CACHE_RESOLVER_INIT).arg(cache_class);
     local_zone_data_ = LocalZoneDataPtr(new LocalZoneData(cache_class_.getCode()));
     rrsets_cache_ = RRsetCachePtr(new RRsetCache(RRSET_CACHE_DEFAULT_SIZE,
                                                  cache_class_.getCode()));
@@ -45,6 +47,8 @@ ResolverClassCache::ResolverClassCache(const RRClass& cache_class) :
 ResolverClassCache::ResolverClassCache(const CacheSizeInfo& cache_info) :
     cache_class_(cache_info.cclass)
 {
+    LOG_DEBUG(logger, DBG_TRACE_BASIC, CACHE_RESOLVER_INIT_INFO).
+        arg(cache_class_);
     uint16_t klass = cache_class_.getCode();
     // TODO We should find one way to load local zone data.
     local_zone_data_ = LocalZoneDataPtr(new LocalZoneData(klass));
@@ -69,8 +73,11 @@ ResolverClassCache::lookup(const isc::dns::Name& qname,
                       const isc::dns::RRType& qtype,
                       isc::dns::Message& response) const
 {
+    LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_RESOLVER_LOOKUP_MSG).
+        arg(qname).arg(qtype);
     // message response should has question section already.
     if (response.beginQuestion() == response.endQuestion()) {
+        LOG_ERROR(logger, CACHE_RESOLVER_NO_QUESTION).arg(qname).arg(qtype);
         isc_throw(MessageNoQuestionSection, "Message has no question section");
     }
 
@@ -79,6 +86,8 @@ ResolverClassCache::lookup(const isc::dns::Name& qname,
     // answer section.
     RRsetPtr rrset_ptr = local_zone_data_->lookup(qname, qtype);
     if (rrset_ptr) {
+        LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_RESOLVER_LOCAL_MSG).
+            arg(qname).arg(qtype);
         response.addRRset(Message::SECTION_ANSWER, rrset_ptr);
         return (true);
     }
@@ -91,11 +100,15 @@ isc::dns::RRsetPtr
 ResolverClassCache::lookup(const isc::dns::Name& qname,
                const isc::dns::RRType& qtype) const
 {
+    LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_RESOLVER_LOOKUP_RRSET).
+        arg(qname).arg(qtype);
     // Algorithm:
     // 1. Search in local zone data first,
     // 2. Then do search in rrsets_cache_.
     RRsetPtr rrset_ptr = local_zone_data_->lookup(qname, qtype);
     if (rrset_ptr) {
+        LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_RESOLVER_LOCAL_RRSET).
+            arg(qname).arg(qtype);
         return (rrset_ptr);
     } else {
         RRsetEntryPtr rrset_entry = rrsets_cache_->lookup(qname, qtype);
@@ -109,6 +122,10 @@ ResolverClassCache::lookup(const isc::dns::Name& qname,
 
 bool
 ResolverClassCache::update(const isc::dns::Message& msg) {
+    LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_RESOLVER_UPDATE_MSG).
+        arg((*msg.beginQuestion())->getName()).
+        arg((*msg.beginQuestion())->getType()).
+        arg((*msg.beginQuestion())->getClass());
     return (messages_cache_->update(msg));
 }
 
@@ -130,6 +147,9 @@ ResolverClassCache::updateRRsetCache(const isc::dns::ConstRRsetPtr& rrset_ptr,
 
 bool
 ResolverClassCache::update(const isc::dns::ConstRRsetPtr& rrset_ptr) {
+    LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_RESOLVER_UPDATE_RRSET).
+        arg(rrset_ptr->getName()).arg(rrset_ptr->getType()).
+        arg(rrset_ptr->getClass());
     // First update local zone, then update rrset cache.
     local_zone_data_->update((*rrset_ptr.get()));
     updateRRsetCache(rrset_ptr, rrsets_cache_);
@@ -166,6 +186,8 @@ ResolverCache::lookup(const isc::dns::Name& qname,
     if (cc) {
         return (cc->lookup(qname, qtype, response));
     } else {
+        LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_RESOLVER_UNKNOWN_CLASS_MSG).
+            arg(qclass);
         return (false);
     }
 }
@@ -179,6 +201,8 @@ ResolverCache::lookup(const isc::dns::Name& qname,
     if (cc) {
         return (cc->lookup(qname, qtype));
     } else {
+        LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_RESOLVER_UNKNOWN_CLASS_RRSET).
+            arg(qclass);
         return (RRsetPtr());
     }
 }
@@ -187,6 +211,8 @@ isc::dns::RRsetPtr
 ResolverCache::lookupDeepestNS(const isc::dns::Name& qname,
                                const isc::dns::RRClass& qclass) const
 {
+    LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_RESOLVER_DEEPEST).arg(qname).
+        arg(qclass);
     isc::dns::RRType qtype = RRType::NS();
     ResolverClassCache* cc = getClassCache(qclass);
     if (cc) {
@@ -213,6 +239,9 @@ ResolverCache::update(const isc::dns::Message& msg) {
     if (cc) {
         return (cc->update(msg));
     } else {
+        LOG_DEBUG(logger, DBG_TRACE_DATA,
+                  CACHE_RESOLVER_UPDATE_UNKNOWN_CLASS_MSG).
+            arg((*msg.beginQuestion())->getClass());
         return (false);
     }
 }
@@ -223,6 +252,9 @@ ResolverCache::update(const isc::dns::ConstRRsetPtr& rrset_ptr) {
     if (cc) {
         return (cc->update(rrset_ptr));
     } else {
+        LOG_DEBUG(logger, DBG_TRACE_DATA,
+                  CACHE_RESOLVER_UPDATE_UNKNOWN_CLASS_RRSET).
+            arg(rrset_ptr->getClass());
         return (false);
     }
 }
diff --git a/src/lib/cache/rrset_cache.cc b/src/lib/cache/rrset_cache.cc
index da19b6d..1a5fd48 100644
--- a/src/lib/cache/rrset_cache.cc
+++ b/src/lib/cache/rrset_cache.cc
@@ -14,8 +14,9 @@
 
 #include <config.h>
 
-#include <string>
 #include "rrset_cache.h"
+#include "logger.h"
+#include <string>
 #include <nsas/nsas_entry_compare.h>
 #include <nsas/hash_table.h>
 #include <nsas/hash_deleter.h>
@@ -34,20 +35,28 @@ RRsetCache::RRsetCache(uint32_t cache_size,
     rrset_lru_((3 * cache_size),
                   new HashDeleter<RRsetEntry>(rrset_table_))
 {
+    LOG_DEBUG(logger, DBG_TRACE_BASIC, CACHE_RRSET_INIT).arg(cache_size).
+        arg(RRClass(rrset_class));
 }
 
 RRsetEntryPtr
 RRsetCache::lookup(const isc::dns::Name& qname,
                    const isc::dns::RRType& qtype)
 {
+    LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_RRSET_LOOKUP).arg(qname).
+        arg(qtype).arg(RRClass(class_));
     const string entry_name = genCacheEntryName(qname, qtype);
-    RRsetEntryPtr entry_ptr = rrset_table_.get(HashKey(entry_name, RRClass(class_)));
+
+    RRsetEntryPtr entry_ptr = rrset_table_.get(HashKey(entry_name,
+                                                       RRClass(class_)));
     if (entry_ptr) {
         if (entry_ptr->getExpireTime() > time(NULL)) {
             // Only touch the non-expired rrset entries
             rrset_lru_.touch(entry_ptr);
             return (entry_ptr);
         } else {
+            LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_RRSET_EXPIRED).arg(qname).
+                arg(qtype).arg(RRClass(class_));
             // the rrset entry has expired, so just remove it from
             // hash table and lru list.
             rrset_table_.remove(entry_ptr->hashKey());
@@ -55,19 +64,31 @@ RRsetCache::lookup(const isc::dns::Name& qname,
         }
     }
 
+    LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_RRSET_NOT_FOUND).arg(qname).
+        arg(qtype).arg(RRClass(class_));
     return (RRsetEntryPtr());
 }
 
 RRsetEntryPtr
-RRsetCache::update(const isc::dns::RRset& rrset, const RRsetTrustLevel& level) {
+RRsetCache::update(const isc::dns::RRset& rrset,
+                   const RRsetTrustLevel& level)
+{
+    LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_RRSET_UPDATE).arg(rrset.getName()).
+        arg(rrset.getType()).arg(rrset.getClass());
     // TODO: If the RRset is an NS, we should update the NSAS as well
     // lookup first
     RRsetEntryPtr entry_ptr = lookup(rrset.getName(), rrset.getType());
     if (entry_ptr) {
         if (entry_ptr->getTrustLevel() > level) {
+            LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_RRSET_UNTRUSTED).
+                arg(rrset.getName()).arg(rrset.getType()).
+                arg(rrset.getClass());
             // existed rrset entry is more authoritative, just return it
             return (entry_ptr);
         } else {
+            LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_RRSET_REMOVE_OLD).
+                arg(rrset.getName()).arg(rrset.getType()).
+                arg(rrset.getClass());
             // Remove the old rrset entry from the lru list.
             rrset_lru_.remove(entry_ptr);
         }
diff --git a/src/lib/cache/tests/run_unittests.cc b/src/lib/cache/tests/run_unittests.cc
index b75fc06..370bc69 100644
--- a/src/lib/cache/tests/run_unittests.cc
+++ b/src/lib/cache/tests/run_unittests.cc
@@ -19,11 +19,15 @@
 
 #include <dns/tests/unittest_util.h>
 
+#include <log/logger_support.h>
+
 int
 main(int argc, char* argv[]) {
     ::testing::InitGoogleTest(&argc, argv);
     isc::UnitTestUtil::addDataPath(TEST_DATA_SRCDIR);
     isc::UnitTestUtil::addDataPath(TEST_DATA_BUILDDIR);
 
+    isc::log::initLogger();
+
     return (isc::util::unittests::run_all());
 }




More information about the bind10-changes mailing list