[#1701] Improved v4 alloc failure logs

In case of lease allocation failure, the allocation engine now logs:
- which shared network the client belongs to
- which subnet (if not shared network) the client belongs to
- which subnets were tried
- for which subnets there were allocation attempts
- for which subnets there were no allocation attempts

diff --git a/src/lib/dhcpsrv/alloc_engine.cc b/src/lib/dhcpsrv/alloc_engine.cc
index d7ecb0925cc155ec6e36c33e602582ead471945b..fcd7297ca8fe53816eec46d4194384e70205e8dd 100644 (file)
--- a/src/lib/dhcpsrv/alloc_engine.cc
+++ b/src/lib/dhcpsrv/alloc_engine.cc
@@ -36,6 +36,7 @@
 #include <algorithm>
 #include <cstring>
 #include <limits>
+#include <list>
 #include <sstream>
 #include <stdint.h>
 #include <string.h>
@@ -4196,8 +4197,19 @@ AllocEngine::allocateUnreservedLease4(ClientContext4& ctx) {
     Subnet4Ptr original_subnet = subnet;
 
     uint64_t total_attempts = 0;
-    while (subnet) {
 
+    // subnets_tried tracks the ids of the subnets for which the allocation engine
+    // has made an attempt to allocate a lease. The first value of the pair is a
+    // subnet id. The second value in the pair is a pool capacity provided the
+    // client belongs to certain classes. The value of 0 indicates that no pool
+    // had any addresses available for that client. Other value indicates that
+    // a number of attempts were made but no address could be assigned because
+    // the addresses were either reserved to other clients or there were valid
+    // leases for these addresses. Based on this information we will be able to
+    // produce a meaningful log message to an operator.
+    std::list<std::pair<uint32_t, uint64_t> > subnets_tried;
+
+    while (subnet) {
         ClientIdPtr client_id;
         if (subnet->getMatchClientId()) {
             client_id = ctx.clientid_;
@@ -4212,6 +4224,10 @@ AllocEngine::allocateUnreservedLease4(ClientContext4& ctx) {
             max_attempts = 0;
         }
 
+        // Remember an id of the current subnet and how many leases are potentially
+        // available for this client.
+        subnets_tried.push_back(std::make_pair(subnet->getID(), max_attempts));
+
         CalloutHandle::CalloutNextStep callout_status = CalloutHandle::NEXT_STEP_CONTINUE;
 
         for (uint64_t i = 0; i < max_attempts; ++i) {
@@ -4276,10 +4292,56 @@ AllocEngine::allocateUnreservedLease4(ClientContext4& ctx) {
         }
     }
 
-    // Unable to allocate an address, return an empty lease.
-    LOG_WARN(alloc_engine_logger, ALLOC_ENGINE_V4_ALLOC_FAIL)
-        .arg(ctx.query_->getLabel())
-        .arg(total_attempts);
+    if (network) {
+        // The client is in the shared network. Let's log the high level message
+        // indicating which shared network the client belongs to.
+        LOG_WARN(alloc_engine_logger, ALLOC_ENGINE_V4_ALLOC_FAIL_SHARED_NETWORK)
+            .arg(ctx.query_->getLabel())
+            .arg(network->getName());
+
+        // The allocation engine could have tried several subnets in this shared
+        // network. We want to log which subnets it tried to use.
+        for (auto subnet_tried : subnets_tried) {
+            // If the allocation engine tried allocate any addresses in this subnet
+            // we want to indicate that the failure was related to a problem with
+            // allocations rather than with access to the address pools. Otherwise,
+            // we want to log that there were zero attempts to allocate a lease,
+            // which is likely because address pools were guarded by the client
+            // classes that the client did not belong to.
+            if (subnet_tried.second > 0) {
+                LOG_WARN(alloc_engine_logger, ALLOC_ENGINE_V4_ALLOC_FAIL_SUBNET_TRIED)
+                    .arg(ctx.query_->getLabel())
+                    .arg(subnet_tried.first);
+            } else {
+                LOG_WARN(alloc_engine_logger, ALLOC_ENGINE_V4_ALLOC_FAIL_SUBNET_POOLS_UNAVAIL)
+                    .arg(ctx.query_->getLabel())
+                    .arg(subnet_tried.first);
+            }
+        }
+
+    } else {
+        // The client is not connected to a shared network. It is connected
+        // to a subnet. Let's log the ID of that subnet.
+        LOG_WARN(alloc_engine_logger, ALLOC_ENGINE_V4_ALLOC_FAIL_SUBNET)
+            .arg(ctx.query_->getLabel())
+            .arg(ctx.subnet_->getID());
+    }
+    if (total_attempts == 0) {
+        // In this case, it seems that none of the pools in the subnets could
+        // be used for that client, both in case the client is connected to
+        // a shared network or to a single subnet. Apparently, the client was
+        // rejected to use the pools because of the client classes' mismatch.
+        LOG_WARN(alloc_engine_logger, ALLOC_ENGINE_V4_ALLOC_FAIL_NO_POOLS)
+            .arg(ctx.query_->getLabel());
+    } else {
+        // This is an old log message which provides a number of attempts
+        // made by the allocation engine to allocate a lease. The only case
+        // when we don't want to log this message is when the number of
+        // attempts is zero (condition above), because it would look silly.
+        LOG_WARN(alloc_engine_logger, ALLOC_ENGINE_V4_ALLOC_FAIL)
+            .arg(ctx.query_->getLabel())
+            .arg(total_attempts);
+    }
 
     const ClientClasses& classes = ctx.query_->getClasses();
     if (!classes.empty()) {

diff --git a/src/lib/dhcpsrv/alloc_engine_messages.cc b/src/lib/dhcpsrv/alloc_engine_messages.cc
index f2fcb1f332256344d2061ac18e51c6cd65722940..44b4f95e90c32c925bb7bb6b9341160aa79cbeeb 100644 (file)
--- a/src/lib/dhcpsrv/alloc_engine_messages.cc
+++ b/src/lib/dhcpsrv/alloc_engine_messages.cc
@@ -12,6 +12,11 @@ extern const isc::log::MessageID ALLOC_ENGINE_REMOVAL_NCR_FAILED = "ALLOC_ENGINE
 extern const isc::log::MessageID ALLOC_ENGINE_V4_ALLOC_ERROR = "ALLOC_ENGINE_V4_ALLOC_ERROR";
 extern const isc::log::MessageID ALLOC_ENGINE_V4_ALLOC_FAIL = "ALLOC_ENGINE_V4_ALLOC_FAIL";
 extern const isc::log::MessageID ALLOC_ENGINE_V4_ALLOC_FAIL_CLASSES = "ALLOC_ENGINE_V4_ALLOC_FAIL_CLASSES";
+extern const isc::log::MessageID ALLOC_ENGINE_V4_ALLOC_FAIL_NO_POOLS = "ALLOC_ENGINE_V4_ALLOC_FAIL_NO_POOLS";
+extern const isc::log::MessageID ALLOC_ENGINE_V4_ALLOC_FAIL_SHARED_NETWORK = "ALLOC_ENGINE_V4_ALLOC_FAIL_SHARED_NETWORK";
+extern const isc::log::MessageID ALLOC_ENGINE_V4_ALLOC_FAIL_SUBNET = "ALLOC_ENGINE_V4_ALLOC_FAIL_SUBNET";
+extern const isc::log::MessageID ALLOC_ENGINE_V4_ALLOC_FAIL_SUBNET_POOLS_UNAVAIL = "ALLOC_ENGINE_V4_ALLOC_FAIL_SUBNET_POOLS_UNAVAIL";
+extern const isc::log::MessageID ALLOC_ENGINE_V4_ALLOC_FAIL_SUBNET_TRIED = "ALLOC_ENGINE_V4_ALLOC_FAIL_SUBNET_TRIED";
 extern const isc::log::MessageID ALLOC_ENGINE_V4_DECLINED_RECOVERED = "ALLOC_ENGINE_V4_DECLINED_RECOVERED";
 extern const isc::log::MessageID ALLOC_ENGINE_V4_DISCOVER_ADDRESS_CONFLICT = "ALLOC_ENGINE_V4_DISCOVER_ADDRESS_CONFLICT";
 extern const isc::log::MessageID ALLOC_ENGINE_V4_DISCOVER_HR = "ALLOC_ENGINE_V4_DISCOVER_HR";
@@ -86,6 +91,11 @@ const char* values[] = {
     "ALLOC_ENGINE_V4_ALLOC_ERROR", "%1: error during attempt to allocate an IPv4 address: %2",
     "ALLOC_ENGINE_V4_ALLOC_FAIL", "%1: failed to allocate an IPv4 address after %2 attempt(s)",
     "ALLOC_ENGINE_V4_ALLOC_FAIL_CLASSES", "%1: Failed to allocate an IPv4 address for client with classes: %2",
+    "ALLOC_ENGINE_V4_ALLOC_FAIL_NO_POOLS", "%1: no pools were available for the address allocation",
+    "ALLOC_ENGINE_V4_ALLOC_FAIL_SHARED_NETWORK", "%1: failed to allocate an IPv4 address in the shared network %2",
+    "ALLOC_ENGINE_V4_ALLOC_FAIL_SUBNET", "%1: failed to allocate an IPv4 address in the subnet with id %2",
+    "ALLOC_ENGINE_V4_ALLOC_FAIL_SUBNET_POOLS_UNAVAIL", "%1: no suitable pools found in the subnet with id %2",
+    "ALLOC_ENGINE_V4_ALLOC_FAIL_SUBNET_TRIED", "%1: no available leases found in the subnet with id %2",
     "ALLOC_ENGINE_V4_DECLINED_RECOVERED", "IPv4 address %1 was recovered after %2 seconds of probation-period",
     "ALLOC_ENGINE_V4_DISCOVER_ADDRESS_CONFLICT", "%1: conflicting reservation for address %2 with existing lease %3",
     "ALLOC_ENGINE_V4_DISCOVER_HR", "client %1 sending DHCPDISCOVER has reservation for the address %2",

diff --git a/src/lib/dhcpsrv/alloc_engine_messages.h b/src/lib/dhcpsrv/alloc_engine_messages.h
index 0d9389b826852fb6008dd26b6b8c8dd20466e69d..b142fad9cf048eb0e2f027dacd043730d5d8e2a2 100644 (file)
--- a/src/lib/dhcpsrv/alloc_engine_messages.h
+++ b/src/lib/dhcpsrv/alloc_engine_messages.h
@@ -13,6 +13,11 @@ extern const isc::log::MessageID ALLOC_ENGINE_REMOVAL_NCR_FAILED;
 extern const isc::log::MessageID ALLOC_ENGINE_V4_ALLOC_ERROR;
 extern const isc::log::MessageID ALLOC_ENGINE_V4_ALLOC_FAIL;
 extern const isc::log::MessageID ALLOC_ENGINE_V4_ALLOC_FAIL_CLASSES;
+extern const isc::log::MessageID ALLOC_ENGINE_V4_ALLOC_FAIL_NO_POOLS;
+extern const isc::log::MessageID ALLOC_ENGINE_V4_ALLOC_FAIL_SHARED_NETWORK;
+extern const isc::log::MessageID ALLOC_ENGINE_V4_ALLOC_FAIL_SUBNET;
+extern const isc::log::MessageID ALLOC_ENGINE_V4_ALLOC_FAIL_SUBNET_POOLS_UNAVAIL;
+extern const isc::log::MessageID ALLOC_ENGINE_V4_ALLOC_FAIL_SUBNET_TRIED;
 extern const isc::log::MessageID ALLOC_ENGINE_V4_DECLINED_RECOVERED;
 extern const isc::log::MessageID ALLOC_ENGINE_V4_DISCOVER_ADDRESS_CONFLICT;
 extern const isc::log::MessageID ALLOC_ENGINE_V4_DISCOVER_HR;

diff --git a/src/lib/dhcpsrv/alloc_engine_messages.mes b/src/lib/dhcpsrv/alloc_engine_messages.mes
index 595fe4b109fb6f9ce823e3e9ddf0beb1504de2e6..3e0488a3dcfc8831152d92bce77ff398858b3b50 100644 (file)
--- a/src/lib/dhcpsrv/alloc_engine_messages.mes
+++ b/src/lib/dhcpsrv/alloc_engine_messages.mes
@@ -25,12 +25,12 @@ return a message to the client refusing a lease. The first argument
 includes the client identification information.
 
 % 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
-empty, or very nearly empty.  As a result, the client will have been
-refused a lease. The first argument includes the client identification
-information.
+This is an old warning message issued when the allocation engine fails to allocate a
+lease for a client. This message includes a number of lease allocation attempts
+that the engine made before giving up. If the number of attempts is 0 because the
+engine was unable to use any of the address pools for the particular client, this
+message is not logged. Even though, several more detailed logs precede this message,
+it was left for backward compatibility.
 
 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.
@@ -50,6 +50,74 @@ useful is to point out that the pool reserved to a given class has ran
 out of addresses. When you see this message, you may consider checking your
 pool size and your classification definitions.
 
+% ALLOC_ENGINE_V4_ALLOC_FAIL_NO_POOLS %1: no pools were available for the address allocation
+This warning message is issued when the allocation engine fails to
+allocate a lease because it could not use any configured pools for the
+particular client. It is also possible that all of the subnets from
+which the allocation engine attempted to assign an address lack address
+pools. In this case, it should be considered misconfiguration if an
+operator expects that some clients should be assigned dynamic addresses.
+A subnet may lack any pools only when all clients should be assigned
+reserved IP addresses.
+
+Suppose the subnets connected to a shared network or a single subnet to
+which the client belongs have pools configured. In that case, this
+message is an indication that none of the pools could be used for the
+client because the client does not belong to appropriate client classes.
+
+% ALLOC_ENGINE_V4_ALLOC_FAIL_SHARED_NETWORK %1: failed to allocate an IPv4 address in the shared network %2
+This warning message is issued when the allocation engine fails to allocate
+a lease for a client connected to a shared network. The first argument
+includes the client identification information. The second argument specifies
+the shared network name. The shared network should contain at least one subnet,
+but typically it aggregates multiple subnets. This log message indicates that
+the allocation engine could not find and allocate any suitable lease in any of
+the subnets within the shared network.
+
+Further log messages print the subnets in this shared network from which the
+allocation engine attempted to assign a lease. The allocation engine does not
+use the subnets in the shared network, which are unavailable to the DHCP client
+due to non-matching client classes. Such subnets are not included in the log
+messages following this message. In the extreme case, the allocation engine
+may use none of the subnets in the shared network for the lease allocation.
+It is the case when the address pools are available to certain client classes,
+but the requesting client does not belong to them. A suitable log message
+informing about the occurrence of this situation is issued after this log
+message.
+
+% ALLOC_ENGINE_V4_ALLOC_FAIL_SUBNET %1: failed to allocate an IPv4 address in the subnet with id %2
+This warning message is issued when the allocation engine fails to allocate
+a lease for a client connected to a subnet that does not belong to a shared
+network. The first argument includes the client identification information.
+The second argument specifies the subnet identifier.
+
+There are many reasons for failing lease allocations. One of them may be the
+address pools exhaustion or existing reservations for the free leases.
+However, in some cases, the allocation engine may fail to find a suitable
+pool for the client when the pools are only available to certain client
+classes, but the requesting client does not belong to them. Further log
+messages provide more information to distinguish between these different
+cases.
+
+% ALLOC_ENGINE_V4_ALLOC_FAIL_SUBNET_POOLS_UNAVAIL %1: no suitable pools found in the subnet with id %2
+This warning message is issued when the allocation engine fails to allocate
+a lease for a client connected to a shared network. The engine tried to
+allocate addresses from different subnets belonging to this shared network,
+but the pools in some of the subnets were apparently guarded by client classes
+that the client did not belong to. All such subnets are logged with this
+message. The log message includes the client identification information
+and a subnet identifier.
+
+% ALLOC_ENGINE_V4_ALLOC_FAIL_SUBNET_TRIED %1: no available leases found in the subnet with id %2
+This warning message is issued when the allocation engine fails to allocate
+a lease for a client connected to a shared network. The engine tried to
+allocate addresses from different subnets belonging to this shared network
+and having a matching client class. This message is logged for each such
+subnet. It is not logged for the subnets from which the engine did not try
+to assign an address because of the non-matching client classes.
+The log message includes the client identification information and a subnet
+identifier.
+
 % ALLOC_ENGINE_V4_DECLINED_RECOVERED IPv4 address %1 was recovered after %2 seconds of probation-period
 This informational message indicates that the specified address was reported
 as duplicate (client sent DECLINE) and the server marked this address as