[master] Merge branch 'trac3479'

src/bin/d2/d2_messages.mes

@@ -97,14 +97,6 @@ application in standalone mode. This means it will not connected to the Kea
 message queue. Standalone mode is only useful during program development,
 and should not be used in a production environment.
 
-% DCTL_STARTING %1 controller starting, pid: %2
-This is an informational message issued when controller for the
-service first starts.
-
-% DCTL_STOPPING %1 controller is exiting
-This is an informational message issued when the controller is exiting
-following a shut down (normal or otherwise) of the service.
-
 % DHCP_DDNS_ADD_FAILED DHCP_DDNS Transaction outcome: %1
 This is an error message issued after DHCP_DDNS attempts to submit DNS mapping
 entry additions have failed.  The precise reason for the failure should be
@@ -129,19 +121,19 @@ This is an informational message indicating the application has received a signa
 instructing it to reload its configuration from file.
 
 % DHCP_DDNS_CLEARED_FOR_SHUTDOWN application has met shutdown criteria for shutdown type: %1
-This is an informational message issued when the application has been instructed
+This is a debug message issued when the application has been instructed
 to shutdown and has met the required criteria to exit.
 
 % DHCP_DDNS_COMMAND command directive received, command: %1 - args: %2
-This is a debug message issued when the Dhcp-Ddns application command method
+This is a debug message issued when the DHCP-DDNS application command method
 has been invoked.
 
 % DHCP_DDNS_CONFIGURE configuration update received: %1
-This is a debug message issued when the Dhcp-Ddns application configure method
+This is a debug message issued when the DHCP-DDNS application configure method
 has been invoked.
 
 % DHCP_DDNS_FAILED application experienced a fatal error: %1
-This is a debug message issued when the Dhcp-Ddns application encounters an
+This is a debug message issued when the DHCP-DDNS application encounters an
 unrecoverable error from within the event loop.
 
 % DHCP_DDNS_FORWARD_ADD_BAD_DNSCLIENT_STATUS DHCP_DDNS received an unknown DNSClient status: %1, while adding a forward address mapping for FQDN %2 to DNS server %3
@@ -290,8 +282,8 @@ configuration needs to be updated or the source of the FQDN itself should be
 investigated.
 
 % DHCP_DDNS_PROCESS_INIT application init invoked
-This is a debug message issued when the Dhcp-Ddns application enters
-its init method.
+This is a debug message issued when the DHCP-DDNS application enters
+its initialization method.
 
 % DHCP_DDNS_QUEUE_MGR_QUEUE_FULL application request queue has reached maximum number of entries %1
 This an error message indicating that DHCP-DDNS is receiving DNS update
@@ -339,7 +331,7 @@ such as an IP address or port, that are unavailable.  DHCP_DDNS will attempt to
 restart the queue manager if given a new configuration.
 
 % DHCP_DDNS_QUEUE_MGR_STOPPED application's queue manager has stopped listening for requests.
-This is an informational message indicating that DHCP_DDNS's Queue Manager has
+This is a debug message indicating that DHCP_DDNS's Queue Manager has
 stopped listening for NameChangeRequests.  This may be because of normal event
 such as reconfiguration or as a result of an error.  There should be log
 messages preceding this one to indicate why it has stopped.
@@ -440,19 +432,23 @@ DHCP_DDNS receives an update request containing a reverse DNS update.  The
 reverse update will not performed.
 
 % DHCP_DDNS_RUN_ENTER application has entered the event loop
-This is a debug message issued when the Dhcp-Ddns application enters
+This is a debug message issued when the DHCP-DDNS application enters
 its run method.
 
 % DHCP_DDNS_RUN_EXIT application is exiting the event loop
-This is a debug message issued when the Dhcp-Ddns exits the
-in event loop.
+This is a debug message issued when the DHCP-DDNS server exits its
+event lo
 
