BIND 10 trac739, updated. 072ba32545ec255923699c0c181345910f86a208 [trac739] Convert main resolver code to use new logging system
BIND 10 source code commits
bind10-changes at lists.isc.org
Mon May 16 12:30:28 UTC 2011
The branch, trac739 has been updated
via 072ba32545ec255923699c0c181345910f86a208 (commit)
from 1f91575ae48846e3a97a0c3921dd808470ba4427 (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 072ba32545ec255923699c0c181345910f86a208
Author: Stephen Morris <stephen at isc.org>
Date: Mon May 16 13:30:01 2011 +0100
[trac739] Convert main resolver code to use new logging system
-----------------------------------------------------------------------
Summary of changes:
src/bin/resolver/Makefile.am | 3 +-
src/bin/resolver/main.cc | 28 ++++++---
src/bin/resolver/resolver.cc | 108 ++++++++++++++++++++++++------------
src/bin/resolver/tests/Makefile.am | 3 +
4 files changed, 96 insertions(+), 46 deletions(-)
-----------------------------------------------------------------------
diff --git a/src/bin/resolver/Makefile.am b/src/bin/resolver/Makefile.am
index 4e615cd..e826081 100644
--- a/src/bin/resolver/Makefile.am
+++ b/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
diff --git a/src/bin/resolver/main.cc b/src/bin/resolver/main.cc
index 310d37f..f79899f 100644
--- a/src/bin/resolver/main.cc
+++ b/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;
diff --git a/src/bin/resolver/resolver.cc b/src/bin/resolver/resolver.cc
index 146fe81..f4ea81b 100644
--- a/src/bin/resolver/resolver.cc
+++ b/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;
diff --git a/src/bin/resolver/tests/Makefile.am b/src/bin/resolver/tests/Makefile.am
index 444358b..32f1bfb 100644
--- a/src/bin/resolver/tests/Makefile.am
+++ b/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
More information about the bind10-changes
mailing list