[trac739] Convert main resolver code to use new logging system

src/bin/resolver/Makefile.am

@@ -40,13 +40,14 @@ spec_config.h: spec_config.h.pre
 
 # Define rule to build logging source files from message file
 resolverdef.h resolverdef.cc: resolverdef.mes
-	$(top_builddir)/src/lib/log/compiler/message $(top_srcdir)/src/lib/resolver/resolverdef.mes
+	$(top_builddir)/src/lib/log/compiler/message $(top_srcdir)/src/bin/resolver/resolverdef.mes
 
 
 BUILT_SOURCES = spec_config.h resolverdef.cc resolverdef.h
 
 pkglibexec_PROGRAMS = b10-resolver
 b10_resolver_SOURCES = resolver.cc resolver.h
+b10_resolver_SOURCES += resolver_log.cc resolver_log.h
 b10_resolver_SOURCES += response_scrubber.cc response_scrubber.h
 b10_resolver_SOURCES += $(top_builddir)/src/bin/auth/change_user.h
 b10_resolver_SOURCES += $(top_builddir)/src/bin/auth/common.h

src/bin/resolver/main.cc

@@ -52,7 +52,10 @@
 #include <cache/resolver_cache.h>
 #include <nsas/nameserver_address_store.h>
 
-#include <log/dummylog.h>
+#include <log/macros.h>
+#include <log/logger_support.h>
+#include <log/debug_levels.h>
+#include "resolver_log.h"
 
 using namespace std;
 using namespace isc::cc;