-% DHCP_DDNS_SHUTDOWN application received shutdown command with args: %1
-This is informational message issued when the application has been instructed
+% DHCP_DDNS_SHUTDOWN DHCP-DDNS has shut down
+This is an informational message indicating that the DHCP-DDNS service
+has shut down.
+
+% DHCP_DDNS_SHUTDOWN_COMMAND application received shutdown command with args: %1
+This is a debug message issued when the application has been instructed
 to shut down by the controller.
 
 % DHCP_DDNS_SHUTDOWN_SIGNAL_RECVD OS signal %1 received, starting shutdown
-This is an informational message indicating the application has received a signal
+This is a debug message indicating the application has received a signal
 instructing it to shutdown.
 
 % DHCP_DDNS_SIGNAL_ERROR signal handler for signal %1, threw an unexpected exception: %2
@@ -461,6 +457,10 @@ error after receiving a signal.  This is a programmatic error and should be
 reported.  While The application will likely continue to operating, it may be
 unable to respond correctly to signals.
 
+% DHCP_DDNS_STARTING DHCP-DDNS starting, pid: %1
+This is an informational message issued when controller for the
+service first starts.
+
 % DHCP_DDNS_STARTING_TRANSACTION Transaction Key: %1
 This is a debug message issued when DHCP-DDNS has begun a transaction for
 a given request.
@@ -478,9 +478,10 @@ likely a programmatic error, rather than a communications issue. Some or all
 of the DNS updates requested as part of this request did not succeed.
 
 % DHCP_DDNS_UNSUPPORTED_SIGNAL ignoring reception of unsupported signal: %1
-This is a debug message indicating that the application received an unsupported
-signal.  This a programmatic error indicating the application has registered to
-receive the signal, but for which no processing logic has been added.
+This is a debug message indicating that the application received an
+unsupported signal.  This is a programming error indicating that the
+application has registered to receive the signal but no associated
+processing logic has been added.
 
 % DHCP_DDNS_UPDATE_REQUEST_SENT %1 for transaction key: %2 to server: %3
 This is a debug message issued when DHCP_DDNS sends a DNS request to a DNS

src/bin/d2/d2_process.cc

@@ -153,7 +153,8 @@ D2Process::canShutdown() const {
         }
 
         if (all_clear) {
-            LOG_INFO(dctl_logger,DHCP_DDNS_CLEARED_FOR_SHUTDOWN)
+            LOG_DEBUG(dctl_logger, DBGLVL_START_SHUT,
+                     DHCP_DDNS_CLEARED_FOR_SHUTDOWN)
                      .arg(getShutdownTypeStr(shutdown_type_));
         }
     }
