From: Marcin Siodelski Date: Wed, 9 Sep 2015 13:44:07 +0000 (+0200) Subject: [3973] Added logging to the lease expiration routine. X-Git-Tag: trac4065_base^2~7 X-Git-Url: http://git.ipfire.org/gitweb.cgi?a=commitdiff_plain;h=d9d36098a7832320b9890bc2fc9a20e67192e0bc;p=thirdparty%2Fkea.git [3973] Added logging to the lease expiration routine. Also added better exception handling. --- diff --git a/src/lib/dhcpsrv/alloc_engine.cc b/src/lib/dhcpsrv/alloc_engine.cc index 8afc1182ac..85794e7bc2 100644 --- a/src/lib/dhcpsrv/alloc_engine.cc +++ b/src/lib/dhcpsrv/alloc_engine.cc @@ -26,6 +26,7 @@ #include #include #include +#include #include #include @@ -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 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 hostname_wire; try { + // Create DHCID + std::vector 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 diff --git a/src/lib/dhcpsrv/alloc_engine.h b/src/lib/dhcpsrv/alloc_engine.h index 0bf1db7894..c6c2756c61 100644 --- a/src/lib/dhcpsrv/alloc_engine.h +++ b/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 - void queueNameChangeRequest(const LeasePtrType& lease, - const IdentifierType& identifier) const; + void queueRemovalNameChangeRequest(const LeasePtrType& lease, + const IdentifierType& identifier) const; public: diff --git a/src/lib/dhcpsrv/alloc_engine_messages.mes b/src/lib/dhcpsrv/alloc_engine_messages.mes index 8488c9f69a..6abf3d5d85 100644 --- a/src/lib/dhcpsrv/alloc_engine_messages.mes +++ b/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. diff --git a/src/lib/dhcpsrv/tests/alloc_engine_expiration_unittest.cc b/src/lib/dhcpsrv/tests/alloc_engine_expiration_unittest.cc index b8d8dc8636..4f1aaffa73 100644 --- a/src/lib/dhcpsrv/tests/alloc_engine_expiration_unittest.cc +++ b/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 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