[3970] Added logging traces to the TimerMgr.

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

src/lib/dhcpsrv/timer_mgr.cc

@@ -15,6 +15,7 @@
 #include <asio.hpp>
 #include <asiolink/io_service.h>
 #include <dhcp/iface_mgr.h>
+#include <dhcpsrv/dhcpsrv_log.h>
 #include <dhcpsrv/timer_mgr.h>
 #include <exceptions/exceptions.h>
 #include <boost/bind.hpp>
@@ -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_();
         }
     }