@@ -163,8 +164,8 @@ D2Process::canShutdown() const {
 
 isc::data::ConstElementPtr
 D2Process::shutdown(isc::data::ConstElementPtr args) {
-    LOG_INFO(dctl_logger, DHCP_DDNS_SHUTDOWN).arg(args ? args->str()
-                                                  : "(no args)");
+    LOG_DEBUG(dctl_logger, DBGLVL_START_SHUT, DHCP_DDNS_SHUTDOWN_COMMAND)
+              .arg(args ? args->str() : "(no arguments)");
 
     // Default shutdown type is normal.
     std::string type_str(getShutdownTypeStr(SD_NORMAL));
@@ -242,9 +243,10 @@ D2Process::checkQueueStatus() {
             // canceling active listening which may generate an IO event, so
             // instigate the stop and get out.
             try {
-                LOG_INFO(dctl_logger, DHCP_DDNS_QUEUE_MGR_STOPPING)
+                LOG_DEBUG(dctl_logger, DBGLVL_START_SHUT,
+                          DHCP_DDNS_QUEUE_MGR_STOPPING)
                          .arg(reconf_queue_flag_ ? "reconfiguration"
-                                                   : "shutdown");
+                                                 : "shutdown");
                 queue_mgr_->stopListening();
             } catch (const isc::Exception& ex) {
                 // It is very unlikey that we would experience an error
@@ -301,7 +303,8 @@ D2Process::checkQueueStatus() {
         // we can do the reconfigure. In other words, we aren't RUNNING or
         // STOPPING.
         if (reconf_queue_flag_) {
-            LOG_INFO (dctl_logger, DHCP_DDNS_QUEUE_MGR_RECONFIGURING);
+            LOG_DEBUG(dctl_logger, DBGLVL_TRACE_BASIC,
+                      DHCP_DDNS_QUEUE_MGR_RECONFIGURING);
             reconfigureQueueMgr();
         }
         break;

src/bin/d2/d2_queue_mgr.cc

@@ -1,4 +1,4 @@
-// Copyright (C) 2013 Internet Systems Consortium, Inc. ("ISC")
+// Copyright (C) 2013-2014 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
@@ -139,7 +139,7 @@ D2QueueMgr::startListening() {
                   << ex.what());
     }
 
-    LOG_INFO (dctl_logger, DHCP_DDNS_QUEUE_MGR_STARTED);
+    LOG_DEBUG(dctl_logger, DBGLVL_START_SHUT, DHCP_DDNS_QUEUE_MGR_STARTED);
 }
 
 void
@@ -174,7 +174,7 @@ D2QueueMgr::stopListening(const State target_stop_state) {
 void
 D2QueueMgr::updateStopState() {
     mgr_state_ = target_stop_state_;
-    LOG_INFO (dctl_logger, DHCP_DDNS_QUEUE_MGR_STOPPED);
+    LOG_DEBUG(dctl_logger, DBGLVL_TRACE_BASIC, DHCP_DDNS_QUEUE_MGR_STOPPED);
 }
 
 

src/bin/d2/d_controller.cc

@@ -64,8 +64,10 @@ DControllerBase::launch(int argc, char* argv[], const bool test_mode) {
         Daemon::loggerInit(bin_name_.c_str(), verbose_);
     }
 
-    LOG_DEBUG(dctl_logger, DBGLVL_START_SHUT, DCTL_STARTING)
-              .arg(app_name_).arg(getpid());
+    // Log the starting of the service.  Although this is the controller
+    // module, use a "DHCP_DDNS_" prefix to the module (to conform to the
+    // principle of least astonishment).
+    LOG_INFO(dctl_logger, DHCP_DDNS_STARTING).arg(getpid());
     try {
         // Step 2 is to create and initialize the application process object.
         initProcess();
@@ -115,8 +117,9 @@ DControllerBase::launch(int argc, char* argv[], const bool test_mode) {
                    "Application process event loop failed: " << ex.what());
     }
 
-    // All done, so bail out.
-    LOG_INFO(dctl_logger, DCTL_STOPPING).arg(app_name_);
+    // All done, so bail out.  Log the event (using a DHCP_DDNS_ prefix
+    // for the same reason as used for DHCP_DDNS_STARTING).
+    LOG_INFO(dctl_logger, DHCP_DDNS_SHUTDOWN);
 }
 
 void
@@ -362,16 +365,15 @@ DControllerBase::processSignal(int signum) {
         case SIGINT:
         case SIGTERM:
         {
-            LOG_INFO(dctl_logger, DHCP_DDNS_SHUTDOWN_SIGNAL_RECVD)
-                     .arg(signum);
+            LOG_DEBUG(dctl_logger, DBGLVL_START_SHUT,
+                      DHCP_DDNS_SHUTDOWN_SIGNAL_RECVD).arg(signum);
             isc::data::ElementPtr arg_set;
             executeCommand(SHUT_DOWN_COMMAND, arg_set);
             break;
         }
 
         default:
-            LOG_DEBUG(dctl_logger, DBGLVL_START_SHUT,
-                      DHCP_DDNS_UNSUPPORTED_SIGNAL).arg(signum);
+            LOG_WARN(dctl_logger, DHCP_DDNS_UNSUPPORTED_SIGNAL).arg(signum);
             break;
     }
 }

src/bin/d2/tests/d2_process_tests.sh.in

@@ -190,24 +190,10 @@ shutdown_test() {
     # Send signal to D2 (SIGTERM, SIGINT etc.)
     send_signal ${signum} ${bin}
 
-    # Wait up to 10s for the D2Controller to log shutdown received.
-    wait_for_message 10 "DHCP_DDNS_SHUTDOWN_SIGNAL_RECVD" 1
+    # Now wait for process to log that it is exiting.
+    wait_for_message 10 "DHCP_DDNS_SHUTDOWN" 1
     if [ ${_WAIT_FOR_MESSAGE} -eq 0 ]; then
-        printf "ERROR: D2Process did report the shutdown signal receipt.\n"
-        clean_exit 1
-    fi
-
-    # Wait up to 10s for the D2Process to log graceful shutdown.
-    wait_for_message 10 "DHCP_DDNS_CLEARED_FOR_SHUTDOWN" 1
-    if [ ${_WAIT_FOR_MESSAGE} -eq 0 ]; then
-        printf "ERROR: D2Process did not log orderly shutdown.\n"
-        clean_exit 1
-    fi
-
-    # Now wait for D2Controller to log that it is exiting.
-    wait_for_message 10 "DCTL_STOPPING" 1
-    if [ ${_WAIT_FOR_MESSAGE} -eq 0 ]; then
-        printf "ERROR: D2Controller did not log shutdown.\n"
+        printf "ERROR: DHCP-DDNS did not log shutdown.\n"
         clean_exit 1
     fi
 

src/bin/keactrl/tests/keactrl_tests.sh.in

@@ -136,7 +136,7 @@ Expected wait_for_message return %d, returned %d."
     assert_eq 0 ${_GET_LOG_MESSAGES} \
         "Expected get_log_messages return %d, returned %d."
 
-    get_log_messages "DCTL_STARTING"
+    get_log_messages "DCTL_STANDALONE"
     assert_eq 0 ${_GET_LOG_MESSAGES} \
         "Expected get_log_messages return %d, returned %d."
 
@@ -176,7 +176,7 @@ Expected wait_for_message return %d, returned %d."
 Expected wait_for_message return %d, returned %d."
 
     # Wait up to 10s for the D2 server to stop.
-    wait_for_message 10 "DCTL_STOPPING" 1
+    wait_for_message 10 "DHCP_DDNS_SHUTDOWN" 1
     assert_eq 1 ${_WAIT_FOR_MESSAGE} \
         "Timeout waiting for ${d2_name} to shutdown. \
 Expected wait_for_message return %d, returned %d."
@@ -240,9 +240,9 @@ Expected wait_for_message return %d, returned %d."
     assert_eq 1 ${_GET_LOG_MESSAGES} \
         "Expected get_log_messages for DHCP4_START_INFO return %d, returned %d."
 
-    get_log_messages "DCTL_STARTING" 1
+    get_log_messages "DCTL_STANDALONE" 1
     assert_eq 1 ${_GET_LOG_MESSAGES} \
-        "Expected get_log_messages for DCTL_STARTING return %d, returned %d."
+        "Expected get_log_messages for DCT_STANDALONE return %d, returned %d."
 
     # Server may shut down imediatelly after configuration has competed.
     # Give it some time to shutdown.
@@ -280,7 +280,7 @@ Expected wait_for_message return %d, returned %d."
 Expected wait_for_message return %d, returned %d."
 
     # Wait up to 10s for the D2 server to stop.
-    wait_for_message 10 "DCTL_STOPPING" 1
+    wait_for_message 10 "DHCP_DDNS_SHUTDOWN" 1
     assert_eq 1 ${_WAIT_FOR_MESSAGE} \
         "Timeout waiting for ${d2_name} to shutdown. \
 Expected wait_for_message return %d, returned %d."
@@ -592,7 +592,7 @@ Expected wait_for_message return %d, returned %d."
 Expected wait_for_message return %d, returned %d."
 
     # Wait up to 10s for the D2 server to stop.
-    wait_for_message 10 "DCTL_STOPPING" 1
+    wait_for_message 10 "DHCP_DDNS_SHUTDOWN" 1
     assert_eq 1 ${_WAIT_FOR_MESSAGE} \
         "Timeout waiting for ${d2_name} to shutdown. \
 Expected wait_for_message return %d, returned %d."
@@ -746,7 +746,7 @@ Expected wait_for_message return %d, returned %d."
 Expected wait_for_message return %d, returned %d."
 
     # Wait up to 10s for the d2 server to stop.
-    wait_for_message 10 "DCTL_STOPPING" 1
+    wait_for_message 10 "DHCP_DDNS_SHUTDOWN" 1
     assert_eq 1 ${_WAIT_FOR_MESSAGE} \
         "Timeout waiting for ${d2_name} to shutdown. \
 Expected wait_for_message return %d, returned %d."
@@ -808,9 +808,9 @@ Expected wait_for_message return %d, returned %d."
     assert_eq 0 ${_GET_LOG_MESSAGES} \
         "Expected get_log_messages return %d, returned %d."
 
-    get_log_messages "DCTL_STARTING"
+    get_log_messages "DCTL_STANDALONE"
     assert_eq 0 ${_GET_LOG_MESSAGES} \
-        "Expected get_log_messages return %d, returned %d."
+    "Expected get_log_messages return %d, returned %d."
 
     # Server may shut down imediatelly after configuration has competed.
     # Give it some time to shutdown.
@@ -885,7 +885,7 @@ Expected wait_for_message return %d, returned %d."
     assert_eq 0 ${ret} "Expected keactrl to return %d, returned value was %d."
 
     # Wait up to 10s for the D2 server to stop.
-    wait_for_message 10 "DCTL_STOPPING" 1
+    wait_for_message 10 "DHCP_DDNS_SHUTDOWN" 1
     assert_eq 1 ${_WAIT_FOR_MESSAGE} \
         "Timeout waiting for ${d2_name} to shutdown. \
 Expected wait_for_message return %d, returned %d."

src/lib/dhcp_ddns/dhcp_ddns_messages.mes

@@ -57,11 +57,13 @@ UDP NCR sender ready status after completing a send.  This is programmatic error
 that should be reported.  The application may or may not continue to operate
 correctly.
 
-% DHCP_DDNS_NCR_UDP_RECV_CANCELED UDP socket receive was canceled while listening for DNS Update requests: %1
-This is an informational  message indicating that the listening over a UDP socket for DNS update requests has been canceled.  This is a normal part of suspending listening operations.
+% DHCP_DDNS_NCR_UDP_RECV_CANCELED UDP socket receive was canceled while listening for DNS Update requests
+This is a debug  message indicating that the listening on a UDP socket
+for DNS update requests has been canceled.  This is a normal part of
+suspending listening operations.
 
 % DHCP_DDNS_NCR_UDP_RECV_ERROR UDP socket receive error while listening for DNS Update requests: %1
-This is an error message indicating that an IO error occurred while listening
+This is an error message indicating that an I/O error occurred while listening
 over a UDP socket for DNS update requests. This could indicate a network
 connectivity or system resource issue.
 

src/lib/dhcp_ddns/ncr_udp.cc

@@ -172,7 +172,7 @@ NameChangeUDPListener::receiveCompletionHandler(const bool successful,
             // log it and go back to listening
             LOG_ERROR(dhcp_ddns_logger, DHCP_DDNS_INVALID_NCR).arg(ex.what());
 
-            // Queue up the next recieve.
+            // Queue up the next receive.
             // NOTE: We must call the base class, NEVER doReceive
             receiveNext();
             return;
@@ -180,8 +180,10 @@ NameChangeUDPListener::receiveCompletionHandler(const bool successful,
     } else {
         asio::error_code error_code = callback->getErrorCode();
         if (error_code.value() == asio::error::operation_aborted) {
-            LOG_INFO(dhcp_ddns_logger, DHCP_DDNS_NCR_UDP_RECV_CANCELED)
-                     .arg(error_code.message());
+            // A shutdown cancels all outstanding reads.  For this reason,
+            // it can be an expected event, so log it as a debug message.
+            LOG_DEBUG(dhcp_ddns_logger, DBGLVL_TRACE_BASIC,
+                      DHCP_DDNS_NCR_UDP_RECV_CANCELED);
             result = STOPPED;
         } else {
             LOG_ERROR(dhcp_ddns_logger, DHCP_DDNS_NCR_UDP_RECV_ERROR)