From: Stephen Morris Date: Tue, 29 Jul 2014 16:08:05 +0000 (+0100) Subject: [3479] Reduce number of messages output during D2 startup and shutdown X-Git-Tag: trac3482_base~66^2~2 X-Git-Url: http://git.ipfire.org/gitweb.cgi?a=commitdiff_plain;h=93847ae6f1e1bbfc2d723b77f2e1bb9a46284783;p=thirdparty%2Fkea.git [3479] Reduce number of messages output during D2 startup and shutdown The messages in question are now output only with logging set to DEBUG: the DHCP-DDNS process now outputs a minimum number of messages by default. --- diff --git a/src/bin/d2/d2_messages.mes b/src/bin/d2/d2_messages.mes index f3c8acaf55..258f97d275 100644 --- a/src/bin/d2/d2_messages.mes +++ b/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 diff --git a/src/bin/d2/d2_process.cc b/src/bin/d2/d2_process.cc index acd58bc814..fba58435f0 100644 --- a/src/bin/d2/d2_process.cc +++ b/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; diff --git a/src/bin/d2/d2_queue_mgr.cc b/src/bin/d2/d2_queue_mgr.cc index 041c2e8912..54c88a0e81 100644 --- a/src/bin/d2/d2_queue_mgr.cc +++ b/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); } diff --git a/src/bin/d2/d_controller.cc b/src/bin/d2/d_controller.cc index 39acdefe04..8bb4d185fd 100644 --- a/src/bin/d2/d_controller.cc +++ b/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; } } diff --git a/src/bin/d2/tests/d2_process_tests.sh.in b/src/bin/d2/tests/d2_process_tests.sh.in index 54ac706906..62cb7c113d 100755 --- a/src/bin/d2/tests/d2_process_tests.sh.in +++ b/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 diff --git a/src/lib/dhcp_ddns/dhcp_ddns_messages.mes b/src/lib/dhcp_ddns/dhcp_ddns_messages.mes index 5cf298e011..eeea3e8631 100644 --- a/src/lib/dhcp_ddns/dhcp_ddns_messages.mes +++ b/src/lib/dhcp_ddns/dhcp_ddns_messages.mes @@ -58,10 +58,12 @@ 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. +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. diff --git a/src/lib/dhcp_ddns/ncr_udp.cc b/src/lib/dhcp_ddns/ncr_udp.cc index 54901f274e..e74c578767 100644 --- a/src/lib/dhcp_ddns/ncr_udp.cc +++ b/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,7 +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) + // 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) .arg(error_code.message()); result = STOPPED; } else {