BIND 10 master, updated. 14a1dcf8c6d299b7b7d91b27c4bd73b06e1fd61d Merge branch 'master' into trac746

BIND 10 source code commits bind10-changes at lists.isc.org
Wed May 25 09:46:53 UTC 2011


The branch, master has been updated
       via  14a1dcf8c6d299b7b7d91b27c4bd73b06e1fd61d (commit)
       via  ce11fa4222196986805f54ab5b67b77dd5fe8e47 (commit)
       via  682108d6e371706f340cfe8575d8e00d1dab09cc (commit)
       via  523ab3a9278385abc26e1438803499a66e260f43 (commit)
       via  8e4fcdf22e1b5d14f740276e3a6c34a90bf3117c (commit)
       via  b02c482b25d489b723927f45c4cfe3fedd89f5b7 (commit)
       via  99240dbca4848d3aa76b34f5ff0d6da4d6bf911c (commit)
      from  b8855cafa94a12af7e087a4866367f2336e10bdb (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 14a1dcf8c6d299b7b7d91b27c4bd73b06e1fd61d
Merge: ce11fa4222196986805f54ab5b67b77dd5fe8e47 b8855cafa94a12af7e087a4866367f2336e10bdb
Author: Stephen Morris <stephen at isc.org>
Date:   Wed May 25 10:16:27 2011 +0100

    Merge branch 'master' into trac746

commit ce11fa4222196986805f54ab5b67b77dd5fe8e47
Author: Stephen Morris <stephen at isc.org>
Date:   Wed May 25 10:15:43 2011 +0100

    [trac746] Add time units to RTT message

commit 682108d6e371706f340cfe8575d8e00d1dab09cc
Author: Jelte Jansen <jelte at isc.org>
Date:   Tue May 24 15:29:25 2011 +0200

    [trac746] some editorial changes to the log message descriptions

commit 523ab3a9278385abc26e1438803499a66e260f43
Author: Stephen Morris <stephen at isc.org>
Date:   Fri May 13 20:41:12 2011 +0100

    [trac746] Add logg library to resolver library link line

commit 8e4fcdf22e1b5d14f740276e3a6c34a90bf3117c
Author: Stephen Morris <stephen at isc.org>
Date:   Fri May 13 20:11:15 2011 +0100

    [trac746] Clean up the resolvedef.{cc,h} files

commit b02c482b25d489b723927f45c4cfe3fedd89f5b7
Author: Stephen Morris <stephen at isc.org>
Date:   Fri May 13 19:37:07 2011 +0100

    [trac746] Message file for the resolver library messages

commit 99240dbca4848d3aa76b34f5ff0d6da4d6bf911c
Author: Stephen Morris <stephen at isc.org>
Date:   Fri May 13 19:35:41 2011 +0100

    [trac746] Add new-style logging to resolver library

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

Summary of changes:
 src/lib/resolve/Makefile.am                        |   22 +++-
 src/lib/resolve/recursive_query.cc                 |  172 ++++++++++++++------
 .../{nsas/nsas_log.cc => resolve/resolve_log.cc}   |    8 +-
 src/lib/{nsas/nsas_log.h => resolve/resolve_log.h} |   38 +++---
 src/lib/resolve/resolvedef.mes                     |  155 ++++++++++++++++++
 src/lib/resolve/tests/run_unittests.cc             |    2 +
 6 files changed, 320 insertions(+), 77 deletions(-)
 copy src/lib/{nsas/nsas_log.cc => resolve/resolve_log.cc} (86%)
 copy src/lib/{nsas/nsas_log.h => resolve/resolve_log.h} (58%)
 create mode 100644 src/lib/resolve/resolvedef.mes

-----------------------------------------------------------------------
diff --git a/src/lib/resolve/Makefile.am b/src/lib/resolve/Makefile.am
index 0b29da4..94ad371 100644
--- a/src/lib/resolve/Makefile.am
+++ b/src/lib/resolve/Makefile.am
@@ -7,16 +7,36 @@ AM_CPPFLAGS += $(SQLITE_CFLAGS)
 
 AM_CXXFLAGS = $(B10_CXXFLAGS)
 
-CLEANFILES = *.gcno *.gcda
+# Define rule to build logging source files from message file
+resolvedef.h resolvedef.cc: resolvedef.mes
+	$(top_builddir)/src/lib/log/compiler/message $(top_srcdir)/src/lib/resolve/resolvedef.mes
+
+# Tell Automake that the nsasdef.{cc,h} source files are created in the build
+# process, so it must create these before doing anything else.  Although they
+# are a dependency of the library (so will be created from the message file
+# anyway), there is no guarantee as to exactly _when_ in the build they will be
+# created.  As the .h file is included in other sources file (so must be
+# present when they are compiled), the safest option is to create it first.
+BUILT_SOURCES = resolvedef.h resolvedef.cc
+
+CLEANFILES = *.gcno *.gcda resolvedef.cc resolvedef.h
 
 lib_LTLIBRARIES = libresolve.la
 libresolve_la_SOURCES = resolve.h resolve.cc
+libresolve_la_SOURCES += resolve_log.h resolve_log.cc
 libresolve_la_SOURCES += resolver_interface.h
 libresolve_la_SOURCES += resolver_callback.h resolver_callback.cc
 libresolve_la_SOURCES += response_classifier.cc response_classifier.h
 libresolve_la_SOURCES += recursive_query.cc recursive_query.h
+
+nodist_libresolve_la_SOURCES = resolvedef.h resolvedef.cc
+
 libresolve_la_LIBADD = $(top_builddir)/src/lib/dns/libdns++.la
 libresolve_la_LIBADD += $(top_builddir)/src/lib/exceptions/libexceptions.la
+libresolve_la_LIBADD += $(top_builddir)/src/lib/log/liblog.la
+
+# The message file should be in the distribution.
+EXTRA_DIST = resolvedef.mes
 
 # Note: the ordering matters: -Wno-... must follow -Wextra (defined in
 # B10_CXXFLAGS)
diff --git a/src/lib/resolve/recursive_query.cc b/src/lib/resolve/recursive_query.cc
index b753cc9..ad073ae 100644
--- a/src/lib/resolve/recursive_query.cc
+++ b/src/lib/resolve/recursive_query.cc
@@ -16,14 +16,13 @@
 #include <stdlib.h>
 #include <sys/socket.h>
 #include <unistd.h>             // for some IPC/network system calls
+#include <string>
 
 #include <boost/lexical_cast.hpp>
 #include <boost/bind.hpp>
 
 #include <config.h>
 
-#include <log/dummylog.h>
-
 #include <dns/question.h>
 #include <dns/message.h>
 #include <dns/opcode.h>
@@ -31,6 +30,7 @@
 #include <dns/rdataclass.h>
 
 #include <resolve/resolve.h>
+#include <resolve/resolve_log.h>
 #include <cache/resolver_cache.h>
 #include <nsas/address_request_callback.h>
 #include <nsas/nameserver_address.h>
@@ -41,10 +41,10 @@
 #include <asiolink/io_service.h>
 #include <resolve/recursive_query.h>
 
-using isc::log::dlog;
 using namespace isc::dns;
 using namespace isc::util;
 using namespace isc::asiolink;
+using namespace isc::resolve;
 
 namespace isc {
 namespace asiodns {
@@ -64,8 +64,20 @@ hasAddress(const Name& name, const RRClass& rrClass,
             cache.lookup(name, RRType::AAAA(), rrClass) != RRsetPtr());
 }
 
+// Convenience function for debug messages.  Question::toText() includes
+// a trailing newline in its output, which makes it awkward to embed in a
+// message.  This just strips that newline from it.
+std::string
+questionText(const isc::dns::Question& question) {
+    std::string text = question.toText();
+    if (!text.empty()) {
+        text.erase(text.size() - 1);
+    }
+    return (text);
 }
 
+} // anonymous namespace
+
 /// \brief Find deepest usable delegation in the cache
 ///
 /// This finds the deepest delegation we have in cache and is safe to use.
@@ -135,8 +147,7 @@ RecursiveQuery::RecursiveQuery(DNSService& dns_service,
 // Set the test server - only used for unit testing.
 void
 RecursiveQuery::setTestServer(const std::string& address, uint16_t port) {
-    dlog("Setting test server to " + address + "(" +
-            boost::lexical_cast<std::string>(port) + ")");
+    LOG_WARN(isc::resolve::logger, RESLIB_TESTSERV).arg(address).arg(port);
     test_server_.first = address;
     test_server_.second = port;
 }
@@ -165,14 +176,16 @@ public:
     ResolverNSASCallback(RunningQuery* rq) : rq_(rq) {}
     
     void success(const isc::nsas::NameserverAddress& address) {
-        dlog("Found a nameserver, sending query to " + address.getAddress().toText());
+        // Success callback, send query to found namesever
+        LOG_DEBUG(isc::resolve::logger, RESLIB_DBG_CB, RESLIB_RUNQUSUCC)
+                  .arg(address.getAddress().toText());
         rq_->nsasCallbackCalled();
         rq_->sendTo(address);
     }
     
     void unreachable() {
-        dlog("Nameservers unreachable");
-        // Drop query or send servfail?
+        // Nameservers unreachable: drop query or send servfail?
+        LOG_DEBUG(isc::resolve::logger, RESLIB_DBG_CB, RESLIB_RUNQUFAIL);
         rq_->nsasCallbackCalled();
         rq_->makeSERVFAIL();
         rq_->callCallback(true);
@@ -298,12 +311,16 @@ private:
     // if we have a response for our query stored already. if
     // so, call handlerecursiveresponse(), if not, we call send()
     void doLookup() {
-        dlog("doLookup: try cache");
+        LOG_DEBUG(isc::resolve::logger, RESLIB_DBG_CACHE, RESLIB_RUNCALOOK)
+                  .arg(questionText(question_));
+
         Message cached_message(Message::RENDER);
         isc::resolve::initResponseMessage(question_, cached_message);
         if (cache_.lookup(question_.getName(), question_.getType(),
                           question_.getClass(), cached_message)) {
-            dlog("Message found in cache, continuing with that");
+
+            LOG_DEBUG(isc::resolve::logger, RESLIB_DBG_CACHE, RESLIB_RUNCAFND)
+                      .arg(questionText(question_));
             // Should these be set by the cache too?
             cached_message.setOpcode(Opcode::QUERY());
             cached_message.setRcode(Rcode::NOERROR());
@@ -313,9 +330,10 @@ private:
                 stop();
             }
         } else {
-            dlog("doLookup: get lowest usable delegation from cache");
             cur_zone_ = deepestDelegation(question_.getName(),
                                           question_.getClass(), cache_);
+            LOG_DEBUG(isc::resolve::logger, RESLIB_DBG_CACHE, RESLIB_DEEPEST)
+                      .arg(questionText(question_)).arg(cur_zone_);
             send();
         }
 
@@ -347,8 +365,9 @@ private:
     void send(IOFetch::Protocol protocol = IOFetch::UDP) {
         protocol_ = protocol;   // Store protocol being used for this
         if (test_server_.second != 0) {
-            dlog("Sending upstream query (" + question_.toText() +
-                 ") to test server at " + test_server_.first);
+            // Send query to test server
+            LOG_DEBUG(isc::resolve::logger, RESLIB_DBG_TRACE, RESLIB_TESTUPSTR)
+                .arg(questionText(question_)).arg(test_server_.first);
             gettimeofday(&current_ns_qsent_time, NULL);
             ++outstanding_events_;
             IOFetch query(protocol, io_, question_,
@@ -356,10 +375,13 @@ private:
                 test_server_.second, buffer_, this,
                 query_timeout_);
             io_.get_io_service().post(query);
+
         } else {
             // Ask the NSAS for an address for the current zone,
             // the callback will call the actual sendTo()
-            dlog("Look up nameserver for " + cur_zone_ + " in NSAS");
+            LOG_DEBUG(isc::resolve::logger, RESLIB_DBG_TRACE, RESLIB_NSASLOOK)
+                      .arg(cur_zone_);
+
             // Can we have multiple calls to nsas_out? Let's assume not
             // for now
             assert(!nsas_callback_out_);
@@ -387,7 +409,7 @@ private:
     //              error message)
     // returns false if we are not done
     bool handleRecursiveAnswer(const Message& incoming) {
-        dlog("Handle response");
+
         // In case we get a CNAME, we store the target
         // here (classify() will set it when it walks through
         // the cname chain to verify it).
@@ -402,46 +424,60 @@ private:
         switch (category) {
         case isc::resolve::ResponseClassifier::ANSWER:
         case isc::resolve::ResponseClassifier::ANSWERCNAME:
-            // Done. copy and return.
-            dlog("Response is an answer");
+            // Answer received - copy and return.
+            LOG_DEBUG(isc::resolve::logger, RESLIB_DBG_RESULTS, RESLIB_ANSWER)
+                      .arg(questionText(question_));
             isc::resolve::copyResponseMessage(incoming, answer_message_);
             cache_.update(*answer_message_);
             return true;
             break;
+
         case isc::resolve::ResponseClassifier::CNAME:
-            dlog("Response is CNAME!");
+            // CNAME received.
+
             // (unfinished) CNAME. We set our question_ to the CNAME
             // target, then start over at the beginning (for now, that
             // is, we reset our 'current servers' to the root servers).
             if (cname_count_ >= RESOLVER_MAX_CNAME_CHAIN) {
-                // just give up
-                dlog("CNAME chain too long");
+                // CNAME chain too long - just give up
+                LOG_DEBUG(isc::resolve::logger, RESLIB_DBG_RESULTS, RESLIB_LONGCHAIN)
+                          .arg(questionText(question_));
                 makeSERVFAIL();
                 return true;
             }
 
+            LOG_DEBUG(isc::resolve::logger, RESLIB_DBG_RESULTS, RESLIB_CNAME)
+                      .arg(questionText(question_));
+
             answer_message_->appendSection(Message::SECTION_ANSWER,
                                            incoming);
 
             question_ = Question(cname_target, question_.getClass(),
                                  question_.getType());
 
-            dlog("Following CNAME chain to " + question_.toText());
+            // Follow CNAME chain.
+            LOG_DEBUG(isc::resolve::logger, RESLIB_DBG_RESULTS, RESLIB_FOLLOWCNAME)
+                      .arg(questionText(question_));
             doLookup();
             return false;
             break;
+
         case isc::resolve::ResponseClassifier::NXDOMAIN:
         case isc::resolve::ResponseClassifier::NXRRSET:
-            dlog("Response is NXDOMAIN or NXRRSET");
-            // NXDOMAIN, just copy and return.
-            dlog(incoming.toText());
+            // Received NXDOMAIN or NXRRSET, just copy and return
+            LOG_DEBUG(isc::resolve::logger, RESLIB_DBG_RESULTS, RESLIB_NXDOMRR)
+                      .arg(questionText(question_));
             isc::resolve::copyResponseMessage(incoming, answer_message_);
             // no negcache yet
             //cache_.update(*answer_message_);
             return true;
             break;
+
         case isc::resolve::ResponseClassifier::REFERRAL:
-            dlog("Response is referral");
+            // Response is a referral
+            LOG_DEBUG(isc::resolve::logger, RESLIB_DBG_RESULTS, RESLIB_REFERRAL)
+                      .arg(questionText(question_));
+
             cache_.update(incoming);
             // Referral. For now we just take the first glue address
             // we find and continue with that
@@ -460,7 +496,8 @@ private:
                         // (this requires a few API changes in related
                         // libraries, so as not to need many conversions)
                         cur_zone_ = rrs->getName().toText();
-                        dlog("Referred to zone " + cur_zone_);
+                        LOG_DEBUG(isc::resolve::logger, RESLIB_DBG_RESULTS, RESLIB_REFERZONE)
+                                  .arg(cur_zone_);
                         found_ns = true;
                         break;
                     }
@@ -484,7 +521,10 @@ private:
                              nsas_callback_, ANY_OK, glue_hints);
                 return false;
             } else {
-                dlog("No NS RRset in referral?");
+                // Referral was received but did not contain an NS RRset.
+                LOG_DEBUG(isc::resolve::logger, RESLIB_DBG_RESULTS, RESLIB_NONSRRSET)
+                          .arg(questionText(question_));
+
                 // TODO this will result in answering with the delegation. oh well
                 isc::resolve::copyResponseMessage(incoming, answer_message_);
                 return true;
@@ -494,7 +534,8 @@ private:
             // Truncated packet.  If the protocol we used for the last one is
             // UDP, re-query using TCP.  Otherwise regard it as an error.
             if (protocol_ == IOFetch::UDP) {
-                dlog("Response truncated, re-querying over TCP");
+                LOG_DEBUG(isc::resolve::logger, RESLIB_DBG_RESULTS, RESLIB_TRUNCATED)
+                          .arg(questionText(question_));
                 send(IOFetch::TCP);
                 return false;
             }
@@ -513,6 +554,8 @@ private:
         case isc::resolve::ResponseClassifier::NOTSINGLE:
         case isc::resolve::ResponseClassifier::OPCODE:
         case isc::resolve::ResponseClassifier::RCODE:
+            LOG_DEBUG(isc::resolve::logger, RESLIB_DBG_RESULTS, RESLIB_RCODERR)
+                      .arg(questionText(question_));
             // Should we try a different server rather than SERVFAIL?
             makeSERVFAIL();
             return true;
@@ -677,7 +720,7 @@ public:
                 rtt = 1000 * (cur_time.tv_sec - current_ns_qsent_time.tv_sec);
                 rtt += (cur_time.tv_usec - current_ns_qsent_time.tv_usec) / 1000;
             }
-            dlog("RTT: " + boost::lexical_cast<std::string>(rtt));
+            LOG_DEBUG(isc::resolve::logger, RESLIB_DBG_RESULTS, RESLIB_RTT).arg(rtt);
             current_ns_address.updateRTT(rtt);
             if (rtt_recorder_) {
                 rtt_recorder_->addRtt(rtt);
@@ -701,19 +744,22 @@ public:
                     stop();
                 }
             } catch (const isc::dns::DNSProtocolError& dpe) {
-                dlog("DNS Protocol error in answer for " +
-                     question_.toText() + " " +
-                     question_.getType().toText() + ": " +
-                     dpe.what());
                 // Right now, we treat this similar to timeouts
                 // (except we don't store RTT)
                 // We probably want to make this an integral part
                 // of the fetch data process. (TODO)
                 if (retries_--) {
-                    dlog("Retrying");
+                    // Retry
+                    LOG_DEBUG(isc::resolve::logger, RESLIB_DBG_RESULTS,
+                              RESLIB_PROTOCOLRTRY)
+                              .arg(questionText(question_)).arg(dpe.what())
+                              .arg(retries_);
                     send();
                 } else {
-                    dlog("Giving up");
+                    // Give up
+                    LOG_DEBUG(isc::resolve::logger, RESLIB_DBG_RESULTS,
+                              RESLIB_PROTOCOL)
+                              .arg(questionText(question_)).arg(dpe.what());
                     if (!callback_called_) {
                         makeSERVFAIL();
                         callCallback(true);
@@ -723,13 +769,17 @@ public:
             }
         } else if (!done_ && retries_--) {
             // Query timed out, but we have some retries, so send again
-            dlog("Timeout for " + question_.toText() + " to " + current_ns_address.getAddress().toText() + ", resending query");
+            LOG_DEBUG(isc::resolve::logger, RESLIB_DBG_RESULTS, RESLIB_TIMEOUTRTRY)
+                      .arg(questionText(question_))
+                      .arg(current_ns_address.getAddress().toText()).arg(retries_);
             current_ns_address.updateRTT(isc::nsas::AddressEntry::UNREACHABLE);
             send();
         } else {
             // We are either already done, or out of retries
             if (result == IOFetch::TIME_OUT) {
-                dlog("Timeout for " + question_.toText() + " to " + current_ns_address.getAddress().toText() + ", giving up");
+                LOG_DEBUG(isc::resolve::logger, RESLIB_DBG_RESULTS, RESLIB_TIMEOUT)
+                          .arg(questionText(question_))
+                          .arg(current_ns_address.getAddress().toText());
                 current_ns_address.updateRTT(isc::nsas::AddressEntry::UNREACHABLE);
             }
             if (!callback_called_) {
@@ -793,8 +843,10 @@ private:
         buffer_->clear();
         int serverIndex = rand() % uc;
         ConstQuestionPtr question = *(query_message_->beginQuestion());
-        dlog("Sending upstream query (" + question->toText() +
-             ") to " + upstream_->at(serverIndex).first);
+        LOG_DEBUG(isc::resolve::logger, RESLIB_DBG_TRACE, RESLIB_UPSTREAM)
+            .arg(questionText(*question))
+            .arg(upstream_->at(serverIndex).first);
+
         ++outstanding_events_;
         // Forward the query, create the IOFetch with
         // query message, so that query flags can be forwarded
@@ -934,14 +986,16 @@ RecursiveQuery::resolve(const QuestionPtr& question,
 
     OutputBufferPtr buffer(new OutputBuffer(0));
 
-    dlog("Asked to resolve: " + question->toText());
-    
-    dlog("Try out cache first (direct call to resolve)");
     // First try to see if we have something cached in the messagecache
+    LOG_DEBUG(isc::resolve::logger, RESLIB_DBG_TRACE, RESLIB_RESOLVE)
+              .arg(questionText(*question)).arg(1);
     if (cache_.lookup(question->getName(), question->getType(),
                       question->getClass(), *answer_message) &&
         answer_message->getRRCount(Message::SECTION_ANSWER) > 0) {
-        dlog("Message found in cache, returning that");
+        // Message found, return that
+        LOG_DEBUG(isc::resolve::logger, RESLIB_DBG_CACHE, RESLIB_RESCAFND)
+                  .arg(questionText(*question)).arg(1);
+        
         // TODO: err, should cache set rcode as well?
         answer_message->setRcode(Rcode::NOERROR());
         callback->success(answer_message);
@@ -952,14 +1006,18 @@ RecursiveQuery::resolve(const QuestionPtr& question,
                                               question->getType(),
                                               question->getClass());
         if (cached_rrset) {
-            dlog("Found single RRset in cache");
+            // Found single RRset in cache
+            LOG_DEBUG(isc::resolve::logger, RESLIB_DBG_CACHE, RESLIB_RRSETFND)
+                      .arg(questionText(*question)).arg(1);
             answer_message->addRRset(Message::SECTION_ANSWER,
                                      cached_rrset);
             answer_message->setRcode(Rcode::NOERROR());
             callback->success(answer_message);
         } else {
-            dlog("Message not found in cache, starting recursive query");
-            // It will delete itself when it is done
+            // Message not found in cache, start recursive query.  It will
+            // delete itself when it is done
+            LOG_DEBUG(isc::resolve::logger, RESLIB_DBG_TRACE, RESLIB_RESCANOTFND)
+                      .arg(questionText(*question)).arg(1);
             new RunningQuery(io, *question, answer_message,
                              test_server_, buffer, callback,
                              query_timeout_, client_timeout_,
@@ -988,14 +1046,17 @@ RecursiveQuery::resolve(const Question& question,
     answer_message->setOpcode(isc::dns::Opcode::QUERY());
     answer_message->addQuestion(question);
     
-    dlog("Asked to resolve: " + question.toText());
-    
     // First try to see if we have something cached in the messagecache
-    dlog("Try out cache first (started by incoming event)");
+    LOG_DEBUG(isc::resolve::logger, RESLIB_DBG_TRACE, RESLIB_RESOLVE)
+              .arg(questionText(question)).arg(2);
+    
     if (cache_.lookup(question.getName(), question.getType(),
                       question.getClass(), *answer_message) &&
         answer_message->getRRCount(Message::SECTION_ANSWER) > 0) {
-        dlog("Message found in cache, returning that");
+
+        // Message found, return that
+        LOG_DEBUG(isc::resolve::logger, RESLIB_DBG_CACHE, RESLIB_RESCAFND)
+                  .arg(questionText(question)).arg(2);
         // TODO: err, should cache set rcode as well?
         answer_message->setRcode(Rcode::NOERROR());
         crs->success(answer_message);
@@ -1006,14 +1067,19 @@ RecursiveQuery::resolve(const Question& question,
                                               question.getType(),
                                               question.getClass());
         if (cached_rrset) {
-            dlog("Found single RRset in cache");
+            // Found single RRset in cache
+            LOG_DEBUG(isc::resolve::logger, RESLIB_DBG_CACHE, RESLIB_RRSETFND)
+                      .arg(questionText(question)).arg(2);
             answer_message->addRRset(Message::SECTION_ANSWER,
                                      cached_rrset);
             answer_message->setRcode(Rcode::NOERROR());
             crs->success(answer_message);
+
         } else {
-            dlog("Message not found in cache, starting recursive query");
-            // It will delete itself when it is done
+            // Message not found in cache, start recursive query.  It will
+            // delete itself when it is done
+            LOG_DEBUG(isc::resolve::logger, RESLIB_DBG_TRACE, RESLIB_RESCANOTFND)
+                      .arg(questionText(question)).arg(2);
             new RunningQuery(io, question, answer_message, 
                              test_server_, buffer, crs, query_timeout_,
                              client_timeout_, lookup_timeout_, retries_,
diff --git a/src/lib/resolve/resolve_log.cc b/src/lib/resolve/resolve_log.cc
new file mode 100644
index 0000000..e41d8d2
--- /dev/null
+++ b/src/lib/resolve/resolve_log.cc
@@ -0,0 +1,26 @@
+// 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.
+
+/// Defines the logger used by the NSAS
+
+#include <resolve/resolve_log.h>
+
+namespace isc {
+namespace resolve {
+
+isc::log::Logger logger("reslib");  // Distinct from "resolver"
+
+} // namespace resolve
+} // namespace isc
+
diff --git a/src/lib/resolve/resolve_log.h b/src/lib/resolve/resolve_log.h
new file mode 100644
index 0000000..89d23c6
--- /dev/null
+++ b/src/lib/resolve/resolve_log.h
@@ -0,0 +1,53 @@
+// 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 __RESOLVE_LOG__H
+#define __RESOLVE_LOG__H
+
+#include <log/macros.h>
+#include "resolvedef.h"
+
+namespace isc {
+namespace resolve {
+
+/// \brief Resolver Library Logging
+///
+/// Defines the levels used to output debug messages in the resolver library.
+/// Note that higher numbers equate to more verbose (and detailed) output.
+
+// The first level traces normal operations
+const int RESLIB_DBG_TRACE = 10;
+
+// The next level extends the normal operations and records the results of the
+// lookups.
+const int RESLIB_DBG_RESULTS = 20;
+
+// Report cache lookups and results
+const int RESLIB_DBG_CACHE = 40;
+
+// Indicate when callbacks are called
+const int RESLIB_DBG_CB = 50;
+
+
+/// \brief Resolver Library Logger
+///
+/// Define the logger used to log messages.  We could define it in multiple
+/// modules, but defining in a single module and linking to it saves time and
+/// space.
+extern isc::log::Logger logger;
+
+} // namespace resolve
+} // namespace isc
+
+#endif // __RESOLVE_LOG__H
diff --git a/src/lib/resolve/resolvedef.mes b/src/lib/resolve/resolvedef.mes
new file mode 100644
index 0000000..61870a6
--- /dev/null
+++ b/src/lib/resolve/resolvedef.mes
@@ -0,0 +1,155 @@
+# 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.
+
+$PREFIX RESLIB_
+$NAMESPACE isc::resolve
+
+% ANSWER        answer received in response to query for <%1>
+A debug message recording that an answer has been received to an upstream
+query for the specified question.  Previous debug messages will have indicated
+the server to which the question was sent.
+
+% CNAME         CNAME received in response to query for <%1>
+A debug message recording that CNAME response has been received to an upstream
+query for the specified question.  Previous debug messages will have indicated
+the server to which the question was sent.
+
+% DEEPEST       did not find <%1> in cache, deepest delegation found is %2
+A debug message, a cache lookup did not find the specified <name, class,
+type> tuple in the cache; instead, the deepest delegation found is indicated.
+
+% FOLLOWCNAME   following CNAME chain to <%1>
+A debug message, a CNAME response was received and another query is being issued
+for the <name, class, type> tuple.
+
+% LONGCHAIN     CNAME received in response to query for <%1>: CNAME chain length exceeded
+A debug message recording that a CNAME response has been received to an upstream
+query for the specified question (Previous debug messages will have indicated
+the server to which the question was sent).  However, receipt of this CNAME
+has meant that the resolver has exceeded the CNAME chain limit (a CNAME chain
+is where on CNAME points to another) and so an error is being returned.
+
+% NONSRRSET     no NS RRSet in referral response received to query for <%1>
+A debug message, this indicates that a response was received for the specified
+query and was categorised as a referral.  However, the received message did
+not contain any NS RRsets.  This may indicate a programming error in the
+response classification code.
+
+% NSASLOOK      looking up nameserver for zone %1 in the NSAS
+A debug message, the RunningQuery object is querying the NSAS for the
+nameservers for the specified zone.
+
+% NXDOMRR       NXDOMAIN/NXRRSET received in response to query for <%1>
+A debug message recording that either a NXDOMAIN or an NXRRSET response has
+been received to an upstream query for the specified question.  Previous debug
+messages will have indicated the server to which the question was sent.
+
+% PROTOCOL      protocol error in answer for %1:  %3
+A debug message indicating that a protocol error was received.  As there
+are no retries left, an error will be reported.
+
+% PROTOCOLRTRY  protocol error in answer for %1: %2 (retries left: %3)
+A debug message indicating that a protocol error was received and that
+the resolver is repeating the query to the same nameserver.  After this
+repeated query, there will be the indicated number of retries left.
+
+% RCODERR       RCODE indicates error in response to query for <%1>
+A debug message, the response to the specified query indicated an error
+that is not covered by a specific code path.  A SERVFAIL will be returned.
+
+% REFERRAL      referral received in response to query for <%1>
+A debug message recording that a referral response has been received to an
+upstream query for the specified question.  Previous debug messages will
+have indicated the server to which the question was sent.
+
+% REFERZONE     referred to zone %1
+A debug message indicating that the last referral message was to the specified
+zone.
+
+% RESCAFND      found <%1> in the cache (resolve() instance %2)
+This is a debug message and indicates that a RecursiveQuery object found the
+the specified <name, class, type> tuple in the cache.  The instance number
+at the end of the message indicates which of the two resolve() methods has
+been called.
+
+% RESCANOTFND   did not find <%1> in the cache, starting RunningQuery (resolve() instance %2)
+This is a debug message and indicates that the look in the cache made by the
+RecursiveQuery::resolve() method did not find an answer, so a new RunningQuery
+object has been created to resolve the question.  The instance number at
+the end of the message indicates which of the two resolve() methods has
+been called.
+
+% RESOLVE       asked to resolve <%1> (resolve() instance %2)
+A debug message, the RecursiveQuery::resolve method has been called to resolve
+the specified <name, class, type> tuple.  The first action will be to lookup
+the specified tuple in the cache.  The instance number at the end of the
+message indicates which of the two resolve() methods has been called.
+
+% RRSETFND      found single RRset in the cache when querying for <%1> (resolve() instance %2)
+A debug message, indicating that when RecursiveQuery::resolve queried the
+cache, a single RRset was found which was put in the answer.  The instance
+number at the end of the message indicates which of the two resolve()
+methods has been called.
+
+% RTT           round-trip time of last query calculated as %1 ms
+A debug message giving the round-trip time of the last query and response.
+
+% RUNCAFND      found <%1> in the cache
+This is a debug message and indicates that a RunningQuery object found
+the specified <name, class, type> tuple in the cache.
+
+% RUNCALOOK     looking up up <%1> in the cache
+This is a debug message and indicates that a RunningQuery object has made
+a call to its doLookup() method to look up the specified <name, class, type>
+tuple, the first action of which will be to examine the cache.
+
+% RUNQUFAIL     failure callback - nameservers are unreachable
+A debug message indicating that a RunningQuery's failure callback has been
+called because all nameservers for the zone in question are unreachable.
+
+% RUNQUSUCC     success callback - sending query to %1
+A debug message indicating that a RunningQuery's success callback has been
+called because a nameserver has been found, and that a query is being sent
+to the specified nameserver.
+
+% TESTSERV      setting test server to %1(%2)
+This is an internal debugging message and is only generated in unit tests.
+It indicates that all upstream queries from the resolver are being routed to
+the specified server, regardless of the address of the nameserver to which
+the query would normally be routed.  As it should never be seen in normal
+operation, it is a warning message instead of a debug message.
+
+% TESTUPSTR     sending upstream query for <%1> to test server at %2
+This is a debug message and should only be seen in unit tests.  A query for
+the specified <name, class, type> tuple is being sent to a test nameserver
+whose address is given in the message.
+
+% TIMEOUT       query <%1> to %2 timed out
+A debug message indicating that the specified query has timed out and as
+there are no retries left, an error will be reported.
+
+% TIMEOUTRTRY   query <%1> to %2 timed out, re-trying (retries left: %3)
+A debug message indicating that the specified query has timed out and that
+the resolver is repeating the query to the same nameserver.  After this
+repeated query, there will be the indicated number of retries left.
+
+% TRUNCATED     response to query for <%1> was truncated, re-querying over TCP
+A debug message, this indicates that the response to the specified query was
+truncated and that the resolver will be re-querying over TCP.  There are
+various reasons why responses may be truncated, so this message is normal and
+gives no cause for concern.
+
+% UPSTREAM      sending upstream query for <%1> to %2
+A debug message indicating that a query for the specified <name, class, type>
+tuple is being sent to a nameserver whose address is given in the message.
diff --git a/src/lib/resolve/tests/run_unittests.cc b/src/lib/resolve/tests/run_unittests.cc
index a7aaeeb..fe8124e 100644
--- a/src/lib/resolve/tests/run_unittests.cc
+++ b/src/lib/resolve/tests/run_unittests.cc
@@ -16,10 +16,12 @@
 #include <util/unittests/run_all.h>
 
 #include <dns/tests/unittest_util.h>
+#include <log/logger_support.h>
 
 int
 main(int argc, char* argv[]) {
     ::testing::InitGoogleTest(&argc, argv);
+    isc::log::initLogger();
 
     return (isc::util::unittests::run_all());
 }




More information about the bind10-changes mailing list