Merge branch 'master' into trac598_new

ChangeLog

@@ -1,25 +1,58 @@
-234.	[func]      jerry
+237.	[bug]		naokikambe
+	Resolved that the stats module wasn't configurable in bindctl in
+	spite of its having configuration items. The configuration part
+	was removed from the original spec file "stats.spec" and was
+	placed in a new spec file "stats-schema.spec". Because it means
+	definitions of statistics items. The command part is still
+	there. Thus stats module currently has no its own configuration,
+	and the items in "stats-schema.spec" are neither visible nor
+	configurable through bindctl. "stats-schema.spec" is shared with
+	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)
+
+236.	[func]		jelte
+	C++ client side of configuration now uses BIND10 logging system.
+	It also has improved error handling when communicating with the
+	rest of the system.
+	(Trac #743, git 86632c12308c3ed099d75eb828f740c526dd7ec0)
+
+235.	[func]		jinmei
+	libdns++: added support for TSIG signing and verification.  It can
+	be done using a newly introduced TSIGContext class.
+	Note: we temporarily disabled support for truncated signature
+	and modified some part of the code introduced in #226 accordingly.
+	We plan to fix this pretty soon.
+	(Trac #812, git ebe0c4b1e66d359227bdd1bd47395fee7b957f14)
+	(Trac #871, git 7c54055c0e47c7a0e36fcfab4b47ff180c0ca8c8)
+	(Trac #813, git ffa2f0672084c1f16e5784cdcdd55822f119feaa)
+	(Trac #893, git 5aaa6c0f628ed7c2093ecdbac93a2c8cf6c94349)
+
+234.	[func]		jerry
 	src/bin/xfrin: update xfrin to use TSIG. Currently it only supports
 	sending a signed TSIG request or SOA request.
 	(Trac #815, git a892818fb13a1839c82104523cb6cb359c970e88)
 
-233.	[func]      stephen
+233.	[func]		stephen
 	Added new-style logging statements to the NSAS code.
 	(Trac #745, git ceef68cd1223ae14d8412adbe18af2812ade8c2d)
 
-232.	[func]      stephen
-	To facilitate the writing of extended descriptions in message files,
-	altered the message file format.  The message is now flagged with a "%"
-	as the first non-blank character in the line and the lines in the
-	extended description are no longer preceded by a "+".
+232.	[func]		stephen
+	To facilitate the writing of extended descriptions in
+	message files, altered the message file format.  The message
+	is now flagged with a "%" as the first non-blank character
+	in the line and the lines in the extended description are
+	no longer preceded by a "+".
 	(Trac #900, git b395258c708b49a5da8d0cffcb48d83294354ba3)
 
-231.	[func]*
+231.	[func]*		vorner
 	The logging interface changed slightly. We use
-	logger.foo(MESSAGE_ID).arg(bar); instead of logger.foo(MESSAGE_ID, bar);
-	internally. The message definitions use '%1,%2,...' instead of '%s,%d',
-	which allows us to cope better with mismatched placeholders and allows
-	reordering of them in case of translation.
+	logger.foo(MESSAGE_ID).arg(bar); instead of logger.foo(MESSAGE_ID,
+	bar); internally. The message definitions use '%1,%2,...'
+	instead of '%s,%d', which allows us to cope better with
+	mismatched placeholders and allows reordering of them in
+	case of translation.
 	(Trac901, git 4903410e45670b30d7283f5d69dc28c2069237d6)
 
 230.	[bug]		naokikambe

configure.ac

@@ -807,6 +807,7 @@ AC_OUTPUT([doc/version.ent
            src/bin/stats/stats.py
            src/bin/stats/stats_httpd.py
            src/bin/stats/stats.spec
+           src/bin/stats/stats-schema.spec
            src/bin/stats/stats-httpd.spec
            src/bin/stats/stats-httpd-xml.tpl
            src/bin/stats/stats-httpd-xsd.tpl

src/bin/stats/Makefile.am

@@ -5,7 +5,7 @@ pkglibexecdir = $(libexecdir)/@PACKAGE@
 pkglibexec_SCRIPTS = b10-stats b10-stats-httpd
 
 b10_statsdir = $(pkgdatadir)
-b10_stats_DATA = stats.spec stats-httpd.spec
+b10_stats_DATA = stats.spec stats-httpd.spec stats-schema.spec
 b10_stats_DATA += stats-httpd-xml.tpl stats-httpd-xsd.tpl stats-httpd-xsl.tpl
 
 CLEANFILES = b10-stats stats.pyc
@@ -13,7 +13,7 @@ CLEANFILES += b10-stats-httpd stats_httpd.pyc
 
 man_MANS = b10-stats.8 b10-stats-httpd.8
 EXTRA_DIST = $(man_MANS) b10-stats.xml b10-stats-httpd.xml
-EXTRA_DIST += stats.spec stats-httpd.spec
+EXTRA_DIST += stats.spec stats-httpd.spec stats-schema.spec
 EXTRA_DIST += stats-httpd-xml.tpl stats-httpd-xsd.tpl stats-httpd-xsl.tpl
 
 if ENABLE_MAN
@@ -28,8 +28,7 @@ endif
 
 # this is done here since configure.ac AC_OUTPUT doesn't expand exec_prefix
 b10-stats: stats.py
-	$(SED) -e "s|@@PYTHONPATH@@|@pyexecdir@|" \
-	       -e "s|.*#@@REMOVED@@$$||"  stats.py >$@
+	$(SED) -e "s|@@PYTHONPATH@@|@pyexecdir@|"  stats.py >$@
 	chmod a+x $@
 
 b10-stats-httpd: stats_httpd.py

src/bin/stats/b10-stats-httpd.8

@@ -66,6 +66,10 @@ bindctl(1)\&. Please see the manual of
 bindctl(1)
 about how to configure the settings\&.
 .PP
+/usr/local/share/bind10\-devel/stats\-schema\&.spec
+\(em This is a spec file for data schema of of BIND 10 statistics\&. This schema cannot be configured via
+bindctl(1)\&.
+.PP
 
 /usr/local/share/bind10\-devel/stats\-httpd\-xml\&.tpl
 \(em the template file of XML document\&.

src/bin/stats/b10-stats-httpd.xml

@@ -112,6 +112,12 @@
       of <refentrytitle>bindctl</refentrytitle><manvolnum>1</manvolnum> about
       how to configure the settings.
     </para>
+    <para><filename>/usr/local/share/bind10-devel/stats-schema.spec</filename>
+      <!--TODO: The filename should be computed from prefix-->
+      &mdash; This is a spec file for data schema of
+      of BIND 10 statistics. This schema cannot be configured 
+      via <refentrytitle>bindctl</refentrytitle><manvolnum>1</manvolnum>.
+    </para>
     <para>
       <filename>/usr/local/share/bind10-devel/stats-httpd-xml.tpl</filename>
       <!--TODO: The filename should be computed from prefix-->

src/bin/stats/b10-stats.8

@@ -63,11 +63,17 @@ switches to verbose mode\&. It sends verbose messages to STDOUT\&.
 .PP
 /usr/local/share/bind10\-devel/stats\&.spec
 \(em This is a spec file for
-\fBb10\-stats\fR\&. It contains definitions of statistics items of BIND 10 and commands received via
+\fBb10\-stats\fR\&. It contains commands for
+\fBb10\-stats\fR\&. They can be invoked via
+bindctl(1)\&.
+.PP
+/usr/local/share/bind10\-devel/stats\-schema\&.spec
+\(em This is a spec file for data schema of of BIND 10 statistics\&. This schema cannot be configured via
 bindctl(1)\&.
 .SH "SEE ALSO"
 .PP
 
+\fBb10-stats-httpd\fR(8),
 \fBbind10\fR(8),
 \fBbindctl\fR(1),
 \fBb10-auth\fR(8),

src/bin/stats/b10-stats.xml

@@ -89,10 +89,17 @@
   <refsect1>
     <title>FILES</title>
     <para><filename>/usr/local/share/bind10-devel/stats.spec</filename>
+      <!--TODO: The filename should be computed from prefix-->
       &mdash; This is a spec file for <command>b10-stats</command>. It
-      contains definitions of statistics items of BIND 10 and commands
-      received via
-      <refentrytitle>bindctl</refentrytitle><manvolnum>1</manvolnum>.
+      contains commands for <command>b10-stats</command>. They can be
+      invoked
+      via <refentrytitle>bindctl</refentrytitle><manvolnum>1</manvolnum>.
+    </para>
+    <para><filename>/usr/local/share/bind10-devel/stats-schema.spec</filename>
+      <!--TODO: The filename should be computed from prefix-->
+      &mdash; This is a spec file for data schema of
+      of BIND 10 statistics. This schema cannot be configured 
+      via <refentrytitle>bindctl</refentrytitle><manvolnum>1</manvolnum>.
     </para>
   </refsect1>
 
@@ -100,6 +107,9 @@
     <title>SEE ALSO</title>
     <para>
       <citerefentry>
+        <refentrytitle>b10-stats-httpd</refentrytitle><manvolnum>8</manvolnum>
+      </citerefentry>,
+      <citerefentry>
         <refentrytitle>bind10</refentrytitle><manvolnum>8</manvolnum>
       </citerefentry>,
       <citerefentry>

src/bin/stats/stats-schema.spec.in

@@ -0,0 +1,87 @@
+{
+  "module_spec": {
+    "module_name": "Stats",
+    "module_description": "Statistics data schema",
+    "config_data": [
+      {
+        "item_name": "report_time",
+        "item_type": "string",
+        "item_optional": false,
+        "item_default": "1970-01-01T00:00:00Z",
+        "item_title": "Report time",
+        "item_description": "A date time when stats module reports",
+        "item_format": "date-time"
+      },
+      {
+        "item_name": "bind10.boot_time",
+        "item_type": "string",
+        "item_optional": false,
+        "item_default": "1970-01-01T00:00:00Z",
+        "item_title": "bind10.BootTime",
+        "item_description": "A date time when bind10 process starts initially",
+        "item_format": "date-time"
+      },
+      {
+        "item_name": "stats.boot_time",
+        "item_type": "string",
+        "item_optional": false,
+        "item_default": "1970-01-01T00:00:00Z",
+        "item_title": "stats.BootTime",
+        "item_description": "A date time when the stats module starts initially or when the stats module restarts",
+        "item_format": "date-time"
+      },
+      {
+        "item_name": "stats.start_time",
+        "item_type": "string",
+        "item_optional": false,
+        "item_default": "1970-01-01T00:00:00Z",
+        "item_title": "stats.StartTime",
+        "item_description": "A date time when the stats module starts collecting data or resetting values last time",
+        "item_format": "date-time"
+      },
+      {
+        "item_name": "stats.last_update_time",
+        "item_type": "string",
+        "item_optional": false,
+        "item_default": "1970-01-01T00:00:00Z",
+        "item_title": "stats.LastUpdateTime",
+        "item_description": "The latest date time when the stats module receives from other modules like auth server or boss process and so on",
+        "item_format": "date-time"
+      },
+      {
+        "item_name": "stats.timestamp",
+        "item_type": "real",
+        "item_optional": false,
+        "item_default": 0.0,
+        "item_title": "stats.Timestamp",
+        "item_description": "A current time stamp since epoch time (1970-01-01T00:00:00Z)",
+        "item_format": "second"
+      },
+      {
+        "item_name": "stats.lname",
+        "item_type": "string",
+        "item_optional": false,
+        "item_default": "",
+        "item_title": "stats.LocalName",
+        "item_description": "A localname of stats module given via CC protocol"
+      },
+      {
+        "item_name": "auth.queries.tcp",
+        "item_type": "integer",
+        "item_optional": false,
+        "item_default": 0,
+        "item_title": "auth.queries.tcp",
+        "item_description": "A number of total query counts which all auth servers receive over TCP since they started initially"
+      },
+      {
+        "item_name": "auth.queries.udp",
+        "item_type": "integer",
+        "item_optional": false,
+        "item_default": 0,
+        "item_title": "auth.queries.udp",
+        "item_description": "A number of total query counts which all auth servers receive over UDP since they started initially"
+      }
+    ],
+    "commands": []
+  }
+}

src/bin/stats/stats.py.in

@@ -24,12 +24,6 @@ from optparse import OptionParser, OptionValueError
 from collections import defaultdict
 from isc.config.ccsession import ModuleCCSession, create_answer
 from isc.cc import Session, SessionError
-# Note: Following lines are removed in b10-stats	#@@REMOVED@@
-if __name__ == 'stats':					#@@REMOVED@@
-    try:						#@@REMOVED@@
-        from fake_time import time, strftime, gmtime	#@@REMOVED@@
-    except ImportError:					#@@REMOVED@@
-        pass						#@@REMOVED@@
 
 # for setproctitle
 import isc.util.process
@@ -39,13 +33,15 @@ isc.util.process.rename()
 # from a directory relative to that, otherwise we use the ones
 # installed on the system
 if "B10_FROM_SOURCE" in os.environ:
-    SPECFILE_LOCATION = os.environ["B10_FROM_SOURCE"] + os.sep + \
-        "src" + os.sep + "bin" + os.sep + "stats" + os.sep + "stats.spec"
+    BASE_LOCATION = os.environ["B10_FROM_SOURCE"] + os.sep + \
+        "src" + os.sep + "bin" + os.sep + "stats"
 else:
     PREFIX = "@prefix@"
     DATAROOTDIR = "@datarootdir@"
-    SPECFILE_LOCATION = "@datadir@" + os.sep + "@PACKAGE@" + os.sep + "stats.spec"
-    SPECFILE_LOCATION = SPECFILE_LOCATION.replace("${datarootdir}", DATAROOTDIR).replace("${prefix}", PREFIX)
+    BASE_LOCATION = "@datadir@" + os.sep + "@PACKAGE@"
+    BASE_LOCATION = BASE_LOCATION.replace("${datarootdir}", DATAROOTDIR).replace("${prefix}", PREFIX)
+SPECFILE_LOCATION = BASE_LOCATION + os.sep + "stats.spec"
+SCHEMA_SPECFILE_LOCATION = BASE_LOCATION + os.sep + "stats-schema.spec"
 
 class Singleton(type):
     """
@@ -184,8 +180,7 @@ class CCSessionListener(Listener):
         self.session = self.subject.session = self.cc_session._session
 
         # initialize internal data
-        self.config_spec = self.cc_session.get_module_spec().get_config_spec()
-        self.stats_spec = self.config_spec
+        self.stats_spec = isc.config.module_spec_from_file(SCHEMA_SPECFILE_LOCATION).get_config_spec()
         self.stats_data = self.initialize_data(self.stats_spec)
 
         # add event handler invoked via SessionSubject object

src/bin/stats/stats.spec.in

@@ -2,86 +2,7 @@
   "module_spec": {
     "module_name": "Stats",
     "module_description": "Stats daemon",
-    "config_data": [
-      {
-        "item_name": "report_time",
-        "item_type": "string",
-        "item_optional": false,
-        "item_default": "1970-01-01T00:00:00Z",
-        "item_title": "Report time",
-        "item_description": "A date time when stats module reports",
-        "item_format": "date-time"
-      },
-      {
-        "item_name": "bind10.boot_time",
-        "item_type": "string",
-        "item_optional": false,
-        "item_default": "1970-01-01T00:00:00Z",
-        "item_title": "bind10.BootTime",
-        "item_description": "A date time when bind10 process starts initially",
-        "item_format": "date-time"
-      },
-      {
-        "item_name": "stats.boot_time",
-        "item_type": "string",
-        "item_optional": false,
-        "item_default": "1970-01-01T00:00:00Z",
-        "item_title": "stats.BootTime",
-        "item_description": "A date time when the stats module starts initially or when the stats module restarts",
-        "item_format": "date-time"
-      },
-      {
-        "item_name": "stats.start_time",
-        "item_type": "string",
-        "item_optional": false,
-        "item_default": "1970-01-01T00:00:00Z",
-        "item_title": "stats.StartTime",
-        "item_description": "A date time when the stats module starts collecting data or resetting values last time",
-        "item_format": "date-time"
-      },
-      {
-        "item_name": "stats.last_update_time",
-        "item_type": "string",
-        "item_optional": false,
-        "item_default": "1970-01-01T00:00:00Z",
-        "item_title": "stats.LastUpdateTime",
-        "item_description": "The latest date time when the stats module receives from other modules like auth server or boss process and so on",
-        "item_format": "date-time"
-      },
-      {
-        "item_name": "stats.timestamp",
-        "item_type": "real",
-        "item_optional": false,
-        "item_default": 0.0,
-        "item_title": "stats.Timestamp",
-        "item_description": "A current time stamp since epoch time (1970-01-01T00:00:00Z)",
-        "item_format": "second"
-      },
-      {
-        "item_name": "stats.lname",
-        "item_type": "string",
-        "item_optional": false,
-        "item_default": "",
-        "item_title": "stats.LocalName",
-        "item_description": "A localname of stats module given via CC protocol"
-      },
-      {
-        "item_name": "auth.queries.tcp",
-        "item_type": "integer",
-        "item_optional": false,
-        "item_default": 0,
-        "item_title": "auth.queries.tcp",
-        "item_description": "A number of total query counts which all auth servers receive over TCP since they started initially"
-      },
-      {
-        "item_name": "auth.queries.udp",
-        "item_type": "integer",
-        "item_optional": false,
-        "item_default": 0,
-        "item_title": "auth.queries.udp",
-        "item_description": "A number of total query counts which all auth servers receive over UDP since they started initially"
-      }
-    ],
+    "config_data": [],
     "commands": [
       {
         "command_name": "status",

src/bin/stats/stats_httpd.py.in

@@ -46,7 +46,7 @@ else:
     BASE_LOCATION = "@datadir@" + os.sep + "@PACKAGE@"
     BASE_LOCATION = BASE_LOCATION.replace("${datarootdir}", DATAROOTDIR).replace("${prefix}", PREFIX)
 SPECFILE_LOCATION = BASE_LOCATION + os.sep + "stats-httpd.spec"
-STATS_SPECFILE_LOCATION = BASE_LOCATION + os.sep + "stats.spec"
+SCHEMA_SPECFILE_LOCATION = BASE_LOCATION + os.sep + "stats-schema.spec"
 XML_TEMPLATE_LOCATION = BASE_LOCATION + os.sep + "stats-httpd-xml.tpl"
 XSD_TEMPLATE_LOCATION = BASE_LOCATION + os.sep + "stats-httpd-xsd.tpl"
 XSL_TEMPLATE_LOCATION = BASE_LOCATION + os.sep + "stats-httpd-xsl.tpl"
@@ -175,7 +175,7 @@ class StatsHttpd:
             SPECFILE_LOCATION, self.config_handler, self.command_handler)
         self.cc_session = self.mccs._session
         # read spec file of stats module and subscribe 'Stats'
-        self.stats_module_spec = isc.config.module_spec_from_file(STATS_SPECFILE_LOCATION)
+        self.stats_module_spec = isc.config.module_spec_from_file(SCHEMA_SPECFILE_LOCATION)
         self.stats_config_spec = self.stats_module_spec.get_config_spec()
         self.stats_module_name = self.stats_module_spec.get_module_name()
 

src/bin/stats/tests/b10-stats_test.py

@@ -23,7 +23,11 @@ import unittest
 import imp
 from isc.cc.session import Session, SessionError
 from isc.config.ccsession import ModuleCCSession, ModuleCCSessionError
+from fake_time import time, strftime, gmtime
 import stats
+stats.time = time
+stats.strftime = strftime
+stats.gmtime = gmtime
 from stats import SessionSubject, CCSessionListener, get_timestamp, get_datetime
 from fake_time import _TEST_TIME_SECS, _TEST_TIME_STRF
 
@@ -540,9 +544,14 @@ class TestStats2(unittest.TestCase):
                              os.environ["B10_FROM_SOURCE"] + os.sep + \
                                  "src" + os.sep + "bin" + os.sep + "stats" + \
                                  os.sep + "stats.spec")
+            self.assertEqual(stats.SCHEMA_SPECFILE_LOCATION,
+                             os.environ["B10_FROM_SOURCE"] + os.sep + \
+                                 "src" + os.sep + "bin" + os.sep + "stats" + \
+                                 os.sep + "stats-schema.spec")
         imp.reload(stats)
         # change path of SPECFILE_LOCATION
         stats.SPECFILE_LOCATION = TEST_SPECFILE_LOCATION
+        stats.SCHEMA_SPECFILE_LOCATION = TEST_SPECFILE_LOCATION
         self.assertEqual(stats.SPECFILE_LOCATION, TEST_SPECFILE_LOCATION)
         self.subject = stats.SessionSubject(session=self.session, verbose=True)
         self.session = self.subject.session

src/bin/zonemgr/tests/zonemgr_test.py

@@ -21,11 +21,12 @@ import os
 import tempfile
 from zonemgr import *
 
-ZONE_NAME_CLASS1_IN = ("sd.cn.", "IN")
-ZONE_NAME_CLASS2_CH = ("tw.cn.", "CH")
-ZONE_NAME_CLASS3_IN = ("example.com", "IN")
-ZONE_NAME_CLASS1_CH = ("sd.cn.", "CH")
-ZONE_NAME_CLASS2_IN = ("tw.cn.", "IN")
+ZONE_NAME_CLASS1_IN = ("example.net.", "IN")
+ZONE_NAME_CLASS1_CH = ("example.net.", "CH")
+ZONE_NAME_CLASS2_IN = ("example.org.", "IN")
+ZONE_NAME_CLASS2_CH = ("example.org.", "CH")
+ZONE_NAME_CLASS3_IN = ("example.com.", "IN")
+ZONE_NAME_CLASS3_CH = ("example.com.", "CH")
 
 MAX_TRANSFER_TIMEOUT = 14400
 LOWERBOUND_REFRESH = 10
@@ -80,12 +81,12 @@ class MyZonemgrRefresh(ZonemgrRefresh):
         self._refresh_jitter = 0.25
 
         def get_zone_soa(zone_name, db_file):
-            if zone_name == 'sd.cn.':
-                return (1, 2, 'sd.cn.', 'cn.sd.', 21600, 'SOA', None,
-                        'a.dns.cn. root.cnnic.cn. 2009073106 7200 3600 2419200 21600')
-            elif zone_name == 'tw.cn.':
-                return (1, 2, 'tw.cn.', 'cn.sd.', 21600, 'SOA', None,
-                        'a.dns.cn. root.cnnic.cn. 2009073112 7200 3600 2419200 21600')
+            if zone_name == 'example.net.':
+                return (1, 2, 'example.net.', 'example.net.sd.', 21600, 'SOA', None,
+                        'a.example.net. root.example.net. 2009073106 7200 3600 2419200 21600')
+            elif zone_name == 'example.org.':
+                return (1, 2, 'example.org.', 'example.org.sd.', 21600, 'SOA', None,
+                        'a.example.org. root.example.org. 2009073112 7200 3600 2419200 21600')
             else:
                 return None
         sqlite3_ds.get_zone_soa = get_zone_soa
@@ -94,15 +95,15 @@ class MyZonemgrRefresh(ZonemgrRefresh):
             self._slave_socket, FakeConfig())
         current_time = time.time()
         self._zonemgr_refresh_info = {
-         ('sd.cn.', 'IN'): {
+         ('example.net.', 'IN'): {
          'last_refresh_time': current_time,
          'next_refresh_time': current_time + 6500,
-         'zone_soa_rdata': 'a.dns.cn. root.cnnic.cn. 2009073105 7200 3600 2419200 21600',
+         'zone_soa_rdata': 'a.example.net. root.example.net. 2009073105 7200 3600 2419200 21600',
          'zone_state': 0},
-         ('tw.cn.', 'CH'): {
+         ('example.org.', 'CH'): {
          'last_refresh_time': current_time,
          'next_refresh_time': current_time + 6900,
-         'zone_soa_rdata': 'a.dns.cn. root.cnnic.cn. 2009073112 7200 3600 2419200 21600',
+         'zone_soa_rdata': 'a.example.org. root.example.org. 2009073112 7200 3600 2419200 21600',
          'zone_state': 0}
         }
 
@@ -157,6 +158,7 @@ class TestZonemgrRefresh(unittest.TestCase):
         self.assertFalse(self.zone_refresh._zone_not_exist(ZONE_NAME_CLASS2_CH))
         self.assertTrue(self.zone_refresh._zone_not_exist(ZONE_NAME_CLASS2_IN))
         self.assertTrue(self.zone_refresh._zone_not_exist(ZONE_NAME_CLASS3_IN))
+        self.assertTrue(self.zone_refresh._zone_not_exist(ZONE_NAME_CLASS3_CH))
 
     def test_set_zone_notify_timer(self):
         time1 = time.time()
@@ -179,20 +181,20 @@ class TestZonemgrRefresh(unittest.TestCase):
         self.assertTrue(self.zone_refresh._zone_is_expired(ZONE_NAME_CLASS1_IN))
 
     def test_get_zone_soa_rdata(self):
-        soa_rdata1  = 'a.dns.cn. root.cnnic.cn. 2009073105 7200 3600 2419200 21600'
-        soa_rdata2  = 'a.dns.cn. root.cnnic.cn. 2009073112 7200 3600 2419200 21600'
+        soa_rdata1  = 'a.example.net. root.example.net. 2009073105 7200 3600 2419200 21600'
+        soa_rdata2  = 'a.example.org. root.example.org. 2009073112 7200 3600 2419200 21600'
         self.assertEqual(soa_rdata1, self.zone_refresh._get_zone_soa_rdata(ZONE_NAME_CLASS1_IN))
         self.assertRaises(KeyError, self.zone_refresh._get_zone_soa_rdata, ZONE_NAME_CLASS1_CH)
         self.assertEqual(soa_rdata2, self.zone_refresh._get_zone_soa_rdata(ZONE_NAME_CLASS2_CH))
         self.assertRaises(KeyError, self.zone_refresh._get_zone_soa_rdata, ZONE_NAME_CLASS2_IN)
 
     def test_zonemgr_reload_zone(self):
-        soa_rdata = 'a.dns.cn. root.cnnic.cn. 2009073106 1800 900 2419200 21600'
+        soa_rdata = 'a.example.net. root.example.net. 2009073106 1800 900 2419200 21600'
         # We need to restore this not to harm other tests
         old_get_zone_soa = sqlite3_ds.get_zone_soa
         def get_zone_soa(zone_name, db_file):
-            return (1, 2, 'sd.cn.', 'cn.sd.', 21600, 'SOA', None,
-                    'a.dns.cn. root.cnnic.cn. 2009073106 1800 900 2419200 21600')
+            return (1, 2, 'example.net.', 'example.net.sd.', 21600, 'SOA', None,
+                    'a.example.net. root.example.net. 2009073106 1800 900 2419200 21600')
         sqlite3_ds.get_zone_soa = get_zone_soa
 
         self.zone_refresh.zonemgr_reload_zone(ZONE_NAME_CLASS1_IN)
@@ -274,15 +276,15 @@ class TestZonemgrRefresh(unittest.TestCase):
         self.assertTrue(self.zone_refresh._zone_mgr_is_empty())
 
     def test_zonemgr_add_zone(self):
-        soa_rdata = 'a.dns.cn. root.cnnic.cn. 2009073106 1800 900 2419200 21600'
+        soa_rdata = 'a.example.net. root.example.net. 2009073106 1800 900 2419200 21600'
         # This needs to be restored. The following test actually failed if we left
         # this unclean
         old_get_zone_soa = sqlite3_ds.get_zone_soa
         time1 = time.time()
 
         def get_zone_soa(zone_name, db_file):
-            return (1, 2, 'sd.cn.', 'cn.sd.', 21600, 'SOA', None,
-                    'a.dns.cn. root.cnnic.cn. 2009073106 1800 900 2419200 21600')
+            return (1, 2, 'example.net.', 'example.net.sd.', 21600, 'SOA', None,
+                    'a.example.net. root.example.net. 2009073106 1800 900 2419200 21600')
 
         sqlite3_ds.get_zone_soa = get_zone_soa
 
@@ -314,15 +316,15 @@ class TestZonemgrRefresh(unittest.TestCase):
         current_time = time.time()
         self.assertTrue(zone_timeout <= current_time)
         self.assertRaises(ZonemgrException, self.zone_refresh.zone_handle_notify,\
-                          ("org.cn.", "IN"), "127.0.0.1")
+                          ZONE_NAME_CLASS3_CH, "127.0.0.1")
         self.assertRaises(ZonemgrException, self.zone_refresh.zone_handle_notify,\
                           ZONE_NAME_CLASS3_IN, "127.0.0.1")
 
     def test_zone_refresh_success(self):
-        soa_rdata = 'a.dns.cn. root.cnnic.cn. 2009073106 1800 900 2419200 21600'
+        soa_rdata = 'a.example.net. root.example.net. 2009073106 1800 900 2419200 21600'
         def get_zone_soa(zone_name, db_file):
-            return (1, 2, 'sd.cn.', 'cn.sd.', 21600, 'SOA', None,
-                    'a.dns.cn. root.cnnic.cn. 2009073106 1800 900 2419200 21600')
+            return (1, 2, 'example.net.', 'example.net.sd.', 21600, 'SOA', None,
+                    'a.example.net. root.example.net. 2009073106 1800 900 2419200 21600')
         sqlite3_ds.get_zone_soa = get_zone_soa
         time1 = time.time()
         self.zone_refresh._zonemgr_refresh_info[ZONE_NAME_CLASS1_IN]["zone_state"] = ZONE_REFRESHING
@@ -337,11 +339,11 @@ class TestZonemgrRefresh(unittest.TestCase):
         last_refresh_time = self.zone_refresh._zonemgr_refresh_info[ZONE_NAME_CLASS1_IN]["last_refresh_time"]
         self.assertTrue(time1 <= last_refresh_time)
         self.assertTrue(last_refresh_time <= time2)
-        self.assertRaises(ZonemgrException, self.zone_refresh.zone_refresh_success, ("org.cn.", "CH"))
+        self.assertRaises(ZonemgrException, self.zone_refresh.zone_refresh_success, ("example.test.", "CH"))
         self.assertRaises(ZonemgrException, self.zone_refresh.zone_refresh_success, ZONE_NAME_CLASS3_IN)
 
     def test_zone_refresh_fail(self):
-        soa_rdata = 'a.dns.cn. root.cnnic.cn. 2009073105 7200 3600 2419200 21600'
+        soa_rdata = 'a.example.net. root.example.net. 2009073105 7200 3600 2419200 21600'
         time1 = time.time()
         self.zone_refresh._zonemgr_refresh_info[ZONE_NAME_CLASS1_IN]["zone_state"] = ZONE_REFRESHING
         self.zone_refresh.zone_refresh_fail(ZONE_NAME_CLASS1_IN)
@@ -357,22 +359,22 @@ class TestZonemgrRefresh(unittest.TestCase):
         self.zone_refresh.zone_refresh_fail(ZONE_NAME_CLASS1_IN)
         self.assertEqual(ZONE_EXPIRED, self.zone_refresh._zonemgr_refresh_info[ZONE_NAME_CLASS1_IN]["zone_state"])
 
-        self.assertRaises(ZonemgrException, self.zone_refresh.zone_refresh_fail, ("org.cn.", "CH"))
+        self.assertRaises(ZonemgrException, self.zone_refresh.zone_refresh_fail, ZONE_NAME_CLASS3_CH)
         self.assertRaises(ZonemgrException, self.zone_refresh.zone_refresh_fail, ZONE_NAME_CLASS3_IN)
 
     def test_find_need_do_refresh_zone(self):
         time1 = time.time()
         self.zone_refresh._zonemgr_refresh_info = {
-                ("sd.cn.","IN"):{
+                ("example.net.","IN"):{
                     'last_refresh_time': time1,
                     'next_refresh_time': time1 + 7200,
-                    'zone_soa_rdata': 'a.dns.cn. root.cnnic.cn. 2009073105 7200 3600 2419200 21600',
+                    'zone_soa_rdata': 'a.example.net. root.example.net. 2009073105 7200 3600 2419200 21600',
                     'zone_state': ZONE_OK},
-                ("tw.cn.","CH"):{
+                ("example.org.","CH"):{
                     'last_refresh_time': time1 - 7200,
                     'next_refresh_time': time1,
                     'refresh_timeout': time1 + MAX_TRANSFER_TIMEOUT,
-                    'zone_soa_rdata': 'a.dns.cn. root.cnnic.cn. 2009073112 7200 3600 2419200 21600',
+                    'zone_soa_rdata': 'a.example.org. root.example.org. 2009073112 7200 3600 2419200 21600',
                     'zone_state': ZONE_REFRESHING}
                 }
         zone_need_refresh = self.zone_refresh._find_need_do_refresh_zone()
@@ -385,10 +387,10 @@ class TestZonemgrRefresh(unittest.TestCase):
     def test_do_refresh(self):
         time1 = time.time()
         self.zone_refresh._zonemgr_refresh_info = {
-                ("sd.cn.", "IN"):{
+                ("example.net.", "IN"):{
                     'last_refresh_time': time1 - 7200,
                     'next_refresh_time': time1 - 1,
-                    'zone_soa_rdata': 'a.dns.cn. root.cnnic.cn. 2009073105 7200 3600 2419200 21600',
+                    'zone_soa_rdata': 'a.example.net. root.example.net. 2009073105 7200 3600 2419200 21600',
                     'zone_state': ZONE_OK}
                 }
         self.zone_refresh._do_refresh(ZONE_NAME_CLASS1_IN)
@@ -416,10 +418,10 @@ class TestZonemgrRefresh(unittest.TestCase):
         """
         time1 = time.time()
         self.zone_refresh._zonemgr_refresh_info = {
-                ("sd.cn.", "IN"):{
+                ("example.net.", "IN"):{
                     'last_refresh_time': time1 - 7200,
                     'next_refresh_time': time1 - 1,
-                    'zone_soa_rdata': 'a.dns.cn. root.cnnic.cn. 2009073105 7200 3600 2419200 21600',
+                    'zone_soa_rdata': 'a.example.net. root.example.net. 2009073105 7200 3600 2419200 21600',
                     'zone_state': ZONE_OK}
                 }
         self.zone_refresh._check_sock = self.zone_refresh._master_socket
@@ -465,19 +467,19 @@ class TestZonemgrRefresh(unittest.TestCase):
         # Put something in
         config.set_zone_list_from_name_classes([ZONE_NAME_CLASS1_IN])
         self.zone_refresh.update_config_data(config)
-        self.assertTrue(("sd.cn.", "IN") in
+        self.assertTrue(("example.net.", "IN") in
                         self.zone_refresh._zonemgr_refresh_info)
         # This one does not exist
         config.set_zone_list_from_name_classes(["example.net", "CH"])
         self.assertRaises(ZonemgrException,
                           self.zone_refresh.update_config_data, config)
         # So it should not affect the old ones
-        self.assertTrue(("sd.cn.", "IN") in
+        self.assertTrue(("example.net.", "IN") in
                         self.zone_refresh._zonemgr_refresh_info)
         # Make sure it works even when we "accidentally" forget the final dot
-        config.set_zone_list_from_name_classes([("sd.cn", "IN")])
+        config.set_zone_list_from_name_classes([("example.net", "IN")])
         self.zone_refresh.update_config_data(config)
-        self.assertTrue(("sd.cn.", "IN") in
+        self.assertTrue(("example.net.", "IN") in
                         self.zone_refresh._zonemgr_refresh_info)
 
     def tearDown(self):
@@ -532,7 +534,7 @@ class TestZonemgr(unittest.TestCase):
         self.assertEqual(self.zonemgr.config_handler(config_data1),
                          {"result": [0]})
         self.assertEqual(config_data1, self.zonemgr._config_data)
-        config_data2 = {"zone_name" : "sd.cn.", "port" : "53", "master" : "192.168.1.1"}
+        config_data2 = {"zone_name" : "example.net.", "port" : "53", "master" : "192.168.1.1"}
         self.zonemgr.config_handler(config_data2)
         self.assertEqual(config_data1, self.zonemgr._config_data)
         # jitter should not be bigger than half of the original value
@@ -553,11 +555,11 @@ class TestZonemgr(unittest.TestCase):
         self.assertEqual("initdb.file", self.zonemgr.get_db_file())
 
     def test_parse_cmd_params(self):
-        params1 = {"zone_name" : "org.cn", "zone_class" : "CH", "master" : "127.0.0.1"}
-        answer1 = (("org.cn", "CH"), "127.0.0.1")
+        params1 = {"zone_name" : "example.com.", "zone_class" : "CH", "master" : "127.0.0.1"}
+        answer1 = (ZONE_NAME_CLASS3_CH, "127.0.0.1")
         self.assertEqual(answer1, self.zonemgr._parse_cmd_params(params1, ZONE_NOTIFY_COMMAND))
-        params2 = {"zone_name" : "org.cn", "zone_class" : "CH"}
-        answer2 = ("org.cn", "CH")
+        params2 = {"zone_name" : "example.com.", "zone_class" : "IN"}
+        answer2 = ZONE_NAME_CLASS3_IN
         self.assertEqual(answer2, self.zonemgr._parse_cmd_params(params2, ZONE_XFRIN_SUCCESS_COMMAND))
         self.assertRaises(ZonemgrException, self.zonemgr._parse_cmd_params, params2, ZONE_NOTIFY_COMMAND)
         params1 = {"zone_class" : "CH"}

src/cppcheck-suppress.lst

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

src/lib/Makefile.am

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

src/lib/config/Makefile.am

@@ -2,9 +2,24 @@ SUBDIRS = . tests
 
 AM_CPPFLAGS = -I$(top_srcdir)/src/lib -I$(top_builddir)/src/lib
 AM_CPPFLAGS += -I$(top_builddir)/src/lib/cc
+AM_CPPFLAGS += -I$(top_srcdir)/src/lib/log -I$(top_builddir)/src/lib/log
 AM_CPPFLAGS += $(BOOST_INCLUDES)
 
+# Define rule to build logging source files from message file
+configdef.h configdef.cc: configdef.mes
+	$(top_builddir)/src/lib/log/compiler/message $(top_srcdir)/src/lib/config/configdef.mes
+
+BUILT_SOURCES = configdef.h configdef.cc
+
 lib_LTLIBRARIES = libcfgclient.la
-libcfgclient_la_SOURCES = config_data.h config_data.cc module_spec.h module_spec.cc ccsession.cc ccsession.h
+libcfgclient_la_SOURCES = config_data.h config_data.cc
+libcfgclient_la_SOURCES += module_spec.h module_spec.cc
+libcfgclient_la_SOURCES += ccsession.cc ccsession.h
+libcfgclient_la_SOURCES += config_log.h config_log.cc
+
+nodist_libcfgclient_la_SOURCES  = configdef.h configdef.cc
+
+# The message file should be in the distribution.
+EXTRA_DIST = configdef.mes
 
-CLEANFILES = *.gcno *.gcda
+CLEANFILES = *.gcno *.gcda configdef.h configdef.cc

src/lib/config/ccsession.cc

@@ -12,12 +12,6 @@
 // OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
 // PERFORMANCE OF THIS SOFTWARE.
 
-// 
-// todo: generalize this and make it into a specific API for all modules
-//       to use (i.e. connect to cc, send config and commands, get config,
-//               react on config change announcements)
-//
-
 #include <config.h>
 
 #include <stdexcept>
@@ -38,6 +32,7 @@
 #include <cc/session.h>
 #include <exceptions/exceptions.h>
 
+#include <config/config_log.h>
 #include <config/ccsession.h>
 
 using namespace std;
@@ -164,18 +159,18 @@ ModuleCCSession::readModuleSpecification(const std::string& filename) {
     // this file should be declared in a @something@ directive
     file.open(filename.c_str());
     if (!file) {
-        cout << "error opening " << filename << ": " << strerror(errno) << endl;
-        exit(1);
+        LOG_ERROR(config_logger, CONFIG_FOPEN_ERR).arg(filename).arg(strerror(errno));
+        isc_throw(CCSessionInitError, strerror(errno));
     }
 
     try {
         module_spec = moduleSpecFromFile(file, true);
     } catch (const JSONError& pe) {
-        cout << "Error parsing module specification file: " << pe.what() << endl;
-        exit(1);
+        LOG_ERROR(config_logger, CONFIG_JSON_PARSE).arg(filename).arg(pe.what());
+        isc_throw(CCSessionInitError, pe.what());
     } catch (const ModuleSpecError& dde) {
-        cout << "Error reading module specification file: " << dde.what() << endl;
-        exit(1);
+        LOG_ERROR(config_logger, CONFIG_MODULE_SPEC).arg(filename).arg(dde.what());
+        isc_throw(CCSessionInitError, dde.what());
     }
     file.close();
     return (module_spec);
@@ -223,7 +218,8 @@ ModuleCCSession::ModuleCCSession(
     int rcode;
     ConstElementPtr err = parseAnswer(rcode, answer);
     if (rcode != 0) {
-        std::cerr << "[" << module_name_ << "] Error in specification: " << answer << std::endl;
+        LOG_ERROR(config_logger, CONFIG_MANAGER_MOD_SPEC).arg(answer->str());
+        isc_throw(CCSessionInitError, answer->str());
     }
     
     setLocalConfig(Element::fromJSON("{}"));
@@ -236,7 +232,8 @@ ModuleCCSession::ModuleCCSession(
         if (rcode == 0) {
             handleConfigUpdate(new_config);
         } else {
-            std::cerr << "[" << module_name_ << "] Error getting config: " << new_config << std::endl;
+            LOG_ERROR(config_logger, CONFIG_MANAGER_CONFIG).arg(new_config->str());
+            isc_throw(CCSessionInitError, answer->str());
         }
     }
 
@@ -348,15 +345,13 @@ ModuleCCSession::checkCommand() {
                 answer = checkModuleCommand(cmd_str, target_module, arg);
             }
         } catch (const CCSessionError& re) {
-            // TODO: Once we have logging and timeouts, we should not
-            // answer here (potential interference)
-            answer = createAnswer(1, re.what());
+            LOG_ERROR(config_logger, CONFIG_CCSESSION_MSG).arg(re.what());
         }
         if (!isNull(answer)) {
             session_.reply(routing, answer);
         }
     }
-    
+
     return (0);
 }
 

src/lib/config/ccsession.h

@@ -135,6 +135,15 @@ public:
 };
 
 ///
+/// \brief This exception is thrown if the constructor fails
+///
+class CCSessionInitError : public isc::Exception {
+public:
+    CCSessionInitError(const char* file, size_t line, const char* what) :
+        isc::Exception(file, line, what) {}
+};
+
+///
 /// \brief This module keeps a connection to the command channel,
 /// holds configuration information, and handles messages from
 /// the command channel
@@ -154,6 +163,11 @@ public:
      * AbstractSession without establishing the session.
      * Note: the design decision on who is responsible for establishing the
      * session is in flux, and may change in near future.
+     *
+     * \exception CCSessionInitError when the initialization fails,
+     *            either because the file cannot be read or there is
+     *            a communication problem with the config manager.
+     *
      * @param command_handler A callback function pointer to be called when
      * a control command from a remote agent needs to be performed on the
      * local module.

src/lib/config/config_log.cc

@@ -0,0 +1,26 @@
+// Copyright (C) 2011  Internet Systems Consortium, Inc. ("ISC")
+//
+// Permission to use, copy, modify, and/or distribute this software for any
+// purpose with or without fee is hereby granted, provided that the above
+// copyright notice and this permission notice appear in all copies.
+//
+// THE SOFTWARE IS PROVIDED "AS IS" AND ISC DISCLAIMS ALL WARRANTIES WITH
+// REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY
+// AND FITNESS.  IN NO EVENT SHALL ISC BE LIABLE FOR ANY SPECIAL, DIRECT,
+// INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER RESULTING FROM
+// LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF CONTRACT, NEGLIGENCE
+// OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
+// PERFORMANCE OF THIS SOFTWARE.
+
+/// Defines the logger used by the config lib
+
+#include "config/config_log.h"
+
+namespace isc {
+namespace config {
+
+isc::log::Logger config_logger("config");
+
+} // namespace nsas
+} // namespace isc
+

src/lib/config/config_log.h

@@ -0,0 +1,38 @@
+// Copyright (C) 2011  Internet Systems Consortium, Inc. ("ISC")
+//
+// Permission to use, copy, modify, and/or distribute this software for any
+// purpose with or without fee is hereby granted, provided that the above
+// copyright notice and this permission notice appear in all copies.
+//
+// THE SOFTWARE IS PROVIDED "AS IS" AND ISC DISCLAIMS ALL WARRANTIES WITH
+// REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY
+// AND FITNESS.  IN NO EVENT SHALL ISC BE LIABLE FOR ANY SPECIAL, DIRECT,
+// INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER RESULTING FROM
+// LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF CONTRACT, NEGLIGENCE
+// OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
+// PERFORMANCE OF THIS SOFTWARE.
+
+#ifndef __CONFIG_LOG__H
+#define __CONFIG_LOG__H
+
+#include <log/macros.h>
+#include "configdef.h"
+
+namespace isc {
+namespace config {
+
+/// \brief Config Logging
+///
+/// Defines logger object for config log messages
+
+/// \brief Config Logger
+///
+/// Define the logger used to log messages.  We could define it in multiple
+/// modules, but defining in a single module and linking to it saves time and
+/// space.
+extern isc::log::Logger config_logger;    // isc::config::config_logger is the CONFIG logger
+
+} // namespace config
+} // namespace isc
+
+#endif // __CONFIG_LOG__H

src/lib/config/configdef.mes

@@ -0,0 +1,50 @@
+# Copyright (C) 2011  Internet Systems Consortium, Inc. ("ISC")
+#
+# Permission to use, copy, modify, and/or distribute this software for any
+# purpose with or without fee is hereby granted, provided that the above
+# copyright notice and this permission notice appear in all copies.
+#
+# THE SOFTWARE IS PROVIDED "AS IS" AND ISC DISCLAIMS ALL WARRANTIES WITH
+# REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY
+# AND FITNESS.  IN NO EVENT SHALL ISC BE LIABLE FOR ANY SPECIAL, DIRECT,
+# INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER RESULTING FROM
+# LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF CONTRACT, NEGLIGENCE
+# OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
+# PERFORMANCE OF THIS SOFTWARE.
+
+$PREFIX CONFIG_
+$NAMESPACE isc::config
+
+% FOPEN_ERR     error opening %1: %2
+There was an error opening the given file.
+
+% JSON_PARSE    JSON parse error in %1: %2
+There was a parse error in the JSON file. The given file does not appear
+to be in valid JSON format. Please verify that the filename is correct
+and that the contents are valid JSON.
+
+% MODULE_SPEC   module specification error in %1: %2
+The given file does not appear to be a valid specification file. Please
+verify that the filename is correct and that its contents are a valid
+BIND10 module specification.
+
+% MANAGER_MOD_SPEC    module specification not accepted by cfgmgr: %1
+The module specification file for this module was rejected by the
+configuration manager. The full error message answer from the
+configuration manager is appended to the log error. The most likely
+cause is that the module is of a different (specification file) version
+than the running configuration manager.
+
+% MANAGER_CONFIG    error getting configuration from cfgmgr: %1
+The configuration manager returned an error when this module requested
+the configuration. The full error message answer from the configuration
+manager is appended to the log error. The most likely cause is that
+the module is of a different (command specification) version than the
+running configuration manager.
+
+% CCSESSION_MSG error in CC session message: %1
+There was a problem with an incoming message on the command and control
+channel. The message does not appear to be a valid command, and is
+missing a required element or contains an unknown data format. This
+most likely means that another BIND10 module is sending a bad message.
+The message itself is ignored by this module.

src/lib/config/tests/Makefile.am

@@ -24,6 +24,7 @@ run_unittests_LDFLAGS = $(AM_LDFLAGS) $(GTEST_LDFLAGS)
 run_unittests_LDADD =  $(GTEST_LDADD)
 run_unittests_LDADD += $(top_builddir)/src/lib/cc/libcc.la
 run_unittests_LDADD += $(top_builddir)/src/lib/exceptions/libexceptions.la
+run_unittests_LDADD += $(top_builddir)/src/lib/log/liblog.la
 run_unittests_LDADD += libfake_session.la
 run_unittests_LDADD += $(top_builddir)/src/lib/config/libcfgclient.la
 

src/lib/config/tests/ccsession_unittests.cc

@@ -264,10 +264,7 @@ TEST_F(CCSessionTest, checkCommand) {
 
     session.addMessage(el("{ \"command\": \"bad_command\" }"), "Spec29", "*");
     result = mccs.checkCommand();
-    EXPECT_EQ(1, session.getMsgQueue()->size());
-    msg = session.getFirstMessage(group, to);
-    EXPECT_EQ("{ \"result\": [ 1, \"Command part in command message missing, empty, or not a list\" ] }", msg->str());
-    EXPECT_EQ(0, result);
+    EXPECT_EQ(0, session.getMsgQueue()->size());
 
     session.addMessage(el("{ \"command\": [ \"bad_command\" ] }"),
                        "Spec29", "*");
@@ -432,4 +429,24 @@ TEST_F(CCSessionTest, ignoreRemoteConfigCommands) {
     EXPECT_EQ(0, session.getMsgQueue()->size());
 }
 
+TEST_F(CCSessionTest, initializationFail) {
+    // bad specification
+    EXPECT_THROW(ModuleCCSession(ccspecfile("spec8.spec"), session,
+                                 NULL, NULL), CCSessionInitError);
+
+    // file that does not exist
+    EXPECT_THROW(ModuleCCSession(ccspecfile("does_not_exist_spec"),
+                                 session, NULL, NULL),
+                                 CCSessionInitError);
+
+
+    session.getMessages()->add(createAnswer(1, el("\"just an error\"")));
+
+    EXPECT_FALSE(session.haveSubscription("Spec29", "*"));
+    EXPECT_THROW(ModuleCCSession(ccspecfile("spec29.spec"), session,
+                                 my_config_handler, my_command_handler),
+                                 CCSessionInitError);
+    EXPECT_TRUE(session.haveSubscription("Spec29", "*"));
+}
+
 }

src/lib/config/tests/run_unittests.cc

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

src/lib/cryptolink/crypto_hmac.cc

@@ -144,8 +144,17 @@ public:
         // Botan's verify_mac checks if len matches the output_length,
         // which causes it to fail for truncated signatures, so we do
         // the check ourselves
+        // SEE BELOW FOR TEMPORARY CHANGE
         try {
             Botan::SecureVector<Botan::byte> our_mac = hmac_->final();
+            if (len < getOutputLength()) {
+                // Currently we don't support truncated signature.  To avoid
+                // validating too short signature accidently, we enforce the
+                // standard signature size for the moment.
+                // Once we support truncation correctly, this if-clause should
+                // (and the capitalized comment above) be removed.
+                return (false);
+            }
             if (len == 0 || len > getOutputLength()) {
                 len = getOutputLength();
             }

src/lib/cryptolink/tests/crypto_unittests.cc

@@ -233,18 +233,6 @@ TEST(CryptoLinkTest, HMAC_MD5_RFC2202_SIGN) {
                                        0x79 };
     doHMACTest(data4, secret4, 25, MD5, hmac_expected4, 16);
 
-    const uint8_t secret5[] = { 0x0c, 0x0c, 0x0c, 0x0c, 0x0c, 0x0c,
-                                0x0c, 0x0c, 0x0c, 0x0c, 0x0c, 0x0c,
-                                0x0c, 0x0c, 0x0c, 0x0c };
-    const uint8_t hmac_expected5[] = { 0x56, 0x46, 0x1e, 0xf2, 0x34,
-                                       0x2e, 0xdc, 0x00, 0xf9, 0xba,
-                                       0xb9, 0x95, 0x69, 0x0e, 0xfd,
-                                       0x4c };
-    doHMACTest("Test With Truncation", secret5, 16, MD5,
-               hmac_expected5, 16);
-    doHMACTest("Test With Truncation", secret5, 16, MD5,
-               hmac_expected5, 12);
-
     const uint8_t hmac_expected6[] = { 0x6b, 0x1a, 0xb7, 0xfe, 0x4b,
                                        0xd7, 0xbf, 0x8f, 0x0b, 0x62,
                                        0xe6, 0xce, 0x61, 0xb9, 0xd0,
@@ -261,6 +249,21 @@ TEST(CryptoLinkTest, HMAC_MD5_RFC2202_SIGN) {
                std::string(80, 0xaa).c_str(), 80, MD5, hmac_expected7, 16);
 }
 
+// Temporarily disabled
+TEST(CryptoLinkTest, DISABLED_HMAC_MD5_RFC2202_SIGN_TRUNCATED) {
+    const uint8_t secret5[] = { 0x0c, 0x0c, 0x0c, 0x0c, 0x0c, 0x0c,
+                                0x0c, 0x0c, 0x0c, 0x0c, 0x0c, 0x0c,
+                                0x0c, 0x0c, 0x0c, 0x0c };
+    const uint8_t hmac_expected5[] = { 0x56, 0x46, 0x1e, 0xf2, 0x34,
+                                       0x2e, 0xdc, 0x00, 0xf9, 0xba,
+                                       0xb9, 0x95, 0x69, 0x0e, 0xfd,
+                                       0x4c };
+    doHMACTest("Test With Truncation", secret5, 16, MD5,
+               hmac_expected5, 16);
+    doHMACTest("Test With Truncation", secret5, 16, MD5,
+               hmac_expected5, 12);
+}
+
 //
 // Test values taken from RFC 2202
 //
@@ -302,19 +305,6 @@ TEST(CryptoLinkTest, HMAC_SHA1_RFC2202_SIGN) {
                                        0x6c, 0x2d, 0x72, 0x35, 0xda };
     doHMACTest(std::string(50, 0xcd), secret4, 25, SHA1, hmac_expected4, 20);
 
-    const uint8_t secret5[] = { 0x0c, 0x0c, 0x0c, 0x0c, 0x0c, 0x0c,
-                                0x0c, 0x0c, 0x0c, 0x0c, 0x0c, 0x0c,
-                                0x0c, 0x0c, 0x0c, 0x0c, 0x0c, 0x0c,
-                                0x0c, 0x0c };
-    const uint8_t hmac_expected5[] = { 0x4c, 0x1a, 0x03, 0x42, 0x4b,
-                                       0x55, 0xe0, 0x7f, 0xe7, 0xf2,
-                                       0x7b, 0xe1, 0xd5, 0x8b, 0xb9,
-                                       0x32, 0x4a, 0x9a, 0x5a, 0x04 };
-    doHMACTest("Test With Truncation", secret5, 20, SHA1,
-               hmac_expected5, 20);
-    doHMACTest("Test With Truncation", secret5, 20, SHA1,
-               hmac_expected5, 12);
-
     const uint8_t hmac_expected6[] = { 0xaa, 0x4a, 0xe5, 0xe1, 0x52,
                                        0x72, 0xd0, 0x0e, 0x95, 0x70,
                                        0x56, 0x37, 0xce, 0x8a, 0x3b,
@@ -331,6 +321,22 @@ TEST(CryptoLinkTest, HMAC_SHA1_RFC2202_SIGN) {
                std::string(80, 0xaa).c_str(), 80, SHA1, hmac_expected7, 20);
 }
 
+// Temporarily disabled
+TEST(CryptoLinkTest, DISABLED_HMAC_SHA1_RFC2202_SIGN_TRUNCATED) {
+    const uint8_t secret5[] = { 0x0c, 0x0c, 0x0c, 0x0c, 0x0c, 0x0c,
+                                0x0c, 0x0c, 0x0c, 0x0c, 0x0c, 0x0c,
+                                0x0c, 0x0c, 0x0c, 0x0c, 0x0c, 0x0c,
+                                0x0c, 0x0c };
+    const uint8_t hmac_expected5[] = { 0x4c, 0x1a, 0x03, 0x42, 0x4b,
+                                       0x55, 0xe0, 0x7f, 0xe7, 0xf2,
+                                       0x7b, 0xe1, 0xd5, 0x8b, 0xb9,
+                                       0x32, 0x4a, 0x9a, 0x5a, 0x04 };
+    doHMACTest("Test With Truncation", secret5, 20, SHA1,
+               hmac_expected5, 20);
+    doHMACTest("Test With Truncation", secret5, 20, SHA1,
+               hmac_expected5, 12);
+}
+
 //
 // Test values taken from RFC 4231
 //
@@ -384,17 +390,6 @@ TEST(CryptoLinkTest, HMAC_SHA256_RFC2202_SIGN) {
                                        0x66, 0x5b };
     doHMACTest(std::string(50, 0xcd), secret4, 25, SHA256, hmac_expected4, 32);
 
-    const uint8_t secret5[] = { 0x0c, 0x0c, 0x0c, 0x0c, 0x0c, 0x0c,
-                                0x0c, 0x0c, 0x0c, 0x0c, 0x0c, 0x0c,
-                                0x0c, 0x0c, 0x0c, 0x0c, 0x0c, 0x0c,
-                                0x0c, 0x0c };
-    const uint8_t hmac_expected5[] = { 0xa3, 0xb6, 0x16, 0x74, 0x73,
-                                       0x10, 0x0e, 0xe0, 0x6e, 0x0c,
-                                       0x79, 0x6c, 0x29, 0x55, 0x55,
-                                       0x2b };
-    doHMACTest("Test With Truncation", secret5, 20, SHA256,
-               hmac_expected5, 16);
-
     const uint8_t hmac_expected6[] = { 0x60, 0xe4, 0x31, 0x59, 0x1e,
                                        0xe0, 0xb6, 0x7f, 0x0d, 0x8a,
                                        0x26, 0xaa, 0xcb, 0xf5, 0xb7,
@@ -418,6 +413,19 @@ TEST(CryptoLinkTest, HMAC_SHA256_RFC2202_SIGN) {
                std::string(131, 0xaa).c_str(), 131, SHA256, hmac_expected7, 32);
 }
 
+TEST(CryptoLinkTest, DISABLED_HMAC_SHA256_RFC2202_SIGN_TRUNCATED) {
+    const uint8_t secret5[] = { 0x0c, 0x0c, 0x0c, 0x0c, 0x0c, 0x0c,
+                                0x0c, 0x0c, 0x0c, 0x0c, 0x0c, 0x0c,
+                                0x0c, 0x0c, 0x0c, 0x0c, 0x0c, 0x0c,
+                                0x0c, 0x0c };
+    const uint8_t hmac_expected5[] = { 0xa3, 0xb6, 0x16, 0x74, 0x73,
+                                       0x10, 0x0e, 0xe0, 0x6e, 0x0c,
+                                       0x79, 0x6c, 0x29, 0x55, 0x55,
+                                       0x2b };
+    doHMACTest("Test With Truncation", secret5, 20, SHA256,
+               hmac_expected5, 16);
+}
+
 namespace {
     size_t
     sigVectorLength(HashAlgorithm alg, size_t len) {

src/lib/datasrc/Makefile.am

@@ -7,7 +7,7 @@ AM_CPPFLAGS += $(SQLITE_CFLAGS)
 
 AM_CXXFLAGS = $(B10_CXXFLAGS)
 
-CLEANFILES = *.gcno *.gcda
+CLEANFILES = *.gcno *.gcda messagedef.h messagedef.cc
 
 lib_LTLIBRARIES = libdatasrc.la
 libdatasrc_la_SOURCES = data_source.h data_source.cc
@@ -20,3 +20,16 @@ libdatasrc_la_SOURCES += zonetable.h zonetable.cc
 libdatasrc_la_SOURCES += memory_datasrc.h memory_datasrc.cc
 libdatasrc_la_SOURCES += zone.h
 libdatasrc_la_SOURCES += result.h
+libdatasrc_la_SOURCES += logger.h logger.cc
+nodist_libdatasrc_la_SOURCES = messagedef.h messagedef.cc
+
+libdatasrc_la_LIBADD = $(top_builddir)/src/lib/exceptions/libexceptions.la
+libdatasrc_la_LIBADD += $(top_builddir)/src/lib/dns/libdns++.la
+libdatasrc_la_LIBADD += $(top_builddir)/src/lib/log/liblog.la
+libdatasrc_la_LIBADD += $(top_builddir)/src/lib/cc/libcc.la
+
+BUILT_SOURCES = messagedef.h messagedef.cc
+messagedef.h messagedef.cc: Makefile messagedef.mes
+	$(top_builddir)/src/lib/log/compiler/message $(top_srcdir)/src/lib/datasrc/messagedef.mes
+
+EXTRA_DIST = messagedef.mes

src/lib/datasrc/cache.cc

@@ -24,6 +24,7 @@
 #include <list>
 
 #include <datasrc/cache.h>
+#include <datasrc/logger.h>
 
 using namespace std;
 using namespace isc::dns;
@@ -204,16 +205,21 @@ public:
 // HotCacheImpl constructor
 HotCacheImpl::HotCacheImpl(int slots, bool enabled) :
     enabled_(enabled), slots_(slots), count_(0)
-{}
+{
+    LOG_DEBUG(logger, DBG_TRACE_BASIC, DATASRC_CACHE_CREATE);
+}
 
 // Insert a cache node into the cache
 inline void
 HotCacheImpl::insert(const CacheNodePtr node) {
+    LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_CACHE_INSERT).
+        arg(node->getRRset()->getName());
     std::map<Question, CacheNodePtr>::const_iterator iter;
     iter = map_.find(node->question);
     if (iter != map_.end()) {
         CacheNodePtr old = iter->second;
         if (old && old->isValid()) {
+            LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_CACHE_OLD_FOUND);
             remove(old);
         }
     }
@@ -225,6 +231,7 @@ HotCacheImpl::insert(const CacheNodePtr node) {
     ++count_;
 
     if (slots_ != 0 && count_ > slots_) {
+        LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_CACHE_FULL);
         remove(lru_.back());
     }
 }
@@ -245,6 +252,8 @@ HotCacheImpl::promote(CacheNodePtr node) {
 // Remove a node from the LRU list and the map
 void
 HotCacheImpl::remove(ConstCacheNodePtr node) {
+    LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_CACHE_REMOVE).
+        arg(node->getRRset()->getName());
     lru_.erase(node->lru_entry_);
     map_.erase(node->question);
     --count_;
@@ -257,6 +266,7 @@ HotCache::HotCache(const int slots) {
 
 // HotCache destructor
 HotCache::~HotCache() {
+    LOG_DEBUG(logger, DBG_TRACE_BASIC, DATASRC_CACHE_DESTROY);
     delete impl_;
 }
 
@@ -303,18 +313,21 @@ HotCache::retrieve(const Name& n, const RRClass& c, const RRType& t,
     std::map<Question, CacheNodePtr>::const_iterator iter;
     iter = impl_->map_.find(Question(n, c, t));
     if (iter == impl_->map_.end()) {
+        LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_CACHE_NOT_FOUND).arg(n);
         return (false);
     }
 
     CacheNodePtr node = iter->second;
 
     if (node->isValid()) {
+        LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_CACHE_FOUND).arg(n);
         impl_->promote(node);
         rrset = node->getRRset();
         flags = node->getFlags();
         return (true);
     }
 
+    LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_CACHE_EXPIRED).arg(n);
     impl_->remove(node);
     return (false);
 }
@@ -328,6 +341,9 @@ HotCache::setSlots(const int slots) {
         return;
     }
 
+    logger.info(DATASRC_CACHE_SLOTS).arg(slots).arg(max(0, impl_->count_ -
+                                                        slots));
+
     while (impl_->slots_ != 0 && impl_->count_ > impl_->slots_) {
         impl_->remove(impl_->lru_.back());
     }
@@ -343,6 +359,11 @@ HotCache::getSlots() const {
 void
 HotCache::setEnabled(const bool e) {
     impl_->enabled_ = e;
+    if (e) {
+        logger.info(DATASRC_CACHE_ENABLE);
+    } else {
+        logger.info(DATASRC_CACHE_DISABLE);
+    }
 }
 
 /// Indicate whether the cache is enabled

src/lib/datasrc/data_source.cc

@@ -25,6 +25,7 @@
 #include <datasrc/cache.h>
 #include <datasrc/data_source.h>
 #include <datasrc/query.h>
+#include <datasrc/logger.h>
 
 #include <util/encode/base32hex.h>
 #include <util/hash/sha1.h>
@@ -83,7 +84,7 @@ class ZoneInfo {
 public:
     ZoneInfo(DataSrc* ts,
              const isc::dns::Name& n,
-             const isc::dns::RRClass& c, 
+             const isc::dns::RRClass& c,
              const isc::dns::RRType& t = isc::dns::RRType::ANY()) :
         top_source_(ts),
         dsm_(((t == RRType::DS() && n.getLabelCount() != 1)
@@ -123,6 +124,8 @@ getAdditional(Query& q, ConstRRsetPtr rrset) {
         const Rdata& rd(it->getCurrent());
         if (rrset->getType() == RRType::NS()) {
             const generic::NS& ns = dynamic_cast<const generic::NS&>(rd);
+            LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_QUERY_GET_NS_ADDITIONAL).
+                arg(ns.getNSName()).arg(rrset->getName());
             q.tasks().push(QueryTaskPtr(
                                new QueryTask(q, ns.getNSName(),
                                              Message::SECTION_ADDITIONAL,
@@ -130,6 +133,8 @@ getAdditional(Query& q, ConstRRsetPtr rrset) {
                                              QueryTask::GETADDITIONAL)));
         } else if (rrset->getType() == RRType::MX()) {
             const generic::MX& mx = dynamic_cast<const generic::MX&>(rd);
+            LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_QUERY_GET_MX_ADDITIONAL).
+                arg(mx.getMXName()).arg(rrset->getName());
             q.tasks().push(QueryTaskPtr(
                                new QueryTask(q, mx.getMXName(),
                                              Message::SECTION_ADDITIONAL,
@@ -143,11 +148,14 @@ getAdditional(Query& q, ConstRRsetPtr rrset) {
 // understand DNAME
 void
 synthesizeCname(QueryTaskPtr task, RRsetPtr rrset, RRsetList& target) {
+    LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_QUERY_SYNTH_CNAME).
+        arg(rrset->getName());
     RdataIteratorPtr it = rrset->getRdataIterator();
 
     // More than one DNAME RR in the RRset is illegal, so we only have
     // to process the first one.
     if (it->isLast()) {
+        logger.error(DATASRC_QUERY_EMPTY_DNAME).arg(rrset->getName());
         return;
     }
 
@@ -171,16 +179,20 @@ synthesizeCname(QueryTaskPtr task, RRsetPtr rrset, RRsetList& target) {
 // to by a CNAME record
 void
 chaseCname(Query& q, QueryTaskPtr task, RRsetPtr rrset) {
+    LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_QUERY_FOLLOW_CNAME).
+        arg(rrset->getName());
     RdataIteratorPtr it = rrset->getRdataIterator();
 
     // More than one CNAME RR in the RRset is illegal, so we only have
     // to process the first one.
     if (it->isLast()) {
+        logger.error(DATASRC_QUERY_EMPTY_CNAME).arg(rrset->getName());
         return;
     }
 
     // Stop chasing CNAMES after 16 lookups, to prevent loops
     if (q.tooMany()) {
+        logger.error(DATASRC_QUERY_TOO_MANY_CNAMES).arg(rrset->getName());
         return;
     }
 
@@ -194,6 +206,8 @@ chaseCname(Query& q, QueryTaskPtr task, RRsetPtr rrset) {
 // Check the cache for data which can answer the current query task.
 bool
 checkCache(QueryTask& task, RRsetList& target) {
+    LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_QUERY_CHECK_CACHE).
+        arg(task.qname).arg(task.qtype);
     HotCache& cache = task.q.getCache();
     RRsetList rrsets;
     RRsetPtr rrset;
@@ -206,6 +220,9 @@ checkCache(QueryTask& task, RRsetList& target) {
         // ANY queries must be handled by the low-level data source,
         // or the results won't be guaranteed to be complete
         if (task.qtype == RRType::ANY() || task.qclass == RRClass::ANY()) {
+            LOG_DEBUG(logger, DBG_TRACE_DATA,
+                      DATASRC_QUERY_NO_CACHE_ANY_SIMPLE).arg(task.qname).
+                arg(task.qtype).arg(task.qclass);
             break;
         }
 
@@ -235,6 +252,8 @@ checkCache(QueryTask& task, RRsetList& target) {
 
     case QueryTask::AUTH_QUERY:         // Find exact RRset or CNAME
         if (task.qtype == RRType::ANY() || task.qclass == RRClass::ANY()) {
+            LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_QUERY_NO_CACHE_ANY_AUTH).
+                arg(task.qname).arg(task.qtype).arg(task.qclass);
             break;
         }
 
@@ -353,6 +372,8 @@ DataSrc::Result
 doQueryTask(QueryTask& task, ZoneInfo& zoneinfo, RRsetList& target) {
     HotCache& cache = task.q.getCache();
     RRsetPtr rrset;
+    LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_DO_QUERY).arg(task.qname).
+        arg(task.qtype);
 
     // First off, make sure at least we have a matching zone in some data
     // source.  We must do this before checking the cache, because it can
@@ -363,11 +384,14 @@ doQueryTask(QueryTask& task, ZoneInfo& zoneinfo, RRsetList& target) {
     const Name* const zonename = zoneinfo.getEnclosingZone();
     if (ds == NULL) {
         task.flags |= DataSrc::NO_SUCH_ZONE;
+        logger.info(DATASRC_QUERY_NO_ZONE).arg(task.qname).arg(task.qclass);
         return (DataSrc::SUCCESS);
     }
 
     // Then check the cache for matching data
     if (checkCache(task, target)) {
+        LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_QUERY_CACHED).
+            arg(task.qname).arg(task.qtype);
         return (DataSrc::SUCCESS);
     }
 
@@ -378,10 +402,13 @@ doQueryTask(QueryTask& task, ZoneInfo& zoneinfo, RRsetList& target) {
     DataSrc::Result result;
     switch (task.op) {
     case QueryTask::SIMPLE_QUERY:
+        LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_QUERY_IS_SIMPLE).
+            arg(task.qname).arg(task.qtype);
         result = ds->findExactRRset(task.qname, task.qclass, task.qtype,
                                     target, task.flags, zonename);
 
         if (result != DataSrc::SUCCESS) {
+            logger.error(DATASRC_QUERY_SIMPLE_FAIL).arg(result);
             return (result);
         }
 
@@ -403,10 +430,13 @@ doQueryTask(QueryTask& task, ZoneInfo& zoneinfo, RRsetList& target) {
         return (result);
 
     case QueryTask::AUTH_QUERY:
+        LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_QUERY_IS_AUTH).
+            arg(task.qname).arg(task.qtype);
         result = ds->findRRset(task.qname, task.qclass, task.qtype,
                                target, task.flags, zonename);
 
         if (result != DataSrc::SUCCESS) {
+            logger.error(DATASRC_QUERY_AUTH_FAIL).arg(result);
             return (result);
         }
 
@@ -439,10 +469,16 @@ doQueryTask(QueryTask& task, ZoneInfo& zoneinfo, RRsetList& target) {
 
     case QueryTask::GLUE_QUERY:
     case QueryTask::NOGLUE_QUERY:
+        LOG_DEBUG(logger, DBG_TRACE_DATA, task.op == QueryTask::GLUE_QUERY ?
+                     DATASRC_QUERY_IS_GLUE : DATASRC_QUERY_IS_NOGLUE).
+            arg(task.qname).arg(task.qtype);
         result = ds->findAddrs(task.qname, task.qclass, target,
                                task.flags, zonename);
 
         if (result != DataSrc::SUCCESS) {
+            logger.error(task.op == QueryTask::GLUE_QUERY ?
+                         DATASRC_QUERY_GLUE_FAIL : DATASRC_QUERY_NOGLUE_FAIL).
+                arg(result);
             return (result);
         }
 
@@ -468,10 +504,13 @@ doQueryTask(QueryTask& task, ZoneInfo& zoneinfo, RRsetList& target) {
         return (result);
 
     case QueryTask::REF_QUERY:
+        LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_QUERY_IS_REF).
+            arg(task.qname).arg(task.qtype);
         result = ds->findReferral(task.qname, task.qclass, target,
                                  task.flags, zonename);
 
         if (result != DataSrc::SUCCESS) {
+            logger.error(DATASRC_QUERY_REF_FAIL).arg(result);
             return (result);
         }
 
@@ -505,6 +544,7 @@ doQueryTask(QueryTask& task, ZoneInfo& zoneinfo, RRsetList& target) {
     }
 
     // Not reached
+    logger.error(DATASRC_QUERY_INVALID_OP);
     return (DataSrc::ERROR);
 }
 
@@ -516,6 +556,8 @@ inline void
 addToMessage(Query& q, const Message::Section sect, RRsetPtr rrset,
              bool no_dnssec = false)
 {
+    LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_QUERY_ADD_RRSET).
+        arg(rrset->getName()).arg(rrset->getType());
     Message& m = q.message();
     if (no_dnssec) {
         if (rrset->getType() == RRType::RRSIG() ||
@@ -534,6 +576,7 @@ addToMessage(Query& q, const Message::Section sect, RRsetPtr rrset,
 // Copy referral information into the authority section of a message
 inline void
 copyAuth(Query& q, RRsetList& auth) {
+    LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_QUERY_COPY_AUTH);
     BOOST_FOREACH(RRsetPtr rrset, auth) {
         if (rrset->getType() == RRType::DNAME()) {
             continue;
@@ -571,6 +614,9 @@ refQuery(const Query& q, const Name& name, ZoneInfo& zoneinfo,
 // they'll be handled in a normal lookup in the zone.
 inline bool
 hasDelegation(Query& q, QueryTaskPtr task, ZoneInfo& zoneinfo) {
+    LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_QUERY_DELEGATION).
+        arg(task->qname);
+
     const Name* const zonename = zoneinfo.getEnclosingZone();
     if (zonename == NULL) {
         if (task->state == QueryTask::GETANSWER) {
@@ -636,6 +682,7 @@ addSOA(Query& q, ZoneInfo& zoneinfo) {
     RRsetList soa;
 
     const Name* const zonename = zoneinfo.getEnclosingZone();
+    LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_QUERY_ADD_SOA).arg(*zonename);
     QueryTask newtask(q, *zonename, RRType::SOA(), QueryTask::SIMPLE_QUERY);
     RETERR(doQueryTask(newtask, zoneinfo, soa));
     if (newtask.flags != 0) {
@@ -649,6 +696,7 @@ addSOA(Query& q, ZoneInfo& zoneinfo) {
 
 inline DataSrc::Result
 addNSEC(Query& q, const Name& name, ZoneInfo& zoneinfo) {
+    LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_QUERY_ADD_NSEC).arg(name);
     RRsetList nsec;
 
     QueryTask newtask(q, name, RRType::NSEC(), QueryTask::SIMPLE_QUERY); 
@@ -665,9 +713,11 @@ inline DataSrc::Result
 getNsec3(Query& q, ZoneInfo& zoneinfo, string& hash, RRsetPtr& target) {
     const DataSrc* ds = zoneinfo.getDataSource();
     const Name* const zonename = zoneinfo.getEnclosingZone();
+    LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_QUERY_ADD_NSEC3).arg(*zonename);
 
     if (ds == NULL) {
         q.message().setRcode(Rcode::SERVFAIL());
+        logger.error(DATASRC_QUERY_NO_DS_NSEC3).arg(*zonename);
         return (DataSrc::ERROR);
     }
 
@@ -770,6 +820,7 @@ proveNX(Query& q, QueryTaskPtr task, ZoneInfo& zoneinfo, const bool wildcard) {
             const DataSrc* ds = zoneinfo.getDataSource();
             if (ds == NULL) {
                 m.setRcode(Rcode::SERVFAIL());
+                logger.error(DATASRC_QUERY_NO_DS_NSEC).arg(*zonename);
                 return (DataSrc::ERROR);
             }
             ds->findPreviousName(task->qname, nsecname, zonename);
@@ -798,6 +849,7 @@ proveNX(Query& q, QueryTaskPtr task, ZoneInfo& zoneinfo, const bool wildcard) {
 // Attempt a wildcard lookup
 inline DataSrc::Result
 tryWildcard(Query& q, QueryTaskPtr task, ZoneInfo& zoneinfo, bool& found) {
+    LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_QUERY_WILDCARD).arg(task->qname);
     Message& m = q.message();
     DataSrc::Result result;
     found = false;
@@ -851,6 +903,8 @@ tryWildcard(Query& q, QueryTaskPtr task, ZoneInfo& zoneinfo, bool& found) {
             result = proveNX(q, task, zoneinfo, true);
             if (result != DataSrc::SUCCESS) {
                 m.setRcode(Rcode::SERVFAIL());
+                logger.error(DATASRC_QUERY_WILDCARD_PROVENX_FAIL).
+                    arg(task->qname).arg(result);
                 return (DataSrc::ERROR);
             }
         }
@@ -873,6 +927,8 @@ tryWildcard(Query& q, QueryTaskPtr task, ZoneInfo& zoneinfo, bool& found) {
 
             RRsetList auth;
             if (!refQuery(q, *zonename, zoneinfo, auth)) {
+                logger.error(DATASRC_QUERY_WILDCARD_REFERRAL).arg(task->qname).
+                    arg(result);
                 return (DataSrc::ERROR);
             }
 
@@ -888,6 +944,8 @@ 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());
     Message& m = q.message();
     vector<RRsetPtr> additional;
 
@@ -905,6 +963,7 @@ DataSrc::doQuery(Query& q) {
         // Can't query directly for RRSIG.
         if (task->qtype == RRType::RRSIG()) {
             m.setRcode(Rcode::REFUSED());
+            logger.warn(DATASRC_QUERY_RRSIG).arg(task->qname);
             return;
         }
 
@@ -912,6 +971,7 @@ DataSrc::doQuery(Query& q) {
         if (task->op == QueryTask::SIMPLE_QUERY ||
             task->op == QueryTask::REF_QUERY) {
             m.setRcode(Rcode::SERVFAIL());
+            logger.error(DATASRC_QUERY_MISPLACED_TASK);
             return;
         }
 
@@ -931,6 +991,7 @@ DataSrc::doQuery(Query& q) {
         result = doQueryTask(*task, zoneinfo, data);
         if (result != SUCCESS) {
             m.setRcode(Rcode::SERVFAIL());
+            logger.error(DATASRC_QUERY_TASK_FAIL).arg(result);
             return;
         }
 
@@ -940,6 +1001,7 @@ DataSrc::doQuery(Query& q) {
         if (task->flags == NO_SUCH_ZONE) {
             if (task->state == QueryTask::GETANSWER) {
                 m.setRcode(Rcode::REFUSED());
+                // No need to log it here, it was already logged in doQueryTask
                 return;
             }
             continue;
@@ -981,6 +1043,7 @@ DataSrc::doQuery(Query& q) {
                     RRsetList auth;
                     if (!refQuery(q, Name(*zonename), zoneinfo, auth) ||
                         !findRRsetFromList(auth, RRType::NS())) {
+                        logger.error(DATASRC_QUERY_MISSING_NS).arg(*zonename);
                         isc_throw(DataSourceError,
                                   "NS RR not found in " << *zonename << "/" <<
                                   q.qclass());
@@ -1005,10 +1068,12 @@ DataSrc::doQuery(Query& q) {
                 continue;
 
             default:
+                logger.error(DATASRC_UNEXPECTED_QUERY_STATE);
                 isc_throw (Unexpected, "unexpected query state");
             }
         } else if (result == ERROR || result == NOT_IMPLEMENTED) {
             m.setRcode(Rcode::SERVFAIL());
+            logger.error(DATASRC_QUERY_FAIL);
             return;
         } else if ((task->flags & CNAME_FOUND) != 0) {
             // The qname node contains a CNAME.  Add a new task to the
@@ -1026,6 +1091,7 @@ DataSrc::doQuery(Query& q) {
                 m.setHeaderFlag(Message::HEADERFLAG_AA, false);
                 if (!refQuery(q, task->qname, zoneinfo, auth)) {
                     m.setRcode(Rcode::SERVFAIL());
+                    logger.error(DATASRC_QUERY_BAD_REFERRAL).arg(task->qname);
                     return;
                 }
                 BOOST_FOREACH (RRsetPtr rrset, auth) {
@@ -1057,6 +1123,7 @@ DataSrc::doQuery(Query& q) {
             result = tryWildcard(q, task, zoneinfo, wildcard_found);
             if (result != SUCCESS) {
                 m.setRcode(Rcode::SERVFAIL());
+                logger.error(DATASRC_QUERY_WILDCARD_FAIL).arg(task->qname);
                 return;
             }
 
@@ -1078,6 +1145,7 @@ DataSrc::doQuery(Query& q) {
 
                 result = addSOA(q, zoneinfo);
                 if (result != SUCCESS) {
+                    logger.error(DATASRC_QUERY_MISSING_SOA).arg(*zonename);
                     isc_throw(DataSourceError,
                               "SOA RR not found in " << *zonename <<
                               "/" << q.qclass());
@@ -1094,6 +1162,7 @@ DataSrc::doQuery(Query& q) {
                 result = proveNX(q, task, zoneinfo, false);
                 if (result != DataSrc::SUCCESS) {
                     m.setRcode(Rcode::SERVFAIL());
+                    logger.error(DATASRC_QUERY_PROVENX_FAIL).arg(task->qname);
                     return;
                 }
             }
@@ -1102,6 +1171,7 @@ DataSrc::doQuery(Query& q) {
         } else {
             // Should never be reached!
             m.setRcode(Rcode::SERVFAIL());
+            logger.error(DATASRC_QUERY_UNKNOWN_RESULT);
             return;
         }
     }
@@ -1197,7 +1267,10 @@ DataSrc::findReferral(const Name& qname, const RRClass& qclass,
 
 void
 MetaDataSrc::addDataSrc(ConstDataSrcPtr data_src) {
+    LOG_DEBUG(logger, DBG_TRACE_BASIC, DATASRC_META_ADD);
     if (getClass() != RRClass::ANY() && data_src->getClass() != getClass()) {
+        logger.error(DATASRC_META_ADD_CLASS_MISMATCH).
+            arg(data_src->getClass()).arg(getClass());
         isc_throw(Unexpected, "class mismatch");
     }
 
@@ -1206,6 +1279,7 @@ MetaDataSrc::addDataSrc(ConstDataSrcPtr data_src) {
 
 void
 MetaDataSrc::removeDataSrc(ConstDataSrcPtr data_src) {
+    LOG_DEBUG(logger, DBG_TRACE_BASIC, DATASRC_META_REMOVE);
     std::vector<ConstDataSrcPtr>::iterator it, itr;
     for (it = data_sources.begin(); it != data_sources.end(); ++it) {
         if (*it == data_src) {

src/lib/datasrc/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 <datasrc/logger.h>
+
+namespace isc {
+namespace datasrc {
+
+isc::log::Logger logger("datasrc");
+
+}
+}

src/lib/datasrc/logger.h

@@ -0,0 +1,46 @@
+// 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 <datasrc/messagedef.h>
+
+/// \file logger.h
+/// \brief Data Source library global logger
+///
+/// This holds the logger for the data source library. It is a private header
+/// and should not be included in any publicly used header, only in local
+/// cc files.
+
+namespace isc {
+namespace datasrc {
+
+/// \brief The logger for this library
+extern isc::log::Logger logger;
+
+enum {
+    /// \brief Trace basic operations
+    DBG_TRACE_BASIC = 10,
+    /// \brief Trace data changes and lookups as well
+    DBG_TRACE_DATA = 20,
+    /// \brief Detailed even about how the lookups happen
+    DBG_TRACE_DETAILED = 50
+};
+
+}
+}
+
+#endif

src/lib/datasrc/memory_datasrc.cc

@@ -24,6 +24,7 @@
 
 #include <datasrc/memory_datasrc.h>
 #include <datasrc/rbtree.h>
+#include <datasrc/logger.h>
 
 using namespace std;
 using namespace isc::dns;
@@ -94,6 +95,8 @@ struct MemoryZone::MemoryZoneImpl {
              l > origin_labels;
              --l, wname = wname.split(1)) {
             if (wname.isWildcard()) {
+                LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_MEM_ADD_WILDCARD).
+                    arg(name);
                 // Ensure a separate level exists for the "wildcarding" name,
                 // and mark the node as "wild".
                 DomainNode* node;
@@ -130,10 +133,13 @@ struct MemoryZone::MemoryZoneImpl {
             // (depending on how we support DNSSEC).  We should revisit it
             // at that point.
             if (!domain->empty()) {
+                LOG_ERROR(logger, DATASRC_MEM_CNAME_TO_NONEMPTY).
+                    arg(rrset->getName());
                 isc_throw(AddError, "CNAME can't be added with other data for "
                           << rrset->getName());
             }
         } else if (domain->find(RRType::CNAME()) != domain->end()) {
+            LOG_ERROR(logger, DATASRC_MEM_CNAME_COEXIST).arg(rrset->getName());
             isc_throw(AddError, "CNAME and " << rrset->getType() <<
                       " can't coexist for " << rrset->getName());
         }
@@ -151,6 +157,7 @@ struct MemoryZone::MemoryZoneImpl {
             (rrset->getType() == RRType::NS() &&
             domain->find(RRType::DNAME()) != domain->end())))
         {
+            LOG_ERROR(logger, DATASRC_MEM_DNAME_NS).arg(rrset->getName());
             isc_throw(AddError, "DNAME can't coexist with NS in non-apex "
                 "domain " << rrset->getName());
         }
@@ -172,6 +179,8 @@ struct MemoryZone::MemoryZoneImpl {
             // XXX: this is not only for CNAME or DNAME. We should generalize
             // this code for all other "singleton RR types" (such as SOA) in a
             // separate task.
+            LOG_ERROR(logger, DATASRC_MEM_SINGLETON).arg(rrset->getName()).
+                arg(rrset->getType());
             isc_throw(AddError, "multiple RRs of singleton type for "
                       << rrset->getName());
         }
@@ -180,6 +189,8 @@ struct MemoryZone::MemoryZoneImpl {
         if (compare.getRelation() != NameComparisonResult::SUPERDOMAIN &&
             compare.getRelation() != NameComparisonResult::EQUAL)
         {
+            LOG_ERROR(logger, DATASRC_MEM_OUT_OF_ZONE).arg(rrset->getName()).
+                arg(origin_);
             isc_throw(OutOfZone, "The name " << rrset->getName() <<
                 " is not contained in zone " << origin_);
         }
@@ -194,10 +205,14 @@ struct MemoryZone::MemoryZoneImpl {
         // behavior.
         if (rrset->getName().isWildcard()) {
             if (rrset->getType() == RRType::NS()) {
+                LOG_ERROR(logger, DATASRC_MEM_WILDCARD_NS).
+                    arg(rrset->getName());
                 isc_throw(AddError, "Invalid NS owner name (wildcard): " <<
                           rrset->getName());
             }
             if (rrset->getType() == RRType::DNAME()) {
+                LOG_ERROR(logger, DATASRC_MEM_WILDCARD_DNAME).
+                    arg(rrset->getName());
                 isc_throw(AddError, "Invalid DNAME owner name (wildcard): " <<
                           rrset->getName());
             }
@@ -210,6 +225,8 @@ struct MemoryZone::MemoryZoneImpl {
      */
     // Implementation of MemoryZone::add
     result::Result add(const ConstRRsetPtr& rrset, DomainTree* domains) {
+        LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_MEM_ADD_RRSET).
+            arg(rrset->getName()).arg(rrset->getType()).arg(origin_);
         // Sanitize input
         addValidation(rrset);
 
@@ -271,6 +288,8 @@ struct MemoryZone::MemoryZoneImpl {
     void addFromLoad(const ConstRRsetPtr& set, DomainTree* domains) {
             switch (add(set, domains)) {
                 case result::EXIST:
+                    LOG_ERROR(logger, DATASRC_MEM_DUP_RRSET).
+                        arg(set->getName()).arg(set->getType());
                     isc_throw(dns::MasterLoadError, "Duplicate rrset: " <<
                         set->toText());
                 case result::SUCCESS:
@@ -307,6 +326,8 @@ struct MemoryZone::MemoryZoneImpl {
         const Domain::const_iterator foundDNAME(node.getData()->find(
             RRType::DNAME()));
         if (foundDNAME != node.getData()->end()) {
+            LOG_DEBUG(logger, DBG_TRACE_DETAILED,
+                      DATASRC_MEM_DNAME_ENCOUNTERED);
             state->dname_node_ = &node;
             state->rrset_ = foundDNAME->second;
             // No more processing below the DNAME (RFC 2672, section 3
@@ -328,6 +349,8 @@ struct MemoryZone::MemoryZoneImpl {
                 return (false);
             }
 
+            LOG_DEBUG(logger, DBG_TRACE_DETAILED, DATASRC_MEM_NS_ENCOUNTERED);
+
             // BIND 9 checks if this node is not the origin.  That's probably
             // because it can support multiple versions for dynamic updates
             // and IXFR, and it's possible that the callback is called at
@@ -363,6 +386,8 @@ struct MemoryZone::MemoryZoneImpl {
         rrset, bool rename)
     {
         if (rename) {
+            LOG_DEBUG(logger, DBG_TRACE_DETAILED, DATASRC_MEM_RENAME).
+                arg(rrset->getName()).arg(name);
             /*
              * We lose a signature here. But it would be wrong anyway, because
              * the name changed. This might turn out to be unimportant in
@@ -385,6 +410,8 @@ struct MemoryZone::MemoryZoneImpl {
     FindResult find(const Name& name, RRType type,
                     RRsetList* target, const FindOptions options) const
     {
+        LOG_DEBUG(logger, DBG_TRACE_BASIC, DATASRC_MEM_FIND).arg(name).
+            arg(type);
         // Get the node
         DomainNode* node(NULL);
         FindState state(options);
@@ -411,12 +438,16 @@ struct MemoryZone::MemoryZoneImpl {
                  * is NULL.
                  */
                 if (state.dname_node_ != NULL) {
+                    LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_MEM_DNAME_FOUND).
+                        arg(state.rrset_->getName());
                     // We were traversing a DNAME node (and wanted to go
                     // lower below it), so return the DNAME
                     return (FindResult(DNAME, prepareRRset(name, state.rrset_,
                         rename)));
                 }
                 if (state.zonecut_node_ != NULL) {
+                    LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_MEM_DELEG_FOUND).
+                        arg(state.rrset_->getName());
                     return (FindResult(DELEGATION, prepareRRset(name,
                         state.rrset_, rename)));
                 }
@@ -426,6 +457,8 @@ struct MemoryZone::MemoryZoneImpl {
                 // the zone but is empty.  Treat it as NXRRSET.
                 if (node_path.getLastComparisonResult().getRelation() ==
                     NameComparisonResult::SUPERDOMAIN) {
+                    LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_MEM_SUPER_STOP).
+                        arg(node_path.getAbsoluteName()).arg(name);
                     return (FindResult(NXRRSET, ConstRRsetPtr()));
                 }
 
@@ -463,6 +496,8 @@ struct MemoryZone::MemoryZoneImpl {
                     if (node_path.getLastComparisonResult().getRelation() ==
                         NameComparisonResult::COMMONANCESTOR && node_path.
                         getLastComparisonResult().getCommonLabels() > 1) {
+                        LOG_DEBUG(logger, DBG_TRACE_DATA,
+                                     DATASRC_MEM_WILDCARD_CANCEL).arg(name);
                         return (FindResult(NXDOMAIN, ConstRRsetPtr()));
                     }
                     Name wildcard(Name("*").concatenate(
@@ -485,6 +520,8 @@ struct MemoryZone::MemoryZoneImpl {
 
                 // fall through
             case DomainTree::NOTFOUND:
+                LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_MEM_NOTFOUND).
+                    arg(name);
                 return (FindResult(NXDOMAIN, ConstRRsetPtr()));
             case DomainTree::EXACTMATCH: // This one is OK, handle it
                 break;
@@ -496,6 +533,8 @@ struct MemoryZone::MemoryZoneImpl {
         // If there is an exact match but the node is empty, it's equivalent
         // to NXRRSET.
         if (node->isEmpty()) {
+            LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_MEM_DOMAIN_EMPTY).
+                arg(name);
             return (FindResult(NXRRSET, ConstRRsetPtr()));
         }
 
@@ -506,6 +545,8 @@ struct MemoryZone::MemoryZoneImpl {
         if (node->getFlag(DomainNode::FLAG_CALLBACK) && node != origin_data_) {
             found = node->getData()->find(RRType::NS());
             if (found != node->getData()->end()) {
+                LOG_DEBUG(logger, DBG_TRACE_DATA,
+                          DATASRC_MEM_EXACT_DELEGATION).arg(name);
                 return (FindResult(DELEGATION, prepareRRset(name,
                     found->second, rename)));
             }
@@ -521,23 +562,30 @@ struct MemoryZone::MemoryZoneImpl {
                     boost::const_pointer_cast<RRset>(prepareRRset(name,
                     found->second, rename)));
             }
+            LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_MEM_ANY_SUCCESS).
+                arg(name);
             return (FindResult(SUCCESS, ConstRRsetPtr()));
         }
 
         found = node->getData()->find(type);
         if (found != node->getData()->end()) {
             // Good, it is here
+            LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_MEM_SUCCESS).arg(name).
+                arg(type);
             return (FindResult(SUCCESS, prepareRRset(name, found->second,
                 rename)));
         } else {
             // Next, try CNAME.
             found = node->getData()->find(RRType::CNAME());
             if (found != node->getData()->end()) {
+                LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_MEM_CNAME).arg(name);
                 return (FindResult(CNAME, prepareRRset(name, found->second,
                     rename)));
             }
         }
         // No exact match or CNAME.  Return NXRRSET.
+        LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_MEM_NXRRSET).arg(type).
+            arg(name);
         return (FindResult(NXRRSET, ConstRRsetPtr()));
     }
 };
@@ -545,9 +593,13 @@ struct MemoryZone::MemoryZoneImpl {
 MemoryZone::MemoryZone(const RRClass& zone_class, const Name& origin) :
     impl_(new MemoryZoneImpl(zone_class, origin))
 {
+    LOG_DEBUG(logger, DBG_TRACE_BASIC, DATASRC_MEM_CREATE).arg(origin).
+        arg(zone_class);
 }
 
 MemoryZone::~MemoryZone() {
+    LOG_DEBUG(logger, DBG_TRACE_BASIC, DATASRC_MEM_DESTROY).arg(getOrigin()).
+        arg(getClass());
     delete impl_;
 }
 
@@ -576,6 +628,8 @@ MemoryZone::add(const ConstRRsetPtr& rrset) {
 
 void
 MemoryZone::load(const string& filename) {
+    LOG_DEBUG(logger, DBG_TRACE_BASIC, DATASRC_MEM_LOAD).arg(getOrigin()).
+        arg(filename);
     // Load it into a temporary tree
     MemoryZoneImpl::DomainTree tmp;
     masterLoad(filename.c_str(), getOrigin(), getClass(),
@@ -588,6 +642,8 @@ MemoryZone::load(const string& filename) {
 
 void
 MemoryZone::swap(MemoryZone& zone) {
+    LOG_DEBUG(logger, DBG_TRACE_BASIC, DATASRC_MEM_SWAP).arg(getOrigin()).
+        arg(zone.getOrigin());
     std::swap(impl_, zone.impl_);
 }
 
@@ -628,6 +684,9 @@ MemoryDataSrc::addZone(ZonePtr zone) {
                   "Null pointer is passed to MemoryDataSrc::addZone()");
     }
 
+    LOG_DEBUG(logger, DBG_TRACE_BASIC, DATASRC_MEM_ADD_ZONE).
+        arg(zone->getOrigin()).arg(zone->getClass().toText());
+
     const result::Result result = impl_->zone_table.addZone(zone);
     if (result == result::SUCCESS) {
         ++impl_->zone_count;
@@ -637,6 +696,7 @@ MemoryDataSrc::addZone(ZonePtr zone) {
 
 MemoryDataSrc::FindResult
 MemoryDataSrc::findZone(const isc::dns::Name& name) const {
+    LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_MEM_FIND_ZONE).arg(name);
     return (FindResult(impl_->zone_table.findZone(name).code,
                        impl_->zone_table.findZone(name).zone));
 }

src/lib/datasrc/messagedef.mes

@@ -0,0 +1,498 @@
+# Copyright (C) 2011  Internet Systems Consortium, Inc. ("ISC")
+#
+# Permission to use, copy, modify, and/or distribute this software for any
+# purpose with or without fee is hereby granted, provided that the above
+# copyright notice and this permission notice appear in all copies.
+#
+# THE SOFTWARE IS PROVIDED "AS IS" AND ISC DISCLAIMS ALL WARRANTIES WITH
+# REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY
+# AND FITNESS.  IN NO EVENT SHALL ISC BE LIABLE FOR ANY SPECIAL, DIRECT,
+# INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER RESULTING FROM
+# LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF CONTRACT, NEGLIGENCE
+# OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
+# PERFORMANCE OF THIS SOFTWARE.
+
+$PREFIX DATASRC_
+$NAMESPACE isc::datasrc
+
+# \brief Messages for the data source library
+
+% CACHE_CREATE creating the hotspot cache
+Debug information that the hotspot cache was created at startup.
+
+% CACHE_DESTROY destroying the hotspot cache
+Debug information. The hotspot cache is being destroyed.
+
+% CACHE_INSERT inserting item '%1' into the cache
+Debug information. It means a new item is being inserted into the hotspot
+cache.
+
+% CACHE_OLD_FOUND older instance of cache item found, replacing
+Debug information. While inserting an item into the hotspot cache, an older
+instance of an item with the same name was found. The old instance will be
+removed. This should be directly followed by CACHE_REMOVE.
+
+% CACHE_FULL cache is full, dropping oldest
+Debug information. After inserting an item into the hotspot cache, the
+maximum number of items was exceeded, so the least recently used item will
+be dropped. This should be directly followed by CACHE_REMOVE.
+
+% CACHE_REMOVE removing '%1' from the cache
+Debug information. An item is being removed from the hotspot cache.
+
+% CACHE_NOT_FOUND the item '%1' was not found
+Debug information. It was attempted to look up an item in the hotspot cache,
+but it is not there.
+
+% CACHE_FOUND the item '%1' was found
+Debug information. An item was successfully looked up in the hotspot cache.
+
+% CACHE_EXPIRED the item '%1' is expired
+Debug information. There was an attempt to look up an item in the hotspot
+cache. And the item was actually there, but it was too old, so it was removed
+instead and nothing is reported (the external behaviour is the same as with
+CACHE_NOT_FOUND).
+
+% CACHE_SLOTS setting the cache size to '%1', dropping '%2' items
+The maximum allowed number of items of the hotspot cache is set to the given
+number. If there are too many, some of them will be dropped. The size of 0
+means no limit.
+
+% CACHE_ENABLE enabling the cache
+The hotspot cache is enabled from now on.
+
+% CACHE_DISABLE disabling the cache
+The hotspot cache is disabled from now on. It is not going to store
+information or return anything.
+
+% QUERY_SYNTH_CNAME synthesizing CNAME from DNAME on '%1'
+Debug information. While answering a query, a DNAME was met. The DNAME itself
+will be returned, but along with it a CNAME for clients which don't understand
+DNAMEs will be synthesized.
+
+% QUERY_EMPTY_DNAME the DNAME on '%1' is empty
+During an attempt to synthesize CNAME from this DNAME it was discovered the
+DNAME is empty (it has no records). This indicates problem with supplied data.
+
+% QUERY_GET_NS_ADDITIONAL addition of A/AAAA for '%1' requested by NS '%2'
+Debug information. While processing a query, a NS record was met. It
+references the mentioned address, so A/AAAA records for it are looked up
+and put it into the additional section.
+
+% QUERY_GET_MX_ADDITIONAL addition of A/AAAA for '%1' requested by MX '%2'
+Debug information. While processing a query, a MX record was met. It
+references the mentioned address, so A/AAAA records for it are looked up
+and put it into the additional section.
+
+% QUERY_FOLLOW_CNAME following CNAME at '%1'
+Debug information. The domain is a CNAME (or a DNAME and we created a CNAME
+for it already), so it's being followed.
+
+% QUERY_EMPTY_CNAME cNAME at '%1' is empty
+There was an CNAME and it was being followed. But it contains no records,
+so there's nowhere to go. There will be no answer. This indicates a problem
+with supplied data.
+We tried to follow
+
+% QUERY_TOO_MANY_CNAMES cNAME chain limit exceeded at '%1'
+A CNAME led to another CNAME and it led to another, and so on. After 16
+CNAMEs, the software gave up. Long CNAME chains are discouraged, and this
+might possibly be a loop as well. Note that some of the CNAMEs might have
+been synthesized from DNAMEs. This indicates problem with supplied data.
+
+% QUERY_CHECK_CACHE checking cache for '%1/%2'
+Debug information. While processing a query, lookup to the hotspot cache
+is being made.
+
+% QUERY_NO_CACHE_ANY_SIMPLE ignoring cache for ANY query (%1/%2 in %3 class)
+Debug information. The hotspot cache is ignored for ANY queries for consistency
+reasons.
+
+% QUERY_NO_CACHE_ANY_AUTH ignoring cache for ANY query (%1/%2 in %3 class)
+Debug information. The hotspot cache is ignored for authoritative ANY queries
+for consistency reasons.
+
+% DO_QUERY handling query for '%1/%2'
+Debug information. We're processing some internal query for given name and
+type.
+
+% QUERY_NO_ZONE no zone containing '%1' in class '%2'
+Lookup of domain failed because the data have no zone that contain the
+domain. Maybe someone sent a query to the wrong server for some reason.
+
+% QUERY_CACHED data for %1/%2 found in cache
+Debug information. The requested data were found in the hotspot cache, so
+no query is sent to the real data source.
+
+% QUERY_IS_SIMPLE simple query (%1/%2)
+Debug information. The last DO_QUERY is a simple query.
+
+% QUERY_IS_AUTH auth query (%1/%2)
+Debug information. The last DO_QUERY is an auth query.
+
+% QUERY_IS_GLUE glue query (%1/%2)
+Debug information. The last DO_QUERY is query for glue addresses.
+
+% QUERY_IS_NOGLUE query for non-glue addresses (%1/%2)
+Debug information. The last DO_QUERY is query for addresses that are not
+glue.
+
+% QUERY_IS_REF query for referral (%1/%2)
+Debug information. The last DO_QUERY is query for referral information.
+
+% QUERY_SIMPLE_FAIL the underlying data source failed with %1
+The underlying data source failed to answer the simple query. 1 means some
+error, 2 is not implemented. The data source should have logged the specific
+error already.
+
+% QUERY_AUTH_FAIL the underlying data source failed with %1
+The underlying data source failed to answer the authoritative query. 1 means
+some error, 2 is not implemented. The data source should have logged the
+specific error already.
+
+% QUERY_GLUE_FAIL the underlying data source failed with %1
+The underlying data source failed to answer the glue query. 1 means some error,
+2 is not implemented. The data source should have logged the specific error
+already.
+
+% QUERY_NOGLUE_FAIL the underlying data source failed with %1
+The underlying data source failed to answer the no-glue query. 1 means some
+error, 2 is not implemented. The data source should have logged the specific
+error already.
+
+% QUERY_REF_FAIL the underlying data source failed with %1
+The underlying data source failed to answer the query for referral information.
+1 means some error, 2 is not implemented. The data source should have logged
+the specific error already.
+
+% QUERY_INVALID_OP invalid query operation requested
+This indicates a programmer error. The DO_QUERY was called with unknown
+operation code.
+
+% QUERY_ADD_RRSET adding RRset '%1/%2' to message
+Debug information. An RRset is being added to the response message.
+
+% QUERY_COPY_AUTH copying authoritative section into message
+Debug information. The whole referral information is being copied into the
+response message.
+
+% QUERY_DELEGATION looking for delegation on the path to '%1'
+Debug information. The software is trying to identify delegation points on the
+way down to the given domain.
+
+% QUERY_ADD_SOA adding SOA of '%1'
+Debug information. A SOA record of the given zone is being added to the
+authority section of the response message.
+
+% QUERY_ADD_NSEC adding NSEC record for '%1'
+Debug information. A NSEC record covering this zone is being added.
+
+% QUERY_ADD_NSEC3 adding NSEC3 record of zone '%1'
+Debug information. A NSEC3 record for the given zone is being added to the
+response message.
+
+% QUERY_NO_DS_NSEC3 there's no DS record in the '%1' zone
+An attempt to add a NSEC3 record into the message failed, because the zone does
+not have any DS record. This indicates problem with the provided data.
+
+% QUERY_NO_DS_NSEC there's no DS record in the '%1' zone
+An attempt to add a NSEC record into the message failed, because the zone does
+not have any DS record. This indicates problem with the provided data.
+
+% QUERY_WILDCARD looking for a wildcard covering '%1'
+Debug information. A direct match wasn't found, so a wildcard covering the
+domain is being looked for now.
+
+% QUERY_WILDCARD_PROVENX_FAIL unable to prove nonexistence of '%1' (%2)
+While processing a wildcard, it wasn't possible to prove nonexistence of the
+given domain or record.  The code is 1 for error and 2 for not implemented.
+
+% QUERY_WILDCARD_REFERRAL unable to find referral info for '%1' (%2)
+While processing a wildcard, a referral was met. But it wasn't possible to get
+enough information for it.  The code is 1 for error, 2 for not implemented.
+
+% QUERY_PROCESS processing query '%1/%2' in the '%3' class
+Debug information. A sure query is being processed now.
+
+% QUERY_RRSIG unable to answer RRSIG query
+The server is unable to answer a direct query for RRSIG type, but was asked
+to do so.
+
+% QUERY_MISPLACED_TASK task of this type should not be here
+This indicates a programming error. A task was found in the internal task
+queue, but this kind of task wasn't designed to be inside the queue (it should
+be handled right away, not queued).
+
+% QUERY_TASK_FAIL task failed with %1
+The query subtask failed. The reason should have been reported by the subtask
+already. The code is 1 for error, 2 for not implemented.
+
+% QUERY_MISSING_NS missing NS records for '%1'
+NS records should have been put into the authority section. However, this zone
+has none. This indicates problem with provided data.
+
+% UNEXPECTED_QUERY_STATE unexpected query state
+This indicates a programming error. An internal task of unknown type was
+generated.
+
+% QUERY_FAIL query failed
+Some subtask of query processing failed. The reason should have been reported
+already. We are returning SERVFAIL.
+
+% QUERY_BAD_REFERRAL bad referral to '%1'
+The domain lives in another zone. But it is not possible to generate referral
+information for it.
+
+% QUERY_WILDCARD_FAIL error processing wildcard for '%1'
+During an attempt to cover the domain by a wildcard an error happened. The
+exact kind was hopefully already reported.
+
+% QUERY_MISSING_SOA the zone '%1' has no SOA
+The answer should have been a negative one (eg. of nonexistence of something).
+To do so, a SOA record should be put into the authority section, but the zone
+does not have one. This indicates problem with provided data.
+
+% QUERY_PROVENX_FAIL unable to prove nonexistence of '%1'
+The user wants DNSSEC and we discovered the entity doesn't exist (either
+domain or the record). But there was an error getting NSEC/NSEC3 record
+to prove the nonexistence.
+
+% QUERY_UNKNOWN_RESULT unknown result of subtask
+This indicates a programmer error. The answer of subtask doesn't look like
+anything known.
+
+% META_ADD adding a data source into meta data source
+Debug information. Yet another data source is being added into the meta data
+source. (probably at startup or reconfiguration)
+
+% META_ADD_CLASS_MISMATCH mismatch between classes '%1' and '%2'
+It was attempted to add a data source into a meta data source. But their
+classes do not match.
+
+% META_REMOVE removing data source from meta data source
+Debug information. A data source is being removed from meta data source.
+
+% MEM_ADD_WILDCARD adding wildcards for '%1'
+Debug information. Some special marks above each * in wildcard name are needed.
+They are being added now for this name.
+
+% MEM_CNAME_TO_NONEMPTY can't add CNAME to domain with other data in '%1'
+Someone or something tried to add a CNAME into a domain that already contains
+some other data. But the protocol forbids coexistence of CNAME with anything
+(RFC 1034, section 3.6.2). This indicates a problem with provided data.
+
+% MEM_CNAME_COEXIST can't add data to CNAME in domain '%1'
+This is the same problem as in MEM_CNAME_TO_NONEMPTY, but it happened the
+other way around -- adding some outher data to CNAME.
+
+% MEM_DNAME_NS dNAME and NS can't coexist in non-apex domain '%1'
+It was requested for DNAME and NS records to be put into the same domain
+which is not the apex (the top of the zone). This is forbidden by RFC
+2672, section 3. This indicates a problem with provided data.
+
+% MEM_SINGLETON trying to add multiple RRs for domain '%1' and type '%2'
+Some resource types are singletons -- only one is allowed in a domain
+(for example CNAME or SOA). This indicates a problem with provided data.
+
+% MEM_OUT_OF_ZONE domain '%1' doesn't belong to zone '%2'
+It was attempted to add the domain into a zone that shouldn't have it
+(eg. the domain is not subdomain of the zone origin). This indicates a
+problem with provided data.
+
+% MEM_WILDCARD_NS nS record in wildcard domain '%1'
+The software refuses to load NS records into a wildcard domain.  It isn't
+explicitly forbidden, but the protocol is ambiguous about how this should
+behave and BIND 9 refuses that as well. Please describe your intention using
+different tools.
+
+% MEM_WILDCARD_DNAME dNAME record in wildcard domain '%1'
+The software refuses to load DNAME records into a wildcard domain.  It isn't
+explicitly forbidden, but the protocol is ambiguous about how this should
+behave and BIND 9 refuses that as well. Please describe your intention using
+different tools.
+
+% MEM_ADD_RRSET adding RRset '%1/%2' into zone '%3'
+Debug information. An RRset is being added to the in-memory data source.
+
+% MEM_DUP_RRSET duplicate RRset '%1/%2'
+An RRset is being inserted into in-memory data source for a second time.  The
+original version must be removed first. Note that loading master files where an
+RRset is split into multiple locations is not supported yet.
+
+% MEM_DNAME_ENCOUNTERED encountered a DNAME
+Debug information. While searching for the requested domain, a DNAME was
+encountered on the way.  This may lead to redirection to a different domain and
+stop the search.
+
+% MEM_NS_ENCOUNTERED encountered a NS
+Debug information. While searching for the requested domain, a NS was
+encountered on the way (a delegation). This may lead to stop of the search.
+
+% MEM_RENAME renaming RRset from '%1' to '%2'
+Debug information. A RRset is being generated from a different RRset (most
+probably a wildcard). So it must be renamed to whatever the user asked for. In
+fact, it's impossible to rename RRsets with our libraries, so a new one is
+created and all resource records are copied over.
+
+% MEM_FIND find '%1/%2'
+Debug information. A search for the requested RRset is being started.
+
+% MEM_DNAME_FOUND DNAME found at '%1'
+Debug information. A DNAME was found instead of the requested information.
+
+% MEM_DELEG_FOUND delegation found at '%1'
+Debug information. A delegation point was found above the requested record.
+
+% MEM_SUPER_STOP stopped at superdomain '%1', domain '%2' is empty
+Debug information. The search stopped at a superdomain of the requested
+domain. The domain is a empty nonterminal, therefore it is treated  as NXRRSET
+case (eg. the domain exists, but it doesn't have the requested record type).
+
+% MEM_WILDCARD_CANCEL wildcard match canceled for '%1'
+Debug information. A domain above wildcard was reached, but there's something
+below the requested domain. Therefore the wildcard doesn't apply here.  This
+behaviour is specified by RFC 1034, section 4.3.3
+
+% MEM_NOTFOUND requested domain '%1' not found
+Debug information. The requested domain does not exist.
+
+% MEM_DOMAIN_EMPTY requested domain '%1' is empty
+Debug information. The requested domain exists in the tree of domains, but
+it is empty. Therefore it doesn't contain the requested resource type.
+
+% MEM_EXACT_DELEGATION delegation at the exact domain '%1'
+Debug information. There's a NS record at the requested domain. This means
+this zone is not authoritative for the requested domain, but a delegation
+should be followed. The requested domain is an apex of some zone.
+
+% MEM_ANY_SUCCESS ANY query for '%1' successful
+Debug information. The domain was found and an ANY type query is being answered
+by providing everything found inside the domain.
+
+% MEM_SUCCESS query for '%1/%2' successful
+Debug information. The requested record was found.
+
+% MEM_CNAME CNAME at the domain '%1'
+Debug information. The requested domain is an alias to a different domain,
+returning the CNAME instead.
+
+% MEM_NXRRSET no such type '%1' at '%2'
+Debug information. The domain exists, but it doesn't hold any record of the
+requested type.
+
+% MEM_CREATE creating zone '%1' in '%2' class
+Debug information. A representation of a zone for the in-memory data source is
+being created.
+
+% MEM_DESTROY destroying zone '%1' in '%2' class
+Debug information. A zone from in-memory data source is being destroyed.
+
+% MEM_LOAD loading zone '%1' from file '%2'
+Debug information. The content of master file is being loaded into the memory.
+
+% MEM_SWAP swapping contents of two zone representations ('%1' and '%2')
+Debug information. The contents of two in-memory zones are being exchanged.
+This is usual practice to do some manipulation in exception-safe manner -- the
+new data are prepared in a different zone object and when it works, they are
+swapped. The old one contains the new data and the other one can be safely
+destroyed.
+
+% MEM_ADD_ZONE adding zone '%1/%2'
+Debug information. A zone is being added into the in-memory data source.
+
+% MEM_FIND_ZONE looking for zone '%1'
+Debug information. A zone object for this zone is being searched for in the
+in-memory data source.
+
+% STATIC_CREATE creating the static datasource
+Debug information. The static data source (the one holding stuff like
+version.bind) is being created.
+
+% STATIC_BAD_CLASS static data source can handle CH only
+For some reason, someone asked the static data source a query that is not in
+the CH class.
+
+% STATIC_FIND looking for '%1/%2'
+Debug information. This resource record set is being looked up in the static
+data source.
+
+% SQLITE_FINDREC looking for record '%1/%2'
+Debug information. The SQLite data source is looking up records of given name
+and type in the database.
+
+% SQLITE_ENCLOSURE looking for zone containing '%1'
+Debug information. The SQLite data source is trying to identify, which zone
+should hold this domain.
+
+% SQLITE_ENCLOSURE_BAD_CLASS class mismatch looking for a zone ('%1' and '%2')
+The SQLite data source can handle only one class at a time and it was asked
+to identify which zone is holding data of a different class.
+
+% SQLITE_ENCLOSURE_NOTFOUND no zone contains it
+Debug information. The last SQLITE_ENCLOSURE query was unsuccessful, there's
+no such zone in our data.
+
+% SQLITE_PREVIOUS looking for name previous to '%1'
+Debug information. We're trying to look up name preceding the supplied one.
+
+% SQLITE_PREVIOUS_NO_ZONE no zone containing '%1'
+The SQLite data source tried to identify name preceding this one. But this
+one is not contained in any zone in the data source.
+
+% SQLITE_FIND_NSEC3 looking for NSEC3 in zone '%1' for hash '%2'
+Debug information. We're trying to look up a NSEC3 record in the SQLite data
+source.
+
+% SQLITE_FIND_NSEC3_NO_ZONE no such zone '%1'
+The SQLite data source was asked to provide a NSEC3 record for given zone.
+But it doesn't contain that zone.
+
+% SQLITE_FIND looking for RRset '%1/%2'
+Debug information. The SQLite data source is looking up a resource record
+set.
+
+% SQLITE_FIND_BAD_CLASS class mismatch looking for an RRset ('%1' and '%2')
+The SQLite data source was looking up an RRset, but the data source contains
+different class than the query was for.
+
+% SQLITE_FINDEXACT looking for exact RRset '%1/%2'
+Debug information. The SQLite data source is looking up an exact resource
+record.
+
+% SQLITE_FINDEXACT_BAD_CLASS class mismatch looking for an RRset ('%1' and '%2')
+The SQLite data source was looking up an exact RRset, but the data source
+contains different class than the query was for.
+
+% SQLITE_FINDADDRS looking for A/AAAA addresses for '%1'
+Debug information. The data source is looking up the addresses for given
+domain name.
+
+% SQLITE_FINDADDRS_BAD_CLASS class mismatch looking for addresses ('%1' and '%2')
+The SQLite data source was looking up A/AAAA addresses, but the data source
+contains different class than the query was for.
+
+% SQLITE_FINDREF looking for referral at '%1'
+Debug information. The SQLite data source is identifying if this domain is
+a referral and where it goes.
+
+% SQLITE_FINDREF_BAD_CLASS class mismatch looking for referral ('%1' and '%2')
+The SQLite data source was trying to identify, if there's a referral. But
+it contains different class than the query was for.
+
+% SQLITE_CREATE sQLite data source created
+Debug information. An instance of SQLite data source is being created.
+
+% SQLITE_DESTROY sQLite data source destroyed
+Debug information. An instance of SQLite data source is being destroyed.
+
+% SQLITE_SETUP setting up SQLite database
+The database for SQLite data source was found empty. It is assumed this is the
+first run and it is being initialized with current schema.  It'll still contain
+no data, but it will be ready for use.
+
+% SQLITE_OPEN opening SQLite database '%1'
+Debug information. The SQLite data source is loading an SQLite database in
+the provided file.
+
+% SQLITE_CLOSE closing SQLite database
+Debug information. The SQLite data source is closing the database file.

src/lib/datasrc/sqlite3_datasrc.cc

@@ -18,6 +18,7 @@
 #include <sqlite3.h>
 
 #include <datasrc/sqlite3_datasrc.h>
+#include <datasrc/logger.h>
 
 #include <dns/rrttl.h>
 #include <dns/rdata.h>
@@ -227,6 +228,8 @@ Sqlite3DataSrc::findRecords(const Name& name, const RRType& rdtype,
                             RRsetList& target, const Name* zonename,
                             const Mode mode, uint32_t& flags) const
 {
+    LOG_DEBUG(logger, DBG_TRACE_DETAILED, DATASRC_SQLITE_FINDREC).arg(name).
+        arg(rdtype);
     flags = 0;
     int zone_id = (zonename == NULL) ? findClosest(name, NULL) :
         findClosest(*zonename, NULL);
@@ -345,12 +348,17 @@ Sqlite3DataSrc::findClosest(const Name& name, unsigned int* position) const {
 
 void
 Sqlite3DataSrc::findClosestEnclosure(DataSrcMatch& match) const {
+    LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_SQLITE_ENCLOSURE).
+        arg(match.getName());
     if (match.getClass() != getClass() && match.getClass() != RRClass::ANY()) {
+        LOG_ERROR(logger, DATASRC_SQLITE_ENCLOSURE_BAD_CLASS).arg(getClass()).
+            arg(match.getClass());
         return;
     }
 
     unsigned int position;
     if (findClosest(match.getName(), &position) == -1) {
+        LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_SQLITE_ENCLOSURE_NOTFOUND);
         return;
     }
 
@@ -362,9 +370,11 @@ Sqlite3DataSrc::findPreviousName(const Name& qname,
                                  Name& target,
                                  const Name* zonename) const
 {
+    LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_SQLITE_PREVIOUS).arg(qname);
     const int zone_id = (zonename == NULL) ?
         findClosest(qname, NULL) : findClosest(*zonename, NULL);
     if (zone_id < 0) {
+        LOG_ERROR(logger, DATASRC_SQLITE_PREVIOUS_NO_ZONE).arg(qname.toText());
         return (ERROR);
     }
     
@@ -402,8 +412,11 @@ Sqlite3DataSrc::findCoveringNSEC3(const Name& zonename,
                                   string& hashstr,
                                   RRsetList& target) const
 {
+    LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_SQLITE_FIND_NSEC3).
+        arg(zonename).arg(hashstr);
     const int zone_id = findClosest(zonename, NULL);
     if (zone_id < 0) {
+        LOG_ERROR(logger, DATASRC_SQLITE_FIND_NSEC3_NO_ZONE).arg(zonename);
         return (ERROR);
     }
 
@@ -484,7 +497,11 @@ Sqlite3DataSrc::findRRset(const Name& qname,
                           uint32_t& flags,
                           const Name* zonename) const
 {
+    LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_SQLITE_FIND).arg(qname).
+        arg(qtype);
     if (qclass != getClass() && qclass != RRClass::ANY()) {
+        LOG_ERROR(logger, DATASRC_SQLITE_FIND_BAD_CLASS).arg(getClass()).
+            arg(qclass);
         return (ERROR);
     }
     findRecords(qname, qtype, target, zonename, NORMAL, flags);
@@ -499,7 +516,11 @@ Sqlite3DataSrc::findExactRRset(const Name& qname,
                                uint32_t& flags,
                                const Name* zonename) const
 {
+    LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_SQLITE_FINDEXACT).arg(qname).
+        arg(qtype);
     if (qclass != getClass() && qclass != RRClass::ANY()) {
+        LOG_ERROR(logger, DATASRC_SQLITE_FINDEXACT_BAD_CLASS).arg(getClass()).
+            arg(qclass);
         return (ERROR);
     }
     findRecords(qname, qtype, target, zonename, NORMAL, flags);
@@ -523,7 +544,10 @@ Sqlite3DataSrc::findAddrs(const Name& qname,
                           uint32_t& flags,
                           const Name* zonename) const
 {
+    LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_SQLITE_FINDADDRS).arg(qname);
     if (qclass != getClass() && qclass != RRClass::ANY()) {
+        LOG_ERROR(logger, DATASRC_SQLITE_FINDADDRS_BAD_CLASS).arg(getClass()).
+            arg(qclass);
         return (ERROR);
     }
     findRecords(qname, RRType::ANY(), target, zonename, ADDRESS, flags);
@@ -537,8 +561,11 @@ Sqlite3DataSrc::findReferral(const Name& qname,
                              uint32_t& flags,
                              const Name* zonename) const
 {
+    LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_SQLITE_FINDREF).arg(qname);
     if (qclass != getClass() && qclass != RRClass::ANY()) {
-            return (ERROR);
+        LOG_ERROR(logger, DATASRC_SQLITE_FINDREF_BAD_CLASS).arg(getClass()).
+            arg(qclass);
+        return (ERROR);
     }
     findRecords(qname, RRType::ANY(), target, zonename, DELEGATION, flags);
     return (SUCCESS);
@@ -546,9 +573,12 @@ Sqlite3DataSrc::findReferral(const Name& qname,
 
 Sqlite3DataSrc::Sqlite3DataSrc() :
     dbparameters(new Sqlite3Parameters)
-{}
+{
+    LOG_DEBUG(logger, DBG_TRACE_BASIC, DATASRC_SQLITE_CREATE);
+}
 
 Sqlite3DataSrc::~Sqlite3DataSrc() {
+    LOG_DEBUG(logger, DBG_TRACE_BASIC, DATASRC_SQLITE_DESTROY);
     if (dbparameters->db_ != NULL) {
         close();
     }
@@ -635,6 +665,7 @@ checkAndSetupSchema(Sqlite3Initializer* initializer) {
         initializer->params_.version_ = sqlite3_column_int(prepared, 0);
         sqlite3_finalize(prepared);
     } else {
+        logger.info(DATASRC_SQLITE_SETUP);
         if (prepared != NULL) {
             sqlite3_finalize(prepared);
         }
@@ -664,6 +695,7 @@ checkAndSetupSchema(Sqlite3Initializer* initializer) {
 //
 void
 Sqlite3DataSrc::open(const string& name) {
+    LOG_DEBUG(logger, DBG_TRACE_BASIC, DATASRC_SQLITE_OPEN).arg(name);
     if (dbparameters->db_ != NULL) {
         isc_throw(DataSourceError, "Duplicate SQLite open with " << name);
     }
@@ -683,6 +715,7 @@ Sqlite3DataSrc::open(const string& name) {
 //
 DataSrc::Result
 Sqlite3DataSrc::close(void) {
+    LOG_DEBUG(logger, DBG_TRACE_BASIC, DATASRC_SQLITE_CLOSE);
     if (dbparameters->db_ == NULL) {
         isc_throw(DataSourceError,
                   "SQLite data source is being closed before open");

src/lib/datasrc/static_datasrc.cc

@@ -26,6 +26,7 @@
 
 #include <datasrc/data_source.h>
 #include <datasrc/static_datasrc.h>
+#include <datasrc/logger.h>
 
 using namespace std;
 using namespace isc::dns;
@@ -112,6 +113,7 @@ StaticDataSrcImpl::StaticDataSrcImpl() :
 }
 
 StaticDataSrc::StaticDataSrc() {
+    LOG_DEBUG(logger, DBG_TRACE_BASIC, DATASRC_STATIC_CREATE);
     setClass(RRClass::CH());
     impl_ = new StaticDataSrcImpl;
 }
@@ -155,8 +157,11 @@ StaticDataSrc::findRRset(const Name& qname,
                          RRsetList& target, uint32_t& flags,
                          const Name* const zonename) const
 {
+    LOG_DEBUG(logger, DBG_TRACE_DATA, DATASRC_STATIC_FIND).arg(qname).
+        arg(qtype);
     flags = 0;
     if (qclass != getClass() && qclass != RRClass::ANY()) {
+        LOG_ERROR(logger, DATASRC_STATIC_BAD_CLASS);
         return (ERROR);
     }
 

src/lib/datasrc/tests/Makefile.am

@@ -27,15 +27,17 @@ run_unittests_SOURCES += test_datasrc.h test_datasrc.cc
 run_unittests_SOURCES += rbtree_unittest.cc
 run_unittests_SOURCES += zonetable_unittest.cc
 run_unittests_SOURCES += memory_datasrc_unittest.cc
+run_unittests_SOURCES += logger_unittest.cc
 run_unittests_CPPFLAGS = $(AM_CPPFLAGS) $(GTEST_INCLUDES)
 run_unittests_LDFLAGS = $(AM_LDFLAGS) $(GTEST_LDFLAGS)
 run_unittests_LDADD = $(GTEST_LDADD)
 run_unittests_LDADD += $(SQLITE_LIBS)
-run_unittests_LDADD += $(top_builddir)/src/lib/testutils/libtestutils.la
 run_unittests_LDADD += $(top_builddir)/src/lib/datasrc/libdatasrc.la
 run_unittests_LDADD += $(top_builddir)/src/lib/dns/libdns++.la
-run_unittests_LDADD += $(top_builddir)/src/lib/cc/libcc.la
+run_unittests_LDADD += $(top_builddir)/src/lib/log/liblog.la
 run_unittests_LDADD += $(top_builddir)/src/lib/exceptions/libexceptions.la
+run_unittests_LDADD += $(top_builddir)/src/lib/cc/libcc.la
+run_unittests_LDADD += $(top_builddir)/src/lib/testutils/libtestutils.la
 endif
 
 noinst_PROGRAMS = $(TESTS)

src/lib/datasrc/tests/logger_unittest.cc

@@ -0,0 +1,31 @@
+// 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.
+
+#include <gtest/gtest.h>
+
+#include <datasrc/logger.h>
+
+using namespace isc::datasrc;
+
+namespace {
+
+TEST(CacheLogger, name) {
+    // This does not check the name only, but the fact the logger is created
+    // The dot is because of empty root logger
+    std::string name(logger.getName());
+    EXPECT_EQ(name.size() - 8, name.rfind(".datasrc")) <<
+        "Wrong logger name: " << name;
+}
+
+}

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

@@ -68,6 +68,9 @@ class TSIGKeyTest(unittest.TestCase):
 
 class TSIGKeyRingTest(unittest.TestCase):
     key_name = Name('example.com')
+    md5_name = Name('hmac-md5.sig-alg.reg.int')
+    sha1_name = Name('hmac-sha1')
+    sha256_name = Name('hmac-sha256')
     secret = b'someRandomData'
 
     def setUp(self):
@@ -152,18 +155,26 @@ class TSIGKeyRingTest(unittest.TestCase):
 
     def test_find(self):
         self.assertEqual((TSIGKeyRing.NOTFOUND, None),
-                         self.keyring.find(self.key_name))
+                         self.keyring.find(self.key_name, self.md5_name))
 
         self.assertEqual(TSIGKeyRing.SUCCESS,
                          self.keyring.add(TSIGKey(self.key_name,
-                                                  TSIGKey.HMACSHA256_NAME,
+                                                  self.sha256_name,
                                                   self.secret)))
-        (code, key) = self.keyring.find(self.key_name)
+        (code, key) = self.keyring.find(self.key_name, self.sha256_name)
         self.assertEqual(TSIGKeyRing.SUCCESS, code)
         self.assertEqual(self.key_name, key.get_key_name())
         self.assertEqual(TSIGKey.HMACSHA256_NAME, key.get_algorithm_name())
         self.assertEqual(self.secret, key.get_secret())
 
+        (code, key) = self.keyring.find(Name('different-key.example'),
+                                        self.sha256_name)
+        self.assertEqual(TSIGKeyRing.NOTFOUND, code)
+        self.assertEqual(None, key)
+        (code, key) = self.keyring.find(self.key_name, self.md5_name)
+        self.assertEqual(TSIGKeyRing.NOTFOUND, code)
+        self.assertEqual(None, key)
+
         self.assertRaises(TypeError, self.keyring.find, 1)
         self.assertRaises(TypeError, self.keyring.find, 'should be a name')
         self.assertRaises(TypeError, self.keyring.find, self.key_name, 0)
@@ -171,24 +182,28 @@ class TSIGKeyRingTest(unittest.TestCase):
     def test_find_from_some(self):
         self.assertEqual(TSIGKeyRing.SUCCESS,
                          self.keyring.add(TSIGKey(self.key_name,
-                                                  TSIGKey.HMACSHA256_NAME,
+                                                  self.sha256_name,
                                                   self.secret)))
         self.assertEqual(TSIGKeyRing.SUCCESS,
                          self.keyring.add(TSIGKey(Name('another.example'),
-                                                  TSIGKey.HMACMD5_NAME,
+                                                  self.md5_name,
                                                   self.secret)))
         self.assertEqual(TSIGKeyRing.SUCCESS,
                          self.keyring.add(TSIGKey(Name('more.example'),
-                                                  TSIGKey.HMACSHA1_NAME,
+                                                  self.sha1_name,
                                                   self.secret)))
 
-        (code, key) = self.keyring.find(Name('another.example'))
+        (code, key) = self.keyring.find(Name('another.example'), self.md5_name)
         self.assertEqual(TSIGKeyRing.SUCCESS, code)
         self.assertEqual(Name('another.example'), key.get_key_name())
         self.assertEqual(TSIGKey.HMACMD5_NAME, key.get_algorithm_name())
 
         self.assertEqual((TSIGKeyRing.NOTFOUND, None),
-                         self.keyring.find(Name('noexist.example')))
+                         self.keyring.find(Name('noexist.example'),
+                                           self.sha1_name))
+        self.assertEqual((TSIGKeyRing.NOTFOUND, None),
+                         self.keyring.find(Name('another.example'),
+                                           self.sha1_name))
 
 if __name__ == '__main__':
     unittest.main()

src/lib/dns/python/tsigkey_python.cc

@@ -416,10 +416,12 @@ TSIGKeyRing_remove(const s_TSIGKeyRing* self, PyObject* args) {
 PyObject*
 TSIGKeyRing_find(const s_TSIGKeyRing* self, PyObject* args) {
     s_Name* key_name;
+    s_Name* algorithm_name;
 
-    if (PyArg_ParseTuple(args, "O!", &name_type, &key_name)) {
+    if (PyArg_ParseTuple(args, "O!O!", &name_type, &key_name,
+                         &name_type, &algorithm_name)) {
         const TSIGKeyRing::FindResult result =
-            self->keyring->find(*key_name->name);
+            self->keyring->find(*key_name->name, *algorithm_name->name);
         if (result.key != NULL) {
             s_TSIGKey* key = PyObject_New(s_TSIGKey, &tsigkey_type);
             if (key == NULL) {

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

@@ -40,6 +40,10 @@ BUILT_SOURCES += rdata_tsig_toWire1.wire rdata_tsig_toWire2.wire
 BUILT_SOURCES += rdata_tsig_toWire3.wire rdata_tsig_toWire4.wire
 BUILT_SOURCES += rdata_tsig_toWire5.wire
 BUILT_SOURCES += tsigrecord_toWire1.wire tsigrecord_toWire2.wire
+BUILT_SOURCES += tsig_verify1.wire tsig_verify2.wire tsig_verify3.wire
+BUILT_SOURCES += tsig_verify4.wire tsig_verify5.wire tsig_verify6.wire
+BUILT_SOURCES += tsig_verify7.wire tsig_verify8.wire tsig_verify9.wire
+BUILT_SOURCES += tsig_verify10.wire
 
 # NOTE: keep this in sync with real file listing
 # so is included in tarball
@@ -108,6 +112,10 @@ EXTRA_DIST += rdata_tsig_toWire1.spec rdata_tsig_toWire2.spec
 EXTRA_DIST += rdata_tsig_toWire3.spec rdata_tsig_toWire4.spec
 EXTRA_DIST += rdata_tsig_toWire5.spec
 EXTRA_DIST += tsigrecord_toWire1.spec tsigrecord_toWire2.spec
+EXTRA_DIST += tsig_verify1.spec tsig_verify2.spec tsig_verify3.spec
+EXTRA_DIST += tsig_verify4.spec tsig_verify5.spec tsig_verify6.spec
+EXTRA_DIST += tsig_verify7.spec tsig_verify8.spec tsig_verify9.spec
+EXTRA_DIST += tsig_verify10.spec
 
 .spec.wire:
 	./gen-wiredata.py -o $@ $<

src/lib/dns/tests/testdata/gen-wiredata.py.in

@@ -283,9 +283,8 @@ class NS(RR):
         f.write('# NS name=%s\n' % (self.nsname))
         f.write('%s\n' % nsname_wire)
 
-class SOA:
-    # this currently doesn't support name compression within the RDATA.
-    rdlen = -1                  # auto-calculate
+class SOA(RR):
+    rdlen = None                  # auto-calculate
     mname = 'ns.example.com'
     rname = 'root.example.com'
     serial = 2010012601
@@ -296,11 +295,9 @@ class SOA:
     def dump(self, f):
         mname_wire = encode_name(self.mname)
         rname_wire = encode_name(self.rname)
-        rdlen = self.rdlen
-        if rdlen < 0:
-            rdlen = int(20 + len(mname_wire) / 2 + len(str(rname_wire)) / 2)
-        f.write('\n# SOA RDATA (RDLEN=%d)\n' % rdlen)
-        f.write('%04x\n' % rdlen);
+        if self.rdlen is None:
+            self.rdlen = int(20 + len(mname_wire) / 2 + len(str(rname_wire)) / 2)
+        self.dump_header(f, self.rdlen)
         f.write('# NNAME=%s RNAME=%s\n' % (self.mname, self.rname))
         f.write('%s %s\n' % (mname_wire, rname_wire))
         f.write('# SERIAL(%d) REFRESH(%d) RETRY(%d) EXPIRE(%d) MINIMUM(%d)\n' %

src/lib/dns/tests/testdata/tsig_verify1.spec

@@ -0,0 +1,19 @@
+#
+# An example of signed AXFR request
+#
+
+[custom]
+sections: header:question:tsig
+[header]
+id: 0x3410
+arcount: 1
+[question]
+rrtype: AXFR
+[tsig]
+as_rr: True
+rr_name: www.example.com
+algorithm: hmac-md5
+time_signed: 0x4da8e951
+mac_size: 16
+mac: 0x35b2fd08268781634400c7c8a5533b13
+original_id: 0x3410

src/lib/dns/tests/testdata/tsig_verify10.spec

@@ -0,0 +1,22 @@
+#
+# A simple DNS query message with TSIG signed whose MAC is too short
+# (only 1 byte)
+#
+
+[custom]
+sections: header:question:tsig
+[header]
+id: 0x2d65
+rd: 1
+arcount: 1
+[question]
+name: www.example.com
+[tsig]
+as_rr: True
+# TSIG QNAME won't be compressed
+rr_name: www.example.com
+algorithm: hmac-md5
+time_signed: 0x4da8877a
+mac_size: 1
+mac: 0x22
+original_id: 0x2d65

src/lib/dns/tests/testdata/tsig_verify2.spec

@@ -0,0 +1,32 @@
+#
+# An example of signed AXFR response
+#
+
+[custom]
+sections: header:question:soa:tsig
+[header]
+id: 0x3410
+aa: 1
+qr: 1
+ancount: 1
+arcount: 1
+[question]
+rrtype: AXFR
+[soa]
+# note that names are compressed in this RR
+as_rr: True
+rr_name: ptr=12
+mname: ns.ptr=12
+rname: root.ptr=12
+serial: 2011041503
+refresh: 7200
+retry: 3600
+expire: 2592000
+[tsig]
+as_rr: True
+rr_name: www.example.com
+algorithm: hmac-md5
+time_signed: 0x4da8e951
+mac_size: 16
+mac: 0xbdd612cd2c7f9e0648bd6dc23713e83c
+original_id: 0x3410

src/lib/dns/tests/testdata/tsig_verify3.spec

@@ -0,0 +1,26 @@
+#
+# An example of signed AXFR response (continued)
+#
+
+[custom]
+sections: header:ns:tsig
+[header]
+id: 0x3410
+aa: 1
+qr: 1
+qdcount: 0
+ancount: 1
+arcount: 1
+[ns]
+# note that names are compressed in this RR
+as_rr: True
+rr_name: example.com.
+nsname: ns.ptr=12
+[tsig]
+as_rr: True
+rr_name: www.example.com
+algorithm: hmac-md5
+time_signed: 0x4da8e951
+mac_size: 16
+mac: 0x102458f7f62ddd7d638d746034130968
+original_id: 0x3410

src/lib/dns/tests/testdata/tsig_verify4.spec

@@ -0,0 +1,27 @@
+#
+# An example of signed DNS response with bogus MAC
+#
+
+[custom]
+sections: header:question:a:tsig
+[header]
+id: 0x2d65
+aa: 1
+qr: 1
+rd: 1
+ancount: 1
+arcount: 1
+[question]
+name: www.example.com
+[a]
+as_rr: True
+rr_name: ptr=12
+[tsig]
+as_rr: True
+rr_name: www.example.com
+algorithm: hmac-md5
+time_signed: 0x4da8877a
+mac_size: 16
+# bogus MAC
+mac: 0xdeadbeefdeadbeefdeadbeefdeadbeef
+original_id: 0x2d65

src/lib/dns/tests/testdata/tsig_verify5.spec

@@ -0,0 +1,26 @@
+#
+# An example of signed DNS response
+#
+
+[custom]
+sections: header:question:a:tsig
+[header]
+id: 0x2d65
+aa: 1
+qr: 1
+rd: 1
+ancount: 1
+arcount: 1
+[question]
+name: www.example.com
+[a]
+as_rr: True
+rr_name: ptr=12
+[tsig]
+as_rr: True
+rr_name: www.example.com
+algorithm: hmac-md5
+time_signed: 0x4da8877a
+mac_size: 16
+mac: 0x8fcda66a7cd1a3b9948eb1869d384a9f
+original_id: 0x2d65

src/lib/dns/tests/testdata/tsig_verify6.spec

@@ -0,0 +1,21 @@
+#
+# Forwarded DNS query message with TSIG signed (header ID != orig ID)
+#
+
+[custom]
+sections: header:question:tsig
+[header]
+id: 0x1035
+rd: 1
+arcount: 1
+[question]
+name: www.example.com
+[tsig]
+as_rr: True
+# TSIG QNAME won't be compressed
+rr_name: www.example.com
+algorithm: hmac-md5
+time_signed: 0x4da8877a
+mac_size: 16
+mac: 0x227026ad297beee721ce6c6fff1e9ef3
+original_id: 0x2d65

src/lib/dns/tests/testdata/tsig_verify7.spec

@@ -0,0 +1,21 @@
+#
+# DNS query message with TSIG that has empty MAC (invalidly)
+#
+
+[custom]
+sections: header:question:tsig
+[header]
+id: 0x2d65
+rd: 1
+arcount: 1
+[question]
+name: www.example.com
+[tsig]
+as_rr: True
+# TSIG QNAME won't be compressed
+rr_name: www.example.com
+algorithm: hmac-md5
+time_signed: 0x4da8877a
+mac_size: 0
+mac: ''
+original_id: 0x2d65

src/lib/dns/tests/testdata/tsig_verify8.spec

@@ -0,0 +1,23 @@
+#
+# DNS query message with TSIG that has empty MAC + BADKEY error
+#
+
+[custom]
+sections: header:question:tsig
+[header]
+id: 0x2d65
+rd: 1
+arcount: 1
+[question]
+name: www.example.com
+[tsig]
+as_rr: True
+# TSIG QNAME won't be compressed
+rr_name: www.example.com
+algorithm: hmac-md5
+time_signed: 0x4da8877a
+mac_size: 0
+mac: ''
+# 17: BADKEY
+error: 17
+original_id: 0x2d65

src/lib/dns/tests/testdata/tsig_verify9.spec

@@ -0,0 +1,21 @@
+#
+# A simple DNS query message with TSIG signed, but TSIG key and algorithm
+# names have upper case characters (unusual)
+#
+
+[custom]
+sections: header:question:tsig
+[header]
+id: 0x2d65
+rd: 1
+arcount: 1
+[question]
+name: www.example.com
+[tsig]
+as_rr: True
+rr_name: WWW.EXAMPLE.COM
+algorithm: HMAC-MD5.SIG-ALG.REG.INT
+time_signed: 0x4da8877a
+mac_size: 16
+mac: 0x227026ad297beee721ce6c6fff1e9ef3
+original_id: 0x2d65

src/lib/dns/tests/tsig_unittest.cc

@@ -70,8 +70,13 @@ class TSIGTest : public ::testing::Test {
 protected:
     TSIGTest() :
         tsig_ctx(NULL), qid(0x2d65), test_name("www.example.com"),
-        test_class(RRClass::IN()), test_ttl(86400), message(Message::RENDER),
-        buffer(0), renderer(buffer)
+        badkey_name("badkey.example.com"), test_class(RRClass::IN()),
+        test_ttl(86400), message(Message::RENDER), buffer(0), renderer(buffer),
+        dummy_data(1024, 0xdd),  // should be sufficiently large for all tests
+        dummy_record(badkey_name, any::TSIG(TSIGKey::HMACMD5_NAME(),
+                                            0x4da8877a,
+                                            TSIGContext::DEFAULT_FUDGE,
+                                            0, NULL, qid, 0, 0, NULL))
     {
         // Make sure we use the system time by default so that we won't be
         // confused due to other tests that tweak the time.
@@ -103,6 +108,8 @@ protected:
                                             bool add_question = true,
                                             Rcode rcode = Rcode::NOERROR());
 
+    void createMessageFromFile(const char* datafile);
+
     // bit-wise constant flags to configure DNS header flags for test
     // messages.
     static const unsigned int QR_FLAG = 0x1;
@@ -111,14 +118,19 @@ protected:
 
     boost::scoped_ptr<TSIGContext> tsig_ctx;
     boost::scoped_ptr<TSIGContext> tsig_verify_ctx;
+    TSIGKeyRing keyring;
     const uint16_t qid;
     const Name test_name;
+    const Name badkey_name;
     const RRClass test_class;
     const RRTTL test_ttl;
     Message message;
     OutputBuffer buffer;
     MessageRenderer renderer;
     vector<uint8_t> secret;
+    vector<uint8_t> dummy_data;
+    const TSIGRecord dummy_record;
+    vector<uint8_t> received_data;
 };
 
 ConstTSIGRecordPtr
@@ -157,15 +169,27 @@ TSIGTest::createMessageAndSign(uint16_t id, const Name& qname,
     renderer.clear();
     message.toWire(renderer);
 
+    TSIGContext::State expected_new_state =
+        (ctx->getState() == TSIGContext::INIT) ?
+        TSIGContext::SENT_REQUEST : TSIGContext::SENT_RESPONSE;
     ConstTSIGRecordPtr tsig = ctx->sign(id, renderer.getData(),
                                         renderer.getLength());
-    EXPECT_EQ(TSIGContext::SIGNED, ctx->getState());
+    EXPECT_EQ(expected_new_state, ctx->getState());
 
     return (tsig);
 }
 
 void
-commonTSIGChecks(ConstTSIGRecordPtr tsig, uint16_t expected_qid,
+TSIGTest::createMessageFromFile(const char* datafile) {
+    message.clear(Message::PARSE);
+    received_data.clear();
+    UnitTestUtil::readWireData(datafile, received_data);
+    InputBuffer buffer(&received_data[0], received_data.size());
+    message.fromWire(buffer);
+}
+
+void
+commonSignChecks(ConstTSIGRecordPtr tsig, uint16_t expected_qid,
                  uint64_t expected_timesigned,
                  const uint8_t* expected_mac, size_t expected_maclen,
                  uint16_t expected_error = 0,
@@ -191,6 +215,17 @@ commonTSIGChecks(ConstTSIGRecordPtr tsig, uint16_t expected_qid,
                         expected_otherdata, expected_otherlen);
 }
 
+void
+commonVerifyChecks(TSIGContext& ctx, const TSIGRecord* record,
+                   const void* data, size_t data_len, TSIGError expected_error,
+                   TSIGContext::State expected_new_state =
+                   TSIGContext::VERIFIED_RESPONSE)
+{
+    EXPECT_EQ(expected_error, ctx.verify(record, data, data_len));
+    EXPECT_EQ(expected_error, ctx.getError());
+    EXPECT_EQ(expected_new_state, ctx.getState());
+}
+
 TEST_F(TSIGTest, initialState) {
     // Until signing or verifying, the state should be INIT
     EXPECT_EQ(TSIGContext::INIT, tsig_ctx->getState());
@@ -199,6 +234,38 @@ TEST_F(TSIGTest, initialState) {
     EXPECT_EQ(TSIGError(Rcode::NOERROR()), tsig_ctx->getError());
 }
 
+TEST_F(TSIGTest, constructFromKeyRing) {
+    // Construct a TSIG context with an empty key ring.  Key shouldn't be
+    // found, and the BAD_KEY error should be recorded.
+    TSIGContext ctx1(test_name, TSIGKey::HMACMD5_NAME(), keyring);
+    EXPECT_EQ(TSIGContext::INIT, ctx1.getState());
+    EXPECT_EQ(TSIGError::BAD_KEY(), ctx1.getError());
+
+    // Add a matching key (we don't use the secret so leave it empty), and
+    // construct it again.  This time it should be constructed with a valid
+    // key.
+    keyring.add(TSIGKey(test_name, TSIGKey::HMACMD5_NAME(), NULL, 0));
+    TSIGContext ctx2(test_name, TSIGKey::HMACMD5_NAME(), keyring);
+    EXPECT_EQ(TSIGContext::INIT, ctx2.getState());
+    EXPECT_EQ(TSIGError::NOERROR(), ctx2.getError());
+
+    // Similar to the first case except that the key ring isn't empty but
+    // it doesn't contain a matching key.
+    TSIGContext ctx3(test_name, TSIGKey::HMACSHA1_NAME(), keyring);
+    EXPECT_EQ(TSIGContext::INIT, ctx3.getState());
+    EXPECT_EQ(TSIGError::BAD_KEY(), ctx3.getError());
+
+    TSIGContext ctx4(Name("different-key.example"), TSIGKey::HMACMD5_NAME(),
+                     keyring);
+    EXPECT_EQ(TSIGContext::INIT, ctx4.getState());
+    EXPECT_EQ(TSIGError::BAD_KEY(), ctx4.getError());
+
+    // "Unknown" algorithm name will result in BADKEY, too.
+    TSIGContext ctx5(test_name, Name("unknown.algorithm"), keyring);
+    EXPECT_EQ(TSIGContext::INIT, ctx5.getState());
+    EXPECT_EQ(TSIGError::BAD_KEY(), ctx5.getError());
+}
+
 // Example output generated by
 // "dig -y www.example.com:SFuWd/q99SzF8Yzd1QbB9g== www.example.com
 // QID: 0x2d65
@@ -213,7 +280,7 @@ TEST_F(TSIGTest, sign) {
 
     {
         SCOPED_TRACE("Sign test for query");
-        commonTSIGChecks(createMessageAndSign(qid, test_name, tsig_ctx.get()),
+        commonSignChecks(createMessageAndSign(qid, test_name, tsig_ctx.get()),
                          qid, 0x4da8877a, common_expected_mac,
                          sizeof(common_expected_mac));
     }
@@ -231,7 +298,7 @@ TEST_F(TSIGTest, signUsingUpperCasedKeyName) {
 
     {
         SCOPED_TRACE("Sign test for query using non canonical key name");
-        commonTSIGChecks(createMessageAndSign(qid, test_name, &cap_ctx), qid,
+        commonSignChecks(createMessageAndSign(qid, test_name, &cap_ctx), qid,
                          0x4da8877a, common_expected_mac,
                          sizeof(common_expected_mac));
     }
@@ -247,7 +314,7 @@ TEST_F(TSIGTest, signUsingUpperCasedAlgorithmName) {
 
     {
         SCOPED_TRACE("Sign test for query using non canonical algorithm name");
-        commonTSIGChecks(createMessageAndSign(qid, test_name, &cap_ctx), qid,
+        commonSignChecks(createMessageAndSign(qid, test_name, &cap_ctx), qid,
                          0x4da8877a, common_expected_mac,
                          sizeof(common_expected_mac));
     }
@@ -281,6 +348,19 @@ TEST_F(TSIGTest, signBadData) {
     EXPECT_THROW(tsig_ctx->sign(0, &dummy_data, 0), InvalidParameter);
 }
 
+TEST_F(TSIGTest, verifyBadData) {
+    // the data must at least hold the DNS message header and the specified
+    // TSIG.
+    EXPECT_THROW(tsig_ctx->verify(&dummy_record, &dummy_data[0],
+                                  12 + dummy_record.getLength() - 1),
+                 InvalidParameter);
+
+    // And the data must not be NULL.
+    EXPECT_THROW(tsig_ctx->verify(&dummy_record, NULL,
+                                  12 + dummy_record.getLength()),
+                 InvalidParameter);
+}
+
 #ifdef ENABLE_CUSTOM_OPERATOR_NEW
 // We enable this test only when we enable custom new/delete at build time
 // We could enable/disable the test runtime using the gtest filter, but
@@ -293,11 +373,10 @@ TEST_F(TSIGTest, signExceptionSafety) {
     // complicated and involves more memory allocation, so the test result
     // won't be reliable.
 
-    tsig_verify_ctx->verifyTentative(createMessageAndSign(qid, test_name,
-                                                          tsig_ctx.get()),
-                                     TSIGError::BAD_KEY());
-    // At this point the state should be changed to "CHECKED"
-    ASSERT_EQ(TSIGContext::CHECKED, tsig_verify_ctx->getState());
+    commonVerifyChecks(*tsig_verify_ctx, &dummy_record, &dummy_data[0],
+                       dummy_data.size(), TSIGError::BAD_KEY(),
+                       TSIGContext::RECEIVED_REQUEST);
+
     try {
         int dummydata;
         isc::util::unittests::force_throw_on_new = true;
@@ -308,8 +387,8 @@ TEST_F(TSIGTest, signExceptionSafety) {
     } catch (const std::bad_alloc&) {
         isc::util::unittests::force_throw_on_new = false;
 
-        // sign() threw, so the state should still be "CHECKED".
-        EXPECT_EQ(TSIGContext::CHECKED, tsig_verify_ctx->getState());
+        // sign() threw, so the state should still be RECEIVED_REQUEST
+        EXPECT_EQ(TSIGContext::RECEIVED_REQUEST, tsig_verify_ctx->getState());
     }
     isc::util::unittests::force_throw_on_new = false;
 }
@@ -339,70 +418,130 @@ TEST_F(TSIGTest, signUsingHMACSHA1) {
     };
     {
         SCOPED_TRACE("Sign test using HMAC-SHA1");
-        commonTSIGChecks(createMessageAndSign(sha1_qid, test_name, &sha1_ctx),
+        commonSignChecks(createMessageAndSign(sha1_qid, test_name, &sha1_ctx),
                          sha1_qid, 0x4dae7d5f, expected_mac,
                          sizeof(expected_mac), 0, 0, NULL,
                          TSIGKey::HMACSHA1_NAME());
     }
 }
 
-// An example response to the signed query used for the "sign" test.
+// The first part of this test checks verifying the signed query used for
+// the "sign" test.
+// The second part of this test generates a signed response to the signed
+// query as follows:
 // Answer: www.example.com. 86400 IN A 192.0.2.1
 // MAC: 8fcda66a7cd1a3b9948eb1869d384a9f
-TEST_F(TSIGTest, signResponse) {
+TEST_F(TSIGTest, verifyThenSignResponse) {
     isc::util::detail::gettimeFunction = testGetTime<0x4da8877a>;
 
-    ConstTSIGRecordPtr tsig = createMessageAndSign(qid, test_name,
-                                                   tsig_ctx.get());
-    tsig_verify_ctx->verifyTentative(tsig);
-    EXPECT_EQ(TSIGContext::CHECKED, tsig_verify_ctx->getState());
+    // This test data for the message test has the same wire format data
+    // as the message used in the "sign" test.
+    createMessageFromFile("message_toWire2.wire");
+    {
+        SCOPED_TRACE("Verify test for request");
+        commonVerifyChecks(*tsig_verify_ctx, message.getTSIGRecord(),
+                           &received_data[0], received_data.size(),
+                           TSIGError::NOERROR(), TSIGContext::RECEIVED_REQUEST);
+    }
 
     // Transform the original message to a response, then sign the response
     // with the context of "verified state".
-    tsig = createMessageAndSign(qid, test_name, tsig_verify_ctx.get(),
-                                QR_FLAG|AA_FLAG|RD_FLAG,
-                                RRType::A(), "192.0.2.1");
+    ConstTSIGRecordPtr tsig = createMessageAndSign(qid, test_name,
+                                                   tsig_verify_ctx.get(),
+                                                   QR_FLAG|AA_FLAG|RD_FLAG,
+                                                   RRType::A(), "192.0.2.1");
     const uint8_t expected_mac[] = {
         0x8f, 0xcd, 0xa6, 0x6a, 0x7c, 0xd1, 0xa3, 0xb9,
         0x94, 0x8e, 0xb1, 0x86, 0x9d, 0x38, 0x4a, 0x9f
     };
     {
         SCOPED_TRACE("Sign test for response");
-        commonTSIGChecks(tsig, qid, 0x4da8877a,
-                         expected_mac, sizeof(expected_mac));
+        commonSignChecks(tsig, qid, 0x4da8877a, expected_mac,
+                         sizeof(expected_mac));
+    }
+}
+
+TEST_F(TSIGTest, verifyUpperCaseNames) {
+    isc::util::detail::gettimeFunction = testGetTime<0x4da8877a>;
+
+    // This test data for the message test has the same wire format data
+    // as the message used in the "sign" test.
+    createMessageFromFile("tsig_verify9.wire");
+    {
+        SCOPED_TRACE("Verify test for request");
+        commonVerifyChecks(*tsig_verify_ctx, message.getTSIGRecord(),
+                           &received_data[0], received_data.size(),
+                           TSIGError::NOERROR(), TSIGContext::RECEIVED_REQUEST);
+    }
+}
+
+TEST_F(TSIGTest, verifyForwardedMessage) {
+    // Similar to the first part of the previous test, but this test emulates
+    // the "forward" case, where the ID of the Header and the original ID in
+    // TSIG is different.
+    isc::util::detail::gettimeFunction = testGetTime<0x4da8877a>;
+
+    createMessageFromFile("tsig_verify6.wire");
+    {
+        SCOPED_TRACE("Verify test for forwarded request");
+        commonVerifyChecks(*tsig_verify_ctx, message.getTSIGRecord(),
+                           &received_data[0], received_data.size(),
+                           TSIGError::NOERROR(), TSIGContext::RECEIVED_REQUEST);
     }
 }
 
 // Example of signing multiple messages in a single TCP stream,
 // taken from data using BIND 9's "one-answer" transfer-format.
+// Request:
+//   QID: 0x3410, flags (none)
+//   Question: example.com/IN/AXFR
+//   Time Signed: 0x4da8e951
+//   MAC: 35b2fd08268781634400c7c8a5533b13
 // First message:
 //   QID: 0x3410, flags QR, AA
 //   Question: example.com/IN/AXFR
 //   Answer: example.com. 86400 IN SOA ns.example.com. root.example.com. (
 //                          2011041503 7200 3600 2592000 1200)
-//   Time Signed: 0x4da8e951
+//   MAC: bdd612cd2c7f9e0648bd6dc23713e83c
 // Second message:
-//    Answer: example.com. 86400 IN NS ns.example.com.
-//    MAC: 102458f7f62ddd7d638d746034130968
+//   Answer: example.com. 86400 IN NS ns.example.com.
+//   MAC: 102458f7f62ddd7d638d746034130968
 TEST_F(TSIGTest, signContinuation) {
     isc::util::detail::gettimeFunction = testGetTime<0x4da8e951>;
 
     const uint16_t axfr_qid = 0x3410;
     const Name zone_name("example.com");
 
-    // Create and sign the AXFR request, then verify it.
-    tsig_verify_ctx->verifyTentative(createMessageAndSign(axfr_qid, zone_name,
-                                                          tsig_ctx.get(), 0,
-                                                          RRType::AXFR()));
-    EXPECT_EQ(TSIGContext::CHECKED, tsig_verify_ctx->getState());
+    // Create and sign the AXFR request
+    ConstTSIGRecordPtr tsig = createMessageAndSign(axfr_qid, zone_name,
+                                                   tsig_ctx.get(), 0,
+                                                   RRType::AXFR());
+    // Then verify it (the wire format test data should contain the same
+    // message data, and verification should succeed).
+    received_data.clear();
+    UnitTestUtil::readWireData("tsig_verify1.wire", received_data);
+    {
+        SCOPED_TRACE("Verify AXFR query");
+        commonVerifyChecks(*tsig_verify_ctx, tsig.get(), &received_data[0],
+                           received_data.size(), TSIGError::NOERROR(),
+                           TSIGContext::RECEIVED_REQUEST);
+    }
 
-    // Create and sign the first response message (we don't need the result
-    // for the purpose of this test)
-    createMessageAndSign(axfr_qid, zone_name, tsig_verify_ctx.get(),
-                         AA_FLAG|QR_FLAG, RRType::AXFR(),
-                         "ns.example.com. root.example.com. "
-                         "2011041503 7200 3600 2592000 1200",
-                         &RRType::SOA());
+    // Create and sign the first response message
+    tsig = createMessageAndSign(axfr_qid, zone_name, tsig_verify_ctx.get(),
+                                AA_FLAG|QR_FLAG, RRType::AXFR(),
+                                "ns.example.com. root.example.com. "
+                                "2011041503 7200 3600 2592000 1200",
+                                &RRType::SOA());
+
+    // Then verify it at the requester side.
+    received_data.clear();
+    UnitTestUtil::readWireData("tsig_verify2.wire", received_data);
+    {
+        SCOPED_TRACE("Verify first AXFR response");
+        commonVerifyChecks(*tsig_ctx, tsig.get(), &received_data[0],
+                           received_data.size(), TSIGError::NOERROR());
+    }
 
     // Create and sign the second response message
     const uint8_t expected_mac[] = {
@@ -411,13 +550,20 @@ TEST_F(TSIGTest, signContinuation) {
     };
     {
         SCOPED_TRACE("Sign test for continued response in TCP stream");
-        commonTSIGChecks(createMessageAndSign(axfr_qid, zone_name,
-                                              tsig_verify_ctx.get(),
-                                              AA_FLAG|QR_FLAG, RRType::AXFR(),
-                                              "ns.example.com.", &RRType::NS(),
-                                              false),
-                         axfr_qid, 0x4da8e951,
-                         expected_mac, sizeof(expected_mac));
+        tsig = createMessageAndSign(axfr_qid, zone_name, tsig_verify_ctx.get(),
+                                    AA_FLAG|QR_FLAG, RRType::AXFR(),
+                                    "ns.example.com.", &RRType::NS(), false);
+        commonSignChecks(tsig, axfr_qid, 0x4da8e951, expected_mac,
+                         sizeof(expected_mac));
+    }
+
+    // Then verify it at the requester side.
+    received_data.clear();
+    UnitTestUtil::readWireData("tsig_verify3.wire", received_data);
+    {
+        SCOPED_TRACE("Verify second AXFR response");
+        commonVerifyChecks(*tsig_ctx, tsig.get(), &received_data[0],
+                           received_data.size(), TSIGError::NOERROR());
     }
 }
 
@@ -443,10 +589,13 @@ TEST_F(TSIGTest, badtimeResponse) {
                                                    RRType::SOA());
 
     // "advance the clock" and try validating, which should fail due to BADTIME
-    // (verifyTentative actually doesn't check the time, though)
     isc::util::detail::gettimeFunction = testGetTime<0x4da8be86>;
-    tsig_verify_ctx->verifyTentative(tsig, TSIGError::BAD_TIME());
-    EXPECT_EQ(TSIGError::BAD_TIME(), tsig_verify_ctx->getError());
+    {
+        SCOPED_TRACE("Verify resulting in BADTIME due to expired SIG");
+        commonVerifyChecks(*tsig_verify_ctx, tsig.get(), &dummy_data[0],
+                           dummy_data.size(), TSIGError::BAD_TIME(),
+                           TSIGContext::RECEIVED_REQUEST);
+    }
 
     // make and sign a response in the context of TSIG error.
     tsig = createMessageAndSign(test_qid, test_name, tsig_verify_ctx.get(),
@@ -459,7 +608,7 @@ TEST_F(TSIGTest, badtimeResponse) {
     };
     {
         SCOPED_TRACE("Sign test for response with BADTIME");
-        commonTSIGChecks(tsig, message.getQid(), 0x4da8b9d6,
+        commonSignChecks(tsig, message.getQid(), 0x4da8b9d6,
                          expected_mac, sizeof(expected_mac),
                          18,     // error: BADTIME
                          sizeof(expected_otherdata),
@@ -467,21 +616,86 @@ TEST_F(TSIGTest, badtimeResponse) {
     }
 }
 
+TEST_F(TSIGTest, badtimeResponse2) {
+    isc::util::detail::gettimeFunction = testGetTime<0x4da8b9d6>;
+
+    ConstTSIGRecordPtr tsig = createMessageAndSign(qid, test_name,
+                                                   tsig_ctx.get(), 0,
+                                                   RRType::SOA());
+
+    // "rewind the clock" and try validating, which should fail due to BADTIME
+    isc::util::detail::gettimeFunction = testGetTime<0x4da8b9d6 - 600>;
+    {
+        SCOPED_TRACE("Verify resulting in BADTIME due to too future SIG");
+        commonVerifyChecks(*tsig_verify_ctx, tsig.get(), &dummy_data[0],
+                           dummy_data.size(), TSIGError::BAD_TIME(),
+                           TSIGContext::RECEIVED_REQUEST);
+    }
+}
+
+TEST_F(TSIGTest, badtimeBoundaries) {
+    isc::util::detail::gettimeFunction = testGetTime<0x4da8b9d6>;
+
+    // Test various boundary conditions.  We intentionally use the magic
+    // number of 300 instead of the constant variable for testing.
+    // In the okay cases, signature is not correct, but it's sufficient to
+    // check the error code isn't BADTIME for the purpose of this test.
+    ConstTSIGRecordPtr tsig = createMessageAndSign(qid, test_name,
+                                                   tsig_ctx.get(), 0,
+                                                   RRType::SOA());
+    isc::util::detail::gettimeFunction = testGetTime<0x4da8b9d6 + 301>;
+    EXPECT_EQ(TSIGError::BAD_TIME(),
+              tsig_verify_ctx->verify(tsig.get(), &dummy_data[0],
+                                      dummy_data.size()));
+    isc::util::detail::gettimeFunction = testGetTime<0x4da8b9d6 + 300>;
+    EXPECT_NE(TSIGError::BAD_TIME(),
+              tsig_verify_ctx->verify(tsig.get(), &dummy_data[0],
+                                      dummy_data.size()));
+    isc::util::detail::gettimeFunction = testGetTime<0x4da8b9d6 - 301>;
+    EXPECT_EQ(TSIGError::BAD_TIME(),
+              tsig_verify_ctx->verify(tsig.get(), &dummy_data[0],
+                                      dummy_data.size()));
+    isc::util::detail::gettimeFunction = testGetTime<0x4da8b9d6 - 300>;
+    EXPECT_NE(TSIGError::BAD_TIME(),
+              tsig_verify_ctx->verify(tsig.get(), &dummy_data[0],
+                                      dummy_data.size()));
+}
+
+TEST_F(TSIGTest, badtimeOverflow) {
+    isc::util::detail::gettimeFunction = testGetTime<200>;
+    ConstTSIGRecordPtr tsig = createMessageAndSign(qid, test_name,
+                                                   tsig_ctx.get(), 0,
+                                                   RRType::SOA());
+
+    // This should be in the okay range, but since "200 - fudge" overflows
+    // and we compare them as 64-bit unsigned integers, it results in a false
+    // positive (we intentionally accept that).
+    isc::util::detail::gettimeFunction = testGetTime<100>;
+    EXPECT_EQ(TSIGError::BAD_TIME(),
+              tsig_verify_ctx->verify(tsig.get(), &dummy_data[0],
+                                      dummy_data.size()));
+}
+
 TEST_F(TSIGTest, badsigResponse) {
     isc::util::detail::gettimeFunction = testGetTime<0x4da8877a>;
 
-    // Sign a simple message, and force the verification to fail with
-    // BADSIG.
-    tsig_verify_ctx->verifyTentative(createMessageAndSign(qid, test_name,
-                                                          tsig_ctx.get()),
-                                     TSIGError::BAD_SIG());
+    // Try to sign a simple message with bogus secret.  It should fail
+    // with BADSIG.
+    createMessageFromFile("message_toWire2.wire");
+    TSIGContext bad_ctx(TSIGKey(test_name, TSIGKey::HMACMD5_NAME(),
+                                &dummy_data[0], dummy_data.size()));
+    {
+        SCOPED_TRACE("Verify resulting in BADSIG");
+        commonVerifyChecks(bad_ctx, message.getTSIGRecord(),
+                           &received_data[0], received_data.size(),
+                           TSIGError::BAD_SIG(), TSIGContext::RECEIVED_REQUEST);
+    }
 
     // Sign the same message (which doesn't matter for this test) with the
     // context of "checked state".
     {
         SCOPED_TRACE("Sign test for response with BADSIG error");
-        commonTSIGChecks(createMessageAndSign(qid, test_name,
-                                              tsig_verify_ctx.get()),
+        commonSignChecks(createMessageAndSign(qid, test_name, &bad_ctx),
                          message.getQid(), 0x4da8877a, NULL, 0,
                          16);   // 16: BADSIG
     }
@@ -490,15 +704,203 @@ TEST_F(TSIGTest, badsigResponse) {
 TEST_F(TSIGTest, badkeyResponse) {
     // A similar test as badsigResponse but for BADKEY
     isc::util::detail::gettimeFunction = testGetTime<0x4da8877a>;
-    tsig_verify_ctx->verifyTentative(createMessageAndSign(qid, test_name,
-                                                          tsig_ctx.get()),
-                                     TSIGError::BAD_KEY());
+    tsig_ctx.reset(new TSIGContext(badkey_name, TSIGKey::HMACMD5_NAME(),
+                                   keyring));
+    {
+        SCOPED_TRACE("Verify resulting in BADKEY");
+        commonVerifyChecks(*tsig_ctx, &dummy_record, &dummy_data[0],
+                           dummy_data.size(), TSIGError::BAD_KEY(),
+                           TSIGContext::RECEIVED_REQUEST);
+    }
+
     {
         SCOPED_TRACE("Sign test for response with BADKEY error");
-        commonTSIGChecks(createMessageAndSign(qid, test_name,
-                                              tsig_verify_ctx.get()),
-                         message.getQid(), 0x4da8877a, NULL, 0,
-                         17);   // 17: BADKEYSIG
+        ConstTSIGRecordPtr sig = createMessageAndSign(qid, test_name,
+                                                      tsig_ctx.get());
+        EXPECT_EQ(badkey_name, sig->getName());
+        commonSignChecks(sig, qid, 0x4da8877a, NULL, 0, 17);   // 17: BADKEY
+    }
+}
+
+TEST_F(TSIGTest, badkeyForResponse) {
+    // "BADKEY" case for a response to a signed message
+    createMessageAndSign(qid, test_name, tsig_ctx.get());
+    {
+        SCOPED_TRACE("Verify a response resulting in BADKEY");
+        commonVerifyChecks(*tsig_ctx, &dummy_record, &dummy_data[0],
+                           dummy_data.size(), TSIGError::BAD_KEY(),
+                           TSIGContext::SENT_REQUEST);
+    }
+
+    // A similar case with a different algorithm
+    const TSIGRecord dummy_record2(test_name,
+                                  any::TSIG(TSIGKey::HMACSHA1_NAME(),
+                                            0x4da8877a,
+                                            TSIGContext::DEFAULT_FUDGE,
+                                            0, NULL, qid, 0, 0, NULL));
+    {
+        SCOPED_TRACE("Verify a response resulting in BADKEY due to bad alg");
+        commonVerifyChecks(*tsig_ctx, &dummy_record2, &dummy_data[0],
+                           dummy_data.size(), TSIGError::BAD_KEY(),
+                           TSIGContext::SENT_REQUEST);
+    }
+}
+
+TEST_F(TSIGTest, badsigThenValidate) {
+    // According to RFC2845 4.6, if TSIG verification fails the client
+    // should discard that message and wait for another signed response.
+    // This test emulates that situation.
+
+    isc::util::detail::gettimeFunction = testGetTime<0x4da8877a>;
+
+    createMessageAndSign(qid, test_name, tsig_ctx.get());
+
+    createMessageFromFile("tsig_verify4.wire");
+    {
+        SCOPED_TRACE("Verify a response that should fail due to BADSIG");
+        commonVerifyChecks(*tsig_ctx, message.getTSIGRecord(),
+                           &received_data[0], received_data.size(),
+                           TSIGError::BAD_SIG(), TSIGContext::SENT_REQUEST);
+    }
+
+    createMessageFromFile("tsig_verify5.wire");
+    {
+        SCOPED_TRACE("Verify a response after a BADSIG failure");
+        commonVerifyChecks(*tsig_ctx, message.getTSIGRecord(),
+                           &received_data[0], received_data.size(),
+                           TSIGError::NOERROR(),
+                           TSIGContext::VERIFIED_RESPONSE);
+    }
+}
+
+TEST_F(TSIGTest, nosigThenValidate) {
+    // Similar to the previous test, but the first response doesn't contain
+    // TSIG.
+    isc::util::detail::gettimeFunction = testGetTime<0x4da8877a>;
+
+    createMessageAndSign(qid, test_name, tsig_ctx.get());
+
+    {
+        SCOPED_TRACE("Verify a response without TSIG that should exist");
+        commonVerifyChecks(*tsig_ctx, NULL, &dummy_data[0],
+                           dummy_data.size(), TSIGError::FORMERR(),
+                           TSIGContext::SENT_REQUEST);
+    }
+
+    createMessageFromFile("tsig_verify5.wire");
+    {
+        SCOPED_TRACE("Verify a response after a FORMERR failure");
+        commonVerifyChecks(*tsig_ctx, message.getTSIGRecord(),
+                           &received_data[0], received_data.size(),
+                           TSIGError::NOERROR(),
+                           TSIGContext::VERIFIED_RESPONSE);
+    }
+}
+
+TEST_F(TSIGTest, badtimeThenValidate) {
+    // Similar to the previous test, but the first response results in BADTIME.
+    isc::util::detail::gettimeFunction = testGetTime<0x4da8877a>;
+
+    ConstTSIGRecordPtr tsig = createMessageAndSign(qid, test_name,
+                                                   tsig_ctx.get());
+
+    // "advance the clock" and try validating, which should fail due to BADTIME
+    isc::util::detail::gettimeFunction = testGetTime<0x4da8877a + 600>;
+    {
+        SCOPED_TRACE("Verify resulting in BADTIME due to expired SIG");
+        commonVerifyChecks(*tsig_ctx, tsig.get(), &dummy_data[0],
+                           dummy_data.size(), TSIGError::BAD_TIME(),
+                           TSIGContext::SENT_REQUEST);
+    }
+
+    // revert the clock again.
+    isc::util::detail::gettimeFunction = testGetTime<0x4da8877a>;
+    createMessageFromFile("tsig_verify5.wire");
+    {
+        SCOPED_TRACE("Verify a response after a BADTIME failure");
+        commonVerifyChecks(*tsig_ctx, message.getTSIGRecord(),
+                           &received_data[0], received_data.size(),
+                           TSIGError::NOERROR(),
+                           TSIGContext::VERIFIED_RESPONSE);
+    }
+}
+
+TEST_F(TSIGTest, emptyMAC) {
+    isc::util::detail::gettimeFunction = testGetTime<0x4da8877a>;
+
+    // We don't allow empty MAC unless the TSIG error is BADSIG or BADKEY.
+    createMessageFromFile("tsig_verify7.wire");
+    {
+        SCOPED_TRACE("Verify test for request");
+        commonVerifyChecks(*tsig_verify_ctx, message.getTSIGRecord(),
+                           &received_data[0], received_data.size(),
+                           TSIGError::BAD_SIG(), TSIGContext::RECEIVED_REQUEST);
+    }
+
+    // If the empty MAC comes with a BADKEY error, the error is passed
+    // transparently.
+    createMessageFromFile("tsig_verify8.wire");
+    {
+        SCOPED_TRACE("Verify test for request");
+        commonVerifyChecks(*tsig_verify_ctx, message.getTSIGRecord(),
+                           &received_data[0], received_data.size(),
+                           TSIGError::BAD_KEY(), TSIGContext::RECEIVED_REQUEST);
+    }
+}
+
+TEST_F(TSIGTest, verifyAfterSendResponse) {
+    // Once the context is used for sending a signed response, it shouldn't
+    // be used for further verification.
+
+    // The following are essentially the same as what verifyThenSignResponse
+    // does with simplification.
+    isc::util::detail::gettimeFunction = testGetTime<0x4da8877a>;
+    createMessageFromFile("message_toWire2.wire");
+    tsig_verify_ctx->verify(message.getTSIGRecord(), &received_data[0],
+                            received_data.size());
+    EXPECT_EQ(TSIGContext::RECEIVED_REQUEST, tsig_verify_ctx->getState());
+    createMessageAndSign(qid, test_name, tsig_verify_ctx.get(),
+                         QR_FLAG|AA_FLAG|RD_FLAG, RRType::A(), "192.0.2.1");
+    EXPECT_EQ(TSIGContext::SENT_RESPONSE, tsig_verify_ctx->getState());
+
+    // Now trying further verification.
+    createMessageFromFile("message_toWire2.wire");
+    EXPECT_THROW(tsig_verify_ctx->verify(message.getTSIGRecord(),
+                                         &received_data[0],
+                                         received_data.size()),
+                 TSIGContextError);
+}
+
+TEST_F(TSIGTest, signAfterVerified) {
+    // Likewise, once the context verifies a response, it shouldn't for
+    // signing any more.
+
+    // The following are borrowed from badsigThenValidate (without the
+    // intermediate failure)
+    isc::util::detail::gettimeFunction = testGetTime<0x4da8877a>;
+    createMessageAndSign(qid, test_name, tsig_ctx.get());
+    createMessageFromFile("tsig_verify5.wire");
+    tsig_ctx->verify(message.getTSIGRecord(), &received_data[0],
+                     received_data.size());
+    EXPECT_EQ(TSIGContext::VERIFIED_RESPONSE, tsig_ctx->getState());
+
+    // Now trying further signing.
+    EXPECT_THROW(createMessageAndSign(qid, test_name, tsig_ctx.get()),
+                 TSIGContextError);
+}
+
+TEST_F(TSIGTest, tooShortMAC) {
+    // Too short MAC should be rejected.
+    // Note: when we implement RFC4635-based checks, the error code will
+    // (probably) be FORMERR.
+
+    isc::util::detail::gettimeFunction = testGetTime<0x4da8877a>;
+    createMessageFromFile("tsig_verify10.wire");
+    {
+        SCOPED_TRACE("Verify test for request");
+        commonVerifyChecks(*tsig_verify_ctx, message.getTSIGRecord(),
+                           &received_data[0], received_data.size(),
+                           TSIGError::BAD_SIG(), TSIGContext::RECEIVED_REQUEST);
     }
 }
 

src/lib/dns/tests/tsigerror_unittest.cc

@@ -93,6 +93,20 @@ TEST(TSIGErrorTest, toText) {
     EXPECT_EQ("65535", TSIGError(65535).toText());
 }
 
+TEST(TSIGErrorTest, toRcode) {
+    // TSIGError derived from the standard Rcode
+    EXPECT_EQ(Rcode::NOERROR(), TSIGError(Rcode::NOERROR()).toRcode());
+
+    // Well known TSIG errors
+    EXPECT_EQ(Rcode::NOTAUTH(), TSIGError::BAD_SIG().toRcode());
+    EXPECT_EQ(Rcode::NOTAUTH(), TSIGError::BAD_KEY().toRcode());
+    EXPECT_EQ(Rcode::NOTAUTH(), TSIGError::BAD_TIME().toRcode());
+
+    // Unknown (or not yet supported) codes are treated as SERVFAIL.
+    EXPECT_EQ(Rcode::SERVFAIL(), TSIGError(19).toRcode());
+    EXPECT_EQ(Rcode::SERVFAIL(), TSIGError(65535).toRcode());
+}
+
 // test operator<<.  We simply confirm it appends the result of toText().
 TEST(TSIGErrorTest, LeftShiftOperator) {
     ostringstream oss;

src/lib/dns/tests/tsigkey_unittest.cc

@@ -33,7 +33,7 @@ class TSIGKeyTest : public ::testing::Test {
 protected:
     TSIGKeyTest() : secret("someRandomData"), key_name("example.com") {}
     string secret;
-    Name key_name;
+    const Name key_name;
 };
 
 TEST_F(TSIGKeyTest, algorithmNames) {
@@ -59,9 +59,13 @@ TEST_F(TSIGKeyTest, construct) {
     EXPECT_PRED_FORMAT4(UnitTestUtil::matchWireData, secret.c_str(),
                         secret.size(), key.getSecret(), key.getSecretLength());
 
+    // "unknown" algorithm is only accepted with empty secret.
     EXPECT_THROW(TSIGKey(key_name, Name("unknown-alg"),
                          secret.c_str(), secret.size()),
                  isc::InvalidParameter);
+    TSIGKey key2(key_name, Name("unknown-alg"), NULL, 0);
+    EXPECT_EQ(key_name, key2.getKeyName());
+    EXPECT_EQ(Name("unknown-alg"), key2.getAlgorithmName());
 
     // The algorithm name should be converted to the canonical form.
     EXPECT_EQ("hmac-sha1.",
@@ -69,6 +73,7 @@ TEST_F(TSIGKeyTest, construct) {
                       secret.c_str(),
                       secret.size()).getAlgorithmName().toText());
 
+    // Same for key name
     EXPECT_EQ("example.com.",
               TSIGKey(Name("EXAMPLE.CoM."), TSIGKey::HMACSHA256_NAME(),
                       secret.c_str(),
@@ -125,12 +130,18 @@ class TSIGKeyRingTest : public ::testing::Test {
 protected:
     TSIGKeyRingTest() :
         key_name("example.com"),
+        md5_name("hmac-md5.sig-alg.reg.int"),
+        sha1_name("hmac-sha1"),
+        sha256_name("hmac-sha256"),
         secretstring("anotherRandomData"),
         secret(secretstring.c_str()),
         secret_len(secretstring.size())
     {}
     TSIGKeyRing keyring;
-    Name key_name;
+    const Name key_name;
+    const Name md5_name;
+    const Name sha1_name;
+    const Name sha256_name;
 private:
     const string secretstring;
 protected:
@@ -150,8 +161,8 @@ TEST_F(TSIGKeyRingTest, add) {
     EXPECT_EQ(TSIGKeyRing::EXIST, keyring.add(
                   TSIGKey(key_name, TSIGKey::HMACSHA256_NAME(),
                           secret, secret_len)));
-    // keys are identified their names, the same name of key with a different
-    // algorithm would be considered a duplicate.
+    // keys are identified by their names, the same name of key with a
+    // different algorithm would be considered a duplicate.
     EXPECT_EQ(TSIGKeyRing::EXIST, keyring.add(
                   TSIGKey(Name("example.com"), TSIGKey::HMACSHA1_NAME(),
                           secret, secret_len)));
@@ -203,44 +214,60 @@ TEST_F(TSIGKeyRingTest, removeFromSome) {
 }
 
 TEST_F(TSIGKeyRingTest, find) {
-    EXPECT_EQ(TSIGKeyRing::NOTFOUND, keyring.find(key_name).code);
-    EXPECT_EQ(static_cast<const TSIGKey*>(NULL), keyring.find(key_name).key);
-
-    EXPECT_EQ(TSIGKeyRing::SUCCESS, keyring.add(
-                  TSIGKey(key_name, TSIGKey::HMACSHA256_NAME(),
-                          secret, secret_len)));
-    const TSIGKeyRing::FindResult result(keyring.find(key_name));
-    EXPECT_EQ(TSIGKeyRing::SUCCESS, result.code);
-    EXPECT_EQ(key_name, result.key->getKeyName());
-    EXPECT_EQ(TSIGKey::HMACSHA256_NAME(), result.key->getAlgorithmName());
+    // If the keyring is empty the search should fail.
+    EXPECT_EQ(TSIGKeyRing::NOTFOUND, keyring.find(key_name, md5_name).code);
+    EXPECT_EQ(static_cast<const TSIGKey*>(NULL),
+              keyring.find(key_name, md5_name).key);
+
+    // Add a key and try to find it.  Should succeed.
+    EXPECT_EQ(TSIGKeyRing::SUCCESS, keyring.add(TSIGKey(key_name, sha256_name,
+                                                        secret, secret_len)));
+    const TSIGKeyRing::FindResult result1(keyring.find(key_name, sha256_name));
+    EXPECT_EQ(TSIGKeyRing::SUCCESS, result1.code);
+    EXPECT_EQ(key_name, result1.key->getKeyName());
+    EXPECT_EQ(TSIGKey::HMACSHA256_NAME(), result1.key->getAlgorithmName());
     EXPECT_PRED_FORMAT4(UnitTestUtil::matchWireData, secret, secret_len,
-                        result.key->getSecret(),
-                        result.key->getSecretLength());
+                        result1.key->getSecret(),
+                        result1.key->getSecretLength());
+
+    // If either key name or algorithm doesn't match, search should fail.
+    const TSIGKeyRing::FindResult result2 =
+        keyring.find(Name("different-key.example"), sha256_name);
+    EXPECT_EQ(TSIGKeyRing::NOTFOUND, result2.code);
+    EXPECT_EQ(static_cast<const TSIGKey*>(NULL), result2.key);
+
+    const TSIGKeyRing::FindResult result3 = keyring.find(key_name, md5_name);
+    EXPECT_EQ(TSIGKeyRing::NOTFOUND, result3.code);
+    EXPECT_EQ(static_cast<const TSIGKey*>(NULL), result3.key);
 }
 
 TEST_F(TSIGKeyRingTest, findFromSome) {
     // essentially the same test, but search a larger set
 
-    EXPECT_EQ(TSIGKeyRing::SUCCESS, keyring.add(
-                  TSIGKey(key_name, TSIGKey::HMACSHA256_NAME(),
-                          secret, secret_len)));
-    EXPECT_EQ(TSIGKeyRing::SUCCESS, keyring.add(
-                  TSIGKey(Name("another.example"), TSIGKey::HMACMD5_NAME(),
-                          secret, secret_len)));
-    EXPECT_EQ(TSIGKeyRing::SUCCESS, keyring.add(
-                  TSIGKey(Name("more.example"), TSIGKey::HMACSHA1_NAME(),
-                          secret, secret_len)));
+    EXPECT_EQ(TSIGKeyRing::SUCCESS, keyring.add(TSIGKey(key_name, sha256_name,
+                                                        secret, secret_len)));
+    EXPECT_EQ(TSIGKeyRing::SUCCESS, keyring.add(TSIGKey(Name("another.example"),
+                                                        md5_name,
+                                                        secret, secret_len)));
+    EXPECT_EQ(TSIGKeyRing::SUCCESS, keyring.add(TSIGKey(Name("more.example"),
+                                                        sha1_name,
+                                                        secret, secret_len)));
 
     const TSIGKeyRing::FindResult result(
-        keyring.find(Name("another.example")));
+        keyring.find(Name("another.example"), md5_name));
     EXPECT_EQ(TSIGKeyRing::SUCCESS, result.code);
     EXPECT_EQ(Name("another.example"), result.key->getKeyName());
     EXPECT_EQ(TSIGKey::HMACMD5_NAME(), result.key->getAlgorithmName());
 
     EXPECT_EQ(TSIGKeyRing::NOTFOUND,
-              keyring.find(Name("noexist.example")).code);
+              keyring.find(Name("noexist.example"), sha1_name).code);
     EXPECT_EQ(static_cast<const TSIGKey*>(NULL),
-              keyring.find(Name("noexist.example")).key);
+              keyring.find(Name("noexist.example"), sha256_name).key);
+
+    EXPECT_EQ(TSIGKeyRing::NOTFOUND,
+              keyring.find(Name("another.example"), sha1_name).code);
+    EXPECT_EQ(static_cast<const TSIGKey*>(NULL),
+              keyring.find(Name("another.example"), sha256_name).key);
 }
 
 TEST(TSIGStringTest, TSIGKeyFromToString) {
@@ -248,6 +275,8 @@ TEST(TSIGStringTest, TSIGKeyFromToString) {
     TSIGKey k2 = TSIGKey("test.example.:MSG6Ng==:hmac-md5.sig-alg.reg.int.");
     TSIGKey k3 = TSIGKey("test.example:MSG6Ng==");
     TSIGKey k4 = TSIGKey(Name("test.example."), Name("hmac-sha1."), NULL, 0);
+    // "Unknown" key with empty secret is okay
+    TSIGKey k5 = TSIGKey("test.example.::unknown");
 
     EXPECT_EQ("test.example.:MSG6Ng==:hmac-md5.sig-alg.reg.int.",
               k1.toText());
@@ -256,6 +285,8 @@ TEST(TSIGStringTest, TSIGKeyFromToString) {
     EXPECT_EQ("test.example.:MSG6Ng==:hmac-md5.sig-alg.reg.int.",
               k3.toText());
     EXPECT_EQ("test.example.::hmac-sha1.", k4.toText());
+    EXPECT_EQ(Name("test.example."), k5.getKeyName());
+    EXPECT_EQ(Name("unknown"), k5.getAlgorithmName());
 
     EXPECT_THROW(TSIGKey(""), isc::InvalidParameter);
     EXPECT_THROW(TSIGKey(":"), isc::InvalidParameter);
@@ -266,7 +297,6 @@ TEST(TSIGStringTest, TSIGKeyFromToString) {
     EXPECT_THROW(TSIGKey("test.example.:"), isc::InvalidParameter);
     EXPECT_THROW(TSIGKey("test.example.:MSG6Ng==:"), isc::InvalidParameter);
     EXPECT_THROW(TSIGKey("test.example.:MSG6Ng==:unknown"), isc::InvalidParameter);
-
 }
 
 

src/lib/dns/tests/tsigrecord_unittest.cc

@@ -98,12 +98,11 @@ TEST_F(TSIGRecordTest, fromParams) {
 
     // Unexpected class
     EXPECT_THROW(TSIGRecord(test_name, RRClass::IN(), TSIGRecord::getTTL(),
-                            test_rdata, 85),
-                 DNSMessageFORMERR);
+                            test_rdata, 85), DNSMessageFORMERR);
 
-    // Unexpected TTL (simply ignored)
-    EXPECT_NO_THROW(TSIGRecord(test_name, TSIGRecord::getClass(),
-                               RRTTL(3600), test_rdata, 85));
+    // Unexpected TTL
+    EXPECT_THROW(TSIGRecord(test_name, TSIGRecord::getClass(),
+                            RRTTL(3600), test_rdata, 85), DNSMessageFORMERR);
 }
 
 TEST_F(TSIGRecordTest, recordToWire) {

src/lib/dns/tsig.cc

@@ -16,7 +16,7 @@
 
 #include <stdint.h>
 
-#include <cassert>              // for the tentative verifyTentative()
+#include <cassert>
 #include <vector>
 
 #include <boost/shared_ptr.hpp>
@@ -44,6 +44,17 @@ namespace isc {
 namespace dns {
 namespace {
 typedef boost::shared_ptr<HMAC> HMACPtr;
+
+// TSIG uses 48-bit unsigned integer to represent time signed.
+// Since gettimeWrapper() returns a 64-bit *signed* integer, we
+// make sure it's stored in an unsigned 64-bit integer variable and
+// represents a value in the expected range.  (In reality, however,
+// gettimeWrapper() will return a positive integer that will fit
+// in 48 bits)
+uint64_t
+getTSIGTime() {
+    return (detail::gettimeWrapper() & 0x0000ffffffffffffULL);
+}
 }
 
 struct TSIGContext::TSIGContextImpl {
@@ -51,17 +62,172 @@ struct TSIGContext::TSIGContextImpl {
         state_(INIT), key_(key), error_(Rcode::NOERROR()),
         previous_timesigned_(0)
     {}
+
+    // This helper method is used from verify().  It's expected to be called
+    // just before verify() returns.  It updates internal state based on
+    // the verification result and return the TSIGError to be returned to
+    // the caller of verify(), so that verify() can call this method within
+    // its 'return' statement.
+    TSIGError postVerifyUpdate(TSIGError error, const void* digest,
+                               uint16_t digest_len)
+    {
+        if (state_ == INIT) {
+            state_ = RECEIVED_REQUEST;
+        } else if (state_ == SENT_REQUEST && error == TSIGError::NOERROR()) {
+            state_ = VERIFIED_RESPONSE;
+        }
+        if (digest != NULL) {
+            previous_digest_.assign(static_cast<const uint8_t*>(digest),
+                                    static_cast<const uint8_t*>(digest) +
+                                    digest_len);
+        }
+        error_ = error;
+        return (error);
+    }
+
+    // The following three are helper methods to compute the digest for
+    // TSIG sign/verify in order to unify the common code logic for sign()
+    // and verify() and to keep these callers concise.
+    // These methods take an HMAC object, which will be updated with the
+    // calculated digest.
+    // Note: All methods construct a local OutputBuffer as a work space with a
+    // fixed initial buffer size to avoid intermediate buffer extension.
+    // This should be efficient enough, especially for fundamentally expensive
+    // operation like cryptographic sign/verify, but if the creation of the
+    // buffer in each helper method is still identified to be a severe
+    // performance bottleneck, we could have this class a buffer as a member
+    // variable and reuse it throughout the object's lifetime.  Right now,
+    // we prefer keeping the scope for local things as small as possible.
+    void digestPreviousMAC(HMACPtr hmac) const;
+    void digestTSIGVariables(HMACPtr hmac, uint16_t rrclass, uint32_t rrttl,
+                             uint64_t time_signed, uint16_t fudge,
+                             uint16_t error, uint16_t otherlen,
+                             const void* otherdata,
+                             bool time_variables_only) const;
+    void digestDNSMessage(HMACPtr hmac, uint16_t qid, const void* data,
+                          size_t data_len) const;
     State state_;
-    TSIGKey key_;
+    const TSIGKey key_;
     vector<uint8_t> previous_digest_;
     TSIGError error_;
     uint64_t previous_timesigned_; // only meaningful for response with BADTIME
 };
 
+void
+TSIGContext::TSIGContextImpl::digestPreviousMAC(HMACPtr hmac) const {
+    // We should have ensured the digest size fits 16 bits within this class
+    // implementation.
+    assert(previous_digest_.size() <= 0xffff);
+
+    OutputBuffer buffer(sizeof(uint16_t) + previous_digest_.size());
+    const uint16_t previous_digest_len(previous_digest_.size());
+    buffer.writeUint16(previous_digest_len);
+    if (previous_digest_len != 0) {
+        buffer.writeData(&previous_digest_[0], previous_digest_len);
+    }
+    hmac->update(buffer.getData(), buffer.getLength());
+}
+
+void
+TSIGContext::TSIGContextImpl::digestTSIGVariables(
+    HMACPtr hmac, uint16_t rrclass, uint32_t rrttl, uint64_t time_signed,
+    uint16_t fudge, uint16_t error, uint16_t otherlen, const void* otherdata,
+    bool time_variables_only) const
+{
+    // It's bit complicated, but we can still predict the necessary size of
+    // the data to be digested.  So we precompute it to avoid possible
+    // reallocation inside OutputBuffer (not absolutely necessary, but this
+    // is a bit more efficient)
+    size_t data_size = 8;
+    if (!time_variables_only) {
+        data_size += 10 + key_.getKeyName().getLength() +
+            key_.getAlgorithmName().getLength();
+    }
+    OutputBuffer buffer(data_size);
+
+    if (!time_variables_only) {
+        key_.getKeyName().toWire(buffer);
+        buffer.writeUint16(rrclass);
+        buffer.writeUint32(rrttl);
+        key_.getAlgorithmName().toWire(buffer);
+    }
+    buffer.writeUint16(time_signed >> 32);
+    buffer.writeUint32(time_signed & 0xffffffff);
+    buffer.writeUint16(fudge);
+
+    if (!time_variables_only) {
+        buffer.writeUint16(error);
+        buffer.writeUint16(otherlen);
+    }
+
+    hmac->update(buffer.getData(), buffer.getLength());
+    if (!time_variables_only && otherlen > 0) {
+        hmac->update(otherdata, otherlen);
+    }
+}
+
+// In digestDNSMessage, we exploit some minimum knowledge of DNS message
+// format:
+// - the header section has a fixed length of 12 octets (MESSAGE_HEADER_LEN)
+// - the offset in the header section to the ID field is 0
+// - the offset in the header section to the ARCOUNT field is 10 (and the field
+//   length is 2 octets)
+// We could construct a separate Message object from the given data, adjust
+// fields via the Message interfaces and then render it back to a separate
+// buffer, but that would be overkilling.  The DNS message header has a
+// fixed length and necessary modifications are quite straightforward, so
+// we do the job using lower level interfaces.
+namespace {
+const size_t MESSAGE_HEADER_LEN = 12;
+}
+void
+TSIGContext::TSIGContextImpl::digestDNSMessage(HMACPtr hmac,
+                                               uint16_t qid, const void* data,
+                                               size_t data_len) const
+{
+    OutputBuffer buffer(MESSAGE_HEADER_LEN);
+    const uint8_t* msgptr = static_cast<const uint8_t*>(data);
+
+    // Install the original ID
+    buffer.writeUint16(qid);
+    msgptr += sizeof(uint16_t);
+
+    // Copy the rest of the header except the ARCOUNT field.
+    buffer.writeData(msgptr, 8);
+    msgptr += 8;
+
+    // Install the adjusted ARCOUNT (we don't care even if the value is bogus
+    // and it underflows; it would simply result in verification failure)
+    buffer.writeUint16(InputBuffer(msgptr, sizeof(uint16_t)).readUint16() - 1);
+    msgptr += 2;
+
+    // Digest the header and the rest of the DNS message
+    hmac->update(buffer.getData(), buffer.getLength());
+    hmac->update(msgptr, data_len - MESSAGE_HEADER_LEN);
+}
+
 TSIGContext::TSIGContext(const TSIGKey& key) : impl_(new TSIGContextImpl(key))
 {
 }
 
+TSIGContext::TSIGContext(const Name& key_name, const Name& algorithm_name,
+                         const TSIGKeyRing& keyring) : impl_(NULL)
+{
+    const TSIGKeyRing::FindResult result(keyring.find(key_name,
+                                                      algorithm_name));
+    if (result.code == TSIGKeyRing::NOTFOUND) {
+        // If not key is found, create a dummy key with the specified key
+        // parameters and empty secret.  In the common scenario this will
+        // be used in subsequent response with a TSIG indicating a BADKEY
+        // error.
+        impl_ = new TSIGContextImpl(TSIGKey(key_name, algorithm_name,
+                                            NULL, 0));
+        impl_->error_ = TSIGError::BAD_KEY();
+    } else {
+        impl_ = new TSIGContextImpl(*result.key);
+    }
+}
+
 TSIGContext::~TSIGContext() {
     delete impl_;
 }
@@ -80,21 +246,20 @@ ConstTSIGRecordPtr
 TSIGContext::sign(const uint16_t qid, const void* const data,
                   const size_t data_len)
 {
+    if (impl_->state_ == VERIFIED_RESPONSE) {
+        isc_throw(TSIGContextError,
+                  "TSIG sign attempt after verifying a response");
+    }
+
     if (data == NULL || data_len == 0) {
         isc_throw(InvalidParameter, "TSIG sign error: empty data is given");
     }
 
     TSIGError error(TSIGError::NOERROR());
-    // TSIG uses 48-bit unsigned integer to represent time signed.
-    // Since gettimeofdayWrapper() returns a 64-bit *signed* integer, we
-    // make sure it's stored in an unsigned 64-bit integer variable and
-    // represents a value in the expected range.  (In reality, however,
-    // gettimeofdayWrapper() will return a positive integer that will fit
-    // in 48 bits)
-    const uint64_t now = (detail::gettimeWrapper() & 0x0000ffffffffffffULL);
+    const uint64_t now = getTSIGTime();
 
     // For responses adjust the error code.
-    if (impl_->state_ == CHECKED) {
+    if (impl_->state_ == RECEIVED_REQUEST) {
         error = impl_->error_;
     }
 
@@ -107,11 +272,10 @@ TSIGContext::sign(const uint16_t qid, const void* const data,
                                               now, DEFAULT_FUDGE, 0, NULL,
                                               qid, error.getCode(), 0, NULL)));
         impl_->previous_digest_.clear();
-        impl_->state_ = SIGNED;
+        impl_->state_ = SENT_RESPONSE;
         return (tsig);
     }
 
-    OutputBuffer variables(0);
     HMACPtr hmac(CryptoLink::getCryptoLink().createHMAC(
                      impl_->key_.getSecret(),
                      impl_->key_.getSecretLength(),
@@ -121,87 +285,169 @@ TSIGContext::sign(const uint16_t qid, const void* const data,
     // If the context has previous MAC (either the Request MAC or its own
     // previous MAC), digest it.
     if (impl_->state_ != INIT) {
-        const uint16_t previous_digest_len(impl_->previous_digest_.size());
-        variables.writeUint16(previous_digest_len);
-        if (previous_digest_len != 0) {
-            variables.writeData(&impl_->previous_digest_[0],
-                                previous_digest_len);
-        }
-        hmac->update(variables.getData(), variables.getLength());
+        impl_->digestPreviousMAC(hmac);
     }
 
     // Digest the message (without TSIG)
     hmac->update(data, data_len);
 
-    //
-    // Digest TSIG variables.  If state_ is SIGNED we skip digesting them
-    // except for time related variables (RFC2845 4.4).
-    //
-    variables.clear();
-    if (impl_->state_ != SIGNED) {
-        impl_->key_.getKeyName().toWire(variables);
-        TSIGRecord::getClass().toWire(variables);
-        variables.writeUint32(TSIGRecord::TSIG_TTL);
-        impl_->key_.getAlgorithmName().toWire(variables);
-    }
+    // Digest TSIG variables.
+    // First, prepare some non constant variables.
     const uint64_t time_signed = (error == TSIGError::BAD_TIME()) ?
         impl_->previous_timesigned_ : now;
-    variables.writeUint16(time_signed >> 32);
-    variables.writeUint32(time_signed & 0xffffffff);
-    variables.writeUint16(DEFAULT_FUDGE);
-    hmac->update(variables.getData(), variables.getLength());
-    variables.clear();
-
-    if (impl_->state_ != SIGNED) {
-        variables.writeUint16(error.getCode());
-
-        // For BADTIME error, digest 6 bytes of other data.
-        // (6 bytes = size of time signed value)
-        variables.writeUint16((error == TSIGError::BAD_TIME()) ? 6 : 0);
-        hmac->update(variables.getData(), variables.getLength());
-
-        variables.clear();
-        if (error == TSIGError::BAD_TIME()) {
-            variables.writeUint16(now >> 32);
-            variables.writeUint32(now & 0xffffffff);
-            hmac->update(variables.getData(), variables.getLength());
-        }
+    // For BADTIME error, we include 6 bytes of other data.
+    // (6 bytes = size of time signed value)
+    const uint16_t otherlen = (error == TSIGError::BAD_TIME()) ? 6 : 0;
+    OutputBuffer otherdatabuf(otherlen);
+    if (error == TSIGError::BAD_TIME()) {
+            otherdatabuf.writeUint16(now >> 32);
+            otherdatabuf.writeUint32(now & 0xffffffff);
     }
-    const uint16_t otherlen = variables.getLength();
+    const void* const otherdata =
+        (otherlen == 0) ? NULL : otherdatabuf.getData();
+    // Then calculate the digest.  If state_ is SENT_RESPONSE we are sending
+    // a continued message in the same TCP stream so skip digesting
+    // variables except for time related variables (RFC2845 4.4).
+    impl_->digestTSIGVariables(hmac, TSIGRecord::getClass().getCode(),
+                               TSIGRecord::TSIG_TTL, time_signed,
+                               DEFAULT_FUDGE, error.getCode(),
+                               otherlen, otherdata,
+                               impl_->state_ == SENT_RESPONSE);
 
     // Get the final digest, update internal state, then finish.
     vector<uint8_t> digest = hmac->sign();
+    assert(digest.size() <= 0xffff); // cryptolink API should have ensured it.
     ConstTSIGRecordPtr tsig(new TSIGRecord(
                                 impl_->key_.getKeyName(),
                                 any::TSIG(impl_->key_.getAlgorithmName(),
                                           time_signed, DEFAULT_FUDGE,
                                           digest.size(), &digest[0],
                                           qid, error.getCode(), otherlen,
-                                          otherlen == 0 ?
-                                          NULL : variables.getData())));
+                                          otherdata)));
     // Exception free from now on.
     impl_->previous_digest_.swap(digest);
-    impl_->state_ = SIGNED;
+    impl_->state_ = (impl_->state_ == INIT) ? SENT_REQUEST : SENT_RESPONSE;
     return (tsig);
 }
 
-void
-TSIGContext::verifyTentative(ConstTSIGRecordPtr tsig, TSIGError error) {
-    const any::TSIG tsig_rdata = tsig->getRdata();
+TSIGError
+TSIGContext::verify(const TSIGRecord* const record, const void* const data,
+                    const size_t data_len)
+{
+    if (impl_->state_ == SENT_RESPONSE) {
+        isc_throw(TSIGContextError,
+                  "TSIG verify attempt after sending a response");
+    }
 
-    impl_->error_ = error;
-    if (error == TSIGError::BAD_TIME()) {
-        impl_->previous_timesigned_ = tsig_rdata.getTimeSigned();
+    // This case happens when we sent a signed request and have received an
+    // unsigned response.  According to RFC2845 Section 4.6 this case should be
+    // considered a "format error" (although the specific error code
+    // wouldn't matter much for the caller).
+    if (record == NULL) {
+        return (impl_->postVerifyUpdate(TSIGError::FORMERR(), NULL, 0));
+    }
+
+    const any::TSIG& tsig_rdata = record->getRdata();
+
+    // Reject some obviously invalid data
+    if (data_len < MESSAGE_HEADER_LEN + record->getLength()) {
+        isc_throw(InvalidParameter,
+                  "TSIG verify: data length is invalid: " << data_len);
+    }
+    if (data == NULL) {
+        isc_throw(InvalidParameter, "TSIG verify: empty data is invalid");
+    }
+
+    // Check key: whether we first verify it with a known key or we verify
+    // it using the consistent key in the context.  If the check fails we are
+    // done with BADKEY.
+    if (impl_->state_ == INIT && impl_->error_ == TSIGError::BAD_KEY()) {
+        return (impl_->postVerifyUpdate(TSIGError::BAD_KEY(), NULL, 0));
+    }
+    if (impl_->key_.getKeyName() != record->getName() ||
+        impl_->key_.getAlgorithmName() != tsig_rdata.getAlgorithm()) {
+        return (impl_->postVerifyUpdate(TSIGError::BAD_KEY(), NULL, 0));
+    }
+
+    // Check time: the current time must be in the range of
+    // [time signed - fudge, time signed + fudge].  Otherwise verification
+    // fails with BADTIME. (RFC2845 Section 4.6.2)
+    // Note: for simplicity we don't explicitly catch the case of too small
+    // current time causing underflow.  With the fact that fudge is quite
+    // small and (for now) non configurable, it shouldn't be a real concern
+    // in practice.
+    const uint64_t now = getTSIGTime();
+    if (tsig_rdata.getTimeSigned() + DEFAULT_FUDGE < now ||
+        tsig_rdata.getTimeSigned() - DEFAULT_FUDGE > now) {
+        const void* digest = NULL;
+        size_t digest_len = 0;
+        if (impl_->state_ == INIT) {
+            digest = tsig_rdata.getMAC();
+            digest_len = tsig_rdata.getMACSize();
+            impl_->previous_timesigned_ = tsig_rdata.getTimeSigned();
+        }
+        return (impl_->postVerifyUpdate(TSIGError::BAD_TIME(), digest,
+                                        digest_len));
+    }
+
+    // TODO: signature length check based on RFC4635
+    // (Right now we enforce the standard signature length in libcryptolink)
+
+    // Handling empty MAC.  While RFC2845 doesn't explicitly prohibit other
+    // cases, it can only reasonably happen in a response with BADSIG or
+    // BADKEY.  We reject other cases as if it were BADSIG to avoid unexpected
+    // acceptance of a bogus signature.  This behavior follows the BIND 9
+    // implementation.
+    if (tsig_rdata.getMACSize() == 0) {
+        TSIGError error = TSIGError(tsig_rdata.getError());
+        if (error != TSIGError::BAD_SIG() && error != TSIGError::BAD_KEY()) {
+            error = TSIGError::BAD_SIG();
+        }
+        return (impl_->postVerifyUpdate(error, NULL, 0));
+    }
+
+    HMACPtr hmac(CryptoLink::getCryptoLink().createHMAC(
+                     impl_->key_.getSecret(),
+                     impl_->key_.getSecretLength(),
+                     impl_->key_.getAlgorithm()),
+                 deleteHMAC);
+
+    // If the context has previous MAC (either the Request MAC or its own
+    // previous MAC), digest it.
+    if (impl_->state_ != INIT) {
+        impl_->digestPreviousMAC(hmac);
     }
 
-    // For simplicity we assume non empty digests.
-    assert(tsig_rdata.getMACSize() != 0);
-    impl_->previous_digest_.assign(
-        static_cast<const uint8_t*>(tsig_rdata.getMAC()),
-        static_cast<const uint8_t*>(tsig_rdata.getMAC()) +
-        tsig_rdata.getMACSize());
+    //
+    // Digest DNS message (excluding the trailing TSIG RR and adjusting the
+    // QID and ARCOUNT header fields)
+    //
+    impl_->digestDNSMessage(hmac, tsig_rdata.getOriginalID(),
+                            data, data_len - record->getLength());
+
+    // Digest TSIG variables.  If state_ is VERIFIED_RESPONSE, it's a
+    // continuation of the same TCP stream and skip digesting them except
+    // for time related variables (RFC2845 4.4).
+    // Note: we use the constant values for RR class and TTL specified
+    // in RFC2845, not received values (we reject other values in constructing
+    // the TSIGRecord).
+    impl_->digestTSIGVariables(hmac, TSIGRecord::getClass().getCode(),
+                               TSIGRecord::TSIG_TTL,
+                               tsig_rdata.getTimeSigned(),
+                               tsig_rdata.getFudge(), tsig_rdata.getError(),
+                               tsig_rdata.getOtherLen(),
+                               tsig_rdata.getOtherData(),
+                               impl_->state_ == VERIFIED_RESPONSE);
 
-    impl_->state_ = CHECKED;
+    // Verify the digest with the received signature.
+    if (hmac->verify(tsig_rdata.getMAC(), tsig_rdata.getMACSize())) {
+        return (impl_->postVerifyUpdate(TSIGError::NOERROR(),
+                                        tsig_rdata.getMAC(),
+                                        tsig_rdata.getMACSize()));
+    }
+
+    return (impl_->postVerifyUpdate(TSIGError::BAD_SIG(), NULL, 0));
 }
+
 } // namespace dns
 } // namespace isc

src/lib/dns/tsig.h

@@ -17,12 +17,27 @@
 
 #include <boost/noncopyable.hpp>
 
+#include <exceptions/exceptions.h>
+
 #include <dns/tsigerror.h>
 #include <dns/tsigkey.h>
 #include <dns/tsigrecord.h>
 
 namespace isc {
 namespace dns {
+
+/// An exception that is thrown for logic errors identified in TSIG
+/// sign/verify operations.
+///
+/// Note that this exception is not thrown for TSIG protocol errors such as
+/// verification failures.  In general, this exception indicates an internal
+/// program bug.
+class TSIGContextError : public isc::Exception {
+public:
+    TSIGContextError(const char* file, size_t line, const char* what) :
+        isc::Exception(file, line, what) {}
+};
+
 /// TSIG session context.
 ///
 /// The \c TSIGContext class maintains a context of a signed session of
@@ -59,8 +74,7 @@ namespace dns {
 /// in this mode will identify the appropriate TSIG key (or internally record
 /// an error if it doesn't find a key).  The server will then verify the
 /// query with the context, and generate a signed response using the same
-/// same context.  (Note: this mode is not yet implemented and may change,
-/// see below).
+/// same context.
 ///
 /// When multiple messages belong to the same TSIG session, either side
 /// (signer or verifier) will keep using the same context.  It records
@@ -68,8 +82,68 @@ namespace dns {
 /// calls to \c sign() or \c verify() work correctly in terms of the TSIG
 /// protocol.
 ///
-/// \note The \c verify() method is not yet implemented.  The implementation
-/// and documentation should be updated in the corresponding task.
+/// \b Examples
+///
+/// This is a typical client application that sends a TSIG signed query
+/// and verifies the response.
+///
+/// \code
+///    // "renderer" is of MessageRenderer to render the message.
+///    // (TSIGKey would be configured from config or command line in real app)
+///    TSIGContext ctx(TSIGKey("key.example:MSG6Ng=="));
+///    Message message(Message::RENDER);
+///    message.addQuestion(Question(Name("www.example.com"), RRClass::IN(),
+///                                 RRType::A()));
+///    message.toWire(renderer, ctx);
+///
+///    // sendto, then recvfrom.  received result in (data, data_len)
+///
+///    message.clear(Message::PARSE);
+///    InputBuffer buffer(data, data_len);
+///    message.fromWire(buffer);
+///    TSIGError tsig_error = ctx.verify(message.getTSIGRecord(),
+///                                      data, data_len);
+///    if (tsig_error == TSIGError::NOERROR()) {
+///        // okay.  ctx can be continuously used if it's receiving subsequent
+///        // signed responses from a TCP stream.
+///    } else if (message.getRcode() == Rcode::NOTAUTH()) {
+///        // hard error.  give up this transaction per RFC2845 4.6.
+///    } else {
+///        // Other error: discard response keep waiting with the same ctx
+///        // for another (again, RFC2845 4.6).
+///    } \endcode
+///
+/// And this is a typical server application that authenticates a signed
+/// query and returns a response according to the result.
+///
+/// \code
+///    // Assume "message" is of type Message for query handling and
+///    // "renderer" is of MessageRenderer to render responses.
+///    Message message(Message::RENDER);
+///
+///    TSIGKeyRing keyring; // this must be configured with keys somewhere
+///
+///    // Receive a query and store it in (data, data_len)
+///    InputBuffer buffer(data, data_len);
+///    message.clear(Message::PARSE);
+///    message.fromWire(buffer);
+///
+///    const TSIGRecord* tsig = message.getTSIGRecord();
+///    if (tsig != NULL) {
+///        TSIGContext ctx(tsig->getName(), tsig->getRdata().getAlgorithm(),
+///                        keyring);
+///        ctx.verify(tsig, data, data_len);
+///
+///        // prepare response
+///        message.makeResponse();
+///        //...
+///        message.toWire(renderer, ctx);
+///
+///        // send the response data back to the client.
+///        // If this is a beginning of a signed session over a TCP and
+///        // server has more data to send to the client, this ctx
+///        // will be used to sign subsequent messages.
+///    } \endcode
 ///
 /// <b>TCP Consideration</b>
 ///
@@ -110,8 +184,10 @@ public:
     /// directly.
     enum State {
         INIT,                   ///< Initial state
-        SIGNED,                 ///< Sign completed
-        CHECKED ///< Verification completed (may or may not successfully)
+        SENT_REQUEST, ///< Client sent a signed request, waiting response
+        RECEIVED_REQUEST,       ///< Server received a signed request
+        SENT_RESPONSE,          ///< Server sent a signed response
+        VERIFIED_RESPONSE       ///< Client successfully verified a response
     };
 
     /// \name Constructors and destructor
@@ -124,6 +200,10 @@ public:
     /// \param key The TSIG key to be used for TSIG sessions with this context.
     explicit TSIGContext(const TSIGKey& key);
 
+    /// Constructor from key parameters and key ring.
+    TSIGContext(const Name& key_name, const Name& algorithm_name,
+                const TSIGKeyRing& keyring);
+
     /// The destructor.
     ~TSIGContext();
     //@}
@@ -141,6 +221,13 @@ public:
     /// complete TSIG RR into the message that has been signed so that it
     /// will become a complete TSIG-signed message.
     ///
+    /// In general, this method is called once by a client to send a
+    /// signed request or one more times by a server to sign
+    /// response(s) to a signed request.  To avoid allowing accidental
+    /// misuse, if this method is called after a "client" validates a
+    /// response, an exception of class \c TSIGContextError will be
+    /// thrown.
+    ///
     /// \note Normal applications are not expected to call this method
     /// directly; they will usually use the \c Message::toWire() method
     /// with a \c TSIGContext object being a parameter and have the
@@ -165,6 +252,7 @@ public:
     /// returns (without an exception being thrown), the internal state of
     /// the \c TSIGContext won't be modified.
     ///
+    /// \exception TSIGContextError Context already verified a response.
     /// \exception InvalidParameter \c data is NULL or \c data_len is 0
     /// \exception cryptolink::LibraryError Some unexpected error in the
     /// underlying crypto operation
@@ -179,6 +267,92 @@ public:
     ConstTSIGRecordPtr sign(const uint16_t qid, const void* const data,
                             const size_t data_len);
 
+    /// Verify a DNS message.
+    ///
+    /// This method verifies given data along with the context and a given
+    /// TSIG in the form of a \c TSIGRecord object.  The data to be verified
+    /// is generally expected to be a complete, wire-format DNS message,
+    /// exactly as received by the host, and ending with a TSIG RR.
+    /// After verification process this method updates its internal state,
+    /// and returns the result in the form of a \c TSIGError object.
+    /// Possible return values are (see the \c TSIGError class description
+    /// for the mnemonics):
+    ///
+    /// - \c NOERROR: The data has been verified correctly.
+    /// - \c FORMERR: \c TSIGRecord is not given (see below).
+    /// - \c BAD_KEY: Appropriate key is not found or specified key doesn't
+    ///               match for the data.
+    /// - \c BAD_TIME: The current time doesn't fall in the range specified
+    ///                in the TSIG.
+    /// - \c BAD_SIG: The signature given in the TSIG doesn't match against
+    ///               the locally computed digest or is the signature is
+    ///               invalid in other way.
+    ///
+    /// If this method is called by a DNS client waiting for a signed
+    /// response and the result is not \c NOERROR, the context can be used
+    /// to try validating another signed message as described in RFC2845
+    /// Section 4.6.
+    ///
+    /// If this method is called by a DNS server that tries to authenticate
+    /// a signed request, and if the result is not \c NOERROR, the
+    /// corresponding error condition is recorded in the context so that
+    /// the server can return a response indicating what was wrong by calling
+    /// \c sign() with the updated context.
+    ///
+    /// In general, this method is called once by a server for
+    /// authenticating a signed request or one more times by a client to
+    /// validate signed response(s) to a signed request.  To avoid allowing
+    /// accidental misuse, if this method is called after a "server" signs
+    /// a response, an exception of class \c TSIGContextError will be thrown.
+    ///
+    /// The \c record parameter can be NULL; in that case this method simply
+    /// returns \c FORMERR as the case described in Section 4.6 of RFC2845,
+    /// i.e., receiving an unsigned response to a signed request.  This way
+    /// a client can transparently pass the result of
+    /// \c Message::getTSIGRecord() without checking whether it's non NULL
+    /// and take an appropriate action based on the result of this method.
+    ///
+    /// This method handles the given data mostly as opaque.  It digests
+    /// the data assuming it begins with a DNS header and ends with a TSIG
+    /// RR whose length is given by calling \c TSIGRecord::getLength() on
+    /// \c record, but otherwise it doesn't parse the data to confirm the
+    /// assumption.  It's caller's responsibility to ensure the data is
+    /// valid and consistent with \c record.  To avoid disruption, this
+    /// method performs minimal validation on the given \c data and \c record:
+    /// \c data must not be NULL; \c data_len must not be smaller than the
+    /// sum of the DNS header length (fixed, 12 octets) and the length of
+    /// the TSIG RR.  If this check fails it throws an \c InvalidParameter
+    /// exception.
+    ///
+    /// One unexpected case that is not covered by this method is that a
+    /// client receives a signed response to an unsigned request.  RFC2845 is
+    /// silent about such cases; BIND 9 explicitly identifies the case and
+    /// rejects it.  With this implementation, the client can know that the
+    /// response contains a TSIG via the result of
+    /// \c Message::getTSIGRecord() and that it is an unexpected TSIG due to
+    /// the fact that it doesn't have a corresponding \c TSIGContext.
+    /// It's up to the client implementation whether to react to such a case
+    /// explicitly (for example, it could either ignore the TSIG and accept
+    /// the response or drop it).
+    ///
+    /// This method provides the strong exception guarantee; unless the method
+    /// returns (without an exception being thrown), the internal state of
+    /// the \c TSIGContext won't be modified.
+    ///
+    /// \todo Support intermediate TCP DNS messages without TSIG (RFC2845 4.4)
+    /// \todo Signature truncation support based on RFC4635
+    ///
+    /// \exception TSIGContextError Context already signed a response.
+    /// \exception InvalidParameter \c data is NULL or \c data_len is too small.
+    ///
+    /// \param record The \c TSIGRecord to be verified with \c data
+    /// \param data Points to the wire-format data (exactly as received) to
+    /// be verified
+    /// \param data_len The length of \c data in bytes
+    /// \return The \c TSIGError that indicates verification result
+    TSIGError verify(const TSIGRecord* const record, const void* const data,
+                     const size_t data_len);
+
     /// Return the current state of the context
     ///
     /// \note
@@ -196,18 +370,6 @@ public:
     /// \exception None
     TSIGError getError() const;
 
-    // This method is tentatively added for testing until a complete
-    // verify() method is implemented.  Once it's done this should be
-    // removed, and corresponding tests should be updated.
-    //
-    // This tentative "verify" method changes the internal state of
-    // the TSIGContext to the CHECKED as if it were verified (though possibly
-    // unsuccessfully) with given tsig_rdata.  If the error parameter is
-    // given and not NOERROR, it's recorded inside the context so that the
-    // subsequent sign() will behave accordingly.
-    void verifyTentative(ConstTSIGRecordPtr tsig,
-                         TSIGError error = TSIGError::NOERROR());
-
     /// \name Protocol constants and defaults
     ///
     //@{

src/lib/dns/tsigerror.cc

@@ -49,6 +49,17 @@ TSIGError::toText() const {
     }
 }
 
+Rcode
+TSIGError::toRcode() const {
+    if (code_ <= MAX_RCODE_FOR_TSIGERROR) {
+        return (Rcode(code_));
+    }
+    if (code_ > BAD_TIME_CODE) {
+        return (Rcode::SERVFAIL());
+    }
+    return (Rcode::NOTAUTH());
+}
+
 std::ostream&
 operator<<(std::ostream& os, const TSIGError& error) {
     return (os << error.toText());

src/lib/dns/tsigerror.h

@@ -125,6 +125,22 @@ public:
     /// \return A string representation of the \c TSIGError.
     std::string toText() const;
 
+    /// \brief Convert the \c TSIGError to a \c Rcode
+    ///
+    /// This method returns an \c Rcode object that is corresponding to
+    /// the TSIG error.  The returned \c Rcode is expected to be used
+    /// by a verifying server to specify the RCODE of a response when
+    /// TSIG verification fails.
+    ///
+    /// Specifically, this method returns \c Rcode::NOTAUTH() for the
+    /// TSIG specific errors, BADSIG, BADKEY, BADTIME, as described in
+    /// RFC2845.  For errors derived from the standard Rcode (code 0-15),
+    /// it returns the corresponding \c Rcode.  For others, this method
+    /// returns \c Rcode::SERVFAIL() as a last resort.
+    ///
+    /// \exception None
+    Rcode toRcode() const;
+
     /// A constant TSIG error object derived from \c Rcode::NOERROR()
     static const TSIGError& NOERROR();
 

src/lib/dns/tsigkey.cc

@@ -42,8 +42,7 @@ namespace {
         if (name == TSIGKey::HMACSHA256_NAME()) {
             return (isc::cryptolink::SHA256);
         }
-        isc_throw(InvalidParameter,
-                  "Unknown TSIG algorithm is specified: " << name);
+        return (isc::cryptolink::UNKNOWN_HASH);
     }
 }
 
@@ -74,7 +73,13 @@ TSIGKey::TSIGKey(const Name& key_name, const Name& algorithm_name,
     if ((secret != NULL && secret_len == 0) ||
         (secret == NULL && secret_len != 0)) {
         isc_throw(InvalidParameter,
-                  "TSIGKey secret and its length are inconsistent");
+                  "TSIGKey secret and its length are inconsistent: " <<
+                  key_name << ":" << algorithm_name);
+    }
+    if (algorithm == isc::cryptolink::UNKNOWN_HASH && secret_len != 0) {
+        isc_throw(InvalidParameter,
+                  "TSIGKey with unknown algorithm has non empty secret: " <<
+                  key_name << ":" << algorithm_name);
     }
     impl_ = new TSIGKeyImpl(key_name, algorithm_name, algorithm, secret,
                             secret_len);
@@ -111,8 +116,15 @@ TSIGKey::TSIGKey(const std::string& str) : impl_(NULL) {
         vector<uint8_t> secret;
         isc::util::encode::decodeBase64(secret_str, secret);
 
+        if (algorithm == isc::cryptolink::UNKNOWN_HASH && !secret.empty()) {
+            isc_throw(InvalidParameter,
+                      "TSIG key with unknown algorithm has non empty secret: "
+                      << str);
+        }
+
         impl_ = new TSIGKeyImpl(Name(keyname_str), algo_name, algorithm,
-                                &secret[0], secret.size());
+                                secret.empty() ? NULL : &secret[0],
+                                secret.size());
     } catch (const Exception& e) {
         // 'reduce' the several types of exceptions name parsing and
         // Base64 decoding can throw to just the InvalidParameter
@@ -230,10 +242,11 @@ TSIGKeyRing::remove(const Name& key_name) {
 }
 
 TSIGKeyRing::FindResult
-TSIGKeyRing::find(const Name& key_name) {
+TSIGKeyRing::find(const Name& key_name, const Name& algorithm_name) const {
     TSIGKeyRingImpl::TSIGKeyMap::const_iterator found =
         impl_->keys.find(key_name);
-    if (found == impl_->keys.end()) {
+    if (found == impl_->keys.end() ||
+        (*found).second.getAlgorithmName() != algorithm_name) {
         return (FindResult(NOTFOUND, NULL));
     }
     return (FindResult(SUCCESS, &((*found).second)));

src/lib/dns/tsigkey.h

@@ -68,12 +68,30 @@ public:
     //@{
     /// \brief Constructor from key parameters
     ///
-    /// In the current implementation, \c algorithm_name must be a known
-    /// algorithm to this implementation, which are defined via the
-    /// <code>static const</code> member functions.  For other names
-    /// an exception of class \c InvalidParameter will be thrown.
-    /// Note: This restriction may be too strict, and we may revisit it
-    /// later.
+    /// \c algorithm_name should generally be a known algorithm to this
+    /// implementation, which are defined via the
+    /// <code>static const</code> member functions.
+    ///
+    /// Other names are still accepted as long as the secret is empty
+    /// (\c secret is \c NULL and \c secret_len is 0), however; in some cases
+    /// we might want to treat just the pair of key name and algorithm name
+    /// opaquely, e.g., when generating a response TSIG with a BADKEY error
+    /// because the algorithm is unknown as specified in Section 3.2 of
+    /// RFC2845 (in which case the algorithm name would be copied from the
+    /// request to the response, and for that purpose it would be convenient
+    /// if a \c TSIGKey object can hold a name for an "unknown" algorithm).
+    ///
+    /// \note RFC2845 does not specify which algorithm name should be used
+    /// in such a BADKEY response.  The behavior of using the same algorithm
+    /// is derived from the BIND 9 implementation.
+    ///
+    /// It is unlikely that a TSIG key with an unknown algorithm is of any
+    /// use with actual crypto operation, so care must be taken when dealing
+    /// with such keys. (The restriction for the secret will prevent
+    /// accidental creation of such a dangerous key, e.g., due to misspelling
+    /// in a configuration file).
+    /// If the given algorithm name is unknown and non empty secret is
+    /// specified, an exception of type \c InvalidParameter will be thrown.
     ///
     /// \c secret and \c secret_len must be consistent in that the latter
     /// is 0 if and only if the former is \c NULL;
@@ -98,9 +116,12 @@ public:
     /// <name>:<secret>[:<algorithm>]
     /// Where <name> is a domain name for the key, <secret> is a
     /// base64 representation of the key secret, and the optional
-    /// algorithm is an algorithm identifier as specified in RFC4635
+    /// algorithm is an algorithm identifier as specified in RFC4635.
     /// The default algorithm is hmac-md5.sig-alg.reg.int.
     ///
+    /// The same restriction about the algorithm name (and secret) as that
+    /// for the other constructor applies.
+    ///
     /// Since ':' is used as a separator here, it is not possible to
     /// use this constructor to create keys with a ':' character in
     /// their name.
@@ -304,7 +325,9 @@ public:
     /// Find a \c TSIGKey for the given name in the \c TSIGKeyRing.
     ///
     /// It searches the internal storage for a \c TSIGKey whose name is
-    /// \c key_name, and returns the result in the form of a \c FindResult
+    /// \c key_name and that uses the hash algorithm identified by
+    /// \c algorithm_name.
+    /// It returns the result in the form of a \c FindResult
     /// object as follows:
     /// - \c code: \c SUCCESS if a key is found; otherwise \c NOTFOUND.
     /// - \c key: A pointer to the found \c TSIGKey object if one is found;
@@ -318,8 +341,9 @@ public:
     /// This method never throws an exception.
     ///
     /// \param key_name The name of the key to be found.
+    /// \param algorithm_name The name of the algorithm of the found key.
     /// \return A \c FindResult object enclosing the search result (see above).
-    FindResult find(const Name& key_name);
+    FindResult find(const Name& key_name, const Name& algorithm_name) const;
 private:
     struct TSIGKeyRingImpl;
     TSIGKeyRingImpl* impl_;

src/lib/dns/tsigrecord.cc

@@ -70,14 +70,16 @@ castToTSIGRdata(const rdata::Rdata& rdata) {
 }
 
 TSIGRecord::TSIGRecord(const Name& name, const RRClass& rrclass,
-                       const RRTTL&, // we ignore TTL
-                       const rdata::Rdata& rdata,
+                       const RRTTL& ttl, const rdata::Rdata& rdata,
                        size_t length) :
     key_name_(name), rdata_(castToTSIGRdata(rdata)), length_(length)
 {
     if (rrclass != getClass()) {
         isc_throw(DNSMessageFORMERR, "Unexpected TSIG RR class: " << rrclass);
     }
+    if (ttl != RRTTL(TSIG_TTL)) {
+        isc_throw(DNSMessageFORMERR, "Unexpected TSIG TTL: " << ttl);
+    }
 }
 
 const RRClass&

src/lib/dns/tsigrecord.h

@@ -83,15 +83,39 @@ public:
     /// TSIG).
     ///
     /// According to RFC2845, a TSIG RR uses fixed RR class (ANY) and TTL (0).
-    /// If the RR class is different from the expected one, this
+    /// If the RR class or TTL is different from the expected one, this
     /// implementation considers it an invalid record and throws an exception
-    /// of class \c DNSMessageFORMERR.  On the other hand, the TTL is simply
-    /// ignored (in that sense we could even omit that parameter, but it's
-    /// still included if and when we want to change the policy).  RFC2845
-    /// is silent about what the receiver should do if it sees an unexpected
-    /// RR class or TTL in a TSIG RR.  This implementation simply follows what
-    /// BIND 9 does (it is not clear why BIND 9 employs the "inconsistent"
-    /// policy).
+    /// of class \c DNSMessageFORMERR.
+    ///
+    /// \note This behavior is not specified in the protocol specification,
+    /// but this implementation rejects unexpected values for the following
+    /// reasons (but in any case, this won't matter much in practice as
+    /// RFC2848 clearly states these fields always have the fixed values and
+    /// any sane implementation of TSIG signer will follow that):
+    /// According to the RFC editor (in a private communication), the intended
+    /// use of the TSIG TTL field is to signal protocol extensions (currently
+    /// no such extension is defined), so this field may actually be
+    /// validly non 0 in future.  However, until the implementation supports
+    /// that extension it may not always be able to handle the extended
+    /// TSIG as intended; the extension may even affect digest computation.
+    /// There's a related issue on this point.  Different implementations
+    /// interpret the RFC in different ways on the received TTL when
+    /// digesting the message: BIND 9 uses the received value (even if
+    /// it's not 0) as part of the TSIG variables; NLnet Labs' LDNS and NSD
+    /// always use a fixed constant of 0 regardless of the received TTL value.
+    /// This means if and when an extension with non 0 TTL is introduced
+    /// there will be interoperability problems in the form of verification
+    /// failure.  By explicitly rejecting it (and subsequently returning
+    /// a response with a format error) we can indicate the source of the
+    /// problem more clearly than a "bad signature" TSIG error, which can
+    /// happen for various reasons.  On the other hand, rejecting unexpected
+    /// RR classes is mostly for consistency; the RFC lists these two fields
+    /// in the same way, so it makes more sense to handle them equally.
+    /// (BIND 9 rejects unexpected RR classes for TSIG, but that is part of
+    /// general check on RR classes on received RRs; it generally requests
+    /// all classes are the same, and if the protocol specifies the use of
+    /// a particular class for a particular type of RR, it requests that
+    /// class be used).
     ///
     /// Likewise, if \c rdata is not of type \c any::TSIG, an exception of
     /// class DNSMessageFORMERR will be thrown.  When the caller is a
@@ -142,8 +166,7 @@ public:
     /// \param name The owner name of the TSIG RR
     /// \param rrclass The RR class of the RR.  Must be \c RRClass::ANY()
     /// (see above)
-    /// \param ttl The TTL of the RR.  Expected to be a zero TTL, but
-    /// actually ignored in this implementation.
+    /// \param ttl The TTL of the RR.  Must be 0 (see above)
     /// \param rdata The RDATA of the RR.  Must be of type \c any::TSIG.
     /// \param length The size of the RR (see above)
     TSIGRecord(const Name& name, const RRClass& rrclass, const RRTTL& ttl,

src/lib/log/log_formatter.h

@@ -125,7 +125,11 @@ public:
     ///
     /// \param arg The argument to place into the placeholder.
     template<class Arg> Formatter& arg(const Arg& value) {
-        return (arg(boost::lexical_cast<std::string>(value)));
+        if (logger_) {
+            return (arg(boost::lexical_cast<std::string>(value)));
+        } else {
+            return (*this);
+        }
     }
     /// \brief String version of arg.
     Formatter& arg(const std::string& arg) {