[trac738] Added final set of messages to b10-auth

src/bin/auth/auth_log.h

@@ -30,9 +30,17 @@ namespace auth {
 // The first level traces start-up, recorded as every components starts.
 const int DBG_AUTH_START = 10;
 
-// This level traces more detailed high-level operations.
+// This level traces more detailed high-level operations (mainly within
+// commands.cc)
 const int DBG_AUTH_OPS = 30;
 
+// Trace detailed operations.  This is the normal debug level when debugging
+// the module.
+const int DBG_AUTH_DETAIL = 50;
+
+// Output detailed messages
+const int DBG_AUTH_MESSAGES = 70;
+
 /// Define the logger for the "auth" module part of b10-auth.  We could define
 /// a logger in each file, but we would want to define a common name to avoid
 /// spelling mistakes, so it is just one small step from there to define a

src/bin/auth/auth_messages.mes

@@ -1,4 +1,4 @@
-# Copyright (C) 2011  Internet Systems Consortium, Inc. ("ISC")
+# 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
@@ -6,7 +6,7 @@
 #
 # 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,
+# 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
@@ -14,8 +14,18 @@
 
 $NAMESPACE isc::auth
 
+% AUTH_AXFR_ERROR error handling AXFR request: %1
+A debug message produced by the authoritative server when it has encountered
+an error processing an AXFR request. The message gives the reason for the
+error and the server will return a SERVFAIL code to the sender.
+
+% AUTH_AXFR_UDP AXFR query received over UDP
+A debug message, output when the authoritative server has received an AXFR
+query over UDP. This is not permitted by the protocol, and the server will
+return a FORMERR error to the sender.
+
 % AUTH_COMMAND_FAILED execution of command '%1' failed: %2
-Execution of the specified command by the authoritative server failed.  The
+Execution of the specified command by the authoritative server failed. The
 message contains the reason for the failure.
 
 % AUTH_CONFIG_CHANNEL_CREATED configuration session channel created
@@ -36,11 +46,25 @@ database has failed, the reason being given in the message. The server will
 continue its initialization although it may not be configured in the desired
 way.
 
-% AUTH_DNSSERVICES_CREATED  DNS services created
+% AUTH_CONFIG_UPDATE_FAIL update of configuration failed: %1
+At attempt to update the configuration the server with information
+from the configuration database has failed, the reason being given in
+the message.
+
+% AUTH_DATA_SOURCE data source database file: %1
+A debug message produced by the authoritative server when it accesses a
+datebase data source, listing the file that is being accessed.
+
+% AUTH_DNSSERVICES_CREATED DNS services created
 A debug message indicating that the component that will handling incoming
 queries for the authoritiative server (DNSServices) has been successfully
 created.
 
+% AUTH_HEADER_PARSE_FAIL unable to parse header in received DNS packet: %1
+A debug message, generated by the authoritative server when an attempt to parse
+the header of a received DNS packet has failed. The reason for the failure is
+given in the message.
+
 % AUTH_LOAD_TSIG loading TSIG keys
 A debug message indicating that the authoritiative server has successfully
 accessed the keyring holding TSIG keys.
@@ -48,30 +72,110 @@ accessed the keyring holding TSIG keys.
 % AUTH_LOAD_ZONE loaded zone %1/%2
 The authoritative server has loaded the named zone of the named class.
 
+% AUTH_MEM_DATASRC_DISABLED memory data source is disabled for class %1
+A debug message reporting that the authoritative server has discovered that
+tge memory data source is disabled for the given class.
+
+% AUTH_MEM_DATASRC_ENABLED memory data source is enabled for class %1
+A debug message reporting that the authoritative server has discovered that
+the memory data source is disabled for the given class.
+
+% AUTH_MESSAGE_PARSE_ERROR unable to parse received DNS packet: %1. Returning SERVFAIL
+A debug message, generated by the authoritative server when an attempt
+to parse a received DNS packet has failed due to something other than
+a protocol error. The reason for the failure is given in the message;
+the server will return a SERVFAIL error code to the sender.
+
+% AUTH_MESSAGE_PROTOCOL_ERROR protocol error in received DNS packet: %1. Returning %2
+A debug message, generated by the authoritative server when an attempt
+to parse a received DNS packet has failed due to a protocol error.
+The reason for the failure is given in the message, as is the error code
+that will be returned to the sender.
+
+% AUTH_MESSAGE_RECEIVED message received:\n%1
+A debug message output by the authoritative server when it receives a valid
+DNS message.
+
+Note: This message includes the packet received, rendered in the form of
+multiple lines of text. For this reason, it is suggested that this log message
+not be routed to the syslog file, where the multiple lines could confuse
+programs that expect a format of one message per line.
+
 % AUTH_NO_STATS_SESSION session interface for statistics is not available
-For some reason, no session to the statistics module is available.  This could
+For some reason, the authoritative server has no session with the statistics
-be an error in configuration.
+module is available. This could be an error in configuration.
+
+% AUTH_NO_XFRIN received NOTIFY but XFRIN session is not running
+This is a debug message produced by the authoritative server when it receives
+a NOTIFY packet but the XFRIN process is not running.  The packet will be
+dropped and nothing returned to the sender.
+
+% AUTH_NOTIFY_RRTYPE invalid question RR type (%1) in incoming NOTIFY
+This debug message is logged by the authoritative server when it receives
+a NOTIFY packet that an RR type of something other than SOA in the
+question section. (The RR type received is included in the message.) The
+server will return a FORMERR error to the sender.
+
+% AUTH_NOTIFY_QUESTIONS invalid number of questions (%1) in incoming NOTIFY
+This debug message is logged by the authoritative server when it receives
+a NOTIFY packet that contains zero or more than one question. (A valid
+NOTIFY packet contains one question.) The server will return a FORMERR
+error to the sender.
+
+% AUTH_PROCESS_FAIL message processing failure: %1
+This message is generated by the authoritative server when it has
+encountered an error whilst processing a received packet: the cause of
+the error is included in the message.
+
+The server will return a SERVFAIL error code to the sender of the packet.
+However, this message indicates a potential error in the server.
+Please open a bug ticket for this issue.
 
 % AUTH_RECEIVED_COMMAND command '%1' received
-A debug message issues when the authoritative server has received a command.
+A debug message issued when the authoritative server has received a command
+on the command channel.
 
 % AUTH_RECEIVED_SENDSTATS command 'sendstats' received
 A debug message issues when the authoritative server has received a command
-from the statistics module to send it the server's statistics data.  The
+from the statistics module to send it the server's statistics data. The
 'sendstats' command is handled differently to other commands, which is why
 the debug message associated with it has its own code.
 
-% AUTH_SERVER_CREATED   server created
+% AUTH_RESPONSE_RECEIVED received response message, ignoring
+A debug message, this is output if the authoritative server receives a DNS
+message with the QR bit set, i.e. a response packet. The server ignores the
+packet as it only response to question packets.
+
+% AUTH_SEND_ERROR_RESPONSE sending an error response (%1 bytes):\n%2
+This is a debug message recording that the authoritative server is sending
+an error response to the originator of the query. A previous message will
+have recorded details of the failure.
+
+Note: This message includes the packet sent, rendered in the form of
+multiple lines of text. For this reason, it is suggested that this log message
+not be routed to the syslog file, where the multiple lines could confuse
+programs that expect a format of one message per line.
+
+% AUTH_SEND_NORMAL_RESPONSE sending an error response (%1 bytes):\n%2
+This is a debug message recording that the authoritative server is sending
+a response to the originator of a query.
+
+Note: This message includes the packet sent, rendered in the form of
+multiple lines of text. For this reason, it is suggested that this log message
+not be routed to the syslog file, where the multiple lines could confuse
+programs that expect a format of one message per line.
+
+% AUTH_SERVER_CREATED  server created
 An informational message indicating that the authoritative server process has
-been created and is initializing.  The AUTH_SERVER_STARTED message will be
+been created and is initializing. The AUTH_SERVER_STARTED message will be
 output when initialization has successfully completed and the server starts
 accepting queries.
 
-% AUTH_SERVER_FAILED   server failed: %1
+% AUTH_SERVER_FAILED  server failed: %1
-The authoritative server has encountered a fatal error and is terminating.  The
+The authoritative server has encountered a fatal error and is terminating. The
 reason for the failure is included in the message.
 
-% AUTH_SERVER_STARTED   server stated
+% AUTH_SERVER_STARTED  server stated
 Initialization of the authoritative server has completed successfully
 and it is entering the main loop, waiting for queries to arrive.
 
@@ -90,14 +194,29 @@ communication over the previously created statistics channel.
 
 % AUTH_STATS_COMMS communication error in sending statistics data: %1
 An error was encountered when the authoritiative server tried to send data
-to the statistics daemon.  The message includes additional information
+to the statistics daemon. The message includes additional information
 describing the reason for the failure.
 
 % AUTH_STATS_TIMEOUT timeout while sending statistics data: %1
 The authoritative server sent data to the statistics daemon but received
-no acknowledgement within the specified time.  The message includes
+no acknowledgement within the specified time. The message includes
 additional information describing the reason for the failure.
 
+% AUTH_STATS_TIMER_DISABLED statistics timer has been disabled
+A debug message indicating that the statistics timer has been disabled in the
+authoritative server and no statistics information is being produced.
+
+% AUTH_STATS_TIMER_SET statistics timer set to %1 second(s)
+A debug message indicating that the statistics timer has been enabled and
+that the authoritative server will produce statistics data at the specified
+interval.
+
+% AUTH_UNSUPPORTED_OPCODE unsupported opcode: %1
+A debug message, produced when a received DNS packet being processed by the
+authoritative server has been found to contain an unsupported opcode. (The
+opcode received is included in the message.) The server will return an
+error code of NOTIMPL to the sender.
+
 % AUTH_XFRIN_CHANNEL_CREATED XFRIN session channel created
 A debug message indicating that the authoritative server has created a channel
 to the XFRIN (Transfer-in) process.
@@ -106,3 +225,16 @@ to the XFRIN (Transfer-in) process.
 A debug message indicating that the authoritative server has established
 communication over the previously-created channel to the XFRIN (Transfer-in)
 process.
+
+% AUTH_ZONEMGR_COMMS error communicating with zone manager: %1
+A debug message output during the processing of a NOTIFY request.
+An error (listed in the message) has been encountered whilst communicating
+with the zone manager.  The NOTIFY request will not be honored.
+
+% AUTH_ZONEMGR_ERROR received error response from zone manager: %1
+A debug message output during the processing of a NOTIFY request.  The zone
+manager component has been informed of the request, but has returned an
+error response (which is included in the message).  The NOTIFY request will
+not be honored.
+
+

src/bin/auth/auth_srv.cc

@@ -59,6 +59,7 @@
 #include <auth/auth_srv.h>
 #include <auth/query.h>
 #include <auth/statistics.h>
+#include <auth/auth_log.h>
 
 using namespace std;
 
@@ -251,7 +252,7 @@ public:
 
 void
 makeErrorMessage(MessagePtr message, OutputBufferPtr buffer,
-                 const Rcode& rcode, const bool verbose_mode,
+                 const Rcode& rcode, const bool&,
                  std::auto_ptr<TSIGContext> tsig_context =
                  std::auto_ptr<TSIGContext>())
 {
@@ -289,11 +290,8 @@ makeErrorMessage(MessagePtr message, OutputBufferPtr buffer,
     } else {
         message->toWire(renderer);
     }
-
+    LOG_DEBUG(auth_logger, DBG_AUTH_MESSAGES, AUTH_SEND_ERROR_RESPONSE)
-    if (verbose_mode) {
+              .arg(message->toText());
-        cerr << "[b10-auth] sending an error response (" <<
-            renderer.getLength() << " bytes):\n" << message->toText() << endl;
-    }
 }
 }
 
