[3852] Added more traces to the Allocation Engine.

src/lib/dhcpsrv/alloc_engine.cc

@@ -501,12 +501,16 @@ AllocEngine::allocateLeases6(ClientContext6& ctx) {
         }
 
         // Unable to allocate an address, return an empty lease.
-        LOG_WARN(alloc_engine_logger, ALLOC_ENGINE_ADDRESS6_ALLOC_FAIL).arg(attempts_);
+        LOG_WARN(alloc_engine_logger, ALLOC_ENGINE_V6_ALLOC_FAIL)
+            .arg(ctx.query_->getLabel())
+            .arg(attempts_);
 
     } catch (const isc::Exception& e) {
 
         // Some other error, return an empty lease.
-        LOG_ERROR(alloc_engine_logger, ALLOC_ENGINE_ADDRESS6_ALLOC_ERROR).arg(e.what());
+        LOG_ERROR(alloc_engine_logger, ALLOC_ENGINE_V6_ALLOC_ERROR)
+            .arg(ctx.query_->getLabel())
+            .arg(e.what());
     }
 
     return (Lease6Collection());
@@ -527,7 +531,7 @@ AllocEngine::allocateUnreservedLeases6(ClientContext6& ctx) {
 
     Lease6Collection leases;
 
-    IOAddress hint("::");
+    IOAddress hint = IOAddress::IPV6_ZERO_ADDRESS();
     if (!ctx.hints_.empty()) {
         /// @todo: We support only one hint for now
         hint = ctx.hints_[0].first;
@@ -571,7 +575,13 @@ AllocEngine::allocateUnreservedLeases6(ClientContext6& ctx) {
                     collection.push_back(lease);
                     return (collection);
                 }
+            } else {
+                LOG_DEBUG(alloc_engine_logger, ALLOC_ENGINE_DBG_TRACE,
+                          ALLOC_ENGINE_V6_HINT_RESERVED)
+                    .arg(ctx.query_->getLabel())
+                    .arg(hint.toText());
             }
+
         } else {
 
             // If the lease is expired, we may likely reuse it, but...
@@ -596,6 +606,12 @@ AllocEngine::allocateUnreservedLeases6(ClientContext6& ctx) {
                     /// @todo: We support only one lease per ia for now
                     leases.push_back(lease);
                     return (leases);
+
+                } else {
+                    LOG_DEBUG(alloc_engine_logger, ALLOC_ENGINE_DBG_TRACE,
+                              ALLOC_ENGINE_V6_EXPIRED_HINT_RESERVED)
+                        .arg(ctx.query_->getLabel())
+                        .arg(hint.toText());
                 }
             }
         }
