[trac745] Add mode logging statements

src/lib/nsas/Makefile.am

@@ -26,7 +26,8 @@ nsasdef.h nsasdef.cc: nsasdef.msg
 	$(top_builddir)/src/lib/log/compiler/message nsasdef.msg
 
 lib_LTLIBRARIES = libnsas.la
-libnsas_la_SOURCES  = address_entry.h address_entry.cc
+libnsas_la_SOURCES  = nsasdef.h nsasdef.cc
+libnsas_la_SOURCES += address_entry.h address_entry.cc
 libnsas_la_SOURCES += asiolink.h
 libnsas_la_SOURCES += hash.cc hash.h
 libnsas_la_SOURCES += hash_deleter.h
@@ -35,10 +36,9 @@ libnsas_la_SOURCES += hash_table.h
 libnsas_la_SOURCES += nameserver_address_store.cc nameserver_address_store.h
 libnsas_la_SOURCES += nameserver_address.h nameserver_address.cc
 libnsas_la_SOURCES += nameserver_entry.cc nameserver_entry.h
-libnsas_la_SOURCES += nsasdef.h nsasdef.cc
 libnsas_la_SOURCES += nsas_entry_compare.h
 libnsas_la_SOURCES += nsas_entry.h nsas_types.h
-libnsas_la_SOURCES += nsas_levels.h
+libnsas_la_SOURCES += nsas_log.cc nsas_log.h
 libnsas_la_SOURCES += zone_entry.cc zone_entry.h
 libnsas_la_SOURCES += fetchable.h
 libnsas_la_SOURCES += address_request_callback.h

src/lib/nsas/nameserver_address_store.cc

@@ -33,7 +33,7 @@
 #include "glue_hints.h"
 #include "address_request_callback.h"
 #include "nsasdef.h"
-#include "nsas_levels.h"
+#include "nsas_log.h"
 
 using namespace isc::dns;
 using namespace std;