@@ -362,15 +360,12 @@ AuthSrv::setMemoryDataSrc(const isc::dns::RRClass& rrclass,
         isc_throw(InvalidParameter,
                   "Memory data source is not supported for RR class "
                   << rrclass);
-    }
+    } else if (!impl_->memory_datasrc_ && memory_datasrc) {
-    if (impl_->verbose_mode_) {
+        LOG_DEBUG(auth_logger, DBG_AUTH_DETAIL, AUTH_MEM_DATASRC_ENABLED)
-        if (!impl_->memory_datasrc_ && memory_datasrc) {
+                  .arg(rrclass);
-            cerr << "[b10-auth] Memory data source is enabled for class "
+    } else if (impl_->memory_datasrc_ && !memory_datasrc) {
-                 << rrclass << endl;
+        LOG_DEBUG(auth_logger, DBG_AUTH_DETAIL, AUTH_MEM_DATASRC_DISABLED)
-        } else if (impl_->memory_datasrc_ && !memory_datasrc) {
+                  .arg(rrclass);
-            cerr << "[b10-auth] Memory data source is disabled for class "
-                 << rrclass << endl;
-        }
     }
     impl_->memory_datasrc_ = memory_datasrc;
 }
@@ -392,18 +387,13 @@ AuthSrv::setStatisticsTimerInterval(uint32_t interval) {
     }
     if (interval == 0) {
         impl_->statistics_timer_.cancel();
+        LOG_DEBUG(auth_logger, DBG_AUTH_OPS, AUTH_STATS_TIMER_DISABLED);
     } else {
         impl_->statistics_timer_.setup(boost::bind(&AuthSrv::submitStatistics,
                                                    this),
                                        interval * 1000);
-    }
+        LOG_DEBUG(auth_logger, DBG_AUTH_OPS, AUTH_STATS_TIMER_SET)
-    if (impl_->verbose_mode_) {
+                  .arg(interval);
-        if (interval == 0) {
-            cerr << "[b10-auth] Disabled statistics timer" << endl;
-        } else {
-            cerr << "[b10-auth] Set statistics timer to " << interval
-                 << " seconds" << endl;
-        }
     }
 }
 