@@ -684,6 +700,9 @@ AllocEngine::allocateReservedLeases6(ClientContext6& ctx, Lease6Collection& exis
 
     // If there are no reservations or the reservation is v4, there's nothing to do.
     if (!ctx.host_ || !ctx.host_->hasIPv6Reservation()) {
+        LOG_DEBUG(alloc_engine_logger, ALLOC_ENGINE_DBG_TRACE,
+                  ALLOC_ENGINE_V6_ALLOC_NO_V6_HR)
+            .arg(ctx.query_->getLabel());
         return;
     }
 
@@ -692,12 +711,6 @@ AllocEngine::allocateReservedLeases6(ClientContext6& ctx, Lease6Collection& exis
 
     // Get the IPv6 reservations of specified type.
     const IPv6ResrvRange& reservs = ctx.host_->getIPv6Reservations(type);
-
-    if (std::distance(reservs.first, reservs.second) == 0) {
-        // No reservations? We're done here.
-        return;
-    }
-
     for (IPv6ResrvIterator resv = reservs.first; resv != reservs.second; ++resv) {
         // We do have a reservation for addr.
         IOAddress addr = resv->second.getPrefix();
@@ -709,6 +722,11 @@ AllocEngine::allocateReservedLeases6(ClientContext6& ctx, Lease6Collection& exis
 
             // Ok, we already have a lease for this reservation and it's usable
             if (((*l)->addr_ == addr) && (*l)->valid_lft_ != 0) {
+                LOG_DEBUG(alloc_engine_logger, ALLOC_ENGINE_DBG_TRACE,
+                          ALLOC_ENGINE_V6_ALLOC_HR_LEASE_EXISTS)
+                    .arg(ctx.query_->getLabel())
+                    .arg((*l)->typeToText((*l)->type_))
+                    .arg((*l)->addr_.toText());
                 return;
             }
         }
@@ -723,10 +741,10 @@ AllocEngine::allocateReservedLeases6(ClientContext6& ctx, Lease6Collection& exis
             existing_leases.push_back(lease);
 
             if (ctx.type_ == Lease::TYPE_NA) {
-                LOG_INFO(alloc_engine_logger, ALLOC_ENGINE_HR_RESERVED_ADDR_GRANTED)
+                LOG_INFO(alloc_engine_logger, ALLOC_ENGINE_V6_HR_ADDR_GRANTED)
                     .arg(addr.toText()).arg(ctx.duid_->toText());
             } else {
-                LOG_INFO(alloc_engine_logger, ALLOC_ENGINE_HR_RESERVED_PREFIX_GRANTED)
+                LOG_INFO(alloc_engine_logger, ALLOC_ENGINE_V6_HR_PREFIX_GRANTED)
                     .arg(addr.toText()).arg(static_cast<int>(prefix_len))
                     .arg(ctx.duid_->toText());
             }
@@ -776,11 +794,11 @@ AllocEngine::removeNonmatchingReservedLeases6(ClientContext6& ctx,
         // Ok, we have a problem. This host has a lease that is reserved
         // for someone else. We need to recover from this.
         if (ctx.type_ == Lease::TYPE_NA) {
-            LOG_INFO(alloc_engine_logger, ALLOC_ENGINE_HR_REVOKED_ADDR6_LEASE)
+            LOG_INFO(alloc_engine_logger, ALLOC_ENGINE_V6_REVOKED_ADDR_LEASE)
                 .arg((*candidate)->addr_.toText()).arg(ctx.duid_->toText())
                 .arg(host->getIdentifierAsText());
         } else {
-            LOG_INFO(alloc_engine_logger, ALLOC_ENGINE_HR_REVOKED_PREFIX6_LEASE)
+            LOG_INFO(alloc_engine_logger, ALLOC_ENGINE_V6_REVOKED_PREFIX_LEASE)
                 .arg((*candidate)->addr_.toText())
                 .arg(static_cast<int>((*candidate)->prefixlen_))
                 .arg(ctx.duid_->toText())
@@ -897,8 +915,10 @@ AllocEngine::reuseExpiredLease(Lease6Ptr& expired, ClientContext6& ctx,
     expired->fqdn_rev_ = ctx.rev_dns_update_;
     expired->prefixlen_ = prefix_len;
 
-    /// @todo: log here that the lease was reused (there's ticket #2524 for
+    LOG_DEBUG(alloc_engine_logger, ALLOC_ENGINE_DBG_TRACE_DETAIL_DATA,
-    /// logging in libdhcpsrv)
+              ALLOC_ENGINE_V6_REUSE_EXPIRED_LEASE_DATA)
+        .arg(ctx.query_->getLabel())
+        .arg(expired->toText());
 
     // Let's execute all callouts registered for lease6_select
     if (ctx.callout_handle_ &&
@@ -1364,12 +1384,16 @@ AllocEngine::allocateLease4(ClientContext4& ctx) {
         new_lease = ctx.fake_allocation_ ? discoverLease4(ctx) : requestLease4(ctx);
         if (!new_lease) {
             // Unable to allocate an address, return an empty lease.
-            LOG_WARN(alloc_engine_logger, ALLOC_ENGINE_ADDRESS4_ALLOC_FAIL).arg(attempts_);
+            LOG_WARN(alloc_engine_logger, ALLOC_ENGINE_V4_ALLOC_FAIL)
+                .arg(ctx.query_->getLabel())
+                .arg(attempts_);
         }
 
     } catch (const isc::Exception& e) {
         // Some other error, return an empty lease.
-        LOG_ERROR(alloc_engine_logger, ALLOC_ENGINE_ADDRESS4_ALLOC_ERROR).arg(e.what());
+        LOG_ERROR(alloc_engine_logger, ALLOC_ENGINE_V4_ALLOC_ERROR)
+            .arg(ctx.query_->getLabel())
+            .arg(e.what());
     }
 
     return (new_lease);
@@ -1843,8 +1867,10 @@ AllocEngine::reuseExpiredLease4(Lease4Ptr& expired,
     updateLease4Information(expired, ctx);
     expired->fixed_ = false;
 
-    /// @todo: log here that the lease was reused (there's ticket #2524 for
+    LOG_DEBUG(alloc_engine_logger, ALLOC_ENGINE_DBG_TRACE_DETAIL_DATA,
-    /// logging in libdhcpsrv)
+              ALLOC_ENGINE_V4_REUSE_EXPIRED_LEASE_DATA)
+        .arg(ctx.query_->getLabel())
+        .arg(expired->toText());
 
     // Let's execute all callouts registered for lease4_select
     if (ctx.callout_handle_ &&  HooksManager::getHooksManager()

src/lib/dhcpsrv/alloc_engine_messages.mes

@@ -14,12 +14,18 @@
 
 $NAMESPACE isc::dhcp
 
-% ALLOC_ENGINE_ADDRESS4_ALLOC_ERROR error during attempt to allocate an IPv4 address: %1
+% ALLOC_ENGINE_DISCOVER_ADDRESS_CONFLICT conflicting reservation for address %1 with existing lease %2
+This warning message is issued when the DHCP server finds that the
+address reserved for the client can't be offered because this address
+is currently allocated to another client. The server will try to allocate
+a different address to the client to use until the conflict is resolved.
+
+% 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
 return a message to the client refusing a lease.
 
-% ALLOC_ENGINE_ADDRESS4_ALLOC_FAIL failed to allocate an IPv4 address after %1 attempt(s)
+% ALLOC_ENGINE_V4_ALLOC_FAIL %1: failed to allocate an IPv4 address after %2 attempt(s)
 The DHCP allocation engine gave up trying to allocate an IPv4 address
 after the specified number of attempts.  This probably means that the
 address pool from which the allocation is being attempted is either
@@ -34,58 +40,6 @@ consider reducing the lease lifetime.  In this way, addresses allocated
 to clients that are no longer active on the network will become available
 available sooner.
 
-% ALLOC_ENGINE_ADDRESS6_ALLOC_ERROR error during attempt to allocate an IPv6 address: %1
-An error occurred during an attempt to allocate an IPv6 address, the
-reason for the failure being contained in the message.  The server will
-return a message to the client refusing a lease.
-
-% ALLOC_ENGINE_ADDRESS6_ALLOC_FAIL failed to allocate an IPv6 address after %1 attempt(s)
-The DHCP allocation engine gave up trying to allocate an IPv6 address
-after the specified number of attempts.  This probably means that the
-address pool from which the allocation is being attempted is either
-empty, or very nearly empty.  As a result, the client will have been
-refused a lease.
-
-This message may indicate that your address pool is too small for the
-number of clients you are trying to service and should be expanded.
-Alternatively, if the you know that the number of concurrently active
-clients is less than the addresses you have available, you may want to
-consider reducing the lease lifetime.  In this way, addresses allocated
-to clients that are no longer active on the network will become available
-available sooner.
-
-% ALLOC_ENGINE_DISCOVER_ADDRESS_CONFLICT conflicting reservation for address %1 with existing lease %2
-This warning message is issued when the DHCP server finds that the
-address reserved for the client can't be offered because this address
-is currently allocated to another client. The server will try to allocate
-a different address to the client to use until the conflict is resolved.
-
-% ALLOC_ENGINE_HR_RESERVED_ADDR_GRANTED reserved address %1 was was assigned to client (duid=%2)
-This informational message signals that the specified client was assigned the address
-reserved for it.
-
-% ALLOC_ENGINE_HR_RESERVED_PREFIX_GRANTED reserved prefix %1/%2 was was assigned to client (duid=%3)
-This informational message signals that the specified client was assigned the prefix
-reserved for it.
-
-% ALLOC_ENGINE_HR_REVOKED_ADDR6_LEASE address %1 was revoked from client %2 as it is reserved for client %3
-This informational message is an indication that the specified IPv6
-address was used by client A but it is now reserved for client B. Client
-A has been told to stop using it so that it can be leased to client B.
-This is a normal occurrence during conflict resolution, which can occur
-in cases such as the system administrator adding a reservation for an
-address that is currently in use by another client.  The server will fully
-recover from this situation, but clients will change their addresses.
-
-% ALLOC_ENGINE_HR_REVOKED_PREFIX6_LEASE Prefix %1/%2 was revoked from client %3 as it is reserved for client %4
-This informational message is an indication that the specified IPv6
-prefix was used by client A but it is now reserved for client B. Client
-A has been told to stop using it so that it can be leased to client B.
-This is a normal occurrence during conflict resolution, which can occur
-in cases such as the system administrator adding a reservation for an
-address that is currently in use by another client.  The server will fully
-recover from this situation, but clients will change their prefixes.
-
 % ALLOC_ENGINE_V4_DISCOVER_HR %1: client sending DHCPDISCOVER has reservation for the address %2
 This message is issued when the allocation engine determines that the
 client sending the DHCPDISCOVER has a reservation for the specified
@@ -113,7 +67,7 @@ offer lease specified in the hint, because the client doesn't
 have any reservations or the reserved or currently allocated
 address is leased to another client.
 
-% ALLOC_ENGINE_V4_REQUEST_ADDRESS_RESERVED %1: requested address is reserved
+% ALLOC_ENGINE_V4_REQUEST_ADDRESS_RESERVED %1: requested address %2 is reserved
 This message is issued when the allocation engine refused to
 allocate address requested by the client, because this
 address is reserved for another client.
@@ -164,6 +118,36 @@ address and the allocation engine determines that there is a
 reservation for this client. The allocation engine will try to
 allocate the reserved address.
 
+% ALLOC_ENGINE_V4_REUSE_EXPIRED_LEASE_DATA %1: reusing expired lease, updated lease information: %2
+This message is logged when the allocation engine is reusing
+an existing lease. The details of the updated lease are
+printed.
+
+% ALLOC_ENGINE_V6_ALLOC_ERROR %1: error during attempt to allocate an IPv6 address: %2
+An error occurred during an attempt to allocate an IPv6 address, the
+reason for the failure being contained in the message.  The server will
+return a message to the client refusing a lease.
+
+% ALLOC_ENGINE_V6_ALLOC_FAIL %1: failed to allocate an IPv6 address after %2 attempt(s)
+The DHCP allocation engine gave up trying to allocate an IPv6 address
+after the specified number of attempts.  This probably means that the
+address pool from which the allocation is being attempted is either
+empty, or very nearly empty.  As a result, the client will have been
+refused a lease.
+
+This message may indicate that your address pool is too small for the
+number of clients you are trying to service and should be expanded.
+Alternatively, if the you know that the number of concurrently active
+clients is less than the addresses you have available, you may want to
+consider reducing the lease lifetime.  In this way, addresses allocated
+to clients that are no longer active on the network will become available
+available sooner.
+
+% ALLOC_ENGINE_V6_ALLOC_HR_LEASE_EXISTS %1: lease type %2 for reserved address/prefix %3 already exists
+This debug message is issued when the allocation engine determines that
+the lease for the IPv6 address or prefix has already been allocated
+for the client and the client can continue using it.
+
 % ALLOC_ENGINE_V6_ALLOC_LEASES_HR %1: leases and static reservations found for client
 This message is logged when the allocation engine is in the process of
 allocating leases for the client, it found existing leases and static
@@ -180,6 +164,13 @@ for this client, but the client appears to have static reservations.
 The allocation engine will try to allocate the reserved resources for
 the client.
 
+% ALLOC_ENGINE_V6_ALLOC_NO_V6_HR %1: unable to allocate reserved leases - no IPv6 reservations
+This message is logged when the allocation engine determines that the
+client has no IPv6 reservations and thus allocation engine will have
+to try to allocate allocating leases from the dynamic pool or stop
+the allocation process if none leases can be allocated from the
+dynamic pool.
+
 % ALLOC_ENGINE_V6_ALLOC_LEASES_NO_HR %1: no reservations found but leases exist for client
 This message is logged when the allocation engine is in the process if
 allocating leases for the client, there are no static reservations,
@@ -218,6 +209,24 @@ message. Depending on its nature, manual intervention may be required to
 continue processing messages from this particular client; other clients
 will be unaffected.
 
+% ALLOC_ENGINE_V6_EXPIRED_HINT_RESERVED %1: expired lease for the client's hint %2 is reserved for another client
+This message is logged when the allocation engine finds that the
+expired lease for the client's hint can't be reused because it
+is reserved for another client.
+
+% ALLOC_ENGINE_V6_HINT_RESERVED %1: lease for the client's hint %2 is reserved for another client
+This message is logged when the allocation engine cannot allocate
+the lease using the client's hint because the lease for this hint
+is reserved for another client.
+
+% ALLOC_ENGINE_V6_HR_ADDR_GRANTED reserved address %1 was was assigned to client (duid=%2)
+This informational message signals that the specified client was assigned the address
+reserved for it.
+
+% ALLOC_ENGINE_V6_HR_PREFIX_GRANTED reserved prefix %1/%2 was was assigned to client (duid=%3)
+This informational message signals that the specified client was assigned the prefix
+reserved for it.
+
 % ALLOC_ENGINE_V6_RENEW_HR %1: allocating leases reserved for the client as a result of Renew
 This debug message is issued when the allocation engine will try to
 allocate reserved leases for the client sending a Renew message.
@@ -236,3 +245,26 @@ to dynamically allocate new leases for the renewing client. This
 is the case when the server couldn't renew any of the existing
 client's leases, e.g. because leased resources are reserved for
 another client.
+
+% ALLOC_ENGINE_V6_REUSE_EXPIRED_LEASE_DATA %1: reusing expired lease, updated lease information: %2
+This message is logged when the allocation engine is reusing
+an existing lease. The details of the updated lease are
+printed.
+
+% ALLOC_ENGINE_V6_REVOKED_ADDR_LEASE address %1 was revoked from client %2 as it is reserved for client %3
+This informational message is an indication that the specified IPv6
+address was used by client A but it is now reserved for client B. Client
+A has been told to stop using it so that it can be leased to client B.
+This is a normal occurrence during conflict resolution, which can occur
+in cases such as the system administrator adding a reservation for an
+address that is currently in use by another client.  The server will fully
+recover from this situation, but clients will change their addresses.
+
+% ALLOC_ENGINE_V6_REVOKED_PREFIX_LEASE Prefix %1/%2 was revoked from client %3 as it is reserved for client %4
+This informational message is an indication that the specified IPv6
+prefix was used by client A but it is now reserved for client B. Client
+A has been told to stop using it so that it can be leased to client B.
+This is a normal occurrence during conflict resolution, which can occur
+in cases such as the system administrator adding a reservation for an
+address that is currently in use by another client.  The server will fully
+recover from this situation, but clients will change their prefixes.

src/lib/dhcpsrv/tests/alloc_engine6_unittest.cc

@@ -125,12 +125,14 @@ TEST_F(AllocEngine6Test, allocateAddress6Nulls) {
     Lease6Ptr lease;
     AllocEngine::ClientContext6 ctx1(Subnet6Ptr(), duid_, iaid_, IOAddress("::"),
                                      Lease::TYPE_NA, false, false, "", false);
+    ctx1.query_.reset(new Pkt6(DHCPV6_REQUEST, 1234));
     EXPECT_NO_THROW(lease = expectOneLease(engine->allocateLeases6(ctx1)));
     ASSERT_FALSE(lease);
 
     // Allocations without DUID are not allowed either
     AllocEngine::ClientContext6 ctx2(subnet_, DuidPtr(), iaid_, IOAddress("::"),
                                      Lease::TYPE_NA, false, false, "", false);
+    ctx2.query_.reset(new Pkt6(DHCPV6_REQUEST, 1234));
     EXPECT_NO_THROW(lease = expectOneLease(engine->allocateLeases6(ctx2)));
     ASSERT_FALSE(lease);
 }