Browse Source

Merge branch 'work/log/cache'

Michal 'vorner' Vaner 14 years ago
parent
commit
c05781723a

+ 10 - 1
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

+ 148 - 0
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.

+ 4 - 0
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());
 

+ 23 - 0
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");
+
+}
+}

+ 44 - 0
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

+ 20 - 0
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);
     }
 

+ 1 - 1
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

+ 4 - 1
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);
         }
 

+ 32 - 0
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);
     }
 }

+ 24 - 3
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);
         }

+ 4 - 0
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());
 }