@@ -420,17 +410,13 @@ AuthSrv::processMessage(const IOMessage& io_message, MessagePtr message,
 
         // Ignore all responses.
         if (message->getHeaderFlag(Message::HEADERFLAG_QR)) {
-            if (impl_->verbose_mode_) {
+            LOG_DEBUG(auth_logger, DBG_AUTH_DETAIL, AUTH_RESPONSE_RECEIVED);
-                cerr << "[b10-auth] received unexpected response, ignoring"
-                     << endl;
-            }
             server->resume(false);
             return;
         }
     } catch (const Exception& ex) {
-        if (impl_->verbose_mode_) {
+        LOG_DEBUG(auth_logger, DBG_AUTH_DETAIL, AUTH_HEADER_PARSE_FAIL)
-            cerr << "[b10-auth] DNS packet exception: " << ex.what() << endl;
+                  .arg(ex.what());
-        }
         server->resume(false);
         return;
     }
@@ -439,27 +425,23 @@ AuthSrv::processMessage(const IOMessage& io_message, MessagePtr message,
         // Parse the message.
         message->fromWire(request_buffer);
     } catch (const DNSProtocolError& error) {
-        if (impl_->verbose_mode_) {
+        LOG_DEBUG(auth_logger, DBG_AUTH_DETAIL, AUTH_MESSAGE_PROTOCOL_ERROR)
-            cerr << "[b10-auth] returning " <<  error.getRcode().toText()
+                  .arg(error.getRcode().toText()).arg(error.what());
-                 << ": " << error.what() << endl;
-        }
         makeErrorMessage(message, buffer, error.getRcode(),
                          impl_->verbose_mode_);
         server->resume(true);
         return;
     } catch (const Exception& ex) {
-        if (impl_->verbose_mode_) {
+        LOG_DEBUG(auth_logger, DBG_AUTH_DETAIL, AUTH_MESSAGE_PARSE_ERROR)
-            cerr << "[b10-auth] returning SERVFAIL: " << ex.what() << endl;
+                  .arg(ex.what());
-        }
         makeErrorMessage(message, buffer, Rcode::SERVFAIL(),
                          impl_->verbose_mode_);
         server->resume(true);
         return;
     } // other exceptions will be handled at a higher layer.
 
