Merge branch 'master' into trac957

Conflicts:
	ChangeLog

ChangeLog

@@ -1,12 +1,81 @@
-TBD.	[bug]           y-aharen
+257.	[bug]           y-aharen
 	Fixed a bug an instance of IntervalTimerImpl may be destructed 
 	while deadline_timer is holding the handler. This fix addresses
 	occasional failure of IntervalTimerTest.destructIntervalTimer.
 	(Trac #957, git TBD)
 
+256.	[bug]		jerry
+	src/bin/xfrin: update xfrin to check TSIG before other part of
+	incoming message.
+	(Trac955, git 261450e93af0b0406178e9ef121f81e721e0855c)
+
+255.	[func]		zhang likun
+	src/lib/cache:  remove empty code in lib/cache and the corresponding
+	suppression rule in	src/cppcheck-suppress.lst.
+	(Trac639, git 4f714bac4547d0a025afd314c309ca5cb603e212)
+
+254.	[bug]		jinmei
+	b10-xfrout: failed to send notifies over IPv6 correctly.
+	(Trac964, git 3255c92714737bb461fb67012376788530f16e40)
+
+253.    [func]		jelte
+	Add configuration options for logging through the virtual module
+	Logging.
+	(Trac 736, git 9fa2a95177265905408c51d13c96e752b14a0824)
+
+252.    [func]      	stephen
+	Add syslog as destination for logging.
+	(Trac976, git 31a30f5485859fd3df2839fc309d836e3206546e)
+
+251.	[bug]*		jinmei
+	Make sure bindctl private files are non readable to anyone except
+	the owner or users in the same group.  Note that if BIND 10 is run
+	with changing the user, this change means that the file owner or
+	group will have to be adjusted.  Also note that this change is
+	only effective for a fresh install; if these files already exist,
+	their permissions must be adjusted by hand (if necessary).
+	(Trac870, git 461fc3cb6ebabc9f3fa5213749956467a14ebfd4)
+
+250.    [bug]           ocean
+	src/lib/util/encode, in some conditions, the DecodeNormalizer's
+	iterator may reach the end() and when later being dereferenced
+	it will cause crash on some platform.
+	(Trac838, git 83e33ec80c0c6485d8b116b13045b3488071770f)
+
+249.    [func]      	jerry
+	xfrout: add support for TSIG verification.
+	(Trac816, git 3b2040e2af2f8139c1c319a2cbc429035d93f217)
+
+248.    [func]      	stephen
+	Add file and stderr as destinations for logging.
+	(Trac555, git 38b3546867425bd64dbc5920111a843a3330646b)
+
+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).
+	(Trac#782, git 77d792c9d7c1a3f95d3e6a8b721ac79002cd7db1)
 
 bind10-devel-20110519 released on May 19, 2011
 

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/\* \

configure.ac

@@ -447,6 +447,55 @@ AC_LINK_IFELSE(
 CPPFLAGS=$CPPFLAGS_SAVED
 LDFLAGS=$LDFLAGS_SAVED
 
+# Check for log4cplus
+log4cplus_path="yes"
+AC_ARG_WITH([log4cplus],
+  AC_HELP_STRING([--with-log4cplus=PATH],
+    [specify exact directory of log4cplus library and headers]),
+    [log4cplus_path="$withval"])
+if test "${log4cplus_path}" == "no" ; then
+    AC_MSG_ERROR([Need log4cplus])
+elif test "${log4cplus_path}" != "yes" ; then
+  LOG4CPLUS_INCLUDES="-I${log4cplus_path}/include"
+  LOG4CPLUS_LDFLAGS="-L${log4cplus_path}/lib"
+else
+# If not specified, try some common paths.
+	log4cplusdirs="/usr/local /usr/pkg /opt /opt/local"
+	for d in $log4cplusdirs
+	do
+		if test -f $d/include/log4cplus/logger.h; then
+			LOG4CPLUS_INCLUDES="-I$d/include"
+			LOG4CPLUS_LDFLAGS="-L$d/lib"
+			break
+		fi
+	done
+fi
+
+LOG4CPLUS_LDFLAGS="$LOG4CPLUS_LDFLAGS -llog4cplus $MULTITHREADING_FLAG"
+
+AC_SUBST(LOG4CPLUS_LDFLAGS)
+AC_SUBST(LOG4CPLUS_INCLUDES)
+
+CPPFLAGS_SAVED=$CPPFLAGS
+CPPFLAGS="$LOG4CPLUS_INCLUDES $CPPFLAGS"
+LDFLAGS_SAVED="$LDFLAGS"
+LDFLAGS="$LOG4CPLUS_LDFLAGS $LDFLAGS"
+
+AC_CHECK_HEADERS([log4cplus/logger.h],,AC_MSG_ERROR([Missing required header files.]))
+AC_LINK_IFELSE(
+        [AC_LANG_PROGRAM([#include <log4cplus/logger.h>
+                         ],
+                         [using namespace log4cplus;
+                          Logger logger = Logger::getInstance("main");
+                         ])],
+        [AC_MSG_RESULT([checking for log4cplus library... yes])],
+        [AC_MSG_RESULT([checking for log4cplus library... no])
+         AC_MSG_ERROR([Needs log4cplus library])]
+)
+
+CPPFLAGS=$CPPFLAGS_SAVED
+LDFLAGS=$LDFLAGS_SAVED
+
 #
 # Configure Boost header path
 #
@@ -775,10 +824,11 @@ 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
+                 src/lib/acl/Makefile
+                 src/lib/acl/tests/Makefile
                  tests/Makefile
                  tests/system/Makefile
                  tests/tools/Makefile
@@ -842,7 +892,11 @@ AC_OUTPUT([doc/version.ent
            src/lib/dns/tests/testdata/gen-wiredata.py
            src/lib/cc/session_config.h.pre
            src/lib/cc/tests/session_unittests_config.h
-           src/lib/log/tests/run_time_init_test.sh
+           src/lib/log/tests/console_test.sh
+           src/lib/log/tests/destination_test.sh
+           src/lib/log/tests/local_file_test.sh
+           src/lib/log/tests/severity_test.sh
+           src/lib/log/tests/tempdir.h
            src/lib/util/python/mkpywrapper.py
            src/lib/server_common/tests/data_path.h
            tests/system/conf.sh
@@ -869,7 +923,10 @@ AC_OUTPUT([doc/version.ent
            chmod +x src/bin/msgq/tests/msgq_test
            chmod +x src/lib/dns/gen-rdatacode.py
            chmod +x src/lib/dns/tests/testdata/gen-wiredata.py
-           chmod +x src/lib/log/tests/run_time_init_test.sh
+           chmod +x src/lib/log/tests/local_file_test.sh
+           chmod +x src/lib/log/tests/console_test.sh
+           chmod +x src/lib/log/tests/destination_test.sh
+           chmod +x src/lib/log/tests/severity_test.sh
            chmod +x src/lib/util/python/mkpywrapper.py
            chmod +x tests/system/conf.sh
           ])
@@ -902,6 +959,8 @@ dnl includes too
   Boost:         ${BOOST_INCLUDES}
   Botan:         ${BOTAN_INCLUDES}
                  ${BOTAN_LDFLAGS}
+  Log4cplus:     ${LOG4CPLUS_INCLUDES}
+                 ${LOG4CPLUS_LDFLAGS}
   SQLite:        $SQLITE_CFLAGS
                  $SQLITE_LIBS
 

doc/Doxyfile

@@ -573,8 +573,8 @@ INPUT                  = ../src/lib/cc ../src/lib/config \
     ../src/bin/auth ../src/bin/resolver ../src/lib/bench \
     ../src/lib/log ../src/lib/asiolink/ ../src/lib/nsas \
     ../src/lib/testutils ../src/lib/cache ../src/lib/server_common/ \
-    ../src/bin/sockcreator/ ../src/lib/util/
-    ../src/lib/resolve
+    ../src/bin/sockcreator/ ../src/lib/util/ \
+    ../src/lib/resolve ../src/lib/acl
 
 # This tag can be used to specify the character encoding of the source files
 # that doxygen parses. Internally doxygen uses the UTF-8 encoding, which is

src/bin/auth/Makefile.am

@@ -51,7 +51,7 @@ 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)

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

@@ -26,3 +26,4 @@ query_bench_LDADD += $(top_builddir)/src/lib/asiodns/libasiodns.la
 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)
+

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

@@ -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,8 @@
 // PERFORMANCE OF THIS SOFTWARE.
 
 #include <gtest/gtest.h>
+#include <log/logger_support.h>
+#include <util/unittests/run_all.h>
 
 #include <dns/tests/unittest_util.h>
 
@@ -21,6 +23,7 @@ main(int argc, char* argv[]) {
     ::testing::InitGoogleTest(&argc, argv);
     isc::UnitTestUtil::addDataPath(TEST_DATA_DIR);
     isc::UnitTestUtil::addDataPath(TEST_DATA_BUILDDIR);
+    isc::log::initLogger();
 
-    return (RUN_ALL_TESTS());
+    return (isc::util::unittests::run_all());
 }

src/bin/cfgmgr/plugins/Makefile.am

@@ -1,5 +1,6 @@
 SUBDIRS = tests
 EXTRA_DIST = README tsig_keys.py tsig_keys.spec
+EXTRA_DIST += logging.spec b10logging.py
 
 config_plugindir = @prefix@/share/@PACKAGE@/config_plugins
 config_plugin_DATA = tsig_keys.py tsig_keys.spec

src/bin/cfgmgr/plugins/b10logging.py

@@ -0,0 +1,96 @@
+# Copyright (C) 2011  Internet Systems Consortium.
+#
+# Permission to use, copy, modify, and 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 INTERNET SYSTEMS CONSORTIUM
+# DISCLAIMS ALL WARRANTIES WITH REGARD TO THIS SOFTWARE INCLUDING ALL
+# IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL
+# INTERNET SYSTEMS CONSORTIUM 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.
+
+# This is the configuration plugin for logging options
+# The name is 'b10logging' because logging.py is an existing module
+#
+# For a technical background, see
+# http://bind10.isc.org/wiki/LoggingCppApiDesign
+#
+
+from isc.config.module_spec import module_spec_from_file
+from isc.util.file import path_search
+from bind10_config import PLUGIN_PATHS
+spec = module_spec_from_file(path_search('logging.spec', PLUGIN_PATHS))
+
+ALLOWED_SEVERITIES = [ 'default',
+                       'debug',
+                       'info',
+                       'warn',
+                       'error',
+                       'fatal',
+                       'none' ]
+ALLOWED_DESTINATIONS = [ 'console',
+                         'file',
+                         'syslog' ]
+ALLOWED_STREAMS = [ 'stdout',
+                    'stderr' ]
+
+def check(config):
+    # Check the data layout first
+    errors=[]
+    if not spec.validate_config(False, config, errors):
+        return ' '.join(errors)
+    # The 'layout' is ok, now check for specific values
+    if 'loggers' in config:
+        for logger in config['loggers']:
+            # name should always be present
+            name = logger['name']
+
+            if 'severity' in logger and\
+               logger['severity'].lower() not in ALLOWED_SEVERITIES:
+                errors.append("bad severity value for logger " + name +
+                              ": " + logger['severity'])
+            if 'output_options' in logger:
+                for output_option in logger['output_options']:
+                    if 'destination' in output_option:
+                        destination = output_option['destination'].lower()
+                        if destination not in ALLOWED_DESTINATIONS:
+                            errors.append("bad destination for logger " +
+                            name + ": " + output_option['destination'])
+                        else:
+                            # if left to default, output is stdout, and
+                            # it will not show in the updated config,
+                            # so 1. we only need to check it if present,
+                            # and 2. if destination is changed, so should
+                            # output. So first check checks 'in', and the
+                            # others 'not in' for 'output'
+                            if destination == "console" and\
+                               'output' in output_option and\
+                               output_option['output'] not in ALLOWED_STREAMS:
+                                errors.append("bad output for logger " + name +
+                                              ": " + output_option['stream'] +
+                                              ", must be stdout or stderr")
+                            elif destination == "file" and\
+                                 'output' not in output_option or\
+                                 output_option['output'] == "":
+                                    errors.append("destination set to file but "
+                                                  "output not set to any "
+                                                  "filename for logger "
+                                                  + name)
+                            elif destination == "syslog" and\
+                                 'output' not in output_option or\
+                                 output_option['output'] == "":
+                                    errors.append("destination set to syslog but "
+                                                  "output not set to any facility"
+                                                  " for logger " + name)
+
+    if errors:
+        return ', '.join(errors)
+    return None
+
+def load():
+    return (spec, check)
+

src/bin/cfgmgr/plugins/logging.spec

@@ -0,0 +1,81 @@
+{
+    "module_spec": {
+        "module_name": "Logging",
+        "module_description": "Logging options",
+        "config_data": [
+            {
+                "item_name": "loggers",
+                "item_type": "list",
+                "item_optional": false,
+                "item_default": [],
+                "list_item_spec": {
+                  "item_name": "logger",
+                  "item_type": "map",
+                  "item_optional": false,
+                  "item_default": {},
+                  "map_item_spec": [
+                  {  "item_name": "name",
+                     "item_type": "string",
+                     "item_optional": false,
+                     "item_default": ""
+                  },
+                  {  "item_name": "severity",
+                     "item_type": "string",
+                     "item_optional": false,
+                     "item_default": "INFO"
+                  },
+                  {  "item_name": "debuglevel",
+                     "item_type": "integer",
+                     "item_optional": false,
+                     "item_default": 0
+                  },
+                  {  "item_name": "additive",
+                     "item_type": "boolean",
+                     "item_optional": false,
+                     "item_default": false
+                  },
+                  { "item_name": "output_options",
+                    "item_type": "list",
+                    "item_optional": false,
+                    "item_default": [],
+                    "list_item_spec": {
+                      "item_name": "output_option",
+                      "item_type": "map",
+                      "item_optional": false,
+                      "item_default": {},
+                      "map_item_spec": [
+                      { "item_name": "destination",
+                        "item_type": "string",
+                        "item_optional": false,
+                        "item_default": "console"
+                      },
+                      { "item_name": "output",
+                        "item_type": "string",
+                        "item_optional": false,
+                        "item_default": "stdout"
+                      },
+                      { "item_name": "flush",
+                        "item_type": "boolean",
+                        "item_optional": false,
+                        "item_default": false
+                      },
+                      { "item_name": "maxsize",
+                        "item_type": "integer",
+                        "item_optional": false,
+                        "item_default": 0
+                      },
+                      { "item_name": "maxver",
+                        "item_type": "integer",
+                        "item_optional": false,
+                        "item_default": 0
+                      }
+                      ]
+                    }
+                  }
+                  ]
+                }
+            }
+        ],
+        "commands": []
+    }
+}

src/bin/cfgmgr/plugins/tests/tsig_keys_test.py

@@ -86,7 +86,7 @@ class TSigKeysTest(unittest.TestCase):
         self.assertEqual("TSIG: Invalid TSIG key string: invalid.key",
                          tsig_keys.check({'keys': ['invalid.key']}))
         self.assertEqual(
-            "TSIG: attempt to decode a value not in base64 char set",
+            "TSIG: Unexpected end of input in BASE decoder",
             tsig_keys.check({'keys': ['invalid.key:123']}))
 
     def test_bad_format(self):

src/bin/cmdctl/Makefile.am

@@ -40,12 +40,13 @@ b10-cmdctl: cmdctl.py
 
 if INSTALL_CONFIGURATIONS
 
-# TODO: permissions handled later
+# Below we intentionally use ${INSTALL} -m 640 instead of $(INSTALL_DATA)
+# because these file will contain sensitive information.
 install-data-local:
 	$(mkinstalldirs) $(DESTDIR)/@sysconfdir@/@PACKAGE@   
 	for f in $(CMDCTL_CONFIGURATIONS) ; do	\
 	  if test ! -f $(DESTDIR)$(sysconfdir)/@PACKAGE@/$$f; then	\
-	    $(INSTALL_DATA) $(srcdir)/$$f $(DESTDIR)$(sysconfdir)/@PACKAGE@/ ;	\
+	    ${INSTALL} -m 640 $(srcdir)/$$f $(DESTDIR)$(sysconfdir)/@PACKAGE@/ ;	\
 	  fi ;	\
 	done
 

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

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,14 @@ 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.");
+                                             my_command_handler,
+                                             true, true);
+        LOG_DEBUG(resolver_logger, RESOLVER_DBG_INIT, RESOLVER_CONFIGCHAN);
 
         // FIXME: This does not belong here, but inside Boss
         if (uid != NULL) {
@@ -213,17 +218,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/bin/resolver/resolver_log.cc

@@ -0,0 +1,19 @@
+// 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 "resolver_log.h"
+
+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,20 +17,24 @@ 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)
-run_unittests_LDADD = $(GTEST_LDADD)
-run_unittests_LDADD += $(SQLITE_LIBS)
+run_unittests_LDFLAGS  = $(AM_LDFLAGS)  $(GTEST_LDFLAGS)
+
+run_unittests_LDADD  = $(GTEST_LDADD)
 run_unittests_LDADD += $(top_builddir)/src/lib/testutils/libtestutils.la
-run_unittests_LDADD += $(top_builddir)/src/lib/datasrc/libdatasrc.la
 run_unittests_LDADD += $(top_builddir)/src/lib/dns/libdns++.la
 run_unittests_LDADD += $(top_builddir)/src/lib/asiodns/libasiodns.la
 run_unittests_LDADD += $(top_builddir)/src/lib/asiolink/libasiolink.la
@@ -42,6 +47,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,8 @@
 // PERFORMANCE OF THIS SOFTWARE.
 
 #include <gtest/gtest.h>
+#include <log/logger_support.h>
+#include <util/unittests/run_all.h>
 
 #include <dns/tests/unittest_util.h>
 
@@ -21,6 +23,7 @@ main(int argc, char* argv[]) {
     ::testing::InitGoogleTest(&argc, argv);
     isc::UnitTestUtil::addDataPath(TEST_DATA_DIR);
     isc::UnitTestUtil::addDataPath(TEST_DATA_BUILDDIR);
+    isc::log::initLogger();
 
-    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/tests/xfrin_test.py

@@ -15,6 +15,7 @@
 
 import unittest
 import socket
+import io
 from isc.testutils.tsigctx_mock import MockTSIGContext
 from xfrin import *
 
@@ -78,7 +79,7 @@ class MockXfrin(Xfrin):
 
     def _get_db_file(self):
         pass
-    
+
     def _cc_check_command(self):
         self._shutdown_event.set()
         if MockXfrin.check_command_hook:
@@ -207,6 +208,18 @@ class TestXfrinConnection(unittest.TestCase):
         mock_ctx.error = error
         return mock_ctx
 
+    def __match_exception(self, expected_exception, expected_msg, expression):
+        # This helper method is a higher-granularity version of assertRaises().
+        # If it's not sufficient to check the exception class (e.g., when
+        # the same type of exceptions can be thrown from many places), this
+        # method can be used to check it with the exception argument.
+        try:
+            expression()
+        except expected_exception as ex:
+            self.assertEqual(str(ex), expected_msg)
+        else:
+            self.assertFalse('exception is expected, but not raised')
+
     def test_close(self):
         # we shouldn't be using the global asyncore map.
         self.assertEqual(len(asyncore.socket_map), 0)
@@ -293,6 +306,31 @@ class TestXfrinConnection(unittest.TestCase):
         self.conn.reply_data = self.conn.create_response_data(bad_qid = True)
         self.assertRaises(XfrinException, self._handle_xfrin_response)
 
+    def test_response_error_code_bad_sig(self):
+        self.conn._tsig_key = TSIG_KEY
+        self.conn._tsig_ctx_creator = \
+            lambda key: self.__create_mock_tsig(key, TSIGError.BAD_SIG)
+        self.conn._send_query(RRType.AXFR())
+        self.conn.reply_data = self.conn.create_response_data(
+                rcode=Rcode.SERVFAIL())
+        # xfrin should check TSIG before other part of incoming message
+        # validate log message for XfrinException
+        self.__match_exception(XfrinException,
+                               "TSIG verify fail: BADSIG",
+                               self._handle_xfrin_response)
+
+    def test_response_bad_qid_bad_key(self):
+        self.conn._tsig_key = TSIG_KEY
+        self.conn._tsig_ctx_creator = \
+            lambda key: self.__create_mock_tsig(key, TSIGError.BAD_KEY)
+        self.conn._send_query(RRType.AXFR())
+        self.conn.reply_data = self.conn.create_response_data(bad_qid=True)
+        # xfrin should check TSIG before other part of incoming message
+        # validate log message for XfrinException
+        self.__match_exception(XfrinException,
+                               "TSIG verify fail: BADKEY",
+                               self._handle_xfrin_response)
+
     def test_response_non_response(self):
         self.conn._send_query(RRType.AXFR())
         self.conn.reply_data = self.conn.create_response_data(response = False)
@@ -337,6 +375,18 @@ class TestXfrinConnection(unittest.TestCase):
         self.conn.response_generator = self._create_soa_response_data
         self.assertRaises(XfrinException, self.conn._check_soa_serial)
 
+    def test_soacheck_bad_qid_bad_sig(self):
+        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['bad_qid'] = True
+        self.conn.response_generator = self._create_soa_response_data
+        # xfrin should check TSIG before other part of incoming message
+        # validate log message for XfrinException
+        self.__match_exception(XfrinException,
+                               "TSIG verify fail: BADSIG",
+                               self.conn._check_soa_serial)
+
     def test_soacheck_non_response(self):
         self.soa_response_params['response'] = False
         self.conn.response_generator = self._create_soa_response_data

src/bin/xfrin/xfrin.py.in

@@ -243,13 +243,13 @@ class XfrinConnection(asyncore.dispatcher):
         msg = Message(Message.PARSE)
         msg.from_wire(soa_response)
 
+        # TSIG related checks, including an unexpected signed response
+        self._check_response_tsig(msg, soa_response)
+
         # perform some minimal level validation.  It's an open issue how
         # strict we should be (see the comment in _check_response_header())
         self._check_response_header(msg)
 
-        # TSIG related checks, including an unexpected signed response
-        self._check_response_tsig(msg, soa_response)
-
         # TODO, need select soa record from data source then compare the two
         # serial, current just return OK, since this function hasn't been used
         # now.
@@ -311,7 +311,7 @@ class XfrinConnection(asyncore.dispatcher):
             raise XfrinException('error response: %s' % msg_rcode.to_text())
 
         if not msg.get_header_flag(Message.HEADERFLAG_QR):
-            raise XfrinException('response is not a response ')
+            raise XfrinException('response is not a response')
 
         if msg.get_qid() != self._query_id:
             raise XfrinException('bad query id')
@@ -362,11 +362,13 @@ class XfrinConnection(asyncore.dispatcher):
             recvdata = self._get_request_response(msg_len)
             msg = Message(Message.PARSE)
             msg.from_wire(recvdata)
-            self._check_response_status(msg)
 
             # TSIG related checks, including an unexpected signed response
             self._check_response_tsig(msg, recvdata)
 
+            # Perform response status validation
+            self._check_response_status(msg)
+
             answer_section = msg.get_section(Message.SECTION_ANSWER)
             for rr in self._handle_answer_section(answer_section):
                 yield rr

src/bin/xfrout/tests/xfrout_test.py.in

@@ -18,11 +18,14 @@
 
 import unittest
 import os
+from isc.testutils.tsigctx_mock import MockTSIGContext
 from isc.cc.session import *
 from pydnspp import *
 from xfrout import *
 import xfrout
 
+TSIG_KEY = TSIGKey("example.com:SFuWd/q99SzF8Yzd1QbB9g==")
+
 # our fake socket, where we can read and insert messages
 class MySocket():
     def __init__(self, family, type):
@@ -85,10 +88,36 @@ class TestXfroutSession(unittest.TestCase):
         msg.from_wire(self.mdata)
         return msg
 
+    def create_mock_tsig_ctx(self, 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(TSIG_KEY)
+        mock_ctx.error = error
+        return mock_ctx
+
+    def message_has_tsig(self, msg):
+        return msg.get_tsig_record() is not None
+
+    def create_request_data_with_tsig(self):
+        msg = Message(Message.RENDER)
+        query_id = 0x1035
+        msg.set_qid(query_id)
+        msg.set_opcode(Opcode.QUERY())
+        msg.set_rcode(Rcode.NOERROR())
+        query_question = Question(Name("example.com."), RRClass.IN(), RRType.AXFR())
+        msg.add_question(query_question)
+
+        renderer = MessageRenderer()
+        tsig_ctx = MockTSIGContext(TSIG_KEY)
+        msg.to_wire(renderer, tsig_ctx)
+        reply_data = renderer.get_data()
+        return reply_data
+
     def setUp(self):
         self.sock = MySocket(socket.AF_INET,socket.SOCK_STREAM)
         self.log = isc.log.NSLogger('xfrout', '',  severity = 'critical', log_to_console = False )
-        self.xfrsess = MyXfroutSession(self.sock, None, Dbserver(), self.log)
+        self.xfrsess = MyXfroutSession(self.sock, None, Dbserver(), self.log, TSIGKeyRing())
         self.mdata = bytes(b'\xd6=\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x07example\x03com\x00\x00\xfc\x00\x01')
         self.soa_record = (4, 3, 'example.com.', 'com.example.', 3600, 'SOA', None, 'master.example.com. admin.example.com. 1234 3600 1800 2419200 7200')
 
@@ -96,6 +125,18 @@ class TestXfroutSession(unittest.TestCase):
         [get_rcode, get_msg] = self.xfrsess._parse_query_message(self.mdata)
         self.assertEqual(get_rcode.to_text(), "NOERROR")
 
+        # tsig signed query message
+        request_data = self.create_request_data_with_tsig()
+        # BADKEY
+        [rcode, msg] = self.xfrsess._parse_query_message(request_data)
+        self.assertEqual(rcode.to_text(), "NOTAUTH")
+        self.assertTrue(self.xfrsess._tsig_ctx is not None)
+        # NOERROR
+        self.xfrsess._tsig_key_ring.add(TSIG_KEY)
+        [rcode, msg] = self.xfrsess._parse_query_message(request_data)
+        self.assertEqual(rcode.to_text(), "NOERROR")
+        self.assertTrue(self.xfrsess._tsig_ctx is not None)
+
     def test_get_query_zone_name(self):
         msg = self.getmsg()
         self.assertEqual(self.xfrsess._get_query_zone_name(msg), "example.com.")
@@ -111,6 +152,14 @@ class TestXfroutSession(unittest.TestCase):
         get_msg = self.sock.read_msg()
         self.assertEqual(get_msg.get_rcode().to_text(), "NXDOMAIN")
 
+        # tsig signed message
+        msg = self.getmsg()
+        self.xfrsess._tsig_ctx = self.create_mock_tsig_ctx(TSIGError.NOERROR)
+        self.xfrsess._reply_query_with_error_rcode(msg, self.sock, Rcode(3))
+        get_msg = self.sock.read_msg()
+        self.assertEqual(get_msg.get_rcode().to_text(), "NXDOMAIN")
+        self.assertTrue(self.message_has_tsig(get_msg))
+
     def test_send_message(self):
         msg = self.getmsg()
         msg.make_response()
@@ -152,6 +201,14 @@ class TestXfroutSession(unittest.TestCase):
         get_msg = self.sock.read_msg()
         self.assertEqual(get_msg.get_rcode().to_text(), "FORMERR")
 
+        # tsig signed message
+        msg = self.getmsg()
+        self.xfrsess._tsig_ctx = self.create_mock_tsig_ctx(TSIGError.NOERROR)
+        self.xfrsess._reply_query_with_format_error(msg, self.sock)
+        get_msg = self.sock.read_msg()
+        self.assertEqual(get_msg.get_rcode().to_text(), "FORMERR")
+        self.assertTrue(self.message_has_tsig(get_msg))
+
     def test_create_rrset_from_db_record(self):
         rrset = self.xfrsess._create_rrset_from_db_record(self.soa_record)
         self.assertEqual(rrset.get_name().to_text(), "example.com.")
@@ -162,11 +219,16 @@ class TestXfroutSession(unittest.TestCase):
 
     def test_send_message_with_last_soa(self):
         rrset_soa = self.xfrsess._create_rrset_from_db_record(self.soa_record)
-
         msg = self.getmsg()
         msg.make_response()
-        self.xfrsess._send_message_with_last_soa(msg, self.sock, rrset_soa, 0)
+
+        # packet number less than TSIG_SIGN_EVERY_NTH
+        packet_neet_not_sign = xfrout.TSIG_SIGN_EVERY_NTH - 1
+        self.xfrsess._send_message_with_last_soa(msg, self.sock, rrset_soa,
+                                                 0, packet_neet_not_sign)
         get_msg = self.sock.read_msg()
+        # tsig context is not exist
+        self.assertFalse(self.message_has_tsig(get_msg))
 
         self.assertEqual(get_msg.get_rr_count(Message.SECTION_QUESTION), 1)
         self.assertEqual(get_msg.get_rr_count(Message.SECTION_ANSWER), 1)
@@ -180,6 +242,42 @@ class TestXfroutSession(unittest.TestCase):
         rdata = answer.get_rdata()
         self.assertEqual(rdata[0].to_text(), self.soa_record[7])
 
+        # msg is the TSIG_SIGN_EVERY_NTH one
+        # sending the message with last soa together
+        self.xfrsess._send_message_with_last_soa(msg, self.sock, rrset_soa,
+                                                 0, TSIG_SIGN_EVERY_NTH)
+        get_msg = self.sock.read_msg()
+        # tsig context is not exist
+        self.assertFalse(self.message_has_tsig(get_msg))
+
+    def test_send_message_with_last_soa_with_tsig(self):
+        # create tsig context
+        self.xfrsess._tsig_ctx = self.create_mock_tsig_ctx(TSIGError.NOERROR)
+
+        rrset_soa = self.xfrsess._create_rrset_from_db_record(self.soa_record)
+        msg = self.getmsg()
+        msg.make_response()
+
+        # packet number less than TSIG_SIGN_EVERY_NTH
+        packet_neet_not_sign = xfrout.TSIG_SIGN_EVERY_NTH - 1
+        # msg is not the TSIG_SIGN_EVERY_NTH one
+        # sending the message with last soa together
+        self.xfrsess._send_message_with_last_soa(msg, self.sock, rrset_soa,
+                                                 0, packet_neet_not_sign)
+        get_msg = self.sock.read_msg()
+        self.assertTrue(self.message_has_tsig(get_msg))
+
+        self.assertEqual(get_msg.get_rr_count(Message.SECTION_QUESTION), 1)
+        self.assertEqual(get_msg.get_rr_count(Message.SECTION_ANSWER), 1)
+        self.assertEqual(get_msg.get_rr_count(Message.SECTION_AUTHORITY), 0)
+
+        # msg is the TSIG_SIGN_EVERY_NTH one
+        # sending the message with last soa together
+        self.xfrsess._send_message_with_last_soa(msg, self.sock, rrset_soa,
+                                                 0, TSIG_SIGN_EVERY_NTH)
+        get_msg = self.sock.read_msg()
+        self.assertTrue(self.message_has_tsig(get_msg))
+
     def test_trigger_send_message_with_last_soa(self):
         rrset_a = RRset(Name("example.com"), RRClass.IN(), RRType.A(), RRTTL(3600))
         rrset_a.add_rdata(Rdata(RRType.A(), RRClass.IN(), "192.0.2.1"))
@@ -187,15 +285,21 @@ class TestXfroutSession(unittest.TestCase):
 
         msg = self.getmsg()
         msg.make_response()
-
         msg.add_rrset(Message.SECTION_ANSWER, rrset_a)
-        # give the function a value that is larger than MAX-len(rrset)
-        self.xfrsess._send_message_with_last_soa(msg, self.sock, rrset_soa, 65520)
 
+        # length larger than MAX-len(rrset)
+        length_need_split = xfrout.XFROUT_MAX_MESSAGE_SIZE - get_rrset_len(rrset_soa) + 1
+        # packet number less than TSIG_SIGN_EVERY_NTH
+        packet_neet_not_sign = xfrout.TSIG_SIGN_EVERY_NTH - 1
+
+        # give the function a value that is larger than MAX-len(rrset)
         # this should have triggered the sending of two messages
         # (1 with the rrset we added manually, and 1 that triggered
         # the sending in _with_last_soa)
+        self.xfrsess._send_message_with_last_soa(msg, self.sock, rrset_soa, length_need_split,
+                                                 packet_neet_not_sign)
         get_msg = self.sock.read_msg()
+        self.assertFalse(self.message_has_tsig(get_msg))
         self.assertEqual(get_msg.get_rr_count(Message.SECTION_QUESTION), 1)
         self.assertEqual(get_msg.get_rr_count(Message.SECTION_ANSWER), 1)
         self.assertEqual(get_msg.get_rr_count(Message.SECTION_AUTHORITY), 0)
@@ -208,6 +312,7 @@ class TestXfroutSession(unittest.TestCase):
         self.assertEqual(rdata[0].to_text(), "192.0.2.1")
 
         get_msg = self.sock.read_msg()
+        self.assertFalse(self.message_has_tsig(get_msg))
         self.assertEqual(get_msg.get_rr_count(Message.SECTION_QUESTION), 0)
         self.assertEqual(get_msg.get_rr_count(Message.SECTION_ANSWER), 1)
         self.assertEqual(get_msg.get_rr_count(Message.SECTION_AUTHORITY), 0)
@@ -223,6 +328,45 @@ class TestXfroutSession(unittest.TestCase):
         # and it should not have sent anything else
         self.assertEqual(0, len(self.sock.sendqueue))
 
+    def test_trigger_send_message_with_last_soa_with_tsig(self):
+        self.xfrsess._tsig_ctx = self.create_mock_tsig_ctx(TSIGError.NOERROR)
+        rrset_soa = self.xfrsess._create_rrset_from_db_record(self.soa_record)
+        msg = self.getmsg()
+        msg.make_response()
+        msg.add_rrset(Message.SECTION_ANSWER, rrset_soa)
+
+        # length larger than MAX-len(rrset)
+        length_need_split = xfrout.XFROUT_MAX_MESSAGE_SIZE - get_rrset_len(rrset_soa) + 1
+        # packet number less than TSIG_SIGN_EVERY_NTH
+        packet_neet_not_sign = xfrout.TSIG_SIGN_EVERY_NTH - 1
+
+        # give the function a value that is larger than MAX-len(rrset)
+        # this should have triggered the sending of two messages
+        # (1 with the rrset we added manually, and 1 that triggered
+        # the sending in _with_last_soa)
+        self.xfrsess._send_message_with_last_soa(msg, self.sock, rrset_soa, length_need_split,
+                                                 packet_neet_not_sign)
+        get_msg = self.sock.read_msg()
+        # msg is not the TSIG_SIGN_EVERY_NTH one, it shouldn't be tsig signed
+        self.assertFalse(self.message_has_tsig(get_msg))
+        # the last packet should be tsig signed
+        get_msg = self.sock.read_msg()
+        self.assertTrue(self.message_has_tsig(get_msg))
+        # and it should not have sent anything else
+        self.assertEqual(0, len(self.sock.sendqueue))
+
+
+        # msg is the TSIG_SIGN_EVERY_NTH one, it should be tsig signed
+        self.xfrsess._send_message_with_last_soa(msg, self.sock, rrset_soa, length_need_split,
+                                                 xfrout.TSIG_SIGN_EVERY_NTH)
+        get_msg = self.sock.read_msg()
+        self.assertTrue(self.message_has_tsig(get_msg))
+        # the last packet should be tsig signed
+        get_msg = self.sock.read_msg()
+        self.assertTrue(self.message_has_tsig(get_msg))
+        # and it should not have sent anything else
+        self.assertEqual(0, len(self.sock.sendqueue))
+
     def test_get_rrset_len(self):
         rrset_soa = self.xfrsess._create_rrset_from_db_record(self.soa_record)
         self.assertEqual(82, get_rrset_len(rrset_soa))
@@ -313,6 +457,51 @@ class TestXfroutSession(unittest.TestCase):
         reply_msg = self.sock.read_msg()
         self.assertEqual(reply_msg.get_rr_count(Message.SECTION_ANSWER), 2)
 
+    def test_reply_xfrout_query_noerror_with_tsig(self):
+        rrset_data = (4, 3, 'a.example.com.', 'com.example.', 3600, 'A', None, '192.168.1.1')
+        global sqlite3_ds
+        global xfrout
+        def get_zone_soa(zonename, file):
+            return self.soa_record
+
+        def get_zone_datas(zone, file):
+            zone_rrsets = []
+            for i in range(0, 100):
+                zone_rrsets.insert(i, rrset_data)
+            return zone_rrsets
+
+        def get_rrset_len(rrset):
+            return 65520
+
+        sqlite3_ds.get_zone_soa = get_zone_soa
+        sqlite3_ds.get_zone_datas = get_zone_datas
+        xfrout.get_rrset_len = get_rrset_len
+
+        self.xfrsess._tsig_ctx = self.create_mock_tsig_ctx(TSIGError.NOERROR)
+        self.xfrsess._reply_xfrout_query(self.getmsg(), self.sock, "example.com.")
+
+        # tsig signed first package
+        reply_msg = self.sock.read_msg()
+        self.assertEqual(reply_msg.get_rr_count(Message.SECTION_ANSWER), 1)
+        self.assertTrue(self.message_has_tsig(reply_msg))
+        # (TSIG_SIGN_EVERY_NTH - 1) packets have no tsig
+        for i in range(0, xfrout.TSIG_SIGN_EVERY_NTH - 1):
+            reply_msg = self.sock.read_msg()
+            self.assertFalse(self.message_has_tsig(reply_msg))
+        # TSIG_SIGN_EVERY_NTH packet has tsig
+        reply_msg = self.sock.read_msg()
+        self.assertTrue(self.message_has_tsig(reply_msg))
+
+        for i in range(0, 100 - TSIG_SIGN_EVERY_NTH):
+            reply_msg = self.sock.read_msg()
+            self.assertFalse(self.message_has_tsig(reply_msg))
+        # tsig signed last package
+        reply_msg = self.sock.read_msg()
+        self.assertTrue(self.message_has_tsig(reply_msg))
+
+        # and it should not have sent anything else
+        self.assertEqual(0, len(self.sock.sendqueue))
+
 class MyCCSession():
     def __init__(self):
         pass
@@ -347,8 +536,23 @@ class TestUnixSockServer(unittest.TestCase):
         self.assertEqual(recv_msg, send_msg)
 
     def test_updata_config_data(self):
+        tsig_key_str = 'example.com:SFuWd/q99SzF8Yzd1QbB9g=='
+        tsig_key_list = [tsig_key_str]
+        bad_key_list = ['bad..example.com:SFuWd/q99SzF8Yzd1QbB9g==']
         self.unix.update_config_data({'transfers_out':10 })
         self.assertEqual(self.unix._max_transfers_out, 10)
+        self.assertTrue(self.unix.tsig_key_ring is not None)
+
+        self.unix.update_config_data({'transfers_out':9, 'tsig_key_ring':tsig_key_list})
+        self.assertEqual(self.unix._max_transfers_out, 9)
+        self.assertEqual(self.unix.tsig_key_ring.size(), 1)
+        self.unix.tsig_key_ring.remove(Name("example.com."))
+        self.assertEqual(self.unix.tsig_key_ring.size(), 0)
+
+        # bad tsig key
+        config_data = {'transfers_out':9, 'tsig_key_ring': bad_key_list}
+        self.assertRaises(None, self.unix.update_config_data(config_data))
+        self.assertEqual(self.unix.tsig_key_ring.size(), 0)
 
     def test_get_db_file(self):
         self.assertEqual(self.unix.get_db_file(), "initdb.file")

src/bin/xfrout/xfrout.py.in

@@ -74,10 +74,12 @@ SPECFILE_LOCATION = SPECFILE_PATH + "/xfrout.spec"
 AUTH_SPECFILE_LOCATION = AUTH_SPECFILE_PATH + os.sep + "auth.spec"
 MAX_TRANSFERS_OUT = 10
 VERBOSE_MODE = False
-
+# tsig sign every N axfr packets.
+TSIG_SIGN_EVERY_NTH = 96
 
 XFROUT_MAX_MESSAGE_SIZE = 65535
 
+
 def get_rrset_len(rrset):
     """Returns the wire length of the given RRset"""
     bytes = bytearray()
@@ -86,15 +88,22 @@ def get_rrset_len(rrset):
 
 
 class XfroutSession():
-    def __init__(self, sock_fd, request_data, server, log):
+    def __init__(self, sock_fd, request_data, server, log, tsig_key_ring):
         # The initializer for the superclass may call functions
         # that need _log to be set, so we set it first
         self._sock_fd = sock_fd
         self._request_data = request_data
         self._server = server
         self._log = log
+        self._tsig_key_ring = tsig_key_ring
+        self._tsig_ctx = None
+        self._tsig_len = 0
         self.handle()
 
+    def create_tsig_ctx(self, tsig_record, tsig_key_ring):
+        return TSIGContext(tsig_record.get_name(), tsig_record.get_rdata().get_algorithm(),
+                           tsig_key_ring)
+
     def handle(self):
         ''' Handle a xfrout query, send xfrout response '''
         try:
@@ -105,17 +114,33 @@ class XfroutSession():
 
         os.close(self._sock_fd)
 
+    def _check_request_tsig(self, msg, request_data):
+        ''' If request has a tsig record, perform tsig related checks '''
+        tsig_record = msg.get_tsig_record()
+        if tsig_record is not None:
+            self._tsig_len = tsig_record.get_length()
+            self._tsig_ctx = self.create_tsig_ctx(tsig_record, self._tsig_key_ring)
+            tsig_error = self._tsig_ctx.verify(tsig_record, request_data)
+            if tsig_error != TSIGError.NOERROR:
+                return Rcode.NOTAUTH()
+
+        return Rcode.NOERROR()
+
     def _parse_query_message(self, mdata):
         ''' parse query message to [socket,message]'''
         #TODO, need to add parseHeader() in case the message header is invalid
         try:
             msg = Message(Message.PARSE)
             Message.from_wire(msg, mdata)
+
+            # TSIG related checks
+            rcode = self._check_request_tsig(msg, mdata)
+
         except Exception as err:
             self._log.log_message("error", str(err))
             return Rcode.FORMERR(), None
 
-        return Rcode.NOERROR(), msg
+        return rcode, msg
 
     def _get_query_zone_name(self, msg):
         question = msg.get_question()[0]
@@ -130,13 +155,20 @@ class XfroutSession():
             total_count += count
 
 
-    def _send_message(self, sock_fd, msg):
+    def _send_message(self, sock_fd, msg, tsig_ctx=None):
         render = MessageRenderer()
         # As defined in RFC5936 section3.4, perform case-preserving name
         # compression for AXFR message.
         render.set_compress_mode(MessageRenderer.CASE_SENSITIVE)
         render.set_length_limit(XFROUT_MAX_MESSAGE_SIZE)
-        msg.to_wire(render)
+
+        # 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 tsig_ctx is not None:
+            msg.to_wire(render, tsig_ctx)
+        else:
+            msg.to_wire(render)
+
         header_len = struct.pack('H', socket.htons(render.get_length()))
         self._send_data(sock_fd, header_len)
         self._send_data(sock_fd, render.get_data())
@@ -145,7 +177,7 @@ class XfroutSession():
     def _reply_query_with_error_rcode(self, msg, sock_fd, rcode_):
         msg.make_response()
         msg.set_rcode(rcode_)
-        self._send_message(sock_fd, msg)
+        self._send_message(sock_fd, msg, self._tsig_ctx)
 
 
     def _reply_query_with_format_error(self, msg, sock_fd):
@@ -155,7 +187,7 @@ class XfroutSession():
 
         msg.make_response()
         msg.set_rcode(Rcode.FORMERR())
-        self._send_message(sock_fd, msg)
+        self._send_message(sock_fd, msg, self._tsig_ctx)
 
     def _zone_has_soa(self, zone):
         '''Judge if the zone has an SOA record.'''
@@ -204,7 +236,9 @@ class XfroutSession():
     def dns_xfrout_start(self, sock_fd, msg_query):
         rcode_, msg = self._parse_query_message(msg_query)
         #TODO. create query message and parse header
-        if rcode_ != Rcode.NOERROR():
+        if rcode_ == Rcode.NOTAUTH():
+            return self._reply_query_with_error_rcode(msg, sock_fd, rcode_)
+        elif rcode_ != Rcode.NOERROR():
             return self._reply_query_with_format_error(msg, sock_fd)
 
         zone_name = self._get_query_zone_name(msg)
@@ -248,37 +282,43 @@ class XfroutSession():
         rrset_.add_rdata(rdata_)
         return rrset_
 
-    def _send_message_with_last_soa(self, msg, sock_fd, rrset_soa, message_upper_len):
+    def _send_message_with_last_soa(self, msg, sock_fd, rrset_soa, message_upper_len,
+                                    count_since_last_tsig_sign):
         '''Add the SOA record to the end of message. If it can't be
         added, a new message should be created to send out the last soa .
         '''
         rrset_len = get_rrset_len(rrset_soa)
 
-        if message_upper_len + rrset_len < XFROUT_MAX_MESSAGE_SIZE:
-            msg.add_rrset(Message.SECTION_ANSWER, rrset_soa)
-        else:
+        if (count_since_last_tsig_sign == TSIG_SIGN_EVERY_NTH and
+            message_upper_len + rrset_len >= XFROUT_MAX_MESSAGE_SIZE):
+            # If tsig context exist, sign the packet with serial number TSIG_SIGN_EVERY_NTH
+            self._send_message(sock_fd, msg, self._tsig_ctx)
+            msg = self._clear_message(msg)
+        elif (count_since_last_tsig_sign != TSIG_SIGN_EVERY_NTH and
+              message_upper_len + rrset_len + self._tsig_len >= XFROUT_MAX_MESSAGE_SIZE):
             self._send_message(sock_fd, msg)
             msg = self._clear_message(msg)
-            msg.add_rrset(Message.SECTION_ANSWER, rrset_soa)
 
-        self._send_message(sock_fd, msg)
+        # If tsig context exist, sign the last packet
+        msg.add_rrset(Message.SECTION_ANSWER, rrset_soa)
+        self._send_message(sock_fd, msg, self._tsig_ctx)
 
 
     def _reply_xfrout_query(self, msg, sock_fd, zone_name):
         #TODO, there should be a better way to insert rrset.
+        count_since_last_tsig_sign = TSIG_SIGN_EVERY_NTH
         msg.make_response()
         msg.set_header_flag(Message.HEADERFLAG_AA)
         soa_record = sqlite3_ds.get_zone_soa(zone_name, self._server.get_db_file())
         rrset_soa = self._create_rrset_from_db_record(soa_record)
         msg.add_rrset(Message.SECTION_ANSWER, rrset_soa)
 
-        message_upper_len = get_rrset_len(rrset_soa)
+        message_upper_len = get_rrset_len(rrset_soa) + self._tsig_len
 
         for rr_data in sqlite3_ds.get_zone_datas(zone_name, self._server.get_db_file()):
             if  self._server._shutdown_event.is_set(): # Check if xfrout is shutdown
                 self._log.log_message("info", "xfrout process is being shutdown")
                 return
-
             # TODO: RRType.SOA() ?
             if RRType(rr_data[5]) == RRType("SOA"): #ignore soa record
                 continue
@@ -294,12 +334,25 @@ class XfroutSession():
                 message_upper_len += rrset_len
                 continue
 
-            self._send_message(sock_fd, msg)
+            # If tsig context exist, sign every N packets
+            if count_since_last_tsig_sign == TSIG_SIGN_EVERY_NTH:
+                count_since_last_tsig_sign = 0
+                self._send_message(sock_fd, msg, self._tsig_ctx)
+            else:
+                self._send_message(sock_fd, msg)
+
+            count_since_last_tsig_sign += 1
             msg = self._clear_message(msg)
             msg.add_rrset(Message.SECTION_ANSWER, rrset_) # Add the rrset to the new message
-            message_upper_len = rrset_len
 
-        self._send_message_with_last_soa(msg, sock_fd, rrset_soa, message_upper_len)
+            # Reserve tsig space for signed packet
+            if count_since_last_tsig_sign == TSIG_SIGN_EVERY_NTH:
+                message_upper_len = rrset_len + self._tsig_len
+            else:
+                message_upper_len = rrset_len
+
+        self._send_message_with_last_soa(msg, sock_fd, rrset_soa, message_upper_len,
+                                         count_since_last_tsig_sign)
 
 class UnixSockServer(socketserver_mixin.NoPollMixIn, ThreadingUnixStreamServer):
     '''The unix domain socket server which accept xfr query sent from auth server.'''
@@ -403,7 +456,7 @@ class UnixSockServer(socketserver_mixin.NoPollMixIn, ThreadingUnixStreamServer):
 
     def finish_request(self, sock_fd, request_data):
         '''Finish one request by instantiating RequestHandlerClass.'''
-        self.RequestHandlerClass(sock_fd, request_data, self, self._log)
+        self.RequestHandlerClass(sock_fd, request_data, self, self._log, self.tsig_key_ring)
 
     def _remove_unused_sock_file(self, sock_file):
         '''Try to remove the socket file. If the file is being used
@@ -449,10 +502,27 @@ class UnixSockServer(socketserver_mixin.NoPollMixIn, ThreadingUnixStreamServer):
         self._log.log_message('info', 'update config data start.')
         self._lock.acquire()
         self._max_transfers_out = new_config.get('transfers_out')
+        self.set_tsig_key_ring(new_config.get('tsig_key_ring'))
         self._log.log_message('info', 'max transfer out : %d', self._max_transfers_out)
         self._lock.release()
         self._log.log_message('info', 'update config data complete.')
 
+    def set_tsig_key_ring(self, key_list):
+        """Set the tsig_key_ring , given a TSIG key string list representation. """
+
+        # XXX add values to configure zones/tsig options
+        self.tsig_key_ring = TSIGKeyRing()
+        # If key string list is empty, create a empty tsig_key_ring
+        if not key_list:
+            return
+
+        for key_item in key_list:
+            try:
+                self.tsig_key_ring.add(TSIGKey(key_item))
+            except InvalidParameter as ipe:
+                errmsg = "bad TSIG key string: " + str(key_item)
+                self._log.log_message('error', '%s' % errmsg)
+
     def get_db_file(self):
         file, is_default = self._cc.get_remote_config_value("Auth", "database_file")
         # this too should be unnecessary, but currently the

src/bin/xfrout/xfrout.spec.pre.in

@@ -37,6 +37,18 @@
     	 "item_type": "integer",
          "item_optional": false,
     	 "item_default": 1048576
+       },
+       {
+         "item_name": "tsig_key_ring",
+         "item_type": "list",
+         "item_optional": true,
+         "item_default": [],
+         "list_item_spec" :
+         {
+             "item_name": "tsig_key",
+             "item_type": "string",
+             "item_optional": true
+         }
        }
       ],
       "commands": [

src/cppcheck-suppress.lst

@@ -4,11 +4,6 @@ debug
 missingInclude
 // This is a template, and should be excluded from the check
 unreadVariable:src/lib/dns/rdata/template.cc:60
-// These three trigger warnings due to the incomplete implementation.  This is
-// our problem, but we need to suppress the warnings for now.
-functionConst:src/lib/cache/resolver_cache.h
-functionConst:src/lib/cache/message_cache.h
-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

src/lib/Makefile.am

@@ -1,3 +1,3 @@
 SUBDIRS = exceptions util log cryptolink dns cc config python xfr \
           bench asiolink asiodns nsas cache resolve testutils datasrc \
-          server_common
+          server_common acl

src/lib/acl/Makefile.am

@@ -0,0 +1,6 @@
+SUBDIRS = tests
+
+EXTRA_DIST = check.h
+
+# TODO: Once we have some cc file we are able to compile, create the library.
+# For now, we have only header files, not creating empty library.

src/lib/acl/check.h

@@ -0,0 +1,195 @@
+// 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 ACL_CHECK_H
+#define ACL_CHECK_H
+
+#include <vector>
+#include <typeinfo>
+#include <sstream>
+
+namespace isc {
+namespace acl {
+
+/**
+ * \brief ACL check base class.
+ *
+ * It is intended that all ACL checks are inherited (maybe indirectly) from
+ * this base class. This will allow us to define new types of checks without
+ * changing any of the code that is using it and with the correct
+ * implementation even without changing the thing that parses configuration
+ * and creates instances of the checks.
+ *
+ * It is implemented as a template. This allows easy reuse of the code for
+ * checking of different types of things (packets of different protocols, etc).
+ * We'll implement the loader and compound checks as templates as well (
+ * and just make sure they are instantiated for each type of thing we want
+ * to check). While most of concrete checks will be specific for one protocol
+ * (or whatever the entity we check is), it makes sense to implement some of
+ * these as templates as well (for example the IP address check, for whatever
+ * context that contains member called ip and has the right methods).
+ *
+ * The Context carries whatever information might be checked for that protocol
+ * (eg. the packet, information where it came from, to what port, ...).
+ */
+template<typename Context> class Check {
+protected:
+    /// \brief Constructor.
+    ///
+    /// Just to make sure this thing is not directly instantiated.
+    Check() { }
+public:
+    /**
+     * \brief The check itself.
+     *
+     * The actual check will be performed here. Every concrete child class
+     * will reimplement it and decide based on the context passed if it
+     * matches.
+     *
+     * The caller should expect this method can throw. The list of exceptions
+     * isn't restricted, as we don't know what kind of checks will be needed.
+     * An exception should be considered as it is impossible to check the
+     * condition. It should lead to either blackholing the packet or returning
+     * some 500-like error (ServFail).
+     *
+     * \param context The thing we are trying to match against this check.
+     * \return true if the context satisfies the check, false otherwise.
+     */
+    virtual bool matches(const Context& context) const = 0;
+
+    /**
+     * \brief Cost for unknown cost estimate.
+     *
+     * This indicates that the estimate for cost is not provided. This
+     * is arbitrary large value, meaning "somehow longish time". To be
+     * on the safe side, we guess more and be just happily suprirised
+     * if it turns out to run faster.
+     */
+    static const unsigned UNKNOWN_COST;
+
+    /**
+     * \brief The expected cost of single match.
+     *
+     * This is here to provide some kind of cost information to optimising
+     * routines. It is in units without any real size, just bigger number
+     * means the check takes longer time. It is expected to be linear scale.
+     * It doesn't need to be exact, but better accuracy might lead to better
+     * optimisations. As of writing this, no optimisations exist yet, but
+     * are expected to exist in future.
+     *
+     * The default is UNKNOWN_COST.
+     */
+    virtual unsigned cost() const {
+        return (UNKNOWN_COST);
+    }
+
+    /// \brief Virtual destructor, as we're virtual
+    virtual ~ Check() { }
+
+    /**
+     * \brief Conversion to text.
+     *
+     * This is meant for debugging purposes, it doesn't have to
+     * serialise the whole information stored in this Check.
+     *
+     * If the check is compound, it should not include the subexpressions
+     * (while we're able to build whatever treeish representation using
+     * CompoundCheck::subexpressions, we're not able to separate them
+     * automatically, as this may produce any kind of free-form string).
+     */
+    virtual std::string toText() const {
+        std::stringstream output;
+        output << typeid(*this).name() << "@" << this;
+        return (output.rdbuf()->str());
+    }
+};
+
+// This seems to be the propper way for static template members
+template<typename Context> const unsigned Check<Context>::UNKNOWN_COST = 10000;
+
+/**
+ * \brief Base class for compound checks.
+ *
+ * While some checks will be a match against some property of the information
+ * passed (eg. the sender's IP address must be in some range), others will
+ * combine results of more checks together to get their own. This is base class
+ * for the second type, allowing listing of the subexpressions (mostly for
+ * debugging purposes to print the whole tree of matches and possible future
+ * optimisations which would like to crawl the expression tree).
+ */
+template<typename Context> class CompoundCheck : public Check<Context> {
+public:
+    /// \brief Abbreviated name for list of subexpressions
+    typedef std::vector<const Check<Context>*> Checks;
+
+    /**
+     * \brief Get the list of subexpressions.
+     *
+     * The result contains pointers to the all subexpressions this check holds
+     * (and therefore might call during its own match() function).
+     *
+     * Using shared pointers looks an overkill here. All the checks must be
+     * alive for the whole life of this one and this check will hold their
+     * ownership. Therefore the only thing the caller needs to do is to make
+     * sure this check is not deleted while it's still using the ones from the
+     * result.
+     *
+     * This method must not throw except for the standard allocation exceptions
+     * to allocate the result.
+     */
+    virtual Checks getSubexpressions() const = 0;
+
+    /**
+     * \brief If the result depends only on results of subexpressions.
+     *
+     * Some optimisations might use the fact that a compound expression is
+     * a function of results of its subexpressions (subchecks) only. But
+     * some compound checks might want to look into the provided context in
+     * their match() as well as looking at the results of the subexpressions.
+     *
+     * This function informs the optimisation routines if it is safe to use
+     * these optimisations.
+     *
+     * \return true if the check depends only on results of subexpressions
+     *    only, false if it examines the context itself as well.
+     * \note The default implementation returns true, as it is expected to
+     *    be the case in majority of cases.
+     */
+    virtual bool pure() const { return (true); }
+
+    /**
+     * \brief Default compound cost function.
+     *
+     * It is simply sum of all subexpressions, as an expected upper bound
+     * on the cost. This expects that the combining itself is cheap relatively
+     * to the checks performed by the subexpressions. In most cases, this
+     * should be good enough, but it can be reimplemented in situations
+     * where most of the subexpressions will be avoided in usual situations.
+     * Replacing the default of 10000 from Check.
+     */
+    virtual unsigned cost() const {
+        Checks checks(getSubexpressions());
+        unsigned result(0);
+        for (typename Checks::const_iterator i(checks.begin());
+             i != checks.end(); ++ i) {
+            result += (*i)->cost();
+        }
+        return (result);
+    }
+};
+
+}
+}
+
+#endif

src/lib/acl/tests/Makefile.am

@@ -0,0 +1,15 @@
+AM_CPPFLAGS = -I$(top_builddir)/src/lib -I$(top_srcdir)/src/lib
+
+TESTS =
+if HAVE_GTEST
+TESTS += run_unittests
+run_unittests_SOURCES = run_unittests.cc
+run_unittests_SOURCES += check_test.cc
+run_unittests_CPPFLAGS = $(AM_CPPFLAGS) $(GTEST_INCLUDES)
+run_unittests_LDFLAGS = $(AM_LDFLAGS) $(GTEST_LDFLAGS)
+
+run_unittests_LDADD = $(GTEST_LDADD)
+run_unittests_LDADD += $(top_builddir)/src/lib/util/unittests/libutil_unittests.la
+endif
+
+noinst_PROGRAMS = $(TESTS)

src/lib/acl/tests/check_test.cc

@@ -0,0 +1,70 @@
+// Copyright (C) 2011  Internet Systems Consortium, Inc. ("ISC")
+//
+// Permission to use, copy, modify, and/or distribute this software for any
+// purpose with or without fee is hereby granted, provided that the above
+// copyright notice and this permission notice appear in all copies.
+//
+// THE SOFTWARE IS PROVIDED "AS IS" AND ISC DISCLAIMS ALL WARRANTIES WITH
+// REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY
+// AND FITNESS.  IN NO EVENT SHALL ISC BE LIABLE FOR ANY SPECIAL, DIRECT,
+// INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER RESULTING FROM
+// LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF CONTRACT, NEGLIGENCE
+// OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
+// PERFORMANCE OF THIS SOFTWARE.
+
+#include <gtest/gtest.h>
+#include <acl/check.h>
+
+using namespace isc::acl;
+
+namespace {
+
+// This test has two function. For one, it checks the default implementations
+// do what they should and it makes sure the template actually compiles
+// (as templates are syntax-checked upon instantiation).
+
+// This is a test check that just passes the boolean it gets.
+class Pass : public Check<bool> {
+public:
+    virtual bool matches(const bool& value) const { return (value); }
+};
+
+// This is a simple test compound check. It contains two Pass checks
+// and passes result of the first one.
+
+class First : public CompoundCheck<bool> {
+public:
+    // The internal checks are public, so we can check the addresses
+    Pass first, second;
+    virtual Checks getSubexpressions() const {
+        Checks result;
+        result.push_back(&first);
+        result.push_back(&second);
+        return (result);
+    }
+    virtual bool matches(const bool& value) const {
+        return (first.matches(value));
+    }
+};
+
+TEST(Check, defaultCheckValues) {
+    Pass p;
+    EXPECT_EQ(Check<bool>::UNKNOWN_COST, p.cost());
+    EXPECT_TRUE(p.matches(true));
+    EXPECT_FALSE(p.matches(false));
+    // The exact text is compiler dependant, but we check it returns something
+    // and can be compiled
+    EXPECT_FALSE(p.toText().empty());
+}
+
+TEST(Check, defaultCompoundValues) {
+    First f;
+    EXPECT_EQ(2 * Check<bool>::UNKNOWN_COST, f.cost());
+    EXPECT_TRUE(f.pure());
+    First::Checks c(f.getSubexpressions());
+    ASSERT_EQ(2, c.size());
+    EXPECT_EQ(&f.first, c[0]);
+    EXPECT_EQ(&f.second, c[1]);
+}
+
+}

src/lib/util/io/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[]) {
+main(int argc, char* argv[]) {
     ::testing::InitGoogleTest(&argc, argv);
-
-    return RUN_ALL_TESTS();
+    return (isc::util::unittests::run_all());
 }
+

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

@@ -25,15 +25,15 @@ run_unittests_SOURCES += io_fetch_unittest.cc
 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) 
+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,16 +13,17 @@
 // PERFORMANCE OF THIS SOFTWARE.
 
 #include <gtest/gtest.h>
+#include <util/unittests/run_all.h>
 
-#include <log/root_logger_name.h>
+#include <log/logger_manager.h>
 #include <dns/tests/unittest_util.h>
 
 int
 main(int argc, char* argv[])
 {
     ::testing::InitGoogleTest(&argc, argv);         // Initialize Google test
-    isc::log::setRootLoggerName("unittest");        // Set a root logger name
+    isc::log::LoggerManager::init("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

@@ -34,13 +34,12 @@ run_unittests_SOURCES += udp_socket_unittest.cc
 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) 
+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,15 +13,13 @@
 // PERFORMANCE OF THIS SOFTWARE.
 
 #include <gtest/gtest.h>
-
-#include <log/root_logger_name.h>
-#include <dns/tests/unittest_util.h>
+#include <util/unittests/run_all.h>
+#include <log/logger_manager.h>
 
 int
 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());
+    isc::log::LoggerManager::init("unittest");      // Set a root logger name
+    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/TODO

@@ -12,7 +12,8 @@
 * When the rrset beging updated is an NS rrset, NSAS should be updated
   together.
 * Share the NXDOMAIN info between different type queries. current implementation
-  can only cache for the type that user quired, for example, if user query A 
+  can only cache for the type that user queried, for example, if user query A
   record of a.example. and the server replied with NXDOMAIN, this should be
   cached for all the types queries of a.example.
-
+* Add the interfaces for resizing and serialization (loading and dumping) to
+  cache.

src/lib/cache/message_cache.cc

@@ -97,24 +97,6 @@ MessageCache::update(const Message& msg) {
     return (message_table_.add(msg_entry, entry_key, true));
 }
 
-#if 0
-void
-MessageCache::dump(const std::string&) {
-    //TODO
-}
-
-void
-MessageCache::load(const std::string&) {
-    //TODO
-}
-
-bool
-MessageCache::resize(uint32_t) {
-    //TODO
-    return (true);
-}
-#endif
-
 } // namespace cache
 } // namespace isc
 

src/lib/cache/message_cache.h

@@ -30,6 +30,8 @@ namespace cache {
 /// The object of MessageCache represents the cache for class-specific
 /// messages.
 ///
+/// \todo The message cache class should provide the interfaces for
+///       loading, dumping and resizing.
 class MessageCache {
 // Noncopyable
 private:
@@ -64,20 +66,6 @@ public:
     /// If the message doesn't exist in the cache, it will be added
     /// directly.
     bool update(const isc::dns::Message& msg);
-
-#if 0
-    /// \brief Dump the message cache to specified file.
-    /// \todo It should can be dumped to one configured database.
-    void dump(const std::string& file_name);
-
-    /// \brief Load the cache from one file.
-    /// \todo It should can be loaded from one configured database.
-    void load(const std::string& file_name);
-
-    /// \brief Resize the size of message cache in runtime.
-    bool resize(uint32_t size);
-#endif
-
 protected:
     /// \brief Get the hash key for the message entry in the cache.
     /// \param name query name of the message.

src/lib/cache/resolver_cache.cc

@@ -227,16 +227,6 @@ ResolverCache::update(const isc::dns::ConstRRsetPtr& rrset_ptr) {
     }
 }
 
-void
-ResolverCache::dump(const std::string&) {
-    //TODO
-}
-
-void
-ResolverCache::load(const std::string&) {
-    //TODO
-}
-
 ResolverClassCache*
 ResolverCache::getClassCache(const isc::dns::RRClass& cache_class) const {
     for (int i = 0; i < class_caches_.size(); ++i) {

src/lib/cache/resolver_cache.h

@@ -76,6 +76,9 @@ public:
 ///
 /// \note Public interaction with the cache should be through ResolverCache,
 /// not directly with this one. (TODO: make this private/hidden/local to the .cc?)
+///
+/// \todo The resolver cache class should provide the interfaces for
+///       loading, dumping and resizing.
 class ResolverClassCache {
 public:
     /// \brief Default Constructor.
@@ -300,23 +303,6 @@ public:
     ///
     bool update(const isc::dns::ConstRRsetPtr& rrset_ptr);
 
-    /// \name Cache Serialization
-    //@{
-    /// \brief Dump the cache content to one file.
-    ///
-    /// \param file_name file to write to
-    ///
-    /// \todo It should can be dumped to one configured database.
-    void dump(const std::string& file_name);
-
-    /// \brief Load the cache from one file.
-    ///
-    /// \param file to load from
-    ///
-    /// \todo It should can be loaded from one configured database.
-    void load(const std::string& file_name);
-    //@}
-
 private:
     /// \brief Returns the class-specific subcache
     ///

src/lib/cache/rrset_cache.cc

@@ -79,24 +79,6 @@ RRsetCache::update(const isc::dns::RRset& rrset, const RRsetTrustLevel& level) {
     return (entry_ptr);
 }
 
-#if 0
-void
-RRsetCache::dump(const std::string&) {
-    //TODO
-}
-
-void
-RRsetCache::load(const std::string&) {
-    //TODO
-}
-
-bool
-RRsetCache::resize(uint32_t) {
-    //TODO
-    return (true);
-}
-#endif
-
 } // namespace cache
 } // namespace isc
 

src/lib/cache/rrset_cache.h

@@ -30,6 +30,9 @@ class RRsetEntry;
 /// \brief RRset Cache
 /// The object of RRsetCache represented the cache for class-specific
 /// RRsets.
+///
+/// \todo The rrset cache class should provide the interfaces for
+///       loading, dumping and resizing.
 class RRsetCache{
     ///
     /// \name Constructors and Destructor
@@ -73,28 +76,6 @@ public:
     RRsetEntryPtr update(const isc::dns::RRset& rrset,
                          const RRsetTrustLevel& level);
 
-#if 0
-    /// \brief Dump the rrset cache to specified file.
-    ///
-    /// \param file_name The file to write to
-    ///
-    /// \todo It should can be dumped to one configured database.
-    void dump(const std::string& file_name);
-
-    /// \brief Load the cache from one file.
-    ///
-    /// \param file_name The file to read from
-    ///
-    /// \todo It should can be loaded from one configured database.
-    void load(const std::string& file_name);
-
-    /// \brief Resize the size of rrset cache in runtime.
-    ///
-    /// \param The size to resize to
-    /// \return true
-    bool resize(uint32_t size);
-#endif
-
     /// \short Protected memebers, so they can be accessed by tests.
 protected:
     uint16_t class_; // The class of the rrset cache.

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)
-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

@@ -35,6 +35,10 @@
 #include <config/config_log.h>
 #include <config/ccsession.h>
 
+#include <log/logger_support.h>
+#include <log/logger_specification.h>
+#include <log/logger_manager.h>
+
 using namespace std;
 
 using isc::data::Element;
@@ -151,6 +155,115 @@ parseCommand(ConstElementPtr& arg, ConstElementPtr command) {
     }
 }
 
+namespace {
+// Temporary workaround functions for missing functionality in
+// getValue() (main problem described in ticket #993)
+// This returns either the value set for the given relative id,
+// or its default value
+// (intentially defined here so this interface does not get
+// included in ConfigData as it is)
+ConstElementPtr getValueOrDefault(ConstElementPtr config_part,
+                                  const std::string& relative_id,
+                                  const ConfigData& config_data,
+                                  const std::string& full_id) {
+    if (config_part->contains(relative_id)) {
+        return config_part->get(relative_id);
+    } else {
+        return config_data.getDefaultValue(full_id);
+    }
+}
+
+// Reads a output_option subelement of a logger configuration,
+// and sets the values thereing to the given OutputOption struct,
+// or defaults values if they are not provided (from config_data).
+void
+readOutputOptionConf(isc::log::OutputOption& output_option,
+                     ConstElementPtr output_option_el,
+                     const ConfigData& config_data)
+{
+    ConstElementPtr destination_el = getValueOrDefault(output_option_el,
+                                    "destination", config_data,
+                                    "loggers/output_options/destination");
+    output_option.destination = isc::log::getDestination(destination_el->stringValue());
+    ConstElementPtr output_el = getValueOrDefault(output_option_el,
+                                    "output", config_data,
+                                    "loggers/output_options/output");
+    if (output_option.destination == isc::log::OutputOption::DEST_CONSOLE) {
+        output_option.stream = isc::log::getStream(output_el->stringValue());
+    } else if (output_option.destination == isc::log::OutputOption::DEST_FILE) {
+        output_option.filename = output_el->stringValue();
+    } else if (output_option.destination == isc::log::OutputOption::DEST_SYSLOG) {
+        output_option.facility = output_el->stringValue();
+    }
+    output_option.flush = getValueOrDefault(output_option_el,
+                              "flush", config_data,
+                              "loggers/output_options/flush")->boolValue();
+    output_option.maxsize = getValueOrDefault(output_option_el,
+                                "maxsize", config_data,
+                                "loggers/output_options/maxsize")->intValue();
+    output_option.maxver = getValueOrDefault(output_option_el,
+                               "maxver", config_data,
+                               "loggers/output_options/maxver")->intValue();
+}
+
+// Reads a full 'loggers' configuration, and adds the loggers therein
+// to the given vector, fills in blanks with defaults from config_data
+void
+readLoggersConf(std::vector<isc::log::LoggerSpecification>& specs,
+                ConstElementPtr logger,
+                const ConfigData& config_data)
+{
+    const std::string lname = logger->get("name")->stringValue();
+    ConstElementPtr severity_el = getValueOrDefault(logger,
+                                      "severity", config_data,
+                                      "loggers/severity");
+    isc::log::Severity severity = isc::log::getSeverity(
+                                      severity_el->stringValue());
+    int dbg_level = getValueOrDefault(logger, "debuglevel",
+                                      config_data,
+                                      "loggers/debuglevel")->intValue();
+    bool additive = getValueOrDefault(logger, "additive", config_data,
+                                      "loggers/additive")->boolValue();
+
+    isc::log::LoggerSpecification logger_spec(
+        lname, severity, dbg_level, additive
+    );
+
+    if (logger->contains("output_options")) {
+        BOOST_FOREACH(ConstElementPtr output_option_el,
+                      logger->get("output_options")->listValue()) {
+            // create outputoptions
+            isc::log::OutputOption output_option;
+            readOutputOptionConf(output_option,
+                                 output_option_el,
+                                 config_data);
+            logger_spec.addOutputOption(output_option);
+        }
+    }
+
+    specs.push_back(logger_spec);
+}
+
+} // end anonymous namespace
+
+void
+my_logconfig_handler(const std::string&n, ConstElementPtr new_config, const ConfigData& config_data) {
+    config_data.getModuleSpec().validateConfig(new_config, true);
+
+    std::vector<isc::log::LoggerSpecification> specs;
+
+    if (new_config->contains("loggers")) {
+        BOOST_FOREACH(ConstElementPtr logger,
+                      new_config->get("loggers")->listValue()) {
+            readLoggersConf(specs, logger, config_data);
+        }
+    }
+
+    isc::log::LoggerManager logger_manager;
+    logger_manager.process(specs.begin(), specs.end());
+}
+
+
 ModuleSpec
 ModuleCCSession::readModuleSpecification(const std::string& filename) {
     std::ifstream file;
@@ -192,8 +305,11 @@ 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,
+    bool handle_logging
     ) :
+    started_(false),
     session_(session)
 {
     module_specification_ = readModuleSpecification(spec_file_name);
@@ -205,10 +321,8 @@ ModuleCCSession::ModuleCCSession(
 
     session_.establish(NULL);
     session_.subscribe(module_name_, "*");
-    //session_.subscribe("Boss", "*");
-    //session_.subscribe("statistics", "*");
-    // send the data specification
 
+    // send the data specification
     ConstElementPtr spec_msg = createCommand("module_spec",
                                              module_specification_.getFullSpec());
     unsigned int seq = session_.group_sendmsg(spec_msg, "ConfigManager");
@@ -237,8 +351,27 @@ ModuleCCSession::ModuleCCSession(
         }
     }
 
+    // Keep track of logging settings automatically
+    if (handle_logging) {
+        addRemoteConfig("Logging", my_logconfig_handler, false);
+    }
+
+    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,
@@ -346,6 +479,11 @@ ModuleCCSession::checkCommand() {
             }
         } catch (const CCSessionError& re) {
             LOG_ERROR(config_logger, CONFIG_CCSESSION_MSG).arg(re.what());
+        } catch (const std::exception& stde) {
+            // No matter what unexpected error happens, we do not want
+            // to crash because of an incoming event, so we log the
+            // exception and continue to run
+            LOG_ERROR(config_logger, CONFIG_CCSESSION_MSG_INTERNAL).arg(stde.what());
         }
         if (!isNull(answer)) {
             session_.reply(routing, answer);
@@ -355,45 +493,55 @@ 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 + "\"} ] }");
+
+        // Send the command
+        ConstElementPtr cmd(createCommand("get_module_spec",
+                            Element::fromJSON("{\"module_name\": \"" + module +
+                                              "\"}")));
         unsigned int seq = session_.group_sendmsg(cmd, "ConfigManager");
         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);
+}
 
-    // 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");
+std::string
+ModuleCCSession::addRemoteConfig(const std::string& spec_name,
+                                 void (*handler)(const std::string& module,
+                                                 ConstElementPtr,
+                                                 const ConfigData&),
+                                 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 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 +549,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);
@@ -412,8 +561,10 @@ ModuleCCSession::addRemoteConfig(const std::string& spec_name,
     remote_module_configs_[module_name] = rmod_config;
     if (handler) {
         remote_module_handlers_[module_name] = handler;
-        handler(module_name, local_config);
+        handler(module_name, local_config, rmod_config);
     }
+
+    // Make sure we get updates in future
     session_.subscribe(module_name);
     return (module_name);
 }
@@ -458,7 +609,7 @@ ModuleCCSession::updateRemoteConfig(const std::string& module_name,
         std::map<std::string, RemoteHandler>::iterator hit =
             remote_module_handlers_.find(module_name);
         if (hit != remote_module_handlers_.end()) {
-            hit->second(module_name, new_config);
+            hit->second(module_name, new_config, it->second);
         }
     }
 }

src/lib/config/ccsession.h

@@ -161,6 +161,7 @@ public:
      * configuration of the local module needs to be updated.
      * This must refer to a valid object of a concrete derived class of
      * AbstractSession without establishing the session.
+     *
      * Note: the design decision on who is responsible for establishing the
      * session is in flux, and may change in near future.
      *
@@ -171,6 +172,14 @@ 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.
+     * @param 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)
+     * @param handle_logging If true, the ModuleCCSession will automatically
+     * take care of logging configuration through the virtual Logging config
+     * module.
      */
     ModuleCCSession(const std::string& spec_file_name,
                     isc::cc::AbstractSession& session,
@@ -178,9 +187,21 @@ 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,
+                    bool handle_logging = false
                     );
 
+    /// 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 +261,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
@@ -263,7 +288,8 @@ public:
     std::string addRemoteConfig(const std::string& spec_name,
                                 void (*handler)(const std::string& module_name,
                                                 isc::data::ConstElementPtr
-                                                update) = NULL,
+                                                update,
+                                                const ConfigData& config_data) = NULL,
                                 bool spec_is_filename = true);
 
     /**
@@ -293,7 +319,8 @@ public:
 private:
     ModuleSpec readModuleSpecification(const std::string& filename);
     void startCheck();
-    
+
+    bool started_;
     std::string module_name_;
     isc::cc::AbstractSession& session_;
     ModuleSpec module_specification_;
@@ -316,12 +343,15 @@ private:
         isc::data::ConstElementPtr args);
 
     typedef void (*RemoteHandler)(const std::string&,
-                                  isc::data::ConstElementPtr);
+                                  isc::data::ConstElementPtr,
+                                  const ConfigData&);
     std::map<std::string, ConfigData> remote_module_configs_;
     std::map<std::string, RemoteHandler> remote_module_handlers_;
 
     void updateRemoteConfig(const std::string& module_name,
                             isc::data::ConstElementPtr new_config);
+
+    ModuleSpec fetchRemoteSpec(const std::string& module, bool is_filename);
 };
 
 }

src/lib/config/config_data.cc

@@ -21,6 +21,63 @@
 
 using namespace isc::data;
 
+namespace {
+
+// Returns the '_spec' part of a list or map specification (recursively,
+// i.e. if it is a list of lists or maps, will return the spec of the
+// inner-most list or map).
+//
+// \param spec_part the list or map specification (part)
+// \return the value of spec_part's "list_item_spec" or "map_item_spec",
+//         or the original spec_part, if it is not a MapElement or does
+//         not contain "list_item_spec" or "map_item_spec"
+ConstElementPtr findListOrMapSubSpec(ConstElementPtr spec_part) {
+    while (spec_part->getType() == Element::map &&
+           (spec_part->contains("list_item_spec") ||
+            spec_part->contains("map_item_spec"))) {
+        if (spec_part->contains("list_item_spec")) {
+            spec_part = spec_part->get("list_item_spec");
+        } else {
+            spec_part = spec_part->get("map_item_spec");
+        }
+    }
+    return spec_part;
+}
+
+// Returns a specific Element in a given specification ListElement
+//
+// \exception DataNotFoundError if the given identifier does not
+// point to an existing element. Since we are dealing with the
+// specification here, and not the config data itself, this should
+// not happen, and is a code bug.
+//
+// \param spec_part ListElement to find the element in
+// \param id_part the name of the element to find (must match the value
+//                "item_name" in the list item
+// \param id_full the full identifier id_part is a part of, this is
+//                used to better report any errors
+ConstElementPtr findItemInSpecList(ConstElementPtr spec_part,
+                                   const std::string& id_part,
+                                   const std::string& id_full)
+{
+    bool found = false;
+    BOOST_FOREACH(ConstElementPtr list_el, spec_part->listValue()) {
+        if (list_el->getType() == Element::map &&
+            list_el->contains("item_name") &&
+            list_el->get("item_name")->stringValue() == id_part) {
+            spec_part = list_el;
+            found = true;
+        }
+    }
+    if (!found) {
+        isc_throw(isc::config::DataNotFoundError,
+                  id_part + " in " + id_full + " not found");
+    }
+    return (spec_part);
+}
+
+} // anonymous namespace
+
 namespace isc {
 namespace config {
 
@@ -36,11 +93,10 @@ namespace config {
 // validated and conforms to the specification.
 static ConstElementPtr
 find_spec_part(ConstElementPtr spec, const std::string& identifier) {
-    //std::cout << "[XX] find_spec_part for " << identifier << std::endl;
     if (!spec) {
         isc_throw(DataNotFoundError, "Empty specification");
     }
-    //std::cout << "in: " << std::endl << spec << std::endl;
+
     ConstElementPtr spec_part = spec;
     if (identifier == "") {
         isc_throw(DataNotFoundError, "Empty identifier");
@@ -49,59 +105,44 @@ find_spec_part(ConstElementPtr spec, const std::string& identifier) {
     size_t sep = id.find('/');
     while(sep != std::string::npos) {
         std::string part = id.substr(0, sep);
-        //std::cout << "[XX] id part: " << part << std::endl;
+
         if (spec_part->getType() == Element::list) {
-            bool found = false;
-            BOOST_FOREACH(ConstElementPtr list_el, spec_part->listValue()) {
-                if (list_el->getType() == Element::map &&
-                    list_el->contains("item_name") &&
-                    list_el->get("item_name")->stringValue() == part) {
-                    spec_part = list_el;
-                    found = true;
-                }
-            }
-            if (!found) {
-                isc_throw(DataNotFoundError, identifier);
-            }
+            spec_part = findItemInSpecList(spec_part, part, identifier);
+        } else {
+            isc_throw(DataNotFoundError,
+                      "Not a list of spec items: " + spec_part->str());
         }
         id = id.substr(sep + 1);
         sep = id.find("/");
+
+        // As long as we are not in the 'final' element as specified
+        // by the identifier, we want to automatically traverse list
+        // and map specifications
+        if (id != "" && id != "/") {
+            spec_part = findListOrMapSubSpec(spec_part);
+        }
     }
     if (id != "" && id != "/") {
         if (spec_part->getType() == Element::list) {
-            bool found = false;
-            BOOST_FOREACH(ConstElementPtr list_el, spec_part->listValue()) {
-                if (list_el->getType() == Element::map &&
-                    list_el->contains("item_name") &&
-                    list_el->get("item_name")->stringValue() == id) {
-                    spec_part = list_el;
-                    found = true;
-                }
-            }
-            if (!found) {
-                isc_throw(DataNotFoundError, identifier);
-            }
+            spec_part = findItemInSpecList(spec_part, id, identifier);
         } else if (spec_part->getType() == Element::map) {
             if (spec_part->contains("map_item_spec")) {
-                bool found = false;
-                BOOST_FOREACH(ConstElementPtr list_el,
-                              spec_part->get("map_item_spec")->listValue()) {
-                    if (list_el->getType() == Element::map &&
-                        list_el->contains("item_name") &&
-                        list_el->get("item_name")->stringValue() == id) {
-                        spec_part = list_el;
-                        found = true;
-                    }
-                }
-                if (!found) {
-                    isc_throw(DataNotFoundError, identifier);
-                }
+                spec_part = findItemInSpecList(
+                                spec_part->get("map_item_spec"),
+                                id, identifier);
             } else {
-                isc_throw(DataNotFoundError, identifier);
+                // Either we already have the element we are looking
+                // for, or we are trying to reach something that does
+                // not exist (i.e. the code does not match the spec)
+                if (!spec_part->contains("item_name") ||
+                    spec_part->get("item_name")->stringValue() != id) {
+                    isc_throw(DataNotFoundError, "Element above " + id +
+                                                 " in " + identifier +
+                                                 " is not a map: " + spec_part->str());
+                }
             }
         }
     }
-    //std::cout << "[XX] found spec part: " << std::endl << spec_part << std::endl;
     return (spec_part);
 }
 
@@ -164,6 +205,17 @@ ConfigData::getValue(bool& is_default, const std::string& identifier) const {
     return (value);
 }
 
+ConstElementPtr
+ConfigData::getDefaultValue(const std::string& identifier) const {
+    ConstElementPtr spec_part =
+        find_spec_part(_module_spec.getConfigSpec(), identifier);
+    if (spec_part->contains("item_default")) {
+        return spec_part->get("item_default");
+    } else {
+        isc_throw(DataNotFoundError, "No default for " + identifier);
+    }
+}
+
 /// Returns an ElementPtr pointing to a ListElement containing
 /// StringElements with the names of the options at the given
 /// identifier. If recurse is true, maps will be expanded as well

src/lib/config/config_data.h

@@ -57,6 +57,16 @@ public:
     ///        value that is to be returned
     isc::data::ConstElementPtr getValue(const std::string& identifier) const;
 
+    /// Returns the default value for the given identifier.
+    ///
+    /// \exception DataNotFoundError if the given identifier does not
+    ///            exist, or if the given value has no specified default
+    ///
+    /// \param identifier The identifier pointing to the configuration
+    ///        value for which the default is to be returned
+    /// \return ElementPtr containing the default value
+    isc::data::ConstElementPtr getDefaultValue(const std::string& identifier) const;
+
     /// Returns the value currently set for the given identifier
     /// If no value is set, the default value (as specified by the
     /// .spec file) is returned. If there is no value and no default,

src/lib/config/configdef.mes

@@ -48,3 +48,10 @@ channel. The message does not appear to be a valid command, and is
 missing a required element or contains an unknown data format. This
 most likely means that another BIND10 module is sending a bad message.
 The message itself is ignored by this module.
+
+% CCSESSION_MSG_INTERNAL error handling CC session message: %1
+There was an internal problem handling an incoming message on the
+command and control channel. An unexpected exception was thrown. This
+most likely points to an internal inconsistency in the module code. The
+exception message is appended to the log error, and the module will
+continue to run, but will not send back an answer.

src/lib/config/tests/Makefile.am

@@ -22,11 +22,12 @@ run_unittests_SOURCES = ccsession_unittests.cc module_spec_unittests.cc config_d
 run_unittests_CPPFLAGS = $(AM_CPPFLAGS) $(GTEST_INCLUDES)
 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

@@ -160,6 +160,10 @@ TEST_F(CCSessionTest, session1) {
     EXPECT_EQ("ConfigManager", group);
     EXPECT_EQ("*", to);
     EXPECT_EQ(0, session.getMsgQueue()->size());
+
+    // without explicit argument, the session should not automatically
+    // subscribe to logging config
+    EXPECT_FALSE(session.haveSubscription("Logging", "*"));
 }
 
 TEST_F(CCSessionTest, session2) {
@@ -351,7 +355,9 @@ int remote_item1(0);
 ConstElementPtr remote_config;
 ModuleCCSession *remote_mccs(NULL);
 
-void remoteHandler(const std::string& module_name, ConstElementPtr config) {
+void remoteHandler(const std::string& module_name,
+                   ConstElementPtr config,
+                   const ConfigData&) {
     remote_module_name = module_name;
     remote_item1 = remote_mccs->getRemoteConfigValue("Spec2", "item1")->
         intValue();
@@ -362,7 +368,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 +421,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 +440,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 +523,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 +574,62 @@ 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);
+}
+
+TEST_F(CCSessionTest, loggingStart) {
+    // provide the logging module spec
+    ConstElementPtr log_spec = moduleSpecFromFile(LOG_SPEC_FILE).getFullSpec();
+    session.getMessages()->add(createAnswer(0, log_spec));
+    // just give an empty config
+    session.getMessages()->add(createAnswer(0, el("{}")));
+    ModuleCCSession mccs(ccspecfile("spec2.spec"), session, NULL, NULL,
+                         true, true);
+    EXPECT_TRUE(session.haveSubscription("Logging", "*"));
+}
+
+TEST_F(CCSessionTest, loggingStartBadSpec) {
+    // provide the logging module spec
+    session.getMessages()->add(createAnswer(0, el("{}")));
+    // just give an empty config
+    session.getMessages()->add(createAnswer(0, el("{}")));
+    EXPECT_THROW(new ModuleCCSession(ccspecfile("spec2.spec"), session,
+                 NULL, NULL, true, true), ModuleSpecError);
+    EXPECT_FALSE(session.haveSubscription("Logging", "*"));
+}
+
+// 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/config_data_unittests.cc

@@ -64,21 +64,35 @@ TEST(ConfigData, getValue) {
     EXPECT_EQ("{  }", cd.getValue(is_default, "value6/")->str());
     EXPECT_TRUE(is_default);
     EXPECT_EQ("[  ]", cd.getValue("value8")->str());
+    EXPECT_EQ("[  ]", cd.getDefaultValue("value8")->str());
+    EXPECT_EQ("empty", cd.getValue("value8/a")->stringValue());
 
     EXPECT_THROW(cd.getValue("")->str(), DataNotFoundError);
     EXPECT_THROW(cd.getValue("/")->str(), DataNotFoundError);
     EXPECT_THROW(cd.getValue("no_such_item")->str(), DataNotFoundError);
     EXPECT_THROW(cd.getValue("value6/a")->str(), DataNotFoundError);
     EXPECT_THROW(cd.getValue("value6/no_such_item")->str(), DataNotFoundError);
-    EXPECT_THROW(cd.getValue("value8/a")->str(), DataNotFoundError);
-    EXPECT_THROW(cd.getValue("value8/a")->str(), DataNotFoundError);
-    EXPECT_THROW(cd.getValue("value8/a")->str(), DataNotFoundError);
+    EXPECT_THROW(cd.getValue("value8/b")->str(), DataNotFoundError);
 
     ModuleSpec spec1 = moduleSpecFromFile(std::string(TEST_DATA_PATH) + "/spec1.spec");
     ConfigData cd1 = ConfigData(spec1);
     EXPECT_THROW(cd1.getValue("anything")->str(), DataNotFoundError);
 }
 
+TEST(ConfigData, getDefaultValue) {
+    ModuleSpec spec31 = moduleSpecFromFile(std::string(TEST_DATA_PATH) + "/spec31.spec");
+    ConfigData cd = ConfigData(spec31);
+    EXPECT_EQ("[  ]", cd.getDefaultValue("first_list_items")->str());
+    EXPECT_EQ("\"foo\"", cd.getDefaultValue("first_list_items/foo")->str());
+    EXPECT_EQ("{  }", cd.getDefaultValue("first_list_items/second_list_items/map_element")->str());
+    EXPECT_EQ("[  ]", cd.getDefaultValue("first_list_items/second_list_items/map_element/list1")->str());
+    EXPECT_EQ("1", cd.getDefaultValue("first_list_items/second_list_items/map_element/list1/number")->str());
+
+    EXPECT_THROW(cd.getDefaultValue("doesnotexist")->str(), DataNotFoundError);
+    EXPECT_THROW(cd.getDefaultValue("first_list_items/second_list_items/map_element/list1/doesnotexist")->str(), DataNotFoundError);
+}
+
+
 TEST(ConfigData, setLocalConfig) {
     ModuleSpec spec2 = moduleSpecFromFile(std::string(TEST_DATA_PATH) + "/spec2.spec");
     ConfigData cd = ConfigData(spec2);

src/lib/config/tests/data_def_unittests_config.h.in

@@ -13,3 +13,4 @@
 // PERFORMANCE OF THIS SOFTWARE.
 
 #define TEST_DATA_PATH "@abs_srcdir@/testdata"
+#define LOG_SPEC_FILE "@abs_top_srcdir@/src/bin/cfgmgr/plugins/logging.spec"

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

@@ -183,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);
@@ -246,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/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,314 +350,158 @@ TEST(CryptoLinkTest, DISABLED_HMAC_SHA1_RFC2202_SIGN_TRUNCATED) {
 //
 // Test values taken from RFC 4231
 //
-//
 //  Test data from RFC4231, including secret key
 //  and source data, they are common for sha224/256/384/512
-//  so put them together in seperate space
-namespace {
-    static const uint8_t secret1[] = { 
-        0x0b, 0x0b, 0x0b, 0x0b, 0x0b, 0x0b, 0x0b, 
-        0x0b, 0x0b, 0x0b, 0x0b, 0x0b, 0x0b, 0x0b,
-        0x0b, 0x0b, 0x0b, 0x0b, 0x0b, 0x0b 
-    };
-
-    static const uint8_t secret2[] = "Jefe";
-    static const uint8_t secret3[] = { 
-        0xaa, 0xaa, 0xaa, 0xaa, 0xaa, 0xaa,
-        0xaa, 0xaa, 0xaa, 0xaa, 0xaa, 0xaa,
-        0xaa, 0xaa, 0xaa, 0xaa, 0xaa, 0xaa,
-        0xaa, 0xaa 
-    };
-    static  const uint8_t secret4[] = { 
+//  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 
     };
-    static const uint8_t secret5[] = { 
-        0x0c, 0x0c, 0x0c, 0x0c, 0x0c, 0x0c,
-        0x0c, 0x0c, 0x0c, 0x0c, 0x0c, 0x0c,
-        0x0c, 0x0c, 0x0c, 0x0c, 0x0c, 0x0c,
-        0x0c, 0x0c 
-    };
-
-    static uint8_t secret6[131]; 
-    static uint8_t secret7[131]; 
-
-    static const std::string data1("Hi There");
-    static const std::string data2("what do ya want for nothing?");
-    static const std::string data3(std::string(50, 0xdd));
-    static const std::string data4(std::string(50, 0xcd));
-    static const std::string data5("Test With Truncation");
-    static const std::string data6("Test Using Larger Than Block-Size Key - Hash Key First");
-    static const std::string data7("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.");
-#define SECRECT(n) secret##n
-#define DATA(n) data##n
-#define HMAC_EXPECTED(n) hmac_expected##n
-
-#define RUN_NTH_TEST_CASE_FOR_ALG(index, hash_algorithm) do {\
-                doHMACTest(DATA(index), \
-                           SECRECT(index), sizeof(SECRECT(index)), \
-                           (hash_algorithm), HMAC_EXPECTED(index), \
-                           sizeof(HMAC_EXPECTED(index)));\
-            }while(0)
-
-#define RUN_TEST_CASES_FOR_ALG(alg) do {\
-        memcpy(secret6, std::string(131, 0xaa).c_str(), 131); \
-        memcpy(secret7, std::string(131, 0xaa).c_str(), 131); \
-        RUN_NTH_TEST_CASE_FOR_ALG(1, alg); \
-        RUN_NTH_TEST_CASE_FOR_ALG(2, alg); \
-        RUN_NTH_TEST_CASE_FOR_ALG(3, alg); \
-        RUN_NTH_TEST_CASE_FOR_ALG(4, alg); \
-        RUN_NTH_TEST_CASE_FOR_ALG(5, alg); \
-        RUN_NTH_TEST_CASE_FOR_ALG(6, alg); \
-        RUN_NTH_TEST_CASE_FOR_ALG(7, alg); \
-    }while(0)
-
-
-};
+    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());
+    }
+}
 
 TEST(CryptoLinkTest, HMAC_SHA256_RFC4231_SIGN) {
-    const uint8_t hmac_expected1[] = { 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 };
-    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 };
-    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 };
-    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 };
-//    const uint8_t hmac_expected5[] = { 0xa3, 0xb6, 0x16, 0x74, 0x73,
-//                                       0x10, 0x0e, 0xe0, 0x6e, 0x0c,
-//                                       0x79, 0x6c, 0x29, 0x55, 0x55,
-//                                       0x2b };
-    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 };
-    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 };
-
-    memcpy(secret6, std::string(131, 0xaa).c_str(), 131); 
-    memcpy(secret7, std::string(131, 0xaa).c_str(), 131); 
-    RUN_NTH_TEST_CASE_FOR_ALG(1, SHA256); 
-    RUN_NTH_TEST_CASE_FOR_ALG(2, SHA256); 
-    RUN_NTH_TEST_CASE_FOR_ALG(3, SHA256);
-    RUN_NTH_TEST_CASE_FOR_ALG(4, SHA256); 
-    RUN_NTH_TEST_CASE_FOR_ALG(6, SHA256); 
-    RUN_NTH_TEST_CASE_FOR_ALG(7, SHA256); 
- 
+    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);
 }
 
-
 //
 // Test values taken from RFC 4231, test optional algorithm 224,384,512
 //
-TEST(CryptoLinkTest, DISABLED_HMAC_SHA224_RFC4231_SIGN) {
-    const uint8_t hmac_expected1[] = { 
-        0x89,0x6f,0xb1,0x12,0x8a,0xbb,0xdf,0x19,0x68,0x32,0x10,0x7c,
-        0xd4,0x9d,0xf3,0x3f,0x47,0xb4,0xb1,0x16,0x99,0x12,0xba,0x4f,
-        0x53,0x68,0x4b,0x22
-    };
-    const uint8_t hmac_expected2[] = { 
-        0xa3,0x0e,0x01,0x09,0x8b,0xc6,0xdb,0xbf,0x45,0x69,0x0f,0x3a,
-        0x7e,0x9e,0x6d,0x0f,0x8b,0xbe,0xa2,0xa3,0x9e,0x61,0x48,0x00,
-        0x8f,0xd0,0x5e,0x44
-    };
- 
-    const uint8_t hmac_expected3[] = {
-        0x7f,0xb3,0xcb,0x35,0x88,0xc6,0xc1,0xf6,0xff,0xa9,0x69,0x4d,
-        0x7d,0x6a,0xd2,0x64,0x93,0x65,0xb0,0xc1,0xf6,0x5d,0x69,0xd1,
-        0xec,0x83,0x33,0xea
-    };
-
-    const uint8_t hmac_expected4[] = {
-        0x6c,0x11,0x50,0x68,0x74,0x01,0x3c,0xac,0x6a,0x2a,0xbc,0x1b,
-        0xb3,0x82,0x62,0x7c,0xec,0x6a,0x90,0xd8,0x6e,0xfc,0x01,0x2d,
-        0xe7,0xaf,0xec,0x5a
-    };
- 
-//    const uint8_t hmac_expected5[] = {
-//        0x0e,0x2a,0xea,0x68,0xa9,0x0c,0x8d,0x37,0xc9,0x88,0xbc,0xdb,0x9f,
-//        0xca,0x6f,0xa8
-//    };
-
-    const uint8_t hmac_expected6[] = {
-        0x95,0xe9,0xa0,0xdb,0x96,0x20,0x95,0xad,0xae,0xbe,0x9b,0x2d,0x6f,
-        0x0d,0xbc,0xe2,0xd4,0x99,0xf1,0x12,0xf2,0xd2,0xb7,0x27,0x3f,0xa6,
-        0x87,0x0e
-    };
-
-    const uint8_t hmac_expected7[] = {
-        0x3a,0x85,0x41,0x66,0xac,0x5d,0x9f,0x02,0x3f,0x54,0xd5,0x17,0xd0,
-        0xb3,0x9d,0xbd,0x94,0x67,0x70,0xdb,0x9c,0x2b,0x95,0xc9,0xf6,0xf5,
-        0x65,0xd1
-    };
- 
-    memcpy(secret6, std::string(131, 0xaa).c_str(), 131); 
-    memcpy(secret7, std::string(131, 0xaa).c_str(), 131); 
-    RUN_NTH_TEST_CASE_FOR_ALG(1, SHA224); 
-    RUN_NTH_TEST_CASE_FOR_ALG(2, SHA224); 
-    RUN_NTH_TEST_CASE_FOR_ALG(3, SHA224);
-    RUN_NTH_TEST_CASE_FOR_ALG(4, SHA224); 
-    RUN_NTH_TEST_CASE_FOR_ALG(6, SHA224); 
-    RUN_NTH_TEST_CASE_FOR_ALG(7, SHA224); 
+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) {
-    const uint8_t hmac_expected1[] = { 
-        0xaf,0xd0,0x39,0x44,0xd8,0x48,0x95,0x62,0x6b,0x08,0x25,0xf4,
-        0xab,0x46,0x90,0x7f,0x15,0xf9,0xda,0xdb,0xe4,0x10,0x1e,0xc6,
-        0x82,0xaa,0x03,0x4c,0x7c,0xeb,0xc5,0x9c,0xfa,0xea,0x9e,0xa9,
-        0x07,0x6e,0xde,0x7f,0x4a,0xf1,0x52,0xe8,0xb2,0xfa,0x9c,0xb6
-    };
-
-    const uint8_t hmac_expected2[] = {
-        0xaf,0x45,0xd2,0xe3,0x76,0x48,0x40,0x31,0x61,0x7f,0x78,0xd2,
-        0xb5,0x8a,0x6b,0x1b,0x9c,0x7e,0xf4,0x64,0xf5,0xa0,0x1b,0x47,
-        0xe4,0x2e,0xc3,0x73,0x63,0x22,0x44,0x5e,0x8e,0x22,0x40,0xca,
-        0x5e,0x69,0xe2,0xc7,0x8b,0x32,0x39,0xec,0xfa,0xb2,0x16,0x49
-    };
- 
-    const uint8_t hmac_expected3[] = {
-        0x88,0x06,0x26,0x08,0xd3,0xe6,0xad,0x8a,0x0a,0xa2,0xac,0xe0,
-        0x14,0xc8,0xa8,0x6f,0x0a,0xa6,0x35,0xd9,0x47,0xac,0x9f,0xeb,
-        0xe8,0x3e,0xf4,0xe5,0x59,0x66,0x14,0x4b,0x2a,0x5a,0xb3,0x9d,
-        0xc1,0x38,0x14,0xb9,0x4e,0x3a,0xb6,0xe1,0x01,0xa3,0x4f,0x27
-    };
- 
-    const uint8_t hmac_expected4[] = {
-        0x3e,0x8a,0x69,0xb7,0x78,0x3c,0x25,0x85,0x19,0x33,0xab,0x62,
-        0x90,0xaf,0x6c,0xa7,0x7a,0x99,0x81,0x48,0x08,0x50,0x00,0x9c,
-        0xc5,0x57,0x7c,0x6e,0x1f,0x57,0x3b,0x4e,0x68,0x01,0xdd,0x23,
-        0xc4,0xa7,0xd6,0x79,0xcc,0xf8,0xa3,0x86,0xc6,0x74,0xcf,0xfb,
-    };
-   
-//    const uint8_t hmac_expected5[] = {
-//        0x3a,0xbf,0x34,0xc3,0x50,0x3b,0x2a,0x23,0xa4,0x6e,0xfc,0x61,0x9b,
-//        0xae,0xf8,0x97,
-//   };
- 
-    const uint8_t hmac_expected6[] = {
-        0x4e,0xce,0x08,0x44,0x85,0x81,0x3e,0x90,0x88,0xd2,0xc6,0x3a,0x04,
-        0x1b,0xc5,0xb4,0x4f,0x9e,0xf1,0x01,0x2a,0x2b,0x58,0x8f,0x3c,0xd1,
-        0x1f,0x05,0x03,0x3a,0xc4,0xc6,0x0c,0x2e,0xf6,0xab,0x40,0x30,0xfe,
-        0x82,0x96,0x24,0x8d,0xf1,0x63,0xf4,0x49,0x52
-    };
- 
-    const uint8_t hmac_expected7[] = {
-        0x66,0x17,0x17,0x8e,0x94,0x1f,0x02,0x0d,0x35,0x1e,0x2f,0x25,0x4e,
-        0x8f,0xd3,0x2c,0x60,0x24,0x20,0xfe,0xb0,0xb8,0xfb,0x9a,0xdc,0xce,
-        0xbb,0x82,0x46,0x1e,0x99,0xc5,0xa6,0x78,0xcc,0x31,0xe7,0x99,0x17,
-        0x6d,0x38,0x60,0xe6,0x11,0x0c,0x46,0x52,0x3e
-    };
-   
-    memcpy(secret6, std::string(131, 0xaa).c_str(), 131); 
-    memcpy(secret7, std::string(131, 0xaa).c_str(), 131); 
-    RUN_NTH_TEST_CASE_FOR_ALG(1, SHA384); 
-    RUN_NTH_TEST_CASE_FOR_ALG(2, SHA384); 
-    RUN_NTH_TEST_CASE_FOR_ALG(3, SHA384);
-    RUN_NTH_TEST_CASE_FOR_ALG(4, SHA384); 
-    RUN_NTH_TEST_CASE_FOR_ALG(6, SHA384); 
-    RUN_NTH_TEST_CASE_FOR_ALG(7, SHA384); 
+    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) {
-    const uint8_t hmac_expected1[] = { 
-        0x87,0xaa,0x7c,0xde,0xa5,0xef,0x61,0x9d,0x4f,0xf0,0xb4,0x24,
-        0x1a,0x1d,0x6c,0xb0,0x23,0x79,0xf4,0xe2,0xce,0x4e,0xc2,0x78,
-        0x7a,0xd0,0xb3,0x05,0x45,0xe1,0x7c,0xde,0xda,0xa8,0x33,0xb7,
-        0xd6,0xb8,0xa7,0x02,0x03,0x8b,0x27,0x4e,0xae,0xa3,0xf4,0xe4,
-        0xbe,0x9d,0x91,0x4e,0xeb,0x61,0xf1,0x70,0x2e,0x69,0x6c,0x20,
-        0x3a,0x12,0x68,0x54
-    };
-   const uint8_t hmac_expected2[] = {
-        0x16,0x4b,0x7a,0x7b,0xfc,0xf8,0x19,0xe2,0xe3,0x95,0xfb,0xe7,
-        0x3b,0x56,0xe0,0xa3,0x87,0xbd,0x64,0x22,0x2e,0x83,0x1f,0xd6,
-        0x10,0x27,0x0c,0xd7,0xea,0x25,0x05,0x54,0x97,0x58,0xbf,0x75,
-        0xc0,0x5a,0x99,0x4a,0x6d,0x03,0x4f,0x65,0xf8,0xf0,0xe6,0xfd,
-        0xca,0xea,0xb1,0xa3,0x4d,0x4a,0x6b,0x4b,0x63,0x6e,0x07,0x0a,
-        0x38,0xbc,0xe7,0x37
-    }; 
- 
-   const uint8_t hmac_expected3[] = {
-        0xfa,0x73,0xb0,0x08,0x9d,0x56,0xa2,0x84,0xef,0xb0,0xf0,0x75,
-        0x6c,0x89,0x0b,0xe9,0xb1,0xb5,0xdb,0xdd,0x8e,0xe8,0x1a,0x36,
-        0x55,0xf8,0x3e,0x33,0xb2,0x27,0x9d,0x39,0xbf,0x3e,0x84,0x82,
-        0x79,0xa7,0x22,0xc8,0x06,0xb4,0x85,0xa4,0x7e,0x67,0xc8,0x07,
-        0xb9,0x46,0xa3,0x37,0xbe,0xe8,0x94,0x26,0x74,0x27,0x88,0x59,
-        0xe1,0x32,0x92,0xfb
-    };
-
-   const uint8_t hmac_expected4[] = {
-        0xb0,0xba,0x46,0x56,0x37,0x45,0x8c,0x69,0x90,0xe5,0xa8,0xc5,
-        0xf6,0x1d,0x4a,0xf7,0xe5,0x76,0xd9,0x7f,0xf9,0x4b,0x87,0x2d,
-        0xe7,0x6f,0x80,0x50,0x36,0x1e,0xe3,0xdb,0xa9,0x1c,0xa5,0xc1,
-        0x1a,0xa2,0x5e,0xb4,0xd6,0x79,0x27,0x5c,0xc5,0x78,0x80,0x63,
-        0xa5,0xf1,0x97,0x41,0x12,0x0c,0x4f,0x2d,0xe2,0xad,0xeb,0xeb,
-        0x10,0xa2,0x98,0xdd
-    };
- 
-//    const uint8_t hmac_expected5[] = {
-//        0x41,0x5f,0xad,0x62,0x71,0x58,0x0a,0x53,0x1d,0x41,0x79,0xbc,0x89,
-//        0x1d,0x87,0xa6,
-//    };
- 
-    const uint8_t hmac_expected6[] = {
-        0x80,0xb2,0x42,0x63,0xc7,0xc1,0xa3,0xeb,0xb7,0x14,0x93,0xc1,0xdd,
-        0x7b,0xe8,0xb4,0x9b,0x46,0xd1,0xf4,0x1b,0x4a,0xee,0xc1,0x12,0x1b,
-        0x01,0x37,0x83,0xf8,0xf3,0x52,0x6b,0x56,0xd0,0x37,0xe0,0x5f,0x25,
-        0x98,0xbd,0x0f,0xd2,0x21,0x5d,0x6a,0x1e,0x52,0x95,0xe6,0x4f,0x73,
-        0xf6,0x3f,0x0a,0xec,0x8b,0x91,0x5a,0x98,0x5d,0x78,0x65,0x98
-    };
-
-    const uint8_t hmac_expected7[] = {
-        0xe3,0x7b,0x6a,0x77,0x5d,0xc8,0x7d,0xba,0xa4,0xdf,0xa9,0xf9,0x6e,
-        0x5e,0x3f,0xfd,0xde,0xbd,0x71,0xf8,0x86,0x72,0x89,0x86,0x5d,0xf5,
-        0xa3,0x2d,0x20,0xcd,0xc9,0x44,0xb6,0x02,0x2c,0xac,0x3c,0x49,0x82,
-        0xb1,0x0d,0x5e,0xeb,0x55,0xc3,0xe4,0xde,0x15,0x13,0x46,0x76,0xfb,
-        0x6d,0xe0,0x44,0x60,0x65,0xc9,0x74,0x40,0xfa,0x8c,0x6a,0x58
-    };
- 
-    memcpy(secret6, std::string(131, 0xaa).c_str(), 131); 
-    memcpy(secret7, std::string(131, 0xaa).c_str(), 131); 
-    RUN_NTH_TEST_CASE_FOR_ALG(1, SHA512); 
-    RUN_NTH_TEST_CASE_FOR_ALG(2, SHA512); 
-    RUN_NTH_TEST_CASE_FOR_ALG(3, SHA512);
-    RUN_NTH_TEST_CASE_FOR_ALG(4, SHA512); 
-    RUN_NTH_TEST_CASE_FOR_ALG(6, SHA512); 
-    RUN_NTH_TEST_CASE_FOR_ALG(7, SHA512); 
+    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)
-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,8 @@
 // PERFORMANCE OF THIS SOFTWARE.
 
 #include <gtest/gtest.h>
+#include <util/unittests/run_all.h>
+#include <log/logger_support.h>
 
 #include <dns/tests/unittest_util.h>
 
@@ -21,5 +23,7 @@ main(int argc, char* argv[]) {
     ::testing::InitGoogleTest(&argc, argv);
     isc::UnitTestUtil::addDataPath(TEST_DATA_DIR);
 
-    return (RUN_ALL_TESTS());
+    isc::log::initLogger();
+
+    return (isc::util::unittests::run_all());
 }

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/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

@@ -2,32 +2,36 @@ SUBDIRS = . compiler tests
 
 AM_CPPFLAGS = -I$(top_builddir)/src/lib -I$(top_srcdir)/src/lib
 AM_CPPFLAGS += $(BOOST_INCLUDES)
-AM_CPPFLAGS += -I$(top_srcdir)/src/lib/log -I$(top_builddir)/src/lib/log
-AM_CPPFLAGS += -I$(top_srcdir)/src/lib/util -I$(top_builddir)/src/lib/util
 
 CLEANFILES = *.gcno *.gcda
 
 lib_LTLIBRARIES = liblog.la
 liblog_la_SOURCES  =
-liblog_la_SOURCES += debug_levels.h logger_levels.h
 liblog_la_SOURCES += dummylog.h dummylog.cc
+liblog_la_SOURCES += impldef.cc impldef.h
+liblog_la_SOURCES += log_formatter.h log_formatter.cc
 liblog_la_SOURCES += logger.cc logger.h
 liblog_la_SOURCES += logger_impl.cc logger_impl.h
+liblog_la_SOURCES += logger_level.h
+liblog_la_SOURCES += logger_level.cc logger_level.h
+liblog_la_SOURCES += logger_level_impl.cc logger_level_impl.h
+liblog_la_SOURCES += logger_manager.cc logger_manager.h
+liblog_la_SOURCES += logger_manager_impl.cc logger_manager_impl.h
+liblog_la_SOURCES += logger_name.cc logger_name.h
+liblog_la_SOURCES += logger_specification.h
 liblog_la_SOURCES += logger_support.cc logger_support.h
+liblog_la_SOURCES += macros.h
 liblog_la_SOURCES += messagedef.cc messagedef.h
 liblog_la_SOURCES += message_dictionary.cc message_dictionary.h
 liblog_la_SOURCES += message_exception.h
 liblog_la_SOURCES += message_initializer.cc message_initializer.h
 liblog_la_SOURCES += message_reader.cc message_reader.h
 liblog_la_SOURCES += message_types.h
-liblog_la_SOURCES += root_logger_name.cc root_logger_name.h
-liblog_la_SOURCES += log_formatter.h log_formatter.cc
-liblog_la_SOURCES += macros.h
+liblog_la_SOURCES += output_option.cc output_option.h
 
 EXTRA_DIST  = README
+EXTRA_DIST += impldef.mes
 EXTRA_DIST += messagedef.mes
-EXTRA_DIST += logger_impl_log4cxx.cc logger_impl_log4cxx.h
-EXTRA_DIST += xdebuglevel.cc xdebuglevel.h
 
 # Note: the ordering matters: -Wno-... must follow -Wextra (defined in
 # B10_CXXFLAGS)
@@ -39,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/README

@@ -117,7 +117,7 @@ Points to note:
 * Lines starting $ are directives.  At present, two directives are recognised:
 
   * $PREFIX, which has one optional argument: the string used to prefix symbols.
-    If absent, there is no prefix to the symbols. (Prefixes are explained below.)
+    If absent, there is no prefix to the symbols (prefixes are explained below).
 
   * $NAMESPACE, which has one argument: the namespace in which the symbols are
     created.  In the absence of a $NAMESPACE directive, symbols will be put in
@@ -135,7 +135,7 @@ Points to note:
   * The replacement tokens are the strings "%1", "%2" etc.  When a message
     is logged, these are replaced with the arguments passed to the logging
     call: %1 refers to the first argument, %2 to the second etc.  Within the
-    message text, the placeholders can appear in any order, and placeholders
+    message text, the placeholders can appear in any order and placeholders
     can be repeated.
      
 * Remaining lines indicate an explanation for the preceding message.  These
@@ -215,33 +215,9 @@ To use the current version of the logging:
 
 1. Build message header file and source file as describe above.
 
-2. In the main module of the program, declare an instance of the
-   RootLoggerName class to define the name of the program's root logger, e.g.
-
-       #include <log/root_logger_name.h>
-
-       isc::log::RootLoggerName("b10-auth");
-
-   This can be declared inside or outside an execution unit.
-
-2. In the code that needs to do logging, declare a logger with a given name,
-   e.g.
-
-       #include <log/logger.h>
-            :
-       isc::log::Logger logger("myname");   // "myname" can be anything
-
-   The above example assumes declaration outside a function.  If declaring
-   non-statically within a function, declare it as:
-
-       isc::log::Logger logger("myname", true);
-
-   (The argument is required to support a possible future implementation of
-   logging.  Currently it has no effect.)
-
-3. The main program unit should include a call to isc::log::initLogger()
+2. The main program unit should include a call to isc::log::initLogger()
    (defined in logger_support.h) to set the logging severity, debug log level,
-   and external message file.
+   and external message file:
 
    a) The logging severity is one of the enum defined in logger.h, i.e.
 
@@ -262,56 +238,43 @@ To use the current version of the logging:
       directive of a particular type will be ignored; multiple directives will
       cause the read of the file to fail with an error.)
 
-4. Issue logging calls using methods on logger, e.g.
+   The settings remain in effect until the logging configuration is read, and
+   so provide the default logging during program initialization.
 
-       logger.error(DPS_NSTIMEOUT).arg("isc.org");
+3. Issue logging calls using supplied macros in "log/macros.h", e.g.
 
-   (where, in the example above we might have defined the symbol in the message
+       LOG_ERROR(logger, DPS_NSTIMEOUT).arg("isc.org");
+
+   (The macros are more efficient that calls to the methods on the logger class:
+   they avoid the overhead of evaluating the parameters to arg() if the
+   settings are such that the message is not going to be output.)
+
+   Note: in the example above we might have defined the symbol in the message
    file with something along the lines of:
 
        $PREFIX DPS_
            :
        NSTIMEOUT  queries to all nameservers for %1 have timed out
 
-   At present, the only logging is to the console.
-
-
-Efficiency Considerations
--------------------------
-A common pattern in logging is a debug call of the form:
-
-   logger.debug(dbglevel, MSGID).arg(expensive_call()).arg(...
-
-... where "expensive_call()" is a function call to obtain logging information
-that may be computationally intensive.  Although the cost may be justified
-when debugging is enabled, the cost is still incurred even if debugging is
-disabled and the debug() method returns without outputting anything.  (The
-same may be true of other logging levels, although there are likely to be
-fewer calls to logger.info(), logger.error() etc. throughout the code and
-they are less likely to be disabled.)
-
-For this reason, a set of macros is provided and are called using the
-construct:
-
-   LOG_DEBUG(logger, dbglevel, MSGID).arg(expensive_call()).arg(...
-   LOG_INFO(logger, MSGID).arg(expensive_call()...)
-
-If these are used, the arguments passed to the arg() method are not evaluated
-if the relevant logging level is disabled.
-
-
 Severity Guidelines
 ===================
 When using logging, the question arises, what severity should a message be
 logged at?  The following is a suggestion - as always, the decision must be
 made in the context of which the message is logged.
 
+One thing that should always be borne in mind is whether the logging could
+be used as a vector for a DOS attack.  For example, if a warning message is
+logged every time an invalid packet is received, an attacker could simply send
+large numbers of invalid packets.  (Of course, warnings could be disabled (or
+just warnings for that that particular logger), but nevertheless the message
+is an attack vector.)
+
 FATAL
 -----
-The program has encountered an error that is so severe that it cannot
-continue (or there is no point in continuing).  When a fatal error has been
-logged, the program will usually exit immediately (via a call to abort()) or
-shortly afterwards, after dumping some diagnostic information.
+The program has encountered an error that is so severe that it cannot continue
+(or there is no point in continuing).  When a fatal error has been logged,
+the program will usually exit immediately (or shortly afterwards) after
+dumping some diagnostic information.
 
 ERROR
 -----
@@ -342,7 +305,7 @@ are distributed between the levels is up to the developer.  So if debugging
 the NSAS (for example), a level 0 message might record the creation of a new
 zone, a level 10 recording a timeout when trying to get a nameserver address,
 but a level 50 would record every query for an address. (And we might add
-level 51 to record every update of the RTT.)
+level 70 to record every update of the RTT.)
 
 Note that like severities, levels are cumulative; so if level 25 is set as the
 debug level, all debug levels from 0 to 25 will be output.  In fact, it is
@@ -397,13 +360,3 @@ is only one piece of code that does this functionality.
 Outstanding Issues
 ==================
 * Ability to configure system according to configuration database.
-
-
-log4cxx Issues
-==============
-Some experimental code to utilise log4cxx as an underlying implementation
-is present in the source code directory although it is not currently used.
-The files are:
-
-   logger_impl_log4cxx.{cc,h}
-   xdebuglevel.{cc,h}

src/lib/log/compiler/Makefile.am

@@ -1,8 +1,6 @@
 SUBDIRS = .
 
 AM_CPPFLAGS = -I$(top_srcdir)/src/lib -I$(top_builddir)/src/lib
-AM_CPPFLAGS += -I$(top_srcdir)/src/lib/log -I$(top_builddir)/src/lib/log
-AM_CPPFLAGS += -I$(top_srcdir)/src/lib/util -I$(top_builddir)/src/lib/util
 AM_CPPFLAGS += $(BOOST_INCLUDES)
 
 AM_CXXFLAGS = $(B10_CXXFLAGS)
@@ -14,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_SOURCES = message.cc
+message_LDADD   = $(top_builddir)/src/lib/log/liblog.la
+message_LDADD  += $(top_builddir)/src/lib/util/libutil.la

src/lib/log/compiler/message.cc

@@ -35,6 +35,8 @@
 
 #include <log/logger.h>
 
+#include <boost/foreach.hpp>
+
 using namespace std;
 using namespace isc::log;
 using namespace isc::util;
@@ -78,10 +80,11 @@ version() {
 void
 usage() {
     cout <<
-        "Usage: message [-h] [-v] <message-file>\n" <<
+        "Usage: message [-h] [-v] [-p] <message-file>\n" <<
         "\n" <<
         "-h       Print this message and exit\n" <<
         "-v       Print the program version and exit\n" <<
+        "-p       Output python source instead of C++ ones\n" <<
         "\n" <<
         "<message-file> is the name of the input message file.\n";
 }
@@ -237,6 +240,44 @@ writeClosingNamespace(ostream& output, const vector<string>& ns) {
     }
 }
 
+/// \breif Write python file
+///
+/// Writes the python file containing the symbol definitions as module level
+/// constants. These are objects which register themself at creation time,
+/// so they can be replaced by dictionary later.
+///
+/// \param file Name of the message file. The source code is written to a file
+///     file of the same name but with a .py suffix.
+/// \param dictionary The dictionary holding the message definitions.
+///
+/// \note We don't use the namespace as in C++. We don't need it, because
+///     python file/module works as implicit namespace as well.
+
+void
+writePythonFile(const string& file, MessageDictionary& dictionary) {
+    Filename message_file(file);
+    Filename python_file(Filename(message_file.name()).useAsDefault(".py"));
+
+    // Open the file for writing
+    ofstream pyfile(python_file.fullName().c_str());
+
+    // Write the comment and imports
+    pyfile <<
+        "# File created from " << message_file.fullName() << " on " <<
+            currentTime() << "\n" <<
+        "\n" <<
+        "import isc.log.message\n" <<
+        "\n";
+
+    vector<string> idents(sortedIdentifiers(dictionary));
+    BOOST_FOREACH(const string& ident, idents) {
+        pyfile << ident << " = isc.log.message.create(\"" <<
+            ident << "\", \"" << quoteString(dictionary.getText(ident)) <<
+            "\")\n";
+    }
+
+    pyfile.close();
+}
 
 /// \brief Write Header File
 ///
@@ -264,52 +305,46 @@ writeHeaderFile(const string& file, const vector<string>& ns_components,
     // Open the output file for writing
     ofstream hfile(header_file.fullName().c_str());
 
-    try {
-        if (hfile.fail()) {
-            throw MessageException(MSG_OPENOUT, header_file.fullName(),
-                strerror(errno));
-        }
-
-        // Write the header preamble.  If there is an error, we'll pick it up
-        // after the last write.
-
-        hfile <<
-            "// File created from " << message_file.fullName() << " on " <<
-                currentTime() << "\n" <<
-             "\n" <<
-             "#ifndef " << sentinel_text << "\n" <<
-             "#define "  << sentinel_text << "\n" <<
-             "\n" <<
-             "#include <log/message_types.h>\n" <<
-             "\n";
-
-        // Write the message identifiers, bounded by a namespace declaration
-        writeOpeningNamespace(hfile, ns_components);
-
-        vector<string> idents = sortedIdentifiers(dictionary);
-        for (vector<string>::const_iterator j = idents.begin();
-            j != idents.end(); ++j) {
-            hfile << "extern const isc::log::MessageID " << *j << ";\n";
-        }
-        hfile << "\n";
+    if (hfile.fail()) {
+        throw MessageException(MSG_OPENOUT, header_file.fullName(),
+            strerror(errno));
+    }
 
-        writeClosingNamespace(hfile, ns_components);
+    // Write the header preamble.  If there is an error, we'll pick it up
+    // after the last write.
+
+    hfile <<
+        "// File created from " << message_file.fullName() << " on " <<
+            currentTime() << "\n" <<
+         "\n" <<
+         "#ifndef " << sentinel_text << "\n" <<
+         "#define "  << sentinel_text << "\n" <<
+         "\n" <<
+         "#include <log/message_types.h>\n" <<
+         "\n";
+
+    // Write the message identifiers, bounded by a namespace declaration
+    writeOpeningNamespace(hfile, ns_components);
+
+    vector<string> idents = sortedIdentifiers(dictionary);
+    for (vector<string>::const_iterator j = idents.begin();
+        j != idents.end(); ++j) {
+        hfile << "extern const isc::log::MessageID " << *j << ";\n";
+    }
+    hfile << "\n";
 
-        // ... and finally the postamble
-        hfile << "#endif // " << sentinel_text << "\n";
+    writeClosingNamespace(hfile, ns_components);
 
-        // Report errors (if any) and exit
-        if (hfile.fail()) {
-            throw MessageException(MSG_WRITERR, header_file.fullName(),
-                strerror(errno));
-        }
+    // ... and finally the postamble
+    hfile << "#endif // " << sentinel_text << "\n";
 
-        hfile.close();
-    }
-    catch (MessageException&) {
-        hfile.close();
-        throw;
+    // Report errors (if any) and exit
+    if (hfile.fail()) {
+        throw MessageException(MSG_WRITERR, header_file.fullName(),
+            strerror(errno));
     }
+
+    hfile.close();
 }
 
 
@@ -357,76 +392,71 @@ writeProgramFile(const string& file, const vector<string>& ns_components,
 
     // Open the output file for writing
     ofstream ccfile(program_file.fullName().c_str());
-    try {
-        if (ccfile.fail()) {
-            throw MessageException(MSG_OPENOUT, program_file.fullName(),
-                strerror(errno));
-        }
 
-        // Write the preamble.  If there is an error, we'll pick it up after
-        // the last write.
+    if (ccfile.fail()) {
+        throw MessageException(MSG_OPENOUT, program_file.fullName(),
+            strerror(errno));
+    }
 
-        ccfile <<
-            "// File created from " << message_file.fullName() << " on " <<
-                currentTime() << "\n" <<
-             "\n" <<
-             "#include <cstddef>\n" <<
-             "#include <log/message_types.h>\n" <<
-             "#include <log/message_initializer.h>\n" <<
-             "\n";
+    // Write the preamble.  If there is an error, we'll pick it up after
+    // the last write.
 
-        // Declare the message symbols themselves.
+    ccfile <<
+        "// File created from " << message_file.fullName() << " on " <<
+            currentTime() << "\n" <<
+         "\n" <<
+         "#include <cstddef>\n" <<
+         "#include <log/message_types.h>\n" <<
+         "#include <log/message_initializer.h>\n" <<
+         "\n";
 
-        writeOpeningNamespace(ccfile, ns_components);
+    // Declare the message symbols themselves.
 
-        vector<string> idents = sortedIdentifiers(dictionary);
-        for (vector<string>::const_iterator j = idents.begin();
-            j != idents.end(); ++j) {
-            ccfile << "extern const isc::log::MessageID " << *j <<
-                " = \"" << *j << "\";\n";
-        }
-        ccfile << "\n";
+    writeOpeningNamespace(ccfile, ns_components);
 
-        writeClosingNamespace(ccfile, ns_components);
+    vector<string> idents = sortedIdentifiers(dictionary);
+    for (vector<string>::const_iterator j = idents.begin();
+        j != idents.end(); ++j) {
+        ccfile << "extern const isc::log::MessageID " << *j <<
+            " = \"" << *j << "\";\n";
+    }
+    ccfile << "\n";
 
-        // Now the code for the message initialization.
+    writeClosingNamespace(ccfile, ns_components);
 
-        ccfile <<
-             "namespace {\n" <<
-             "\n" <<
-             "const char* values[] = {\n";
+    // Now the code for the message initialization.
 
-        // Output the identifiers and the associated text.
-        idents = sortedIdentifiers(dictionary);
-        for (vector<string>::const_iterator i = idents.begin();
-            i != idents.end(); ++i) {
-                ccfile << "    \"" << *i << "\", \"" <<
-                    quoteString(dictionary.getText(*i)) << "\",\n";
-        }
+    ccfile <<
+         "namespace {\n" <<
+         "\n" <<
+         "const char* values[] = {\n";
 
+    // Output the identifiers and the associated text.
+    idents = sortedIdentifiers(dictionary);
+    for (vector<string>::const_iterator i = idents.begin();
+        i != idents.end(); ++i) {
+            ccfile << "    \"" << *i << "\", \"" <<
+                quoteString(dictionary.getText(*i)) << "\",\n";
+    }
 
-        // ... and the postamble
-        ccfile <<
-            "    NULL\n" <<
-            "};\n" <<
-            "\n" <<
-            "const isc::log::MessageInitializer initializer(values);\n" <<
-            "\n" <<
-            "} // Anonymous namespace\n" <<
-            "\n";
-
-        // Report errors (if any) and exit
-        if (ccfile.fail()) {
-            throw MessageException(MSG_WRITERR, program_file.fullName(),
-                strerror(errno));
-        }
 
-        ccfile.close();
-    }
-    catch (MessageException&) {
-        ccfile.close();
-        throw;
+    // ... and the postamble
+    ccfile <<
+        "    NULL\n" <<
+        "};\n" <<
+        "\n" <<
+        "const isc::log::MessageInitializer initializer(values);\n" <<
+        "\n" <<
+        "} // Anonymous namespace\n" <<
+        "\n";
+
+    // Report errors (if any) and exit
+    if (ccfile.fail()) {
+        throw MessageException(MSG_WRITERR, program_file.fullName(),
+            strerror(errno));
     }
+
+    ccfile.close();
 }
 
 
@@ -466,13 +496,19 @@ warnDuplicates(MessageReader& reader) {
 int
 main(int argc, char* argv[]) {
 
-    const char* soptions = "hv";               // Short options
+    const char* soptions = "hvp";               // Short options
 
     optind = 1;             // Ensure we start a new scan
     int  opt;               // Value of the option
 
+    bool doPython = false;
+
     while ((opt = getopt(argc, argv, soptions)) != -1) {
         switch (opt) {
+            case 'p':
+                doPython = true;
+                break;
+
             case 'h':
                 usage();
                 return 0;
@@ -508,15 +544,27 @@ main(int argc, char* argv[]) {
         MessageReader reader(&dictionary);
         reader.readFile(message_file);
 
-        // Get the namespace into which the message definitions will be put and
-        // split it into components.
-        vector<string> ns_components = splitNamespace(reader.getNamespace());
-
-        // Write the header file.
-        writeHeaderFile(message_file, ns_components, dictionary);
-
-        // Write the file that defines the message symbols and text
-        writeProgramFile(message_file, ns_components, dictionary);
+        if (doPython) {
+            // Warn in case of ignored directives
+            if (!reader.getNamespace().empty()) {
+                cerr << "Python mode, ignoring the $NAMESPACE directive" <<
+                    endl;
+            }
+
+            // Write the whole python file
+            writePythonFile(message_file, dictionary);
+        } else {
+            // Get the namespace into which the message definitions will be put and
+            // split it into components.
+            vector<string> ns_components =
+                splitNamespace(reader.getNamespace());
+
+            // Write the header file.
+            writeHeaderFile(message_file, ns_components, dictionary);
+
+            // Write the file that defines the message symbols and text
+            writeProgramFile(message_file, ns_components, dictionary);
+        }
 
         // Finally, warn of any duplicates encountered.
         warnDuplicates(reader);

src/lib/log/impldef.cc

@@ -0,0 +1,29 @@
+// File created from impldef.mes on Wed Jun  1 10:32:57 2011
+
+#include <cstddef>
+#include <log/message_types.h>
+#include <log/message_initializer.h>
+
+namespace isc {
+namespace log {
+
+extern const isc::log::MessageID LOGIMPL_ABOVEDBGMAX = "LOGIMPL_ABOVEDBGMAX";
+extern const isc::log::MessageID LOGIMPL_BADDEBUG = "LOGIMPL_BADDEBUG";
+extern const isc::log::MessageID LOGIMPL_BELOWDBGMIN = "LOGIMPL_BELOWDBGMIN";
+
+} // namespace log
+} // namespace isc
+
+namespace {
+
+const char* values[] = {
+    "LOGIMPL_ABOVEDBGMAX", "debug level of %1 is too high and will be set to the maximum of %2",
+    "LOGIMPL_BADDEBUG", "debug string is '%1': must be of the form DEBUGn",
+    "LOGIMPL_BELOWDBGMIN", "debug level of %1 is too low and will be set to the minimum of %2",
+    NULL
+};
+
+const isc::log::MessageInitializer initializer(values);
+
+} // Anonymous namespace
+

src/lib/log/impldef.h

@@ -0,0 +1,18 @@
+// File created from impldef.mes on Wed Jun  1 10:32:57 2011
+
+#ifndef __IMPLDEF_H
+#define __IMPLDEF_H
+
+#include <log/message_types.h>
+
+namespace isc {
+namespace log {
+
+extern const isc::log::MessageID LOGIMPL_ABOVEDBGMAX;
+extern const isc::log::MessageID LOGIMPL_BADDEBUG;
+extern const isc::log::MessageID LOGIMPL_BELOWDBGMIN;
+
+} // namespace log
+} // namespace isc
+
+#endif // __IMPLDEF_H

src/lib/log/impldef.mes

@@ -0,0 +1,38 @@
+# 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.
+
+# \brief Logger Implementation Messages
+#
+# This holds messages generated by the underlying logger implementation.  They
+# are likely to be specific to that implementation, and may well change if the
+# underlying implementation is changed.  For that reason, they have been put
+# in a separate file.
+
+$PREFIX LOGIMPL_
+$NAMESPACE isc::log
+
+% ABOVEDBGMAX   debug level of %1 is too high and will be set to the maximum of %2
+A message from the underlying logger implementation code, the debug level
+(as set by the string DEBGUGn) is above the maximum allowed value and has
+been reduced to that value.
+
+% BADDEBUG      debug string is '%1': must be of the form DEBUGn
+The string indicating the extended logging level (used by the underlying
+logger implementation code) is not of the stated form.  In particular,
+it starts DEBUG but does not end with an integer.
+
+% BELOWDBGMIN   debug level of %1 is too low and will be set to the minimum of %2
+A message from the underlying logger implementation code, the debug level
+(as set by the string DEBGUGn) is below the minimum allowed value and has
+been increased to that value.

src/lib/log/log_formatter.h

@@ -15,8 +15,11 @@
 #ifndef __LOG_FORMATTER_H
 #define __LOG_FORMMATER_H
 
+#include <cstddef>
 #include <string>
+#include <iostream>
 #include <boost/lexical_cast.hpp>
+#include <log/logger_level.h>
 
 namespace isc {
 namespace log {
@@ -73,13 +76,17 @@ private:
     ///
     /// If NULL, we are not active and should not produce anything.
     mutable Logger* logger_;
-    /// \brief Prefix (eg. "ERROR", "DEBUG" or like that)
-    const char* prefix_;
+
+    /// \brief Message severity
+    Severity severity_;
+
     /// \brief The messages with %1, %2... placeholders
     std::string* message_;
+
     /// \brief Which will be the next placeholder to replace
     unsigned nextPlaceholder_;
-    Formatter& operator =(const Formatter& other);
+
+
 public:
     /// \brief Constructor of "active" formatter
     ///
@@ -89,34 +96,57 @@ public:
     ///
     /// It is not expected to be called by user of logging system directly.
     ///
-    /// \param prefix The severity prefix, like "ERROR" or "DEBUG"
+    /// \param severity The severity of the message (DEBUG, ERROR etc.)
     /// \param message The message with placeholders. We take ownership of
     ///     it and we will modify the string. Must not be NULL unless
     ///     logger is also NULL, but it's not checked.
     /// \param logger The logger where the final output will go, or NULL
     ///     if no output is wanted.
-    Formatter(const char* prefix = NULL, std::string* message = NULL,
+    Formatter(const Severity& severity = NONE, std::string* message = NULL,
               Logger* logger = NULL) :
-        logger_(logger), prefix_(prefix), message_(message),
-        nextPlaceholder_(1)
+        logger_(logger), severity_(severity), message_(message),
+        nextPlaceholder_(0)
     {
     }
 
+    /// \brief Copy constructor
+    ///
+    /// "Control" is passed to the created object in that it is the created object
+    /// that will have responsibility for outputting the formatted message - the
+    /// object being copied relinquishes that responsibility.
     Formatter(const Formatter& other) :
-        logger_(other.logger_), prefix_(other.prefix_),
+        logger_(other.logger_), severity_(other.severity_),
         message_(other.message_), nextPlaceholder_(other.nextPlaceholder_)
     {
-        other.logger_ = false;
+        other.logger_ = NULL;
     }
+
     /// \brief Destructor.
     //
     /// This is the place where output happens if the formatter is active.
     ~ Formatter() {
         if (logger_) {
-            logger_->output(prefix_, *message_);
+            logger_->output(severity_, *message_);
             delete message_;
         }
     }
+
+    /// \brief Assignment operator
+    ///
+    /// Essentially the same function as the assignment operator - the object being
+    /// assigned to takes responsibility for outputting the message.
+    Formatter& operator =(const Formatter& other) {
+        if (&other != this) {
+            logger_ = other.logger_;
+            severity_ = other.severity_;
+            message_ = other.message_;
+            nextPlaceholder_ = other.nextPlaceholder_;
+            other.logger_ = NULL;
+        }
+
+        return *this;
+    }
+
     /// \brief Replaces another placeholder
     ///
     /// Replaces another placeholder and returns a new formatter with it.
@@ -131,17 +161,25 @@ public:
             return (*this);
         }
     }
+
     /// \brief String version of arg.
     Formatter& arg(const std::string& arg) {
         if (logger_) {
-            // FIXME: This logic has a problem. If we had a message like
-            // "%1 %2" and called .arg("%2").arg(42), we would get "42 %2".
-            // But we consider this to be rare enough not to complicate
-            // matters.
-            replacePlaceholder(message_, arg, nextPlaceholder_ ++);
+            // 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.cc

@@ -17,9 +17,9 @@
 
 #include <log/logger.h>
 #include <log/logger_impl.h>
+#include <log/logger_name.h>
 #include <log/message_dictionary.h>
 #include <log/message_types.h>
-#include <log/root_logger_name.h>
 
 #include <util/strutil.h>
 
@@ -28,10 +28,9 @@ using namespace std;
 namespace isc {
 namespace log {
 
-// Initialize Logger implementation.  Does not check whether the implementation
-// has already been initialized - that was done by the caller (getLoggerPtr()).
+// Initialize Logger.
 void Logger::initLoggerImpl() {
-    loggerptr_ = new LoggerImpl(name_, infunc_);
+    loggerptr_ = new LoggerImpl(name_);
 }
 
 // Destructor.
@@ -75,6 +74,14 @@ Logger::getDebugLevel() {
     return (getLoggerPtr()->getDebugLevel());
 }
 
+// Effective debug level (only relevant if messages of severity DEBUG are being
+// logged).
+
+int
+Logger::getEffectiveDebugLevel() {
+    return (getLoggerPtr()->getEffectiveDebugLevel());
+}
+
 // Check on the current severity settings
 
 bool
@@ -112,14 +119,14 @@ Logger::isFatalEnabled() {
 // Output methods
 
 void
-Logger::output(const char* sevText, const string& message) {
-    getLoggerPtr()->outputRaw(sevText, message);
+Logger::output(const Severity& severity, const std::string& message) {
+    getLoggerPtr()->outputRaw(severity, message);
 }
 
 Logger::Formatter
 Logger::debug(int dbglevel, const isc::log::MessageID& ident) {
     if (isDebugEnabled(dbglevel)) {
-        return (Formatter("DEBUG", getLoggerPtr()->lookupMessage(ident),
+        return (Formatter(DEBUG, getLoggerPtr()->lookupMessage(ident),
                           this));
     } else {
         return (Formatter());
@@ -129,7 +136,7 @@ Logger::debug(int dbglevel, const isc::log::MessageID& ident) {
 Logger::Formatter
 Logger::info(const isc::log::MessageID& ident) {
     if (isInfoEnabled()) {
-        return (Formatter("INFO ", getLoggerPtr()->lookupMessage(ident),
+        return (Formatter(INFO, getLoggerPtr()->lookupMessage(ident),
                           this));
     } else {
         return (Formatter());
@@ -139,7 +146,7 @@ Logger::info(const isc::log::MessageID& ident) {
 Logger::Formatter
 Logger::warn(const isc::log::MessageID& ident) {
     if (isWarnEnabled()) {
-        return (Formatter("WARN ", getLoggerPtr()->lookupMessage(ident),
+        return (Formatter(WARN, getLoggerPtr()->lookupMessage(ident),
                           this));
     } else {
         return (Formatter());
@@ -149,7 +156,7 @@ Logger::warn(const isc::log::MessageID& ident) {
 Logger::Formatter
 Logger::error(const isc::log::MessageID& ident) {
     if (isErrorEnabled()) {
-        return (Formatter("ERROR", getLoggerPtr()->lookupMessage(ident),
+        return (Formatter(ERROR, getLoggerPtr()->lookupMessage(ident),
                           this));
     } else {
         return (Formatter());
@@ -159,22 +166,18 @@ Logger::error(const isc::log::MessageID& ident) {
 Logger::Formatter
 Logger::fatal(const isc::log::MessageID& ident) {
     if (isFatalEnabled()) {
-        return (Formatter("FATAL", getLoggerPtr()->lookupMessage(ident),
+        return (Formatter(FATAL, getLoggerPtr()->lookupMessage(ident),
                           this));
     } else {
         return (Formatter());
     }
 }
 
-bool Logger::operator==(Logger& other) {
-    return (*getLoggerPtr() == *other.getLoggerPtr());
-}
-
-// Protected methods (used for testing)
+// Comparison (testing only)
 
-void
-Logger::reset() {
-    LoggerImpl::reset();
+bool
+Logger::operator==(Logger& other) {
+    return (*getLoggerPtr() == *other.getLoggerPtr());
 }
 
 } // namespace log

src/lib/log/logger.h

@@ -18,34 +18,73 @@
 #include <cstdlib>
 #include <string>
 
-#include <log/debug_levels.h>
-#include <log/logger_levels.h>
+#include <log/logger_level.h>
 #include <log/message_types.h>
 #include <log/log_formatter.h>
 
 namespace isc {
 namespace log {
 
-/// \brief Logging API
-///
-/// This module forms the interface into the logging subsystem. Features of the
-/// system and its implementation are:
-///
-/// # Multiple logging objects can be created, each given a name; those with the
-///   same name share characteristics (like destination, level being logged
-///   etc.)
-/// # Messages can be logged at severity levels of FATAL, ERROR, WARN, INFO or
-///   DEBUG.  The DEBUG level has further sub-levels numbered 0 (least
-///   informative) to 99 (most informative).
-/// # Each logger has a severity level set associated with it.  When a message
-///   is logged, it is output only if it is logged at a level equal to the
-///   logger severity level or greater, e.g. if the logger's severity is WARN,
-///   only messages logged at WARN, ERROR or FATAL will be output.
-/// # Messages are identified by message identifiers, which are keys into a
-///   message dictionary.
+/// \page LoggingApi Logging API
+/// \section LoggingApiOverview Overview
+/// BIND 10 logging uses the concepts of the widely-used Java logging
+/// package log4j (http://logging.apache.log/log4j), albeit implemented 
+/// in C++ using an open-source port.  Features of the system are:
+/// 
+/// - Within the code objects - known as loggers - can be created and
+/// used to log messages.  These loggers have names; those with the
+/// same name share characteristics (such as output destination).
+/// - Loggers have a hierarchical relationship, with each logger being
+/// the child of another logger, except for the top of the hierarchy, the
+/// root logger.  If a logger does not log a message, it is passed to the
+/// parent logger.
+/// - Messages can be logged at severity levels of FATAL, ERROR, WARN, INFO
+/// or DEBUG.  The DEBUG level has further sub-levels numbered 0 (least
+/// informative) to 99 (most informative).
+/// - Each logger has a severity level set associated with it.  When a
+/// message is logged, it is output only if it is logged at a level equal
+/// to the logger severity level or greater, e.g. if the logger's severity
+/// is WARN, only messages logged at WARN, ERROR or FATAL will be output.
+/// 
+/// \section LoggingApiLoggerNames BIND 10 Logger Names
+/// Within BIND 10, the root logger root logger is given the name of the
+/// program (via the stand-alone function setRootLoggerName()). Other loggers
+/// are children of the root logger and are named "<program>.<sublogger>".
+/// This name appears in logging output, allowing users to identify both
+/// the BIND 10 program and the component within the program that generated
+/// the message.
+/// 
+/// When creating a logger, the abbreviated name "<sublogger>" can be used;
+/// the program name will be prepended to it when the logger is created.
+/// In this way, individual libraries can have their own loggers without
+/// worrying about the program in which they are used, but:
+/// - The origin of the message will be clearly identified.
+/// - The same component can have different options (e.g. logging severity)
+/// in different programs at the same time.
+/// 
+/// \section LoggingApiLoggingMessages Logging Messages
+/// Instead of embedding the text of messages within the code, each message
+/// is referred to using a symbolic name.  The logging code uses this name as
+/// a key in a dictionary from which the message text is obtained.  Such a
+/// system allows for the optional replacement of message text at run time.
+/// More details about the message disction (and the compiler used to create
+/// the symbol definitions) can be found in other modules in the src/lib/log
+/// directory.
 
 class LoggerImpl;   // Forward declaration of the implementation class
 
+/// \brief Logger Class
+///
+/// This class is the main class used for logging.  Use comprises:
+///
+/// 1. Constructing a logger by instantiating it with a specific name. (If the
+/// same logger is in multiple functions within a file, overhead can be
+/// minimised by declaring it as a file-wide static variable.)
+/// 2. Using the error(), info() etc. methods to log an error.  (However, it is
+/// recommended to use the LOG_ERROR, LOG_INFO etc. macros defined in macros.h.
+/// These will avoid the potentially-expensive evaluation of arguments if the
+/// severity is such that the message will be suppressed.)
+
 class Logger {
 public:
 
@@ -56,32 +95,7 @@ public:
     /// \param name Name of the logger.  If the name is that of the root name,
     /// this creates an instance of the root logger; otherwise it creates a
     /// child of the root logger.
-    ///
-    /// \param infunc This argument is present to get round a bug in some
-    /// implementations of the logging system.  If the logger is declared in
-    /// a function (such that it will be deleted when the function exits,
-    /// before the program ends), set this true.  If declared outside a
-    /// function (such that it gets deleted during program rundown), set false
-    /// (the default).\n
-    /// \n
-    /// The problems encountered was that during program rundown, one logging
-    /// implementation (log4cxx) threw a MutexException (this is described in
-    /// https://issues.apache.org/jira/browse/LOGCXX-322).  As this only occurs
-    /// during program rundown, the issue is not serious - it just looks bad to
-    /// have the program crash instead of shut down cleanly.\n
-    /// \n
-    /// If log4cxx is chosen as the implementation, this flag controls the
-    /// deletion of the underlying log4cxx data structures when the logger is
-    /// deleted.  Setting it false for externally-declared loggers inhibits
-    /// their deletion; so at program exit the memory is not reclaimed during
-    /// program rundown, only when the process is selected.  Setting it true
-    /// for loggers that will be deleted in the normal running of the program
-    /// enables their deletion - which causes no issues as the problem only
-    /// manifests itself during program rundown.
-    /// \n
-    /// The flag has no effect on non-log4cxx implementations.
-    Logger(const std::string& name, bool infunc = false) :
-        loggerptr_(NULL), name_(name), infunc_(infunc)
+    Logger(const std::string& name) : loggerptr_(NULL), name_(name)
     {}
 
     /// \brief Destructor
@@ -95,7 +109,6 @@ public:
     /// \return The full name of the logger (including the root name)
     virtual std::string getName();
 
-
     /// \brief Set Severity Level for Logger
     ///
     /// Sets the level at which this logger will log messages.  If none is set,
@@ -107,14 +120,12 @@ public:
     /// outside these limits is silently coerced to the nearest boundary.
     virtual void setSeverity(isc::log::Severity severity, int dbglevel = 1);
 
-
     /// \brief Get Severity Level for Logger
     ///
     /// \return The current logging level of this logger.  In most cases though,
     /// the effective logging level is what is required.
     virtual isc::log::Severity getSeverity();
 
-
     /// \brief Get Effective Severity Level for Logger
     ///
     /// \return The effective severity level of the logger.  This is the same
@@ -122,13 +133,18 @@ public:
     /// is the severity of the parent.
     virtual isc::log::Severity getEffectiveSeverity();
 
-
     /// \brief Return DEBUG Level
     ///
     /// \return Current setting of debug level.  This is returned regardless of
     /// whether the severity is set to debug.
     virtual int getDebugLevel();
 
+    /// \brief Get Effective Debug Level for Logger
+    ///
+    /// \return The effective debug level of the logger.  This is the same
+    /// as getDebugLevel() if the logger has a debug level set, but otherwise
+    /// is the debug level of the parent.
+    virtual int getEffectiveDebugLevel();
 
     /// \brief Returns if Debug Message Should Be Output
     ///
@@ -137,23 +153,18 @@ public:
     /// checked is less than or equal to the debug level set for the logger.
     virtual bool isDebugEnabled(int dbglevel = MIN_DEBUG_LEVEL);
 
-
     /// \brief Is INFO Enabled?
     virtual bool isInfoEnabled();
 
-
     /// \brief Is WARNING Enabled?
     virtual bool isWarnEnabled();
 
-
     /// \brief Is ERROR Enabled?
     virtual bool isErrorEnabled();
 
-
     /// \brief Is FATAL Enabled?
     virtual bool isFatalEnabled();
 
-
     /// \brief Output Debug Message
     ///
     /// \param dbglevel Debug level, ranging between 0 and 99.  Higher numbers
@@ -161,25 +172,21 @@ public:
     /// \param ident Message identification.
     Formatter debug(int dbglevel, const MessageID& ident);
 
-
     /// \brief Output Informational Message
     ///
     /// \param ident Message identification.
     Formatter info(const MessageID& ident);
 
-
     /// \brief Output Warning Message
     ///
     /// \param ident Message identification.
     Formatter warn(const MessageID& ident);
 
-
     /// \brief Output Error Message
     ///
     /// \param ident Message identification.
     Formatter error(const MessageID& ident);
 
-
     /// \brief Output Fatal Message
     ///
     /// \param ident Message identification.
@@ -188,25 +195,20 @@ public:
     /// \brief Equality
     ///
     /// Check if two instances of this logger refer to the same stream.
-    /// (This method is principally for testing.)
     ///
     /// \return true if the logger objects are instances of the same logger.
     bool operator==(Logger& other);
 
-protected:
-
-    /// \brief Reset Global Data
-    ///
-    /// Used for testing, this calls upon the underlying logger implementation
-    /// to clear any global data.
-    static void reset();
-
 private:
     friend class isc::log::Formatter<Logger>;
+
     /// \brief Raw output function
     ///
     /// This is used by the formatter to output formatted output.
-    void output(const char* sevText, const std::string& message);
+    ///
+    /// \param severity Severity of the message being output.
+    /// \param message Text of the message to be output.
+    void output(const Severity& severity, const std::string& message);
 
     /// \brief Copy Constructor
     ///
@@ -245,7 +247,6 @@ private:
 
     LoggerImpl*     loggerptr_;     ///< Pointer to the underlying logger
     std::string     name_;          ///< Copy of the logger name
-    bool            infunc_;        ///< Copy of the infunc argument
 };
 
 } // namespace log

src/lib/log/logger_impl.cc

@@ -19,38 +19,37 @@
 #include <stdarg.h>
 #include <stdio.h>
 #include <boost/lexical_cast.hpp>
+#include <boost/static_assert.hpp>
+
+#include <log4cplus/configurator.h>
 
-#include <log/debug_levels.h>
-#include <log/root_logger_name.h>
 #include <log/logger.h>
 #include <log/logger_impl.h>
+#include <log/logger_level.h>
+#include <log/logger_level_impl.h>
+#include <log/logger_name.h>
 #include <log/message_dictionary.h>
 #include <log/message_types.h>
-#include <log/root_logger_name.h>
 
 #include <util/strutil.h>
 
+// Note: as log4cplus and the BIND 10 logger have many concepts in common, and
+// thus many similar names, to disambiguate types we don't "use" the log4cplus
+// namespace: instead, all log4cplus types are explicitly qualified.
+
 using namespace std;
 
 namespace isc {
 namespace log {
 
-// Static initializations
-
-LoggerImpl::LoggerInfoMap LoggerImpl::logger_info_;
-LoggerImpl::LoggerInfo LoggerImpl::root_logger_info_(isc::log::INFO, 0);
-
-// Constructor
-LoggerImpl::LoggerImpl(const std::string& name, bool)
+// Constructor.  The setting of logger_ must be done when the variable is
+// constructed (instead of being left to the body of the function); 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) : name_(expandLoggerName(name)),
+    logger_(log4cplus::Logger::getInstance(name_))
 {
-    // Are we the root logger?
-    if (name == getRootLoggerName()) {
-        is_root_ = true;
-        name_ = name;
-    } else {
-        is_root_ = false;
-        name_ = getRootLoggerName() + "." + name;
-    }
 }
 
 // Destructor. (Here because of virtual declaration.)
@@ -59,140 +58,42 @@ LoggerImpl::~LoggerImpl() {
 }
 
 // Set the severity for logging.
-
 void
 LoggerImpl::setSeverity(isc::log::Severity severity, int dbglevel) {
-
-    // Silently coerce the debug level into the valid range of 0 to 99
-
-    int debug_level = max(MIN_DEBUG_LEVEL, min(MAX_DEBUG_LEVEL, dbglevel));
-    if (is_root_) {
-
-        // Can only set severity for the root logger, you can't disable it.
-        // Any attempt to do so is silently ignored.
-        if (severity != isc::log::DEFAULT) {
-            root_logger_info_ = LoggerInfo(severity, debug_level);
-        }
-
-    } else if (severity == isc::log::DEFAULT) {
-
-        // Want to set to default; this means removing the information
-        // about this logger from the logger_info_ if it is set.
-        LoggerInfoMap::iterator i = logger_info_.find(name_);
-        if (i != logger_info_.end()) {
-            logger_info_.erase(i);
-        }
-
-    } else {
-
-        // Want to set this information
-        logger_info_[name_] = LoggerInfo(severity, debug_level);
-    }
+    Level level(severity, dbglevel);
+    logger_.setLogLevel(LoggerLevelImpl::convertFromBindLevel(level));
 }
 
 // Return severity level
-
 isc::log::Severity
 LoggerImpl::getSeverity() {
+    Level level = LoggerLevelImpl::convertToBindLevel(logger_.getLogLevel());
+    return level.severity;
+}
 
-    if (is_root_) {
-        return (root_logger_info_.severity);
-    }
-    else {
-        LoggerInfoMap::iterator i = logger_info_.find(name_);
-        if (i != logger_info_.end()) {
-           return ((i->second).severity);
-        }
-        else {
-            return (isc::log::DEFAULT);
-        }
-    }
+// Return current debug level (only valid if current severity level is DEBUG).
+int
+LoggerImpl::getDebugLevel() {
+    Level level = LoggerLevelImpl::convertToBindLevel(logger_.getLogLevel());
+    return level.dbglevel;
 }
 
 // Get effective severity.  Either the current severity or, if not set, the
 // severity of the root level.
-
 isc::log::Severity
 LoggerImpl::getEffectiveSeverity() {
-
-    if (!is_root_ && !logger_info_.empty()) {
-
-        // Not root logger and there is at least one item in the info map for a
-        // logger.
-        LoggerInfoMap::iterator i = logger_info_.find(name_);
-        if (i != logger_info_.end()) {
-
-            // Found, so return the severity.
-            return ((i->second).severity);
-        }
-    }
-
-    // Must be the root logger, or this logger is defaulting to the root logger
-    // settings.
-    return (root_logger_info_.severity);
+    Level level = LoggerLevelImpl::convertToBindLevel(logger_.getChainedLogLevel());
+    return level.severity;
 }
 
-// Get the debug level.  This returns 0 unless the severity is DEBUG.
-
+// Return effective debug level (only valid if current effective severity level
+// is DEBUG).
 int
-LoggerImpl::getDebugLevel() {
-
-    if (!is_root_ && !logger_info_.empty()) {
-
-        // Not root logger and there is something in the map, check if there
-        // is a setting for this one.
-        LoggerInfoMap::iterator i = logger_info_.find(name_);
-        if (i != logger_info_.end()) {
-
-            // Found, so return the debug level.
-            if ((i->second).severity == isc::log::DEBUG) {
-                return ((i->second).dbglevel);
-            } else {
-                return (0);
-            }
-        }
-    }
-
-    // Must be the root logger, or this logger is defaulting to the root logger
-    // settings.
-    if (root_logger_info_.severity == isc::log::DEBUG) {
-        return (root_logger_info_.dbglevel);
-    } else {
-        return (0);
-    }
+LoggerImpl::getEffectiveDebugLevel() {
+    Level level = LoggerLevelImpl::convertToBindLevel(logger_.getChainedLogLevel());
+    return level.dbglevel;
 }
 
-// The code for isXxxEnabled is quite simple and is in the header.  The only
-// exception is isDebugEnabled() where we have the complication of the debug
-// levels.
-
-bool
-LoggerImpl::isDebugEnabled(int dbglevel) {
-
-    if (!is_root_ && !logger_info_.empty()) {
-
-        // Not root logger and there is something in the map, check if there
-        // is a setting for this one.
-        LoggerInfoMap::iterator i = logger_info_.find(name_);
-        if (i != logger_info_.end()) {
-
-            // Found, so return the debug level.
-            if ((i->second).severity <= isc::log::DEBUG) {
-                return ((i->second).dbglevel >= dbglevel);
-            } else {
-                return (false); // Nothing lower than debug
-            }
-        }
-    }
-
-    // Must be the root logger, or this logger is defaulting to the root logger
-    // settings.
-    if (root_logger_info_.severity <= isc::log::DEBUG) {
-        return (root_logger_info_.dbglevel >= dbglevel);
-    } else {
-       return (false);
-    }
-}
 
 // Output a general message
 string*
@@ -202,18 +103,27 @@ LoggerImpl::lookupMessage(const MessageID& ident) {
 }
 
 void
-LoggerImpl::outputRaw(const char* sevText, const string& message) {
-    // Get the time in a struct tm format, and convert to text
-    time_t t_time;
-    time(&t_time);
-    struct tm* tm_time = localtime(&t_time);
-
-    char chr_time[32];
-    (void) strftime(chr_time, sizeof(chr_time), "%Y-%m-%d %H:%M:%S", tm_time);
-
-    // Now output.
-    cout << chr_time << " " << sevText << " [" << getName() << "] " <<
-        message << endl;
+LoggerImpl::outputRaw(const Severity& severity, const string& message) {
+    switch (severity) {
+        case DEBUG:
+            LOG4CPLUS_DEBUG(logger_, message);
+            break;
+
+        case INFO:
+            LOG4CPLUS_INFO(logger_, message);
+            break;
+
+        case WARN:
+            LOG4CPLUS_WARN(logger_, message);
+            break;
+
+        case ERROR:
+            LOG4CPLUS_ERROR(logger_, message);
+            break;
+
+        case FATAL:
+            LOG4CPLUS_FATAL(logger_, message);
+    }
 }
 
 } // namespace log

src/lib/log/logger_impl.h

@@ -18,15 +18,19 @@
 #include <stdarg.h>
 #include <time.h>
 
+#include <iostream>
 #include <cstdlib>
 #include <string>
 #include <map>
 #include <utility>
 
-#include <log/debug_levels.h>
-#include <log/logger.h>
+
+// log4cplus logger header file
+#include <log4cplus/logger.h>
+
+// BIND-10 logger files
+#include <log/logger_level_impl.h>
 #include <log/message_types.h>
-#include <log/root_logger_name.h>
 
 namespace isc {
 namespace log {
@@ -35,46 +39,36 @@ namespace log {
 ///
 /// The logger uses a "pimpl" idiom for implementation, where the base logger
 /// class contains little more than a pointer to the implementation class, and
-/// all actions are carried out by the latter.  This class is an implementation
-/// class that just outputs to stdout.
+/// all actions are carried out by the latter.
+///
+/// This particular implementation is based on log4cplus (from sourceforge:
+/// http://log4cplus.sourceforge.net).  Particular items of note:
+///
+/// a) BIND 10 loggers have names of the form "program.sublogger".  In other
+/// words, each of the loggers is a sub-logger of the main program logger.
+/// In log4cplus, there is a root logger (called "root" according to the
+/// documentation, but actually unnamed) and all loggers created are subloggers
+/// if it.
+///
+/// In this implementation, the log4cplus root logger is unused.  Instead, the
+/// BIND 10 root logger is created as a child of the log4cplus root logger,
+/// and all other loggers used in the program are created as sub-loggers of
+/// that.  In this way, the logging system can just include the name of the
+/// logger in each message without the need to specially consider if the
+/// message is the root logger or not.
+///
+/// b) The idea of debug levels is implemented.  See logger_level.h and
+/// logger_level_impl.h for more details on this.
 
 class LoggerImpl {
 public:
 
-    /// \brief Information About Logger
-    ///
-    /// Holds a information about a logger, namely its severity and its debug
-    /// level.  This could be a std::pair, except that it gets confusing when
-    /// accessing the LoggerInfoMap: that returns a pair, so we to reference
-    /// elements we would use constructs like ((i->first).second);
-    struct LoggerInfo {
-        isc::log::Severity  severity;
-        int                 dbglevel;
-
-        LoggerInfo(isc::log::Severity sev = isc::log::INFO,
-            int dbg = MIN_DEBUG_LEVEL) : severity(sev), dbglevel(dbg)
-        {}
-    };
-
-
-    /// \brief Information About All Loggers
-    ///
-    /// Information about all loggers in the system - except the root logger -
-    /// is held in a map, linking name of the logger (excluding the root
-    /// name component) and its set severity and debug levels.  The root
-    /// logger information is held separately.
-    typedef std::map<std::string, LoggerInfo>   LoggerInfoMap;
-
-
     /// \brief Constructor
     ///
     /// Creates a logger of the specific name.
     ///
     /// \param name Name of the logger.
-    ///
-    /// \param exit_delete This argument is present to get round a bug in
-    /// the log4cxx implementation.  It is unused here.
-    LoggerImpl(const std::string& name, bool);
+    LoggerImpl(const std::string& name);
 
 
     /// \brief Destructor
@@ -94,16 +88,16 @@ public:
     ///
     /// \param severity Severity level to log
     /// \param dbglevel If the severity is DEBUG, this is the debug level.
-    /// This can be in the range 1 to 100 and controls the verbosity.  A value
+    /// This can be in the range 0 to 99 and controls the verbosity.  A value
     /// outside these limits is silently coerced to the nearest boundary.
-    virtual void setSeverity(isc::log::Severity severity, int dbglevel = 1);
+    virtual void setSeverity(Severity severity, int dbglevel = 1);
 
 
     /// \brief Get Severity Level for Logger
     ///
     /// \return The current logging level of this logger.  In most cases though,
     /// the effective logging level is what is required.
-    virtual isc::log::Severity getSeverity();
+    virtual Severity getSeverity();
 
 
     /// \brief Get Effective Severity Level for Logger
@@ -111,67 +105,62 @@ public:
     /// \return The effective severity level of the logger.  This is the same
     /// as getSeverity() if the logger has a severity level set, but otherwise
     /// is the severity of the parent.
-    virtual isc::log::Severity getEffectiveSeverity();
+    virtual Severity getEffectiveSeverity();
 
 
-    /// \brief Return DEBUG Level
+    /// \brief Return debug level
     ///
-    /// \return Current setting of debug level.  This is returned regardless of
-    /// whether the
+    /// \return Current setting of debug level.  This will be zero if the
+    ///         the current severity level is not DEBUG.
     virtual int getDebugLevel();
 
 
+    /// \brief Return effective debug level
+    ///
+    /// \return Current setting of effective debug level.  This will be zero if
+    ///         the current effective severity level is not DEBUG.
+    virtual int getEffectiveDebugLevel();
+
+
     /// \brief Returns if Debug Message Should Be Output
     ///
     /// \param dbglevel Level for which debugging is checked.  Debugging is
     /// enabled only if the logger has DEBUG enabled and if the dbglevel
     /// checked is less than or equal to the debug level set for the logger.
-    virtual bool
-    isDebugEnabled(int dbglevel = MIN_DEBUG_LEVEL);
+    virtual bool isDebugEnabled(int dbglevel = MIN_DEBUG_LEVEL) {
+        Level level(DEBUG, dbglevel);
+        return logger_.isEnabledFor(LoggerLevelImpl::convertFromBindLevel(level));
+    }
 
     /// \brief Is INFO Enabled?
     virtual bool isInfoEnabled() {
-        return (isEnabled(isc::log::INFO));
+        return (logger_.isEnabledFor(log4cplus::INFO_LOG_LEVEL));
     }
 
     /// \brief Is WARNING Enabled?
     virtual bool isWarnEnabled() {
-        return (isEnabled(isc::log::WARN));
+        return (logger_.isEnabledFor(log4cplus::WARN_LOG_LEVEL));
     }
 
     /// \brief Is ERROR Enabled?
     virtual bool isErrorEnabled() {
-        return (isEnabled(isc::log::ERROR));
+        return (logger_.isEnabledFor(log4cplus::ERROR_LOG_LEVEL));
     }
 
     /// \brief Is FATAL Enabled?
     virtual bool isFatalEnabled() {
-        return (isEnabled(isc::log::FATAL));
-    }
-
-
-    /// \brief Common Severity check
-    ///
-    /// Implements the common severity check.  As an optimisation, this checks
-    /// to see if any logger-specific levels have been set (a quick check as it
-    /// just involves seeing if the collection of logger information is empty).
-    /// if not, it returns the information for the root level; if so, it has
-    /// to take longer and look up the information in the map holding the
-    /// logging details.
-    virtual bool isEnabled(isc::log::Severity severity) {
-        if (logger_info_.empty()) {
-            return (root_logger_info_.severity <= severity);
-        }
-        else {
-            return (getSeverity() <= severity);
-        }
+        return (logger_.isEnabledFor(log4cplus::FATAL_LOG_LEVEL));
     }
 
     /// \brief Raw output
     ///
     /// Writes the message with time into the log. Used by the Formatter
     /// to produce output.
-    void outputRaw(const char* sev_text, const std::string& message);
+    ///
+    /// \param severity Severity of the message. (This controls the prefix
+    ///        label output with the message text.)
+    /// \param message Text of the message.
+    void outputRaw(const Severity& severity, const std::string& message);
 
     /// \brief Look up message text in dictionary
     ///
@@ -188,28 +177,9 @@ public:
         return (name_ == other.name_);
     }
 
-
-    /// \brief Reset Global Data
-    ///
-    /// Only used for testing, this clears all the logger information and
-    /// resets it back to default values.
-    static void reset() {
-        root_logger_info_ = LoggerInfo(isc::log::INFO, MIN_DEBUG_LEVEL);
-        logger_info_.clear();
-    }
-
-
 private:
-    bool                is_root_;           ///< true if a root logger
-    std::string         name_;              ///< Name of this logger
-
-    // Split the status of the root logger from this logger.  If - is will
-    // probably be the usual case - no per-logger setting is enabled, a
-    // quick check of logger_info_.empty() will return true and we can quickly
-    // return the root logger status without a length lookup in the map.
-
-    static LoggerInfo       root_logger_info_;  ///< Status of root logger
-    static LoggerInfoMap    logger_info_;       ///< Store of debug levels etc.
+    std::string         name_;              ///< Full name of this logger
+    log4cplus::Logger   logger_;            ///< Underlying log4cplus logger
 };
 
 } // namespace log

src/lib/log/logger_impl_log4cxx.cc

@@ -1,242 +0,0 @@
-// Copyright (C) 2011  Internet Systems Consortium, Inc. ("ISC")
-//
-// Permission to use, copy, modify, and/or distribute this software for any
-// purpose with or without fee is hereby granted, provided that the above
-// copyright notice and this permission notice appear in all copies.
-//
-// THE SOFTWARE IS PROVIDED "AS IS" AND ISC DISCLAIMS ALL WARRANTIES WITH
-// REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY
-// AND FITNESS.  IN NO EVENT SHALL ISC BE LIABLE FOR ANY SPECIAL, DIRECT,
-// INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER RESULTING FROM
-// LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF CONTRACT, NEGLIGENCE
-// OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
-// PERFORMANCE OF THIS SOFTWARE
-
-#include <iostream>
-
-#include <stdarg.h>
-#include <stdio.h>
-
-#include <log4cxx/appender.h>
-#include <log4cxx/basicconfigurator.h>
-#include <log4cxx/patternlayout.h>
-#include <log4cxx/consoleappender.h>
-
-#include <log/root_logger_name.h>
-#include <log/logger.h>
-#include <log/logger_impl.h>
-#include <log/message_dictionary.h>
-#include <log/message_types.h>
-#include <log/xdebuglevel.h>
-
-#include <util/strutil.h>
-
-using namespace std;
-
-namespace isc {
-namespace log {
-
-// Static initializations
-
-bool LoggerImpl::init_ = false;
-
-// Destructor.  Delete log4cxx stuff if "don't delete" is clear.
-
-LoggerImpl::~LoggerImpl() {
-    if (exit_delete_) {
-        delete loggerptr_;
-    }
-}
-
-// Initialize logger - create a logger as a child of the root logger.  With
-// log4cxx this is assured by naming the logger <parent>.<child>.
-
-void
-LoggerImpl::initLogger() {
-
-    // Initialize basic logging if not already done.  This is a one-off for
-    // all loggers.
-    if (!init_) {
-
-        // TEMPORARY
-        // Add a suitable console logger to the log4cxx root logger.  (This
-        // is the logger at the root of the log4cxx tree, not the BIND-10 root
-        // logger, which is one level down.)  The chosen format is:
-        //
-        // YYYY-MM-DD hh:mm:ss.sss [logger] SEVERITY: text
-        //
-        // As noted, this is a temporary hack: it is done here to ensure that
-        // a suitable output and output pattern is set.  Future versions of the
-        // software will set this based on configuration data.
-
-        log4cxx::LayoutPtr layout(
-            new log4cxx::PatternLayout(
-                "%d{yyyy-MM-DD HH:mm:ss.SSS} %-5p [%c] %m\n"));
-        log4cxx::AppenderPtr console(
-            new log4cxx::ConsoleAppender(layout));
-        log4cxx::LoggerPtr sys_root_logger = log4cxx::Logger::getRootLogger();
-        sys_root_logger->addAppender(console);
-
-        // Set the default logging to INFO
-        sys_root_logger->setLevel(log4cxx::Level::getInfo());
-
-        // All static stuff initialized
-        init_ = true;
-    }
-
-    // Initialize this logger.  Name this as to whether the BIND-10 root logger
-    // name has been set.  (If not, this mucks up the hierarchy :-( ).
-    string root_name = RootLoggerName::getName();
-    if (root_name.empty() || (name_ == root_name)) {
-        loggerptr_ = new log4cxx::LoggerPtr(log4cxx::Logger::getLogger(name_));
-    }
-    else {
-        loggerptr_ = new log4cxx::LoggerPtr(
-            log4cxx::Logger::getLogger(root_name + "." + name_)
-        );
-    }
-}
-
-
-// Set the severity for logging.  There is a 1:1 mapping between the logging
-// severity and the log4cxx logging levels, apart from DEBUG.
-//
-// In log4cxx, each of the logging levels (DEBUG, INFO, WARN etc.) has a numeric
-// value.  The level is set to one of these and any numeric level equal to or
-// above it that is reported.  For example INFO has a value of 20000 and ERROR
-// a value of 40000. So if a message of WARN severity (= 30000) is logged, it is
-// not logged when the logger's severity level is ERROR (as 30000 !>= 40000).
-// It is reported if the logger's severity level is set to WARN (as 30000 >=
-/// 30000) or INFO (30000 >= 20000).
-//
-// This gives a simple system for handling different debug levels.  The debug
-// level is a number between 0 and 99, with 0 being least verbose and 99 the
-// most.  To implement this seamlessly, when DEBUG is set, the numeric value
-// of the logging level is actually set to (DEBUG - debug-level).  Similarly
-// messages of level "n" are logged at a logging level of (DEBUG - n).  Thus if
-// the logging level is set to DEBUG and the debug level set to 25, the actual
-// level set is 10000 - 25 = 99975.
-//
-// Attempting to log a debug message of level 26 is an attempt to log a message
-// of level 10000 - 26 = 9974.  As 9974 !>= 9975, it is not logged.  A
-// message of level 25 is, because 9975 >= 9975.
-//
-// The extended set of logging levels is implemented by the XDebugLevel class.
-
-void
-LoggerImpl::setSeverity(isc::log::Severity severity, int dbglevel) {
-    switch (severity) {
-        case NONE:
-            getLogger()->setLevel(log4cxx::Level::getOff());
-            break;
-
-        case FATAL:
-            getLogger()->setLevel(log4cxx::Level::getFatal());
-            break;
-
-        case ERROR:
-            getLogger()->setLevel(log4cxx::Level::getError());
-            break;
-
-        case WARN:
-            getLogger()->setLevel(log4cxx::Level::getWarn());
-            break;
-
-        case INFO:
-            getLogger()->setLevel(log4cxx::Level::getInfo());
-            break;
-
-        case DEBUG:
-            getLogger()->setLevel(
-                log4cxx::XDebugLevel::getExtendedDebug(dbglevel));
-            break;
-
-        // Will get here for DEFAULT or any other value.  This disables the
-        // logger's own severity and it defaults to the severity of the parent
-        // logger.
-        default:
-            getLogger()->setLevel(0);
-    }
-}
-
-// Convert between numeric log4cxx logging level and BIND-10 logging severity.
-
-isc::log::Severity
-LoggerImpl::convertLevel(int value) {
-
-    // The order is optimised.  This is only likely to be called when testing
-    // for writing debug messages, so the check for DEBUG_INT is first.
-    if (value <= log4cxx::Level::DEBUG_INT) {
-        return (DEBUG);
-    } else if (value <= log4cxx::Level::INFO_INT) {
-        return (INFO);
-    } else if (value <= log4cxx::Level::WARN_INT) {
-        return (WARN);
-    } else if (value <= log4cxx::Level::ERROR_INT) {
-        return (ERROR);
-    } else if (value <= log4cxx::Level::FATAL_INT) {
-        return (FATAL);
-    } else {
-        return (NONE);
-    }
-}
-
-
-// Return the logging severity associated with this logger.
-
-isc::log::Severity
-LoggerImpl::getSeverityCommon(const log4cxx::LoggerPtr& ptrlogger,
-    bool check_parent) {
-
-    log4cxx::LevelPtr level = ptrlogger->getLevel();
-    if (level == log4cxx::LevelPtr()) {
-
-        // Null level returned, logging should be that of the parent.
-
-        if (check_parent) {
-            log4cxx::LoggerPtr parent = ptrlogger->getParent();
-            if (parent == log4cxx::LoggerPtr()) {
-
-                // No parent, so reached the end of the chain.  Return INFO
-                // severity.
-                return (INFO);
-            }
-            else {
-                return (getSeverityCommon(parent, check_parent));
-            }
-        }
-        else {
-            return (DEFAULT);
-        }
-    } else {
-        return (convertLevel(level->toInt()));
-    }
-}
-
-
-// Get the debug level.  This returns 0 unless the severity is DEBUG.
-
-int
-LoggerImpl::getDebugLevel() {
-
-    log4cxx::LevelPtr level = getLogger()->getLevel();
-    if (level == log4cxx::LevelPtr()) {
-
-        // Null pointer returned, logging should be that of the parent.
-        return (0);
-
-    } else {
-        int severity = level->toInt();
-        if (severity <= log4cxx::Level::DEBUG_INT) {
-            return (log4cxx::Level::DEBUG_INT - severity);
-        }
-        else {
-            return (0);
-        }
-    }
-}
-
-
-
-} // namespace log
-} // namespace isc

src/lib/log/logger_impl_log4cxx.h

@@ -1,315 +0,0 @@
-// 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 __LOGGER_IMPL_LOG4CXX_H
-#define __LOGGER_IMPL_LOG4CXX_H
-
-#include <cstdlib>
-#include <string>
-#include <boost/lexical_cast.hpp>
-#include <log4cxx/logger.h>
-#include <log4cxx/logger.h>
-
-#include <log/debug_levels.h>
-#include <log/logger.h>
-#include <log/message_types.h>
-
-namespace isc {
-namespace log {
-
-/// \brief Log4cxx Logger Implementation
-///
-/// The logger uses a "pimpl" idiom for implementation, where the base logger
-/// class contains little more than a pointer to the implementation class, and
-/// all actions are carried out by the latter.  This class is an implementation
-/// class interfacing to the log4cxx logging system.
-
-class LoggerImpl {
-public:
-
-    /// \brief Constructor
-    ///
-    /// Creates/attaches to a logger of a specific name.
-    ///
-    /// \param name Name of the logger.  If the name is that of the root name,
-    /// this creates an instance of the root logger; otherwise it creates a
-    /// child of the root logger.
-    ///
-    /// \param exit_delete This argument is present to get round a bug in
-    /// log4cxx.  If a log4cxx logger is declared outside an execution unit, it
-    /// is not deleted until the program runs down.  At that point all such
-    /// objects - including internal log4cxx objects - are deleted.  However,
-    /// there seems to be a bug in log4cxx where the way that such objects are
-    /// destroyed causes a MutexException to be thrown (this is described in
-    /// https://issues.apache.org/jira/browse/LOGCXX-322).  As this only occurs
-    /// during program rundown, the issue is not serious - it just looks bad to
-    /// have the program crash instead of shut down cleanly.\n
-    /// \n
-    /// The original implementation of the isc::log::Logger had as a member a
-    /// log4cxx logger (actually a LoggerPtr).  If the isc:: Logger was declared
-    /// statically, when it was destroyed at the end of the program the internal
-    /// LoggerPtr was destroyed, which triggered the problem.  The problem did
-    /// not occur if the isc::log::Logger was created on the stack.  To get
-    /// round this, the internal LoggerPtr is now created dynamically.  The
-    /// exit_delete argument controls its destruction: if true, it is destroyed
-    /// in the ISC Logger destructor.  If false, it is not.\n
-    /// \n
-    /// When creating an isc::log::Logger on the stack, the argument should be
-    /// false (the default); when the Logger is destroyed, all the internal
-    /// log4cxx objects are destroyed.  As only the logger (and not the internal
-    /// log4cxx data structures are being destroyed), all is well.  However,
-    /// when creating the logger statically, the argument should be false.  This
-    /// means that the log4cxx objects are not destroyed at program rundown;
-    /// instead memory is reclaimed and files are closed when the process is
-    /// destroyed, something that does not trigger the bug.
-    LoggerImpl(const std::string& name, bool exit_delete = false) :
-        loggerptr_(NULL), name_(name), exit_delete_(exit_delete)
-    {}
-
-
-    /// \brief Destructor
-    virtual ~LoggerImpl();
-
-
-    /// \brief Get the full name of the logger (including the root name)
-    virtual std::string getName() {
-        return (getLogger()->getName());
-    }
-
-
-    /// \brief Set Severity Level for Logger
-    ///
-    /// Sets the level at which this logger will log messages.  If none is set,
-    /// the level is inherited from the parent.
-    ///
-    /// \param severity Severity level to log
-    /// \param dbglevel If the severity is DEBUG, this is the debug level.
-    /// This can be in the range 1 to 100 and controls the verbosity.  A value
-    /// outside these limits is silently coerced to the nearest boundary.
-    virtual void setSeverity(isc::log::Severity severity, int dbglevel = 1);
-
-
-    /// \brief Get Severity Level for Logger
-    ///
-    /// \return The current logging level of this logger.  In most cases though,
-    /// the effective logging level is what is required.
-    virtual isc::log::Severity getSeverity() {
-        return (getSeverityCommon(getLogger(), false));
-    }
-
-
-    /// \brief Get Effective Severity Level for Logger
-    ///
-    /// \return The effective severity level of the logger.  This is the same
-    /// as getSeverity() if the logger has a severity level set, but otherwise
-    /// is the severity of the parent.
-    virtual isc::log::Severity getEffectiveSeverity() {
-        return (getSeverityCommon(getLogger(), true));
-    }
-
-
-    /// \brief Return DEBUG Level
-    ///
-    /// \return Current setting of debug level.  This is returned regardless of
-    /// whether the
-    virtual int getDebugLevel();
-
-
-    /// \brief Returns if Debug Message Should Be Output
-    ///
-    /// \param dbglevel Level for which debugging is checked.  Debugging is
-    /// enabled only if the logger has DEBUG enabled and if the dbglevel
-    /// checked is less than or equal to the debug level set for the logger.
-    virtual bool
-    isDebugEnabled(int dbglevel = MIN_DEBUG_LEVEL) {
-        return (getLogger()->getEffectiveLevel()->toInt() <=
-            (log4cxx::Level::DEBUG_INT - dbglevel));
-    }
-
-
-    /// \brief Is INFO Enabled?
-    virtual bool isInfoEnabled() {
-        return (getLogger()->isInfoEnabled());
-    }
-
-
-    /// \brief Is WARNING Enabled?
-    virtual bool isWarnEnabled() {
-        return (getLogger()->isWarnEnabled());
-    }
-
-
-    /// \brief Is ERROR Enabled?
-    virtual bool isErrorEnabled() {
-        return (getLogger()->isErrorEnabled());
-    }
-
-
-    /// \brief Is FATAL Enabled?
-    virtual bool isFatalEnabled() {
-        return (getLogger()->isFatalEnabled());
-    }
-
-
-    /// \brief Output Debug Message
-    ///
-    /// \param ident Message identification.
-    /// \param text Text to log
-    void debug(const MessageID& ident, const char* text) {
-        LOG4CXX_DEBUG(getLogger(), ident << ", " << text);
-    }
-
-
-    /// \brief Output Informational Message
-    ///
-    /// \param ident Message identification.
-    /// \param text Text to log
-    void info(const MessageID& ident, const char* text) {
-        LOG4CXX_INFO(getLogger(), ident << ", " << text);
-    }
-
-
-    /// \brief Output Warning Message
-    ///
-    /// \param ident Message identification.
-    /// \param text Text to log
-    void warn(const MessageID& ident, const char* text) {
-        LOG4CXX_WARN(getLogger(), ident << ", " << text);
-    }
-
-
-    /// \brief Output Error Message
-    ///
-    /// \param ident Message identification.
-    /// \param text Text to log
-    void error(const MessageID& ident, const char* text) {
-        LOG4CXX_ERROR(getLogger(), ident << ", " << text);
-    }
-
-
-    /// \brief Output Fatal Message
-    ///
-    /// \param ident Message identification.
-    /// \param text Text to log
-    void fatal(const MessageID& ident, const char* text) {
-        LOG4CXX_FATAL(getLogger(), ident << ", " << text);
-    }
-
-    //@{
-    /// \brief Testing Methods
-    ///
-    /// The next set of methods are used in testing.  As they are accessed from
-    /// the main logger class, they must be public.
-
-    /// \brief Equality
-    ///
-    /// Check if two instances of this logger refer to the same stream.
-    /// (This method is principally for testing.)
-    ///
-    /// \return true if the logger objects are instances of the same logger.
-    bool operator==(LoggerImpl& other) {
-        return (*loggerptr_ == *other.loggerptr_);
-    }
-
-
-    /// \brief Logger Initialized
-    ///
-    /// Check that the logger has been properly initialized.  (This method
-    /// is principally for testing.)
-    ///
-    /// \return true if this logger object has been initialized.
-    bool isInitialized() {
-        return (loggerptr_ != NULL);
-    }
-
-    /// \brief Reset Global Data
-    ///
-    /// Only used for testing, this clears all the logger information and
-    /// resets it back to default values.  This is a no-op for log4cxx.
-    static void reset() {
-    }
-
-    //@}
-
-protected:
-
-    /// \brief Convert Between BIND-10 and log4cxx Logging Levels
-    ///
-    /// This method is marked protected to allow for unit testing.
-    ///
-    /// \param value log4cxx numeric logging level
-    ///
-    /// \return BIND-10 logging severity
-    isc::log::Severity convertLevel(int value);
-
-private:
-
-    /// \brief Get Severity Level for Logger
-    ///
-    /// This is common code for getSeverity() and getEffectiveSeverity() -
-    /// it returns the severity of the logger; if not set (and the check_parent)
-    /// flag is set, it searches up the parent-child tree until a severity
-    /// level is found and uses that.
-    ///
-    /// \param ptrlogger Pointer to the log4cxx logger to check.
-    /// \param check_parent true to search up the tree, false to return the
-    /// current level.
-    ///
-    /// \return The effective severity level of the logger.  This is the same
-    /// as getSeverity() if the logger has a severity level set, but otherwise
-    /// is the severity of the parent.
-    isc::log::Severity getSeverityCommon(const log4cxx::LoggerPtr& ptrlogger,
-        bool check_parent);
-
-
-
-    /// \brief Initialize log4cxx Logger
-    ///
-    /// Creates the log4cxx logger used internally.  A function is provided for
-    /// this so that the creation does not take place when this Logger object
-    /// is created but when it is used.  As the latter occurs in executable
-    /// code but the former can occur during initialization, this order
-    /// guarantees that anything that is statically initialized has completed
-    /// its initialization by the time the logger is used.
-    void initLogger();
-
-
-    /// \brief Return underlying log4cxx logger, initializing it if necessary
-    ///
-    /// \return Loggerptr object
-    log4cxx::LoggerPtr& getLogger() {
-        if (loggerptr_ == NULL) {
-            initLogger();
-        }
-        return (*loggerptr_);
-    }
-
-    // Members.  Note that loggerptr_ is a pointer to a LoggerPtr, which is
-    // itself a pointer to the underlying log4cxx logger.  This is due to the
-    // problems with memory deletion on program exit, explained in the comments
-    // for the "exit_delete" parameter in this class's constructor.
-
-    log4cxx::LoggerPtr*  loggerptr_;    ///< Pointer to the underlying logger
-    std::string          name_;         ///< Name of this logger]
-    bool                 exit_delete_;  ///< Delete loggerptr_ on exit?
-
-    // NOTE - THIS IS A PLACE HOLDER
-    static bool         init_;      ///< Set true when initialized
-};
-
-} // namespace log
-} // namespace isc
-
-
-#endif // __LOGGER_IMPL_LOG4CXX_H