[trac555] Merge branch 'master' into trac555

Conflicts:
	src/lib/log/tests/Makefile.am
	src/lib/log/tests/logger_unittest.cc
	src/lib/log/tests/run_unittests.cc

ChangeLog

@@ -1,3 +1,32 @@
+247.    [func]      jelte
+	Upstream queries from the resolver now set EDNS0 buffer size.
+	(Trac834, git 48e10c2530fe52c9bde6197db07674a851aa0f5d)
+
+246.    [func]      stephen
+	Implement logging using log4cplus (http://log4cplus.sourceforge.net)
+	(Trac899, git 31d3f525dc01638aecae460cb4bc2040c9e4df10)
+
+245.    [func]      vorner
+	Authoritative server can now sign the answers using TSIG
+	(configured in tsig_keys/keys, list of strings like
+	"name:<base64-secret>:sha1-hmac"). It doesn't use them for
+	ACL yet, only verifies them and signs if the request is signed.
+	(Trac875, git fe5e7003544e4e8f18efa7b466a65f336d8c8e4d)
+
+244.	[func] 		stephen
+	In unit tests, allow the choice of whether unhandled exceptions are
+	caught in the unit test program (and details printed) or allowed to
+	propagate to the default exception handler.  See the bind10-dev thread
+	https://lists.isc.org/pipermail/bind10-dev/2011-January/001867.html
+	for more details.
+	(Trac #542, git 1aa773d84cd6431aa1483eb34a7f4204949a610f)
+
+243.	[func]*		feng
+	Add optional hmac algorithm SHA224/384/812.
+	(Trac#782, git 77d792c9d7c1a3f95d3e6a8b721ac79002cd7db1)
+
+bind10-devel-20110519 released on May 19, 2011
+
 242.	[func]		jinmei
 	xfrin: added support for TSIG verify.  This change completes TSIG
 	support in b10-xfrin.
@@ -13,17 +42,19 @@
 	Updated configuration options to Xfrin, so that you can specify
 	a master address, port, and TSIG key per zone. Still only one per
 	zone at this point, and TSIG keys are (currently) only specified
-	by their full string representation.
+	by their full string representation. This replaces the
+	Xfrin/master_addr, Xfrin/master_port, and short-lived
+	Xfrin/tsig_key configurations with a Xfrin/zones list.
 	(Trac #811, git 88504d121c5e08fff947b92e698a54d24d14c375)
 
 239.	[bug]		jerry
-	src/bin/xfrout: If a zone doesn't have notify slaves(only has
+	src/bin/xfrout: If a zone doesn't have notify slaves (only has
 	one apex ns record - the primary master name server) will cause
 	b10-xfrout uses 100% of CPU.
 	(Trac #684, git d11b5e89203a5340d4e5ca51c4c02db17c33dc1f)
 
 238.	[func]		zhang likun
-	Implement the simplest forwarder, which pass everything throught
+	Implement the simplest forwarder, which pass everything through
 	except QID, port number. The response will not be cached.
 	(Trac #598_new, git 8e28187a582820857ef2dae9b13637a3881f13ba)
 
@@ -76,7 +107,7 @@
 	(Trac #900, git b395258c708b49a5da8d0cffcb48d83294354ba3)
 
 231.	[func]*		vorner
-	The logging interface changed slightly. We use
+    The logging interface changed slightly. We use
 	logger.foo(MESSAGE_ID).arg(bar); instead of logger.foo(MESSAGE_ID,
 	bar); internally. The message definitions use '%1,%2,...'
 	instead of '%s,%d', which allows us to cope better with
@@ -118,14 +149,14 @@
 	(Trac #781, git 9df42279a47eb617f586144dce8cce680598558a)
 
 225.	[func]		naokikambe
-	Added the HTTP/XML interface(b10-stats-httpd) to the
+	Added the HTTP/XML interface (b10-stats-httpd) to the
 	statistics feature in BIND 10. b10-stats-httpd is a standalone
 	HTTP server and it requests statistics data to the stats
-	daemon(b10-stats) and sends it to HTTP clients in XML
+	daemon (b10-stats) and sends it to HTTP clients in XML
 	format. Items of the data collected via b10-stats-httpd
 	are almost equivalent to ones which are collected via
-	bindctl. Since it also can send XSL(Extensible Stylessheet
-	Language) document and XSD(XML Schema definition) document,
+	bindctl. Since it also can send XSL (Extensible Stylesheet
+	Language) document and XSD (XML Schema definition) document,
 	XML document is human-friendly to view through web browsers
 	and its data types are strictly defined.
 	(Trac #547, git 1cbd51919237a6e65983be46e4f5a63d1877b1d3)
@@ -144,11 +175,13 @@
 	reconfigure them.
 	(Trac #775, git 572ac2cf62e18f7eb69d670b890e2a3443bfd6e7)
 
-222.	[bug]		jerry
-	src/lib/zonemgr: Fix a bug that xfrin not checking for new copy of
-	zone on startup.  Imposes some random jitters to avoid many zones
-	need to do refresh at the same time.
-	(Trac #387, svn 9140fab9bab5f6502bd15d391fd51ac078b0b89b)
+222.	[bug]*		jerry
+	src/lib/zonemgr: Fix a bug that xfrin not checking for new
+	copy of zone on startup.  Imposes some random jitters to
+	avoid many zones need to do refresh at the same time. This
+	removed the Zonemgr/jitter_scope setting and introduced
+	Zonemgr/refresh_jitter and Zonemgr/reload_jitter.
+	(Trac #387, git 1241ddcffa16285d0a7bb01d6a8526e19fbb70cb)
 
 221.	[func]*		jerry
 	src/lib/util: Create C++ utility library.

Makefile.am

@@ -38,8 +38,11 @@ report-cpp-coverage:
 			c++/4.4\*/ext/\* \
 			c++/4.4\*/\*-\*/bits/\* \
 			boost/\* \
+			botan/\* \
 			ext/asio/\* \
+			ext/coroutine/\* \
 			gtest/\* \
+			log4cplus/\* \
 			usr/include/\* \
 			tests/\* \
 			unittests/\* \

README

@@ -19,7 +19,9 @@ backends), b10-resolver recursive or forwarding DNS server, b10-cmdctl
 remote control daemon, b10-cfgmgr configuration manager, b10-xfrin
 AXFR inbound service, b10-xfrout outgoing AXFR service, b10-zonemgr
 secondary manager, b10-stats statistics collection and reporting
-daemon, and a new libdns++ library for C++ with a python wrapper.
+daemon, b10-stats-httpd for HTTP access to XML-formatted stats,
+b10-host DNS lookup utility, and a new libdns++ library for C++
+with a python wrapper.
 
 Documentation is included and also available via the BIND 10
 website at http://bind10.isc.org/

configure.ac

@@ -2,7 +2,7 @@
 # Process this file with autoconf to produce a configure script.
 
 AC_PREREQ([2.59])
-AC_INIT(bind10-devel, 20110322, bind10-dev@isc.org)
+AC_INIT(bind10-devel, 20110519, bind10-dev@isc.org)
 AC_CONFIG_SRCDIR(README)
 AM_INIT_AUTOMAKE
 AC_CONFIG_HEADERS([config.h])
@@ -824,7 +824,6 @@ AC_CONFIG_FILES([Makefile
                  src/lib/server_common/tests/Makefile
                  src/lib/util/Makefile
                  src/lib/util/io/Makefile
-                 src/lib/util/io/tests/Makefile
                  src/lib/util/unittests/Makefile
                  src/lib/util/pyunittests/Makefile
                  src/lib/util/tests/Makefile

doc/guide/bind10-guide.xml

@@ -79,12 +79,24 @@
         3.1 is the minimum version which will work.
       </para>
 
-      <note><para>
+      <para>
+	BIND 10 uses the Botan crypto library for C++. It requires
+	at least Botan version 1.8. To build BIND 10, install the
+	Botan libraries and development include headers.
+      </para>
+
+<!--
+TODO
+Debian and Ubuntu:
+ libgmp3-dev and libbz2-dev required for botan too
+-->
+
+      <para>
 	The authoritative server requires SQLite 3.3.9 or newer.
 	The <command>b10-xfrin</command>, <command>b10-xfrout</command>,
 	and <command>b10-zonemgr</command> modules require the
 	libpython3 library and the Python _sqlite3.so module.
-      </para></note>
+      </para>
 <!-- TODO: this will change ... -->
 
 <!-- TODO: list where to get these from -->

src/bin/auth/Makefile.am

@@ -51,11 +51,10 @@ b10_auth_LDADD += $(top_builddir)/src/lib/cc/libcc.la
 b10_auth_LDADD += $(top_builddir)/src/lib/exceptions/libexceptions.la
 b10_auth_LDADD += $(top_builddir)/src/lib/asiodns/libasiodns.la
 b10_auth_LDADD += $(top_builddir)/src/lib/asiolink/libasiolink.la
-b10_auth_LDADD += $(top_builddir)/src/lib/nsas/libnsas.la
+b10_auth_LDADD += $(top_builddir)/src/lib/log/liblog.la
 b10_auth_LDADD += $(top_builddir)/src/lib/xfr/libxfr.la
 b10_auth_LDADD += $(top_builddir)/src/lib/server_common/libserver_common.la
 b10_auth_LDADD += $(SQLITE_LIBS)
-b10_auth_LDFLAGS = $(LOG4CPLUS_LDFLAGS)
 
 # TODO: config.h.in is wrong because doesn't honor pkgdatadir
 # and can't use @datadir@ because doesn't expand default ${prefix}

src/bin/auth/auth_config.cc

@@ -60,6 +60,15 @@ private:
     set<string> configured_sources_;
 };
 
+/// A derived \c AuthConfigParser for the version value
+/// (which is not used at this moment)
+class VersionConfig : public AuthConfigParser {
+public:
+    VersionConfig() {}
+    virtual void build(ConstElementPtr) {};
+    virtual void commit() {};
+};
+
 void
 DatasourcesConfig::build(ConstElementPtr config_value) {
     BOOST_FOREACH(ConstElementPtr datasrc_elem, config_value->listValue()) {
@@ -293,6 +302,11 @@ createAuthConfigParser(AuthSrv& server, const std::string& config_id,
         // we may introduce dynamic registration of configuration parsers,
         // and then this test can be done in a cleaner and safer way.
         return (new ThrowerCommitConfig());
+    } else if (config_id == "version") {
+        // Currently, the version identifier is ignored, but it should
+        // later be used to mark backwards incompatible changes in the
+        // config data
+        return (new VersionConfig());
     } else {
         isc_throw(AuthConfigError, "Unknown configuration identifier: " <<
                   config_id);

src/bin/auth/auth_srv.cc

@@ -20,6 +20,7 @@
 #include <cassert>
 #include <iostream>
 #include <vector>
+#include <memory>
 
 #include <boost/bind.hpp>
 
@@ -43,6 +44,7 @@
 #include <dns/rrset.h>
 #include <dns/rrttl.h>
 #include <dns/message.h>
+#include <dns/tsig.h>
 
 #include <datasrc/query.h>
 #include <datasrc/data_source.h>
@@ -73,6 +75,7 @@ using namespace isc::xfr;
 using namespace isc::asiolink;
 using namespace isc::asiodns;
 using namespace isc::server_common::portconfig;
+using boost::shared_ptr;
 
 class AuthSrvImpl {
 private:
@@ -85,11 +88,14 @@ public:
     isc::data::ConstElementPtr setDbFile(isc::data::ConstElementPtr config);
 
     bool processNormalQuery(const IOMessage& io_message, MessagePtr message,
-                            OutputBufferPtr buffer);
+                            OutputBufferPtr buffer,
+                            auto_ptr<TSIGContext> tsig_context);
     bool processAxfrQuery(const IOMessage& io_message, MessagePtr message,
-                          OutputBufferPtr buffer);
+                          OutputBufferPtr buffer,
+                          auto_ptr<TSIGContext> tsig_context);
     bool processNotify(const IOMessage& io_message, MessagePtr message,
-                       OutputBufferPtr buffer);
+                       OutputBufferPtr buffer,
+                       auto_ptr<TSIGContext> tsig_context);
 
     IOService io_service_;
 
@@ -116,6 +122,9 @@ public:
 
     /// Addresses we listen on
     AddressList listen_addresses_;
+
+    /// The TSIG keyring
+    const shared_ptr<TSIGKeyRing>* keyring_;
 private:
     std::string db_file_;
 
@@ -139,6 +148,7 @@ AuthSrvImpl::AuthSrvImpl(const bool use_cache,
     memory_datasrc_class_(RRClass::IN()),
     statistics_timer_(io_service_),
     counters_(verbose_mode_),
+    keyring_(NULL),
     xfrout_connected_(false),
     xfrout_client_(xfrout_client)
 {
@@ -241,7 +251,9 @@ public:
 
 void
 makeErrorMessage(MessagePtr message, OutputBufferPtr buffer,
-                 const Rcode& rcode, const bool verbose_mode)
+                 const Rcode& rcode, const bool verbose_mode,
+                 std::auto_ptr<TSIGContext> tsig_context =
+                 std::auto_ptr<TSIGContext>())
 {
     // extract the parameters that should be kept.
     // XXX: with the current implementation, it's not easy to set EDNS0
@@ -272,7 +284,11 @@ makeErrorMessage(MessagePtr message, OutputBufferPtr buffer,
     message->setRcode(rcode);
 
     MessageRenderer renderer(*buffer);
-    message->toWire(renderer);
+    if (tsig_context.get() != NULL) {
+        message->toWire(renderer, *tsig_context);
+    } else {
+        message->toWire(renderer);
+    }
 
     if (verbose_mode) {
         cerr << "[b10-auth] sending an error response (" <<
@@ -446,29 +462,51 @@ AuthSrv::processMessage(const IOMessage& io_message, MessagePtr message,
     }
 
     // Perform further protocol-level validation.
+    // TSIG first
+    // If this is set to something, we know we need to answer with TSIG as well
+    std::auto_ptr<TSIGContext> tsig_context;
+    const TSIGRecord* tsig_record(message->getTSIGRecord());
+    TSIGError tsig_error(TSIGError::NOERROR());
+
+    // Do we do TSIG?
+    // The keyring can be null if we're in test
+    if (impl_->keyring_ != NULL && tsig_record != NULL) {
+        tsig_context.reset(new TSIGContext(tsig_record->getName(),
+                                           tsig_record->getRdata().
+                                                getAlgorithm(),
+                                           **impl_->keyring_));
+        tsig_error = tsig_context->verify(tsig_record, io_message.getData(),
+                                          io_message.getDataSize());
+    }
 
     bool sendAnswer = true;
-    if (message->getOpcode() == Opcode::NOTIFY()) {
-        sendAnswer = impl_->processNotify(io_message, message, buffer);
+    if (tsig_error != TSIGError::NOERROR()) {
+        makeErrorMessage(message, buffer, tsig_error.toRcode(),
+                         impl_->verbose_mode_, tsig_context);
+    } else if (message->getOpcode() == Opcode::NOTIFY()) {
+        sendAnswer = impl_->processNotify(io_message, message, buffer,
+                                          tsig_context);
     } else if (message->getOpcode() != Opcode::QUERY()) {
         if (impl_->verbose_mode_) {
             cerr << "[b10-auth] unsupported opcode" << endl;
         }
         makeErrorMessage(message, buffer, Rcode::NOTIMP(),
-                         impl_->verbose_mode_);
+                         impl_->verbose_mode_, tsig_context);
     } else if (message->getRRCount(Message::SECTION_QUESTION) != 1) {
         makeErrorMessage(message, buffer, Rcode::FORMERR(),
-                         impl_->verbose_mode_);
+                         impl_->verbose_mode_, tsig_context);
     } else {
         ConstQuestionPtr question = *message->beginQuestion();
         const RRType &qtype = question->getType();
         if (qtype == RRType::AXFR()) {
-            sendAnswer = impl_->processAxfrQuery(io_message, message, buffer);
+            sendAnswer = impl_->processAxfrQuery(io_message, message, buffer,
+                                                 tsig_context);
         } else if (qtype == RRType::IXFR()) {
             makeErrorMessage(message, buffer, Rcode::NOTIMP(),
-                             impl_->verbose_mode_);
+                             impl_->verbose_mode_, tsig_context);
         } else {
-            sendAnswer = impl_->processNormalQuery(io_message, message, buffer);
+            sendAnswer = impl_->processNormalQuery(io_message, message, buffer,
+                                                   tsig_context);
         }
     }
 
@@ -477,7 +515,8 @@ AuthSrv::processMessage(const IOMessage& io_message, MessagePtr message,
 
 bool
 AuthSrvImpl::processNormalQuery(const IOMessage& io_message, MessagePtr message,
-                                OutputBufferPtr buffer)
+                                OutputBufferPtr buffer,
+                                auto_ptr<TSIGContext> tsig_context)
 {
     ConstEDNSPtr remote_edns = message->getEDNS();
     const bool dnssec_ok = remote_edns && remote_edns->getDNSSECAwareness();
@@ -523,7 +562,11 @@ AuthSrvImpl::processNormalQuery(const IOMessage& io_message, MessagePtr message,
     const bool udp_buffer =
         (io_message.getSocket().getProtocol() == IPPROTO_UDP);
     renderer.setLengthLimit(udp_buffer ? remote_bufsize : 65535);
-    message->toWire(renderer);
+    if (tsig_context.get() != NULL) {
+        message->toWire(renderer, *tsig_context);
+    } else {
+        message->toWire(renderer);
+    }
 
     if (verbose_mode_) {
         cerr << "[b10-auth] sending a response ("
@@ -536,7 +579,8 @@ AuthSrvImpl::processNormalQuery(const IOMessage& io_message, MessagePtr message,
 
 bool
 AuthSrvImpl::processAxfrQuery(const IOMessage& io_message, MessagePtr message,
-                              OutputBufferPtr buffer)
+                              OutputBufferPtr buffer,
+                              auto_ptr<TSIGContext> tsig_context)
 {
     // Increment query counter.
     incCounter(io_message.getSocket().getProtocol());
@@ -545,7 +589,8 @@ AuthSrvImpl::processAxfrQuery(const IOMessage& io_message, MessagePtr message,
         if (verbose_mode_) {
             cerr << "[b10-auth] AXFR query over UDP isn't allowed" << endl;
         }
-        makeErrorMessage(message, buffer, Rcode::FORMERR(), verbose_mode_);
+        makeErrorMessage(message, buffer, Rcode::FORMERR(), verbose_mode_,
+                         tsig_context);
         return (true);
     }
 
@@ -572,7 +617,8 @@ AuthSrvImpl::processAxfrQuery(const IOMessage& io_message, MessagePtr message,
             cerr << "[b10-auth] Error in handling XFR request: " << err.what()
                  << endl;
         }
-        makeErrorMessage(message, buffer, Rcode::SERVFAIL(), verbose_mode_);
+        makeErrorMessage(message, buffer, Rcode::SERVFAIL(), verbose_mode_,
+                         tsig_context);
         return (true);
     }
 
@@ -581,7 +627,8 @@ AuthSrvImpl::processAxfrQuery(const IOMessage& io_message, MessagePtr message,
 
 bool
 AuthSrvImpl::processNotify(const IOMessage& io_message, MessagePtr message, 
-                           OutputBufferPtr buffer)
+                           OutputBufferPtr buffer,
+                           std::auto_ptr<TSIGContext> tsig_context)
 {
     // The incoming notify must contain exactly one question for SOA of the
     // zone name.
@@ -590,7 +637,8 @@ AuthSrvImpl::processNotify(const IOMessage& io_message, MessagePtr message,
                 cerr << "[b10-auth] invalid number of questions in notify: "
                      << message->getRRCount(Message::SECTION_QUESTION) << endl;
         }
-        makeErrorMessage(message, buffer, Rcode::FORMERR(), verbose_mode_);
+        makeErrorMessage(message, buffer, Rcode::FORMERR(), verbose_mode_,
+                         tsig_context);
         return (true);
     }
     ConstQuestionPtr question = *message->beginQuestion();
@@ -599,7 +647,8 @@ AuthSrvImpl::processNotify(const IOMessage& io_message, MessagePtr message,
                 cerr << "[b10-auth] invalid question RR type in notify: "
                      << question->getType() << endl;
         }
-        makeErrorMessage(message, buffer, Rcode::FORMERR(), verbose_mode_);
+        makeErrorMessage(message, buffer, Rcode::FORMERR(), verbose_mode_,
+                         tsig_context);
         return (true);
     }
 
@@ -662,7 +711,11 @@ AuthSrvImpl::processNotify(const IOMessage& io_message, MessagePtr message,
     message->setRcode(Rcode::NOERROR());
 
     MessageRenderer renderer(*buffer);
-    message->toWire(renderer);
+    if (tsig_context.get() != NULL) {
+        message->toWire(renderer, *tsig_context);
+    } else {
+        message->toWire(renderer);
+    }
     return (true);
 }
 
@@ -772,3 +825,8 @@ void
 AuthSrv::setDNSService(isc::asiodns::DNSService& dnss) {
     dnss_ = &dnss;
 }
+
+void
+AuthSrv::setTSIGKeyRing(const shared_ptr<TSIGKeyRing>* keyring) {
+    impl_->keyring_ = keyring;
+}

src/bin/auth/auth_srv.h

@@ -44,6 +44,9 @@ class MemoryDataSrc;
 namespace xfr {
 class AbstractXfroutClient;
 }
+namespace dns {
+class TSIGKeyRing;
+}
 }
 
 
@@ -374,6 +377,14 @@ public:
     /// \brief Assign an ASIO DNS Service queue to this Auth object
     void setDNSService(isc::asiodns::DNSService& dnss);
 
+    /// \brief Sets the keyring used for verifying and signing
+    ///
+    /// The parameter is pointer to shared pointer, because the automatic
+    /// reloading routines of tsig keys replace the actual keyring object.
+    /// It is expected the pointer will point to some statically-allocated
+    /// object, it doesn't take ownership of it.
+    void setTSIGKeyRing(const boost::shared_ptr<isc::dns::TSIGKeyRing>*
+                        keyring);
 
 private:
     AuthSrvImpl* impl_;

src/bin/auth/benchmarks/Makefile.am

@@ -27,5 +27,3 @@ query_bench_LDADD += $(top_builddir)/src/lib/asiolink/libasiolink.la
 query_bench_LDADD += $(top_builddir)/src/lib/server_common/libserver_common.la
 query_bench_LDADD += $(SQLITE_LIBS)
 
-query_bench_LDFLAGS = $(LOG4CPLUS_LDFLAGS)
-

src/bin/auth/main.cc

@@ -47,6 +47,7 @@
 #include <asiodns/asiodns.h>
 #include <asiolink/asiolink.h>
 #include <log/dummylog.h>
+#include <server_common/keyring.h>
 
 using namespace std;
 using namespace isc::data;
@@ -152,9 +153,14 @@ main(int argc, char* argv[]) {
         cc_session = new Session(io_service.get_io_service());
         cout << "[b10-auth] Configuration session channel created." << endl;
 
+        // We delay starting listening to new commands/config just before we
+        // go into the main loop to avoid confusion due to mixture of
+        // synchronous and asynchronous operations (this would happen in
+        // initializing TSIG keys below).  Until then all operations on the
+        // CC session will take place synchronously.
         config_session = new ModuleCCSession(specfile, *cc_session,
                                              my_config_handler,
-                                             my_command_handler);
+                                             my_command_handler, false);
         cout << "[b10-auth] Configuration channel established." << endl;
 
         xfrin_session = new Session(io_service.get_io_service());
@@ -190,6 +196,14 @@ main(int argc, char* argv[]) {
             changeUser(uid);
         }
 
+        cout << "[b10-auth] Loading TSIG keys" << endl;
+        isc::server_common::initKeyring(*config_session);
+        auth_server->setTSIGKeyRing(&isc::server_common::keyring);
+
+        // Now start asynchronous read.
+        config_session->start();
+        cout << "[b10-auth] Configuration channel started." << endl;
+
         cout << "[b10-auth] Server started." << endl;
         io_service.run();
 

src/bin/auth/tests/Makefile.am

@@ -37,7 +37,7 @@ run_unittests_SOURCES += change_user_unittest.cc
 run_unittests_SOURCES += statistics_unittest.cc
 run_unittests_SOURCES += run_unittests.cc
 run_unittests_CPPFLAGS = $(AM_CPPFLAGS) $(GTEST_INCLUDES)
-run_unittests_LDFLAGS = $(AM_LDFLAGS) $(GTEST_LDFLAGS) $(LOG4CPLUS_LDFLAGS)
+run_unittests_LDFLAGS = $(AM_LDFLAGS) $(GTEST_LDFLAGS)
 run_unittests_LDADD = $(GTEST_LDADD)
 run_unittests_LDADD += $(SQLITE_LIBS)
 run_unittests_LDADD += $(top_builddir)/src/lib/testutils/libtestutils.la
@@ -52,6 +52,7 @@ run_unittests_LDADD += $(top_builddir)/src/lib/xfr/libxfr.la
 run_unittests_LDADD += $(top_builddir)/src/lib/log/liblog.la
 run_unittests_LDADD += $(top_builddir)/src/lib/server_common/libserver_common.la
 run_unittests_LDADD += $(top_builddir)/src/lib/nsas/libnsas.la
+run_unittests_LDADD += $(top_builddir)/src/lib/util/unittests/libutil_unittests.la
 endif
 
 noinst_PROGRAMS = $(TESTS)

src/bin/auth/tests/auth_srv_unittest.cc

@@ -16,6 +16,8 @@
 
 #include <vector>
 
+#include <boost/shared_ptr.hpp>
+
 #include <gtest/gtest.h>
 
 #include <dns/message.h>
@@ -25,8 +27,10 @@
 #include <dns/rrtype.h>
 #include <dns/rrttl.h>
 #include <dns/rdataclass.h>
+#include <dns/tsig.h>
 
 #include <server_common/portconfig.h>
+#include <server_common/keyring.h>
 
 #include <datasrc/memory_datasrc.h>
 #include <auth/auth_srv.h>
@@ -50,6 +54,7 @@ using namespace isc::asiolink;
 using namespace isc::testutils;
 using namespace isc::server_common::portconfig;
 using isc::UnitTestUtil;
+using boost::shared_ptr;
 
 namespace {
 const char* const CONFIG_TESTDB =
@@ -242,6 +247,139 @@ TEST_F(AuthSrvTest, AXFRSuccess) {
     EXPECT_TRUE(xfrout.isConnected());
 }
 
+// Try giving the server a TSIG signed request and see it can anwer signed as
+// well
+TEST_F(AuthSrvTest, TSIGSigned) {
+    // Prepare key, the client message, etc
+    const TSIGKey key("key:c2VjcmV0Cg==:hmac-sha1");
+    TSIGContext context(key);
+    UnitTestUtil::createRequestMessage(request_message, opcode, default_qid,
+                         Name("version.bind"), RRClass::CH(), RRType::TXT());
+    createRequestPacket(request_message, IPPROTO_UDP, &context);
+
+    // Run the message through the server
+    shared_ptr<TSIGKeyRing> keyring(new TSIGKeyRing);
+    keyring->add(key);
+    server.setTSIGKeyRing(&keyring);
+    server.processMessage(*io_message, parse_message, response_obuffer,
+                          &dnsserv);
+
+    // What did we get?
+    EXPECT_TRUE(dnsserv.hasAnswer());
+    headerCheck(*parse_message, default_qid, Rcode::NOERROR(),
+                opcode.getCode(), QR_FLAG | AA_FLAG, 1, 1, 1, 0);
+    // We need to parse the message ourself, or getTSIGRecord won't work
+    InputBuffer ib(response_obuffer->getData(), response_obuffer->getLength());
+    Message m(Message::PARSE);
+    m.fromWire(ib);
+
+    const TSIGRecord* tsig = m.getTSIGRecord();
+    ASSERT_TRUE(tsig != NULL) << "Missing TSIG signature";
+    TSIGError error(context.verify(tsig, response_obuffer->getData(),
+                                   response_obuffer->getLength()));
+    EXPECT_EQ(TSIGError::NOERROR(), error) <<
+        "The server signed the response, but it doesn't seem to be valid";
+}
+
+// Give the server a signed request, but don't give it the key. It will
+// not be able to verify it, returning BADKEY
+TEST_F(AuthSrvTest, TSIGSignedBadKey) {
+    TSIGKey key("key:c2VjcmV0Cg==:hmac-sha1");
+    TSIGContext context(key);
+    UnitTestUtil::createRequestMessage(request_message, opcode, default_qid,
+                         Name("version.bind"), RRClass::CH(), RRType::TXT());
+    createRequestPacket(request_message, IPPROTO_UDP, &context);
+
+    // Process the message, but use a different key there
+    shared_ptr<TSIGKeyRing> keyring(new TSIGKeyRing);
+    server.setTSIGKeyRing(&keyring);
+    server.processMessage(*io_message, parse_message, response_obuffer,
+                          &dnsserv);
+
+    EXPECT_TRUE(dnsserv.hasAnswer());
+    headerCheck(*parse_message, default_qid, TSIGError::BAD_KEY().toRcode(),
+                opcode.getCode(), QR_FLAG, 1, 0, 0, 0);
+    // We need to parse the message ourself, or getTSIGRecord won't work
+    InputBuffer ib(response_obuffer->getData(), response_obuffer->getLength());
+    Message m(Message::PARSE);
+    m.fromWire(ib);
+
+    const TSIGRecord* tsig = m.getTSIGRecord();
+    ASSERT_TRUE(tsig != NULL) <<
+        "Missing TSIG signature (we should have one even at error)";
+    EXPECT_EQ(TSIGError::BAD_KEY_CODE, tsig->getRdata().getError());
+    EXPECT_EQ(0, tsig->getRdata().getMACSize()) <<
+        "It should be unsigned with this error";
+}
+
+// Give the server a signed request, but signed by a different key
+// (with the same name). It should return BADSIG
+TEST_F(AuthSrvTest, TSIGBadSig) {
+    TSIGKey key("key:c2VjcmV0Cg==:hmac-sha1");
+    TSIGContext context(key);
+    UnitTestUtil::createRequestMessage(request_message, opcode, default_qid,
+                         Name("version.bind"), RRClass::CH(), RRType::TXT());
+    createRequestPacket(request_message, IPPROTO_UDP, &context);
+
+    // Process the message, but use a different key there
+    shared_ptr<TSIGKeyRing> keyring(new TSIGKeyRing);
+    keyring->add(TSIGKey("key:QkFECg==:hmac-sha1"));
+    server.setTSIGKeyRing(&keyring);
+    server.processMessage(*io_message, parse_message, response_obuffer,
+                          &dnsserv);
+
+    EXPECT_TRUE(dnsserv.hasAnswer());
+    headerCheck(*parse_message, default_qid, TSIGError::BAD_SIG().toRcode(),
+                opcode.getCode(), QR_FLAG, 1, 0, 0, 0);
+    // We need to parse the message ourself, or getTSIGRecord won't work
+    InputBuffer ib(response_obuffer->getData(), response_obuffer->getLength());
+    Message m(Message::PARSE);
+    m.fromWire(ib);
+
+    const TSIGRecord* tsig = m.getTSIGRecord();
+    ASSERT_TRUE(tsig != NULL) <<
+        "Missing TSIG signature (we should have one even at error)";
+    EXPECT_EQ(TSIGError::BAD_SIG_CODE, tsig->getRdata().getError());
+    EXPECT_EQ(0, tsig->getRdata().getMACSize()) <<
+        "It should be unsigned with this error";
+}
+
+// Give the server a signed unsupported request with a bad signature.
+// This checks the server first verifies the signature before anything
+// else.
+TEST_F(AuthSrvTest, TSIGCheckFirst) {
+    TSIGKey key("key:c2VjcmV0Cg==:hmac-sha1");
+    TSIGContext context(key);
+    // Pass a wrong opcode there. The server shouldn't know what to do
+    // about it.
+    UnitTestUtil::createRequestMessage(request_message, Opcode::RESERVED14(),
+                                       default_qid, Name("version.bind"),
+                                       RRClass::CH(), RRType::TXT());
+    createRequestPacket(request_message, IPPROTO_UDP, &context);
+
+    // Process the message, but use a different key there
+    shared_ptr<TSIGKeyRing> keyring(new TSIGKeyRing);
+    keyring->add(TSIGKey("key:QkFECg==:hmac-sha1"));
+    server.setTSIGKeyRing(&keyring);
+    server.processMessage(*io_message, parse_message, response_obuffer,
+                          &dnsserv);
+
+    EXPECT_TRUE(dnsserv.hasAnswer());
+    headerCheck(*parse_message, default_qid, TSIGError::BAD_SIG().toRcode(),
+                Opcode::RESERVED14().getCode(), QR_FLAG, 0, 0, 0, 0);
+    // We need to parse the message ourself, or getTSIGRecord won't work
+    InputBuffer ib(response_obuffer->getData(), response_obuffer->getLength());
+    Message m(Message::PARSE);
+    m.fromWire(ib);
+
+    const TSIGRecord* tsig = m.getTSIGRecord();
+    ASSERT_TRUE(tsig != NULL) <<
+        "Missing TSIG signature (we should have one even at error)";
+    EXPECT_EQ(TSIGError::BAD_SIG_CODE, tsig->getRdata().getError());
+    EXPECT_EQ(0, tsig->getRdata().getMACSize()) <<
+        "It should be unsigned with this error";
+}
+
 TEST_F(AuthSrvTest, AXFRConnectFail) {
     EXPECT_FALSE(xfrout.isConnected()); // check prerequisite
     xfrout.disableConnect();

src/bin/auth/tests/config_unittest.cc

@@ -74,6 +74,13 @@ TEST_F(AuthConfigTest, databaseConfig) {
                             "{\"database_file\": \"should_be_ignored\"}")));
 }
 
+TEST_F(AuthConfigTest, versionConfig) {
+    // make sure it does not throw on 'version'
+    EXPECT_NO_THROW(configureAuthServer(
+                        server,
+                        Element::fromJSON("{\"version\": 0}")));
+}
+
 TEST_F(AuthConfigTest, exceptionGuarantee) {
     EXPECT_EQ(AuthSrv::MemoryDataSrcPtr(), server.getMemoryDataSrc(rrclass));
     // This configuration contains an invalid item, which will trigger

src/bin/auth/tests/run_unittests.cc

@@ -13,6 +13,7 @@
 // PERFORMANCE OF THIS SOFTWARE.
 
 #include <gtest/gtest.h>
+#include <util/unittests/run_all.h>
 
 #include <dns/tests/unittest_util.h>
 
@@ -22,5 +23,5 @@ main(int argc, char* argv[]) {
     isc::UnitTestUtil::addDataPath(TEST_DATA_DIR);
     isc::UnitTestUtil::addDataPath(TEST_DATA_BUILDDIR);
 
-    return (RUN_ALL_TESTS());
+    return (isc::util::unittests::run_all());
 }

src/bin/resolver/Makefile.am

@@ -18,10 +18,12 @@ endif
 
 pkglibexecdir = $(libexecdir)/@PACKAGE@
 
-CLEANFILES = *.gcno *.gcda resolver.spec spec_config.h
+CLEANFILES  = *.gcno *.gcda
+CLEANFILES += resolver.spec spec_config.h
+CLEANFILES += resolverdef.cc resolverdef.h
 
 man_MANS = b10-resolver.8
-EXTRA_DIST = $(man_MANS) b10-resolver.xml
+EXTRA_DIST = $(man_MANS) b10-resolver.xml resolverdef.mes
 
 if ENABLE_MAN
 
@@ -36,13 +38,24 @@ resolver.spec: resolver.spec.pre
 spec_config.h: spec_config.h.pre
 	$(SED) -e "s|@@LOCALSTATEDIR@@|$(localstatedir)|" spec_config.h.pre >$@
 
-BUILT_SOURCES = spec_config.h 
+# 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/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
 b10_resolver_SOURCES += main.cc
+
+nodist_b10_resolver_SOURCES = resolverdef.cc resolverdef.h
+
+
 b10_resolver_LDADD =  $(top_builddir)/src/lib/dns/libdns++.la
 b10_resolver_LDADD += $(top_builddir)/src/lib/config/libcfgclient.la
 b10_resolver_LDADD += $(top_builddir)/src/lib/cc/libcc.la
@@ -56,7 +69,7 @@ b10_resolver_LDADD += $(top_builddir)/src/lib/cache/libcache.la
 b10_resolver_LDADD += $(top_builddir)/src/lib/nsas/libnsas.la
 b10_resolver_LDADD += $(top_builddir)/src/lib/resolve/libresolve.la
 b10_resolver_LDADD += $(top_builddir)/src/bin/auth/change_user.o
-b10_resolver_LDFLAGS = -pthread $(LOG4CPLUS_LDFLAGS)
+b10_resolver_LDFLAGS = -pthread
 
 # TODO: config.h.in is wrong because doesn't honor pkgdatadir
 # and can't use @datadir@ because doesn't expand default ${prefix}

src/bin/resolver/main.cc

@@ -52,13 +52,14 @@
 #include <cache/resolver_cache.h>
 #include <nsas/nameserver_address_store.h>
 
-#include <log/dummylog.h>
+#include <log/logger_support.h>
+#include <log/logger_level.h>
+#include "resolver_log.h"
 
 using namespace std;
 using namespace isc::cc;
 using namespace isc::config;
 using namespace isc::data;
-using isc::log::dlog;
 using namespace isc::asiodns;
 using namespace isc::asiolink;
 
@@ -79,7 +80,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") {
@@ -100,7 +101,7 @@ usage() {
 
 int
 main(int argc, char* argv[]) {
-    isc::log::dprefix = "b10-resolver";
+    bool verbose = false;
     int ch;
     const char* uid = NULL;
 
@@ -110,7 +111,7 @@ main(int argc, char* argv[]) {
             uid = optarg;
             break;
         case 'v':
-            isc::log::denabled = true;
+            verbose = true;
             break;
         case '?':
         default:
@@ -122,13 +123,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];
-        }
-        dlog(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),
+                         isc::log::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;
 
@@ -144,7 +150,7 @@ main(int argc, char* argv[]) {
         }
 
         resolver = boost::shared_ptr<Resolver>(new Resolver());
-        dlog("Server created.");
+        LOG_DEBUG(resolver_logger, RESOLVER_DBG_INIT, RESOLVER_CREATED);
 
         SimpleCallback* checkin = resolver->getCheckinProvider();
         DNSLookup* lookup = resolver->getDNSLookupProvider();
@@ -197,15 +203,13 @@ main(int argc, char* argv[]) {
         
         DNSService dns_service(io_service, checkin, lookup, answer);
         resolver->setDNSService(dns_service);
-        dlog("IOService created.");
+        LOG_DEBUG(resolver_logger, RESOLVER_DBG_INIT, RESOLVER_SERVICE);
 
         cc_session = new Session(io_service.get_io_service());
-        dlog("Configuration session channel created.");
-
         config_session = new ModuleCCSession(specfile, *cc_session,
                                              my_config_handler,
                                              my_command_handler);
-        dlog("Configuration channel established.");
+        LOG_DEBUG(resolver_logger, RESOLVER_DBG_INIT, RESOLVER_CONFIGCHAN);
 
         // FIXME: This does not belong here, but inside Boss
         if (uid != NULL) {
@@ -213,17 +217,18 @@ main(int argc, char* argv[]) {
         }
 
         resolver->setConfigSession(config_session);
-        dlog("Config loaded");
+        LOG_DEBUG(resolver_logger, RESOLVER_DBG_INIT, RESOLVER_CONFIGLOAD);
 
-        dlog("Server started.");
+        LOG_INFO(resolver_logger, RESOLVER_STARTED);
         io_service.run();
     } catch (const std::exception& ex) {
-        dlog(string("Server failed: ") + ex.what(),true);
+        LOG_FATAL(resolver_logger, RESOLVER_FAILED).arg(ex.what());
         ret = 1;
     }
 
     delete config_session;
     delete cc_session;
 
+    LOG_INFO(resolver_logger, RESOLVER_SHUTDOWN);
     return (ret);
 }

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;
@@ -85,7 +83,7 @@ public:
                     isc::cache::ResolverCache& cache)
     {
         assert(!rec_query_); // queryShutdown must be called first
-        dlog("Query setup");
+        LOG_DEBUG(resolver_logger, RESOLVER_DBG_INIT, RESOLVER_QUSETUP);
         rec_query_ = new RecursiveQuery(dnss, 
                                         nsas, cache,
                                         upstream_,
@@ -101,7 +99,7 @@ public:
         // (this is not a safety check, just to prevent logging of
         // actions that are not performed
         if (rec_query_) {
-            dlog("Query shutdown");
+            LOG_DEBUG(resolver_logger, RESOLVER_DBG_INIT, RESOLVER_QUSHUT);
             delete rec_query_;
             rec_query_ = NULL;
         }
@@ -113,13 +111,12 @@ public:
         upstream_ = upstream;
         if (dnss) {
             if (!upstream_.empty()) {
-                dlog("Setting forward addresses:");
                 BOOST_FOREACH(const AddressPair& address, upstream) {
-                    dlog(" " + address.first + ":" +
-                        boost::lexical_cast<string>(address.second));
+                    LOG_INFO(resolver_logger, RESOLVER_FWDADDR)
+                             .arg(address.first).arg(address.second);
                 }
             } else {
-                dlog("No forward addresses, running in recursive mode");
+                LOG_INFO(resolver_logger, RESOLVER_RECURSIVE);
             }
         }
     }
@@ -130,13 +127,12 @@ public:
         upstream_root_ = upstream_root;
         if (dnss) {
             if (!upstream_root_.empty()) {
-                dlog("Setting root addresses:");
                 BOOST_FOREACH(const AddressPair& address, upstream_root) {
-                    dlog(" " + address.first + ":" +
-                        boost::lexical_cast<string>(address.second));
+                    LOG_INFO(resolver_logger, RESOLVER_ROOTADDR)
+                             .arg(address.first).arg(address.second);
                 }
             } else {
-                dlog("No root addresses");
+                LOG_WARN(resolver_logger, RESOLVER_NOROOTADDR);
             }
         }
     }
@@ -186,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_;
@@ -234,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
@@ -312,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);
     }
 };
 
@@ -335,9 +324,12 @@ private:
 
 Resolver::Resolver() :
     impl_(new ResolverImpl()),
+    dnss_(NULL),
     checkin_(new ConfigCheck(this)),
     dns_lookup_(new MessageLookup(this)),
     dns_answer_(new MessageAnswer),
+    nsas_(NULL),
+    cache_(NULL),
     configured_(false)
 {}
 
@@ -391,21 +383,26 @@ Resolver::processMessage(const IOMessage& io_message,
                          OutputBufferPtr buffer,
                          DNSServer* server)
 {
-    dlog("Got a DNS 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)) {
-            dlog("Received unexpected response, ignoring");
+            LOG_DEBUG(resolver_logger, RESOLVER_DBG_IO, RESOLVER_UNEXRESP);
             server->resume(false);
             return;
         }
+
     } catch (const Exception& ex) {
-        dlog(string("DNS packet exception: ") + ex.what(),true);
+        LOG_DEBUG(resolver_logger, RESOLVER_DBG_IO, RESOLVER_HDRERR)
+                  .arg(ex.what());
         server->resume(false);
         return;
     }
@@ -414,37 +411,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);
 
     // 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());
         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 +461,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 +517,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);
 
     try {
         // Parse forward_addresses
@@ -530,6 +560,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 +568,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 +576,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 +629,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 +673,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/lib/util/io/tests/run_unittests.cc

@@ -12,11 +12,8 @@
 // OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
 // PERFORMANCE OF THIS SOFTWARE.
 
-#include <gtest/gtest.h>
+/// Defines the logger used by the NSAS
 
-int
-main(int argc, char *argv[]) {
-    ::testing::InitGoogleTest(&argc, argv);
+#include "resolver_log.h"
 
-    return RUN_ALL_TESTS();
-}
+isc::log::Logger resolver_logger("resolver");

src/bin/resolver/resolver_log.h

@@ -0,0 +1,49 @@
+// 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 __RESOLVER_LOG__H
+#define __RESOLVER_LOG__H
+
+#include <log/macros.h>
+#include "resolverdef.h"
+
+/// \brief Resolver Logging
+///
+/// Defines the levels used to output debug messages in the resolver.  Note that
+/// higher numbers equate to more verbose (and detailed) output.
+
+// Initialization
+const int RESOLVER_DBG_INIT = 10;
+
+// Configuration messages
+const int RESOLVER_DBG_CONFIG = 30;
+
+// Trace sending and receiving of messages
+const int RESOLVER_DBG_IO = 50;
+
+// Trace processing of messages
+const int RESOLVER_DBG_PROCESS = 70;
+
+// Detailed message information
+const int RESOLVER_DBG_DETAIL = 90;
+
+
+/// \brief Resolver 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 resolver_logger;
+
+#endif // __RESOLVER_LOG__H

src/bin/resolver/resolverdef.mes

@@ -0,0 +1,193 @@
+# 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 RESOLVER_
+# No namespace declaration - these constants go in the global namespace
+# along with the resolver methods.
+
+% AXFRTCP       AXFR request received over TCP
+A debug message, the resolver received a NOTIFY message over TCP.  The server
+cannot process it and will return an error message to the sender with the
+RCODE set to NOTIMP.
+
+% AXFRUDP       AXFR request received over UDP
+A debug message, the resolver received a NOTIFY message over UDP.  The server
+cannot process it (and in any case, an AXFR request should be sent over TCP)
+and will return an error message to the sender with the RCODE set to FORMERR.
+
+% CONFIGCHAN    configuration channel created
+A debug message, output when the resolver has successfully established a
+connection to the configuration channel.
+
+% CONFIGERR     error in configuration: %1
+An error was detected in a configuration update received by the resolver. This
+may be in the format of the configuration message (in which case this is a
+programming error) or it may be in the data supplied (in which case it is
+a user error).  The reason for the error, given as a parameter in the message,
+will give more details.
+
+% CONFIGLOAD    configuration loaded
+A debug message, output when the resolver configuration has been successfully
+loaded.
+
+% CONFIGUPD     configuration updated: %1
+A debug message, the configuration has been updated with the specified
+information.
+
+% DNSMSGRCVD    DNS message received: %1
+A debug message, this always precedes some other logging message and is the
+formatted contents of the DNS packet that the other message refers to.
+
+% DNSMSGSENT    DNS message of %1 bytes sent: %2
+A debug message, this contains details of the response sent back to the querying
+system.
+
+% CLTMOSMALL    client timeout of %1 is too small
+An error indicating that the configuration value specified for the query
+timeout is too small.
+
+% CREATED       main resolver object created
+A debug message, output when the Resolver() object has been created.
+
+% FAILED        resolver failed, reason: %1
+This is an error message output when an unhandled exception is caught by the
+resolver.  All it can do is to shut down.
+
+% FWDADDR       setting forward address %1(%2)
+This message may appear multiple times during startup, and it lists the
+forward addresses used by the resolver when running in forwarding mode.
+
+% FWDQUERY      processing forward query
+The received query has passed all checks and is being forwarded to upstream
+servers.
+
+% HDRERR        message received, exception when processing header: %1
+A debug message noting that an exception occurred during the processing of
+a received packet.  The packet has been dropped.
+
+% IXFR          IXFR request received
+The resolver received a NOTIFY message over TCP.  The server cannot process it
+and will return an error message to the sender with the RCODE set to NOTIMP.
+
+% LKTMOSMALL    lookup timeout of %1 is too small
+An error indicating that the configuration value specified for the lookup
+timeout is too small.
+
+% NFYNOTAUTH    NOTIFY arrived but server is not authoritative
+The resolver received a NOTIFY message.  As the server is not authoritative it
+cannot process it, so it returns an error message to the sender with the RCODE
+set to NOTAUTH.
+
+% NORMQUERY     processing normal query
+The received query has passed all checks and is being processed by the resolver.
+
+% NOTIN         non-IN class request received, returning REFUSED message
+A debug message, the resolver has received a DNS packet that was not IN class.
+The resolver cannot handle such packets, so is returning a REFUSED response to
+the sender.
+
+% NOROOTADDR    no root addresses available
+A warning message during startup, indicates that no root addresses have been
+set.  This may be because the resolver will get them from a priming query.
+
+% NOTONEQUES    query contained %1 questions, exactly one question was expected
+A debug message, the resolver received a query that contained the number of
+entires in the question section detailed in the message.  This is a malformed
+message, as a DNS query must contain only one question.  The resolver will
+return a message to the sender with the RCODE set to FORMERR.
+
+% OPCODEUNS     opcode %1 not supported by the resolver
+A debug message, the resolver received a message with an unsupported opcode
+(it can only process QUERY opcodes).  It will return a message to the sender
+with the RCODE set to NOTIMP.
+
+% PARSEERR      error parsing received message: %1 - returning %2
+A debug message noting that the resolver received a message and the parsing
+of the body of the message failed due to some non-protocol related reason
+(although the parsing of the header succeeded).  The message parameters give
+a textual description of the problem and the RCODE returned.
+
+% PRINTMSG      print message command, aeguments are: %1
+This message is logged when a "print_message" command is received over the
+command channel.
+
+% PROTERR       protocol error parsing received message: %1 - returning %2
+A debug message noting that the resolver received a message and the parsing
+of the body of the message failed due to some protocol error (although the
+parsing of the header succeeded).  The message parameters give a textual
+description of the problem and the RCODE returned.
+
+% QUSETUP       query setup
+A debug message noting that the resolver is creating a RecursiveQuery object.
+
+% QUSHUT        query shutdown
+A debug message noting that the resolver is destroying a RecursiveQuery object.
+
+% QUTMOSMALL    query timeout of %1 is too small
+An error indicating that the configuration value specified for the query
+timeout is too small.
+
+% RECURSIVE     running in recursive mode
+This is an informational message that appears at startup noting that the
+resolver is running in recursive mode.
+
+% RECVMSG       resolver has received a DNS message
+A debug message indicating that the resolver has received a message.  Depending
+on the debug settings, subsequent log output will indicate the nature of the
+message.
+
+% RETRYNEG      negative number of retries (%1) specified in the configuration
+An error message indicating that the resolver configuration has specified a
+negative retry count.  Only zero or positive values are valid.
+
+% ROOTADDR      setting root address %1(%2)
+This message may appear multiple times during startup; it lists the root
+addresses used by the resolver.
+
+% SERVICE       service object created
+A debug message, output when the main service object (which handles the
+received queries) is created.
+
+% SETPARAM      query timeout: %1, client timeout: %2, lookup timeout: %3, retry count: %4
+A debug message, lists the parameters associated with the message.  These are:
+query timeout: the timeout (in ms) used for queries originated by the resolver
+to upstream servers.  Client timeout: the interval to resolver a query by
+a client: after this time, the resolver sends back a SERVFAIL to the client
+whilst continuing to resolver the query. Lookup timeout: the time at which the
+resolver gives up trying to resolve a query.  Retry count: the number of times
+the resolver will retry a query to an upstream server if it gets a timeout.
+
+The client and lookup timeouts require a bit more explanation. The
+resolution of the clent query might require a large number of queries to
+upstream nameservers.  Even if none of these queries timeout, the total time
+taken to perform all the queries may exceed the client timeout.  When this
+happens, a SERVFAIL is returned to the client, but the resolver continues
+with the resolution process. Data received is added to the cache.  However,
+there comes a time - the lookup timeout - when even the resolve gives up.
+At this point it will wait for pending upstream queries to complete or
+timeout and drop the query.
+
+% SHUTDOWN      resolver shutdown complete
+This information message is output when the resolver has shut down.
+
+% STARTED       resolver started
+This informational message is output by the resolver when all initialization
+has been completed and it is entering its main loop.
+
+% STARTING      starting resolver with command line '%1'
+An informational message, this is output when the resolver starts up.
+
+% UNEXRESP      received unexpected response, ignoring
+A debug message noting that the server has received a response instead of a
+query and is ignoring it.

src/bin/resolver/tests/Makefile.am

@@ -1,6 +1,7 @@
 AM_CPPFLAGS = -I$(top_srcdir)/src/lib -I$(top_builddir)/src/lib
 AM_CPPFLAGS += -I$(top_builddir)/src/lib/dns -I$(top_srcdir)/src/bin
 AM_CPPFLAGS += -I$(top_builddir)/src/lib/cc
+AM_CPPFLAGS += -I$(top_builddir)/src/bin/resolver
 AM_CPPFLAGS += -DTEST_DATA_DIR=\"$(top_srcdir)/src/lib/testutils/testdata\"
 AM_CPPFLAGS += -DTEST_DATA_BUILDDIR=\"$(abs_top_builddir)/src/lib/testutils/testdata\"
 AM_CPPFLAGS += $(BOOST_INCLUDES)
@@ -16,17 +17,23 @@ 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 += ../response_scrubber.h ../response_scrubber.cc
 run_unittests_SOURCES += resolver_unittest.cc
 run_unittests_SOURCES += resolver_config_unittest.cc
 run_unittests_SOURCES += response_scrubber_unittest.cc
 run_unittests_SOURCES += run_unittests.cc
+
+nodist_run_unittests_SOURCES = ../resolverdef.h ../resolverdef.cc
+
 run_unittests_CPPFLAGS = $(AM_CPPFLAGS) $(GTEST_INCLUDES)
-run_unittests_LDFLAGS = $(AM_LDFLAGS) $(GTEST_LDFLAGS) $(LOG4CPLUS_LDFLAGS)
-run_unittests_LDADD = $(GTEST_LDADD)
+run_unittests_LDFLAGS  = $(AM_LDFLAGS)  $(GTEST_LDFLAGS)
+
+run_unittests_LDADD  = $(GTEST_LDADD)
 run_unittests_LDADD += $(SQLITE_LIBS)
 run_unittests_LDADD += $(top_builddir)/src/lib/testutils/libtestutils.la
 run_unittests_LDADD += $(top_builddir)/src/lib/datasrc/libdatasrc.la
@@ -42,6 +49,7 @@ run_unittests_LDADD += $(top_builddir)/src/lib/server_common/libserver_common.la
 run_unittests_LDADD += $(top_builddir)/src/lib/cache/libcache.la
 run_unittests_LDADD += $(top_builddir)/src/lib/nsas/libnsas.la
 run_unittests_LDADD += $(top_builddir)/src/lib/resolve/libresolve.la
+run_unittests_LDADD += $(top_builddir)/src/lib/util/unittests/libutil_unittests.la
 
 # Note the ordering matters: -Wno-... must follow -Wextra (defined in
 # B10_CXXFLAGS

src/bin/resolver/tests/run_unittests.cc

@@ -13,6 +13,7 @@
 // PERFORMANCE OF THIS SOFTWARE.
 
 #include <gtest/gtest.h>
+#include <util/unittests/run_all.h>
 
 #include <dns/tests/unittest_util.h>
 
@@ -22,5 +23,5 @@ main(int argc, char* argv[]) {
     isc::UnitTestUtil::addDataPath(TEST_DATA_DIR);
     isc::UnitTestUtil::addDataPath(TEST_DATA_BUILDDIR);
 
-    return (RUN_ALL_TESTS());
+    return (isc::util::unittests::run_all());
 }

src/bin/sockcreator/tests/Makefile.am

@@ -16,10 +16,9 @@ run_unittests_SOURCES += run_unittests.cc
 
 run_unittests_CPPFLAGS = $(AM_CPPFLAGS) $(GTEST_INCLUDES)
 run_unittests_LDFLAGS = $(AM_LDFLAGS) $(GTEST_LDFLAGS)
-run_unittests_LDADD = $(GTEST_LDADD)
+run_unittests_LDADD  = $(GTEST_LDADD)
+run_unittests_LDADD += $(top_builddir)/src/lib/util/unittests/libutil_unittests.la
 run_unittests_LDADD += $(top_builddir)/src/lib/util/io/libutil_io.la
-run_unittests_LDADD += \
-	$(top_builddir)/src/lib/util/unittests/libutil_unittests.la
 endif
 
 noinst_PROGRAMS = $(TESTS)

src/bin/sockcreator/tests/run_unittests.cc

@@ -13,10 +13,11 @@
 // PERFORMANCE OF THIS SOFTWARE.
 
 #include <gtest/gtest.h>
+#include <util/unittests/run_all.h>
 
 int
 main(int argc, char *argv[]) {
     ::testing::InitGoogleTest(&argc, argv);
 
-    return RUN_ALL_TESTS();
+    return isc::util::unittests::run_all();
 }

src/bin/xfrin/b10-xfrin.8

@@ -2,12 +2,12 @@
 .\"     Title: b10-xfrin
 .\"    Author: [FIXME: author] [see http://docbook.sf.net/el/author]
 .\" Generator: DocBook XSL Stylesheets v1.75.2 <http://docbook.sf.net/>
-.\"      Date: September 8, 2010
+.\"      Date: May 19, 2011
 .\"    Manual: BIND10
 .\"    Source: BIND10
 .\"  Language: English
 .\"
-.TH "B10\-XFRIN" "8" "September 8, 2010" "BIND10" "BIND10"
+.TH "B10\-XFRIN" "8" "May 19, 2011" "BIND10" "BIND10"
 .\" -----------------------------------------------------------------
 .\" * set default formatting
 .\" -----------------------------------------------------------------
@@ -43,7 +43,7 @@ boss process\&. When triggered it can request and receive a zone transfer and st
 .ps -1
 .br
 .sp
-The Y1 prototype release only supports AXFR\&. IXFR is not implemented\&.
+This prototype release only supports AXFR\&. IXFR is not implemented\&.
 .sp .5v
 .RE
 .PP
@@ -61,15 +61,34 @@ receives its configurations from
 .PP
 The configurable settings are:
 .PP
-\fImaster_addr\fR
-The default is 127\&.0\&.0\&.1\&.
-.PP
-\fImaster_port\fR
-The default is 53\&.
-.PP
 \fItransfers\-in\fR
 defines the maximum number of inbound zone transfers that can run concurrently\&. The default is 10\&.
 .PP
+
+\fIzones\fR
+is a list of zones known to the
+\fBb10\-xfrin\fR
+daemon\&. The list items are:
+\fIname\fR
+(the zone name),
+\fImaster_addr\fR
+(the zone master to transfer from),
+\fImaster_port\fR
+(defaults to 53), and
+\fItsig_key\fR
+(optional TSIG key to use)\&. The
+\fItsig_key\fR
+is specified using a full string colon\-delimited name:key:algorithm representation (e\&.g\&.
+\(lqfoo\&.example\&.org:EvABsfU2h7uofnmqaRCrhHunGsd=:hmac\-sha1\(rq)\&.
+.PP
+(The site\-wide
+\fImaster_addr\fR
+and
+\fImaster_port\fR
+configurations are deprecated; use the
+\fIzones\fR
+list configuration instead\&.)
+.PP
 The configuration commands are:
 .PP
 
@@ -106,7 +125,9 @@ to define the class (defaults to
 \fImaster\fR
 to define the IP address of the authoritative server to transfer from, and
 \fIport\fR
-to define the port number on the authoritative server (defaults to 53)\&.
+to define the port number on the authoritative server (defaults to 53)\&. If the address or port is not specified, it will use the values previously defined in the
+\fIzones\fR
+configuration\&.
 .PP
 
 \fBshutdown\fR
@@ -143,5 +164,5 @@ The
 daemon was implemented in March 2010 by Zhang Likun of CNNIC for the ISC BIND 10 project\&.
 .SH "COPYRIGHT"
 .br
-Copyright \(co 2010 Internet Systems Consortium, Inc. ("ISC")
+Copyright \(co 2010-2011 Internet Systems Consortium, Inc. ("ISC")
 .br

src/bin/xfrin/b10-xfrin.xml

@@ -2,7 +2,7 @@
                "http://www.oasis-open.org/docbook/xml/4.2/docbookx.dtd"
 	       [<!ENTITY mdash "&#8212;">]>
 <!--
- - Copyright (C) 2010  Internet Systems Consortium, Inc. ("ISC")
+ - Copyright (C) 2010-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
@@ -20,7 +20,7 @@
 <refentry>
 
   <refentryinfo>
-    <date>September 8, 2010</date>
+    <date>May 19, 2011</date>
   </refentryinfo>
 
   <refmeta>
@@ -36,7 +36,7 @@
 
   <docinfo>
     <copyright>
-      <year>2010</year>
+      <year>2010-2011</year>
       <holder>Internet Systems Consortium, Inc. ("ISC")</holder>
     </copyright>
   </docinfo>
@@ -62,6 +62,12 @@
       the zone in a BIND 10 zone data store.
     </para>
 
+<!-- TODO:
+xfrin only does the transfer to make it as simple as possible.
+The logic for handling transfer triggers or zone management is handled
+in separate zonemgr process.
+-->
+
     <note><simpara>
       This prototype release only supports AXFR. IXFR is not implemented.
     </simpara></note>
@@ -86,20 +92,33 @@
       The configurable settings are:
     </para>
 
-    <para><varname>master_addr</varname>
-<!-- TODO: how can there be a single setting for this? -->
-       The default is 127.0.0.1.
+    <para><varname>transfers-in</varname>
+      defines the maximum number of inbound zone transfers
+      that can run concurrently. The default is 10.
     </para>
 
-    <para><varname>master_port</varname>
-<!-- TODO: what if custom is needed per zone? -->
-      The default is 53.
+<!-- TODO: is name okay for master_addr or just IP? -->
+    <para>
+      <varname>zones</varname> is a list of zones known to the
+      <command>b10-xfrin</command> daemon.
+      The list items are:
+      <varname>name</varname> (the zone name),
+      <varname>master_addr</varname> (the zone master to transfer from),
+      <varname>master_port</varname> (defaults to 53), and
+      <varname>tsig_key</varname> (optional TSIG key to use).
+      The <varname>tsig_key</varname> is specified using a full string
+      colon-delimited name:key:algorithm representation (e.g.
+      <quote>foo.example.org:EvABsfU2h7uofnmqaRCrhHunGsd=:hmac-sha1</quote>).
     </para>
+<!-- TODO: document this better -->
+<!-- TODO: the tsig_key format may change -->
 
-    <para><varname>transfers-in</varname>
-      defines the maximum number of inbound zone transfers
-      that can run concurrently. The default is 10.
+    <para>
+      (The site-wide <varname>master_addr</varname> and
+      <varname>master_port</varname> configurations are deprecated;
+      use the <varname>zones</varname> list configuration instead.)
     </para>
+<!-- NOTE: also tsig_key but not mentioning since so short lived. -->
 
 <!-- TODO: formating -->
     <para>
@@ -148,6 +167,9 @@
       the authoritative server to transfer from,
       and <varname>port</varname> to define the port number on the
       authoritative server (defaults to 53).
+      If the address or port is not specified, it will use the
+      values previously defined in the <varname>zones</varname>
+      configuration.
      </para>
 <!-- TODO: later hostname for master? -->
 

src/bin/xfrin/tests/xfrin_test.py

@@ -149,7 +149,7 @@ class MockXfrinConnection(XfrinConnection):
                              rcode=Rcode.NOERROR(),
                              questions=default_questions,
                              answers=default_answers,
-                             tsig=False):
+                             tsig_ctx=None):
         resp = Message(Message.RENDER)
         qid = self.qid
         if bad_qid:
@@ -163,10 +163,7 @@ class MockXfrinConnection(XfrinConnection):
         [resp.add_rrset(Message.SECTION_ANSWER, a) for a in answers]
 
         renderer = MessageRenderer()
-        if tsig:
-            # for now, we don't need a valid SIG.  We only need to include
-            # TSIG RR.  So how to add it and which key is used don't matter.
-            tsig_ctx = TSIGContext(TSIG_KEY)
+        if tsig_ctx is not None:
             resp.to_wire(renderer, tsig_ctx)
         else:
             resp.to_wire(renderer)
@@ -193,8 +190,8 @@ class TestXfrinConnection(unittest.TestCase):
             'axfr_after_soa': self._create_normal_response_data
             }
         self.axfr_response_params = {
-            'tsig_1st': False,
-            'tsig_2nd': False
+            'tsig_1st': None,
+            'tsig_2nd': None
             }
 
     def tearDown(self):
@@ -202,6 +199,14 @@ class TestXfrinConnection(unittest.TestCase):
         if os.path.exists(TEST_DB_FILE):
             os.remove(TEST_DB_FILE)
 
+    def __create_mock_tsig(self, key, error):
+        # This helper function creates a MockTSIGContext for a given key
+        # and TSIG error to be used as a result of verify (normally faked
+        # one)
+        mock_ctx = MockTSIGContext(key)
+        mock_ctx.error = error
+        return mock_ctx
+
     def test_close(self):
         # we shouldn't be using the global asyncore map.
         self.assertEqual(len(asyncore.socket_map), 0)
@@ -259,7 +264,7 @@ class TestXfrinConnection(unittest.TestCase):
         self.assertEqual(self.conn.query_data, b'\x00\x1d\x105\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x07example\x03com\x00\x00\xfc\x00\x01')
 
         # soa request with tsig
-        self.conn._tsig_ctx = MockTSIGContext(TSIG_KEY)
+        self.conn._tsig_key = TSIG_KEY
         self.conn._send_query(RRType.SOA())
         self.assertTrue(message_has_tsig(self.conn.query_data[2:]))
 
@@ -272,7 +277,7 @@ class TestXfrinConnection(unittest.TestCase):
         self.assertRaises(XfrinTestException, self._handle_xfrin_response)
 
     def test_response_with_tsigfail(self):
-        self.conn._tsig_ctx = MockTSIGContext(TSIG_KEY)
+        self.conn._tsig_key = TSIG_KEY
         # server tsig check fail, return with RCODE 9 (NOTAUTH)
         self.conn._send_query(RRType.SOA())
         self.conn.reply_data = self.conn.create_response_data(rcode=Rcode.NOTAUTH())
@@ -343,32 +348,34 @@ class TestXfrinConnection(unittest.TestCase):
         self.assertRaises(XfrinException, self.conn._check_soa_serial)
 
     def test_soacheck_with_tsig(self):
-        self.conn._tsig_ctx = MockTSIGContext(TSIG_KEY)
+        # Use a mock tsig context emulating a validly signed response
+        self.conn._tsig_key = TSIG_KEY
+        self.conn._tsig_ctx_creator = \
+            lambda key: self.__create_mock_tsig(key, TSIGError.NOERROR)
         self.conn.response_generator = self._create_soa_response_data
-        # emulate a validly signed response
-        self.conn._tsig_ctx.error = TSIGError.NOERROR
         self.assertEqual(self.conn._check_soa_serial(), XFRIN_OK)
         self.assertEqual(self.conn._tsig_ctx.get_error(), TSIGError.NOERROR)
 
     def test_soacheck_with_tsig_notauth(self):
-        self.conn._tsig_ctx = MockTSIGContext(TSIG_KEY)
-
         # emulate a valid error response
+        self.conn._tsig_key = TSIG_KEY
+        self.conn._tsig_ctx_creator = \
+            lambda key: self.__create_mock_tsig(key, TSIGError.BAD_SIG)
         self.soa_response_params['rcode'] = Rcode.NOTAUTH()
         self.conn.response_generator = self._create_soa_response_data
-        self.conn._tsig_ctx.error = TSIGError.BAD_SIG
 
         self.assertRaises(XfrinException, self.conn._check_soa_serial)
 
     def test_soacheck_with_tsig_noerror_badsig(self):
-        self.conn._tsig_ctx = MockTSIGContext(TSIG_KEY)
+        self.conn._tsig_key = TSIG_KEY
+        self.conn._tsig_ctx_creator = \
+            lambda key: self.__create_mock_tsig(key, TSIGError.BAD_SIG)
 
         # emulate a normal response bad verification failure due to BADSIG.
         # According RFC2845, in this case we should ignore it and keep
         # waiting for a valid response until a timeout.  But we immediately
         # treat this as a final failure (just as BIND 9 does).
         self.conn.response_generator = self._create_soa_response_data
-        self.conn._tsig_ctx.error = TSIGError.BAD_SIG
 
         self.assertRaises(XfrinException, self.conn._check_soa_serial)
 
@@ -377,7 +384,7 @@ class TestXfrinConnection(unittest.TestCase):
         # contain a TSIG while we sent a signed query.  RFC2845 states
         # we should wait for a valid response in this case, but we treat
         # it as a fatal transaction failure, too.
-        self.conn._tsig_ctx = TSIGContext(TSIG_KEY)
+        self.conn._tsig_key = TSIG_KEY
         self.conn.response_generator = self._create_soa_response_data
         self.assertRaises(XfrinException, self.conn._check_soa_serial)
 
@@ -424,8 +431,9 @@ class TestXfrinConnection(unittest.TestCase):
     def test_do_xfrin_with_tsig(self):
         # use TSIG with a mock context.  we fake all verify results to
         # emulate successful verification.
-        self.conn._tsig_ctx = MockTSIGContext(TSIG_KEY)
-        self.conn._tsig_ctx.error = TSIGError.NOERROR
+        self.conn._tsig_key = TSIG_KEY
+        self.conn._tsig_ctx_creator = \
+            lambda key: self.__create_mock_tsig(key, TSIGError.NOERROR)
         self.conn.response_generator = self._create_normal_response_data
         self.assertEqual(self.conn.do_xfrin(False), XFRIN_OK)
         # We use two messages in the tests.  The same context should have been
@@ -435,8 +443,9 @@ class TestXfrinConnection(unittest.TestCase):
     def test_do_xfrin_with_tsig_fail(self):
         # TSIG verify will fail for the first message.  xfrin should fail
         # immediately.
-        self.conn._tsig_ctx = MockTSIGContext(TSIG_KEY)
-        self.conn._tsig_ctx.error = TSIGError.BAD_SIG
+        self.conn._tsig_key = TSIG_KEY
+        self.conn._tsig_ctx_creator = \
+            lambda key: self.__create_mock_tsig(key, TSIGError.BAD_SIG)
         self.conn.response_generator = self._create_normal_response_data
         self.assertEqual(self.conn.do_xfrin(False), XFRIN_FAIL)
         self.assertEqual(1, self.conn._tsig_ctx.verify_called)
@@ -449,8 +458,9 @@ class TestXfrinConnection(unittest.TestCase):
             if self.conn._tsig_ctx.verify_called == 1:
                 return TSIGError.NOERROR
             return TSIGError.BAD_SIG
-        self.conn._tsig_ctx = MockTSIGContext(TSIG_KEY)
-        self.conn._tsig_ctx.error = fake_tsig_error
+        self.conn._tsig_key = TSIG_KEY
+        self.conn._tsig_ctx_creator = \
+            lambda key: self.__create_mock_tsig(key, fake_tsig_error)
         self.conn.response_generator = self._create_normal_response_data
         self.assertEqual(self.conn.do_xfrin(False), XFRIN_FAIL)
         self.assertEqual(2, self.conn._tsig_ctx.verify_called)
@@ -458,6 +468,9 @@ class TestXfrinConnection(unittest.TestCase):
     def test_do_xfrin_with_missing_tsig(self):
         # XFR request sent with TSIG, but the response doesn't have TSIG.
         # xfr should fail.
+        self.conn._tsig_key = TSIG_KEY
+        self.conn._tsig_ctx_creator = \
+            lambda key: self.__create_mock_tsig(key, None)
         self.conn._tsig_ctx = MockTSIGContext(TSIG_KEY)
         self.conn.response_generator = self._create_normal_response_data
         self.assertEqual(self.conn.do_xfrin(False), XFRIN_FAIL)
@@ -476,8 +489,9 @@ class TestXfrinConnection(unittest.TestCase):
             if self.conn._tsig_ctx.verify_called == 1:
                 return TSIGError.NOERROR
             return TSIGError.FORMERR
-        self.conn._tsig_ctx = MockTSIGContext(TSIG_KEY)
-        self.conn._tsig_ctx.error = fake_tsig_error
+        self.conn._tsig_key = TSIG_KEY
+        self.conn._tsig_ctx_creator = \
+            lambda key: self.__create_mock_tsig(key, fake_tsig_error)
         self.conn.response_generator = self._create_normal_response_data
         self.assertEqual(self.conn.do_xfrin(False), XFRIN_FAIL)
         self.assertEqual(2, self.conn._tsig_ctx.verify_called)
@@ -485,14 +499,14 @@ class TestXfrinConnection(unittest.TestCase):
     def test_do_xfrin_with_unexpected_tsig(self):
         # XFR request wasn't signed, but response includes TSIG.  Like BIND 9,
         # we reject that.
-        self.axfr_response_params['tsig_1st'] = True
+        self.axfr_response_params['tsig_1st'] = TSIGContext(TSIG_KEY)
         self.conn.response_generator = self._create_normal_response_data
         self.assertEqual(self.conn.do_xfrin(False), XFRIN_FAIL)
 
     def test_do_xfrin_with_unexpected_tsig_for_second_message(self):
         # similar to the previous test, but the first message is normal.
         # the second one contains an unexpected TSIG.  should be rejected.
-        self.axfr_response_params['tsig_2nd'] = True
+        self.axfr_response_params['tsig_2nd'] = TSIGContext(TSIG_KEY)
         self.conn.response_generator = self._create_normal_response_data
         self.assertEqual(self.conn.do_xfrin(False), XFRIN_FAIL)
 
@@ -514,6 +528,23 @@ class TestXfrinConnection(unittest.TestCase):
         self.conn.response_generator = self._create_soa_response_data
         self.assertEqual(self.conn.do_xfrin(True), XFRIN_OK)
 
+    def test_do_soacheck_and_xfrin_with_tsig(self):
+        # We are going to have a SOA query/response transaction, followed by
+        # AXFR, all TSIG signed.  xfrin should use a new TSIG context for
+        # AXFR.  We are not interested in whether verify works correctly in
+        # this test, so we simply fake the results (they need to succeed for
+        # this test)
+        self.conn._tsig_key = TSIG_KEY
+        self.conn._tsig_ctx_creator = \
+            lambda key: self.__create_mock_tsig(key, TSIGError.NOERROR)
+        self.soa_response_params['tsig'] = True
+        self.conn.response_generator = self._create_soa_response_data
+        self.assertEqual(self.conn.do_xfrin(True), XFRIN_OK)
+        # We should've got 3 response messages: 1 SOA and two AXFR, but
+        # the context should be replaced for AXFR, so verify() should be
+        # called only twice for the latest context.
+        self.assertEqual(2, self.conn._tsig_ctx.verify_called)
+
     def test_do_soacheck_broken_response(self):
         self.conn.response_generator = self._create_broken_response_data
         # XXX: TODO: this test failed here, should xfr not raise an
@@ -543,22 +574,37 @@ class TestXfrinConnection(unittest.TestCase):
         # containing just a single SOA RR.
         tsig_1st = self.axfr_response_params['tsig_1st']
         tsig_2nd = self.axfr_response_params['tsig_2nd']
-        self.conn.reply_data = self.conn.create_response_data(tsig=tsig_1st)
-        self.conn.reply_data += self.conn.create_response_data(tsig=tsig_2nd)
+        self.conn.reply_data = self.conn.create_response_data(tsig_ctx=tsig_1st)
+        self.conn.reply_data += \
+            self.conn.create_response_data(tsig_ctx=tsig_2nd)
 
     def _create_soa_response_data(self):
         # This helper method creates a DNS message that is supposed to be
         # used a valid response to SOA queries prior to XFR.
+        # If tsig is True, it tries to verify the query with a locally
+        # created TSIG context (which may or may not succeed) so that the
+        # response will include a TSIG.
         # If axfr_after_soa is True, it resets the response_generator so that
         # a valid XFR messages will follow.
+
+        verify_ctx = None
+        if self.soa_response_params['tsig']:
+            # xfrin (curreently) always uses TCP.  strip off the length field.
+            query_data = self.conn.query_data[2:]
+            query_message = Message(Message.PARSE)
+            query_message.from_wire(query_data)
+            verify_ctx = TSIGContext(TSIG_KEY)
+            verify_ctx.verify(query_message.get_tsig_record(), query_data)
+
         self.conn.reply_data = self.conn.create_response_data(
             bad_qid=self.soa_response_params['bad_qid'],
             response=self.soa_response_params['response'],
             rcode=self.soa_response_params['rcode'],
             questions=self.soa_response_params['questions'],
-            tsig=self.soa_response_params['tsig'])
+            tsig_ctx=verify_ctx)
         if self.soa_response_params['axfr_after_soa'] != None:
-            self.conn.response_generator = self.soa_response_params['axfr_after_soa']
+            self.conn.response_generator = \
+                self.soa_response_params['axfr_after_soa']
 
     def _create_broken_response_data(self):
         # This helper method creates a bogus "DNS message" that only contains

src/bin/xfrin/xfrin.py.in

@@ -134,9 +134,14 @@ class XfrinConnection(asyncore.dispatcher):
         self._shutdown_event = shutdown_event
         self._verbose = verbose
         self._master_address = master_addrinfo[2]
+        self._tsig_key = tsig_key
         self._tsig_ctx = None
-        if tsig_key is not None:
-            self._tsig_ctx = TSIGContext(tsig_key)
+        # tsig_ctx_creator is introduced to allow tests to use a mock class for
+        # easier tests (in normal case we always use the default)
+        self._tsig_ctx_creator = self.__create_tsig_ctx
+
+    def __create_tsig_ctx(self, key):
+        return TSIGContext(key)
 
     def connect_to_master(self):
         '''Connect to master in TCP.'''
@@ -176,7 +181,8 @@ class XfrinConnection(asyncore.dispatcher):
         render = MessageRenderer()
         # XXX Currently, python wrapper doesn't accept 'None' parameter in this case,
         # we should remove the if statement and use a universal interface later.
-        if self._tsig_ctx is not None:
+        if self._tsig_key is not None:
+            self._tsig_ctx = self._tsig_ctx_creator(self._tsig_key)
             msg.to_wire(render, self._tsig_ctx)
         else:
             msg.to_wire(render)

src/bin/zonemgr/b10-zonemgr.8

@@ -2,12 +2,12 @@
 .\"     Title: b10-zonemgr
 .\"    Author: [FIXME: author] [see http://docbook.sf.net/el/author]
 .\" Generator: DocBook XSL Stylesheets v1.75.2 <http://docbook.sf.net/>
-.\"      Date: October 18, 2010
+.\"      Date: May 19, 2011
 .\"    Manual: BIND10
 .\"    Source: BIND10
 .\"  Language: English
 .\"
-.TH "B10\-ZONEMGR" "8" "October 18, 2010" "BIND10" "BIND10"
+.TH "B10\-ZONEMGR" "8" "May 19, 2011" "BIND10" "BIND10"
 .\" -----------------------------------------------------------------
 .\" * set default formatting
 .\" -----------------------------------------------------------------
@@ -46,11 +46,6 @@ receives its configurations from
 The configurable settings are:
 .PP
 
-\fIjitter_scope\fR
-defines the random jitter range subtracted from the refresh and retry timers to avoid many zones from refreshing at the same time\&. The refresh or retry time actually used is a random time between the defined refresh or retry time and it multiplied by the
-\fIjitter_scope\fR\&. This is re\-evaluated after each refresh or retry\&. This value is a real number and the maximum is 0\&.5 (half of the refresh or retry time)\&. The default is 0\&.25\&. Set to 0 to disable the jitter\&.
-.PP
-
 \fIlowerbound_refresh\fR
 defines the minimum SOA REFRESH time in seconds\&. The default is 10\&.
 .PP
@@ -59,10 +54,36 @@ defines the minimum SOA REFRESH time in seconds\&. The default is 10\&.
 defines the minimum SOA RETRY time in seconds\&. The default is 5\&.
 .PP
 
+\fIrefresh_jitter\fR
+This value is a real number\&. The maximum amount is 0\&.5\&. The default is 0\&.25\&.
+.PP
+
+\fIreload_jitter\fR
+This value is a real number\&. The default is 0\&.75\&.
+.PP
+
 \fImax_transfer_timeout\fR
 defines the maximum amount of time in seconds for a transfer\&.
 The default is 14400 (4 hours)\&.
 .PP
+
+\fIsecondary_zones\fR
+is a list of slave zones that the
+\fBb10\-zonemgr\fR
+should keep timers for\&. The list items include the
+\fIname\fR
+(which defines the zone name) and the
+\fIclass\fR
+(which defaults to
+\(lqIN\(rq)\&.
+.PP
+(A deprecated configuration is
+\fIjitter_scope\fR
+which is superceded by
+\fIrefresh_jitter\fR
+and
+\fIreload_jitter\fR\&.)
+.PP
 The configuration commands are:
 .PP
 
@@ -107,5 +128,5 @@ The
 daemon was designed in July 2010 by CNNIC for the ISC BIND 10 project\&.
 .SH "COPYRIGHT"
 .br
-Copyright \(co 2010 Internet Systems Consortium, Inc. ("ISC")
+Copyright \(co 2010-2011 Internet Systems Consortium, Inc. ("ISC")
 .br

src/bin/zonemgr/b10-zonemgr.xml

@@ -2,7 +2,7 @@
                "http://www.oasis-open.org/docbook/xml/4.2/docbookx.dtd"
 	       [<!ENTITY mdash "&#8212;">]>
 <!--
- - Copyright (C) 2010  Internet Systems Consortium, Inc. ("ISC")
+ - Copyright (C) 2010-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
@@ -20,7 +20,7 @@
 <refentry>
 
   <refentryinfo>
-    <date>October 18, 2010</date>
+    <date>May 19, 2011</date>
   </refentryinfo>
 
   <refmeta>
@@ -36,7 +36,7 @@
 
   <docinfo>
     <copyright>
-      <year>2010</year>
+      <year>2010-2011</year>
       <holder>Internet Systems Consortium, Inc. ("ISC")</holder>
     </copyright>
   </docinfo>
@@ -92,6 +92,39 @@
     <para>
       The configurable settings are:
     </para>
+
+    <para>
+      <varname>lowerbound_refresh</varname>
+      defines the minimum SOA REFRESH time in seconds.
+      The default is 10.
+    </para>
+
+    <para>
+      <varname>lowerbound_retry</varname>
+      defines the minimum SOA RETRY time in seconds.
+      The default is 5.
+    </para>
+
+    <para>
+      <varname>refresh_jitter</varname>
+      This value is a real number.
+      The maximum amount is 0.5.
+      The default is 0.25.
+    </para>
+<!-- TODO: needs to be documented -->
+<!-- TODO:      Set to 0 to disable the jitter.   -->
+
+    <para>
+      <varname>reload_jitter</varname>
+      This value is a real number.
+      The default is 0.75.
+    </para>
+<!-- TODO: needs to be documented -->
+<!-- TODO:      Set to 0 to disable the jitter.   -->
+<!-- what does 0 do? -->
+<!-- TODO: no max? -->
+
+<!-- TODO: remove this. This is old removed config
     <para>
       <varname>jitter_scope</varname>
       defines the random jitter range subtracted from the refresh
@@ -106,16 +139,8 @@
       The default is 0.25.
       Set to 0 to disable the jitter.
     </para>
-    <para>
-      <varname>lowerbound_refresh</varname>
-      defines the minimum SOA REFRESH time in seconds.
-      The default is 10.
-    </para>
-    <para>
-      <varname>lowerbound_retry</varname>
-      defines the minimum SOA RETRY time in seconds.
-      The default is 5.
-    </para>
+-->
+
     <para>
       <varname>max_transfer_timeout</varname>
       defines the maximum amount of time in seconds for a transfer.
@@ -123,6 +148,21 @@
       The default is 14400 (4 hours).
     </para>
 
+<!-- TODO: this duplicates list in Xfrin too -->
+    <para>
+      <varname>secondary_zones</varname> is a list of slave zones
+      that the <command>b10-zonemgr</command> should keep timers for.
+      The list items include the <varname>name</varname> (which
+      defines the zone name) and the <varname>class</varname>
+      (which defaults to <quote>IN</quote>).
+    </para>
+
+    <para>
+      (A deprecated configuration is <varname>jitter_scope</varname>
+      which is superceded by <varname>refresh_jitter</varname>
+      and <varname>reload_jitter</varname>.)
+    </para>
+
 <!-- TODO: formating -->
     <para>
       The configuration commands are:

src/bin/zonemgr/tests/zonemgr_test.py

@@ -434,6 +434,14 @@ class TestZonemgrRefresh(unittest.TestCase):
         self.assertTrue(zone_state == ZONE_REFRESHING)
 
     def test_update_config_data(self):
+        # make sure it doesn't fail if we only provide secondary zones
+        config_data = {
+                    "secondary_zones": [ { "name": "example.net.",
+                                           "class": "IN" } ]
+                }
+        self.zone_refresh.update_config_data(config_data)
+
+        # update all values
         config_data = {
                     "lowerbound_refresh" : 60,
                     "lowerbound_retry" : 30,
@@ -449,6 +457,53 @@ class TestZonemgrRefresh(unittest.TestCase):
         self.assertEqual(0.25, self.zone_refresh._refresh_jitter)
         self.assertEqual(0.75, self.zone_refresh._reload_jitter)
 
+        # make sure they are not reset when we only update one
+        config_data = {
+                    "reload_jitter" : 0.35,
+                }
+        self.zone_refresh.update_config_data(config_data)
+        self.assertEqual(60, self.zone_refresh._lowerbound_refresh)
+        self.assertEqual(30, self.zone_refresh._lowerbound_retry)
+        self.assertEqual(19800, self.zone_refresh._max_transfer_timeout)
+        self.assertEqual(0.25, self.zone_refresh._refresh_jitter)
+        self.assertEqual(0.35, self.zone_refresh._reload_jitter)
+
+        # and make sure we restore the previous config if something
+        # goes wrong
+        config_data = {
+                    "lowerbound_refresh" : 61,
+                    "lowerbound_retry" : 31,
+                    "max_transfer_timeout" : 19801,
+                    "refresh_jitter" : 0.21,
+                    "reload_jitter" : 0.71,
+                    "secondary_zones": [ { "name": "doesnotexist",
+                                           "class": "IN" } ]
+                }
+        self.assertRaises(ZonemgrException,
+                          self.zone_refresh.update_config_data,
+                          config_data)
+        self.assertEqual(60, self.zone_refresh._lowerbound_refresh)
+        self.assertEqual(30, self.zone_refresh._lowerbound_retry)
+        self.assertEqual(19800, self.zone_refresh._max_transfer_timeout)
+        self.assertEqual(0.25, self.zone_refresh._refresh_jitter)
+        self.assertEqual(0.35, self.zone_refresh._reload_jitter)
+
+        # Make sure we accept 0 as a value
+        config_data = {
+                    "lowerbound_refresh" : 60,
+                    "lowerbound_retry" : 30,
+                    "max_transfer_timeout" : 19800,
+                    "refresh_jitter" : 0,
+                    "reload_jitter" : 0.75,
+                    "secondary_zones": []
+                }
+        self.zone_refresh.update_config_data(config_data)
+        self.assertEqual(60, self.zone_refresh._lowerbound_refresh)
+        self.assertEqual(30, self.zone_refresh._lowerbound_retry)
+        self.assertEqual(19800, self.zone_refresh._max_transfer_timeout)
+        self.assertEqual(0, self.zone_refresh._refresh_jitter)
+        self.assertEqual(0.75, self.zone_refresh._reload_jitter)
+
     def test_shutdown(self):
         self.zone_refresh._check_sock = self.zone_refresh._master_socket
         listener = self.zone_refresh.run_timer()

src/bin/zonemgr/zonemgr.py.in

@@ -101,6 +101,11 @@ class ZonemgrRefresh:
         self._check_sock = slave_socket
         self._db_file = db_file
         self._zonemgr_refresh_info = {}
+        self._lowerbound_refresh = None
+        self._lowerbound_retry = None
+        self._max_transfer_timeout = None
+        self._refresh_jitter = None
+        self._reload_jitter = None
         self.update_config_data(config_data)
         self._running = False
 
@@ -404,37 +409,73 @@ class ZonemgrRefresh:
 
     def update_config_data(self, new_config):
         """ update ZonemgrRefresh config """
+        # TODO: we probably want to store all this info in a nice
+        # class, so that we don't have to backup and restore every
+        # single value.
+        # TODO2: We also don't use get_default_value yet
         backup = self._zonemgr_refresh_info.copy()
+
+        # Get a new value, but only if it is defined (commonly used below)
+        # We don't use "value or default", because if value would be
+        # 0, we would take default
+        def val_or_default(value, default):
+            if value is not None:
+                return value
+            else:
+                return default
+
+        # store the values so we can restore them if there is a problem
+        lowerbound_refresh_backup = self._lowerbound_refresh
+        self._lowerbound_refresh = val_or_default(
+            new_config.get('lowerbound_refresh'), self._lowerbound_refresh)
+
+        lowerbound_retry_backup = self._lowerbound_retry
+        self._lowerbound_retry = val_or_default(
+            new_config.get('lowerbound_retry'), self._lowerbound_retry)
+
+        max_transfer_timeout_backup = self._max_transfer_timeout
+        self._max_transfer_timeout = val_or_default(
+            new_config.get('max_transfer_timeout'), self._max_transfer_timeout)
+
+        refresh_jitter_backup = self._refresh_jitter
+        self._refresh_jitter = val_or_default(
+            new_config.get('refresh_jitter'), self._refresh_jitter)
+
+        reload_jitter_backup = self._reload_jitter
+        self._reload_jitter = val_or_default(
+            new_config.get('reload_jitter'), self._reload_jitter)
         try:
             required = {}
-            # Add new zones
-            for secondary_zone in new_config.get('secondary_zones'):
-                name = secondary_zone['name']
-                # Be tolerant to sclerotic users who forget the final dot
-                if name[-1] != '.':
-                    name = name + '.'
-                name_class = (name, secondary_zone['class'])
-                required[name_class] = True
-                # Add it only if it isn't there already
-                if not name_class in self._zonemgr_refresh_info:
-                    self.zonemgr_add_zone(name_class)
-            # Drop the zones that are no longer there
-            # Do it in two phases, python doesn't like deleting while iterating
-            to_drop = []
-            for old_zone in self._zonemgr_refresh_info:
-                if not old_zone in required:
-                    to_drop.append(old_zone)
-            for drop in to_drop:
-                del self._zonemgr_refresh_info[drop]
+            secondary_zones = new_config.get('secondary_zones')
+            if secondary_zones is not None:
+                # Add new zones
+                for secondary_zone in new_config.get('secondary_zones'):
+                    name = secondary_zone['name']
+                    # Be tolerant to sclerotic users who forget the final dot
+                    if name[-1] != '.':
+                        name = name + '.'
+                    name_class = (name, secondary_zone['class'])
+                    required[name_class] = True
+                    # Add it only if it isn't there already
+                    if not name_class in self._zonemgr_refresh_info:
+                        self.zonemgr_add_zone(name_class)
+                # Drop the zones that are no longer there
+                # Do it in two phases, python doesn't like deleting while iterating
+                to_drop = []
+                for old_zone in self._zonemgr_refresh_info:
+                    if not old_zone in required:
+                        to_drop.append(old_zone)
+                for drop in to_drop:
+                    del self._zonemgr_refresh_info[drop]
         # If we are not able to find it in database, restore the original
         except:
             self._zonemgr_refresh_info = backup
+            self._lowerbound_refresh = lowerbound_refresh_backup
+            self._lowerbound_retry = lowerbound_retry_backup
+            self._max_transfer_timeout = max_transfer_timeout_backup
+            self._refresh_jitter = refresh_jitter_backup
+            self._reload_jitter = reload_jitter_backup
             raise
-        self._lowerbound_refresh = new_config.get('lowerbound_refresh')
-        self._lowerbound_retry = new_config.get('lowerbound_retry')
-        self._max_transfer_timeout = new_config.get('max_transfer_timeout')
-        self._refresh_jitter = new_config.get('refresh_jitter')
-        self._reload_jitter = new_config.get('reload_jitter')
 
 class Zonemgr:
     """Zone manager class."""

src/cppcheck-suppress.lst

@@ -12,4 +12,4 @@ functionConst:src/lib/cache/rrset_cache.h
 // Intentional self assignment tests.  Suppress warning about them.
 selfAssignment:src/lib/dns/tests/name_unittest.cc:293
 selfAssignment:src/lib/dns/tests/rdata_unittest.cc:228
-selfAssignment:src/lib/dns/tests/tsigkey_unittest.cc:125
+selfAssignment:src/lib/dns/tests/tsigkey_unittest.cc:137

src/lib/asiodns/io_fetch.cc

@@ -209,16 +209,6 @@ IOFetch::IOFetch(Protocol protocol, IOService& service,
     msg->setHeaderFlag(Message::HEADERFLAG_CD,
                        query_message->getHeaderFlag(Message::HEADERFLAG_CD));
 
-    ConstEDNSPtr edns(query_message->getEDNS());
-    const bool dnssec_ok = edns && edns->getDNSSECAwareness();
-    if (edns) {
-        EDNSPtr edns_response(new EDNS());
-        edns_response->setDNSSECAwareness(dnssec_ok);
-        // TODO: We should make our own edns bufsize length configurable
-        edns_response->setUDPSize(Message::DEFAULT_MAX_EDNS0_UDPSIZE);
-        msg->setEDNS(edns_response);
-    }
-
     initIOFetch(msg, protocol, service,
                 **(query_message->beginQuestion()),
                 address, port, buff, cb, wait);
@@ -238,6 +228,9 @@ IOFetch::initIOFetch(MessagePtr& query_msg, Protocol protocol, IOService& servic
     query_msg->setRcode(Rcode::NOERROR());
     query_msg->setHeaderFlag(Message::HEADERFLAG_RD);
     query_msg->addQuestion(question);
+    EDNSPtr edns_query(new EDNS());
+    edns_query->setUDPSize(Message::DEFAULT_MAX_EDNS0_UDPSIZE);
+    query_msg->setEDNS(edns_query);
     MessageRenderer renderer(*data_->msgbuf);
     query_msg->toWire(renderer);
 }

src/lib/asiodns/tests/Makefile.am

@@ -27,13 +27,14 @@ run_unittests_CPPFLAGS = $(AM_CPPFLAGS) $(GTEST_INCLUDES)
 run_unittests_LDADD  = $(GTEST_LDADD)
 run_unittests_LDADD += $(SQLITE_LIBS)
 run_unittests_LDADD += $(top_builddir)/src/lib/dns/libdns++.la
+run_unittests_LDADD += $(top_builddir)/src/lib/util/unittests/libutil_unittests.la
 run_unittests_LDADD += $(top_builddir)/src/lib/util/libutil.la
 run_unittests_LDADD += $(top_builddir)/src/lib/asiolink/libasiolink.la
 run_unittests_LDADD += $(top_builddir)/src/lib/log/liblog.la
 run_unittests_LDADD += $(top_builddir)/src/lib/exceptions/libexceptions.la
 run_unittests_LDADD += $(top_builddir)/src/lib/asiodns/libasiodns.la
 
-run_unittests_LDFLAGS = $(AM_LDFLAGS) $(GTEST_LDFLAGS) $(LOG4CPLUS_LDFLAGS)
+run_unittests_LDFLAGS = $(AM_LDFLAGS) $(GTEST_LDFLAGS)
 
 # Note: the ordering matters: -Wno-... must follow -Wextra (defined in
 # B10_CXXFLAGS)

src/lib/asiodns/tests/io_fetch_unittest.cc

@@ -130,6 +130,9 @@ public:
         msg.setRcode(Rcode::NOERROR());
         msg.setHeaderFlag(Message::HEADERFLAG_RD);
         msg.addQuestion(question_);
+        EDNSPtr msg_edns(new EDNS());
+        msg_edns->setUDPSize(Message::DEFAULT_MAX_EDNS0_UDPSIZE);
+        msg.setEDNS(msg_edns);
         MessageRenderer renderer(*msgbuf_);
         msg.toWire(renderer);
         MessageRenderer renderer2(*expected_buffer_);

src/lib/asiodns/tests/run_unittests.cc

@@ -13,6 +13,7 @@
 // PERFORMANCE OF THIS SOFTWARE.
 
 #include <gtest/gtest.h>
+#include <util/unittests/run_all.h>
 
 #include <log/root_logger_name.h>
 #include <dns/tests/unittest_util.h>
@@ -24,5 +25,5 @@ main(int argc, char* argv[])
     isc::log::setRootLoggerName("unittest");        // Set a root logger name
     isc::UnitTestUtil::addDataPath(TEST_DATA_DIR);  // Add location of test data
 
-    return (RUN_ALL_TESTS());
+    return (isc::util::unittests::run_all());
 }

src/lib/asiolink/tests/Makefile.am

@@ -36,11 +36,11 @@ run_unittests_CPPFLAGS = $(AM_CPPFLAGS) $(GTEST_INCLUDES)
 run_unittests_LDADD  = $(GTEST_LDADD)
 run_unittests_LDADD += $(SQLITE_LIBS)
 run_unittests_LDADD += $(top_builddir)/src/lib/asiolink/libasiolink.la
-run_unittests_LDADD += $(top_builddir)/src/lib/util/libutil.la
 run_unittests_LDADD += $(top_builddir)/src/lib/log/liblog.la
+run_unittests_LDADD += $(top_builddir)/src/lib/util/unittests/libutil_unittests.la
 run_unittests_LDADD += $(top_builddir)/src/lib/exceptions/libexceptions.la
 
-run_unittests_LDFLAGS = $(AM_LDFLAGS) $(GTEST_LDFLAGS) $(LOG4CPLUS_LDFLAGS)
+run_unittests_LDFLAGS = $(AM_LDFLAGS) $(GTEST_LDFLAGS)
 
 # Note: the ordering matters: -Wno-... must follow -Wextra (defined in
 # B10_CXXFLAGS)

src/lib/asiolink/tests/run_unittests.cc

@@ -13,6 +13,7 @@
 // PERFORMANCE OF THIS SOFTWARE.
 
 #include <gtest/gtest.h>
+#include <util/unittests/run_all.h>
 
 #include <log/root_logger_name.h>
 #include <dns/tests/unittest_util.h>
@@ -23,5 +24,5 @@ main(int argc, char* argv[])
     ::testing::InitGoogleTest(&argc, argv);         // Initialize Google test
     isc::log::setRootLoggerName("unittest");        // Set a root logger name
 
-    return (RUN_ALL_TESTS());
+    return (isc::util::unittests::run_all());
 }

src/lib/bench/tests/Makefile.am

@@ -14,10 +14,10 @@ run_unittests_SOURCES += loadquery_unittest.cc
 
 run_unittests_CPPFLAGS = $(AM_CPPFLAGS) $(GTEST_INCLUDES)
 run_unittests_LDFLAGS = $(AM_LDFLAGS) $(GTEST_LDFLAGS)
-run_unittests_LDADD = $(top_builddir)/src/lib/exceptions/libexceptions.la
+run_unittests_LDADD  = $(top_builddir)/src/lib/bench/libbench.la
 run_unittests_LDADD += $(top_builddir)/src/lib/dns/libdns++.la
-run_unittests_LDADD += $(top_builddir)/src/lib/util/libutil.la
-run_unittests_LDADD += $(top_builddir)/src/lib/bench/libbench.la
+run_unittests_LDADD += $(top_builddir)/src/lib/util/unittests/libutil_unittests.la
+run_unittests_LDADD += $(top_builddir)/src/lib/exceptions/libexceptions.la
 run_unittests_LDADD += $(GTEST_LDADD)
 endif
 

src/lib/bench/tests/run_unittests.cc

@@ -13,10 +13,11 @@
 // PERFORMANCE OF THIS SOFTWARE.
 
 #include <gtest/gtest.h>
+#include <util/unittests/run_all.h>
 
 int
 main(int argc, char* argv[]) {
     ::testing::InitGoogleTest(&argc, argv);
 
-    return (RUN_ALL_TESTS());
+    return (isc::util::unittests::run_all());
 }

src/lib/cache/tests/Makefile.am

@@ -32,20 +32,20 @@ TESTS =
 if HAVE_GTEST
 TESTS += run_unittests
 run_unittests_SOURCES  = run_unittests.cc
-run_unittests_SOURCES  += $(top_srcdir)/src/lib/dns/tests/unittest_util.cc
-run_unittests_SOURCES  += rrset_entry_unittest.cc
-run_unittests_SOURCES  += rrset_cache_unittest.cc
-run_unittests_SOURCES  += message_cache_unittest.cc
-run_unittests_SOURCES  += message_entry_unittest.cc
-run_unittests_SOURCES  += local_zone_data_unittest.cc
-run_unittests_SOURCES  += resolver_cache_unittest.cc
-run_unittests_SOURCES  += negative_cache_unittest.cc
-run_unittests_SOURCES  += cache_test_messagefromfile.h
-run_unittests_SOURCES  += cache_test_sectioncount.h
+run_unittests_SOURCES += $(top_srcdir)/src/lib/dns/tests/unittest_util.cc
+run_unittests_SOURCES += rrset_entry_unittest.cc
+run_unittests_SOURCES += rrset_cache_unittest.cc
+run_unittests_SOURCES += message_cache_unittest.cc
+run_unittests_SOURCES += message_entry_unittest.cc
+run_unittests_SOURCES += local_zone_data_unittest.cc
+run_unittests_SOURCES += resolver_cache_unittest.cc
+run_unittests_SOURCES += negative_cache_unittest.cc
+run_unittests_SOURCES += cache_test_messagefromfile.h
+run_unittests_SOURCES += cache_test_sectioncount.h
 
 run_unittests_CPPFLAGS = $(AM_CPPFLAGS) $(GTEST_INCLUDES)
-run_unittests_LDFLAGS = $(AM_LDFLAGS) $(GTEST_LDFLAGS) $(LOG4CPLUS_LDFLAGS)
-run_unittests_LDADD = $(GTEST_LDADD)
+run_unittests_LDFLAGS  = $(AM_LDFLAGS) $(GTEST_LDFLAGS)
+run_unittests_LDADD    = $(GTEST_LDADD)
 
 # NOTE: we may have to clean up this hack later (see the note in configure.ac)
 if NEED_LIBBOOST_THREAD
@@ -55,14 +55,14 @@ endif
 run_unittests_LDADD += $(top_builddir)/src/lib/cache/libcache.la
 run_unittests_LDADD += $(top_builddir)/src/lib/nsas/libnsas.la
 run_unittests_LDADD += $(top_builddir)/src/lib/dns/libdns++.la
-run_unittests_LDADD += $(top_builddir)/src/lib/util/libutil.la
 run_unittests_LDADD += $(top_builddir)/src/lib/asiolink/libasiolink.la
+run_unittests_LDADD += $(top_builddir)/src/lib/util/unittests/libutil_unittests.la
 run_unittests_LDADD += $(top_builddir)/src/lib/exceptions/libexceptions.la
 endif
 
 noinst_PROGRAMS = $(TESTS)
 
-EXTRA_DIST = testdata/message_cname_referral.wire
+EXTRA_DIST  = testdata/message_cname_referral.wire
 EXTRA_DIST += testdata/message_example_com_soa.wire
 EXTRA_DIST += testdata/message_fromWire1
 EXTRA_DIST += testdata/message_fromWire2

src/lib/cache/tests/run_unittests.cc

@@ -15,6 +15,7 @@
 #include <config.h>
 
 #include <gtest/gtest.h>
+#include <util/unittests/run_all.h>
 
 #include <dns/tests/unittest_util.h>
 
@@ -24,5 +25,5 @@ main(int argc, char* argv[]) {
     isc::UnitTestUtil::addDataPath(TEST_DATA_SRCDIR);
     isc::UnitTestUtil::addDataPath(TEST_DATA_BUILDDIR);
 
-    return (RUN_ALL_TESTS());
+    return (isc::util::unittests::run_all());
 }

src/lib/cc/tests/Makefile.am

@@ -26,6 +26,7 @@ run_unittests_LDFLAGS = $(AM_LDFLAGS) $(GTEST_LDFLAGS)
 
 run_unittests_LDADD = $(GTEST_LDADD)
 run_unittests_LDADD +=  $(top_builddir)/src/lib/cc/libcc.la
+run_unittests_LDADD +=  $(top_builddir)/src/lib/util/unittests/libutil_unittests.la
 run_unittests_LDADD +=  $(top_builddir)/src/lib/exceptions/libexceptions.la
 
 endif

src/lib/cc/tests/run_unittests.cc

@@ -13,9 +13,10 @@
 // PERFORMANCE OF THIS SOFTWARE.
 
 #include <gtest/gtest.h>
+#include <util/unittests/run_all.h>
 
 int
 main(int argc, char* argv[]) {
     ::testing::InitGoogleTest(&argc, argv);
-    return (RUN_ALL_TESTS());
+    return (isc::util::unittests::run_all());
 }

src/lib/config/ccsession.cc

@@ -192,8 +192,10 @@ ModuleCCSession::ModuleCCSession(
     isc::data::ConstElementPtr(*config_handler)(
         isc::data::ConstElementPtr new_config),
     isc::data::ConstElementPtr(*command_handler)(
-        const std::string& command, isc::data::ConstElementPtr args)
+        const std::string& command, isc::data::ConstElementPtr args),
+    bool start_immediately
     ) :
+    started_(false),
     session_(session)
 {
     module_specification_ = readModuleSpecification(spec_file_name);
@@ -237,8 +239,21 @@ ModuleCCSession::ModuleCCSession(
         }
     }
 
+    if (start_immediately) {
+        start();
+    }
+}
+
+void
+ModuleCCSession::start() {
+    if (started_) {
+        isc_throw(CCSessionError, "Module CC session already started");
+    }
+
     // register callback for asynchronous read
     session_.startRead(boost::bind(&ModuleCCSession::startCheck, this));
+
+    started_ = true;
 }
 
 /// Validates the new config values, if they are correct,
@@ -355,45 +370,56 @@ ModuleCCSession::checkCommand() {
     return (0);
 }
 
-std::string
-ModuleCCSession::addRemoteConfig(const std::string& spec_name,
-                                 void (*handler)(const std::string& module,
-                                          ConstElementPtr),
-                                 bool spec_is_filename)
-{
-    std::string module_name;
-    ModuleSpec rmod_spec;
-    if (spec_is_filename) {
-        // It's a file name, so load it
-        rmod_spec = readModuleSpecification(spec_name);
-        module_name =
-            rmod_spec.getFullSpec()->get("module_name")->stringValue();
+ModuleSpec
+ModuleCCSession::fetchRemoteSpec(const std::string& module, bool is_filename) {
+    if (is_filename) {
+        // It is a filename, simply load it.
+        return (readModuleSpecification(module));
     } else {
         // It's module name, request it from config manager
-        ConstElementPtr cmd = Element::fromJSON("{ \"command\": ["
-                                                "\"get_module_spec\","
-                                                "{\"module_name\": \"" +
-                                                module_name + "\"} ] }");
-        unsigned int seq = session_.group_sendmsg(cmd, "ConfigManager");
+
+        // Send the command
+        ConstElementPtr cmd(createCommand("get_module_spec",
+                            Element::fromJSON("{\"module_name\": \"" + module +
+                                              "\"}")));
+        const unsigned int seq = session_.group_sendmsg(cmd, "ConfigManager");
+
+        // Wait for the answer
         ConstElementPtr env, answer;
         session_.group_recvmsg(env, answer, false, seq);
         int rcode;
         ConstElementPtr spec_data = parseAnswer(rcode, answer);
         if (rcode == 0 && spec_data) {
-            rmod_spec = ModuleSpec(spec_data);
-            module_name = spec_name;
-            if (module_name != rmod_spec.getModuleName()) {
+            // received OK, construct the spec out of it
+            ModuleSpec spec = ModuleSpec(spec_data);
+            if (module != spec.getModuleName()) {
+                // It's a different module!
                 isc_throw(CCSessionError, "Module name mismatch");
             }
+            return (spec);
         } else {
-            isc_throw(CCSessionError, "Error getting config for " + module_name + ": " + answer->str());
+            isc_throw(CCSessionError, "Error getting config for " +
+                      module + ": " + answer->str());
         }
     }
-    ConfigData rmod_config = ConfigData(rmod_spec);
+}
+
+std::string
+ModuleCCSession::addRemoteConfig(const std::string& spec_name,
+                                 void (*handler)(const std::string& module,
+                                          ConstElementPtr),
+                                 bool spec_is_filename)
+{
+    // First get the module name, specification and default config
+    const ModuleSpec rmod_spec(fetchRemoteSpec(spec_name, spec_is_filename));
+    const std::string module_name(rmod_spec.getModuleName());
+    ConfigData rmod_config(rmod_spec);
 
-    // Get the current configuration values for that module
-    ConstElementPtr cmd = Element::fromJSON("{ \"command\": [\"get_config\", {\"module_name\":\"" + module_name + "\"} ] }");
-    unsigned int seq = session_.group_sendmsg(cmd, "ConfigManager");
+    // Get the current configuration values from config manager
+    ConstElementPtr cmd(createCommand("get_config",
+                        Element::fromJSON("{\"module_name\": \"" +
+                                          module_name + "\"}")));
+    const unsigned int seq = session_.group_sendmsg(cmd, "ConfigManager");
 
     ConstElementPtr env, answer;
     session_.group_recvmsg(env, answer, false, seq);
@@ -401,6 +427,7 @@ ModuleCCSession::addRemoteConfig(const std::string& spec_name,
     ConstElementPtr new_config = parseAnswer(rcode, answer);
     ElementPtr local_config;
     if (rcode == 0 && new_config) {
+        // Merge the received config into existing local config
         local_config = rmod_config.getLocalConfig();
         isc::data::merge(local_config, new_config);
         rmod_config.setLocalConfig(local_config);
@@ -414,6 +441,8 @@ ModuleCCSession::addRemoteConfig(const std::string& spec_name,
         remote_module_handlers_[module_name] = handler;
         handler(module_name, local_config);
     }
+
+    // Make sure we get updates in future
     session_.subscribe(module_name);
     return (module_name);
 }

src/lib/config/ccsession.h

@@ -171,6 +171,11 @@ public:
      * @param command_handler A callback function pointer to be called when
      * a control command from a remote agent needs to be performed on the
      * local module.
+     * @start_immediately If true (default), start listening to new commands
+     * and configuration changes asynchronously at the end of the constructor;
+     * if false, it will be delayed until the start() method is explicitly
+     * called. (This is a short term workaround for an initialization trouble.
+     * We'll need to develop a cleaner solution, and then remove this knob)
      */
     ModuleCCSession(const std::string& spec_file_name,
                     isc::cc::AbstractSession& session,
@@ -178,9 +183,20 @@ public:
                         isc::data::ConstElementPtr new_config) = NULL,
                     isc::data::ConstElementPtr(*command_handler)(
                         const std::string& command,
-                        isc::data::ConstElementPtr args) = NULL
+                        isc::data::ConstElementPtr args) = NULL,
+                    bool start_immediately = true
                     );
 
+    /// Start receiving new commands and configuration changes asynchronously.
+    ///
+    /// This method must be called only once, and only when the ModuleCCSession
+    /// was constructed with start_immediately being false.  Otherwise
+    /// CCSessionError will be thrown.
+    ///
+    /// As noted in the constructor, this method should be considered a short
+    /// term workaround and will be removed in future.
+    void start();
+
     /**
      * Optional optimization for checkCommand loop; returns true
      * if there are unhandled queued messages in the cc session.
@@ -240,12 +256,16 @@ public:
      * for those changes. This function will subscribe to the relevant module
      * channel.
      *
+     * This method must be called before calling the \c start() method on the
+     * ModuleCCSession (it also implies the ModuleCCSession must have been
+     * constructed with start_immediately being false).
+     *
      * \param spec_name This specifies the module to add. It is either a
      *                  filename of the spec file to use or a name of module
      *                  (in case it's a module name, the spec data is
      *                  downloaded from the configuration manager, therefore
      *                  the configuration manager must know it). If
-     *                  spec_is_filenabe is true (the default), then a
+     *                  spec_is_filename is true (the default), then a
      *                  filename is assumed, otherwise a module name.
      * \param handler The handler function called whenever there's a change.
      *                Called once initally from this function. May be NULL
@@ -293,7 +313,8 @@ public:
 private:
     ModuleSpec readModuleSpecification(const std::string& filename);
     void startCheck();
-    
+
+    bool started_;
     std::string module_name_;
     isc::cc::AbstractSession& session_;
     ModuleSpec module_specification_;
@@ -322,6 +343,8 @@ private:
 
     void updateRemoteConfig(const std::string& module_name,
                             isc::data::ConstElementPtr new_config);
+
+    ModuleSpec fetchRemoteSpec(const std::string& module, bool is_filename);
 };
 
 }

src/lib/config/tests/Makefile.am

@@ -20,13 +20,14 @@ TESTS += run_unittests
 run_unittests_SOURCES = ccsession_unittests.cc module_spec_unittests.cc config_data_unittests.cc run_unittests.cc
 
 run_unittests_CPPFLAGS = $(AM_CPPFLAGS) $(GTEST_INCLUDES)
-run_unittests_LDFLAGS = $(AM_LDFLAGS) $(GTEST_LDFLAGS) $(LOG4CPLUS_LDFLAGS)
+run_unittests_LDFLAGS = $(AM_LDFLAGS) $(GTEST_LDFLAGS)
 run_unittests_LDADD =  $(GTEST_LDADD)
+run_unittests_LDADD += libfake_session.la
 run_unittests_LDADD += $(top_builddir)/src/lib/cc/libcc.la
+run_unittests_LDADD += $(top_builddir)/src/lib/config/libcfgclient.la
 run_unittests_LDADD += $(top_builddir)/src/lib/exceptions/libexceptions.la
 run_unittests_LDADD += $(top_builddir)/src/lib/log/liblog.la
-run_unittests_LDADD += libfake_session.la
-run_unittests_LDADD += $(top_builddir)/src/lib/config/libcfgclient.la
+run_unittests_LDADD += $(top_builddir)/src/lib/util/unittests/libutil_unittests.la
 
 endif
 

src/lib/config/tests/ccsession_unittests.cc

@@ -362,7 +362,7 @@ TEST_F(CCSessionTest, remoteConfig) {
     std::string module_name;
     int item1;
     
-    ModuleCCSession mccs(ccspecfile("spec1.spec"), session, NULL, NULL);
+    ModuleCCSession mccs(ccspecfile("spec1.spec"), session, NULL, NULL, false);
     EXPECT_TRUE(session.haveSubscription("Spec1", "*"));
     
     // first simply connect, with no config values, and see we get
@@ -415,7 +415,16 @@ TEST_F(CCSessionTest, remoteConfig) {
         EXPECT_NO_THROW(module_name = mccs.addRemoteConfig("Spec2", NULL,
                                                            false));
 
+        const size_t qsize(session.getMsgQueue()->size());
+        EXPECT_TRUE(session.getMsgQueue()->get(qsize - 2)->equals(*el(
+            "[ \"ConfigManager\", \"*\", { \"command\": ["
+            "\"get_module_spec\", { \"module_name\": \"Spec2\" } ] } ]")));
+        EXPECT_TRUE(session.getMsgQueue()->get(qsize - 1)->equals(*el(
+            "[ \"ConfigManager\", \"*\", { \"command\": [ \"get_config\","
+            "{ \"module_name\": \"Spec2\" } ] } ]")));
         EXPECT_EQ("Spec2", module_name);
+        // Since we returned an empty local config above, the default value
+        // for "item1", which is 1, should be used.
         EXPECT_NO_THROW(item1 =
                         mccs.getRemoteConfigValue(module_name,
                                                   "item1")->intValue());
@@ -425,6 +434,18 @@ TEST_F(CCSessionTest, remoteConfig) {
     }
 
     {
+        SCOPED_TRACE("With bad module name");
+        // It is almost the same as above, but we supply wrong module name.
+        // It should fail.
+        // Try adding it with downloading the spec from config manager
+        ModuleSpec spec(moduleSpecFromFile(ccspecfile("spec2.spec")));
+        session.getMessages()->add(createAnswer(0, spec.getFullSpec()));
+
+        EXPECT_THROW(module_name = mccs.addRemoteConfig("Spec1", NULL, false),
+                     CCSessionError);
+    }
+
+    {
         // Try adding it with a handler.
         // Pass non-default value to see the handler is called after
         // downloading the configuration, not too soon.
@@ -496,7 +517,8 @@ TEST_F(CCSessionTest, ignoreRemoteConfigCommands) {
     session.getMessages()->add(createAnswer(0, el("{  }")));
 
     EXPECT_FALSE(session.haveSubscription("Spec29", "*"));
-    ModuleCCSession mccs(ccspecfile("spec29.spec"), session, my_config_handler, my_command_handler);
+    ModuleCCSession mccs(ccspecfile("spec29.spec"), session, my_config_handler,
+                         my_command_handler, false);
     EXPECT_TRUE(session.haveSubscription("Spec29", "*"));
 
     EXPECT_EQ(2, session.getMsgQueue()->size());
@@ -546,4 +568,41 @@ TEST_F(CCSessionTest, initializationFail) {
     EXPECT_TRUE(session.haveSubscription("Spec29", "*"));
 }
 
+// Test it throws when we try to start it twice (once from the constructor)
+TEST_F(CCSessionTest, doubleStartImplicit) {
+    ModuleCCSession mccs(ccspecfile("spec29.spec"), session, NULL, NULL);
+    EXPECT_THROW(mccs.start(), CCSessionError);
+}
+
+// The same, but both starts are explicit
+TEST_F(CCSessionTest, doubleStartExplicit) {
+    ModuleCCSession mccs(ccspecfile("spec29.spec"), session, NULL, NULL,
+                         false);
+    mccs.start();
+    EXPECT_THROW(mccs.start(), CCSessionError);
+}
+
+// Test we can request synchronous receive before we start the session,
+// and check there's the mechanism if we do it after
+TEST_F(CCSessionTest, delayedStart) {
+    ModuleCCSession mccs(ccspecfile("spec2.spec"), session, NULL, NULL, false);
+    session.getMessages()->add(createAnswer());
+    ConstElementPtr env, answer;
+    EXPECT_NO_THROW(session.group_recvmsg(env, answer, false, 3));
+    mccs.start();
+    session.getMessages()->add(createAnswer());
+    EXPECT_THROW(session.group_recvmsg(env, answer, false, 3),
+                 FakeSession::DoubleRead);
+}
+
+// Similar to the above, but more implicitly by calling addRemoteConfig().
+// We should construct ModuleCCSession with start_immediately being false
+// if we need to call addRemoteConfig().
+// The correct cases are covered in remoteConfig test.
+TEST_F(CCSessionTest, doubleStartWithAddRemoteConfig) {
+    ModuleCCSession mccs(ccspecfile("spec29.spec"), session, NULL, NULL);
+    session.getMessages()->add(createAnswer(0, el("{}")));
+    EXPECT_THROW(mccs.addRemoteConfig(ccspecfile("spec2.spec")),
+                 FakeSession::DoubleRead);
+}
 }

src/lib/config/tests/fake_session.cc

@@ -71,7 +71,8 @@ FakeSession::FakeSession(isc::data::ElementPtr initial_messages,
                          isc::data::ElementPtr msg_queue) :
     messages_(initial_messages),
     subscriptions_(subscriptions),
-    msg_queue_(msg_queue)
+    msg_queue_(msg_queue),
+    started_(false)
 {
 }
 
@@ -84,6 +85,7 @@ FakeSession::disconnect() {
 
 void
 FakeSession::startRead(boost::function<void()>) {
+    started_ = true;
 }
 
 void
@@ -91,7 +93,13 @@ FakeSession::establish(const char*) {
 }
 
 bool
-FakeSession::recvmsg(ConstElementPtr& msg, bool, int) {
+FakeSession::recvmsg(ConstElementPtr& msg, bool nonblock, int) {
+    if (started_ && !nonblock) {
+        // This would schedule another read for length, leading to
+        // corputed data
+        isc_throw(DoubleRead, "Second read scheduled from recvmsg");
+    }
+
     //cout << "[XX] client asks for message " << endl;
     if (messages_ &&
         messages_->getType() == Element::list &&
@@ -105,7 +113,15 @@ FakeSession::recvmsg(ConstElementPtr& msg, bool, int) {
 }
 
 bool
-FakeSession::recvmsg(ConstElementPtr& env, ConstElementPtr& msg, bool, int) {
+FakeSession::recvmsg(ConstElementPtr& env, ConstElementPtr& msg, bool nonblock,
+                     int)
+{
+    if (started_ && !nonblock) {
+        // This would schedule another read for length, leading to
+        // corputed data
+        isc_throw(DoubleRead, "Second read scheduled from recvmsg");
+    }
+
     //cout << "[XX] client asks for message and env" << endl;
     env = ElementPtr();
     if (messages_ &&

src/lib/config/tests/fake_session.h

@@ -42,6 +42,14 @@ public:
                 isc::data::ElementPtr msg_queue);
     virtual ~FakeSession();
 
+    // This is thrown if two reads for length at once are scheduled at once.
+    // Such thing does bad things currently (see discussion in ticket #931).
+    class DoubleRead : public Exception {
+    public:
+        DoubleRead(const char* file, size_t line, const char* what) :
+            Exception(file, line, what) {}
+    };
+
     virtual void startRead(boost::function<void()> read_callback);
 
     virtual void establish(const char* socket_file = NULL);
@@ -89,6 +97,7 @@ private:
     const isc::data::ElementPtr messages_;
     isc::data::ElementPtr subscriptions_;
     isc::data::ElementPtr msg_queue_;
+    bool started_;
 };
 } // namespace cc
 } // namespace isc

src/lib/config/tests/run_unittests.cc

@@ -13,16 +13,12 @@
 // PERFORMANCE OF THIS SOFTWARE.
 
 #include <gtest/gtest.h>
+#include <util/unittests/run_all.h>
 #include <log/logger_support.h>
 
 int
 main(int argc, char* argv[]) {
     ::testing::InitGoogleTest(&argc, argv);
-
-    // TODO: UNCOMMENT ON MERGE
-    // (this is the call we want in master, but branch point does not
-    // have this yet)
-    //isc::log::initLogger();
-
-    return (RUN_ALL_TESTS());
+    isc::log::initLogger();
+    return (isc::util::unittests::run_all());
 }

src/lib/config/tests/testdata/Makefile.am

@@ -51,3 +51,5 @@ EXTRA_DIST += spec26.spec
 EXTRA_DIST += spec27.spec
 EXTRA_DIST += spec28.spec
 EXTRA_DIST += spec29.spec
+EXTRA_DIST += spec30.spec
+EXTRA_DIST += spec31.spec

src/lib/config/tests/testdata/spec30.spec

@@ -0,0 +1,45 @@
+{
+    "module_spec": {
+        "module_name": "lists",
+        "module_description": "Logging options",
+        "config_data": [
+            {
+                "item_name": "first_list_items",
+                "item_type": "list",
+                "item_optional": false,
+                "item_default": [],
+                "list_item_spec": {
+                  "item_name": "first_list_item",
+                  "item_type": "map",
+                  "item_optional": false,
+                  "item_default": {},
+                  "map_item_spec": [
+                  {  "item_name": "foo",
+                     "item_type": "string",
+                     "item_optional": false,
+                     "item_default": "foo"
+                  },
+                  { "item_name": "second_list_items",
+                    "item_type": "list",
+                    "item_optional": false,
+                    "item_default": [],
+                    "list_item_spec": {
+                      "item_name": "second_list_item",
+                      "item_type": "map",
+                      "item_optional": false,
+                      "item_default": {},
+                      "map_item_spec": [
+                      { "item_name": "final_element",
+                        "item_type": "string",
+                        "item_optional": false,
+                        "item_default": "hello"
+                      }
+                      ]
+                    }
+                  }
+                  ]
+                }
+            }
+        ]
+    }
+}

src/lib/config/tests/testdata/spec31.spec

@@ -0,0 +1,63 @@
+{
+    "module_spec": {
+        "module_name": "lists",
+        "module_description": "Logging options",
+        "config_data": [
+            {
+                "item_name": "first_list_items",
+                "item_type": "list",
+                "item_optional": false,
+                "item_default": [],
+                "list_item_spec": {
+                  "item_name": "first_list_item",
+                  "item_type": "map",
+                  "item_optional": false,
+                  "item_default": {},
+                  "map_item_spec": [
+                  {  "item_name": "foo",
+                     "item_type": "string",
+                     "item_optional": false,
+                     "item_default": "foo"
+                  },
+                  { "item_name": "second_list_items",
+                    "item_type": "list",
+                    "item_optional": false,
+                    "item_default": [],
+                    "list_item_spec": {
+                      "item_name": "second_list_item",
+                      "item_type": "map",
+                      "item_optional": false,
+                      "item_default": {},
+                      "map_item_spec": [
+                      { "item_name": "map_element",
+                        "item_type": "map",
+                        "item_optional": false,
+                        "item_default": {},
+                        "map_item_spec": [
+                        { "item_name": "list1",
+                          "item_type": "list",
+                          "item_optional": false,
+                          "item_default": [],
+                          "list_item_spec":
+                          { "item_name": "list2",
+                            "item_type": "list",
+                            "item_optional": false,
+                            "item_default": [],
+                            "list_item_spec":
+                            { "item_name": "number",
+                              "item_type": "integer",
+                              "item_optional": false,
+                              "item_default": 1
+                            }
+                          }
+                        }]
+                      }
+                      ]
+                    }
+                  }
+                  ]
+                }
+            }
+        ]
+    }
+}

src/lib/cryptolink/crypto_hmac.cc

@@ -36,6 +36,15 @@ getBotanHashAlgorithmName(isc::cryptolink::HashAlgorithm algorithm) {
     case isc::cryptolink::SHA256:
         return ("SHA-256");
         break;
+    case isc::cryptolink::SHA224:
+        return ("SHA-224");
+        break;
+    case isc::cryptolink::SHA384:
+        return ("SHA-384");
+        break;
+    case isc::cryptolink::SHA512:
+        return ("SHA-512");
+        break;
     case isc::cryptolink::UNKNOWN_HASH:
         return ("Unknown");
         break;
@@ -61,7 +70,8 @@ public:
                 getBotanHashAlgorithmName(hash_algorithm));
         } catch (const Botan::Algorithm_Not_Found&) {
             isc_throw(isc::cryptolink::UnsupportedAlgorithm,
-                      "Unknown hash algorithm: " + hash_algorithm);
+                      "Unknown hash algorithm: " <<
+                      static_cast<int>(hash_algorithm));
         } catch (const Botan::Exception& exc) {
             isc_throw(isc::cryptolink::LibraryError, exc.what());
         }
@@ -173,9 +183,9 @@ public:
         try {
             Botan::SecureVector<Botan::byte> our_mac = hmac_->final();
             if (len < getOutputLength()) {
-                // Currently we don't support truncated signature.  To avoid
-                // validating too short signature accidently, we enforce the
-                // standard signature size for the moment.
+                // Currently we don't support truncated signature in TSIG (see
+                // #920).  To avoid validating too short signature accidently,
+                // we enforce the standard signature size for the moment.
                 // Once we support truncation correctly, this if-clause should
                 // (and the capitalized comment above) be removed.
                 return (false);
@@ -236,7 +246,7 @@ HMAC::verify(const void* sig, const size_t len) {
 }
 
 void
-signHMAC(const void* data, size_t data_len, const void* secret,
+signHMAC(const void* data, const size_t data_len, const void* secret,
          size_t secret_len, const HashAlgorithm hash_algorithm,
          isc::util::OutputBuffer& result, size_t len)
 {

src/lib/cryptolink/cryptolink.h

@@ -29,15 +29,19 @@ namespace cryptolink {
 
 /// \brief Hash algorithm identifiers
 enum HashAlgorithm {
-    MD5 = 0,            ///< MD5
-    SHA1 = 1,           ///< SHA-1
-    SHA256 = 2,         ///< SHA-256
-    UNKNOWN_HASH = 3    ///< This value can be used in conversion
+    UNKNOWN_HASH = 0,   ///< This value can be used in conversion
                         ///  functions, to be returned when the
                         ///  input is unknown (but a value MUST be
                         ///  returned), for instance when the input
                         ///  is a Name or a string, and the return
                         ///  value is a HashAlgorithm.
+    MD5 = 1,            ///< MD5
+    SHA1 = 2,           ///< SHA-1
+    SHA256 = 3,         ///< SHA-256
+    SHA224 = 4,         ///< SHA-224
+    SHA384 = 5,         ///< SHA-384
+    SHA512 = 6          ///< SHA-512
+
 };
 
 // Forward declaration for createHMAC()

src/lib/cryptolink/tests/Makefile.am

@@ -16,10 +16,11 @@ TESTS += run_unittests
 run_unittests_SOURCES = run_unittests.cc
 run_unittests_SOURCES += crypto_unittests.cc
 run_unittests_CPPFLAGS = $(AM_CPPFLAGS) $(GTEST_INCLUDES)
-run_unittests_LDFLAGS = $(AM_LDFLAGS) $(GTEST_LDFLAGS)
+run_unittests_LDFLAGS = ${BOTAN_LDFLAGS} $(AM_LDFLAGS) $(GTEST_LDFLAGS)
 run_unittests_LDADD = $(GTEST_LDADD)
-run_unittests_LDADD += $(top_builddir)/src/lib/cryptolink/libcryptolink.la
 run_unittests_LDADD += $(top_builddir)/src/lib/util/libutil.la
+run_unittests_LDADD += $(top_builddir)/src/lib/cryptolink/libcryptolink.la
+run_unittests_LDADD += $(top_builddir)/src/lib/util/unittests/libutil_unittests.la
 run_unittests_LDADD += $(top_builddir)/src/lib/exceptions/libexceptions.la
 endif
 

src/lib/cryptolink/tests/crypto_unittests.cc

@@ -13,8 +13,16 @@
 // PERFORMANCE OF THIS SOFTWARE.
 
 #include <config.h>
+
+#include <string>
+#include <vector>
+
+#include <boost/lexical_cast.hpp>
+
 #include <gtest/gtest.h>
 
+#include <util/encode/hex.h>
+
 #include <cryptolink/cryptolink.h>
 #include <cryptolink/crypto_hmac.h>
 
@@ -23,7 +31,9 @@
 
 #include <boost/shared_ptr.hpp>
 
+using namespace boost;
 using namespace isc::util;
+using namespace isc::util::encode;
 using namespace isc::cryptolink;
 
 namespace {
@@ -340,77 +350,158 @@ TEST(CryptoLinkTest, DISABLED_HMAC_SHA1_RFC2202_SIGN_TRUNCATED) {
 //
 // Test values taken from RFC 4231
 //
-TEST(CryptoLinkTest, HMAC_SHA256_RFC2202_SIGN) {
-    const uint8_t secret[] = { 0x0b, 0x0b, 0x0b, 0x0b, 0x0b, 0x0b, 0x0b,
-                               0x0b, 0x0b, 0x0b, 0x0b, 0x0b, 0x0b, 0x0b,
-                               0x0b, 0x0b, 0x0b, 0x0b, 0x0b, 0x0b };
-    const uint8_t hmac_expected[] = { 0xb0, 0x34, 0x4c, 0x61, 0xd8,
-                                      0xdb, 0x38, 0x53, 0x5c, 0xa8,
-                                      0xaf, 0xce, 0xaf, 0x0b, 0xf1,
-                                      0x2b, 0x88, 0x1d, 0xc2, 0x00,
-                                      0xc9, 0x83, 0x3d, 0xa7, 0x26,
-                                      0xe9, 0x37, 0x6c, 0x2e, 0x32,
-                                      0xcf, 0xf7 };
-    doHMACTest("Hi There", secret, 20, SHA256, hmac_expected, 32);
-
-    const uint8_t hmac_expected2[] = { 0x5b, 0xdc, 0xc1, 0x46, 0xbf,
-                                       0x60, 0x75, 0x4e, 0x6a, 0x04,
-                                       0x24, 0x26, 0x08, 0x95, 0x75,
-                                       0xc7, 0x5a, 0x00, 0x3f, 0x08,
-                                       0x9d, 0x27, 0x39, 0x83, 0x9d,
-                                       0xec, 0x58, 0xb9, 0x64, 0xec,
-                                       0x38, 0x43 };
-    doHMACTest("what do ya want for nothing?", "Jefe", 4, SHA256,
-               hmac_expected2, 32);
+//  Test data from RFC4231, including secret key
+//  and source data, they are common for sha224/256/384/512
+//  so put them together within the separate function.
+void
+doRFC4231Tests(HashAlgorithm hash_algorithm,
+               const std::vector<std::vector<uint8_t> >& hmac_list)
+{
+    std::vector<std::string> data_list;
+    std::vector<std::string> secret_list;
+
+    data_list.push_back("Hi There");
+    data_list.push_back("what do ya want for nothing?");
+    data_list.push_back(std::string(50, 0xdd));
+    data_list.push_back(std::string(50, 0xcd));
+    data_list.push_back("Test With Truncation");
+    data_list.push_back("Test Using Larger Than Block-Size Key - "
+                        "Hash Key First");
+    data_list.push_back("This is a test using a larger than block-size "
+                        "key and a larger than block-size data. The key "
+                        "needs to be hashed before being used by the HMAC "
+                        "algorithm.");
+
+    secret_list.push_back(std::string(20, 0x0b));
+    secret_list.push_back("Jefe");
+    secret_list.push_back(std::string(20, 0xaa));
+    const uint8_t secret_array[] = {
+        0x01, 0x02, 0x03, 0x04, 0x05, 0x06,
+        0x07, 0x08, 0x09, 0x0a, 0x0b, 0x0c,
+        0x0d, 0x0e, 0x0f, 0x10, 0x11, 0x12,
+        0x13, 0x14, 0x15, 0x16, 0x17, 0x18,
+        0x19 
+    };
+    secret_list.push_back(std::string(secret_array,
+                                      secret_array + sizeof(secret_array)));
+    secret_list.push_back(std::string(20, 0x0c));
+    secret_list.push_back(std::string(131, 0xaa));
+    secret_list.push_back(std::string(131, 0xaa));
+
+    // Make sure we provide a consistent size of test data
+    ASSERT_EQ(secret_list.size(), data_list.size());
+    ASSERT_EQ(secret_list.size(), hmac_list.size());
+
+    for (int i = 0; i < data_list.size(); ++i) {
+        SCOPED_TRACE("RFC4231 HMAC test for algorithm ID: " +
+                     lexical_cast<std::string>(hash_algorithm) +
+                     ", data ID: " + lexical_cast<std::string>(i));
+        // Until #920 is resolved we have to skip truncation cases.
+        if (data_list[i] == "Test With Truncation") {
+            continue;
+        }
+        doHMACTest(data_list[i], secret_list[i].c_str(), secret_list[i].size(),
+                   hash_algorithm, &hmac_list[i][0], hmac_list[i].size());
+    }
+}
 
-    const uint8_t secret3[] = { 0xaa, 0xaa, 0xaa, 0xaa, 0xaa, 0xaa,
-                                0xaa, 0xaa, 0xaa, 0xaa, 0xaa, 0xaa,
-                                0xaa, 0xaa, 0xaa, 0xaa, 0xaa, 0xaa,
-                                0xaa, 0xaa };
-    const uint8_t hmac_expected3[] = { 0x77, 0x3e, 0xa9, 0x1e, 0x36,
-                                       0x80, 0x0e, 0x46, 0x85, 0x4d,
-                                       0xb8, 0xeb, 0xd0, 0x91, 0x81,
-                                       0xa7, 0x29, 0x59, 0x09, 0x8b,
-                                       0x3e, 0xf8, 0xc1, 0x22, 0xd9,
-                                       0x63, 0x55, 0x14, 0xce, 0xd5,
-                                       0x65, 0xfe };
-    doHMACTest(std::string(50, 0xdd), secret3, 20, SHA256, hmac_expected3, 32);
+TEST(CryptoLinkTest, HMAC_SHA256_RFC4231_SIGN) {
+    std::vector<std::vector<uint8_t> > hmac_expected_list(7);
+
+    int i = 0;
+    decodeHex(
+        "b0344c61d8db38535ca8afceaf0bf12b881dc200c9833da726e9376c2e32cff7",
+        hmac_expected_list[i++]);
+    decodeHex(
+        "5bdcc146bf60754e6a042426089575c75a003f089d2739839dec58b964ec3843",
+        hmac_expected_list[i++]);
+    decodeHex(
+        "773ea91e36800e46854db8ebd09181a72959098b3ef8c122d9635514ced565fe",
+        hmac_expected_list[i++]);
+    decodeHex(
+        "82558a389a443c0ea4cc819899f2083a85f0faa3e578f8077a2e3ff46729665b",
+        hmac_expected_list[i++]);
+    decodeHex("a3b6167473100ee06e0c796c2955552b", hmac_expected_list[i++]);
+    decodeHex(
+        "60e431591ee0b67f0d8a26aacbf5b77f8e0bc6213728c5140546040f0ee37f54",
+        hmac_expected_list[i++]);
+    decodeHex(
+        "9b09ffa71b942fcb27635fbcd5b0e944bfdc63644f0713938a7f51535c3a35e2",
+        hmac_expected_list[i++]);
+
+    doRFC4231Tests(SHA256, hmac_expected_list);
+}
 
-    const uint8_t secret4[] = { 0x01, 0x02, 0x03, 0x04, 0x05, 0x06,
-                                0x07, 0x08, 0x09, 0x0a, 0x0b, 0x0c,
-                                0x0d, 0x0e, 0x0f, 0x10, 0x11, 0x12,
-                                0x13, 0x14, 0x15, 0x16, 0x17, 0x18,
-                                0x19 };
-    const uint8_t hmac_expected4[] = { 0x82, 0x55, 0x8a, 0x38, 0x9a,
-                                       0x44, 0x3c, 0x0e, 0xa4, 0xcc,
-                                       0x81, 0x98, 0x99, 0xf2, 0x08,
-                                       0x3a, 0x85, 0xf0, 0xfa, 0xa3,
-                                       0xe5, 0x78, 0xf8, 0x07, 0x7a,
-                                       0x2e, 0x3f, 0xf4, 0x67, 0x29,
-                                       0x66, 0x5b };
-    doHMACTest(std::string(50, 0xcd), secret4, 25, SHA256, hmac_expected4, 32);
-
-    const uint8_t hmac_expected6[] = { 0x60, 0xe4, 0x31, 0x59, 0x1e,
-                                       0xe0, 0xb6, 0x7f, 0x0d, 0x8a,
-                                       0x26, 0xaa, 0xcb, 0xf5, 0xb7,
-                                       0x7f, 0x8e, 0x0b, 0xc6, 0x21,
-                                       0x37, 0x28, 0xc5, 0x14, 0x05,
-                                       0x46, 0x04, 0x0f, 0x0e, 0xe3,
-                                       0x7f, 0x54 };
-    doHMACTest("Test Using Larger Than Block-Size Key - Hash Key First",
-               std::string(131, 0xaa).c_str(), 131, SHA256, hmac_expected6, 32);
-
-    const uint8_t hmac_expected7[] = { 0x9b, 0x09, 0xff, 0xa7, 0x1b,
-                                       0x94, 0x2f, 0xcb, 0x27, 0x63,
-                                       0x5f, 0xbc, 0xd5, 0xb0, 0xe9,
-                                       0x44, 0xbf, 0xdc, 0x63, 0x64,
-                                       0x4f, 0x07, 0x13, 0x93, 0x8a,
-                                       0x7f, 0x51, 0x53, 0x5c, 0x3a,
-                                       0x35, 0xe2 };
-    doHMACTest("This is a test using a larger than block-size key and a"
-               " larger than block-size data. The key needs to be hashe"
-               "d before being used by the HMAC algorithm.",
-               std::string(131, 0xaa).c_str(), 131, SHA256, hmac_expected7, 32);
+//
+// Test values taken from RFC 4231, test optional algorithm 224,384,512
+//
+TEST(CryptoLinkTest, HMAC_SHA224_RFC4231_SIGN) {
+    std::vector<std::vector<uint8_t> > hmac_expected_list(7);
+
+    int i = 0;
+    decodeHex("896fb1128abbdf196832107cd49df33f47b4b1169912ba4f53684b22",
+              hmac_expected_list[i++]);
+    decodeHex("a30e01098bc6dbbf45690f3a7e9e6d0f8bbea2a39e6148008fd05e44",
+              hmac_expected_list[i++]);
+    decodeHex("7fb3cb3588c6c1f6ffa9694d7d6ad2649365b0c1f65d69d1ec8333ea",
+              hmac_expected_list[i++]);
+    decodeHex("6c11506874013cac6a2abc1bb382627cec6a90d86efc012de7afec5a",
+              hmac_expected_list[i++]);
+    decodeHex("0e2aea68a90c8d37c988bcdb9fca6fa8", hmac_expected_list[i++]);
+    decodeHex("95e9a0db962095adaebe9b2d6f0dbce2d499f112f2d2b7273fa6870e",
+              hmac_expected_list[i++]);
+    decodeHex("3a854166ac5d9f023f54d517d0b39dbd946770db9c2b95c9f6f565d1",
+              hmac_expected_list[i++]);
+
+    doRFC4231Tests(SHA224, hmac_expected_list);
+}
+
+TEST(CryptoLinkTest, HMAC_SHA384_RFC4231_SIGN) {
+    std::vector<std::vector<uint8_t> > hmac_expected_list(7);
+
+    int i = 0;
+    decodeHex("afd03944d84895626b0825f4ab46907f15f9dadbe4101ec682aa034c7cebc5"
+              "9cfaea9ea9076ede7f4af152e8b2fa9cb6", hmac_expected_list[i++]);
+    decodeHex("af45d2e376484031617f78d2b58a6b1b9c7ef464f5a01b47e42ec373632244"
+              "5e8e2240ca5e69e2c78b3239ecfab21649", hmac_expected_list[i++]);
+    decodeHex("88062608d3e6ad8a0aa2ace014c8a86f0aa635d947ac9febe83ef4e5596614"
+              "4b2a5ab39dc13814b94e3ab6e101a34f27", hmac_expected_list[i++]);
+    decodeHex("3e8a69b7783c25851933ab6290af6ca77a9981480850009cc5577c6e1f573b"
+              "4e6801dd23c4a7d679ccf8a386c674cffb", hmac_expected_list[i++]);
+    decodeHex("3abf34c3503b2a23a46efc619baef897", hmac_expected_list[i++]);
+    decodeHex("4ece084485813e9088d2c63a041bc5b44f9ef1012a2b588f3cd11f05033ac4"
+              "c60c2ef6ab4030fe8296248df163f44952", hmac_expected_list[i++]);
+    decodeHex("6617178e941f020d351e2f254e8fd32c602420feb0b8fb9adccebb82461e99"
+              "c5a678cc31e799176d3860e6110c46523e", hmac_expected_list[i++]);
+
+    doRFC4231Tests(SHA384, hmac_expected_list);
+}
+
+TEST(CryptoLinkTest, HMAC_SHA512_RFC4231_SIGN) {
+    std::vector<std::vector<uint8_t> > hmac_expected_list(7);
+
+    int i = 0;
+    decodeHex("87aa7cdea5ef619d4ff0b4241a1d6cb02379f4e2ce4ec2787ad0b30545e17c"
+              "dedaa833b7d6b8a702038b274eaea3f4e4be9d914eeb61f1702e696c203a12"
+              "6854", hmac_expected_list[i++]);
+    decodeHex("164b7a7bfcf819e2e395fbe73b56e0a387bd64222e831fd610270cd7ea2505"
+              "549758bf75c05a994a6d034f65f8f0e6fdcaeab1a34d4a6b4b636e070a38bc"
+              "e737", hmac_expected_list[i++]);
+    decodeHex("fa73b0089d56a284efb0f0756c890be9b1b5dbdd8ee81a3655f83e33b2279d"
+              "39bf3e848279a722c806b485a47e67c807b946a337bee8942674278859e132"
+              "92fb", hmac_expected_list[i++]);
+    decodeHex("b0ba465637458c6990e5a8c5f61d4af7e576d97ff94b872de76f8050361ee3"
+              "dba91ca5c11aa25eb4d679275cc5788063a5f19741120c4f2de2adebeb10a2"
+              "98dd", hmac_expected_list[i++]);
+    decodeHex("415fad6271580a531d4179bc891d87a6", hmac_expected_list[i++]);
+    decodeHex("80b24263c7c1a3ebb71493c1dd7be8b49b46d1f41b4aeec1121b013783f8f3"
+              "526b56d037e05f2598bd0fd2215d6a1e5295e64f73f63f0aec8b915a985d78"
+              "6598", hmac_expected_list[i++]);
+    decodeHex("e37b6a775dc87dbaa4dfa9f96e5e3ffddebd71f8867289865df5a32d20cdc9"
+              "44b6022cac3c4982b10d5eeb55c3e4de15134676fb6de0446065c97440fa8c"
+              "6a58", hmac_expected_list[i++]);
+
+    doRFC4231Tests(SHA512, hmac_expected_list);
 }
 
 TEST(CryptoLinkTest, DISABLED_HMAC_SHA256_RFC2202_SIGN_TRUNCATED) {

src/lib/cryptolink/tests/run_unittests.cc

@@ -13,10 +13,11 @@
 // PERFORMANCE OF THIS SOFTWARE.
 
 #include <gtest/gtest.h>
+#include <util/unittests/run_all.h>
 
 int
 main(int argc, char* argv[]) {
     ::testing::InitGoogleTest(&argc, argv);
 
-    return (RUN_ALL_TESTS());
+    return (isc::util::unittests::run_all());
 }

src/lib/datasrc/tests/Makefile.am

@@ -28,9 +28,11 @@ run_unittests_SOURCES += rbtree_unittest.cc
 run_unittests_SOURCES += zonetable_unittest.cc
 run_unittests_SOURCES += memory_datasrc_unittest.cc
 run_unittests_SOURCES += logger_unittest.cc
+
 run_unittests_CPPFLAGS = $(AM_CPPFLAGS) $(GTEST_INCLUDES)
-run_unittests_LDFLAGS = $(AM_LDFLAGS) $(GTEST_LDFLAGS) $(LOG4CPLUS_LDFLAGS)
-run_unittests_LDADD = $(GTEST_LDADD)
+run_unittests_LDFLAGS  = $(AM_LDFLAGS)  $(GTEST_LDFLAGS)
+
+run_unittests_LDADD  = $(GTEST_LDADD)
 run_unittests_LDADD += $(SQLITE_LIBS)
 run_unittests_LDADD += $(top_builddir)/src/lib/datasrc/libdatasrc.la
 run_unittests_LDADD += $(top_builddir)/src/lib/dns/libdns++.la
@@ -38,6 +40,7 @@ run_unittests_LDADD += $(top_builddir)/src/lib/log/liblog.la
 run_unittests_LDADD += $(top_builddir)/src/lib/exceptions/libexceptions.la
 run_unittests_LDADD += $(top_builddir)/src/lib/cc/libcc.la
 run_unittests_LDADD += $(top_builddir)/src/lib/testutils/libtestutils.la
+run_unittests_LDADD += $(top_builddir)/src/lib/util/unittests/libutil_unittests.la
 endif
 
 noinst_PROGRAMS = $(TESTS)

src/lib/datasrc/tests/run_unittests.cc

@@ -13,6 +13,7 @@
 // PERFORMANCE OF THIS SOFTWARE.
 
 #include <gtest/gtest.h>
+#include <util/unittests/run_all.h>
 
 #include <dns/tests/unittest_util.h>
 
@@ -21,5 +22,5 @@ main(int argc, char* argv[]) {
     ::testing::InitGoogleTest(&argc, argv);
     isc::UnitTestUtil::addDataPath(TEST_DATA_DIR);
 
-    return (RUN_ALL_TESTS());
+    return (isc::util::unittests::run_all());
 }

src/lib/dns/python/message_python.cc

@@ -15,6 +15,7 @@
 #include <exceptions/exceptions.h>
 #include <dns/message.h>
 #include <dns/rcode.h>
+#include <dns/tsig.h>
 
 using namespace isc::dns;
 using namespace isc::util;
@@ -697,6 +698,11 @@ Message_toWire(s_Message* self, PyObject* args) {
             PyErr_Clear();
             PyErr_SetString(po_InvalidMessageOperation, imo.what());
             return (NULL);
+        } catch (const TSIGContextError& ex) {
+            // toWire() with a TSIG context can fail due to this if the
+            // python program has a bug.
+            PyErr_SetString(po_TSIGContextError, ex.what());
+            return (NULL);
         }
     }
     PyErr_Clear();

src/lib/dns/python/tests/tsigkey_python_test.py

@@ -25,6 +25,9 @@ class TSIGKeyTest(unittest.TestCase):
                          TSIGKey.HMACMD5_NAME)
         self.assertEqual(Name('hmac-sha1'), TSIGKey.HMACSHA1_NAME)
         self.assertEqual(Name('hmac-sha256'), TSIGKey.HMACSHA256_NAME)
+        self.assertEqual(Name('hmac-sha224'), TSIGKey.HMACSHA224_NAME)
+        self.assertEqual(Name('hmac-sha384'), TSIGKey.HMACSHA384_NAME)
+        self.assertEqual(Name('hmac-sha512'), TSIGKey.HMACSHA512_NAME)
 
     def test_init(self):
         key = TSIGKey(self.key_name, TSIGKey.HMACMD5_NAME, self.secret)

src/lib/dns/python/tsigkey_python.cc

@@ -256,6 +256,12 @@ initModulePart_TSIGKey(PyObject* mod) {
                              createNameObject(TSIGKey::HMACSHA1_NAME()));
         installClassVariable(tsigkey_type, "HMACSHA256_NAME",
                              createNameObject(TSIGKey::HMACSHA256_NAME()));
+        installClassVariable(tsigkey_type, "HMACSHA224_NAME",
+                             createNameObject(TSIGKey::HMACSHA224_NAME()));
+        installClassVariable(tsigkey_type, "HMACSHA384_NAME",
+                             createNameObject(TSIGKey::HMACSHA384_NAME()));
+        installClassVariable(tsigkey_type, "HMACSHA512_NAME",
+                             createNameObject(TSIGKey::HMACSHA512_NAME()));
     } catch (const exception& ex) {
         const string ex_what =
             "Unexpected failure in TSIGKey initialization: " +

src/lib/dns/tests/Makefile.am

@@ -53,12 +53,15 @@ run_unittests_SOURCES += tsigkey_unittest.cc
 run_unittests_SOURCES += tsigrecord_unittest.cc
 run_unittests_SOURCES += run_unittests.cc
 run_unittests_CPPFLAGS = $(AM_CPPFLAGS) $(GTEST_INCLUDES)
-run_unittests_LDFLAGS = $(AM_LDFLAGS) $(GTEST_LDFLAGS)
+# We shouldn't need to include BOTAN_LDFLAGS here, but there
+# is one test system where the path for GTEST_LDFLAGS contains
+# an older version of botan, and somehow that version gets
+# linked if we don't
+run_unittests_LDFLAGS = $(AM_LDFLAGS) $(BOTAN_LDFLAGS) $(GTEST_LDFLAGS)
 run_unittests_LDADD = $(GTEST_LDADD)
 run_unittests_LDADD += $(top_builddir)/src/lib/dns/libdns++.la
 run_unittests_LDADD += $(top_builddir)/src/lib/util/libutil.la
 run_unittests_LDADD += $(top_builddir)/src/lib/util/unittests/libutil_unittests.la
-run_unittests_LDADD += $(top_builddir)/src/lib/util/io/libutil_io.la
 run_unittests_LDADD += $(top_builddir)/src/lib/exceptions/libexceptions.la
 endif
 

src/lib/dns/tests/run_unittests.cc

@@ -13,6 +13,7 @@
 // PERFORMANCE OF THIS SOFTWARE.
 
 #include <gtest/gtest.h>
+#include <util/unittests/run_all.h>
 
 #include <util/unittests/testdata.h>
 #include <dns/tests/unittest_util.h>
@@ -25,5 +26,5 @@ main(int argc, char* argv[]) {
     isc::UnitTestUtil::addDataPath(TEST_DATA_BUILDDIR);
     isc::util::unittests::addTestDataPath(TEST_DATA_BUILDDIR);
 
-    return (RUN_ALL_TESTS());
+    return (isc::util::unittests::run_all());
 }

src/lib/dns/tests/tsig_unittest.cc

@@ -425,6 +425,29 @@ TEST_F(TSIGTest, signUsingHMACSHA1) {
     }
 }
 
+TEST_F(TSIGTest, signUsingHMACSHA224) {
+    isc::util::detail::gettimeFunction = testGetTime<0x4dae7d5f>;
+
+    secret.clear();
+    decodeBase64("MA+QDhXbyqUak+qnMFyTyEirzng=", secret);
+    TSIGContext sha1_ctx(TSIGKey(test_name, TSIGKey::HMACSHA224_NAME(),
+                                 &secret[0], secret.size()));
+
+    const uint16_t sha1_qid = 0x0967;
+    const uint8_t expected_mac[] = {
+        0x3b, 0x93, 0xd3, 0xc5, 0xf9, 0x64, 0xb9, 0xc5, 0x00, 0x35, 
+        0x02, 0x69, 0x9f, 0xfc, 0x44, 0xd6, 0xe2, 0x66, 0xf4, 0x08, 
+        0xef, 0x33, 0xa2, 0xda, 0xa1, 0x48, 0x71, 0xd3
+    };
+    {
+        SCOPED_TRACE("Sign test using HMAC-SHA1");
+        commonSignChecks(createMessageAndSign(sha1_qid, test_name, &sha1_ctx),
+                         sha1_qid, 0x4dae7d5f, expected_mac,
+                         sizeof(expected_mac), 0, 0, NULL,
+                         TSIGKey::HMACSHA224_NAME());
+    }
+}
+
 // The first part of this test checks verifying the signed query used for
 // the "sign" test.
 // The second part of this test generates a signed response to the signed

src/lib/dns/tests/tsigkey_unittest.cc

@@ -40,6 +40,9 @@ TEST_F(TSIGKeyTest, algorithmNames) {
     EXPECT_EQ(Name("hmac-md5.sig-alg.reg.int"), TSIGKey::HMACMD5_NAME());
     EXPECT_EQ(Name("hmac-sha1"), TSIGKey::HMACSHA1_NAME());
     EXPECT_EQ(Name("hmac-sha256"), TSIGKey::HMACSHA256_NAME());
+    EXPECT_EQ(Name("hmac-sha224"), TSIGKey::HMACSHA224_NAME());
+    EXPECT_EQ(Name("hmac-sha384"), TSIGKey::HMACSHA384_NAME());
+    EXPECT_EQ(Name("hmac-sha512"), TSIGKey::HMACSHA512_NAME());
 
     // Also check conversion to cryptolink definitions
     EXPECT_EQ(isc::cryptolink::MD5, TSIGKey(key_name, TSIGKey::HMACMD5_NAME(),
@@ -49,6 +52,15 @@ TEST_F(TSIGKeyTest, algorithmNames) {
     EXPECT_EQ(isc::cryptolink::SHA256, TSIGKey(key_name,
                                                TSIGKey::HMACSHA256_NAME(),
                                                NULL, 0).getAlgorithm());
+    EXPECT_EQ(isc::cryptolink::SHA224, TSIGKey(key_name,
+                                               TSIGKey::HMACSHA224_NAME(),
+                                               NULL, 0).getAlgorithm());
+    EXPECT_EQ(isc::cryptolink::SHA384, TSIGKey(key_name,
+                                               TSIGKey::HMACSHA384_NAME(),
+                                               NULL, 0).getAlgorithm());
+    EXPECT_EQ(isc::cryptolink::SHA512, TSIGKey(key_name,
+                                               TSIGKey::HMACSHA512_NAME(),
+                                               NULL, 0).getAlgorithm());
 }
 
 TEST_F(TSIGKeyTest, construct) {

src/lib/dns/tsigkey.cc

@@ -42,6 +42,16 @@ namespace {
         if (name == TSIGKey::HMACSHA256_NAME()) {
             return (isc::cryptolink::SHA256);
         }
+        if (name == TSIGKey::HMACSHA224_NAME()) {
+            return (isc::cryptolink::SHA224);
+        }
+        if (name == TSIGKey::HMACSHA384_NAME()) {
+            return (isc::cryptolink::SHA384);
+        }
+        if (name == TSIGKey::HMACSHA512_NAME()) {
+            return (isc::cryptolink::SHA512);
+        }
+ 
         return (isc::cryptolink::UNKNOWN_HASH);
     }
 }
@@ -207,6 +217,24 @@ Name& TSIGKey::HMACSHA256_NAME() {
     return (alg_name);
 }
 
+const
+Name& TSIGKey::HMACSHA224_NAME() {
+    static Name alg_name("hmac-sha224");
+    return (alg_name);
+}
+
+const
+Name& TSIGKey::HMACSHA384_NAME() {
+    static Name alg_name("hmac-sha384");
+    return (alg_name);
+}
+
+const
+Name& TSIGKey::HMACSHA512_NAME() {
+    static Name alg_name("hmac-sha512");
+    return (alg_name);
+}
+
 struct TSIGKeyRing::TSIGKeyRingImpl {
     typedef map<Name, TSIGKey> TSIGKeyMap;
     typedef pair<Name, TSIGKey> NameAndKey;

src/lib/dns/tsigkey.h

@@ -206,6 +206,9 @@ public:
     static const Name& HMACMD5_NAME();    ///< HMAC-MD5 (RFC2845)
     static const Name& HMACSHA1_NAME();   ///< HMAC-SHA1 (RFC4635)
     static const Name& HMACSHA256_NAME(); ///< HMAC-SHA256 (RFC4635)
+    static const Name& HMACSHA224_NAME(); ///< HMAC-SHA256 (RFC4635)
+    static const Name& HMACSHA384_NAME(); ///< HMAC-SHA256 (RFC4635)
+    static const Name& HMACSHA512_NAME(); ///< HMAC-SHA256 (RFC4635)
     //@}
 
 private:

src/lib/exceptions/tests/run_unittests.cc

@@ -17,5 +17,8 @@
 int
 main(int argc, char* argv[]) {
     ::testing::InitGoogleTest(&argc, argv);
+
+    // Unlike other tests we cannot use our wrapper for RUN_ALL_TESTS()
+    // due to dependency.
     return (RUN_ALL_TESTS());
 }

src/lib/log/Makefile.am

@@ -1,7 +1,7 @@
 SUBDIRS = . compiler tests
 
 AM_CPPFLAGS = -I$(top_builddir)/src/lib -I$(top_srcdir)/src/lib
-AM_CPPFLAGS += $(BOOST_INCLUDES) $(LOG4CPLUS_INCLUDES)
+AM_CPPFLAGS += $(BOOST_INCLUDES)
 
 CLEANFILES = *.gcno *.gcda
 
@@ -43,5 +43,6 @@ if USE_CLANGPP
 # Same for clang++, but we need to turn off -Werror completely.
 liblog_la_CXXFLAGS += -Wno-error
 endif
-liblog_la_CPPFLAGS = $(AM_CPPFLAGS)
-liblog_la_LIBADD = $(top_builddir)/src/lib/util/libutil.la
+liblog_la_CPPFLAGS = $(AM_CPPFLAGS) $(LOG4CPLUS_INCLUDES)
+liblog_la_LDFLAGS  = $(LOG4CPLUS_LDFLAGS)
+liblog_la_LIBADD   = $(top_builddir)/src/lib/util/libutil.la

src/lib/log/compiler/Makefile.am

@@ -12,7 +12,7 @@ endif
 CLEANFILES = *.gcno *.gcda
 
 noinst_PROGRAMS = message
+
 message_SOURCES = message.cc
-message_LDADD  = $(top_builddir)/src/lib/log/liblog.la
-message_LDADD += $(top_builddir)/src/lib/util/libutil.la
-message_LDADD += $(LOG4CPLUS_LDFLAGS)
+message_LDADD   = $(top_builddir)/src/lib/log/liblog.la
+message_LDADD  += $(top_builddir)/src/lib/util/libutil.la

src/lib/log/log_formatter.h

@@ -165,9 +165,16 @@ public:
     /// \brief String version of arg.
     Formatter& arg(const std::string& arg) {
         if (logger_) {
-            // Note that if we had a message like "%1 %2" and called
-            // .arg(42).arg("%1"), we would get "42 %1" (i.e. no recursive
-            // replacements).  This is a limitation but not a problem.
+            // Note that this method does a replacement and returns the
+            // modified string. If there are multiple invocations of arg() (e.g.
+            // logger.info(msgid).arg(xxx).arg(yyy)...), each invocation
+            // operates on the string returned by the previous one. This
+            // sequential operation means that if we had a message like "%1 %2",
+            // and called .arg("%2").arg(42), we would get "42 42"; the first
+            // call replaces the %1" with "%2" and the second replaces all
+            // occurrences of "%2" with 42. (Conversely, the sequence
+            // .arg(42).arg("%1") would return "42 %1" - there are no recursive
+            // replacements).
             replacePlaceholder(message_, arg, ++nextPlaceholder_ );
         }
         return (*this);

src/lib/log/logger_impl.cc

@@ -43,13 +43,17 @@ using namespace std;
 namespace isc {
 namespace log {
 
-// Constructor
-LoggerImpl::LoggerImpl(const string& name)
+// Constructor.  Although it may be immediately reset, logger_ is initialized to
+// the log4cplus root logger; at least one compiler requires that all member
+// variables be constructed before the constructor is run, but log4cplus::Logger
+// (the type of logger_) has no default constructor.
+LoggerImpl::LoggerImpl(const string& name) :
+    logger_(log4cplus::Logger::getRoot())
 {
     // Are we the root logger?
     if (name == getRootLoggerName()) {
         name_ = name;
-        logger_ = log4cplus::Logger::getRoot();
+        // logger_ already set to log4cplus root logger at this point
 
     } else {
         name_ = getRootLoggerName() + "." + name;

src/lib/log/logger_level.h

@@ -38,7 +38,7 @@ typedef enum {
     NONE = 6    // Disable logging
 } Severity;
 
-/// Minimum/maximum debug levels.  These are defined wi
+/// Minimum/maximum debug levels.
 
 const int MIN_DEBUG_LEVEL = 0;
 const int MAX_DEBUG_LEVEL = 99;

src/lib/log/tests/Makefile.am

@@ -1,7 +1,7 @@
 SUBDIRS = .
 
 AM_CPPFLAGS = -I$(top_builddir)/src/lib -I$(top_srcdir)/src/lib
-AM_CPPFLAGS += $(BOOST_INCLUDES) $(LOG4CPLUS_INCLUDES)
+AM_CPPFLAGS += $(BOOST_INCLUDES)
 AM_CXXFLAGS = $(B10_CXXFLAGS)
 
 if USE_STATIC_LINK
@@ -27,13 +27,20 @@ run_unittests_SOURCES += logger_specification_unittest.cc
 # run_unittests_SOURCES += output_option_unittest.cc
 # run_unittests_SOURCES += root_logger_name_unittest.cc
 
-run_unittests_CPPFLAGS = $(AM_CPPFLAGS) $(GTEST_INCLUDES)
-run_unittests_LDFLAGS = $(AM_LDFLAGS) $(GTEST_LDFLAGS) $(LOG4CPLUS_LDFLAGS)
+run_unittests_CPPFLAGS = $(AM_CPPFLAGS) $(GTEST_INCLUDES) $(LOG4CPLUS_INCLUDES)
+run_unittests_LDFLAGS  = $(AM_LDFLAGS)  $(GTEST_LDFLAGS)
 
+run_unittests_CXXFLAGS = $(AM_CXXFLAGS)
+if USE_CLANGPP
+# This is to workaround unused variables tcout and tcerr in
+# log4cplus's streams.h.
+run_unittests_CXXFLAGS += -Wno-unused-variable
+endif
 run_unittests_LDADD  = $(GTEST_LDADD)
 run_unittests_LDADD += $(top_builddir)/src/lib/log/liblog.la
 run_unittests_LDADD += $(top_builddir)/src/lib/util/libutil.la
 run_unittests_LDADD += $(top_builddir)/src/lib/exceptions/libexceptions.la
+run_unittests_LDADD += $(top_builddir)/src/lib/util/unittests/libutil_unittests.la
 endif
 
 TESTS += logger_example

src/lib/log/tests/run_unittests.cc

@@ -13,13 +13,13 @@
 // PERFORMANCE OF THIS SOFTWARE.
 
 #include <gtest/gtest.h>
+#include <util/unittests/run_all.h>
 
 #include <log/logger_support.h>
 
 int
 main(int argc, char* argv[]) {
     ::testing::InitGoogleTest(&argc, argv);
-
     isc::log::initLogger();
-    return (RUN_ALL_TESTS());
+    return (isc::util::unittests::run_all());
 }

src/lib/nsas/tests/Makefile.am

@@ -43,8 +43,8 @@ run_unittests_SOURCES += zone_entry_unittest.cc
 run_unittests_SOURCES += fetchable_unittest.cc
 
 run_unittests_CPPFLAGS = $(AM_CPPFLAGS) $(GTEST_INCLUDES)
-run_unittests_LDFLAGS = $(AM_LDFLAGS) $(GTEST_LDFLAGS) $(LOG4CPLUS_LDFLAGS)
-run_unittests_LDADD = $(GTEST_LDADD)
+run_unittests_LDFLAGS  = $(AM_LDFLAGS)  $(GTEST_LDFLAGS)
+run_unittests_LDADD    = $(GTEST_LDADD)
 
 # NOTE: we may have to clean up this hack later (see the note in configure.ac)
 if NEED_LIBBOOST_THREAD
@@ -56,6 +56,7 @@ run_unittests_LDADD += $(top_builddir)/src/lib/util/libutil.la
 run_unittests_LDADD += $(top_builddir)/src/lib/log/liblog.la
 run_unittests_LDADD += $(top_builddir)/src/lib/dns/libdns++.la
 run_unittests_LDADD += $(top_builddir)/src/lib/asiolink/libasiolink.la
+run_unittests_LDADD += $(top_builddir)/src/lib/util/unittests/libutil_unittests.la
 run_unittests_LDADD += $(top_builddir)/src/lib/exceptions/libexceptions.la
 endif
 

src/lib/nsas/tests/run_unittests.cc

@@ -12,24 +12,13 @@
 // OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
 // PERFORMANCE OF THIS SOFTWARE.
 
-#include <config.h>
-#include <stdlib.h>
-
-#include <string>
-#include <boost/lexical_cast.hpp>
-
 #include <gtest/gtest.h>
-
-#include <dns/tests/unittest_util.h>
 #include <log/logger_support.h>
-
-using namespace std;
+#include <util/unittests/run_all.h>
 
 int
 main(int argc, char* argv[]) {
     ::testing::InitGoogleTest(&argc, argv);
-
     isc::log::initLogger();
-
-    return (RUN_ALL_TESTS());
+    return (isc::util::unittests::run_all());
 }

src/lib/python/Makefile.am

@@ -1,6 +1,7 @@
 SUBDIRS = isc
 
 python_PYTHON =	bind10_config.py
+pythondir = $(pyexecdir)
 
 # Explicitly define DIST_COMMON so ${python_PYTHON} is not included
 # as we don't want the generated file included in distributed tarfile.

src/lib/python/bind10_config.py.in

@@ -42,7 +42,8 @@ def reload():
             DATA_PATH = os.environ["B10_FROM_SOURCE_LOCALSTATEDIR"]
         else:
             DATA_PATH = os.environ["B10_FROM_SOURCE"]
-        PLUGIN_PATHS = [DATA_PATH + '/src/bin/cfgmgr/plugins']
+        PLUGIN_PATHS = [os.environ["B10_FROM_SOURCE"] +
+                            '/src/bin/cfgmgr/plugins']
     else:
         DATA_PATH = "@localstatedir@/@PACKAGE@".replace("${prefix}", PREFIX)
         PLUGIN_PATHS = ["@prefix@/share/@PACKAGE@/config_plugins"]

src/lib/python/isc/config/ccsession.py

@@ -329,10 +329,18 @@ class ModuleCCSession(ConfigData):
             if answer:
                 rcode, value = parse_answer(answer)
                 if rcode == 0:
-                    if value != None and self.get_module_spec().validate_config(False, value):
-                        self.set_local_config(value);
-                        if self._config_handler:
-                            self._config_handler(value)
+                    errors = []
+                    if value != None:
+                        if self.get_module_spec().validate_config(False,
+                                                                  value,
+                                                                  errors):
+                            self.set_local_config(value);
+                            if self._config_handler:
+                                self._config_handler(value)
+                        else:
+                            raise ModuleCCSessionError(
+                                "Wrong data in configuration: " +
+                                " ".join(errors))
                 else:
                     # log error
                     print("[" + self._module_name + "] Error requesting configuration: " + value)

src/lib/python/isc/config/cfgmgr.py

@@ -272,7 +272,12 @@ class ConfigManager:
             if type(cmd) == dict:
                 if 'module_name' in cmd and cmd['module_name'] != '':
                     module_name = cmd['module_name']
-                    answer = ccsession.create_answer(0, self.get_module_spec(module_name))
+                    spec = self.get_module_spec(cmd['module_name'])
+                    if type(spec) != type({}):
+                        # this is a ModuleSpec object.  Extract the
+                        # internal spec.
+                        spec = spec.get_full_spec()
+                    answer = ccsession.create_answer(0, spec)
                 else:
                     answer = ccsession.create_answer(1, "Bad module_name in get_module_spec command")
             else:

src/lib/python/isc/config/config_data.py

@@ -108,6 +108,52 @@ def convert_type(spec_part, value):
     except TypeError as err:
         raise isc.cc.data.DataTypeError(str(err))
 
+def _get_map_or_list(spec_part):
+    """Returns the list or map specification if this is a list or a
+       map specification part. If not, returns the given spec_part
+       itself"""
+    if "map_item_spec" in spec_part:
+        return spec_part["map_item_spec"]
+    elif "list_item_spec" in spec_part:
+        return spec_part["list_item_spec"]
+    else:
+        return spec_part
+
+def _find_spec_part_single(cur_spec, id_part):
+    """Find the spec part for the given (partial) name. This partial
+       name does not contain separators ('/'), and the specification
+       part should be a direct child of the given specification part.
+       id_part may contain list selectors, which will be ignored.
+       Returns the child part.
+       Raises DataNotFoundError if it was not found."""
+    # strip list selector part
+    # don't need it for the spec part, so just drop it
+    id, list_indices = isc.cc.data.split_identifier_list_indices(id_part)
+
+    # The specification we want a sub-part for should be either a
+    # list or a map, which is internally represented by a dict with
+    # an element 'map_item_spec', a dict with an element 'list_item_spec',
+    # or a list (when it is the 'main' config_data element of a module).
+    if type(cur_spec) == dict and 'map_item_spec' in cur_spec.keys():
+        for cur_spec_item in cur_spec['map_item_spec']:
+            if cur_spec_item['item_name'] == id:
+                return cur_spec_item
+        # not found
+        raise isc.cc.data.DataNotFoundError(id + " not found")
+    elif type(cur_spec) == dict and 'list_item_spec' in cur_spec.keys():
+        if cur_spec['item_name'] == id:
+            return cur_spec['list_item_spec']
+        # not found
+        raise isc.cc.data.DataNotFoundError(id + " not found")
+    elif type(cur_spec) == list:
+        for cur_spec_item in cur_spec:
+            if cur_spec_item['item_name'] == id:
+                return cur_spec_item
+        # not found
+        raise isc.cc.data.DataNotFoundError(id + " not found")
+    else:
+        raise isc.cc.data.DataNotFoundError("Not a correct config specification")
+
 def find_spec_part(element, identifier):
     """find the data definition for the given identifier
        returns either a map with 'item_name' etc, or a list of those"""
@@ -117,38 +163,15 @@ def find_spec_part(element, identifier):
     id_parts[:] = (value for value in id_parts if value != "")
     cur_el = element
 
-    for id_part in id_parts:
-        # strip list selector part
-        # don't need it for the spec part, so just drop it
-        id, list_indices = isc.cc.data.split_identifier_list_indices(id_part)
-        # is this part still needed? (see below)
-        if type(cur_el) == dict and 'map_item_spec' in cur_el.keys():
-            found = False
-            for cur_el_item in cur_el['map_item_spec']:
-                if cur_el_item['item_name'] == id:
-                    cur_el = cur_el_item
-                    found = True
-            if not found:
-                raise isc.cc.data.DataNotFoundError(id + " not found")
-        elif type(cur_el) == dict and 'list_item_spec' in cur_el.keys():
-            cur_el = cur_el['list_item_spec']
-        elif type(cur_el) == list:
-            found = False
-            for cur_el_item in cur_el:
-                if cur_el_item['item_name'] == id:
-                    cur_el = cur_el_item
-                    # if we need to go further, we may need to 'skip' a step here
-                    # but not if we're done
-                    if id_parts[-1] != id_part and type(cur_el) == dict:
-                        if "map_item_spec" in cur_el:
-                            cur_el = cur_el["map_item_spec"]
-                        elif "list_item_spec" in cur_el:
-                            cur_el = cur_el["list_item_spec"]
-                    found = True
-            if not found:
-                raise isc.cc.data.DataNotFoundError(id + " not found")
-        else:
-            raise isc.cc.data.DataNotFoundError("Not a correct config specification")
+    # up to the last element, if the result is a map or a list,
+    # we want its subspecification (i.e. list_item_spec or
+    # map_item_spec). For the last element in the identifier we
+    # always want the 'full' spec of the item
+    for id_part in id_parts[:-1]:
+        cur_el = _find_spec_part_single(cur_el, id_part)
+        cur_el = _get_map_or_list(cur_el)
+
+    cur_el = _find_spec_part_single(cur_el, id_parts[-1])
     return cur_el
 
 def spec_name_list(spec, prefix="", recurse=False):

src/lib/python/isc/config/module_spec.py

@@ -87,7 +87,7 @@ class ModuleSpec:
            validate only a part of a configuration tree (like a list of
            non-default values)"""
         data_def = self.get_config_spec()
-        if data_def:
+        if data_def is not None:
             return _validate_spec_list(data_def, full, data, errors)
         else:
             # no spec, always bad
@@ -345,7 +345,7 @@ def _validate_spec_list(module_spec, full, data, errors):
             for spec_item in module_spec:
                 if spec_item["item_name"] == item_name:
                     found = True
-            if not found:
+            if not found and item_name != "version":
                 if errors != None:
                     errors.append("unknown item " + item_name)
                 validated = False

src/lib/python/isc/config/tests/ccsession_test.py

@@ -220,6 +220,31 @@ class TestModuleCCSession(unittest.TestCase):
         self.assertEqual({'command': ['get_config', {'module_name': 'Spec2'}]},
                          fake_session.get_message('ConfigManager', None))
 
+    def test_start5(self):
+        fake_session = FakeModuleCCSession()
+        mccs = self.create_session("spec2.spec", None, None, fake_session)
+        mccs.set_config_handler(self.my_config_handler_ok)
+        self.assertEqual(len(fake_session.message_queue), 0)
+        fake_session.group_sendmsg(None, 'Spec2')
+        fake_session.group_sendmsg(None, 'Spec2')
+        self.assertRaises(ModuleCCSessionError, mccs.start)
+        self.assertEqual(len(fake_session.message_queue), 2)
+        self.assertEqual({'command': ['module_spec', mccs.specification._module_spec]},
+                         fake_session.get_message('ConfigManager', None))
+        self.assertEqual({'command': ['get_config', {'module_name': 'Spec2'}]},
+                         fake_session.get_message('ConfigManager', None))
+
+        self.assertEqual(len(fake_session.message_queue), 0)
+        fake_session.group_sendmsg({'result': [ 0 ]}, "Spec2")
+        fake_session.group_sendmsg({'result': [ 0, {"Wrong": True} ]}, "Spec2")
+        self.assertRaises(ModuleCCSessionError, mccs.start)
+        self.assertEqual(len(fake_session.message_queue), 2)
+
+        self.assertEqual({'command': ['module_spec', mccs.specification._module_spec]},
+                         fake_session.get_message('ConfigManager', None))
+        self.assertEqual({'command': ['get_config', {'module_name': 'Spec2'}]},
+                         fake_session.get_message('ConfigManager', None))
+
     def test_get_socket(self):
         fake_session = FakeModuleCCSession()
         mccs = self.create_session("spec1.spec", None, None, fake_session)

src/lib/python/isc/config/tests/cfgmgr_test.py

@@ -178,6 +178,8 @@ class TestConfigManager(unittest.TestCase):
         module_spec2 = self.cm.get_module_spec(module_spec.get_module_name())
         self.assertEqual(module_spec, module_spec2)
 
+        self.assertEqual({}, self.cm.get_module_spec("nosuchmodule"))
+
     def test_get_config_spec(self):
         config_spec = self.cm.get_config_spec()
         self.assertEqual(config_spec, {})
@@ -323,6 +325,9 @@ class TestConfigManager(unittest.TestCase):
         self._handle_msg_helper({ "command": [ "module_spec", { 'foo': 1 } ] },
                                 {'result': [1, 'Error in data definition: no module_name in module_spec']})
         self._handle_msg_helper({ "command": [ "get_module_spec" ] }, { 'result': [ 0, { self.spec.get_module_name(): self.spec.get_full_spec() } ]})
+        self._handle_msg_helper({ "command": [ "get_module_spec",
+                                               { "module_name" : "Spec2" } ] },
+                                { 'result': [ 0, self.spec.get_full_spec() ] })
         self._handle_msg_helper({ "command": [ "get_commands_spec" ] }, { 'result': [ 0, { self.spec.get_module_name(): self.spec.get_commands_spec() } ]})
         # re-add this once we have new way to propagate spec changes (1 instead of the current 2 messages)
         #self.assertEqual(len(self.fake_session.message_queue), 2)

src/lib/python/isc/config/tests/config_data_test.py

@@ -329,6 +329,35 @@ class TestMultiConfigData(unittest.TestCase):
         spec_part = self.mcd.find_spec_part("Spec2/item1")
         self.assertEqual({'item_name': 'item1', 'item_type': 'integer', 'item_optional': False, 'item_default': 1, }, spec_part)
 
+    def test_find_spec_part_nested(self):
+        module_spec = isc.config.module_spec_from_file(self.data_path + os.sep + "spec30.spec")
+        self.mcd.set_specification(module_spec)
+        spec_part = self.mcd.find_spec_part("/lists/first_list_items[0]/second_list_items[1]/final_element")
+        self.assertEqual({'item_name': 'final_element', 'item_type': 'string', 'item_default': 'hello', 'item_optional': False}, spec_part)
+        spec_part = self.mcd.find_spec_part("/BAD_NAME/first_list_items[0]/second_list_items[1]/final_element")
+        self.assertEqual(None, spec_part)
+
+    def test_find_spec_part_nested2(self):
+        module_spec = isc.config.module_spec_from_file(self.data_path + os.sep + "spec31.spec")
+        self.mcd.set_specification(module_spec)
+        spec_part = self.mcd.find_spec_part("/lists/first_list_items[0]/second_list_items[1]/map_element/list1[1]/list2[2]")
+        self.assertEqual({"item_name": "number", "item_type": "integer", "item_optional": False, "item_default": 1}, spec_part)
+
+        spec_part = self.mcd.find_spec_part("/DOESNOTEXIST")
+        self.assertEqual(None, spec_part)
+        spec_part = self.mcd.find_spec_part("/lists/DOESNOTEXIST")
+        self.assertEqual(None, spec_part)
+        spec_part = self.mcd.find_spec_part("/lists/first_list_items[0]/DOESNOTEXIST")
+        self.assertEqual(None, spec_part)
+        spec_part = self.mcd.find_spec_part("/lists/first_list_items[0]/second_list_items[1]/DOESNOTEXIST")
+        self.assertEqual(None, spec_part)
+        spec_part = self.mcd.find_spec_part("/lists/first_list_items[0]/second_list_items[1]/map_element/DOESNOTEXIST")
+        self.assertEqual(None, spec_part)
+        spec_part = self.mcd.find_spec_part("/lists/first_list_items[0]/second_list_items[1]/map_element/list1[1]/DOESNOTEXIST")
+        self.assertEqual(None, spec_part)
+        spec_part = self.mcd.find_spec_part("/lists/first_list_items[0]/second_list_items[1]/map_element/list1[1]/list2[1]/DOESNOTEXIST")
+        self.assertEqual(None, spec_part)
+
     def test_get_current_config(self):
         cf = { 'module1': { 'item1': 2, 'item2': True } }
         self.mcd._set_current_config(cf);

src/lib/python/isc/datasrc/sqlite3_ds.py

@@ -235,13 +235,13 @@ def load(dbfile, zone, reader):
         zone += '.'
 
     conn, cur = open(dbfile)
-    old_zone_id = get_zoneid(zone, cur)
+    try:
+        old_zone_id = get_zoneid(zone, cur)
 
-    temp = str(random.randrange(100000))
-    cur.execute("INSERT INTO zones (name, rdclass) VALUES (?, 'IN')", [temp])
-    new_zone_id = cur.lastrowid
+        temp = str(random.randrange(100000))
+        cur.execute("INSERT INTO zones (name, rdclass) VALUES (?, 'IN')", [temp])
+        new_zone_id = cur.lastrowid
 
-    try:
         for name, ttl, rdclass, rdtype, rdata in reader():
             sigtype = ''
             if rdtype.lower() == 'rrsig':
@@ -266,20 +266,20 @@ def load(dbfile, zone, reader):
                                VALUES (?, ?, ?, ?, ?, ?)""",
                             [new_zone_id, name, reverse_name(name), ttl,
                              rdtype, rdata])
+
+        if old_zone_id:
+            cur.execute("DELETE FROM zones WHERE id=?", [old_zone_id])
+            cur.execute("UPDATE zones SET name=? WHERE id=?", [zone, new_zone_id])
+            conn.commit()
+            cur.execute("DELETE FROM records WHERE zone_id=?", [old_zone_id])
+            cur.execute("DELETE FROM nsec3 WHERE zone_id=?", [old_zone_id])
+            conn.commit()
+        else:
+            cur.execute("UPDATE zones SET name=? WHERE id=?", [zone, new_zone_id])
+            conn.commit()
     except Exception as e:
         fail = "Error while loading " + zone + ": " + e.args[0]
         raise Sqlite3DSError(fail)
-
-    if old_zone_id:
-        cur.execute("DELETE FROM zones WHERE id=?", [old_zone_id])
-        cur.execute("UPDATE zones SET name=? WHERE id=?", [zone, new_zone_id])
-        conn.commit()
-        cur.execute("DELETE FROM records WHERE zone_id=?", [old_zone_id])
-        cur.execute("DELETE FROM nsec3 WHERE zone_id=?", [old_zone_id])
-        conn.commit()
-    else:
-        cur.execute("UPDATE zones SET name=? WHERE id=?", [zone, new_zone_id])
-        conn.commit()
-
-    cur.close()
-    conn.close()
+    finally:
+        cur.close()
+        conn.close()

src/lib/python/isc/datasrc/tests/Makefile.am

@@ -4,6 +4,7 @@ EXTRA_DIST = $(PYTESTS)
 
 EXTRA_DIST += testdata/brokendb.sqlite3
 EXTRA_DIST += testdata/example.com.sqlite3
+CLEANFILES = $(abs_builddir)/example.com.out.sqlite3
 
 # test using command-line arguments, so use check-local target instead of TESTS
 check-local:
@@ -16,5 +17,6 @@ endif
 	echo Running test: $$pytest ; \
 	env PYTHONPATH=$(abs_top_srcdir)/src/lib/python:$(abs_top_builddir)/src/lib/python:$(abs_top_builddir)/src/lib/python/isc/log \
 	TESTDATA_PATH=$(abs_srcdir)/testdata \
+	TESTDATA_WRITE_PATH=$(abs_builddir) \
 	$(PYCOVERAGE_RUN) $(abs_srcdir)/$$pytest || exit ; \
 	done

src/lib/python/isc/datasrc/tests/sqlite3_ds_test.py

@@ -17,8 +17,31 @@ from isc.datasrc import sqlite3_ds
 import os
 import socket
 import unittest
+import sqlite3
 
 TESTDATA_PATH = os.environ['TESTDATA_PATH'] + os.sep
+TESTDATA_WRITE_PATH = os.environ['TESTDATA_WRITE_PATH'] + os.sep
+
+READ_ZONE_DB_FILE = TESTDATA_PATH + "example.com.sqlite3"
+WRITE_ZONE_DB_FILE = TESTDATA_WRITE_PATH + "example.com.out.sqlite3"
+BROKEN_DB_FILE = TESTDATA_PATH + "brokendb.sqlite3"
+
+def example_reader():
+    my_zone = [
+        ("example.com.",    "3600",    "IN",  "SOA", "ns.example.com. admin.example.com. 1234 3600 1800 2419200 7200"),
+        ("example.com.",    "3600",    "IN",  "NS", "ns.example.com."),
+        ("ns.example.com.", "3600",    "IN",  "A", "192.0.2.1")
+    ]
+    for rr in my_zone:
+        yield rr
+
+def example_reader_nested():
+    # this iterator is used in the 'locked' test; it will cause
+    # the load() method to try and write to the same database
+    sqlite3_ds.load(WRITE_ZONE_DB_FILE,
+                    ".",
+                    example_reader)
+    return example_reader()
 
 class TestSqlite3_ds(unittest.TestCase):
     def test_zone_exist(self):
@@ -33,11 +56,40 @@ class TestSqlite3_ds(unittest.TestCase):
         # Open a broken database file
         self.assertRaises(sqlite3_ds.Sqlite3DSError,
                           sqlite3_ds.zone_exist, "example.com",
-                          TESTDATA_PATH + "brokendb.sqlite3")
+                          BROKEN_DB_FILE)
         self.assertTrue(sqlite3_ds.zone_exist("example.com.",
-                            TESTDATA_PATH + "example.com.sqlite3"))
+                        READ_ZONE_DB_FILE))
         self.assertFalse(sqlite3_ds.zone_exist("example.org.",
-                            TESTDATA_PATH + "example.com.sqlite3"))
+                         READ_ZONE_DB_FILE))
+
+    def test_load_db(self):
+        sqlite3_ds.load(WRITE_ZONE_DB_FILE, ".", example_reader)
+
+    def test_locked_db(self):
+        # load it first to make sure it exists
+        sqlite3_ds.load(WRITE_ZONE_DB_FILE, ".", example_reader)
+
+        # and manually create a writing session as well
+        con = sqlite3.connect(WRITE_ZONE_DB_FILE);
+        cur = con.cursor()
+        cur.execute("delete from records")
+
+        self.assertRaises(sqlite3_ds.Sqlite3DSError,
+                          sqlite3_ds.load, WRITE_ZONE_DB_FILE, ".",
+                          example_reader)
+
+        con.rollback()
+
+        # and make sure lock does not stay
+        sqlite3_ds.load(WRITE_ZONE_DB_FILE, ".", example_reader)
+
+        # force locked db by nested loads
+        self.assertRaises(sqlite3_ds.Sqlite3DSError,
+                          sqlite3_ds.load, WRITE_ZONE_DB_FILE, ".",
+                          example_reader_nested)
+
+        # and make sure lock does not stay
+        sqlite3_ds.load(WRITE_ZONE_DB_FILE, ".", example_reader)
 
 if __name__ == '__main__':
     unittest.main()

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)

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_,

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
+

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