-    if (impl_->verbose_mode_) {
+    LOG_DEBUG(auth_logger, DBG_AUTH_MESSAGES, AUTH_RESPONSE_RECEIVED)
-        cerr << "[b10-auth] received a message:\n" << message->toText() << endl;
+              .arg(message->toText());
-    }
 
     // Perform further protocol-level validation.
     // TSIG first
@@ -487,9 +469,8 @@ AuthSrv::processMessage(const IOMessage& io_message, MessagePtr message,
         sendAnswer = impl_->processNotify(io_message, message, buffer,
                                           tsig_context);
     } else if (message->getOpcode() != Opcode::QUERY()) {
-        if (impl_->verbose_mode_) {
+        LOG_DEBUG(auth_logger, DBG_AUTH_DETAIL, AUTH_UNSUPPORTED_OPCODE)
-            cerr << "[b10-auth] unsupported opcode" << endl;
+                  .arg(message->getOpcode().toText());
-        }
         makeErrorMessage(message, buffer, Rcode::NOTIMP(),
                          impl_->verbose_mode_, tsig_context);
     } else if (message->getRRCount(Message::SECTION_QUESTION) != 1) {
@@ -550,10 +531,7 @@ AuthSrvImpl::processNormalQuery(const IOMessage& io_message, MessagePtr message,
             data_sources_.doQuery(query);
         }
     } catch (const Exception& ex) {
-        if (verbose_mode_) {
+        LOG_ERROR(auth_logger, AUTH_PROCESS_FAIL).arg(ex.what());
-            cerr << "[b10-auth] Internal error, returning SERVFAIL: " <<
-                ex.what() << endl;
-        }
         makeErrorMessage(message, buffer, Rcode::SERVFAIL(), verbose_mode_);
         return (true);
     }
