From: Marcin Siodelski Date: Wed, 2 Sep 2015 11:51:25 +0000 (+0200) Subject: [3970] Added logging traces to the TimerMgr. X-Git-Tag: fd4o6_base~5^2~6 X-Git-Url: http://git.ipfire.org/gitweb/gitweb.cgi?a=commitdiff_plain;h=eb14cfe592a0151bc361b1a1c3c65f8e2c8f7eb0;p=thirdparty%2Fkea.git [3970] Added logging traces to the TimerMgr. --- diff --git a/src/lib/dhcpsrv/dhcpsrv_messages.mes b/src/lib/dhcpsrv/dhcpsrv_messages.mes index e3e887b7fd..c49863c83f 100644 --- a/src/lib/dhcpsrv/dhcpsrv_messages.mes +++ b/src/lib/dhcpsrv/dhcpsrv_messages.mes @@ -527,6 +527,56 @@ lease from the PostgreSQL database for the specified address. A debug message issued when the server is attempting to update IPv6 lease from the PostgreSQL database for the specified address. +% DHCPSRV_TIMERMGR_REGISTER_TIMER registering timer: %1, using interval: %2 ms +A debug message issued when the new interval timer is registered in +the Timer Manager. This timer will have a callback function +associated with it, and this function will be executed according +to the interval specified. The unique name of the timer and the +interval at which the callback function will be executed is +included in the message. + +% DHCPSRV_TIMERMGR_RUN_TIMER_OPERATION running operation for timer: %1 +A debug message issued when the Timer Manager is about to +run a periodic operation associated with the given timer. +An example of such operation is a periodic cleanup of +expired leases. The name of the timer is included in the +message. + +% DHCPSRV_TIMERMGR_START_THREAD starting thread for timers +A debug message issued when the Timer Manager is starting a +worker thread to run started timers. The worker thread is +typically started right after all timers have been registered +and runs until timers need to be reconfigured, e.g. their +interval is changed, new timers are registered or existing +timers are unregistered. + +% DHCPSRV_TIMERMGR_START_TIMER starting timer: %1 +A debug message issued when the registered interval timer is +being started. If this operation is successful the timer will +periodically execute the operation associated with it. The +name of the started timer is included in the message. + +% DHCPSRV_TIMERMGR_STOP_THREAD stopping thread for timers +A debug message issued when the Timer Manager is stopping +the worker thread which executes interval timers. When the +thread is stopped no timers will be executed. The thread is +typically stopped at the server reconfiguration or when the +server shuts down. + +% DHCPSRV_TIMERMGR_STOP_TIMER stopping timer: %1 +A debug message issued when the registered interval timer is +being stopped. The timer remains registered and can be restarted +if necessary. The name of the timer is included in the message. + +% DHCPSRV_TIMERMGR_UNREGISTER_ALL_TIMERS unregistering all timers +A debug message issued when all registered interval timers are +being unregistered from the Timer Manager. + +% DHCPSRV_TIMERMGR_UNREGISTER_TIMER unregistering timer: %1 +A debug message issued when one of the registered interval timers +is unregistered from the Timer Manager. The name of the timer is +included in the message. + % DHCPSRV_UNEXPECTED_NAME database access parameters passed through '%1', expected 'lease-database' The parameters for access the lease database were passed to the server through the named configuration parameter, but the code was expecting them to be diff --git a/src/lib/dhcpsrv/timer_mgr.cc b/src/lib/dhcpsrv/timer_mgr.cc index 1d81e1ccf0..1361b7cc3b 100644 --- a/src/lib/dhcpsrv/timer_mgr.cc +++ b/src/lib/dhcpsrv/timer_mgr.cc @@ -15,6 +15,7 @@ #include #include #include +#include #include #include #include @@ -52,6 +53,11 @@ TimerMgr::registerTimer(const std::string& timer_name, const long interval, const IntervalTimer::Mode& scheduling_mode) { + LOG_DEBUG(dhcpsrv_logger, DHCPSRV_DBG_TRACE, + DHCPSRV_TIMERMGR_REGISTER_TIMER) + .arg(timer_name) + .arg(interval); + // Timer name must not be empty. if (timer_name.empty()) { isc_throw(BadValue, "registered timer name must not be empty"); @@ -91,8 +97,13 @@ TimerMgr::registerTimer(const std::string& timer_name, void TimerMgr::deregisterTimer(const std::string& timer_name) { + + LOG_DEBUG(dhcpsrv_logger, DHCPSRV_DBG_TRACE, + DHCPSRV_TIMERMGR_UNREGISTER_TIMER) + .arg(timer_name); + if (thread_) { - isc_throw(InvalidOperation, "unable to deregister timer " + isc_throw(InvalidOperation, "unable to unregister timer " << timer_name << " while worker thread is running"); } @@ -101,7 +112,7 @@ TimerMgr::deregisterTimer(const std::string& timer_name) { // Check if the timer has been registered. if (timer_info_it == registered_timers_.end()) { - isc_throw(BadValue, "unable to deregister non existing timer '" + isc_throw(BadValue, "unable to unregister non existing timer '" << timer_name << "'"); } @@ -119,6 +130,10 @@ TimerMgr::deregisterTimer(const std::string& timer_name) { void TimerMgr::deregisterTimers() { + + LOG_DEBUG(dhcpsrv_logger, DHCPSRV_DBG_TRACE, + DHCPSRV_TIMERMGR_UNREGISTER_ALL_TIMERS); + // Copy the map holding timers configuration. This is required so as // we don't cut the branch which we're sitting on when we will be // erasing the timers. We're going to iterate over the register timers @@ -139,6 +154,11 @@ TimerMgr::deregisterTimers() { void TimerMgr::setup(const std::string& timer_name) { + + LOG_DEBUG(dhcpsrv_logger, DHCPSRV_DBG_TRACE, + DHCPSRV_TIMERMGR_START_TIMER) + .arg(timer_name); + // Check if the specified timer exists. TimerInfoMap::const_iterator timer_info_it = registered_timers_.find(timer_name); if (timer_info_it == registered_timers_.end()) { @@ -156,6 +176,11 @@ TimerMgr::setup(const std::string& timer_name) { void TimerMgr::cancel(const std::string& timer_name) { + + LOG_DEBUG(dhcpsrv_logger, DHCPSRV_DBG_TRACE, + DHCPSRV_TIMERMGR_STOP_TIMER) + .arg(timer_name); + // Find the timer of our interest. TimerInfoMap::const_iterator timer_info_it = registered_timers_.find(timer_name); if (timer_info_it == registered_timers_.end()) { @@ -172,6 +197,10 @@ void TimerMgr::startThread() { // Do not start the thread if the thread is already there. if (!thread_) { + // Only log it if we really start the thread. + LOG_DEBUG(dhcpsrv_logger, DHCPSRV_DBG_TRACE, + DHCPSRV_TIMERMGR_START_THREAD); + // The thread will simply run IOService::run(), which is a blocking call // to keep running handlers for all timers according to how they have // been scheduled. @@ -183,6 +212,10 @@ void TimerMgr::stopThread() { // If thread is not running, this is no-op. if (thread_) { + // Only log it if we really have something to stop. + LOG_DEBUG(dhcpsrv_logger, DHCPSRV_DBG_TRACE, + DHCPSRV_TIMERMGR_STOP_THREAD); + // Stop the IO Service. This will break the IOService::run executed in the // worker thread. The thread will now terminate. getIOService().post(boost::bind(&IOService::stop, &getIOService())); @@ -249,6 +282,13 @@ TimerMgr::watchSocketCallback(const std::string& timer_name, const bool mark_rea // TimerMgr user to perform custom actions on the expiration of // the given timer. timer_info.watch_socket_->clearReady(); + + // Running user-defined operation for the timer. Logging it + // on the slightly lower debug level as there may be many + // such traces. + LOG_DEBUG(dhcpsrv_logger, DHCPSRV_DBG_TRACE_DETAIL, + DHCPSRV_TIMERMGR_RUN_TIMER_OPERATION) + .arg(timer_name); timer_info.user_callback_(); } }