@@ -78,7 +81,7 @@ my_command_handler(const string& command, ConstElementPtr args) {
     ConstElementPtr answer = createAnswer();
 
     if (command == "print_message") {
-        cout << args << endl;
+        LOG_INFO(resolver_logger, RESOLVER_PRINTMSG).arg(args);
         /* let's add that message to our answer as well */
         answer = createAnswer(0, args);
     } else if (command == "shutdown") {
@@ -99,7 +102,7 @@ usage() {
 
 int
 main(int argc, char* argv[]) {
-    isc::log::dprefix = "b10-resolver";
+    bool verbose = false;
     int ch;
     const char* uid = NULL;
 
@@ -109,7 +112,7 @@ main(int argc, char* argv[]) {
             uid = optarg;
             break;
         case 'v':
-            isc::log::denabled = true;
+            verbose = true;
             break;
         case '?':
         default:
@@ -121,13 +124,18 @@ main(int argc, char* argv[]) {
         usage();
     }
 
-    if (isc::log::denabled) { // Show the command line
-        string cmdline("Command line:");
-        for (int i = 0; i < argc; ++ i) {
-            cmdline = cmdline + " " + argv[i];
-        }
-        LOG_INFO(resolver_logger, RESOLVER_STARTING).arg(cmdline);
+    // Until proper logging comes along, initialize the logging with the
+    // temporary initLogger() code.  If verbose, we'll use maximum verbosity.
+    isc::log::initLogger("b10-resolver",
+                         (verbose ? isc::log::DEBUG : isc::log::INFO),
+                         MAX_DEBUG_LEVEL, NULL);
+
+    // Print the starting message
+    string cmdline = argv[0];
+    for (int i = 1; i < argc; ++ i) {
+        cmdline = cmdline + " " + argv[i];
     }
+    LOG_INFO(resolver_logger, RESOLVER_STARTING).arg(cmdline);
 
     int ret = 0;
 

src/bin/resolver/resolver.cc

@@ -45,9 +45,8 @@
 
 #include <resolve/recursive_query.h>
 
-#include <log/dummylog.h>
-
-#include <resolver/resolver.h>
+#include "resolver.h"
+#include "resolver_log.h"
 
 using namespace std;
 
@@ -56,7 +55,6 @@ using namespace isc::util;
 using namespace isc::dns;
 using namespace isc::data;
 using namespace isc::config;
-using isc::log::dlog;
 using namespace isc::asiodns;
 using namespace isc::asiolink;
 using namespace isc::server_common::portconfig;
@@ -184,8 +182,6 @@ class QuestionInserter {
 public:
     QuestionInserter(MessagePtr message) : message_(message) {}
     void operator()(const QuestionPtr question) {
-        dlog(string("Adding question ") + question->getName().toText() +
-            " to message");
         message_->addQuestion(question);
     }
     MessagePtr message_;
@@ -232,10 +228,6 @@ makeErrorMessage(MessagePtr message, MessagePtr answer_message,
     message->setRcode(rcode);
     MessageRenderer renderer(*buffer);
     message->toWire(renderer);
-
-    dlog(string("Sending an error response (") +
-        boost::lexical_cast<string>(renderer.getLength()) + " bytes):\n" +
-        message->toText());
 }
 
 // This is a derived class of \c DNSLookup, to serve as a
@@ -310,9 +302,8 @@ public:
 
         answer_message->toWire(renderer);
 
-        dlog(string("sending a response (") +
-            boost::lexical_cast<string>(renderer.getLength()) + "bytes): \n" +
-            answer_message->toText());
+        LOG_DEBUG(resolver_logger, RESOLVER_DBG_DETAIL, RESOLVER_DNSMSGSENT)
+                  .arg(renderer.getLength()).arg(answer_message->toText());
     }
 };
 
@@ -392,19 +383,22 @@ Resolver::processMessage(const IOMessage& io_message,
     InputBuffer request_buffer(io_message.getData(), io_message.getDataSize());
     // First, check the header part.  If we fail even for the base header,
     // just drop the message.
+
+    // In the following code, the debug output is such that there should only be
+    // one debug message if packet processing failed.  There could be two if
+    // it succeeded.
     try {
         query_message->parseHeader(request_buffer);
 
         // Ignore all responses.
         if (query_message->getHeaderFlag(Message::HEADERFLAG_QR)) {
-            LOG_DEBUG(resolver_logger, RESOLVER_DBG_RECVMSG, RESOLVER_UNEXRESP);
+            LOG_DEBUG(resolver_logger, RESOLVER_DBG_IO, RESOLVER_UNEXRESP);
             server->resume(false);
             return;
         }
-        LOG_DEBUG(resolver_logger, RESOLVER_DBG_RECVMSG, RESOLVER_RECVMSG);
 
     } catch (const Exception& ex) {
-        LOG_DEBUG(resolver_logger, RESOLVER_DBG_RECVMSG, RESOLVER_PKTEXCEPT)
+        LOG_DEBUG(resolver_logger, RESOLVER_DBG_IO, RESOLVER_HDRERR)
                   .arg(ex.what());
         server->resume(false);
         return;
@@ -414,37 +408,49 @@ Resolver::processMessage(const IOMessage& io_message,
     try {
         query_message->fromWire(request_buffer);
     } catch (const DNSProtocolError& error) {
-        dlog(string("returning ") + error.getRcode().toText() + ": " + 
-            error.what());
+        LOG_DEBUG(resolver_logger, RESOLVER_DBG_IO, RESOLVER_PROTERR)
+                  .arg(error.what()).arg(error.getRcode());
         makeErrorMessage(query_message, answer_message,
                          buffer, error.getRcode());
         server->resume(true);
         return;
     } catch (const Exception& ex) {
-        dlog(string("returning SERVFAIL: ") + ex.what());
+        LOG_DEBUG(resolver_logger, RESOLVER_DBG_IO, RESOLVER_PROTERR)
+                  .arg(ex.what()).arg(Rcode::SERVFAIL());
         makeErrorMessage(query_message, answer_message,
                          buffer, Rcode::SERVFAIL());
         server->resume(true);
         return;
-    } // other exceptions will be handled at a higher layer.
+    } // Other exceptions will be handled at a higher layer.
 
-    dlog("received a message:\n" + query_message->toText());
+    // Note:  there appears to be no LOG_DEBUG for a successfully-received
+    // message.  This is not an oversight - it is handled below.  In the
+    // meantime, output the full message for debug purposes (if requested).
+    LOG_DEBUG(resolver_logger, RESOLVER_DBG_DETAIL, RESOLVER_DNSMSGRCVD)
+              .arg(query_message->toText());
 
     // Perform further protocol-level validation.
     bool sendAnswer = true;
     if (query_message->getOpcode() == Opcode::NOTIFY()) {
+
         makeErrorMessage(query_message, answer_message,
                          buffer, Rcode::NOTAUTH());
-        dlog("Notify arrived, but we are not authoritative");
+        // Notify arrived, but we are not authoritative.
+        LOG_DEBUG(resolver_logger, RESOLVER_DBG_PROCESS, RESOLVER_NFYNOTAUTH);
+
     } else if (query_message->getOpcode() != Opcode::QUERY()) {
-        dlog("Unsupported opcode (got: " + query_message->getOpcode().toText() +
-            ", expected: " + Opcode::QUERY().toText());
+
+        // Unsupported opcode.
+        LOG_DEBUG(resolver_logger, RESOLVER_DBG_PROCESS, RESOLVER_OPCODEUNS)
+                  .arg(query_message->getOpcode().toText());
         makeErrorMessage(query_message, answer_message,
                          buffer, Rcode::NOTIMP());
+
     } else if (query_message->getRRCount(Message::SECTION_QUESTION) != 1) {
-        dlog("The query contained " +
-            boost::lexical_cast<string>(query_message->getRRCount(
-            Message::SECTION_QUESTION) + " questions, exactly one expected"));
+
+        // Not one question
+        LOG_DEBUG(resolver_logger, RESOLVER_DBG_PROCESS, RESOLVER_NOTONEQUES)
+                  .arg(query_message->getRRCount(Message::SECTION_QUESTION));
         makeErrorMessage(query_message, answer_message,
                          buffer, Rcode::FORMERR());
     } else {
@@ -452,16 +458,32 @@ Resolver::processMessage(const IOMessage& io_message,
         const RRType &qtype = question->getType();
         if (qtype == RRType::AXFR()) {
             if (io_message.getSocket().getProtocol() == IPPROTO_UDP) {
+
+                // Can't process AXFR request receoved over UDP
+                LOG_DEBUG(resolver_logger, RESOLVER_DBG_PROCESS,
+                          RESOLVER_AXFRUDP);
                 makeErrorMessage(query_message, answer_message,
                                  buffer, Rcode::FORMERR());
             } else {
+
+                // ... or over TCP for that matter
+                LOG_DEBUG(resolver_logger, RESOLVER_DBG_PROCESS,
+                          RESOLVER_AXFRTCP);
                 makeErrorMessage(query_message, answer_message,
                                  buffer, Rcode::NOTIMP());
             }
         } else if (qtype == RRType::IXFR()) {
+
+            // Can't process IXFR request
+            LOG_DEBUG(resolver_logger, RESOLVER_DBG_PROCESS, RESOLVER_IXFR);
             makeErrorMessage(query_message, answer_message,
                              buffer, Rcode::NOTIMP());
+
         } else if (question->getClass() != RRClass::IN()) {
+
+            // Non-IN message received, refuse it.
+            LOG_DEBUG(resolver_logger, RESOLVER_DBG_PROCESS, RESOLVER_NOTIN)
+                      .arg(question->getClass());
             makeErrorMessage(query_message, answer_message,
                              buffer, Rcode::REFUSED());
         } else {
@@ -492,18 +514,23 @@ ResolverImpl::processNormalQuery(ConstMessagePtr query_message,
                                  DNSServer* server)
 {
     if (upstream_.empty()) {
-        dlog("Processing normal query");
+        // Processing normal query
+        LOG_DEBUG(resolver_logger, RESOLVER_DBG_IO, RESOLVER_NORMQUERY);
         ConstQuestionPtr question = *query_message->beginQuestion();
         rec_query_->resolve(*question, answer_message, buffer, server);
+
     } else {
-        dlog("Processing forward query");
+
+        // Processing forward query
+        LOG_DEBUG(resolver_logger, RESOLVER_DBG_IO, RESOLVER_FWDQUERY);
         rec_query_->forward(query_message, answer_message, buffer, server);
     }
 }
 
 ConstElementPtr
 Resolver::updateConfig(ConstElementPtr config) {
-    dlog("New config comes: " + config->toWire());
+    LOG_DEBUG(resolver_logger, RESOLVER_DBG_CONFIG, RESOLVER_CONFIGUPD)
+              .arg(config->toWire());
 
     try {
         // Parse forward_addresses
@@ -530,6 +557,7 @@ Resolver::updateConfig(ConstElementPtr config) {
             // check for us
             qtimeout = qtimeoutE->intValue();
             if (qtimeout < -1) {
+                LOG_ERROR(resolver_logger, RESOLVER_QUTMOSMALL).arg(qtimeout);
                 isc_throw(BadValue, "Query timeout too small");
             }
             set_timeouts = true;
@@ -537,6 +565,7 @@ Resolver::updateConfig(ConstElementPtr config) {
         if (ctimeoutE) {
             ctimeout = ctimeoutE->intValue();
             if (ctimeout < -1) {
+                LOG_ERROR(resolver_logger, RESOLVER_CLTMOSMALL).arg(ctimeout);
                 isc_throw(BadValue, "Client timeout too small");
             }
             set_timeouts = true;
@@ -544,12 +573,18 @@ Resolver::updateConfig(ConstElementPtr config) {
         if (ltimeoutE) {
             ltimeout = ltimeoutE->intValue();
             if (ltimeout < -1) {
+                LOG_ERROR(resolver_logger, RESOLVER_LKTMOSMALL).arg(ltimeout);
                 isc_throw(BadValue, "Lookup timeout too small");
             }
             set_timeouts = true;
         }
         if (retriesE) {
+            // Do the assignment from "retriesE->intValue()" to "retries"
+            // _after_ the comparison (as opposed to before it for the timeouts)
+            // because "retries" is unsigned.
             if (retriesE->intValue() < 0) {
+                LOG_ERROR(resolver_logger, RESOLVER_RETRYNEG)
+                          .arg(retriesE->intValue());
                 isc_throw(BadValue, "Negative number of retries");
             }
             retries = retriesE->intValue();
@@ -591,8 +626,11 @@ Resolver::updateConfig(ConstElementPtr config) {
         }
         setConfigured();
         return (isc::config::createAnswer());
+
     } catch (const isc::Exception& error) {
-        dlog(string("error in config: ") + error.what(),true);
+
+        // Configuration error
+        LOG_ERROR(resolver_logger, RESOLVER_CONFIGERR).arg(error.what());
         return (isc::config::createAnswer(1, error.what()));
     }
 }
@@ -632,10 +670,10 @@ Resolver::setListenAddresses(const AddressList& addresses) {
 void
 Resolver::setTimeouts(int query_timeout, int client_timeout,
                       int lookup_timeout, unsigned retries) {
-    dlog("Setting query timeout to " + boost::lexical_cast<string>(query_timeout) +
-         ", client timeout to " + boost::lexical_cast<string>(client_timeout) +
-         ", lookup timeout to " + boost::lexical_cast<string>(lookup_timeout) +
-         " and retry count to " + boost::lexical_cast<string>(retries));
+    LOG_DEBUG(resolver_logger, RESOLVER_DBG_CONFIG, RESOLVER_SETPARAM)
+              .arg(query_timeout).arg(client_timeout).arg(lookup_timeout)
+              .arg(retries);
+
     impl_->query_timeout_ = query_timeout;
     impl_->client_timeout_ = client_timeout;
     impl_->lookup_timeout_ = lookup_timeout;

src/bin/resolver/tests/Makefile.am

@@ -16,9 +16,12 @@ CLEANFILES = *.gcno *.gcda
 TESTS =
 if HAVE_GTEST
 TESTS += run_unittests
+
 run_unittests_SOURCES = $(top_srcdir)/src/lib/dns/tests/unittest_util.h
 run_unittests_SOURCES += $(top_srcdir)/src/lib/dns/tests/unittest_util.cc
 run_unittests_SOURCES += ../resolver.h ../resolver.cc
+run_unittests_SOURCES += ../resolver_log.h ../resolver_log.cc
+run_unittests_SOURCES += ../resolverdef.h ../resolverdef.cc
 run_unittests_SOURCES += ../response_scrubber.h ../response_scrubber.cc
 run_unittests_SOURCES += resolver_unittest.cc
 run_unittests_SOURCES += resolver_config_unittest.cc