@@ -567,12 +545,8 @@ AuthSrvImpl::processNormalQuery(const IOMessage& io_message, MessagePtr message,
     } else {
         message->toWire(renderer);
     }
-
+    LOG_DEBUG(auth_logger, DBG_AUTH_MESSAGES, AUTH_SEND_NORMAL_RESPONSE)
-    if (verbose_mode_) {
+              .arg(renderer.getLength()).arg(message->toText());
-        cerr << "[b10-auth] sending a response ("
-             << renderer.getLength()
-             << " bytes):\n" << message->toText() << endl;
-    }
 
     return (true);
 }
@@ -586,9 +560,7 @@ AuthSrvImpl::processAxfrQuery(const IOMessage& io_message, MessagePtr message,
     incCounter(io_message.getSocket().getProtocol());
 
     if (io_message.getSocket().getProtocol() == IPPROTO_UDP) {
-        if (verbose_mode_) {
+        LOG_DEBUG(auth_logger, DBG_AUTH_DETAIL, AUTH_AXFR_UDP);
-            cerr << "[b10-auth] AXFR query over UDP isn't allowed" << endl;
-        }
         makeErrorMessage(message, buffer, Rcode::FORMERR(), verbose_mode_,
                          tsig_context);
         return (true);
@@ -613,10 +585,8 @@ AuthSrvImpl::processAxfrQuery(const IOMessage& io_message, MessagePtr message,
             xfrout_connected_ = false;
         }
 
-        if (verbose_mode_) {
+        LOG_DEBUG(auth_logger, DBG_AUTH_DETAIL, AUTH_AXFR_ERROR)
-            cerr << "[b10-auth] Error in handling XFR request: " << err.what()
+                  .arg(err.what());
-                 << endl;
-        }
         makeErrorMessage(message, buffer, Rcode::SERVFAIL(), verbose_mode_,
                          tsig_context);
         return (true);
@@ -633,20 +603,16 @@ AuthSrvImpl::processNotify(const IOMessage& io_message, MessagePtr message,
     // The incoming notify must contain exactly one question for SOA of the
     // zone name.
     if (message->getRRCount(Message::SECTION_QUESTION) != 1) {
-        if (verbose_mode_) {
+        LOG_DEBUG(auth_logger, DBG_AUTH_OPS, AUTH_NOTIFY_QUESTIONS)
-                cerr << "[b10-auth] invalid number of questions in notify: "
+                  .arg(message->getRRCount(Message::SECTION_QUESTION));
-                     << message->getRRCount(Message::SECTION_QUESTION) << endl;
-        }
         makeErrorMessage(message, buffer, Rcode::FORMERR(), verbose_mode_,
                          tsig_context);
         return (true);
     }
     ConstQuestionPtr question = *message->beginQuestion();
     if (question->getType() != RRType::SOA()) {
-        if (verbose_mode_) {
+        LOG_DEBUG(auth_logger, DBG_AUTH_OPS, AUTH_NOTIFY_RRTYPE)
-                cerr << "[b10-auth] invalid question RR type in notify: "
+                  .arg(question->getType().toText());
-                     << question->getType() << endl;
-        }
         makeErrorMessage(message, buffer, Rcode::FORMERR(), verbose_mode_,
                          tsig_context);
         return (true);
@@ -664,10 +630,7 @@ AuthSrvImpl::processNotify(const IOMessage& io_message, MessagePtr message,
     // silent about such cases, but there doesn't seem to be anything we can
     // improve at the primary server side by sending an error anyway.
     if (xfrin_session_ == NULL) {
-        if (verbose_mode_) {
+        LOG_DEBUG(auth_logger, DBG_AUTH_OPS, AUTH_NO_XFRIN);
-            cerr << "[b10-auth] "
-                "session interface for xfrin is not available" << endl;
-        }
         return (false);
     }
 
@@ -693,16 +656,13 @@ AuthSrvImpl::processNotify(const IOMessage& io_message, MessagePtr message,
         int rcode;
         parsed_answer = parseAnswer(rcode, answer);
         if (rcode != 0) {
-            if (verbose_mode_) {
+            LOG_DEBUG(auth_logger, DBG_AUTH_OPS, AUTH_ZONEMGR_ERROR)
-                cerr << "[b10-auth] failed to notify Zonemgr: "
+                      .arg(parsed_answer->str());
-                     << parsed_answer->str() << endl;
-            }
             return (false);
         }
     } catch (const Exception& ex) {
-        if (verbose_mode_) {
+            LOG_DEBUG(auth_logger, DBG_AUTH_OPS, AUTH_ZONEMGR_COMMS)
-            cerr << "[b10-auth] failed to notify Zonemgr: " << ex.what() << endl;
+                      .arg(ex.what());
-        }
         return (false);
     }
 
@@ -762,10 +722,7 @@ AuthSrvImpl::setDbFile(ConstElementPtr config) {
     } else {
         return (answer);
     }
-
+    LOG_DEBUG(auth_logger, DBG_AUTH_OPS, AUTH_DATA_SOURCE).arg(db_file_);
-    if (verbose_mode_) {
-        cerr << "[b10-auth] Data source database file: " << db_file_ << endl;
-    }
 
     // create SQL data source
     // Note: the following step is tricky to be exception-safe and to ensure
@@ -795,9 +752,7 @@ AuthSrv::updateConfig(ConstElementPtr new_config) {
         }
         return (impl_->setDbFile(new_config));
     } catch (const isc::Exception& error) {
-        if (impl_->verbose_mode_) {
+        LOG_ERROR(auth_logger, AUTH_CONFIG_UPDATE_FAIL).arg(error.what());
-            cerr << "[b10-auth] error: " << error.what() << endl;
-        }
         return (isc::config::createAnswer(1, error.what()));
     }
 }