Browse Source

[master] Merge branch 'master' of ssh://bind10.isc.org/var/bind10/git/bind10

JINMEI Tatuya 14 years ago
parent
commit
4e0adcf353

+ 14 - 0
ChangeLog

@@ -1,3 +1,17 @@
+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

+ 1 - 0
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

+ 3 - 4
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

+ 4 - 0
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\&.

+ 6 - 0
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-->

+ 7 - 1
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),

+ 13 - 3
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>

+ 87 - 0
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": []
+  }
+}

+ 7 - 12
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

+ 1 - 80
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",

+ 2 - 2
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()
 

+ 9 - 0
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

+ 14 - 1
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

+ 22 - 1
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

+ 75 - 1
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) {

+ 23 - 0
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");
+
+}
+}

+ 46 - 0
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

+ 60 - 0
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));
 }

+ 498 - 0
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.

+ 35 - 2
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");

+ 5 - 0
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);
     }
 

+ 4 - 2
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)

+ 31 - 0
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;
+}
+
+}

+ 5 - 1
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) {