@@ -41,11 +41,6 @@ using namespace std;
 namespace isc {
 namespace nsas {
 
-// Define logger for messages (local to this file)
-namespace {
-isc::log::Logger logger("nsas");
-}
-
 // Constructor.
 //
 // The LRU lists are set equal to three times the size of the respective
@@ -92,7 +87,7 @@ NameserverAddressStore::lookup(const string& zone, const RRClass& class_code,
     boost::shared_ptr<AddressRequestCallback> callback, AddressFamily family,
     const GlueHints& glue_hints)
 {
-    logger.debug(NSAS_DBG_TRACE, NSAS_LOOKUPZONE, zone.c_str());
+    nsas_logger.debug(NSAS_DBG_TRACE, NSAS_LOOKUPZONE, zone.c_str());
 
     pair<bool, boost::shared_ptr<ZoneEntry> > zone_obj(
         zone_hash_->getOrAdd(HashKey(zone, class_code),
@@ -113,7 +108,7 @@ NameserverAddressStore::cancel(const string& zone,
     const boost::shared_ptr<AddressRequestCallback>& callback,
     AddressFamily family)
 {
-    logger.debug(NSAS_DBG_TRACE, NSAS_LOOKUPCANCEL, zone.c_str());
+    nsas_logger.debug(NSAS_DBG_TRACE, NSAS_LOOKUPCANCEL, zone.c_str());
 
     boost::shared_ptr<ZoneEntry> entry(zone_hash_->get(HashKey(zone,
                                                                class_code)));

src/lib/nsas/nameserver_entry.cc

@@ -40,6 +40,7 @@
 #include "address_entry.h"
 #include "nameserver_address.h"
 #include "nameserver_entry.h"
+#include "nsas_log.h"
 
 using namespace isc::asiolink;
 using namespace isc::nsas;
@@ -178,6 +179,9 @@ NameserverEntry::updateAddressRTTAtIndex(uint32_t rtt, size_t index,
         new_rtt = 1;
     }
     addresses_[family][index].setRTT(new_rtt);
+    nsas_logger.debug(NSAS_DBG_RTT, NSAS_SETRTT,
+                      addresses_[family][index].getAddress().toText().c_str(),
+                      old_rtt, new_rtt);
 }
 
 void
@@ -203,7 +207,7 @@ NameserverEntry::setAddressUnreachable(const IOAddress& address) {
  * \short A callback into the resolver.
  *
  * Whenever we ask the resolver something, this is created and the answer is
- * fed back trough this. It holds a shared pointer to the entry so it is not
+ * fed back through this. It holds a shared pointer to the entry so it is not
  * destroyed too soon.
  */
 class NameserverEntry::ResolverCallback :
@@ -230,6 +234,7 @@ class NameserverEntry::ResolverCallback :
             if (!response_message ||
                 response_message->getRcode() != isc::dns::Rcode::NOERROR() ||
                 response_message->getRRCount(isc::dns::Message::SECTION_ANSWER) == 0) {
+                nsas_logger.error(NSAS_INVRESPSTR, entry_->getName().c_str());
                 failureInternal(lock);
                 return;
             }
@@ -243,7 +248,13 @@ class NameserverEntry::ResolverCallback :
             if (response->getType() != type_ ||
                 response->getClass() != RRClass(entry_->getClass()))
             {
-                // TODO Log we got answer of different type
+                // Invalid response type or class
+                nsas_logger.error(NSAS_INVRESPTC, entry_->getName().c_str(),
+                                  type_.toText().c_str(),
+                                  RRClass(entry_->getClass()).toText().c_str(),
+                                  response->getType().toText().c_str(),
+                                  response->getClass().toText().c_str());
+
                 failureInternal(lock);
                 return;
             }
@@ -264,8 +275,10 @@ class NameserverEntry::ResolverCallback :
                     }
                 }
                 // If we found it, use it. If not, create a new one.
-                entries.push_back(found ? *found : AddressEntry(IOAddress(
-                    i->getCurrent().toText()), 1));
+                entries.push_back(found ? *found : AddressEntry(
+                                                   IOAddress(address), 1));
+                nsas_logger.debug(NSAS_DBG_RESULTS, NSAS_NSLKUPSUCC,
+                                  address.c_str(), entry_->getName().c_str());
             }
 
             // We no longer need the previous set of addresses, we have
@@ -310,6 +323,9 @@ class NameserverEntry::ResolverCallback :
          * So mark the current address family as unreachable.
          */
         virtual void failure() {
+            nsas_logger.debug(NSAS_DBG_RESULTS, NSAS_NSLKUPFAIL,
+                              type_.toText().c_str(),
+                              entry_->getName().c_str());
             Lock lock(entry_->mutex_);
             failureInternal(lock);
         }
@@ -422,6 +438,8 @@ NameserverEntry::askIP(isc::resolve::ResolverInterface* resolver,
         // Ask for both types of addresses
         // We are unlocked here, as the callback from that might want to lock
         lock.unlock();
+
+        nsas_logger.debug(NSAS_DBG_TRACE, NSAS_NSADDR, getName().c_str());
         askIP(resolver, RRType::A(), V4_ONLY);
         askIP(resolver, RRType::AAAA(), V6_ONLY);
         // Make sure we end the routine when we are not locked

src/lib/nsas/nsas_log.h

@@ -12,14 +12,42 @@
 // OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
 // PERFORMANCE OF THIS SOFTWARE.
 
-#ifndef __NSAS_LEVELS_H
-#define __NSAS_LEVELS_H
+#ifndef __NSAS_LOG__H
+#define __NSAS_LOG__H
 
-/// \brief NSAS Debug Levels
+#include <log/logger.h>
+#include "nsasdef.h"
+
+namespace isc {
+namespace nsas {
+
+/// \brief NSAS Logging
 ///
 /// Defines the levels used to output debug messages in the NSAS.  Note that
 /// higher numbers equate to more verbose (and detailed) output.
 
-const int NSAS_DBG_TRACE = 10;  // Trace of normal operations
+// The first level traces normal operations - asking the NSAS for an address,
+// and cancelling a lookup.  It also records when the NSAS calls back to the
+// resolver to resolve something.
+const int NSAS_DBG_TRACE = 10;
+
+// The next level extends the normal operations and records the results of the
+// lookups.
+const int NSAS_DBG_RESULTS = 20;
+
+// Additional information on the usage of the names - the RTT values obtained
+// when queries were done.
+const int NSAS_DBG_RTT = 30;
+
+
+/// \brief NSAS 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 nsas_logger;    // isc::nsas::logger is the NSAS logger
+
+} // namespace nsas
+} // namespace isc
 
-#endif // __NSAS_LEVELS_H
+#endif // __NSAS_LOG__H

src/lib/nsas/nsasdef.msg

@@ -15,10 +15,47 @@
 $PREFIX NSAS_
 $NAMESPACE isc::nsas
 
+INVRESPSTR      queried for %s but got invalid response
++ This message indicates an internal error in the nameserver address store
++ component (NSAS) of the resolver.  The NSAS made a query for a RR for the
++ specified nameserver but received an invalid response.  Either the success
++ function was called without a DNS message or the message was invalid on some
++ way. (In the latter case, the error should have been picked up elsewhere in
++ the processing logic, hence the raising of the error here.)
+
+INVRESPTC       queried for %s RR of type/class %s/%s, received response %s/%s
++ This message indicates an internal error in the nameserver address store
++ component (NSAS) of the resolver.  The NSAS made a query for the given RR
++ type and class, but instead received an answer with the given type and class.
+
 LOOKUPCANCEL    lookup for zone %s has been cancelled
-+ A debug message, this is output when a NSAS lookup for a zone has been
-+ cancelled.
++ A debug message, this is output when a NSAS (nameserver address store -
++ part of the resolver) lookup for a zone has been + cancelled.
 
 LOOKUPZONE      searching NSAS for nameservers for zone %s
-+ A debug message, this is output when a call is made to the NSAS to obtain
-+ the nameservers for the specified zone.
++ A debug message, this is output when a call is made to the nameserver address
++ store (part of the resolver) to obtain the nameservers for the specified zone.
+
+NSADDR          asking resolver to obtain A and AAAA records for %s
++ A debug message, the NSAS (nameserver address store - part of the resolver) is
++ making a callback into the resolver to retrieve the address records for the
++ specified nameserver.
+
+NSLKUPFAIL      failed to lookup any %s for %s
++ A debug message, the NSAS (nameserver address store - part of the resolver)
++ has been unable to retrieve the specified resource record for the specified
++ nameserver.  This is not necessarily a problem - the nameserver may be
++ unreachable, in which case the NSAS will try other nameservers in the zone.
+
+NSLKUPSUCC      found address %s for %s
++ A debug message, the NSAS (nameserver address store - part of the resolver)
++ has retrieved the given address for the specified nameserver through an
++ external query.
+
+SETRTT          reporting RTT for %s as %d; new value is now %d
++ A NSAS (nameserver address store - part of the resolver) debug message
++ reporting the round-trip time (RTT) for a query made to the specified
++ nameserver.  The RTT has been updated using the value given and the new RTT is
++ displayed.  (The RTT is subject to a calculation that damps out sudden
++ changes.  As a result, the new RTT is not necessarily equal to the RTT
++ reported.)