Merge branch 'master' into trac1024

ChangeLog

@@ -1,3 +1,23 @@
+268.	[func]		stephen
+	Add environment variable to allow redirection of logging output during
+	unit tests.
+	(Trac #1071, git 05164f9d61006869233b498d248486b4307ea8b6)
+
+267.	[func]		tomek
+	Added a dummy module for DHCP6. This module does not actually
+	do anything at this point, and BIND 10 has no option for
+	starting it yet. It is included as a base for further
+	development.
+	(Trac #990, git 4a590df96a1b1d373e87f1f56edaceccb95f267d)
+
+266.	[func]		Multiple developers
+        Convert various error messages, debugging and other output
+        to the new logging interface, including for b10-resolver,
+        the resolver library, the CC library, b10-auth, b10-cfgmgr,
+        b10-xfrin, and b10-xfrout. This includes a lot of new
+        documentation describing the new log messages.
+        (Trac #738, #739, #742, #746, #759, #761, #762)
+
 265.	[func]*		jinmei
 	b10-resolver: Introduced ACL on incoming queries.  By default the
 	resolver accepts queries from ::1 and 127.0.0.1 and rejects all
@@ -52,7 +72,7 @@
 	Now builds and runs with Python 3.2
 	(Trac #710, git dae1d2e24f993e1eef9ab429326652f40a006dfb)
 
-257.	[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.
@@ -61,25 +81,25 @@
 256.	[bug]		jerry
 	src/bin/xfrin: update xfrin to check TSIG before other part of
 	incoming message.
-	(Trac955, git 261450e93af0b0406178e9ef121f81e721e0855c)
+	(Trac #955, 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)
+	(Trac #639, git 4f714bac4547d0a025afd314c309ca5cb603e212)
 
 254.	[bug]		jinmei
 	b10-xfrout: failed to send notifies over IPv6 correctly.
-	(Trac964, git 3255c92714737bb461fb67012376788530f16e40)
+	(Trac #964, git 3255c92714737bb461fb67012376788530f16e40)
 
-253.    [func]		jelte
+253.	[func]		jelte
 	Add configuration options for logging through the virtual module
 	Logging.
-	(Trac 736, git 9fa2a95177265905408c51d13c96e752b14a0824)
+	(Trac #736, git 9fa2a95177265905408c51d13c96e752b14a0824)
 
-252.    [func]      	stephen
+252.	[func]		stephen
 	Add syslog as destination for logging.
-	(Trac976, git 31a30f5485859fd3df2839fc309d836e3206546e)
+	(Trac #976, git 31a30f5485859fd3df2839fc309d836e3206546e)
 
 251.	[bug]*		jinmei
 	Make sure bindctl private files are non readable to anyone except
@@ -88,38 +108,38 @@
 	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)
+	(Trac #870, git 461fc3cb6ebabc9f3fa5213749956467a14ebfd4)
 
-250.    [bug]           ocean
+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)
+	(Trac #838, git 83e33ec80c0c6485d8b116b13045b3488071770f)
 
-249.    [func]      	jerry
+249.	[func]		jerry
 	xfrout: add support for TSIG verification.
-	(Trac816, git 3b2040e2af2f8139c1c319a2cbc429035d93f217)
+	(Trac #816, git 3b2040e2af2f8139c1c319a2cbc429035d93f217)
 
-248.    [func]      	stephen
+248.	[func]		stephen
 	Add file and stderr as destinations for logging.
-	(Trac555, git 38b3546867425bd64dbc5920111a843a3330646b)
+	(Trac #555, git 38b3546867425bd64dbc5920111a843a3330646b)
 
-247.    [func]      	jelte
+247.	[func]		jelte
 	Upstream queries from the resolver now set EDNS0 buffer size.
-	(Trac834, git 48e10c2530fe52c9bde6197db07674a851aa0f5d)
+	(Trac #834, git 48e10c2530fe52c9bde6197db07674a851aa0f5d)
 
-246.    [func]      	stephen
+246.	[func]		stephen
 	Implement logging using log4cplus (http://log4cplus.sourceforge.net)
-	(Trac899, git 31d3f525dc01638aecae460cb4bc2040c9e4df10)
+	(Trac #899, git 31d3f525dc01638aecae460cb4bc2040c9e4df10)
 
-245.    [func]      	vorner
+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)
+	(Trac #875, git fe5e7003544e4e8f18efa7b466a65f336d8c8e4d)
 
-244.	[func] 		stephen
+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
@@ -129,7 +149,7 @@
 
 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
 
@@ -176,7 +196,7 @@ bind10-devel-20110519 released on May 19, 2011
 	stats module and stats-httpd module, and maybe with other
 	statistical modules in future. "stats.spec" has own configuration
 	and commands of stats module, if it requires.
-	(Trac#719, git a234b20dc6617392deb8a1e00eb0eed0ff353c0a)
+	(Trac #719, git a234b20dc6617392deb8a1e00eb0eed0ff353c0a)
 
 236.	[func]		jelte
 	C++ client side of configuration now uses BIND10 logging system.
@@ -219,13 +239,13 @@ bind10-devel-20110519 released on May 19, 2011
 	instead of '%s,%d', which allows us to cope better with
 	mismatched placeholders and allows reordering of them in
 	case of translation.
-	(Trac901, git 4903410e45670b30d7283f5d69dc28c2069237d6)
+	(Trac #901, git 4903410e45670b30d7283f5d69dc28c2069237d6)
 
 230.	[bug]		naokikambe
 	Removed too repeated verbose messages in two cases of:
 	 - when auth sends statistics data to stats
 	 - when stats receives statistics data from other modules
-	(Trac#620, git 0ecb807011196eac01f281d40bc7c9d44565b364)
+	(Trac #620, git 0ecb807011196eac01f281d40bc7c9d44565b364)
 
 229.	[doc]		jreed
 	Add manual page for b10-host.

configure.ac

@@ -920,6 +920,7 @@ AC_OUTPUT([doc/version.ent
            src/lib/cc/tests/session_unittests_config.h
            src/lib/log/tests/console_test.sh
            src/lib/log/tests/destination_test.sh
+           src/lib/log/tests/init_logger_test.sh
            src/lib/log/tests/local_file_test.sh
            src/lib/log/tests/severity_test.sh
            src/lib/log/tests/tempdir.h
@@ -949,9 +950,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/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/init_logger_test.sh
+           chmod +x src/lib/log/tests/local_file_test.sh
            chmod +x src/lib/log/tests/severity_test.sh
            chmod +x src/lib/util/python/mkpywrapper.py
            chmod +x src/lib/python/isc/log/tests/log_console.py

doc/guide/bind10-guide.xml

@@ -5,6 +5,23 @@
 <!ENTITY % version SYSTEM "version.ent">
 %version;
 ]>
+
+<!--
+ - Copyright (C) 2010-2011  Internet Systems Consortium, Inc. ("ISC")
+ -
+ - Permission to use, copy, modify, and/or distribute this software for any
+ - purpose with or without fee is hereby granted, provided that the above
+ - 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.
+-->
+
 <book>
   <?xml-stylesheet href="bind10-guide.css" type="text/css"?>
 

src/bin/auth/tests/command_unittest.cc

@@ -48,9 +48,9 @@ using namespace isc::datasrc;
 using namespace isc::config;
 
 namespace {
-class AuthConmmandTest : public ::testing::Test {
+class AuthCommandTest : public ::testing::Test {
 protected:
-    AuthConmmandTest() : server(false, xfrout), rcode(-1) {
+    AuthCommandTest() : server(false, xfrout), rcode(-1) {
         server.setStatisticsSession(&statistics_session);
     }
     void checkAnswer(const int expected_code) {
@@ -67,14 +67,14 @@ public:
     void stopServer();          // need to be public for boost::bind
 };
 
-TEST_F(AuthConmmandTest, unknownCommand) {
+TEST_F(AuthCommandTest, unknownCommand) {
     result = execAuthServerCommand(server, "no_such_command",
                                    ConstElementPtr());
     parseAnswer(rcode, result);
     EXPECT_EQ(1, rcode);
 }
 
-TEST_F(AuthConmmandTest, DISABLED_unexpectedException) {
+TEST_F(AuthCommandTest, DISABLED_unexpectedException) {
     // execAuthServerCommand() won't catch standard exceptions.
     // Skip this test for now: ModuleCCSession doesn't seem to validate
     // commands.
@@ -83,7 +83,7 @@ TEST_F(AuthConmmandTest, DISABLED_unexpectedException) {
                  runtime_error);
 }
 
-TEST_F(AuthConmmandTest, sendStatistics) {
+TEST_F(AuthCommandTest, sendStatistics) {
     result = execAuthServerCommand(server, "sendstats", ConstElementPtr());
     // Just check some message has been sent.  Detailed tests specific to
     // statistics are done in its own tests.
@@ -92,15 +92,15 @@ TEST_F(AuthConmmandTest, sendStatistics) {
 }
 
 void
-AuthConmmandTest::stopServer() {
+AuthCommandTest::stopServer() {
     result = execAuthServerCommand(server, "shutdown", ConstElementPtr());
     parseAnswer(rcode, result);
     assert(rcode == 0); // make sure the test stops when something is wrong
 }
 
-TEST_F(AuthConmmandTest, shutdown) {
+TEST_F(AuthCommandTest, shutdown) {
     isc::asiolink::IntervalTimer itimer(server.getIOService());
-    itimer.setup(boost::bind(&AuthConmmandTest::stopServer, this), 1);
+    itimer.setup(boost::bind(&AuthCommandTest::stopServer, this), 1);
     server.getIOService().run();
     EXPECT_EQ(0, rcode);
 }
@@ -165,7 +165,7 @@ newZoneChecks(AuthSrv& server) {
               find(Name("ns.test2.example"), RRType::AAAA()).code);
 }
 
-TEST_F(AuthConmmandTest, loadZone) {
+TEST_F(AuthCommandTest, loadZone) {
     configureZones(server);
 
     ASSERT_EQ(0, system(INSTALL_PROG " " TEST_DATA_DIR
@@ -182,7 +182,7 @@ TEST_F(AuthConmmandTest, loadZone) {
     newZoneChecks(server);
 }
 
-TEST_F(AuthConmmandTest, loadBrokenZone) {
+TEST_F(AuthCommandTest, loadBrokenZone) {
     configureZones(server);
 
     ASSERT_EQ(0, system(INSTALL_PROG " " TEST_DATA_DIR
@@ -195,7 +195,7 @@ TEST_F(AuthConmmandTest, loadBrokenZone) {
     zoneChecks(server);     // zone shouldn't be replaced
 }
 
-TEST_F(AuthConmmandTest, loadUnreadableZone) {
+TEST_F(AuthCommandTest, loadUnreadableZone) {
     configureZones(server);
 
     // install the zone file as unreadable
@@ -209,7 +209,7 @@ TEST_F(AuthConmmandTest, loadUnreadableZone) {
     zoneChecks(server);     // zone shouldn't be replaced
 }
 
-TEST_F(AuthConmmandTest, loadZoneWithoutDataSrc) {
+TEST_F(AuthCommandTest, loadZoneWithoutDataSrc) {
     // try to execute load command without configuring the zone beforehand.
     // it should fail.
     result = execAuthServerCommand(server, "loadzone",
@@ -218,7 +218,7 @@ TEST_F(AuthConmmandTest, loadZoneWithoutDataSrc) {
     checkAnswer(1);
 }
 
-TEST_F(AuthConmmandTest, loadSqlite3DataSrc) {
+TEST_F(AuthCommandTest, loadSqlite3DataSrc) {
     // For sqlite3 data source we don't have to do anything (the data source
     // (re)loads itself automatically)
     result = execAuthServerCommand(server, "loadzone",
@@ -228,7 +228,7 @@ TEST_F(AuthConmmandTest, loadSqlite3DataSrc) {
     checkAnswer(0);
 }
 
-TEST_F(AuthConmmandTest, loadZoneInvalidParams) {
+TEST_F(AuthCommandTest, loadZoneInvalidParams) {
     configureZones(server);
 
     // null arg

src/bin/bind10/Makefile.am

@@ -1,16 +1,17 @@
 SUBDIRS = . tests
 
 sbin_SCRIPTS = bind10
-CLEANFILES = bind10 bind10.pyc
+CLEANFILES = bind10 bind10.pyc bind10_messages.py bind10_messages.pyc
 
 pkglibexecdir = $(libexecdir)/@PACKAGE@
+pyexec_DATA = bind10_messages.py
 
 bind10dir = $(pkgdatadir)
 bind10_DATA = bob.spec
 EXTRA_DIST = bob.spec
 
 man_MANS = bind10.8
-EXTRA_DIST += $(man_MANS) bind10.xml
+EXTRA_DIST += $(man_MANS) bind10.xml bind10_messages.mes
 
 if ENABLE_MAN
 
@@ -19,6 +20,9 @@ bind10.8: bind10.xml
 
 endif
 
+bind10_messages.py: bind10_messages.mes
+	$(top_builddir)/src/lib/log/compiler/message -p $(top_srcdir)/src/bin/bind10/bind10_messages.mes
+
 # this is done here since configure.ac AC_OUTPUT doesn't expand exec_prefix
 bind10: bind10.py
 	$(SED) -e "s|@@PYTHONPATH@@|@pyexecdir@|" \

src/bin/bind10/bind10.py.in

@@ -65,6 +65,16 @@ import posix
 import isc.cc
 import isc.util.process
 import isc.net.parse
+import isc.log
+from bind10_messages import *
+
+isc.log.init("b10-boss")
+logger = isc.log.Logger("boss")
+
+# Pending system-wide debug level definitions, the ones we
+# use here are hardcoded for now
+DBG_PROCESS = 10
+DBG_COMMANDS = 30
 
 # Assign this process some longer name
 isc.util.process.rename(sys.argv[0])
@@ -252,8 +262,7 @@ class BoB:
             if new_config['start_' + name]:
                 if not started:
                     if self.uid is not None:
-                        sys.stderr.write("[bind10] Starting " + name + " as " +
-                            "a user, not root. This might fail.\n")
+                        logger.info(BIND10_START_AS_NON_ROOT, name)
                     start()
             else:
                 stop()
@@ -279,9 +288,8 @@ class BoB:
             self.started_auth_family = False
 
         # The real code of the config handler function follows here
-        if self.verbose:
-            sys.stdout.write("[bind10] Handling new configuration: " +
-                str(new_config) + "\n")
+        logger.debug(DBG_COMMANDS, BIND10_RECEIVED_NEW_CONFIGURATION,
+                     new_config)
         start_stop('resolver', self.started_resolver_family, resolver_on,
             resolver_off)
         start_stop('auth', self.started_auth_family, auth_on, auth_off)
@@ -298,8 +306,7 @@ class BoB:
         return process_list
 
     def command_handler(self, command, args):
-        if self.verbose:
-            sys.stdout.write("[bind10] Boss got command: " + str(command) + "\n")
+        logger.debug(DBG_COMMANDS, BIND10_RECEIVED_COMMAND, command)
         answer = isc.config.ccsession.create_answer(1, "command not implemented")
         if type(command) != str:
             answer = isc.config.ccsession.create_answer(1, "bad command")
@@ -332,12 +339,10 @@ class BoB:
             start, this runs through the list of started processes, killing
             each one.  It then clears that list.
         """
-        if self.verbose:
-            sys.stdout.write("[bind10] killing started processes:\n")
+        logger.info(BIND10_KILLING_ALL_PROCESSES)
 
         for pid in self.processes:
-            if self.verbose:
-                sys.stdout.write("[bind10] - %s\n" % self.processes[pid].name)
+            logger.info(BIND10_KILL_PROCESS, self.processes[pid].name)
             self.processes[pid].process.kill()
         self.processes = {}
 
@@ -351,23 +356,20 @@ class BoB:
             xfrin/xfrout and zone manager as we don't need to start those if we
             are not running the authoritative server.)
         """
-        if self.verbose:
-            sys.stdout.write("[bind10] Reading Boss configuration:\n")
+        logger.info(BIND10_READING_BOSS_CONFIGURATION)
 
         config_data = self.ccs.get_full_config()
         self.cfg_start_auth = config_data.get("start_auth")
         self.cfg_start_resolver = config_data.get("start_resolver")
 
-        if self.verbose:
-            sys.stdout.write("[bind10] - start_auth: %s\n" %
-                str(self.cfg_start_auth))
-            sys.stdout.write("[bind10] - start_resolver: %s\n" %
-                str(self.cfg_start_resolver))
+        logger.info(BIND10_CONFIGURATION_START_AUTH, self.cfg_start_auth)
+        logger.info(BIND10_CONFIGURATION_START_RESOLVER, self.cfg_start_resolver)
 
     def log_starting(self, process, port = None, address = None):
         """
             A convenience function to output a "Starting xxx" message if the
-            verbose option is set.  Putting this into a separate method ensures
+            logging is set to DEBUG with debuglevel DBG_PROCESS or higher.
+            Putting this into a separate method ensures
             that the output form is consistent across all processes.
 
             The process name (passed as the first argument) is put into
@@ -377,13 +379,14 @@ class BoB:
             appended to the message (if present).
         """
         self.curproc = process
-        if self.verbose:
-            sys.stdout.write("[bind10] Starting %s" % self.curproc)
-            if port is not None:
-                sys.stdout.write(" on port %d" % port)
-                if address is not None:
-                    sys.stdout.write(" (address %s)" % str(address))
-            sys.stdout.write("\n")
+        if port is None and address is None:
+            logger.info(BIND10_STARTING_PROCESS, self.curproc)
+        elif address is None:
+            logger.info(BIND10_STARTING_PROCESS_PORT, self.curproc,
+                        port)
+        else:
+            logger.info(BIND10_STARTING_PROCESS_PORT_ADDRESS,
+                        self.curproc, address, port)
 
     def log_started(self, pid = None):
         """
@@ -391,11 +394,10 @@ class BoB:
             message.  As with starting_message(), this ensures a consistent
             format.
         """
-        if self.verbose:
-            sys.stdout.write("[bind10] Started %s" % self.curproc)
-            if pid is not None:
-                sys.stdout.write(" (PID %d)" % pid)
-            sys.stdout.write("\n")
+        if pid is None:
+            logger.debug(DBG_PROCESS, BIND10_STARTED_PROCESS, self.curproc)
+        else:
+            logger.debug(DBG_PROCESS, BIND10_STARTED_PROCESS_PID, self.curproc, pid)
 
     # The next few methods start the individual processes of BIND-10.  They
     # are called via start_all_processes().  If any fail, an exception is
@@ -459,7 +461,9 @@ class BoB:
         """
         self.log_starting("ccsession")
         self.ccs = isc.config.ModuleCCSession(SPECFILE_LOCATION, 
-                                      self.config_handler, self.command_handler)
+                                      self.config_handler,
+                                      self.command_handler,
+                                      None, True)
         self.ccs.start()
         self.log_started()
 
@@ -620,12 +624,12 @@ class BoB:
         # running
         c_channel_env = {}
         if self.msgq_socket_file is not None:
-             c_channel_env["BIND10_MSGQ_SOCKET_FILE"] = self.msgq_socket_file 
-        if self.verbose:
-           sys.stdout.write("[bind10] Checking for already running b10-msgq\n")
+             c_channel_env["BIND10_MSGQ_SOCKET_FILE"] = self.msgq_socket_file
+        logger.debug(DBG_PROCESS, BIND10_CHECK_MSGQ_ALREADY_RUNNING)
         # try to connect, and if we can't wait a short while
         try:
             self.cc_session = isc.cc.Session(self.msgq_socket_file)
+            logger.fatal(BIND10_MSGQ_ALREADY_RUNNING)
             return "b10-msgq already running, or socket file not cleaned , cannot start"
         except isc.cc.session.SessionError:
             # this is the case we want, where the msgq is not running
@@ -663,8 +667,7 @@ class BoB:
         Stop the given process, friendly-like. The process is the name it has
         (in logs, etc), the recipient is the address on msgq.
         """
-        if self.verbose:
-            sys.stdout.write("[bind10] Asking %s to terminate\n" % process)
+        logger.info(BIND10_STOP_PROCESS, process)
         # TODO: Some timeout to solve processes that don't want to die would
         # help. We can even store it in the dict, it is used only as a set
         self.expected_shutdowns[process] = 1
@@ -690,8 +693,7 @@ class BoB:
 
     def shutdown(self):
         """Stop the BoB instance."""
-        if self.verbose:
-            sys.stdout.write("[bind10] Stopping the server.\n")
+        logger.info(BIND10_SHUTDOWN)
         # first try using the BIND 10 request to stop
         try:
             self.stop_all_processes()
@@ -705,9 +707,8 @@ class BoB:
         # next try sending a SIGTERM
         processes_to_stop = list(self.processes.values())
         for proc_info in processes_to_stop:
-            if self.verbose:
-                sys.stdout.write("[bind10] Sending SIGTERM to %s (PID %d).\n" % 
-                                 (proc_info.name, proc_info.pid))
+            logger.info(BIND10_SEND_SIGTERM, proc_info.name,
+                        proc_info.pid)
             try:
                 proc_info.process.terminate()
             except OSError:
@@ -721,17 +722,15 @@ class BoB:
             self.reap_children()
             processes_to_stop = list(self.processes.values())
             for proc_info in processes_to_stop:
-                if self.verbose:
-                    sys.stdout.write("[bind10] Sending SIGKILL to %s (PID %d).\n" % 
-                                     (proc_info.name, proc_info.pid))
+                logger.info(BIND10_SEND_SIGKILL, proc_info.name,
+                            proc_info.pid)
                 try:
                     proc_info.process.kill()
                 except OSError:
                     # ignore these (usually ESRCH because the child
                     # finally exited)
                     pass
-        if self.verbose:
-            sys.stdout.write("[bind10] All processes ended, server done.\n")
+        logger.info(BIND10_SHUTDOWN_COMPLETE)
 
     def _get_process_exit_status(self):
         return os.waitpid(-1, os.WNOHANG)
@@ -759,18 +758,16 @@ class BoB:
                 # elsewhere.
                 if self.runnable:
                     if exit_status is None:
-                        sys.stdout.write(
-                            "[bind10] Process %s (PID %d) died: exit status not available" % 
-                            (proc_info.name, proc_info.pid))
+                        logger.warn(BIND10_PROCESS_ENDED_NO_EXIT_STATUS,
+                                    proc_info.name, proc_info.pid)
                     else:
-                        sys.stdout.write(
-                            "[bind10] Process %s (PID %d) terminated, exit status = %d\n" % 
-                            (proc_info.name, proc_info.pid, exit_status))
+                        logger.warn(BIND10_PROCESS_ENDED_WITH_EXIT_STATUS,
+                                    proc_info.name, proc_info.pid,
+                                    exit_status)
 
                     # Was it a special process?
                     if proc_info.name == "b10-msgq":
-                        sys.stdout.write(
-                                 "[bind10] The b10-msgq process died, shutting down.\n")
+                        logger.fatal(BIND10_MSGQ_DAEMON_ENDED)
                         self.runnable = False
 
                 # If we're in 'brittle' mode, we want to shutdown after
@@ -778,7 +775,7 @@ class BoB:
                 if self.brittle:
                     self.runnable = False
             else:
-                sys.stdout.write("[bind10] Unknown child pid %d exited.\n" % pid)
+                logger.info(BIND10_UNKNOWN_CHILD_PROCESS_ENDED, pid)
 
     def restart_processes(self):
         """
@@ -809,14 +806,11 @@ class BoB:
                     next_restart = restart_time
                 still_dead[proc_info.pid] = proc_info
             else:
-                if self.verbose:
-                    sys.stdout.write("[bind10] Resurrecting dead %s process...\n" % 
-                        proc_info.name)
+                logger.info(BIND10_RESURRECTING_PROCESS, proc_info.name)
                 try:
                     proc_info.respawn()
                     self.processes[proc_info.pid] = proc_info
-                    sys.stdout.write("[bind10] Resurrected %s (PID %d)\n" %
-                                     (proc_info.name, proc_info.pid))
+                    logger.info(BIND10_RESURRECTED_PROCESS, proc_info.name, proc_info.pid)
                 except:
                     still_dead[proc_info.pid] = proc_info
         # remember any processes that refuse to be resurrected
@@ -848,8 +842,7 @@ def fatal_signal(signal_number, stack_frame):
     """We need to exit (SIGINT or SIGTERM received)."""
     global options
     global boss_of_bind
-    if options.verbose:
-        sys.stdout.write("[bind10] Received %s.\n" % get_signame(signal_number))
+    logger.info(BIND10_RECEIVED_SIGNAL, get_signame(signal_number))
     signal.signal(signal.SIGCHLD, signal.SIG_DFL)
     boss_of_bind.runnable = False
 
@@ -967,12 +960,11 @@ def main():
             pass
 
         if setuid is None:
-            sys.stderr.write("bind10: invalid user: '%s'\n" % options.user)
+            logger.fatal(BIND10_INVALID_USER, options.user)
             sys.exit(1)
 
     # Announce startup.
-    if options.verbose:
-        sys.stdout.write("%s\n" % VERSION)
+    logger.info(BIND10_STARTING, VERSION)
 
     # Create wakeup pipe for signal handlers
     wakeup_pipe = os.pipe()
@@ -994,9 +986,9 @@ def main():
                        setuid, username, options.cmdctl_port, options.brittle)
     startup_result = boss_of_bind.startup()
     if startup_result:
-        sys.stderr.write("[bind10] Error on startup: %s\n" % startup_result)
+        logger.fatal(BIND10_STARTUP_ERROR, startup_result)
         sys.exit(1)
-    sys.stdout.write("[bind10] BIND 10 started\n")
+    logger.info(BIND10_STARTUP_COMPLETE)
     dump_pid(options.pid_file)
 
     # In our main loop, we check for dead processes or messages 
@@ -1022,7 +1014,7 @@ def main():
             if err.args[0] == errno.EINTR:
                 (rlist, wlist, xlist) = ([], [], [])
             else:
-                sys.stderr.write("[bind10] Error with select(); %s\n" % err)
+                logger.fatal(BIND10_SELECT_ERROR, err)
                 break
 
         for fd in rlist + xlist:
@@ -1030,8 +1022,8 @@ def main():
                 try:
                     boss_of_bind.ccs.check_command()
                 except isc.cc.session.ProtocolError:
-                    if options.verbose:
-                        sys.stderr.write("[bind10] msgq channel disappeared.\n")
+                    logger.fatal(BIND10_MSGQ_DISAPPEARED)
+                    self.runnable = False
                     break
             elif fd == wakeup_fd:
                 os.read(wakeup_fd, 32)
@@ -1039,7 +1031,6 @@ def main():
     # shutdown
     signal.signal(signal.SIGCHLD, signal.SIG_DFL)
     boss_of_bind.shutdown()
-    sys.stdout.write("[bind10] BIND 10 exiting\n");
     unlink_pid_file(options.pid_file)
     sys.exit(0)
 

src/bin/bind10/bind10_messages.mes

@@ -0,0 +1,157 @@
+# 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.
+
+# No namespace declaration - these constants go in the global namespace
+# of the xfrin messages python module.
+
+% BIND10_CHECK_MSGQ_ALREADY_RUNNING checking if msgq is already running
+The boss process is starting up and will now check if the message bus
+daemon is already running. If so, it will not be able to start, as it
+needs a dedicated message bus.
+
+% BIND10_CONFIGURATION_START_AUTH start authoritative server: %1
+This message shows whether or not the authoritative server should be
+started according to the configuration.
+
+% BIND10_CONFIGURATION_START_RESOLVER start resolver: %1
+This message shows whether or not the resolver should be
+started according to the configuration.
+
+% BIND10_INVALID_USER invalid user: %1
+The boss process was started with the -u option, to drop root privileges
+and continue running as the specified user, but the user is unknown.
+
+% BIND10_KILL_PROCESS killing process %1
+The boss module is sending a kill signal to process with the given name,
+as part of the process of killing all started processes during a failed
+startup, as described for BIND10_KILLING_ALL_PROCESSES
+
+% BIND10_KILLING_ALL_PROCESSES killing all started processes
+The boss module was not able to start every process it needed to start
+during startup, and will now kill the processes that did get started.
+
+% BIND10_MSGQ_ALREADY_RUNNING msgq daemon already running, cannot start
+There already appears to be a message bus daemon running. Either an
+old process was not shut down correctly, and needs to be killed, or
+another instance of BIND10, with the same msgq domain socket, is
+running, which needs to be stopped.
+
+% BIND10_MSGQ_DAEMON_ENDED b10-msgq process died, shutting down
+The message bus daemon has died. This is a fatal error, since it may
+leave the system in an inconsistent state. BIND10 will now shut down.
+
+% BIND10_MSGQ_DISAPPEARED msgq channel disappeared
+While listening on the message bus channel for messages, it suddenly
+disappeared. The msgq daemon may have died. This might lead to an
+inconsistent state of the system, and BIND 10 will now shut down.
+
+% BIND10_PROCESS_ENDED_NO_EXIT_STATUS process %1 (PID %2) died: exit status not available
+The given process ended unexpectedly, but no exit status is
+available. See BIND10_PROCESS_ENDED_WITH_EXIT_STATUS for a longer
+description.
+
+% BIND10_PROCESS_ENDED_WITH_EXIT_STATUS process %1 (PID %2) terminated, exit status = %3
+The given process ended unexpectedly with the given exit status.
+Depending on which module it was, it may simply be restarted, or it
+may be a problem that will cause the boss module to shut down too.
+The latter happens if it was the message bus daemon, which, if it has
+died suddenly, may leave the system in an inconsistent state. BIND10
+will also shut down now if it has been run with --brittle.
+
+% BIND10_READING_BOSS_CONFIGURATION reading boss configuration
+The boss process is starting up, and will now process the initial
+configuration, as received from the configuration manager.
+
+% BIND10_RECEIVED_COMMAND received command: %1
+The boss module received a command and shall now process it. The command
+is printed.
+
+% BIND10_RECEIVED_NEW_CONFIGURATION received new configuration: %1
+The boss module received a configuration update and is going to apply
+it now. The new configuration is printed.
+
+% BIND10_RECEIVED_SIGNAL received signal %1
+The boss module received the given signal.
+
+% BIND10_RESURRECTED_PROCESS resurrected %1 (PID %2)
+The given process has been restarted successfully, and is now running
+with the given process id.
+
+% BIND10_RESURRECTING_PROCESS resurrecting dead %1 process...
+The given process has ended unexpectedly, and is now restarted.
+
+% BIND10_SELECT_ERROR error in select() call: %1
+There was a fatal error in the call to select(), used to see if a child
+process has ended or if there is a message on the message bus. This
+should not happen under normal circumstances and is considered fatal,
+so BIND 10 will now shut down. The specific error is printed.
+
+% BIND10_SEND_SIGKILL sending SIGKILL to %1 (PID %2)
+The boss module is sending a SIGKILL signal to the given process.
+
+% BIND10_SEND_SIGTERM sending SIGTERM to %1 (PID %2)
+The boss module is sending a SIGTERM signal to the given process.
+
+% BIND10_SHUTDOWN stopping the server
+The boss process received a command or signal telling it to shut down.
+It will send a shutdown command to each process. The processes that do
+not shut down will then receive a SIGTERM signal. If that doesn't work,
+it shall send SIGKILL signals to the processes still alive.
+
+% BIND10_SHUTDOWN_COMPLETE all processes ended, shutdown complete
+All child processes have been stopped, and the boss process will now
+stop itself.
+
+% BIND10_START_AS_NON_ROOT starting %1 as a user, not root. This might fail.
+The given module is being started or restarted without root privileges.
+If the module needs these privileges, it may have problems starting.
+Note that this issue should be resolved by the pending 'socket-creator'
+process; once that has been implemented, modules should not need root
+privileges anymore. See tickets #800 and #801 for more information.
+
+% BIND10_STARTED_PROCESS started %1
+The given process has successfully been started.
+
+% BIND10_STARTED_PROCESS_PID started %1 (PID %2)
+The given process has successfully been started, and has the given PID.
+
+% BIND10_STARTING starting BIND10: %1
+Informational message on startup that shows the full version.
+
+% BIND10_STARTING_PROCESS starting process %1
+The boss module is starting the given process.
+
+% BIND10_STARTING_PROCESS_PORT starting process %1 (to listen on port %2)
+The boss module is starting the given process, which will listen on the
+given port number.
+
+% BIND10_STARTING_PROCESS_PORT_ADDRESS starting process %1 (to listen on %2#%3)
+The boss module is starting the given process, which will listen on the
+given address and port number (written as <address>#<port>).
+
+% BIND10_STARTUP_COMPLETE BIND 10 started
+All modules have been successfully started, and BIND 10 is now running.
+
+% BIND10_STARTUP_ERROR error during startup: %1
+There was a fatal error when BIND10 was trying to start. The error is
+shown, and BIND10 will now shut down.
+
+% BIND10_STOP_PROCESS asking %1 to shut down
+The boss module is sending a shutdown command to the given module over
+the message channel.
+
+% BIND10_UNKNOWN_CHILD_PROCESS_ENDED unknown child pid %1 exited
+An unknown child process has exited. The PID is printed, but no further
+action will be taken by the boss process.
+

src/bin/cmdctl/Makefile.am

@@ -3,6 +3,7 @@ SUBDIRS = . tests
 pkglibexecdir = $(libexecdir)/@PACKAGE@
 
 pkglibexec_SCRIPTS = b10-cmdctl
+pyexec_DATA = cmdctl_messages.py
 
 b10_cmdctldir = $(pkgdatadir)
 
@@ -18,10 +19,10 @@ b10_cmdctl_DATA += cmdctl.spec
 
 EXTRA_DIST = $(CMDCTL_CONFIGURATIONS)
 
-CLEANFILES=	b10-cmdctl cmdctl.pyc cmdctl.spec
+CLEANFILES=	b10-cmdctl cmdctl.pyc cmdctl.spec cmdctl_messages.py cmdctl_messages.pyc
 
 man_MANS = b10-cmdctl.8
-EXTRA_DIST += $(man_MANS) b10-cmdctl.xml
+EXTRA_DIST += $(man_MANS) b10-cmdctl.xml cmdctl_messages.mes
 
 if ENABLE_MAN
 
@@ -33,8 +34,11 @@ endif
 cmdctl.spec: cmdctl.spec.pre
 	$(SED) -e "s|@@SYSCONFDIR@@|$(sysconfdir)|" cmdctl.spec.pre >$@
 
+cmdctl_messages.py: cmdctl_messages.mes
+	$(top_builddir)/src/lib/log/compiler/message -p $(top_srcdir)/src/bin/cmdctl/cmdctl_messages.mes
+
 # this is done here since configure.ac AC_OUTPUT doesn't expand exec_prefix
-b10-cmdctl: cmdctl.py
+b10-cmdctl: cmdctl.py cmdctl_messages.py
 	$(SED) "s|@@PYTHONPATH@@|@pyexecdir@|" cmdctl.py >$@
 	chmod a+x $@
 

src/bin/cmdctl/cmdctl.py.in

@@ -47,6 +47,18 @@ import isc.net.parse
 from optparse import OptionParser, OptionValueError
 from hashlib import sha1
 from isc.util import socketserver_mixin
+from cmdctl_messages import *
+
+# TODO: these debug-levels are hard-coded here; we are planning on
+# creating a general set of debug levels, see ticket #1074. When done,
+# we should remove these values and use the general ones in the
+# logger.debug calls
+
+# Debug level for communication with BIND10
+DBG_CMDCTL_MESSAGING = 30
+
+isc.log.init("b10-cmdctl")
+logger = isc.log.Logger("cmdctl")
 
 try:
     import threading
@@ -173,7 +185,8 @@ class SecureHTTPRequestHandler(http.server.BaseHTTPRequestHandler):
         if not user_name:
             return False, ["need user name"]
         if not self.server.get_user_info(user_name):
-            return False, ["user doesn't exist"]
+            logger.info(CMDCTL_NO_SUCH_USER, user_name)
+            return False, ["username or password error"]
 
         user_pwd = user_info.get('password')
         if not user_pwd:
@@ -181,7 +194,8 @@ class SecureHTTPRequestHandler(http.server.BaseHTTPRequestHandler):
         local_info = self.server.get_user_info(user_name)
         pwd_hashval = sha1((user_pwd + local_info[1]).encode())
         if pwd_hashval.hexdigest() != local_info[0]:
-            return False, ["password doesn't match"] 
+            logger.info(CMDCTL_BAD_PASSWORD, user_name)
+            return False, ["username or password error"]
 
         return True, None
    
@@ -238,7 +252,8 @@ class CommandControl():
         self._cc = isc.cc.Session()
         self._module_cc = isc.config.ModuleCCSession(SPECFILE_LOCATION,
                                               self.config_handler,
-                                              self.command_handler)
+                                              self.command_handler,
+                                              None, True)
         self._module_name = self._module_cc.get_module_spec().get_module_name()
         self._cmdctl_config_data = self._module_cc.get_full_config()
         self._module_cc.start()
@@ -281,7 +296,7 @@ class CommandControl():
                 errstr = 'unknown config item: ' + key
             
             if errstr != None:
-                self.log_info('Fail to apply config data, ' + errstr) 
+                logger.error(CMDCTL_BAD_CONFIG_DATA, errstr);
                 return ccsession.create_answer(1, errstr)
 
         return ccsession.create_answer(0)
@@ -387,8 +402,8 @@ class CommandControl():
         '''Send the command from bindctl to proper module. '''
         errstr = 'unknown error'
         answer = None
-        if self._verbose:
-            self.log_info("Begin send command '%s' to module '%s'" %(command_name, module_name))
+        logger.debug(DBG_CMDCTL_MESSAGING, CMDCTL_SEND_COMMAND,
+                     command_name, module_name)
 
         if module_name == self._module_name:
             # Process the command sent to cmdctl directly. 
@@ -396,15 +411,14 @@ class CommandControl():
         else:
             msg = ccsession.create_command(command_name, params)
             seq = self._cc.group_sendmsg(msg, module_name)
+            logger.debug(DBG_CMDCTL_MESSAGING, CMDCTL_COMMAND_SENT,
+                         command_name, module_name)
             #TODO, it may be blocked, msqg need to add a new interface waiting in timeout.
             try:
                 answer, env = self._cc.group_recvmsg(False, seq)
             except isc.cc.session.SessionTimeout:
                 errstr = "Module '%s' not responding" % module_name
 
-        if self._verbose:
-            self.log_info("Finish send command '%s' to module '%s'" % (command_name, module_name))
-
         if answer:
             try:
                 rcode, arg = ccsession.parse_answer(answer)
@@ -415,16 +429,13 @@ class CommandControl():
                     else:
                         return rcode, {}
                 else:
-                    # TODO: exception
                     errstr = str(answer['result'][1])
             except ccsession.ModuleCCSessionError as mcse:
                 errstr = str("Error in ccsession answer:") + str(mcse)
-                self.log_info(errstr)
+
+        logger.error(CMDCTL_COMMAND_ERROR, command_name, module_name, errstr)
         return 1, {'error': errstr}
     
-    def log_info(self, msg):
-        sys.stdout.write("[b10-cmdctl] %s\n" % str(msg))
-
     def get_cmdctl_config_data(self):
         ''' If running in source code tree, use keyfile, certificate
         and user accounts file in source code. '''
@@ -481,14 +492,15 @@ class SecureHTTPServer(socketserver_mixin.NoPollMixIn,
                 for row in reader:
                     self._user_infos[row[0]] = [row[1], row[2]]
             except (IOError, IndexError) as e:
-                self.log_info("Fail to read user database, %s" % e)                
+                logger.error(CMDCTL_USER_DATABASE_READ_ERROR,
+                             accounts_file, e)
             finally:
                 if csvfile:
                     csvfile.close()
 
         self._accounts_file = accounts_file
         if len(self._user_infos) == 0:
-            self.log_info("Fail to get user information, will deny any user")                
+            logger.error(CMDCTL_NO_USER_ENTRIES_READ)
          
     def get_user_info(self, username):
         '''Get user's salt and hashed string. If the user
@@ -520,7 +532,7 @@ class SecureHTTPServer(socketserver_mixin.NoPollMixIn,
                                       ssl_version = ssl.PROTOCOL_SSLv23)
             return ssl_sock 
         except (ssl.SSLError, CmdctlException) as err :
-            self.log_info("Deny client's connection because %s" % str(err))
+            logger.info(CMDCTL_SSL_SETUP_FAILURE_USER_DENIED, err)
             self.close_request(sock)
             # raise socket error to finish the request
             raise socket.error
@@ -547,9 +559,6 @@ class SecureHTTPServer(socketserver_mixin.NoPollMixIn,
     def send_command_to_module(self, module_name, command_name, params):
         return self.cmdctl.send_command_with_check(module_name, command_name, params)
    
-    def log_info(self, msg):
-        sys.stdout.write("[b10-cmdctl] %s\n" % str(msg))
-
 httpd = None
 
 def signal_handler(signal, frame):
@@ -607,15 +616,13 @@ if __name__ == '__main__':
         run(options.addr, options.port, options.idle_timeout, options.verbose)
         result = 0
     except isc.cc.SessionError as err:
-        sys.stderr.write("[b10-cmdctl] Error creating b10-cmdctl, "
-                         "is the command channel daemon running?\n")        
+        logger.fatal(CMDCTL_CC_SESSION_ERROR, err)
     except isc.cc.SessionTimeout:
-        sys.stderr.write("[b10-cmdctl] Error creating b10-cmdctl, "
-                         "is the configuration manager running?\n")        
+        logger.fatal(CMDCTL_CC_SESSION_TIMEOUT)
     except KeyboardInterrupt:
-        sys.stderr.write("[b10-cmdctl] exit from Cmdctl\n")
+        logger.info(CMDCTL_STOPPED_BY_KEYBOARD)
     except CmdctlException as err:
-        sys.stderr.write("[b10-cmdctl] " + str(err) + "\n")
+        logger.fatal(CMDCTL_UNCAUGHT_EXCEPTION, err);
 
     if httpd:
         httpd.shutdown()

src/bin/cmdctl/cmdctl_messages.mes

@@ -0,0 +1,81 @@
+# 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.
+
+# No namespace declaration - these constants go in the global namespace
+# of the cmdctl_messages python module.
+
+% CMDCTL_BAD_CONFIG_DATA error in config data: %1
+There was an error reading the updated configuration data. The specific
+error is printed.
+
+% CMDCTL_BAD_PASSWORD bad password for user: %1
+A login attempt was made to b10-cmdctl, but the password was wrong.
+Users can be managed with the tool b10-cmdctl-usermgr.
+
+% CMDCTL_CC_SESSION_ERROR error reading from cc channel: %1
+There was a problem reading from the command and control channel. The
+most likely cause is that the message bus daemon is not running.
+
+% CMDCTL_CC_SESSION_TIMEOUT timeout on cc channel
+A timeout occurred when waiting for essential data from the cc session.
+This usually occurs when b10-cfgmgr is not running or not responding.
+Since we are waiting for essential information, this is a fatal error,
+and the cmdctl daemon will now shut down.
+
+% CMDCTL_COMMAND_ERROR error in command %1 to module %2: %3
+An error was encountered sending the given command to the given module.
+Either there was a communication problem with the module, or the module
+was not able to process the command, and sent back an error. The
+specific error is printed in the message.
+
+% CMDCTL_COMMAND_SENT command '%1' to module '%2' was sent
+This debug message indicates that the given command has been sent to
+the given module.
+
+% CMDCTL_NO_SUCH_USER username not found in user database: %1
+A login attempt was made to b10-cmdctl, but the username was not known.
+Users can be added with the tool b10-cmdctl-usermgr.
+
+% CMDCTL_NO_USER_ENTRIES_READ failed to read user information, all users will be denied
+The b10-cmdctl daemon was unable to find any user data in the user
+database file. Either it was unable to read the file (in which case
+this message follows a message CMDCTL_USER_DATABASE_READ_ERROR
+containing a specific error), or the file was empty. Users can be added
+with the tool b10-cmdctl-usermgr.
+
+% CMDCTL_SEND_COMMAND sending command %1 to module %2
+This debug message indicates that the given command is being sent to
+the given module.
+
+% CMDCTL_SSL_SETUP_FAILURE_USER_DENIED failed to create an SSL connection (user denied): %1
+The user was denied because the SSL connection could not successfully
+be set up. The specific error is given in the log message. Possible
+causes may be that the ssl request itself was bad, or the local key or
+certificate file could not be read.
+
+% CMDCTL_STOPPED_BY_KEYBOARD keyboard interrupt, shutting down
+There was a keyboard interrupt signal to stop the cmdctl daemon. The
+daemon will now shut down.
+
+% CMDCTL_UNCAUGHT_EXCEPTION uncaught exception: %1
+The b10-cdmctl daemon encountered an uncaught exception and
+will now shut down. This is indicative of a programming error and
+should not happen under normal circumstances. The exception message
+is printed.
+
+% CMDCTL_USER_DATABASE_READ_ERROR failed to read user database file %1: %2
+The b10-cmdctl daemon was unable to read the user database file. The
+file may be unreadable for the daemon, or it may be corrupted. In the
+latter case, it can be recreated with b10-cmdctl-usermgr. The specific
+error is printed in the log message.

src/bin/cmdctl/tests/cmdctl_test.py

@@ -173,7 +173,7 @@ class TestSecureHTTPRequestHandler(unittest.TestCase):
         self.handler.server._user_infos['root'] = ['aa', 'aaa']
         ret, msg = self.handler._check_user_name_and_pwd()
         self.assertFalse(ret)
-        self.assertEqual(msg, ['password doesn\'t match'])
+        self.assertEqual(msg, ['username or password error'])
 
     def test_check_user_name_and_pwd_2(self):
         user_info = {'username':'root', 'password':'abc123'}
@@ -214,7 +214,7 @@ class TestSecureHTTPRequestHandler(unittest.TestCase):
 
         ret, msg = self.handler._check_user_name_and_pwd()
         self.assertFalse(ret)
-        self.assertEqual(msg, ['user doesn\'t exist'])
+        self.assertEqual(msg, ['username or password error'])
 
     def test_do_POST(self):
         self.handler.headers = {}

src/bin/resolver/Makefile.am

@@ -59,6 +59,8 @@ nodist_b10_resolver_SOURCES = resolver_messages.cc resolver_messages.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
+b10_resolver_LDADD += $(top_builddir)/src/lib/util/libutil.la
+b10_resolver_LDADD += $(top_builddir)/src/lib/acl/libdnsacl.la
 b10_resolver_LDADD += $(top_builddir)/src/lib/exceptions/libexceptions.la
 b10_resolver_LDADD += $(top_builddir)/src/lib/asiodns/libasiodns.la
 b10_resolver_LDADD += $(top_builddir)/src/lib/asiolink/libasiolink.la

src/bin/resolver/resolver.cc

@@ -26,7 +26,7 @@
 
 #include <exceptions/exceptions.h>
 
-#include <acl/acl.h>
+#include <acl/dns.h>
 #include <acl/loader.h>
 
 #include <asiodns/asiodns.h>
@@ -62,6 +62,7 @@ using boost::shared_ptr;
 using namespace isc;
 using namespace isc::util;
 using namespace isc::acl;
+using isc::acl::dns::RequestACL;
 using namespace isc::dns;
 using namespace isc::data;
 using namespace isc::config;
@@ -82,7 +83,9 @@ public:
         client_timeout_(4000),
         lookup_timeout_(30000),
         retries_(3),
-        query_acl_(new Resolver::ClientACL(REJECT)),
+        // we apply "reject all" (implicit default of the loader) ACL by
+        // default:
+        query_acl_(acl::dns::getRequestLoader().load(Element::fromJSON("[]"))),
         rec_query_(NULL)
     {}
 
@@ -160,11 +163,11 @@ public:
                                          OutputBufferPtr buffer,
                                          DNSServer* server);
 
-    const Resolver::ClientACL& getQueryACL() const {
+    const RequestACL& getQueryACL() const {
         return (*query_acl_);
     }
 
-    void setQueryACL(shared_ptr<const Resolver::ClientACL> new_acl) {
+    void setQueryACL(shared_ptr<const RequestACL> new_acl) {
         query_acl_ = new_acl;
     }
 
@@ -192,7 +195,7 @@ public:
 
 private:
     /// ACL on incoming queries
-    shared_ptr<const Resolver::ClientACL> query_acl_;
+    shared_ptr<const RequestACL> query_acl_;
 
     /// Object to handle upstream queries
     RecursiveQuery* rec_query_;
@@ -514,8 +517,10 @@ ResolverImpl::processNormalQuery(const IOMessage& io_message,
     const RRClass qclass = question->getClass();
 
     // Apply query ACL
-    Client client(io_message);
-    const BasicAction query_action(getQueryACL().execute(client));
+    const Client client(io_message);
+    const BasicAction query_action(
+        getQueryACL().execute(acl::dns::RequestContext(
+                                  client.getRequestSourceIPAddress())));
     if (query_action == isc::acl::REJECT) {
         LOG_INFO(resolver_logger, RESOLVER_QUERY_REJECTED)
             .arg(question->getName()).arg(qtype).arg(qclass).arg(client);
@@ -574,32 +579,6 @@ ResolverImpl::processNormalQuery(const IOMessage& io_message,
     return (RECURSION);
 }
 
-namespace {
-// This is a simplified ACL parser for the initial implementation with minimal
-// external dependency.  For a longer term we'll switch to a more generic
-// loader with allowing more complicated ACL syntax.
-shared_ptr<const Resolver::ClientACL>
-createQueryACL(isc::data::ConstElementPtr acl_config) {
-    if (!acl_config) {
-        return (shared_ptr<const Resolver::ClientACL>());
-    }
-
-    shared_ptr<Resolver::ClientACL> new_acl(
-        new Resolver::ClientACL(REJECT));
-    BOOST_FOREACH(ConstElementPtr rule, acl_config->listValue()) {
-        ConstElementPtr action = rule->get("action");
-        ConstElementPtr from = rule->get("from");
-        if (!action || !from) {
-            isc_throw(BadValue, "query ACL misses mandatory parameter");
-        }
-        new_acl->append(shared_ptr<IPCheck<Client> >(
-                            new IPCheck<Client>(from->stringValue())),
-                        defaultActionLoader(action));
-    }
-    return (new_acl);
-}
-}
-
 ConstElementPtr
 Resolver::updateConfig(ConstElementPtr config) {
     LOG_DEBUG(resolver_logger, RESOLVER_DBG_CONFIG, RESOLVER_CONFIG_UPDATED)
@@ -616,8 +595,10 @@ Resolver::updateConfig(ConstElementPtr config) {
         ConstElementPtr listenAddressesE(config->get("listen_on"));
         AddressList listenAddresses(parseAddresses(listenAddressesE,
                                                       "listen_on"));
-        shared_ptr<const ClientACL> query_acl(createQueryACL(
-                                                  config->get("query_acl")));
+        const ConstElementPtr query_acl_cfg(config->get("query_acl"));
+        const shared_ptr<const RequestACL> query_acl =
+            query_acl_cfg ? acl::dns::getRequestLoader().load(query_acl_cfg) :
+            shared_ptr<RequestACL>();
         bool set_timeouts(false);
         int qtimeout = impl_->query_timeout_;
         int ctimeout = impl_->client_timeout_;
@@ -777,13 +758,13 @@ Resolver::getListenAddresses() const {
     return (impl_->listen_);
 }
 
-const Resolver::ClientACL&
+const RequestACL&
 Resolver::getQueryACL() const {
     return (impl_->getQueryACL());
 }
 
 void
-Resolver::setQueryACL(shared_ptr<const ClientACL> new_acl) {
+Resolver::setQueryACL(shared_ptr<const RequestACL> new_acl) {
     if (!new_acl) {
         isc_throw(InvalidParameter, "NULL pointer is passed to setQueryACL");
     }

src/bin/resolver/resolver.h

@@ -21,10 +21,9 @@
 
 #include <boost/shared_ptr.hpp>
 
-#include <acl/acl.h>
-
 #include <cc/data.h>
 #include <config/ccsession.h>
+#include <acl/dns.h>
 #include <dns/message.h>
 #include <util/buffer.h>
 
@@ -41,12 +40,6 @@
 
 #include <resolve/resolver_interface.h>
 
-namespace isc {
-namespace server_common {
-class Client;
-}
-}
-
 class ResolverImpl;
 
 /**
@@ -246,13 +239,10 @@ public:
      */
     int getRetries() const;
 
-    // Shortcut typedef used for query ACL.
-    typedef isc::acl::ACL<isc::server_common::Client> ClientACL;
-
     /// Get the query ACL.
     ///
     /// \exception None
-    const ClientACL& getQueryACL() const;
+    const isc::acl::dns::RequestACL& getQueryACL() const;
 
     /// Set the new query ACL.
     ///
@@ -265,7 +255,8 @@ public:
     /// \exception InvalidParameter The given pointer is NULL
     ///
     /// \param new_acl The new ACL to replace the existing one.
-    void setQueryACL(boost::shared_ptr<const ClientACL> new_acl);
+    void setQueryACL(boost::shared_ptr<const isc::acl::dns::RequestACL>
+                     new_acl);
 
 private:
     ResolverImpl* impl_;

src/bin/resolver/resolver_messages.mes

@@ -210,10 +210,14 @@ query in the form of <Source IP address>#<source port>.
 % RESOLVER_QUERY_REJECTED   query rejected: '%1/%2/%3' from %4
 An informational message that indicates an incoming query is rejected
 in terms of the query ACL.  This results in a response with an RCODE of
-REFUSED.  See QUERYACCEPTED for the information given in the message.
+REFUSED. The log message shows the query in the form of <query
+name>/<query type>/<query class>, and the client that sends the
+query in the form of <Source IP address>#<source port>.
 
 % RESOLVER_QUERY_DROPPED    query dropped: '%1/%2/%3' from %4
 An informational message that indicates an incoming query is dropped
-in terms of the query ACL.  Unlike the QUERYREJECTED case, the server does
-not return any response.  See QUERYACCEPTED for the information given in
-the message.
+in terms of the query ACL.  Unlike the RESOLVER_QUERY_REJECTED
+case, the server does not return any response.  The log message
+shows the query in the form of <query name>/<query type>/<query
+class>, and the client that sends the query in the form of <Source
+IP address>#<source port>.

src/bin/resolver/tests/Makefile.am

@@ -39,6 +39,7 @@ 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
 run_unittests_LDADD += $(top_builddir)/src/lib/config/libcfgclient.la
+run_unittests_LDADD += $(top_builddir)/src/lib/acl/libdnsacl.la
 run_unittests_LDADD += $(top_builddir)/src/lib/cc/libcc.la
 run_unittests_LDADD += $(top_builddir)/src/lib/exceptions/libexceptions.la
 run_unittests_LDADD += $(top_builddir)/src/lib/xfr/libxfr.la

src/bin/resolver/tests/resolver_config_unittest.cc

@@ -43,6 +43,7 @@
 using namespace std;
 using boost::scoped_ptr;
 using namespace isc::acl;
+using isc::acl::dns::RequestContext;
 using namespace isc::data;
 using namespace isc::testutils;
 using namespace isc::asiodns;
@@ -57,19 +58,22 @@ protected:
     DNSService dnss;
     Resolver server;
     scoped_ptr<const IOEndpoint> endpoint;
-    scoped_ptr<const IOMessage> request;
+    scoped_ptr<const IOMessage> query_message;
     scoped_ptr<const Client> client;
+    scoped_ptr<const RequestContext> request;
     ResolverConfig() : dnss(ios, NULL, NULL, NULL) {
         server.setDNSService(dnss);
         server.setConfigured();
     }
-    const Client& createClient(const string& source_addr) {
+    const RequestContext& createRequest(const string& source_addr) {
         endpoint.reset(IOEndpoint::create(IPPROTO_UDP, IOAddress(source_addr),
                                           53210));
-        request.reset(new IOMessage(NULL, 0, IOSocket::getDummyUDPSocket(),
-                                    *endpoint));
-        client.reset(new Client(*request));
-        return (*client);
+        query_message.reset(new IOMessage(NULL, 0,
+                                          IOSocket::getDummyUDPSocket(),
+                                          *endpoint));
+        client.reset(new Client(*query_message));
+        request.reset(new RequestContext(client->getRequestSourceIPAddress()));
+        return (*request);
     }
     void invalidTest(const string &JSON, const string& name);
 };
@@ -100,14 +104,14 @@ TEST_F(ResolverConfig, forwardAddresses) {
 
 TEST_F(ResolverConfig, forwardAddressConfig) {
     // Try putting there some address
-    ElementPtr config(Element::fromJSON("{"
-        "\"forward_addresses\": ["
-        "   {"
-        "       \"address\": \"192.0.2.1\","
-        "       \"port\": 53"
-        "   }"
-        "]"
-        "}"));
+    ConstElementPtr config(Element::fromJSON("{"
+                                             "\"forward_addresses\": ["
+                                             " {"
+                                             "   \"address\": \"192.0.2.1\","
+                                             "   \"port\": 53"
+                                             " }"
+                                             "]"
+                                             "}"));
     ConstElementPtr result(server.updateConfig(config));
     EXPECT_EQ(result->toWire(), isc::config::createAnswer()->toWire());
     EXPECT_TRUE(server.isForwarding());
@@ -127,14 +131,14 @@ TEST_F(ResolverConfig, forwardAddressConfig) {
 
 TEST_F(ResolverConfig, rootAddressConfig) {
     // Try putting there some address
-    ElementPtr config(Element::fromJSON("{"
-        "\"root_addresses\": ["
-        "   {"
-        "       \"address\": \"192.0.2.1\","
-        "       \"port\": 53"
-        "   }"
-        "]"
-        "}"));
+    ConstElementPtr config(Element::fromJSON("{"
+                                             "\"root_addresses\": ["
+                                             " {"
+                                             "    \"address\": \"192.0.2.1\","
+                                             "    \"port\": 53"
+                                             " }"
+                                             "]"
+                                             "}"));
     ConstElementPtr result(server.updateConfig(config));
     EXPECT_EQ(result->toWire(), isc::config::createAnswer()->toWire());
     ASSERT_EQ(1, server.getRootAddresses().size());
@@ -210,12 +214,12 @@ TEST_F(ResolverConfig, timeouts) {
 }
 
 TEST_F(ResolverConfig, timeoutsConfig) {
-    ElementPtr config = Element::fromJSON("{"
-            "\"timeout_query\": 1000,"
-            "\"timeout_client\": 2000,"
-            "\"timeout_lookup\": 3000,"
-            "\"retries\": 4"
-            "}");
+    ConstElementPtr config = Element::fromJSON("{"
+                                               "\"timeout_query\": 1000,"
+                                               "\"timeout_client\": 2000,"
+                                               "\"timeout_lookup\": 3000,"
+                                               "\"retries\": 4"
+                                               "}");
     ConstElementPtr result(server.updateConfig(config));
     EXPECT_EQ(result->toWire(), isc::config::createAnswer()->toWire());
     EXPECT_EQ(1000, server.getQueryTimeout());
@@ -253,51 +257,51 @@ TEST_F(ResolverConfig, invalidTimeoutsConfig) {
 
 TEST_F(ResolverConfig, defaultQueryACL) {
     // If no configuration is loaded, the default ACL should reject everything.
-    EXPECT_EQ(REJECT, server.getQueryACL().execute(createClient("192.0.2.1")));
+    EXPECT_EQ(REJECT, server.getQueryACL().execute(createRequest("192.0.2.1")));
     EXPECT_EQ(REJECT, server.getQueryACL().execute(
-                  createClient("2001:db8::1")));
+                  createRequest("2001:db8::1")));
 
     // The following would be allowed if the server had loaded the default
     // configuration from the spec file.  In this context it should not have
     // happened, and they should be rejected just like the above cases.
-    EXPECT_EQ(REJECT, server.getQueryACL().execute(createClient("127.0.0.1")));
-    EXPECT_EQ(REJECT, server.getQueryACL().execute(createClient("::1")));
+    EXPECT_EQ(REJECT, server.getQueryACL().execute(createRequest("127.0.0.1")));
+    EXPECT_EQ(REJECT, server.getQueryACL().execute(createRequest("::1")));
 }
 
 TEST_F(ResolverConfig, emptyQueryACL) {
     // Explicitly configured empty ACL should have the same effect.
-    ElementPtr config(Element::fromJSON("{ \"query_acl\": [] }"));
+    ConstElementPtr config(Element::fromJSON("{ \"query_acl\": [] }"));
     ConstElementPtr result(server.updateConfig(config));
     EXPECT_EQ(result->toWire(), isc::config::createAnswer()->toWire());
-    EXPECT_EQ(REJECT, server.getQueryACL().execute(createClient("192.0.2.1")));
+    EXPECT_EQ(REJECT, server.getQueryACL().execute(createRequest("192.0.2.1")));
     EXPECT_EQ(REJECT, server.getQueryACL().execute(
-                  createClient("2001:db8::1")));
+                  createRequest("2001:db8::1")));
 }
 
 TEST_F(ResolverConfig, queryACLIPv4) {
     // A simple "accept" query for a specific IPv4 address
-    ElementPtr config(Element::fromJSON(
-                          "{ \"query_acl\": "
-                          "  [ {\"action\": \"ACCEPT\","
-                          "     \"from\": \"192.0.2.1\"} ] }"));
+    ConstElementPtr config(Element::fromJSON(
+                               "{ \"query_acl\": "
+                               "  [ {\"action\": \"ACCEPT\","
+                               "     \"from\": \"192.0.2.1\"} ] }"));
     ConstElementPtr result(server.updateConfig(config));
     EXPECT_EQ(result->toWire(), isc::config::createAnswer()->toWire());
-    EXPECT_EQ(ACCEPT, server.getQueryACL().execute(createClient("192.0.2.1")));
+    EXPECT_EQ(ACCEPT, server.getQueryACL().execute(createRequest("192.0.2.1")));
     EXPECT_EQ(REJECT, server.getQueryACL().execute(
-                  createClient("2001:db8::1")));
+                  createRequest("2001:db8::1")));
 }
 
 TEST_F(ResolverConfig, queryACLIPv6) {
     // same for IPv6
-    ElementPtr config(Element::fromJSON(
-                          "{ \"query_acl\": "
-                          "  [ {\"action\": \"ACCEPT\","
-                          "     \"from\": \"2001:db8::1\"} ] }"));
+    ConstElementPtr config(Element::fromJSON(
+                               "{ \"query_acl\": "
+                               "  [ {\"action\": \"ACCEPT\","
+                               "     \"from\": \"2001:db8::1\"} ] }"));
     ConstElementPtr result(server.updateConfig(config));
     EXPECT_EQ(result->toWire(), isc::config::createAnswer()->toWire());
-    EXPECT_EQ(REJECT, server.getQueryACL().execute(createClient("192.0.2.1")));
+    EXPECT_EQ(REJECT, server.getQueryACL().execute(createRequest("192.0.2.1")));
     EXPECT_EQ(ACCEPT, server.getQueryACL().execute(
-                  createClient("2001:db8::1")));
+                  createRequest("2001:db8::1")));
 }
 
 TEST_F(ResolverConfig, multiEntryACL) {
@@ -306,25 +310,26 @@ TEST_F(ResolverConfig, multiEntryACL) {
     // as it should have been tested in the underlying ACL module.  All we
     // have to do to check is a reasonably complicated ACL configuration is
     // loaded as expected.
-    ElementPtr config(Element::fromJSON(
-                          "{ \"query_acl\": "
-                          "  [ {\"action\": \"ACCEPT\","
-                          "     \"from\": \"192.0.2.1\"},"
-                          "    {\"action\": \"REJECT\","
-                          "     \"from\": \"192.0.2.0/24\"},"
-                          "    {\"action\": \"DROP\","
-                          "     \"from\": \"2001:db8::1\"},"
-                          "] }"));
+    ConstElementPtr config(Element::fromJSON(
+                               "{ \"query_acl\": "
+                               "  [ {\"action\": \"ACCEPT\","
+                               "     \"from\": \"192.0.2.1\"},"
+                               "    {\"action\": \"REJECT\","
+                               "     \"from\": \"192.0.2.0/24\"},"
+                               "    {\"action\": \"DROP\","
+                               "     \"from\": \"2001:db8::1\"},"
+                               "] }"));
     ConstElementPtr result(server.updateConfig(config));
     EXPECT_EQ(result->toWire(), isc::config::createAnswer()->toWire());
-    EXPECT_EQ(ACCEPT, server.getQueryACL().execute(createClient("192.0.2.1")));
-    EXPECT_EQ(REJECT, server.getQueryACL().execute(createClient("192.0.2.2")));
+    EXPECT_EQ(ACCEPT, server.getQueryACL().execute(createRequest("192.0.2.1")));
+    EXPECT_EQ(REJECT, server.getQueryACL().execute(createRequest("192.0.2.2")));
     EXPECT_EQ(DROP, server.getQueryACL().execute(
-                  createClient("2001:db8::1")));
+                  createRequest("2001:db8::1")));
     EXPECT_EQ(REJECT, server.getQueryACL().execute(
-                  createClient("2001:db8::2"))); // match the default rule
+                  createRequest("2001:db8::2"))); // match the default rule
 }
 
+
 int
 getResultCode(ConstElementPtr result) {
     int rcode;
@@ -332,6 +337,22 @@ getResultCode(ConstElementPtr result) {
     return (rcode);
 }
 
+TEST_F(ResolverConfig, queryACLActionOnly) {
+    // "action only" rule will be accepted by the loader, which can
+    // effectively change the default action.
+    ConstElementPtr config(Element::fromJSON(
+                               "{ \"query_acl\": "
+                               "  [ {\"action\": \"ACCEPT\","
+                               "     \"from\": \"192.0.2.1\"},"
+                               "    {\"action\": \"DROP\"} ] }"));
+    EXPECT_EQ(0, getResultCode(server.updateConfig(config)));
+    EXPECT_EQ(ACCEPT, server.getQueryACL().execute(createRequest("192.0.2.1")));
+
+    // We reject non matching queries by default, but the last resort
+    // rule should have changed the action in that case to "DROP".
+    EXPECT_EQ(DROP, server.getQueryACL().execute(createRequest("192.0.2.2")));
+}
+
 TEST_F(ResolverConfig, badQueryACL) {
     // Most of these cases shouldn't happen in practice because the syntax
     // check should be performed before updateConfig().  But we check at
@@ -346,10 +367,6 @@ TEST_F(ResolverConfig, badQueryACL) {
                   server.updateConfig(
                       Element::fromJSON("{ \"query_acl\":"
                                         " [ {\"from\": \"192.0.2.1\"} ] }"))));
-    EXPECT_EQ(1, getResultCode(
-                  server.updateConfig(
-                      Element::fromJSON("{ \"query_acl\":"
-                                        " [ {\"action\": \"DROP\"} ] }"))));
     // invalid "action"
     EXPECT_EQ(1, getResultCode(
                   server.updateConfig(
@@ -361,7 +378,6 @@ TEST_F(ResolverConfig, badQueryACL) {
                       Element::fromJSON("{ \"query_acl\":"
                                         " [ {\"action\": \"BADACTION\","
                                         "    \"from\": \"192.0.2.1\"}]}"))));
-
     // invalid "from"
     EXPECT_EQ(1, getResultCode(
                   server.updateConfig(

src/bin/resolver/tests/resolver_unittest.cc

@@ -27,6 +27,7 @@
 using namespace std;
 using namespace isc::dns;
 using namespace isc::data;
+using isc::acl::dns::RequestACL;
 using namespace isc::testutils;
 using isc::UnitTestUtil;
 
@@ -156,8 +157,7 @@ TEST_F(ResolverTest, notifyFail) {
 TEST_F(ResolverTest, setQueryACL) {
     // valid cases are tested through other tests.  We only explicitly check
     // an invalid case: passing a NULL shared pointer.
-    EXPECT_THROW(server.setQueryACL(
-                     boost::shared_ptr<const Resolver::ClientACL>()),
+    EXPECT_THROW(server.setQueryACL(boost::shared_ptr<const RequestACL>()),
                  isc::InvalidParameter);
 }
 

src/lib/acl/dns.cc

@@ -12,20 +12,107 @@
 // OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
 // PERFORMANCE OF THIS SOFTWARE.
 
-#include "dns.h"
+#include <memory>
+#include <string>
+#include <vector>
+
+#include <boost/shared_ptr.hpp>
+
+#include <exceptions/exceptions.h>
+
+#include <cc/data.h>
+
+#include <acl/dns.h>
+#include <acl/ip_check.h>
+#include <acl/loader.h>
+#include <acl/logic_check.h>
+
+using namespace std;
+using boost::shared_ptr;
+using namespace isc::data;
 
 namespace isc {
 namespace acl {
+
+/// The specialization of \c IPCheck for access control with \c RequestContext.
+///
+/// It returns \c true if the remote (source) IP address of the request
+/// matches the expression encapsulated in the \c IPCheck, and returns
+/// \c false if not.
+///
+/// \note The match logic is expected to be extended as we add
+/// more match parameters (at least there's a plan for TSIG key).
+template <>
+bool
+IPCheck<dns::RequestContext>::matches(
+    const dns::RequestContext& request) const
+{
+    return (compare(request.remote_address.getData(),
+                    request.remote_address.getFamily()));
+}
+
 namespace dns {
 
-Loader&
-getLoader() {
-    static Loader* loader(NULL);
+vector<string>
+internal::RequestCheckCreator::names() const {
+    // Probably we should eventually build this vector in a more
+    // sophisticated way.  For now, it's simple enough to hardcode
+    // everything.
+    vector<string> supported_names;
+    supported_names.push_back("from");
+    return (supported_names);
+}
+
+shared_ptr<RequestCheck>
+internal::RequestCheckCreator::create(const string& name,
+                                      ConstElementPtr definition,
+                                      // unused:
+                                      const acl::Loader<RequestContext>&)
+{
+    if (!definition) {
+        isc_throw(LoaderError,
+                  "NULL pointer is passed to RequestCheckCreator");
+    }
+
+    if (name == "from") {
+        return (shared_ptr<internal::RequestIPCheck>(
+                    new internal::RequestIPCheck(definition->stringValue())));
+    } else {
+        // This case shouldn't happen (normally) as it should have been
+        // rejected at the loader level.  But we explicitly catch the case
+        // and throw an exception for that.
+        isc_throw(LoaderError, "Invalid check name for RequestCheck: " <<
+                  name);
+    }
+}
+
+RequestLoader&
+getRequestLoader() {
+    static RequestLoader* loader(NULL);
     if (loader == NULL) {
-        loader = new Loader(REJECT);
-        // TODO: This is the place where we register default check creators
-        // like IP check, etc, once we have them.
+        // Creator registration may throw, so we first store the new loader
+        // in an auto pointer in order to provide the strong exception
+        // guarantee.
+        auto_ptr<RequestLoader> loader_ptr =
+            auto_ptr<RequestLoader>(new RequestLoader(REJECT));
+
+        // Register default check creator(s)
+        loader_ptr->registerCreator(shared_ptr<internal::RequestCheckCreator>(
+                                        new internal::RequestCheckCreator()));
+        loader_ptr->registerCreator(
+            shared_ptr<NotCreator<RequestContext> >(
+                new NotCreator<RequestContext>("NOT")));
+        loader_ptr->registerCreator(
+            shared_ptr<LogicCreator<AnyOfSpec, RequestContext> >(
+                new LogicCreator<AnyOfSpec, RequestContext>("ANY")));
+        loader_ptr->registerCreator(
+            shared_ptr<LogicCreator<AllOfSpec, RequestContext> >(
+                new LogicCreator<AllOfSpec, RequestContext>("ALL")));
+
+        // From this point there shouldn't be any exception thrown
+        loader = loader_ptr.release();
     }
+
     return (*loader);
 }
 

src/lib/acl/dns.h

@@ -13,12 +13,17 @@
 // PERFORMANCE OF THIS SOFTWARE.
 
 #ifndef ACL_DNS_H
-#define ACL_DNS_H
+#define ACL_DNS_H 1
 
-#include "loader.h"
+#include <string>
+#include <vector>
 
-#include <asiolink/io_address.h>
-#include <dns/message.h>
+#include <boost/shared_ptr.hpp>
+
+#include <cc/data.h>
+
+#include <acl/ip_check.h>
+#include <acl/loader.h>
 
 namespace isc {
 namespace acl {
@@ -30,47 +35,65 @@ namespace dns {
  * This plays the role of Context of the generic template ACLs (in namespace
  * isc::acl).
  *
- * It is simple structure holding just the bunch of information. Therefore
- * the names don't end up with a slash, there are no methods so they can't be
- * confused with local variables.
+ * It is a simple structure holding just the bunch of information. Therefore
+ * the names don't end up with an underscore; there are no methods so they
+ * can't be confused with local variables.
+ *
+ * This structure is generally expected to be ephemeral and read-only: It
+ * would be constructed immediately before a particular ACL is checked
+ * and used only for the ACL match purposes.  Due to this nature, and since
+ * ACL processing is often performance sensitive (typically it's performed
+ * against all incoming packets), the construction is designed to be
+ * lightweight: it tries to avoid expensive data copies or dynamic memory
+ * allocation as much as possible.  Specifically, the constructor can
+ * take a pointer or reference to an object and keeps it as a reference
+ * (not making a local copy).  This also means the caller is responsible for
+ * keeping the passed parameters valid while this structure is used.
+ * This should generally be reasonable as this structure is expected to be
+ * used only for a very short period as stated above.
  *
- * \todo Do we want a constructor to set this in a shorter manner? So we can
- *     call the ACLs directly?
+ * Based on the minimalist philosophy, the initial implementation only
+ * maintains the remote (source) IP address of the request.  The plan is
+ * to add more parameters of the request.  A scheduled next step is to
+ * support the TSIG key (if it's included in the request).  Other possibilities
+ * are the local (destination) IP address, the remote and local port numbers,
+ * various fields of the DNS request (e.g. a particular header flag value).
  */
 struct RequestContext {
-    /// \brief The DNS message (payload).
-    isc::dns::ConstMessagePtr message;
-    /// \brief The remote IP address (eg. the client).
-    asiolink::IOAddress remote_address;
-    /// \brief The local IP address (ours, of the interface where we received).
-    asiolink::IOAddress local_address;
-    /// \brief The remote port.
-    uint16_t remote_port;
-    /// \brief The local port.
-    uint16_t local_port;
-    /**
-     * \brief Name of the TSIG key the message is signed with.
-     *
-     * This will be either the name of the TSIG key the message is signed with,
-     * or empty string, if the message is not signed. It is true we could get
-     * the information from the message itself, but because at the time when
-     * the ACL is checked, the signature has been verified already, so passing
-     * it around is probably cheaper.
-     *
-     * It is expected that messages with invalid signatures are handled before
-     * ACL.
-     */
-    std::string tsig_key_name;
+    /// The constructor
+    ///
+    /// This is a trivial constructor that perform straightforward
+    /// initialization of the member variables from the given parameters.
+    ///
+    /// \exception None
+    ///
+    /// \parameter remote_address_param The remote IP address
+    explicit RequestContext(const IPAddress& remote_address_param) :
+        remote_address(remote_address_param)
+    {}
+
+    ///
+    /// \name Parameter variables
+    ///
+    /// These member variables must be immutable so that the integrity of
+    /// the structure is kept throughout its lifetime.  The easiest way is
+    /// to declare the variable as const.  If it's not possible for a
+    /// particular variable, it must be defined as private and accessible
+    /// only via an accessor method.
+    //@{
+    /// \brief The remote IP address (eg. the client's IP address).
+    const IPAddress& remote_address;
+    //@}
 };
 
 /// \brief DNS based check.
-typedef acl::Check<RequestContext> Check;
+typedef acl::Check<RequestContext> RequestCheck;
 /// \brief DNS based compound check.
 typedef acl::CompoundCheck<RequestContext> CompoundCheck;
 /// \brief DNS based ACL.
-typedef acl::ACL<RequestContext> ACL;
+typedef acl::ACL<RequestContext> RequestACL;
 /// \brief DNS based ACL loader.
-typedef acl::Loader<RequestContext> Loader;
+typedef acl::Loader<RequestContext> RequestLoader;
 
 /**
  * \brief Loader singleton access function.
@@ -80,10 +103,38 @@ typedef acl::Loader<RequestContext> Loader;
  * one is enough, this one will have registered default checks and it
  * is known one, so any plugins can registrer additional checks as well.
  */
-Loader& getLoader();
+RequestLoader& getRequestLoader();
+
+// The following is essentially private to the implementation and could
+// be hidden in the implementation file.  But it's visible via this header
+// file for testing purposes.  They are not supposed to be used by normal
+// applications directly, and to signal the intent, they are given inside
+// a separate namespace.
+namespace internal {
+
+// Shortcut typedef
+typedef isc::acl::IPCheck<RequestContext> RequestIPCheck;
 
-}
-}
-}
+class RequestCheckCreator : public acl::Loader<RequestContext>::CheckCreator {
+public:
+    virtual std::vector<std::string> names() const;
+
+    virtual boost::shared_ptr<RequestCheck>
+    create(const std::string& name, isc::data::ConstElementPtr definition,
+           const acl::Loader<RequestContext>& loader);
+
+    /// Until we are sure how the various rules work for this case, we won't
+    /// allow unexpected special interpretation for list definitions.
+    virtual bool allowListAbbreviation() const { return (false); }
+};
+} // end of namespace "internal"
+
+} // end of namespace "dns"
+} // end of namespace "acl"
+} // end of namespace "isc"
 
 #endif
+
+// Local Variables:
+// mode: c++
+// End:

src/lib/acl/loader.h

@@ -15,7 +15,8 @@
 #ifndef ACL_LOADER_H
 #define ACL_LOADER_H
 
-#include "acl.h"
+#include <exceptions/exceptions.h>
+#include <acl/acl.h>
 #include <cc/data.h>
 #include <boost/function.hpp>
 #include <boost/shared_ptr.hpp>
@@ -81,7 +82,7 @@ public:
  * or if it doesn't contain one of the accepted values.
  *
  * \param action The JSON representation of the action. It must be a string
- *     and contain one of "ACCEPT", "REJECT" or "DENY".
+ *     and contain one of "ACCEPT", "REJECT" or "DROP.
  * \note We could define different names or add aliases if needed.
  */
 BasicAction defaultActionLoader(data::ConstElementPtr action);
@@ -297,16 +298,28 @@ public:
      * \brief Load an ACL.
      *
      * This parses an ACL list, creates the checks and actions of each element
-     * and returns it. It may throw LoaderError if it isn't a list or the
-     * "action" key is missing in some element. Also, no exceptions from
-     * loadCheck (therefore from whatever creator is used) and from the
-     * actionLoader passed to constructor are not caught.
+     * and returns it.
+     *
+     * No exceptions from \c loadCheck (therefore from whatever creator is
+     * used) and from the actionLoader passed to constructor are caught.
+     *
+     * \exception InvalidParameter The given element is NULL (most likely a
+     * caller's bug)
+     * \exception LoaderError The given element isn't a list or the
+     * "action" key is missing in some element
      *
      * \param description The JSON list of ACL.
+     *
+     * \return The newly created ACL object
      */
     boost::shared_ptr<ACL<Context, Action> > load(const data::ConstElementPtr&
                                                   description) const
     {
+        if (!description) {
+            isc_throw(isc::InvalidParameter,
+                      "Null description is passed to ACL loader");
+        }
+
         // We first check it's a list, so we can use the list reference
         // (the list may be huge)
         if (description->getType() != data::Element::list) {
@@ -460,3 +473,7 @@ private:
 #include "logic_check.h"
 
 #endif
+
+// Local Variables:
+// mode: c++
+// End:

src/lib/acl/logic_check.h

@@ -200,6 +200,86 @@ private:
     const std::string name_;
 };
 
+/**
+ * \brief The NOT operator for ACLs.
+ *
+ * This simply returns the negation of whatever returns the subexpression.
+ */
+template<typename Context>
+class NotOperator : public CompoundCheck<Context> {
+public:
+    /**
+     * \brief Constructor
+     *
+     * \param expr The subexpression to be negated by this NOT.
+     */
+    NotOperator(const boost::shared_ptr<Check<Context> >& expr) :
+        expr_(expr)
+    { }
+    /**
+     * \brief The list of subexpressions
+     *
+     * \return The vector will contain single value and it is the expression
+     *     passed by constructor.
+     */
+    virtual typename CompoundCheck<Context>::Checks getSubexpressions() const {
+        typename CompoundCheck<Context>::Checks result;
+        result.push_back(expr_.get());
+        return (result);
+    }
+    /// \brief The matching function
+    virtual bool matches(const Context& context) const {
+        return (!expr_->matches(context));
+    }
+private:
+    /// \brief The subexpression
+    const boost::shared_ptr<Check<Context> > expr_;
+};
+
+template<typename Context, typename Action = BasicAction>
+class NotCreator : public Loader<Context, Action>::CheckCreator {
+public:
+    /**
+     * \brief Constructor
+     *
+     * \param name The name of the NOT operator to be loaded as.
+     */
+    NotCreator(const std::string& name) :
+        name_(name)
+    { }
+    /**
+     * \brief List of the names this loads
+     *
+     * \return Single-value vector containing the name passed to the
+     *     constructor.
+     */
+    virtual std::vector<std::string> names() const {
+        std::vector<std::string> result;
+        result.push_back(name_);
+        return (result);
+    }
+    /// \brief Create the check.
+    virtual boost::shared_ptr<Check<Context> > create(const std::string&,
+                                                      data::ConstElementPtr
+                                                      definition,
+                                                      const Loader<Context,
+                                                      Action>& loader)
+    {
+        return (boost::shared_ptr<Check<Context> >(new NotOperator<Context>(
+                    loader.loadCheck(definition))));
+    }
+    /**
+     * \brief Or-abbreviated form.
+     *
+     * This returns false. In theory, the NOT operator could be used with
+     * the abbreviated form, but it would be confusing. Such syntax is
+     * therefore explicitly forbidden.
+     */
+    virtual bool allowListAbbreviation() const { return (false); }
+public:
+    const std::string name_;
+};
+
 }
 }
 

src/lib/acl/tests/Makefile.am

@@ -20,6 +20,7 @@ run_unittests_SOURCES += loader_test.cc
 run_unittests_SOURCES += logcheck.h
 run_unittests_SOURCES += creators.h
 run_unittests_SOURCES += logic_check_test.cc
+run_unittests_SOURCES += sockaddr.h
 
 run_unittests_CPPFLAGS = $(AM_CPPFLAGS) $(GTEST_INCLUDES)
 run_unittests_LDFLAGS = $(AM_LDFLAGS) $(GTEST_LDFLAGS)

src/lib/acl/tests/dns_test.cc

@@ -12,24 +12,194 @@
 // OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
 // PERFORMANCE OF THIS SOFTWARE.
 
+#include <stdint.h>
+
+#include <algorithm>
+#include <vector>
+#include <string>
+
+#include <boost/scoped_ptr.hpp>
+#include <boost/shared_ptr.hpp>
+
+#include <exceptions/exceptions.h>
+
+#include <cc/data.h>
 #include <acl/dns.h>
+#include <acl/loader.h>
+#include <acl/check.h>
+#include <acl/ip_check.h>
+
+#include "sockaddr.h"
+
 #include <gtest/gtest.h>
 
+using namespace std;
+using boost::scoped_ptr;
+using namespace isc::data;
+using namespace isc::acl;
 using namespace isc::acl::dns;
+using isc::acl::LoaderError;
 
 namespace {
 
-// Tests that the getLoader actually returns something, returns the same every
-// time and the returned value can be used to anything. It is not much of a
-// test, but the getLoader is not much of a function.
-TEST(DNSACL, getLoader) {
-    Loader* l(&getLoader());
+TEST(DNSACL, getRequestLoader) {
+    dns::RequestLoader* l(&getRequestLoader());
     ASSERT_TRUE(l != NULL);
-    EXPECT_EQ(l, &getLoader());
-    EXPECT_NO_THROW(l->load(isc::data::Element::fromJSON(
-        "[{\"action\": \"DROP\"}]")));
-    // TODO Test that the things we should register by default, like IP based
-    // check, are loaded.
+    EXPECT_EQ(l, &getRequestLoader());
+    EXPECT_NO_THROW(l->load(Element::fromJSON("[{\"action\": \"DROP\"}]")));
+
+    // Confirm it can load the ACl syntax acceptable to a default creator.
+    // Tests to see whether the loaded rules work correctly will be in
+    // other dedicated tests below.
+    EXPECT_NO_THROW(l->load(Element::fromJSON("[{\"action\": \"DROP\","
+                                              "  \"from\": \"192.0.2.1\"}]")));
+}
+
+class RequestCheckCreatorTest : public ::testing::Test {
+protected:
+    dns::internal::RequestCheckCreator creator_;
+
+    typedef boost::shared_ptr<const dns::RequestCheck> ConstRequestCheckPtr;
+    ConstRequestCheckPtr check_;
+};
+
+TEST_F(RequestCheckCreatorTest, names) {
+    ASSERT_EQ(1, creator_.names().size());
+    EXPECT_EQ("from", creator_.names()[0]);
+}
+
+TEST_F(RequestCheckCreatorTest, allowListAbbreviation) {
+    EXPECT_FALSE(creator_.allowListAbbreviation());
+}
+
+// The following two tests check the creator for the form of
+// 'from: "IP prefix"'.  We don't test many variants of prefixes, which
+// are done in the tests for IPCheck.
+TEST_F(RequestCheckCreatorTest, createIPv4Check) {
+    check_ = creator_.create("from", Element::fromJSON("\"192.0.2.1\""),
+                             getRequestLoader());
+    const dns::internal::RequestIPCheck& ipcheck_ =
+        dynamic_cast<const dns::internal::RequestIPCheck&>(*check_);
+    EXPECT_EQ(AF_INET, ipcheck_.getFamily());
+    EXPECT_EQ(32, ipcheck_.getPrefixlen());
+    const vector<uint8_t> check_address(ipcheck_.getAddress());
+    ASSERT_EQ(4, check_address.size());
+    const uint8_t expected_address[] = { 192, 0, 2, 1 };
+    EXPECT_TRUE(equal(check_address.begin(), check_address.end(),
+                      expected_address));
+}
+
+TEST_F(RequestCheckCreatorTest, createIPv6Check) {
+    check_ = creator_.create("from",
+                             Element::fromJSON("\"2001:db8::5300/120\""),
+                             getRequestLoader());
+    const dns::internal::RequestIPCheck& ipcheck_ =
+        dynamic_cast<const dns::internal::RequestIPCheck&>(*check_);
+    EXPECT_EQ(AF_INET6, ipcheck_.getFamily());
+    EXPECT_EQ(120, ipcheck_.getPrefixlen());
+    const vector<uint8_t> check_address(ipcheck_.getAddress());
+    ASSERT_EQ(16, check_address.size());
+    const uint8_t expected_address[] = { 0x20, 0x01, 0x0d, 0xb8, 0x00, 0x00,
+                                         0x00, 0x00, 0x00, 0x00, 0x00, 0x00,
+                                         0x00, 0x00, 0x53, 0x00 };
+    EXPECT_TRUE(equal(check_address.begin(), check_address.end(),
+                      expected_address));
+}
+
+TEST_F(RequestCheckCreatorTest, badCreate) {
+    // Invalid name
+    EXPECT_THROW(creator_.create("bad", Element::fromJSON("\"192.0.2.1\""),
+                                 getRequestLoader()), LoaderError);
+
+    // Invalid type of parameter
+    EXPECT_THROW(creator_.create("from", Element::fromJSON("4"),
+                                 getRequestLoader()),
+                 isc::data::TypeError);
+    EXPECT_THROW(creator_.create("from", Element::fromJSON("[]"),
+                                 getRequestLoader()),
+                 isc::data::TypeError);
+
+    // Syntax error for IPCheck
+    EXPECT_THROW(creator_.create("from", Element::fromJSON("\"bad\""),
+                                 getRequestLoader()),
+                 isc::InvalidParameter);
+
+    // NULL pointer
+    EXPECT_THROW(creator_.create("from", ConstElementPtr(), getRequestLoader()),
+                 LoaderError);
+}
+
+class RequestCheckTest : public ::testing::Test {
+protected:
+    typedef boost::shared_ptr<const dns::RequestCheck> ConstRequestCheckPtr;
+
+    // A helper shortcut to create a single IP check for the given prefix.
+    ConstRequestCheckPtr createIPCheck(const string& prefix) {
+        return (creator_.create("from", Element::fromJSON(
+                                    string("\"") + prefix + string("\"")),
+                                getRequestLoader()));
+    }
+
+    // create a one time request context for a specific test.  Note that
+    // getSockaddr() uses a static storage, so it cannot be called more than
+    // once in a single test.
+    const dns::RequestContext& getRequest4() {
+        ipaddr.reset(new IPAddress(tests::getSockAddr("192.0.2.1")));
+        request.reset(new dns::RequestContext(*ipaddr));
+        return (*request);
+    }
+    const dns::RequestContext& getRequest6() {
+        ipaddr.reset(new IPAddress(tests::getSockAddr("2001:db8::1")));
+        request.reset(new dns::RequestContext(*ipaddr));
+        return (*request);
+    }
+
+private:
+    scoped_ptr<IPAddress> ipaddr;
+    scoped_ptr<dns::RequestContext> request;
+    dns::internal::RequestCheckCreator creator_;
+};
+
+TEST_F(RequestCheckTest, checkIPv4) {
+    // Exact match
+    EXPECT_TRUE(createIPCheck("192.0.2.1")->matches(getRequest4()));
+    // Exact match (negative)
+    EXPECT_FALSE(createIPCheck("192.0.2.53")->matches(getRequest4()));
+    // Prefix match
+    EXPECT_TRUE(createIPCheck("192.0.2.0/24")->matches(getRequest4()));
+    // Prefix match (negative)
+    EXPECT_FALSE(createIPCheck("192.0.1.0/24")->matches(getRequest4()));
+    // Address family mismatch (the first 4 bytes of the IPv6 address has the
+    // same binary representation as the client's IPv4 address, which
+    // shouldn't confuse the match logic)
+    EXPECT_FALSE(createIPCheck("c000:0201::")->matches(getRequest4()));
+}
+
+TEST_F(RequestCheckTest, checkIPv6) {
+    // The following are a set of tests of the same concept as checkIPv4
+    EXPECT_TRUE(createIPCheck("2001:db8::1")->matches(getRequest6()));
+    EXPECT_FALSE(createIPCheck("2001:db8::53")->matches(getRequest6()));
+    EXPECT_TRUE(createIPCheck("2001:db8::/64")->matches(getRequest6()));
+    EXPECT_FALSE(createIPCheck("2001:db8:1::/64")->matches(getRequest6()));
+    EXPECT_FALSE(createIPCheck("32.1.13.184")->matches(getRequest6()));
+}
+
+// The following tests test only the creators are registered, they are tested
+// elsewhere
+
+TEST(DNSACL, notLoad) {
+    EXPECT_NO_THROW(getRequestLoader().loadCheck(isc::data::Element::fromJSON(
+        "{\"NOT\": {\"from\": \"192.0.2.1\"}}")));
+}
+
+TEST(DNSACL, allLoad) {
+    EXPECT_NO_THROW(getRequestLoader().loadCheck(isc::data::Element::fromJSON(
+        "{\"ALL\": [{\"from\": \"192.0.2.1\"}]}")));
+}
+
+TEST(DNSACL, anyLoad) {
+    EXPECT_NO_THROW(getRequestLoader().loadCheck(isc::data::Element::fromJSON(
+        "{\"ANY\": [{\"from\": \"192.0.2.1\"}]}")));
 }
 
 }

src/lib/acl/tests/ip_check_unittest.cc

@@ -14,12 +14,13 @@
 
 #include <sys/types.h>
 #include <sys/socket.h>
-#include <netdb.h>
 #include <string.h>
 
 #include <gtest/gtest.h>
 #include <acl/ip_check.h>
 
+#include "sockaddr.h"
+
 using namespace isc::acl;
 using namespace isc::acl::internal;
 using namespace std;
@@ -159,32 +160,8 @@ TEST(IPFunctionCheck, SplitIPAddress) {
     EXPECT_THROW(splitIPAddress(" 1/ "), isc::InvalidParameter);
 }
 
-const struct sockaddr&
-getSockAddr(const char* const addr) {
-    struct addrinfo hints, *res;
-    memset(&hints, 0, sizeof(hints));
-    hints.ai_family = AF_UNSPEC;
-    hints.ai_socktype = SOCK_STREAM;
-    hints.ai_flags = AI_NUMERICHOST;
-
-    if (getaddrinfo(addr, NULL, &hints, &res) == 0) {
-        static struct sockaddr_storage ss;
-        void* ss_ptr = &ss;
-        memcpy(ss_ptr, res->ai_addr, res->ai_addrlen);
-        freeaddrinfo(res);
-        return (*static_cast<struct sockaddr*>(ss_ptr));
-    }
-
-    // We don't expect getaddrinfo to fail for our tests.  But if that
-    // ever happens we return a dummy value that would make subsequent test
-    // fail.
-    static struct sockaddr sa_dummy;
-    sa_dummy.sa_family = AF_UNSPEC;
-    return (sa_dummy);
-}
-
 TEST(IPAddress, constructIPv4) {
-    IPAddress ipaddr(getSockAddr("192.0.2.1"));
+    IPAddress ipaddr(tests::getSockAddr("192.0.2.1"));
     const char expected_data[4] = { 192, 0, 2, 1 };
     EXPECT_EQ(AF_INET, ipaddr.getFamily());
     EXPECT_EQ(4, ipaddr.getLength());
@@ -192,7 +169,7 @@ TEST(IPAddress, constructIPv4) {
 }
 
 TEST(IPAddress, constructIPv6) {
-    IPAddress ipaddr(getSockAddr("2001:db8:1234:abcd::53"));
+    IPAddress ipaddr(tests::getSockAddr("2001:db8:1234:abcd::53"));
     const char expected_data[16] = { 0x20, 0x01, 0x0d, 0xb8, 0x12, 0x34, 0xab,
                                      0xcd, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00,
                                      0x00, 0x53 };

src/lib/acl/tests/loader_test.cc

@@ -13,6 +13,7 @@
 // PERFORMANCE OF THIS SOFTWARE.
 
 #include "creators.h"
+#include <exceptions/exceptions.h>
 #include <acl/loader.h>
 #include <string>
 #include <gtest/gtest.h>
@@ -373,7 +374,10 @@ TEST_F(LoaderTest, ACLPropagate) {
                      Element::fromJSON(
                          "[{\"action\": \"ACCEPT\", \"throw\": 1}]")),
                  TestCreatorError);
+}
 
+TEST_F(LoaderTest, nullDescription) {
+    EXPECT_THROW(loader_.load(ConstElementPtr()), isc::InvalidParameter);
 }
 
 }

src/lib/acl/tests/logic_check_test.cc

@@ -93,6 +93,7 @@ public:
             LogicCreator<AllOfSpec, Log>("ALL")));
         loader_.registerCreator(CreatorPtr(new ThrowCreator));
         loader_.registerCreator(CreatorPtr(new LogCreator));
+        loader_.registerCreator(CreatorPtr(new NotCreator<Log>("NOT")));
     }
     // To mark which parts of the check did run
     Log log_;
@@ -242,4 +243,49 @@ TEST_F(LogicCreatorTest, nested) {
     log_.checkFirst(2);
 }
 
+void notTest(bool value) {
+    NotOperator<Log> notOp(shared_ptr<Check<Log> >(new ConstCheck(value, 0)));
+    Log log;
+    // It returns negated value
+    EXPECT_EQ(!value, notOp.matches(log));
+    // And runs the only one thing there
+    log.checkFirst(1);
+    // Check the getSubexpressions does sane things
+    ASSERT_EQ(1, notOp.getSubexpressions().size());
+    EXPECT_EQ(value, notOp.getSubexpressions()[0]->matches(log));
+}
+
+TEST(Not, trueValue) {
+    notTest(true);
+}
+
+TEST(Not, falseValue) {
+    notTest(false);
+}
+
+TEST_F(LogicCreatorTest, notInvalid) {
+    EXPECT_THROW(loader_.loadCheck(Element::fromJSON("{\"NOT\": null}")),
+                 LoaderError);
+    EXPECT_THROW(loader_.loadCheck(Element::fromJSON("{\"NOT\": \"hello\"}")),
+                 LoaderError);
+    EXPECT_THROW(loader_.loadCheck(Element::fromJSON("{\"NOT\": true}")),
+                 LoaderError);
+    EXPECT_THROW(loader_.loadCheck(Element::fromJSON("{\"NOT\": 42}")),
+                 LoaderError);
+    EXPECT_THROW(loader_.loadCheck(Element::fromJSON("{\"NOT\": []}")),
+                 LoaderError);
+    EXPECT_THROW(loader_.loadCheck(Element::fromJSON("{\"NOT\": [{"
+                                                     "\"logcheck\": [0, true]"
+                                                     "}]}")),
+                 LoaderError);
+}
+
+TEST_F(LogicCreatorTest, notValid) {
+    shared_ptr<NotOperator<Log> > notOp(load<NotOperator<Log> >("{\"NOT\":"
+                                                                "  {\"logcheck\":"
+                                                                "     [0, true]}}"));
+    EXPECT_FALSE(notOp->matches(log_));
+    log_.checkFirst(1);
+}
+
 }

src/lib/acl/tests/sockaddr.h

@@ -0,0 +1,69 @@
+// 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_TEST_SOCKADDR_H
+#define __ACL_TEST_SOCKADDR_H 1
+
+#include <sys/types.h>
+#include <sys/socket.h>
+#include <netdb.h>
+#include <string.h>
+
+#include <exceptions/exceptions.h>
+
+namespace isc {
+namespace acl {
+namespace tests {
+
+// This is a helper function that returns a sockaddr for the given textual
+// IP address.  Note that "inline" is crucial because this function is defined
+// in a header file included in multiple .cc files.  Without inline it would
+// produce an external linkage and cause troubles at link time.
+//
+// Note that this function uses a static storage for the return value.
+// So if it's called more than once in a singe context (e.g., in the same
+// EXPECT_xx()), it's unlikely to work as expected.
+inline const struct sockaddr&
+getSockAddr(const char* const addr) {
+    struct addrinfo hints, *res;
+    memset(&hints, 0, sizeof(hints));
+    hints.ai_family = AF_UNSPEC;
+    hints.ai_socktype = SOCK_STREAM;
+    hints.ai_flags = AI_NUMERICHOST;
+
+    if (getaddrinfo(addr, NULL, &hints, &res) == 0) {
+        static struct sockaddr_storage ss;
+        void* ss_ptr = &ss;
+        memcpy(ss_ptr, res->ai_addr, res->ai_addrlen);
+        freeaddrinfo(res);
+        return (*static_cast<struct sockaddr*>(ss_ptr));
+    }
+
+    // We don't expect getaddrinfo to fail for our tests.  But if that
+    // ever happens we throw an exception to make sure the corresponding test
+    // fail (either due to a failure of *_NO_THROW or the uncaught exception).
+    isc_throw(Unexpected,
+              "failed to convert textual IP address to sockaddr for " <<
+              addr);
+}
+
+} // end of namespace "tests"
+} // end of namespace "acl"
+} // end of namespace "isc"
+
+#endif  // __ACL_TEST_SOCKADDR_H
+
+// Local Variables:
+// mode: c++
+// End:

src/lib/cache/Makefile.am

@@ -31,5 +31,14 @@ libcache_la_SOURCES  += cache_entry_key.h cache_entry_key.cc
 libcache_la_SOURCES  += rrset_copy.h rrset_copy.cc
 libcache_la_SOURCES  += local_zone_data.h local_zone_data.cc
 libcache_la_SOURCES  += message_utility.h message_utility.cc
+libcache_la_SOURCES  += logger.h logger.cc
+nodist_libcache_la_SOURCES = cache_messages.cc cache_messages.h
 
-CLEANFILES = *.gcno *.gcda
+BUILT_SOURCES = cache_messages.cc cache_messages.h
+
+cache_messages.cc cache_messages.h: cache_messages.mes
+	$(top_builddir)/src/lib/log/compiler/message $(top_srcdir)/src/lib/cache/cache_messages.mes
+
+CLEANFILES = *.gcno *.gcda cache_messages.cc cache_messages.h
+
+EXTRA_DIST = cache_messages.mes

src/lib/cache/cache_messages.mes

@@ -0,0 +1,148 @@
+# Copyright (C) 2010  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.
+
+$NAMESPACE isc::cache
+
+% CACHE_ENTRY_MISSING_RRSET missing RRset to generate message for %1
+The cache tried to generate the complete answer message. It knows the structure
+of the message, but some of the RRsets to be put there are not in cache (they
+probably expired already). Therefore it pretends the message was not found.
+
+% CACHE_LOCALZONE_FOUND found entry with key %1 in local zone data
+Debug message, noting that the requested data was successfully found in the
+local zone data of the cache.
+
+% CACHE_LOCALZONE_UNKNOWN entry with key %1 not found in local zone data
+Debug message. The requested data was not found in the local zone data.
+
+% CACHE_LOCALZONE_UPDATE updating local zone element at key %1
+Debug message issued when there's update to the local zone section of cache.
+
+% CACHE_MESSAGES_DEINIT deinitialized message cache
+Debug message. It is issued when the server deinitializes the message cache.
+
+% CACHE_MESSAGES_EXPIRED found an expired message entry for %1 in the message cache
+Debug message. The requested data was found in the message cache, but it
+already expired. Therefore the cache removes the entry and pretends it found
+nothing.
+
+% CACHE_MESSAGES_FOUND found a message entry for %1 in the message cache
+Debug message. We found the whole message in the cache, so it can be returned
+to user without any other lookups.
+
+% CACHE_MESSAGES_INIT initialized message cache for %1 messages of class %2
+Debug message issued when a new message cache is issued. It lists the class
+of messages it can hold and the maximum size of the cache.
+
+% CACHE_MESSAGES_REMOVE removing old instance of %1/%2/%3 first
+Debug message. This may follow CACHE_MESSAGES_UPDATE and indicates that, while
+updating, the old instance is being removed prior of inserting a new one.
+
+% CACHE_MESSAGES_UNCACHEABLE not inserting uncacheable message %1/%2/%3
+Debug message, noting that the given message can not be cached. This is because
+there's no SOA record in the message. See RFC 2308 section 5 for more
+information.
+
+% CACHE_MESSAGES_UNKNOWN no entry for %1 found in the message cache
+Debug message. The message cache didn't find any entry for the given key.
+
+% CACHE_MESSAGES_UPDATE updating message entry %1/%2/%3
+Debug message issued when the message cache is being updated with a new
+message. Either the old instance is removed or, if none is found, new one
+is created.
+
+% CACHE_RESOLVER_DEEPEST looking up deepest NS for %1/%2
+Debug message. The resolver cache is looking up the deepest known nameserver,
+so the resolution doesn't have to start from the root.
+
+% CACHE_RESOLVER_INIT_INFO initializing resolver cache for class %1
+Debug message, the resolver cache is being created for this given class. The
+difference from CACHE_RESOLVER_INIT is only in different format of passed
+information, otherwise it does the same.
+
+% CACHE_RESOLVER_INIT initializing resolver cache for class %1
+Debug message. The resolver cache is being created for this given class.
+
+% CACHE_RESOLVER_LOCAL_MSG message for %1/%2 found in local zone data
+Debug message. The resolver cache found a complete message for the user query
+in the zone data.
+
+% CACHE_RESOLVER_LOCAL_RRSET RRset for %1/%2 found in local zone data
+Debug message. The resolver cache found a requested RRset in the local zone
+data.
+
+% CACHE_RESOLVER_LOOKUP_MSG looking up message in resolver cache for %1/%2
+Debug message. The resolver cache is trying to find a message to answer the
+user query.
+
+% CACHE_RESOLVER_LOOKUP_RRSET looking up RRset in resolver cache for %1/%2
+Debug message. The resolver cache is trying to find an RRset (which usually
+originates as internally from resolver).
+
+% CACHE_RESOLVER_NO_QUESTION answer message for %1/%2 has empty question section
+The cache tried to fill in found data into the response message. But it
+discovered the message contains no question section, which is invalid.
+This is likely a programmer error, please submit a bug report.
+
+% CACHE_RESOLVER_UNKNOWN_CLASS_MSG no cache for class %1
+Debug message. While trying to lookup a message in the resolver cache, it was
+discovered there's no cache for this class at all. Therefore no message is
+found.
+
+% CACHE_RESOLVER_UNKNOWN_CLASS_RRSET no cache for class %1
+Debug message. While trying to lookup an RRset in the resolver cache, it was
+discovered there's no cache for this class at all. Therefore no data is found.
+
+% CACHE_RESOLVER_UPDATE_MSG updating message for %1/%2/%3
+Debug message. The resolver is updating a message in the cache.
+
+% CACHE_RESOLVER_UPDATE_RRSET updating RRset for %1/%2/%3
+Debug message. The resolver is updating an RRset in the cache.
+
+% CACHE_RESOLVER_UPDATE_UNKNOWN_CLASS_MSG no cache for class %1
+Debug message. While trying to insert a message into the cache, it was
+discovered that there's no cache for the class of message. Therefore
+the message will not be cached.
+
+% CACHE_RESOLVER_UPDATE_UNKNOWN_CLASS_RRSET no cache for class %1
+Debug message. While trying to insert an RRset into the cache, it was
+discovered that there's no cache for the class of the RRset. Therefore
+the message will not be cached.
+
+% CACHE_RRSET_EXPIRED found expired RRset %1/%2/%3
+Debug message. The requested data was found in the RRset cache. However, it is
+expired, so the cache removed it and is going to pretend nothing was found.
+
+% CACHE_RRSET_INIT initializing RRset cache for %2 RRsets of class %1
+Debug message. The RRset cache to hold at most this many RRsets for the given
+class is being created.
+
+% CACHE_RRSET_LOOKUP looking up %1/%2/%3 in RRset cache
+Debug message. The resolver is trying to look up data in the RRset cache.
+
+% CACHE_RRSET_NOT_FOUND no RRset found for %1/%2/%3
+Debug message which can follow CACHE_RRSET_LOOKUP. This means the data is not
+in the cache.
+
+% CACHE_RRSET_REMOVE_OLD removing old RRset for %1/%2/%3 to make space for new one
+Debug message which can follow CACHE_RRSET_UPDATE. During the update, the cache
+removed an old instance of the RRset to replace it with the new one.
+
+% CACHE_RRSET_UNTRUSTED not replacing old RRset for %1/%2/%3, it has higher trust level
+Debug message which can follow CACHE_RRSET_UPDATE. The cache already holds the
+same RRset, but from more trusted source, so the old one is kept and new one
+ignored.
+
+% CACHE_RRSET_UPDATE updating RRset %1/%2/%3 in the cache
+Debug message. The RRset is updating its data with this given RRset.

src/lib/cache/local_zone_data.cc

@@ -16,6 +16,7 @@
 #include "local_zone_data.h"
 #include "cache_entry_key.h"
 #include "rrset_copy.h"
+#include "logger.h"
 
 using namespace std;
 using namespace isc::dns;
@@ -33,8 +34,10 @@ LocalZoneData::lookup(const isc::dns::Name& name,
     string key = genCacheEntryName(name, type);
     RRsetMapIterator iter = rrsets_map_.find(key);
     if (iter == rrsets_map_.end()) {
+        LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_LOCALZONE_UNKNOWN).arg(key);
         return (RRsetPtr());
     } else {
+        LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_LOCALZONE_FOUND).arg(key);
         return (iter->second);
     }
 }
@@ -43,6 +46,7 @@ void
 LocalZoneData::update(const isc::dns::RRset& rrset) {
     //TODO Do we really need to recreate the rrset again?
     string key = genCacheEntryName(rrset.getName(), rrset.getType());
+    LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_LOCALZONE_UPDATE).arg(key);
     RRset* rrset_copy = new RRset(rrset.getName(), rrset.getClass(),
                                   rrset.getType(), rrset.getTTL());
 

src/lib/cache/logger.cc

@@ -0,0 +1,23 @@
+// 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 <cache/logger.h>
+
+namespace isc {
+namespace cache {
+
+isc::log::Logger logger("cache");
+
+}
+}

src/lib/cache/logger.h

@@ -0,0 +1,44 @@
+// 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 __DATASRC_LOGGER_H
+#define __DATASRC_LOGGER_H
+
+#include <log/macros.h>
+#include <cache/cache_messages.h>
+
+/// \file logger.h
+/// \brief Cache library global logger
+///
+/// This holds the logger for the cache library. It is a private header
+/// and should not be included in any publicly used header, only in local
+/// cc files.
+
+namespace isc {
+namespace cache {
+
+/// \brief The logger for this library
+extern isc::log::Logger logger;
+
+enum {
+    /// \brief Trace basic operations
+    DBG_TRACE_BASIC = 10,
+    /// \brief Trace data operations
+    DBG_TRACE_DATA = 40,
+};
+
+}
+}
+
+#endif

src/lib/cache/message_cache.cc

@@ -1,6 +1,7 @@
 // Copyright (C) 2010  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.
 //
@@ -20,6 +21,7 @@
 #include "message_cache.h"
 #include "message_utility.h"
 #include "cache_entry_key.h"
+#include "logger.h"
 
 namespace isc {
 namespace cache {
@@ -39,11 +41,14 @@ MessageCache::MessageCache(const RRsetCachePtr& rrset_cache,
     message_lru_((3 * cache_size),
                   new HashDeleter<MessageEntry>(message_table_))
 {
+    LOG_DEBUG(logger, DBG_TRACE_BASIC, CACHE_MESSAGES_INIT).arg(cache_size).
+        arg(RRClass(message_class));
 }
 
 MessageCache::~MessageCache() {
     // Destroy all the message entries in the cache.
     message_lru_.clear();
+    LOG_DEBUG(logger, DBG_TRACE_BASIC, CACHE_MESSAGES_DEINIT);
 }
 
 bool
@@ -57,26 +62,38 @@ MessageCache::lookup(const isc::dns::Name& qname,
     if(msg_entry) {
         // Check whether the message entry has expired.
        if (msg_entry->getExpireTime() > time(NULL)) {
+            LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_MESSAGES_FOUND).
+                arg(entry_name);
             message_lru_.touch(msg_entry);
             return (msg_entry->genMessage(time(NULL), response));
         } else {
             // message entry expires, remove it from hash table and lru list.
+            LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_MESSAGES_EXPIRED).
+                arg(entry_name);
             message_table_.remove(entry_key);
             message_lru_.remove(msg_entry);
             return (false);
        }
     }
 
+    LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_MESSAGES_UNKNOWN).arg(entry_name);
     return (false);
 }
 
 bool
 MessageCache::update(const Message& msg) {
     if (!canMessageBeCached(msg)){
+        LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_MESSAGES_UNCACHEABLE).
+            arg((*msg.beginQuestion())->getName()).
+            arg((*msg.beginQuestion())->getType()).
+            arg((*msg.beginQuestion())->getClass());
         return (false);
     }
 
     QuestionIterator iter = msg.beginQuestion();
+    LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_MESSAGES_UPDATE).
+        arg((*iter)->getName()).arg((*iter)->getType()).
+        arg((*iter)->getClass());
     std::string entry_name = genCacheEntryName((*iter)->getName(),
                                                (*iter)->getType());
     HashKey entry_key = HashKey(entry_name, RRClass(message_class_));
@@ -88,6 +105,9 @@ MessageCache::update(const Message& msg) {
     // add the message entry, maybe there is one way to touch it once.
     MessageEntryPtr old_msg_entry = message_table_.get(entry_key);
     if (old_msg_entry) {
+        LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_MESSAGES_REMOVE).
+            arg((*iter)->getName()).arg((*iter)->getType()).
+            arg((*iter)->getClass());
         message_lru_.remove(old_msg_entry);
     }
 

src/lib/cache/message_cache.h

@@ -39,7 +39,7 @@ private:
     MessageCache& operator=(const MessageCache& source);
 public:
     /// \param rrset_cache The cache that stores the RRsets that the
-    ///        message entry will points to
+    ///        message entry will point to
     /// \param cache_size The size of message cache.
     /// \param message_class The class of the message cache
     /// \param negative_soa_cache The cache that stores the SOA record

src/lib/cache/message_entry.cc

@@ -20,6 +20,7 @@
 #include "message_entry.h"
 #include "message_utility.h"
 #include "rrset_cache.h"
+#include "logger.h"
 
 using namespace isc::dns;
 using namespace std;
@@ -64,7 +65,7 @@ static uint32_t MAX_UINT32 = numeric_limits<uint32_t>::max();
 // tunable.  Values of one to three hours have been found to work well
 // and would make sensible a default.  Values exceeding one day have
 // been found to be problematic. (sec 5, RFC2308)
-// The default value is 3 hourse (10800 seconds)
+// The default value is 3 hours (10800 seconds)
 // TODO:Give an option to let user configure
 static uint32_t MAX_NEGATIVE_CACHE_TTL = 10800;
 
@@ -142,6 +143,8 @@ MessageEntry::genMessage(const time_t& time_now,
         // has expired, if it is, return false.
         vector<RRsetEntryPtr> rrset_entry_vec;
         if (false == getRRsetEntries(rrset_entry_vec, time_now)) {
+            LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_ENTRY_MISSING_RRSET).
+                arg(entry_name_);
             return (false);
         }
 

src/lib/cache/resolver_cache.cc

@@ -17,6 +17,7 @@
 #include "resolver_cache.h"
 #include "dns/message.h"
 #include "rrset_cache.h"
+#include "logger.h"
 #include <string>
 #include <algorithm>
 
@@ -29,6 +30,7 @@ namespace cache {
 ResolverClassCache::ResolverClassCache(const RRClass& cache_class) :
     cache_class_(cache_class)
 {
+    LOG_DEBUG(logger, DBG_TRACE_BASIC, CACHE_RESOLVER_INIT).arg(cache_class);
     local_zone_data_ = LocalZoneDataPtr(new LocalZoneData(cache_class_.getCode()));
     rrsets_cache_ = RRsetCachePtr(new RRsetCache(RRSET_CACHE_DEFAULT_SIZE,
                                                  cache_class_.getCode()));
@@ -45,6 +47,8 @@ ResolverClassCache::ResolverClassCache(const RRClass& cache_class) :
 ResolverClassCache::ResolverClassCache(const CacheSizeInfo& cache_info) :
     cache_class_(cache_info.cclass)
 {
+    LOG_DEBUG(logger, DBG_TRACE_BASIC, CACHE_RESOLVER_INIT_INFO).
+        arg(cache_class_);
     uint16_t klass = cache_class_.getCode();
     // TODO We should find one way to load local zone data.
     local_zone_data_ = LocalZoneDataPtr(new LocalZoneData(klass));
@@ -69,8 +73,11 @@ ResolverClassCache::lookup(const isc::dns::Name& qname,
                       const isc::dns::RRType& qtype,
                       isc::dns::Message& response) const
 {
+    LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_RESOLVER_LOOKUP_MSG).
+        arg(qname).arg(qtype);
     // message response should has question section already.
     if (response.beginQuestion() == response.endQuestion()) {
+        LOG_ERROR(logger, CACHE_RESOLVER_NO_QUESTION).arg(qname).arg(qtype);
         isc_throw(MessageNoQuestionSection, "Message has no question section");
     }
 
@@ -79,6 +86,8 @@ ResolverClassCache::lookup(const isc::dns::Name& qname,
     // answer section.
     RRsetPtr rrset_ptr = local_zone_data_->lookup(qname, qtype);
     if (rrset_ptr) {
+        LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_RESOLVER_LOCAL_MSG).
+            arg(qname).arg(qtype);
         response.addRRset(Message::SECTION_ANSWER, rrset_ptr);
         return (true);
     }
@@ -91,11 +100,15 @@ isc::dns::RRsetPtr
 ResolverClassCache::lookup(const isc::dns::Name& qname,
                const isc::dns::RRType& qtype) const
 {
+    LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_RESOLVER_LOOKUP_RRSET).
+        arg(qname).arg(qtype);
     // Algorithm:
     // 1. Search in local zone data first,
     // 2. Then do search in rrsets_cache_.
     RRsetPtr rrset_ptr = local_zone_data_->lookup(qname, qtype);
     if (rrset_ptr) {
+        LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_RESOLVER_LOCAL_RRSET).
+            arg(qname).arg(qtype);
         return (rrset_ptr);
     } else {
         RRsetEntryPtr rrset_entry = rrsets_cache_->lookup(qname, qtype);
@@ -109,6 +122,10 @@ ResolverClassCache::lookup(const isc::dns::Name& qname,
 
 bool
 ResolverClassCache::update(const isc::dns::Message& msg) {
+    LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_RESOLVER_UPDATE_MSG).
+        arg((*msg.beginQuestion())->getName()).
+        arg((*msg.beginQuestion())->getType()).
+        arg((*msg.beginQuestion())->getClass());
     return (messages_cache_->update(msg));
 }
 
@@ -130,6 +147,9 @@ ResolverClassCache::updateRRsetCache(const isc::dns::ConstRRsetPtr& rrset_ptr,
 
 bool
 ResolverClassCache::update(const isc::dns::ConstRRsetPtr& rrset_ptr) {
+    LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_RESOLVER_UPDATE_RRSET).
+        arg(rrset_ptr->getName()).arg(rrset_ptr->getType()).
+        arg(rrset_ptr->getClass());
     // First update local zone, then update rrset cache.
     local_zone_data_->update((*rrset_ptr.get()));
     updateRRsetCache(rrset_ptr, rrsets_cache_);
@@ -166,6 +186,8 @@ ResolverCache::lookup(const isc::dns::Name& qname,
     if (cc) {
         return (cc->lookup(qname, qtype, response));
     } else {
+        LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_RESOLVER_UNKNOWN_CLASS_MSG).
+            arg(qclass);
         return (false);
     }
 }
@@ -179,6 +201,8 @@ ResolverCache::lookup(const isc::dns::Name& qname,
     if (cc) {
         return (cc->lookup(qname, qtype));
     } else {
+        LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_RESOLVER_UNKNOWN_CLASS_RRSET).
+            arg(qclass);
         return (RRsetPtr());
     }
 }
@@ -187,6 +211,8 @@ isc::dns::RRsetPtr
 ResolverCache::lookupDeepestNS(const isc::dns::Name& qname,
                                const isc::dns::RRClass& qclass) const
 {
+    LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_RESOLVER_DEEPEST).arg(qname).
+        arg(qclass);
     isc::dns::RRType qtype = RRType::NS();
     ResolverClassCache* cc = getClassCache(qclass);
     if (cc) {
@@ -213,6 +239,9 @@ ResolverCache::update(const isc::dns::Message& msg) {
     if (cc) {
         return (cc->update(msg));
     } else {
+        LOG_DEBUG(logger, DBG_TRACE_DATA,
+                  CACHE_RESOLVER_UPDATE_UNKNOWN_CLASS_MSG).
+            arg((*msg.beginQuestion())->getClass());
         return (false);
     }
 }
@@ -223,6 +252,9 @@ ResolverCache::update(const isc::dns::ConstRRsetPtr& rrset_ptr) {
     if (cc) {
         return (cc->update(rrset_ptr));
     } else {
+        LOG_DEBUG(logger, DBG_TRACE_DATA,
+                  CACHE_RESOLVER_UPDATE_UNKNOWN_CLASS_RRSET).
+            arg(rrset_ptr->getClass());
         return (false);
     }
 }

src/lib/cache/rrset_cache.cc

@@ -14,8 +14,9 @@
 
 #include <config.h>
 
-#include <string>
 #include "rrset_cache.h"
+#include "logger.h"
+#include <string>
 #include <nsas/nsas_entry_compare.h>
 #include <nsas/hash_table.h>
 #include <nsas/hash_deleter.h>
@@ -34,20 +35,28 @@ RRsetCache::RRsetCache(uint32_t cache_size,
     rrset_lru_((3 * cache_size),
                   new HashDeleter<RRsetEntry>(rrset_table_))
 {
+    LOG_DEBUG(logger, DBG_TRACE_BASIC, CACHE_RRSET_INIT).arg(cache_size).
+        arg(RRClass(rrset_class));
 }
 
 RRsetEntryPtr
 RRsetCache::lookup(const isc::dns::Name& qname,
                    const isc::dns::RRType& qtype)
 {
+    LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_RRSET_LOOKUP).arg(qname).
+        arg(qtype).arg(RRClass(class_));
     const string entry_name = genCacheEntryName(qname, qtype);
-    RRsetEntryPtr entry_ptr = rrset_table_.get(HashKey(entry_name, RRClass(class_)));
+
+    RRsetEntryPtr entry_ptr = rrset_table_.get(HashKey(entry_name,
+                                                       RRClass(class_)));
     if (entry_ptr) {
         if (entry_ptr->getExpireTime() > time(NULL)) {
             // Only touch the non-expired rrset entries
             rrset_lru_.touch(entry_ptr);
             return (entry_ptr);
         } else {
+            LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_RRSET_EXPIRED).arg(qname).
+                arg(qtype).arg(RRClass(class_));
             // the rrset entry has expired, so just remove it from
             // hash table and lru list.
             rrset_table_.remove(entry_ptr->hashKey());
@@ -55,19 +64,31 @@ RRsetCache::lookup(const isc::dns::Name& qname,
         }
     }
 
+    LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_RRSET_NOT_FOUND).arg(qname).
+        arg(qtype).arg(RRClass(class_));
     return (RRsetEntryPtr());
 }
 
 RRsetEntryPtr
-RRsetCache::update(const isc::dns::RRset& rrset, const RRsetTrustLevel& level) {
+RRsetCache::update(const isc::dns::RRset& rrset,
+                   const RRsetTrustLevel& level)
+{
+    LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_RRSET_UPDATE).arg(rrset.getName()).
+        arg(rrset.getType()).arg(rrset.getClass());
     // TODO: If the RRset is an NS, we should update the NSAS as well
     // lookup first
     RRsetEntryPtr entry_ptr = lookup(rrset.getName(), rrset.getType());
     if (entry_ptr) {
         if (entry_ptr->getTrustLevel() > level) {
+            LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_RRSET_UNTRUSTED).
+                arg(rrset.getName()).arg(rrset.getType()).
+                arg(rrset.getClass());
             // existed rrset entry is more authoritative, just return it
             return (entry_ptr);
         } else {
+            LOG_DEBUG(logger, DBG_TRACE_DATA, CACHE_RRSET_REMOVE_OLD).
+                arg(rrset.getName()).arg(rrset.getType()).
+                arg(rrset.getClass());
             // Remove the old rrset entry from the lru list.
             rrset_lru_.remove(entry_ptr);
         }

src/lib/cache/tests/Makefile.am

@@ -53,6 +53,7 @@ run_unittests_LDADD += -lboost_thread
 endif
 
 run_unittests_LDADD += $(top_builddir)/src/lib/cache/libcache.la
+run_unittests_LDADD += $(top_builddir)/src/lib/log/liblog.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/asiolink/libasiolink.la

src/lib/cache/tests/run_unittests.cc

@@ -19,11 +19,15 @@
 
 #include <dns/tests/unittest_util.h>
 
+#include <log/logger_support.h>
+
 int
 main(int argc, char* argv[]) {
     ::testing::InitGoogleTest(&argc, argv);
     isc::UnitTestUtil::addDataPath(TEST_DATA_SRCDIR);
     isc::UnitTestUtil::addDataPath(TEST_DATA_BUILDDIR);
 
+    isc::log::initLogger();
+
     return (isc::util::unittests::run_all());
 }

src/lib/cc/data.cc

@@ -447,7 +447,9 @@ from_stringstream_map(std::istream &in, const std::string& file, int& line,
     ElementPtr map = Element::createMap();
     skip_chars(in, " \t\n", line, pos);
     char c = in.peek();
-    if (c == '}') {
+    if (c == EOF) {
+        throwJSONError(std::string("Unterminated map, <string> or } expected"), file, line, pos);
+    } else if (c == '}') {
         // empty map, skip closing curly
         c = in.get();
     } else {

src/lib/cc/tests/data_unittests.cc

@@ -396,9 +396,24 @@ TEST(Element, to_and_from_wire) {
     EXPECT_EQ("1", Element::fromWire(ss, 1)->str());
 
     // Some malformed JSON input
+    EXPECT_THROW(Element::fromJSON("{ "), isc::data::JSONError);
+    EXPECT_THROW(Element::fromJSON("{ \"a\" "), isc::data::JSONError);
+    EXPECT_THROW(Element::fromJSON("{ \"a\": "), isc::data::JSONError);
+    EXPECT_THROW(Element::fromJSON("{ \"a\": \"b\""), isc::data::JSONError);
+    EXPECT_THROW(Element::fromJSON("{ \"a\": {"), isc::data::JSONError);
+    EXPECT_THROW(Element::fromJSON("{ \"a\": {}"), isc::data::JSONError);
+    EXPECT_THROW(Element::fromJSON("{ \"a\": []"), isc::data::JSONError);
+    EXPECT_THROW(Element::fromJSON("{ \"a\": [ }"), isc::data::JSONError);
     EXPECT_THROW(Element::fromJSON("{\":"), isc::data::JSONError);
     EXPECT_THROW(Element::fromJSON("]"), isc::data::JSONError);
     EXPECT_THROW(Element::fromJSON("[ 1, 2, }"), isc::data::JSONError);
+    EXPECT_THROW(Element::fromJSON("[ 1, 2, {}"), isc::data::JSONError);
+    EXPECT_THROW(Element::fromJSON("[ 1, 2, { ]"), isc::data::JSONError);
+    EXPECT_THROW(Element::fromJSON("[ "), isc::data::JSONError);
+    EXPECT_THROW(Element::fromJSON("{{}}"), isc::data::JSONError);
+    EXPECT_THROW(Element::fromJSON("{[]}"), isc::data::JSONError);
+    EXPECT_THROW(Element::fromJSON("{ \"a\", \"b\" }"), isc::data::JSONError);
+    EXPECT_THROW(Element::fromJSON("[ \"a\": \"b\" ]"), isc::data::JSONError);
 }
 
 ConstElementPtr

src/lib/datasrc/data_source.cc

@@ -945,7 +945,7 @@ tryWildcard(Query& q, QueryTaskPtr task, ZoneInfo& zoneinfo, bool& found) {
 void
 DataSrc::doQuery(Query& q) {
     LOG_DEBUG(logger, DBG_TRACE_BASIC, DATASRC_QUERY_PROCESS).arg(q.qname()).
-        arg(q.qclass());
+        arg(q.qtype()).arg(q.qclass());
     Message& m = q.message();
     vector<RRsetPtr> additional;
 

src/lib/datasrc/memory_datasrc.cc

@@ -225,10 +225,13 @@ struct MemoryZone::MemoryZoneImpl {
      */
     // Implementation of MemoryZone::add
     result::Result add(const ConstRRsetPtr& rrset, DomainTree* domains) {
+        // Sanitize input.  This will cause an exception to be thrown
+        // if the input RRset is empty.
+        addValidation(rrset);
+
+        // OK, can add the RRset.
         LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_MEM_ADD_RRSET).
             arg(rrset->getName()).arg(rrset->getType()).arg(origin_);
-        // Sanitize input
-        addValidation(rrset);
 
         // Add wildcards possibly contained in the owner name to the domain
         // tree.

src/lib/log/README

@@ -142,13 +142,19 @@ Points to note:
     the error originated from the logging library and the "WRITE_ERROR"
     indicates that there was a problem in a write operation.
 
-  * 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
-    can be repeated.
-     
-* Remaining lines indicate an explanation for the preceding message.  These
+  * The rest of the line - from the first non-space character to the
+    last non- space character - is taken exactly for the text
+    of the message. There are no restrictions on what characters may
+    be in this text, other than they be printable.  (This means that
+    both single-quote (') and double-quote (") characters are allowed.)
+    The message text may include replacement tokens (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 can be repeated. Otherwise,
+    the message is printed unmodified.
+
+* Remaining lines indicate an explanation for the preceding message. These
   are intended to be processed by a separate program and used to generate
   an error messages manual.  They are ignored by the message compiler.
 
@@ -232,8 +238,8 @@ Using the Logging - C++
 =======================
 1. Build message header file and source file as describe above.
 
-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
+2. The main program unit must include a call to isc::log::initLogger()
+   (described in more detail below) to set the logging severity, debug log
    level, and external message file:
 
    a) The logging severity is one of the enum defined in logger.h, i.e.
@@ -279,9 +285,9 @@ Using the Logging - Python
 ==========================
 1. Build message module as describe above.
 
-2. The main program unit should include a call to isc.log.init() to
-   set the to set the logging severity, debug log level, and external
-   message file:
+2. The main program unit must include a call to isc.log.init()
+   (described in more detail below) to set the to set the logging
+   severity, debug log level, and external message file:
 
    a) The logging severity is one of the strings:
 
@@ -316,6 +322,91 @@ Using the Logging - Python
 
        logger.error(LOG_WRITE_ERROR, "output.txt");
 
+Logging Initialization
+======================
+In all cases, if an attempt is made to use a logging method before the logging
+has been initialized, the program will terminate with a LoggingNotInitialized
+exception.
+
+C++
+---
+Logging Initialization is carried out by calling initLogger().  There are two
+variants to the call, one for use by production programs and one for use by
+unit tests.
+
+Variant #1, Used by Production Programs
+---------------------------------------
+void isc::log::initLogger(const std::string& root,
+                          isc::log::Severity severity = isc::log::INFO,
+                          int dbglevel = 0, const char* file = NULL);
+
+This is the call that should be used by production programs:
+
+root
+Name of the program (e.g. "b10-auth").  This is also the name of the root
+logger and is used when configuring logging.
+
+severity
+Default severity that the program will start logging with.  Although this may
+be overridden when the program obtains its configuration from the configuration
+database, this is the severity that it used until then.  (This may be set by
+a command-line parameter.)
+
+dbglevel
+The debug level used if "severity" is set to isc::log::DEBUG.
+
+file
+The name of a local message file.  This will be read and its definitions used
+to replace the compiled-in text of the messages.
+
+
+Variant #2, Used by Unit Tests
+------------------------------
+    void isc::log::initLogger()
+
+This is the call that should be used by unit tests.  In this variant, all the
+options are supplied by environment variables. (It should not be used for
+production programs to avoid the chance that the program operation is affected
+by inadvertently-defined environment variables.)
+
+The environment variables are:
+
+B10_LOGGER_ROOT
+Sets the "root" for the unit test.  If not defined, the name "bind10" is used.
+
+B10_LOGGER_SEVERITY
+The severity to set for the root logger in the unit test.  Valid values are
+"DEBUG", "INFO", "WARN", "ERROR", "FATAL" and "NONE".  If not defined, "INFO"
+is used.
+
+B10_LOGGER_DBGLEVEL
+If B10_LOGGER_SEVERITY is set to "DEBUG", the debug level.  This can be a
+number between 0 and 99, and defaults to 0.
+
+B10_LOGGER_LOCALMSG
+If defined, points to a local message file.  The default is not to use a local
+message file.
+
+B10_LOGGER_DESTINATION
+The location to which log message are written.  This can be one of:
+
+   stdout               Message are written to stdout
+   stderr               Messages are written to stderr
+   syslog[:facility]    Messages are written to syslog.  If the optional
+                        "facility" is used, the messages are written using
+                        that facility.  (This defaults to "local0" if not
+                        specified.)
+   Anything else        Interpreted as the name of a file to which output
+                        is appended.  If the file does not exist, a new one
+                        is opened.
+
+In the case of "stdout", "stderr" and "syslog", they must be written exactly
+as is - no leading or trailing spaces, and in lower-case.
+
+Python
+------
+To be supplied
+
 
 Severity Guidelines
 ===================

src/lib/log/log_formatter.h

@@ -163,6 +163,8 @@ public:
     }
 
     /// \brief String version of arg.
+    ///
+    /// \param arg The text to place into the placeholder.
     Formatter& arg(const std::string& arg) {
         if (logger_) {
             // Note that this method does a replacement and returns the
@@ -179,7 +181,6 @@ public:
         }
         return (*this);
     }
-
 };
 
 }

src/lib/log/log_messages.cc

@@ -1,4 +1,4 @@
-// File created from log_messages.mes on Wed Jun 22 11:54:57 2011
+// File created from log_messages.mes on Thu Jul  7 15:32:06 2011
 
 #include <cstddef>
 #include <log/message_types.h>

src/lib/log/log_messages.h

@@ -1,4 +1,4 @@
-// File created from log_messages.mes on Wed Jun 22 11:54:57 2011
+// File created from log_messages.mes on Thu Jul  7 15:32:06 2011
 
 #ifndef __LOG_MESSAGES_H
 #define __LOG_MESSAGES_H

src/lib/log/log_messages.mes

@@ -28,23 +28,23 @@ destination should be one of "console", "file", or "syslog".
 
 % LOG_BAD_SEVERITY unrecognized log severity: %1
 A logger severity value was given that was not recognized. The severity
-should be one of "DEBUG", "INFO", "WARN", "ERROR", or "FATAL".
+should be one of "DEBUG", "INFO", "WARN", "ERROR", "FATAL" or "NONE".
 
 % LOG_BAD_STREAM bad log console output stream: %1
-A log console output stream was given that was not recognized. The output
-stream should be one of "stdout", or "stderr"
+Logging has been configured so that output is written to the terminal
+(console) but the stream on which it is to be written is not recognised.
+Allowed values are "stdout" and "stderr".
 
 % LOG_DUPLICATE_MESSAGE_ID duplicate message ID (%1) in compiled code
-During start-up, BIND10 detected that the given message identification had
-been defined multiple times in the BIND10 code.
-
-This has no ill-effects other than the possibility that an erronous
-message may be logged.  However, as it is indicative of a programming
-error, please log a bug report.
+During start-up, BIND 10 detected that the given message identification
+had been defined multiple times in the BIND 10 code.  This indicates a
+programming error; please submit a bug report.
 
 % LOG_DUPLICATE_NAMESPACE line %1: duplicate $NAMESPACE directive found
 When reading a message file, more than one $NAMESPACE directive was found.
-Such a condition is regarded as an error and the read will be abandoned.
+(This directive is used to set a C++ namespace when generating header
+files during software development.)  Such a condition is regarded as an
+error and the read will be abandoned.
 
 % LOG_INPUT_OPEN_FAIL unable to open message file %1 for input: %2
 The program was not able to open the specified input message file for
@@ -99,10 +99,10 @@ There may be several reasons why this message may appear:
 - The program outputting the message may not use that particular message
 (e.g. it originates in a module not used by the program.)
 
-- The local file was written for an earlier version of the BIND10 software
+- The local file was written for an earlier version of the BIND 10 software
 and the later version no longer generates that message.
 
-Whatever the reason, there is no impact on the operation of BIND10.
+Whatever the reason, there is no impact on the operation of BIND 10.
 
 % LOG_OPEN_OUTPUT_FAIL unable to open %1 for output: %2
 Originating within the logging code, the program was not able to open
@@ -115,7 +115,7 @@ This error is generated when the compiler finds a $PREFIX directive with
 more than one argument.
 
 Note: the $PREFIX directive is deprecated and will be removed in a future
-version of BIND10.
+version of BIND 10.
 
 % LOG_PREFIX_INVALID_ARG line %1: $PREFIX directive has an invalid argument ('%2')
 Within a message file, the $PREFIX directive takes a single argument,
@@ -123,13 +123,13 @@ a prefix to be added to the symbol names when a C++ file is created.
 As such, it must adhere to restrictions on C++ symbol names (e.g. may
 only contain alphanumeric characters or underscores, and may nor start
 with a digit).  A $PREFIX directive was found with an argument (given
-in the message) that violates those restictions.
+in the message) that violates those restrictions.
 
 Note: the $PREFIX directive is deprecated and will be removed in a future
-version of BIND10.
+version of BIND 10.
 
 % LOG_READING_LOCAL_FILE reading local message file %1
-This is an informational message output by BIND10 when it starts to read
+This is an informational message output by BIND 10 when it starts to read
 a local message file.  (A local message file may replace the text of
 one of more messages; the ID of the message will not be changed though.)
 

src/lib/log/logger_support.cc

@@ -31,7 +31,9 @@
 
 #include <log/logger_level.h>
 #include <log/logger_manager.h>
+#include <log/logger_specification.h>
 #include <log/logger_support.h>
+#include <log/output_option.h>
 
 using namespace std;
 
@@ -40,6 +42,77 @@ namespace {
 // Flag to hold logging initialization state.
 bool logging_init_state = false;
 
+
+// Set logging destination according to the setting of B10_LOGGER_DESTINATION.
+// (See header for initLogger() for more details.)  This is a no-op if the
+// environment variable is not defined.
+//
+// \param root Name of the root logger
+// \param severity Severity level to be assigned to the root logger
+// \param dbglevel Debug level
+
+void
+setDestination(const char* root, const isc::log::Severity severity,
+               const int dbglevel) {
+
+    using namespace isc::log;
+
+    const char* destination = getenv("B10_LOGGER_DESTINATION");
+    if (destination != NULL) {
+
+        // Constants: not declared static as this is function is expected to be
+        // called once only
+        const string STDOUT = "stdout";
+        const string STDERR = "stderr";
+        const string SYSLOG = "syslog";
+        const string SYSLOG_COLON = "syslog:";
+
+        // Prepare the objects to define the logging specification
+        LoggerSpecification spec(root, severity, dbglevel);
+        OutputOption option;
+
+        // Set up output option according to destination specification
+        const string dest = destination;
+        if (dest == STDOUT) {
+            option.destination = OutputOption::DEST_CONSOLE;
+            option.stream = OutputOption::STR_STDOUT;
+
+        } else if (dest == STDERR) {
+            option.destination = OutputOption::DEST_CONSOLE;
+            option.stream = OutputOption::STR_STDERR;
+
+        } else if (dest == SYSLOG) {
+            option.destination = OutputOption::DEST_SYSLOG;
+            // Use default specified in OutputOption constructor for the
+            // syslog destination
+
+        } else if (dest.find(SYSLOG_COLON) == 0) {
+            option.destination = OutputOption::DEST_SYSLOG;
+            // Must take account of the string actually being "syslog:"
+            if (dest == SYSLOG_COLON) {
+                cerr << "**ERROR** value for B10_LOGGER_DESTINATION of " <<
+                        SYSLOG_COLON << " is invalid, " << SYSLOG <<
+                        " will be used instead\n";
+                // Use default for logging facility
+
+            } else {
+                // Everything else in the string is the facility name
+                option.facility = dest.substr(SYSLOG_COLON.size());
+            }
+
+        } else {
+            // Not a recognised destination, assume a file
+            option.destination = OutputOption::DEST_FILE;
+            option.filename = dest;
+        }
+
+        // ... and set the destination
+        spec.addOutputOption(option);
+        LoggerManager manager;
+        manager.process(spec);
+    }
+}
+
 } // Anonymous namespace
 
 namespace isc {
@@ -115,11 +188,14 @@ void initLogger(isc::log::Severity severity, int dbglevel) {
         }
     }
 
-    /// Set the local message file
+    // Set the local message file
     const char* localfile = getenv("B10_LOGGER_LOCALMSG");
 
     // Initialize logging
     initLogger(root, severity, dbglevel, localfile);
+
+    // Now set the destination for logging output
+    setDestination(root, severity, dbglevel);
 }
 
 } // namespace log

src/lib/log/logger_support.h

@@ -68,26 +68,37 @@ void initLogger(const std::string& root,
 /// Performs run-time initialization of the logger via the setting of
 /// environment variables.  These are:
 ///
-/// B10_LOGGER_ROOT
+/// - B10_LOGGER_ROOT\n
 /// Name of the root logger.  If not given, the string "bind10" will be used.
 ///
-/// B10_LOGGER_SEVERITY
+/// - B10_LOGGER_SEVERITY\n
 /// Severity of messages that will be logged.  This must be one of the strings
 /// "DEBUG", "INFO", "WARN", "ERROR", "FATAL" or "NONE". (Must be upper case
 /// and must not contain leading or trailing spaces.)  If not specified (or if
 /// specified but incorrect), the default passed as argument to this function
 /// (currently DEBUG) will be used.
 ///
-/// B10_LOGGER_DBGLEVEL
+/// - B10_LOGGER_DBGLEVEL\n
 /// Ignored if the level is not DEBUG, this should be a number between 0 and
 /// 99 indicating the logging severity.  The default is 0.  If outside these
 /// limits or if not a number, The value passed to this function (default
 /// of MAX_DEBUG_LEVEL) is used.
 ///
-/// B10_LOGGER_LOCALMSG
+/// - B10_LOGGER_LOCALMSG\n
 /// If defined, the path specification of a file that contains message
 /// definitions replacing ones in the default dictionary.
 ///
+/// - B10_LOGGER_DESTINATION\n
+/// If defined, the destination of the logging output.  This can be one of:
+///   - \c stdout Send output to stdout.
+///   - \c stderr Send output to stderr
+///   - \c syslog Send output to syslog using the facility local0.
+///   - \c syslog:xxx  Send output to syslog, using the facility xxx. ("xxx"
+///     should be one of the syslog facilities such as "local0".)  There must
+///     be a colon between "syslog" and "xxx
+///   - \c other Anything else is interpreted as the name of a file to which
+///     output is appended.  If the file does not exist, it is created.
+///
 /// Any errors in the settings cause messages to be output to stderr.
 ///
 /// This function is aimed at test programs, allowing the default settings to

src/lib/log/tests/Makefile.am

@@ -52,12 +52,23 @@ logger_example_LDFLAGS = $(AM_LDFLAGS) $(LOG4CPLUS_LDFLAGS)
 logger_example_LDADD  = $(top_builddir)/src/lib/log/liblog.la
 logger_example_LDADD += $(top_builddir)/src/lib/util/libutil.la
 
+check_PROGRAMS += init_logger_test
+init_logger_test_SOURCES = init_logger_test.cc
+init_logger_test_CPPFLAGS = $(AM_CPPFLAGS) $(GTEST_INCLUDES)
+init_logger_test_LDFLAGS = $(AM_LDFLAGS) $(LOG4CPLUS_LDFLAGS)
+init_logger_test_LDADD  = $(top_builddir)/src/lib/log/liblog.la
+init_logger_test_LDADD += $(top_builddir)/src/lib/util/libutil.la
+
 noinst_PROGRAMS = $(TESTS)
 
-# Additional test using the shell
-PYTESTS = console_test.sh local_file_test.sh severity_test.sh
+# Additional test using the shell.  These are principally tests
+# where the global logging environment is affected, and where the
+# output needs to be compared with stored output (where "cut" and
+# "diff" are useful utilities).
+
 check-local:
 	$(SHELL) $(abs_builddir)/console_test.sh
 	$(SHELL) $(abs_builddir)/destination_test.sh
+	$(SHELL) $(abs_builddir)/init_logger_test.sh
 	$(SHELL) $(abs_builddir)/local_file_test.sh
 	$(SHELL) $(abs_builddir)/severity_test.sh

src/lib/log/tests/console_test.sh.in

@@ -13,8 +13,6 @@
 # OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
 # PERFORMANCE OF THIS SOFTWARE.
 
-# \brief
-#
 # The logger supports the idea of a "console" logger than logs to either stdout
 # or stderr.  This test checks that both these options work.
 

src/lib/log/tests/destination_test.sh.in

@@ -13,10 +13,7 @@
 # OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
 # PERFORMANCE OF THIS SOFTWARE.
 
-# \brief Severity test
-#
-# Checks that the logger will limit the output of messages less severy than
-# the severity/debug setting.
+# Checks that the logger will route messages to the chosen destination.
 
 testname="Destination test"
 echo $testname

src/lib/log/tests/init_logger_test.cc

@@ -0,0 +1,42 @@
+// 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 <log/macros.h>
+#include <log/logger_support.h>
+#include <log/log_messages.h>
+
+using namespace isc::log;
+
+/// \brief Test InitLogger
+///
+/// A program used in testing the logger that initializes logging using
+/// initLogger(), then outputs several messages at different severities and
+/// debug levels.  An external script sets the environment variables and checks
+/// that they have the desired effect.
+
+int
+main(int, char**) {
+    initLogger();
+    Logger logger("log");
+
+    LOG_DEBUG(logger, 0, LOG_BAD_DESTINATION).arg("debug-0");
+    LOG_DEBUG(logger, 50, LOG_BAD_DESTINATION).arg("debug-50");
+    LOG_DEBUG(logger, 99, LOG_BAD_DESTINATION).arg("debug-99");
+    LOG_INFO(logger, LOG_BAD_SEVERITY).arg("info");
+    LOG_WARN(logger, LOG_BAD_STREAM).arg("warn");
+    LOG_ERROR(logger, LOG_DUPLICATE_MESSAGE_ID).arg("error");
+    LOG_FATAL(logger, LOG_NO_MESSAGE_ID).arg("fatal");
+
+    return (0);
+}

src/lib/log/tests/init_logger_test.sh.in

@@ -0,0 +1,110 @@
+#!/bin/sh
+# 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.
+
+# Checks that the initLogger() call uses for unit tests respects the setting of
+# the environment variables.
+
+testname="initLogger test"
+echo $testname
+
+failcount=0
+tempfile=@abs_builddir@/init_logger_test_tempfile_$$
+destfile=@abs_builddir@/init_logger_test_destfile_$$
+
+passfail() {
+    if [ $1 -eq 0 ]; then
+        echo " pass"
+    else
+        echo " FAIL"
+        failcount=`expr $failcount + $1`
+    fi
+}
+
+echo "1. Checking that B10_LOGGER_SEVERITY/B10_LOGGER_DBGLEVEL work"
+
+echo -n  "   - severity=DEBUG, dbglevel=99: "
+cat > $tempfile << .
+DEBUG [bind10.log] LOG_BAD_DESTINATION unrecognized log destination: debug-0
+DEBUG [bind10.log] LOG_BAD_DESTINATION unrecognized log destination: debug-50
+DEBUG [bind10.log] LOG_BAD_DESTINATION unrecognized log destination: debug-99
+INFO  [bind10.log] LOG_BAD_SEVERITY unrecognized log severity: info
+WARN  [bind10.log] LOG_BAD_STREAM bad log console output stream: warn
+ERROR [bind10.log] LOG_DUPLICATE_MESSAGE_ID duplicate message ID (error) in compiled code
+FATAL [bind10.log] LOG_NO_MESSAGE_ID line fatal: message definition line found without a message ID
+.
+B10_LOGGER_SEVERITY=DEBUG B10_LOGGER_DBGLEVEL=99 ./init_logger_test 2>&1 | \
+    cut -d' ' -f3- | diff $tempfile -
+passfail $?
+
+echo -n  "   - severity=DEBUG, dbglevel=50: "
+cat > $tempfile << .
+DEBUG [bind10.log] LOG_BAD_DESTINATION unrecognized log destination: debug-0
+DEBUG [bind10.log] LOG_BAD_DESTINATION unrecognized log destination: debug-50
+INFO  [bind10.log] LOG_BAD_SEVERITY unrecognized log severity: info
+WARN  [bind10.log] LOG_BAD_STREAM bad log console output stream: warn
+ERROR [bind10.log] LOG_DUPLICATE_MESSAGE_ID duplicate message ID (error) in compiled code
+FATAL [bind10.log] LOG_NO_MESSAGE_ID line fatal: message definition line found without a message ID
+.
+B10_LOGGER_SEVERITY=DEBUG B10_LOGGER_DBGLEVEL=50 ./init_logger_test 2>&1 | \
+    cut -d' ' -f3- | diff $tempfile -
+passfail $?
+
+echo -n  "   - severity=WARN: "
+cat > $tempfile << .
+WARN  [bind10.log] LOG_BAD_STREAM bad log console output stream: warn
+ERROR [bind10.log] LOG_DUPLICATE_MESSAGE_ID duplicate message ID (error) in compiled code
+FATAL [bind10.log] LOG_NO_MESSAGE_ID line fatal: message definition line found without a message ID
+.
+B10_LOGGER_SEVERITY=WARN ./init_logger_test 2>&1 | \
+    cut -d' ' -f3- | diff $tempfile -
+passfail $?
+
+echo "2. Checking that B10_LOGGER_DESTINATION works"
+
+echo -n  "   - stdout: "
+cat > $tempfile << .
+FATAL [bind10.log] LOG_NO_MESSAGE_ID line fatal: message definition line found without a message ID
+.
+rm -f $destfile
+B10_LOGGER_SEVERITY=FATAL B10_LOGGER_DESTINATION=stdout ./init_logger_test 1> $destfile
+cut -d' ' -f3- $destfile | diff $tempfile -
+passfail $?
+
+echo -n  "   - stderr: "
+rm -f $destfile
+B10_LOGGER_SEVERITY=FATAL B10_LOGGER_DESTINATION=stderr ./init_logger_test 2> $destfile
+cut -d' ' -f3- $destfile | diff $tempfile -
+passfail $?
+
+echo -n  "   - file: "
+rm -f $destfile
+B10_LOGGER_SEVERITY=FATAL B10_LOGGER_DESTINATION=$destfile ./init_logger_test
+cut -d' ' -f3- $destfile | diff $tempfile -
+passfail $?
+
+# Note: can't automatically test syslog output.
+
+if [ $failcount -eq 0 ]; then
+    echo "PASS: $testname"
+elif [ $failcount -eq 1 ]; then
+    echo "FAIL: $testname - 1 test failed"
+else
+    echo "FAIL: $testname - $failcount tests failed"
+fi
+
+# Tidy up.
+rm -f $tempfile $destfile
+
+exit $failcount

src/lib/log/tests/local_file_test.sh.in

@@ -13,8 +13,6 @@
 # OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
 # PERFORMANCE OF THIS SOFTWARE.
 
-# \brief Local message file test
-#
 # Checks that a local message file can override the definitions in the message
 # dictionary.
 

src/lib/log/tests/severity_test.sh.in

@@ -13,9 +13,7 @@
 # OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
 # PERFORMANCE OF THIS SOFTWARE.
 
-# \brief Severity test
-#
-# Checks that the logger will limit the output of messages less severy than
+# Checks that the logger will limit the output of messages less severe than
 # the severity/debug setting.
 
 testname="Severity test"
@@ -33,7 +31,7 @@ passfail() {
     fi
 }
 
-echo -n "1. runInitTest default parameters:"
+echo -n "1. Default parameters:"
 cat > $tempfile << .
 FATAL [example] LOG_WRITE_ERROR error writing to test1: 42
 ERROR [example] LOG_READING_LOCAL_FILE reading local message file dummy/file

src/lib/python/isc/cc/message.py

@@ -35,7 +35,7 @@ def from_wire(data):
        Raises an AttributeError if the given object has no decode()
        method (which should return a string).
        '''
-    return json.loads(data.decode('utf8'))
+    return json.loads(data.decode('utf8'), strict=False)
 
 if __name__ == "__main__":
     import doctest

src/lib/python/isc/cc/session.py

@@ -93,6 +93,19 @@ class Session:
                 self._socket.send(msg)
 
     def recvmsg(self, nonblock = True, seq = None):
+        """Reads a message. If nonblock is true, and there is no
+           message to read, it returns (None, None).
+           If seq is not None, it should be a value as returned by
+           group_sendmsg(), in which case only the response to
+           that message is returned, and others will be queued until
+           the next call to this method.
+           If seq is None, only messages that are *not* responses
+           will be returned, and responses will be queued.
+           The queue is checked for relevant messages before data
+           is read from the socket.
+           Raises a SessionError if there is a JSON decode problem in
+           the message that is read, or if the session has been closed
+           prior to the call of recvmsg()"""
         with self._lock:
             if len(self._queue) > 0:
                 i = 0;
@@ -109,16 +122,22 @@ class Session:
             if data and len(data) > 2:
                 header_length = struct.unpack('>H', data[0:2])[0]
                 data_length = len(data) - 2 - header_length
-                if data_length > 0:
-                    env = isc.cc.message.from_wire(data[2:header_length+2])
-                    msg = isc.cc.message.from_wire(data[header_length + 2:])
-                    if (seq == None and "reply" not in env) or (seq != None and "reply" in env and seq == env["reply"]):
-                        return env, msg
+                try:
+                    if data_length > 0:
+                        env = isc.cc.message.from_wire(data[2:header_length+2])
+                        msg = isc.cc.message.from_wire(data[header_length + 2:])
+                        if (seq == None and "reply" not in env) or (seq != None and "reply" in env and seq == env["reply"]):
+                            return env, msg
+                        else:
+                            self._queue.append((env,msg))
+                            return self.recvmsg(nonblock, seq)
                     else:
-                        self._queue.append((env,msg))
-                        return self.recvmsg(nonblock, seq)
-                else:
-                    return isc.cc.message.from_wire(data[2:header_length+2]), None
+                        return isc.cc.message.from_wire(data[2:header_length+2]), None
+                except ValueError as ve:
+                    # TODO: when we have logging here, add a debug
+                    # message printing the data that we were unable
+                    # to parse as JSON
+                    raise SessionError(ve)
             return None, None
 
     def _receive_bytes(self, size):

src/lib/python/isc/cc/tests/message_test.py

@@ -31,6 +31,10 @@ class MessageTest(unittest.TestCase):
         self.msg2_str = "{\"aaa\": [1, 1.1, true, false, null]}";
         self.msg2_wire = self.msg2_str.encode()
 
+        self.msg3 = { "aaa": [ 1, 1.1, True, False, "string\n" ] }
+        self.msg3_str = "{\"aaa\": [1, 1.1, true, false, \"string\n\" ]}";
+        self.msg3_wire = self.msg3_str.encode()
+
     def test_encode_json(self):
         self.assertEqual(self.msg1_wire, isc.cc.message.to_wire(self.msg1))
         self.assertEqual(self.msg2_wire, isc.cc.message.to_wire(self.msg2))
@@ -40,6 +44,7 @@ class MessageTest(unittest.TestCase):
     def test_decode_json(self):
         self.assertEqual(self.msg1, isc.cc.message.from_wire(self.msg1_wire))
         self.assertEqual(self.msg2, isc.cc.message.from_wire(self.msg2_wire))
+        self.assertEqual(self.msg3, isc.cc.message.from_wire(self.msg3_wire))
 
         self.assertRaises(AttributeError, isc.cc.message.from_wire, 1)
         self.assertRaises(ValueError, isc.cc.message.from_wire, b'\x001')

src/lib/python/isc/cc/tests/session_test.py

@@ -274,6 +274,16 @@ class testSession(unittest.TestCase):
         self.assertEqual({"hello": "b"}, msg)
         self.assertFalse(sess.has_queued_msgs())
 
+    def test_recv_bad_msg(self):
+        sess = MySession()
+        self.assertFalse(sess.has_queued_msgs())
+        sess._socket.addrecv({'to': 'someone' }, {'hello': 'b'})
+        sess._socket.addrecv({'to': 'someone', 'reply': 1}, {'hello': 'a'})
+        # mangle the bytes a bit
+        sess._socket.recvqueue[5] = sess._socket.recvqueue[5] - 2
+        sess._socket.recvqueue = sess._socket.recvqueue[:-2]
+        self.assertRaises(SessionError, sess.recvmsg, True, 1)
+
     def test_next_sequence(self):
         sess = MySession()
         self.assertEqual(sess._sequence, 1)

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

@@ -380,6 +380,9 @@ class ConfigManager:
                 answer, env = self.cc.group_recvmsg(False, seq)
             except isc.cc.SessionTimeout:
                 answer = ccsession.create_answer(1, "Timeout waiting for answer from " + module_name)
+            except isc.cc.SessionError as se:
+                logger.error(CFGMGR_BAD_UPDATE_RESPONSE_FROM_MODULE, module_name, se)
+                answer = ccsession.create_answer(1, "Unable to parse response from " + module_name + ": " + str(se))
         if answer:
             rcode, val = ccsession.parse_answer(answer)
             if rcode == 0:

src/lib/python/isc/config/cfgmgr_messages.mes

@@ -20,6 +20,13 @@ An older version of the configuration database has been found, from which
 there was an automatic upgrade path to the current version. These changes
 are now applied, and no action from the administrator is necessary.
 
+% CFGMGR_BAD_UPDATE_RESPONSE_FROM_MODULE Unable to parse response from module %1: %2
+The configuration manager sent a configuration update to a module, but
+the module responded with an answer that could not be parsed. The answer
+message appears to be invalid JSON data, or not decodable to a string.
+This is likely to be a problem in the module in question. The update is
+assumed to have failed, and will not be stored.
+
 % CFGMGR_CC_SESSION_ERROR Error connecting to command channel: %1
 The configuration manager daemon was unable to connect to the messaging
 system. The most likely cause is that msgq is not running.

src/lib/python/isc/log/Makefile.am

@@ -23,6 +23,15 @@ log_la_LIBADD += $(PYTHON_LIB)
 # This is not installed, it helps locate the module during tests
 EXTRA_DIST = __init__.py
 
+# We're going to abuse install-data-local for a pre-install check.
+# This is to be considered a short term hack and is expected to be removed
+# in a near future version.
+install-data-local:
+	if test -d @pyexecdir@/isc/log; then \
+		echo "@pyexecdir@/isc/log is deprecated, and will confuse newer versions.  Please (re)move it by hand."; \
+		exit 1; \
+	fi
+
 pytest:
 	$(SHELL) tests/log_test
 

src/lib/server_common/Makefile.am

@@ -20,6 +20,9 @@ lib_LTLIBRARIES = libserver_common.la
 libserver_common_la_SOURCES = client.h client.cc
 libserver_common_la_SOURCES += keyring.h keyring.cc
 libserver_common_la_SOURCES += portconfig.h portconfig.cc
+libserver_common_la_SOURCES += logger.h logger.cc
+nodist_libserver_common_la_SOURCES = server_common_messages.h
+nodist_libserver_common_la_SOURCES += server_common_messages.cc
 libserver_common_la_LIBADD = $(top_builddir)/src/lib/exceptions/libexceptions.la
 libserver_common_la_LIBADD += $(top_builddir)/src/lib/asiolink/libasiolink.la
 libserver_common_la_LIBADD += $(top_builddir)/src/lib/cc/libcc.la
@@ -27,5 +30,10 @@ libserver_common_la_LIBADD += $(top_builddir)/src/lib/config/libcfgclient.la
 libserver_common_la_LIBADD += $(top_builddir)/src/lib/log/liblog.la
 libserver_common_la_LIBADD += $(top_builddir)/src/lib/acl/libacl.la
 libserver_common_la_LIBADD += $(top_builddir)/src/lib/dns/libdns++.la
+BUILT_SOURCES = server_common_messages.h server_common_messages.cc
+server_common_messages.h server_common_messages.cc: server_common_messages.mes
+	$(top_builddir)/src/lib/log/compiler/message $(top_srcdir)/src/lib/server_common/server_common_messages.mes
 
-CLEANFILES = *.gcno *.gcda
+EXTRA_DIST = server_common_messages.mes
+
+CLEANFILES = *.gcno *.gcda server_common_messages.h server_common_messages.cc

src/lib/server_common/client.cc

@@ -66,10 +66,3 @@ std::ostream&
 isc::server_common::operator<<(std::ostream& os, const Client& client) {
     return (os << client.toText());
 }
-
-template <>
-bool
-IPCheck<Client>::matches(const Client& client) const {
-    const IPAddress& request_src(client.getRequestSourceIPAddress());
-    return (compare(request_src.getData(), request_src.getFamily()));
-}

src/lib/server_common/client.h

@@ -145,17 +145,6 @@ private:
 /// parameter \c os after the insertion operation.
 std::ostream& operator<<(std::ostream& os, const Client& client);
 }
-
-namespace acl {
-/// The specialization of \c IPCheck for access control with \c Client.
-///
-/// It returns \c true if the source IP address of the client's request
-/// matches the expression encapsulated in the \c IPCheck, and returns
-/// \c false if not.
-template <>
-bool IPCheck<server_common::Client>::matches(
-    const server_common::Client& client) const;
-}
 }
 
 #endif  // __CLIENT_H

src/lib/server_common/keyring.cc

@@ -13,6 +13,7 @@
 // PERFORMANCE OF THIS SOFTWARE.
 
 #include <server_common/keyring.h>
+#include <server_common/logger.h>
 
 using namespace isc::dns;
 using namespace isc::data;
@@ -31,6 +32,7 @@ updateKeyring(const std::string&, ConstElementPtr data,
               const isc::config::ConfigData&) {
     ConstElementPtr list(data->get("keys"));
     KeyringPtr load(new TSIGKeyRing);
+    LOG_DEBUG(logger, DBG_TRACE_BASIC, SRVCOMM_KEYS_UPDATE);
 
     // Note that 'data' only contains explicitly configured config parameters.
     // So if we use the default list is NULL, rather than an empty list, and
@@ -50,6 +52,7 @@ initKeyring(config::ModuleCCSession& session) {
         // We are already initialized
         return;
     }
+    LOG_DEBUG(logger, DBG_TRACE_BASIC, SRVCOMM_KEYS_INIT);
     session.addRemoteConfig("tsig_keys", updateKeyring, false);
 }
 
@@ -59,6 +62,7 @@ deinitKeyring(config::ModuleCCSession& session) {
         // Not initialized, ignore it
         return;
     }
+    LOG_DEBUG(logger, DBG_TRACE_BASIC, SRVCOMM_KEYS_DEINIT);
     keyring.reset();
     session.removeRemoteConfig("tsig_keys");
 }

src/lib/server_common/logger.cc

@@ -0,0 +1,23 @@
+// 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 <server_common/logger.h>
+
+namespace isc {
+namespace server_common {
+
+isc::log::Logger logger("server_common");
+
+}
+}

src/lib/server_common/logger.h

@@ -0,0 +1,44 @@
+// 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 __SERVER_COMMON_LOGGER_H
+#define __SERVER_COMMON_LOGGER_H
+
+#include <log/macros.h>
+#include <server_common/server_common_messages.h>
+
+/// \file logger.h
+/// \brief Server Common library global logger
+///
+/// This holds the logger for the server common library. It is a private header
+/// and should not be included in any publicly used header, only in local
+/// cc files.
+
+namespace isc {
+namespace server_common {
+
+/// \brief The logger for this library
+extern isc::log::Logger logger;
+
+enum {
+    /// \brief Trace basic operations
+    DBG_TRACE_BASIC = 10,
+    /// \brief Print also values used
+    DBG_TRACE_VALUES = 40
+};
+
+}
+}
+
+#endif

src/lib/server_common/portconfig.cc

@@ -13,10 +13,10 @@
 // PERFORMANCE OF THIS SOFTWARE.
 
 #include <server_common/portconfig.h>
+#include <server_common/logger.h>
 
 #include <asiolink/io_address.h>
 #include <asiodns/dns_service.h>
-#include <log/dummylog.h>
 
 #include <boost/foreach.hpp>
 #include <boost/lexical_cast.hpp>
@@ -25,7 +25,6 @@ using namespace std;
 using namespace isc::data;
 using namespace isc::asiolink;
 using namespace isc::asiodns;
-using isc::log::dlog;
 
 namespace isc {
 namespace server_common {
@@ -43,6 +42,8 @@ parseAddresses(isc::data::ConstElementPtr addresses,
                 ConstElementPtr addr(addrPair->get("address"));
                 ConstElementPtr port(addrPair->get("port"));
                 if (!addr || ! port) {
+                    LOG_ERROR(logger, SRVCOMM_ADDRESS_MISSING).
+                        arg(addrPair->str());
                     isc_throw(BadValue, "Address must contain both the IP"
                         "address and port");
                 }
@@ -50,6 +51,8 @@ parseAddresses(isc::data::ConstElementPtr addresses,
                     IOAddress(addr->stringValue());
                     if (port->intValue() < 0 ||
                         port->intValue() > 0xffff) {
+                        LOG_ERROR(logger, SRVCOMM_PORT_RANGE).
+                            arg(port->intValue()).arg(addrPair->str());
                         isc_throw(BadValue, "Bad port value (" <<
                             port->intValue() << ")");
                     }
@@ -57,11 +60,14 @@ parseAddresses(isc::data::ConstElementPtr addresses,
                         port->intValue()));
                 }
                 catch (const TypeError &e) { // Better error message
+                    LOG_ERROR(logger, SRVCOMM_ADDRESS_TYPE).
+                        arg(addrPair->str());
                     isc_throw(TypeError,
                         "Address must be a string and port an integer");
                 }
             }
         } else if (addresses->getType() != Element::null) {
+            LOG_ERROR(logger, SRVCOMM_ADDRESSES_NOT_LIST).arg(elemName);
             isc_throw(TypeError, elemName + " config element must be a list");
         }
     }
@@ -86,10 +92,10 @@ installListenAddresses(const AddressList& newAddresses,
                        isc::asiodns::DNSService& service)
 {
     try {
-        dlog("Setting listen addresses:");
+        LOG_DEBUG(logger, DBG_TRACE_BASIC, SRVCOMM_SET_LISTEN);
         BOOST_FOREACH(const AddressPair& addr, newAddresses) {
-            dlog(" " + addr.first + ":" +
-                        boost::lexical_cast<string>(addr.second));
+            LOG_DEBUG(logger, DBG_TRACE_VALUES, SRVCOMM_ADDRESS_VALUE).
+                arg(addr.first).arg(addr.second);
         }
         setAddresses(service, newAddresses);
         addressStore = newAddresses;
@@ -108,13 +114,12 @@ installListenAddresses(const AddressList& newAddresses,
          * user will get error info, command control can be used to set new
          * address. So we just catch the exception without propagating outside
          */
-        dlog(string("Unable to set new address: ") + e.what(), true);
+        LOG_ERROR(logger, SRVCOMM_ADDRESS_FAIL).arg(e.what());
         try {
             setAddresses(service, addressStore);
         }
         catch (const exception& e2) {
-            dlog("Unable to recover from error;", true);
-            dlog(string("Rollback failed with: ") + e2.what(), true);
+            LOG_FATAL(logger, SRVCOMM_ADDRESS_UNRECOVERABLE).arg(e2.what());
         }
         //Anyway the new configure has problem, we need to notify configure
         //manager the new configure doesn't work

src/lib/server_common/server_common_messages.mes

@@ -0,0 +1,73 @@
+# 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.
+
+$NAMESPACE isc::server_common
+
+# \brief Messages for the server_common library
+
+% SRVCOMM_ADDRESSES_NOT_LIST the address and port specification is not a list in %1
+This points to an error in configuration. What was supposed to be a list of
+IP address - port pairs isn't a list at all but something else.
+
+% SRVCOMM_ADDRESS_FAIL failed to listen on addresses (%1)
+The server failed to bind to one of the address/port pair it should according
+to configuration, for reason listed in the message (usually because that pair
+is already used by other service or missing privileges). The server will try
+to recover and bind the address/port pairs it was listening to before (if any).
+
+% SRVCOMM_ADDRESS_MISSING address specification is missing "address" or "port" element in %1
+This points to an error in configuration. An address specification in the
+configuration is missing either an address or port and so cannot be used. The
+specification causing the error is given in the message.
+
+% SRVCOMM_ADDRESS_TYPE address specification type is invalid in %1
+This points to an error in configuration. An address specification in the
+configuration malformed. The specification causing the error is given in the
+message. A valid specification contains an address part (which must be a string
+and must represent a valid IPv4 or IPv6 address) and port (which must be an
+integer in the range valid for TCP/UDP ports on your system).
+
+% SRVCOMM_ADDRESS_UNRECOVERABLE failed to recover original addresses also (%2)
+The recovery of old addresses after SRVCOMM_ADDRESS_FAIL also failed for
+the reason listed.
+
+The condition indicates problems with the server and/or the system on
+which it is running.  The server will continue running to allow
+reconfiguration, but will not be listening on any address or port until
+an administrator does so.
+
+% SRVCOMM_ADDRESS_VALUE address to set: %1#%2
+Debug message. This lists one address and port value of the set of
+addresses we are going to listen on (eg. there will be one log message
+per pair). This appears only after SRVCOMM_SET_LISTEN, but might
+be hidden, as it has higher debug level.
+
+% SRVCOMM_KEYS_DEINIT deinitializing TSIG keyring
+Debug message indicating that the server is deinitializing the TSIG keyring.
+
+% SRVCOMM_KEYS_INIT initializing TSIG keyring
+Debug message indicating that the server is initializing the global TSIG
+keyring. This should be seen only at server start.
+
+% SRVCOMM_KEYS_UPDATE updating TSIG keyring
+Debug message indicating new keyring is being loaded from configuration (either
+on startup or as a result of configuration update).
+
+% SRVCOMM_PORT_RANGE port out of valid range (%1 in %2)
+This points to an error in configuration. The port in an address
+specification is outside the valid range of 0 to 65535.
+
+% SRVCOMM_SET_LISTEN setting addresses to listen to
+Debug message, noting that the server is about to start listening on a
+different set of IP addresses and ports than before.

src/lib/server_common/tests/Makefile.am

@@ -38,8 +38,10 @@ run_unittests_LDADD += $(top_builddir)/src/lib/server_common/libserver_common.la
 run_unittests_LDADD += $(top_builddir)/src/lib/asiolink/libasiolink.la
 run_unittests_LDADD += $(top_builddir)/src/lib/asiodns/libasiodns.la
 run_unittests_LDADD += $(top_builddir)/src/lib/cc/libcc.la
+run_unittests_LDADD += $(top_builddir)/src/lib/log/liblog.la
 run_unittests_LDADD += $(top_builddir)/src/lib/acl/libacl.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/dns/libdns++.la
 run_unittests_LDADD += $(top_builddir)/src/lib/util/unittests/libutil_unittests.la
 run_unittests_LDADD += $(top_builddir)/src/lib/exceptions/libexceptions.la

src/lib/server_common/tests/client_unittest.cc

@@ -89,30 +89,6 @@ TEST_F(ClientTest, constructIPv6) {
                         client6->getRequestSourceIPAddress().getData(), 16));
 }
 
-TEST_F(ClientTest, ACLCheckIPv4) {
-    // Exact match
-    EXPECT_TRUE(IPCheck<Client>("192.0.2.1").matches(*client4));
-    // Exact match (negative)
-    EXPECT_FALSE(IPCheck<Client>("192.0.2.53").matches(*client4));
-    // Prefix match
-    EXPECT_TRUE(IPCheck<Client>("192.0.2.0/24").matches(*client4));
-    // Prefix match (negative)
-    EXPECT_FALSE(IPCheck<Client>("192.0.1.0/24").matches(*client4));
-    // Address family mismatch (the first 4 bytes of the IPv6 address has the
-    // same binary representation as the client's IPv4 address, which
-    // shouldn't confuse the match logic)
-    EXPECT_FALSE(IPCheck<Client>("c000:0201::").matches(*client4));
-}
-
-TEST_F(ClientTest, ACLCheckIPv6) {
-    // The following are a set of tests of the same concept as ACLCheckIPv4
-    EXPECT_TRUE(IPCheck<Client>("2001:db8::1").matches(*client6));
-    EXPECT_FALSE(IPCheck<Client>("2001:db8::53").matches(*client6));
-    EXPECT_TRUE(IPCheck<Client>("2001:db8::/64").matches(*client6));
-    EXPECT_FALSE(IPCheck<Client>("2001:db8:1::/64").matches(*client6));
-    EXPECT_FALSE(IPCheck<Client>("32.1.13.184").matches(*client6));
-}
-
 TEST_F(ClientTest, toText) {
     EXPECT_EQ("192.0.2.1#53214", client4->toText());
     EXPECT_EQ("2001:db8::1#53216", client6->toText());

src/lib/server_common/tests/run_unittests.cc

@@ -16,6 +16,7 @@
 
 #include <gtest/gtest.h>
 #include <util/unittests/run_all.h>
+#include <log/logger_support.h>
 
 #include <dns/tests/unittest_util.h>
 
@@ -23,5 +24,7 @@ int
 main(int argc, char* argv[]) {
     ::testing::InitGoogleTest(&argc, argv);
 
+    isc::log::initLogger();
+
     return (isc::util::unittests::run_all());
 }

tools/system_messages.py

@@ -58,6 +58,12 @@ SEC_HEADER="""<?xml version="1.0" encoding="UTF-8"?>
 <!ENTITY % version SYSTEM "version.ent">
 %version;
 ]>
+<!--
+     This XML document is generated using the system_messages.py tool
+     based on the .mes message files.
+
+     Do not edit this file.
+-->
 <book>
   <?xml-stylesheet href="bind10-guide.css" type="text/css"?>