[3973] Added logging to the lease expiration routine.

Also added better exception handling.

src/lib/dhcpsrv/alloc_engine.cc

@@ -26,6 +26,7 @@
 #include <dhcpsrv/lease_mgr_factory.h>
 #include <dhcp/dhcp6.h>
 #include <stats/stats_mgr.h>
+#include <util/stopwatch.h>
 #include <hooks/server_hooks.h>
 #include <hooks/hooks_manager.h>
 
@@ -1280,6 +1281,16 @@ AllocEngine::updateLeaseData(ClientContext6& ctx, const Lease6Collection& leases
 void
 AllocEngine::reclaimExpiredLeases6(const size_t max_leases, const uint16_t timeout,
                                    const bool remove_lease) {
+
+    LOG_DEBUG(alloc_engine_logger, ALLOC_ENGINE_DBG_TRACE,
+              ALLOC_ENGINE_V6_LEASES_RECLAMATION_START)
+        .arg(max_leases)
+        .arg(timeout);
+
+    // Create stopwatch and automatically start it to measure the time
+    // taken by the routine.
+    util::Stopwatch stopwatch;
+
     LeaseMgr& lease_mgr = LeaseMgrFactory::instance();
 
     Lease6Collection leases;
@@ -1288,53 +1299,84 @@ AllocEngine::reclaimExpiredLeases6(const size_t max_leases, const uint16_t timeo
     for (Lease6Collection::const_iterator lease_it = leases.begin();
          lease_it != leases.end(); ++lease_it) {
 
-        /// @todo execute a lease6_expire hook here
+        try {
+            /// @todo execute a lease6_expire hook here.
 
-        /// @todo perform DNS update here
-        queueNameChangeRequest(*lease_it, *(*lease_it)->duid_);
+            // Generate removal name change request for D2, if required.
+            // This will return immediatelly if the DNS wasn't updated
+            // when the lease was created.
+            queueRemovalNameChangeRequest(*lease_it, *(*lease_it)->duid_);
 
-        // Reclaim the lease - depending on the configuration, set the
-        // expired-reclaimed state or simply remove it.
-        if (remove_lease) {
-            LeaseMgrFactory::instance().deleteLease((*lease_it)->addr_);
+            // Reclaim the lease - depending on the configuration, set the
+            // expired-reclaimed state or simply remove it.
+            if (remove_lease) {
+                lease_mgr.deleteLease((*lease_it)->addr_);
 
-        } else {
-            (*lease_it)->state_ = Lease::STATE_EXPIRED_RECLAIMED;
-            LeaseMgrFactory::instance().updateLease6(*lease_it);
+            } else {
+                // Clear FQDN information as we have already sent the
+                // name change request to remove the DNS record.
+                (*lease_it)->hostname_.clear();
+                (*lease_it)->fqdn_fwd_ = false;
+                (*lease_it)->fqdn_rev_ = false;
+                (*lease_it)->state_ = Lease::STATE_EXPIRED_RECLAIMED;
+                lease_mgr.updateLease6(*lease_it);
+            }
+
+            // Lease has been reclaimed.
+            LOG_DEBUG(alloc_engine_logger, ALLOC_ENGINE_DBG_TRACE,
+                      ALLOC_ENGINE_V6_LEASE_RECLAIMED)
+                .arg((*lease_it)->addr_.toText());
+
+        } catch (const std::exception& ex) {
+            LOG_ERROR(alloc_engine_logger, ALLOC_ENGINE_V6_LEASE_RECLAMATION_FAILED)
+                .arg((*lease_it)->addr_.toText())
+                .arg(ex.what());
         }
     }
+
+    // Stop measuring the time.
+    stopwatch.stop();
+
+    // Mark completion of the lease reclamation routine and present some stats.
+    LOG_DEBUG(alloc_engine_logger, ALLOC_ENGINE_DBG_TRACE,
+              ALLOC_ENGINE_V6_LEASES_RECLAMATION_COMPLETE)
+        .arg(leases.size())
+        .arg(stopwatch.logFormatTotalDuration());
 }
 
+
+
 template<typename LeasePtrType, typename IdentifierType>
 void
-AllocEngine::queueNameChangeRequest(const LeasePtrType& lease,
-                                    const IdentifierType& identifier) const {
-
-    if (lease->hostname_.empty() || !lease->fqdn_fwd_ || !lease->fqdn_rev_) {
-        return;
-    }
+AllocEngine::queueRemovalNameChangeRequest(const LeasePtrType& lease,
+                                           const IdentifierType& identifier) const {
 
-    if (!CfgMgr::instance().getD2ClientMgr().ddnsEnabled()) {
+    // Check if there is a need for update.
+    if (!lease || lease->hostname_.empty() || (!lease->fqdn_fwd_ && !lease->fqdn_rev_)
+        || !CfgMgr::instance().getD2ClientMgr().ddnsEnabled()) {
         return;
     }
 
-    std::vector<uint8_t> hostname_wire;
     try {
+        // Create DHCID
+        std::vector<uint8_t> hostname_wire;
         OptionDataTypeUtil::writeFqdn(lease->hostname_, hostname_wire, true);
+        dhcp_ddns::D2Dhcid dhcid = D2Dhcid(identifier, hostname_wire);
 
-    } catch (const std::exception& ex) {
+        // Create name change request.
+        NameChangeRequestPtr ncr(new NameChangeRequest(isc::dhcp_ddns::CHG_REMOVE,
+                                                       lease->fqdn_fwd_, lease->fqdn_rev_,
+                                                       lease->hostname_,
+                                                       lease->addr_.toText(),
+                                                       dhcid, 0, lease->valid_lft_));
+        // Send name change request.
+        CfgMgr::instance().getD2ClientMgr().sendRequest(ncr);
 
+    } catch (const std::exception& ex) {
+        LOG_ERROR(alloc_engine_logger, ALLOC_ENGINE_REMOVAL_NCR_FAILED)
+            .arg(lease->addr_.toText())
+            .arg(ex.what());
     }
-
-    isc::dhcp_ddns::D2Dhcid dhcid(identifier, hostname_wire);
-    NameChangeRequestPtr ncr;
-    ncr.reset(new NameChangeRequest(isc::dhcp_ddns::CHG_REMOVE,
-                                    lease->fqdn_fwd_, lease->fqdn_rev_,
-                                    lease->hostname_,
-                                    lease->addr_.toText(),
-                                    dhcid, 0, lease->valid_lft_));
-
-    CfgMgr::instance().getD2ClientMgr().sendRequest(ncr);
 }
 
 } // end of isc::dhcp namespace

src/lib/dhcpsrv/alloc_engine.h

@@ -678,9 +678,20 @@ private:
     /// @param lease IPv6 lease to be extended.
     void extendLease6(ClientContext6& ctx, Lease6Ptr lease);
 
+    /// @brief Sends removal name change reuqest to D2.
+    ///
+    /// This method is exception safe.
+    ///
+    /// @param lease Pointer to a lease for which NCR should be sent.
+    /// @param identifier Identifier to be used to generate DHCID for
+    /// the DNS update. For DHCPv4 it will be hardware address, client
+    /// identifier. For DHCPv6 it will be a DUID.
+    ///
+    /// @tparam LeasePtrType Pointer to a lease.
+    /// @tparam Identifier HW Address, Client Identifier or DUID.
     template<typename LeasePtrType, typename IdentifierType>
-    void queueNameChangeRequest(const LeasePtrType& lease,
-                                const IdentifierType& identifier) const;
+    void queueRemovalNameChangeRequest(const LeasePtrType& lease,
+                                       const IdentifierType& identifier) const;
 
 public:
 

src/lib/dhcpsrv/alloc_engine_messages.mes

@@ -14,6 +14,14 @@
 
 $NAMESPACE isc::dhcp
 
+% ALLOC_ENGINE_REMOVAL_NCR_FAILED sending removal name change request failed for lease %1: %2
+This error message is logged when sending a removal name change request
+to D2 failed. This name change request is usually generated when the
+lease reclamation routine acts upon expired leases. If a lease being
+reclaimed has a corresponding DNS entry it needs to be removed.
+This message indicates that removal of the DNS entry has failed.
+Nevertheless the lease will be reclaimed. 
+
 % ALLOC_ENGINE_V4_ALLOC_ERROR %1: error during attempt to allocate an IPv4 address: %2
 An error occurred during an attempt to allocate an IPv4 address, the
 reason for the failure being contained in the message.  The server will
@@ -246,6 +254,30 @@ reserved for it.
 This informational message signals that the specified client was assigned the prefix
 reserved for it.
 
+% ALLOC_ENGINE_V6_LEASE_RECLAMATION_FAILED failed to reclaim the lease %1: %2
+This error message is logged when the allocation engine fails to
+reclaim an expired lease. The reason for the failure is included in the
+message. The error may be triggered in the lease expiration hook or
+while performing the operation on the lease database.
+
+% ALLOC_ENGINE_V6_LEASE_RECLAIMED successfully reclaimed IPv6 lease %1
+This debug message is logged when the allocation engine successfully
+reclaims a lease.
+
+% ALLOC_ENGINE_V6_LEASES_RECLAMATION_COMPLETE reclaimed %1 leases in %2
+This debug message is logged when the allocation engine completes
+reclamation of a set of expired leases. The maximum number of leases
+to be reclaimed in a single pass of the lease reclamation routine
+is configurable. However, the number of reclaimed leases may also
+be limited by the timeout value. The message includes the number
+of reclaimed leases and the total time.
+
+% ALLOC_ENGINE_V6_LEASES_RECLAMATION_START starting reclamation of expired leases (limit = %1 leases, timeout = %2 seconds)
+This debug message is issued when the allocation engine starts the
+reclamation of the expired leases. The maximum number of leases to
+be reclaimed and the timeout is included in the message. If any of
+these values is 0, it means "unlimited".
+
 % ALLOC_ENGINE_V6_RENEW_HR allocating leases reserved for the client %1 as a result of Renew
 This debug message is issued when the allocation engine tries to
 allocate reserved leases for the client sending a Renew message.

src/lib/dhcpsrv/tests/alloc_engine_expiration_unittest.cc

@@ -252,10 +252,15 @@ public:
 
     /// @brief Lease algorithm checking if lease state is expired-reclaimed.
     ///
+    /// This algorithm also checks that the FQDN information has been removed
+    /// from the lease.
+    ///
     /// @param lease Pointer to lease.
     /// @return true if lease state is "expired-reclaimed".
     static bool leaseReclaimed(const Lease6Ptr& lease) {
-        return (lease && lease->stateExpiredReclaimed());
+        return (lease && lease->stateExpiredReclaimed() &&
+                lease->hostname_.empty() && !lease->fqdn_fwd_ &&
+                !lease->fqdn_rev_);
     }
 
     /// @brief Lease algorithm checking if lease state is not
@@ -299,6 +304,11 @@ ExpirationAllocEngine6Test::~ExpirationAllocEngine6Test() {
         mgr.stopSender();
         mgr.clearQueue();
     }
+    // Reset configuration. This is important because the CfgMgr is
+    // a singleton and test configuration would affect all subsequent
+    // tests.
+    D2ClientConfigPtr cfg(new D2ClientConfig());
+    mgr.setD2ClientConfig(cfg);
 }
 
 void
@@ -636,6 +646,46 @@ TEST_F(ExpirationAllocEngine6Test, reclaimExpiredLeases6WithDDNSAndLimit) {
     }
 }
 
+// This test verifies that if some leases have invalid hostnames, the
+// lease reclamation routine continues with reclamation of leases anyway.
+TEST_F(ExpirationAllocEngine6Test, reclaimExpiredLeases6InvalidHostname) {
+    boost::scoped_ptr<AllocEngine> engine;
+    ASSERT_NO_THROW(engine.reset(new AllocEngine(AllocEngine::ALLOC_ITERATIVE,
+                                                 100, false)));
+    ASSERT_TRUE(engine);
 
+    // DNS must be started for the D2 client to accept NCRs.
+    ASSERT_NO_THROW(enableDDNS());
+
+    for (size_t i = 0; i < TEST_LEASES_NUM; ++i) {
+        // Generate invalid hostname for every other lease.
+        if (evenLeaseIndex(i)) {
+            // Hostname with two consecutive dots is invalid and may result
+            // in exception if the reclamation routine doesn't protect
+            // aginst such exceptions.
+            std::ostringstream hostname_s;
+            hostname_s << "invalid-host" << i << "..example.com";
+            leases_[i]->hostname_ = hostname_s.str();
+            ASSERT_NO_THROW(LeaseMgrFactory::instance().updateLease6(leases_[i]));
+        }
+        // Every lease is expired.
+        expire(i, 10 + i);
+    }
+
+    // Although we know that some hostnames are broken we don't want the
+    // reclamation process to break when it finds a broken record.
+    // It should rather continue to process other leases.
+    ASSERT_NO_THROW(engine->reclaimExpiredLeases6(0, 0, false));
+
+    // All leases should have been reclaimed. Broken DNS entry doesn't
+    // warrant that we don't reclaim the lease.
+    EXPECT_TRUE(testLeases(&leaseReclaimed, &allLeaseIndexes));
+    // The routine should not generate DNS updates for the leases with broken
+    // hostname.
+    EXPECT_TRUE(testLeases(&dnsUpdateNotGeneratedForLease, &evenLeaseIndex));
+    // But it should generate DNS updates for the leases with the correct
+    // hostname.
+    EXPECT_TRUE(testLeases(&dnsUpdateGeneratedForLease, &oddLeaseIndex));
+}
 
 }; // end of anonymous namespace