[#2085] Emit a warning when HTTP queue grows

src/lib/http/client.cc
    ConnectionPool::Destination::pushRequest() - emits
    a warning if the queue size has exceeded its threshold

src/lib/http/http_messages.mes
    HTTP_CLIENT_QUEUE_SIZE_GROWING - new log message

diff --git a/ChangeLog b/ChangeLog
index 4a543ea43bea6708af98185c09406eb2fc9042f5..6de3a1de4240939993cc98a7507b32f56aa73001 100644 (file)
--- a/ChangeLog
+++ b/ChangeLog
@@ -1,3 +1,8 @@
+1948.  [func]          tmark
+       HTTP library will now emit a warning log when the queue of
+       pending client requests for a given URL exceeds a threshold.
+       (Gitlab #2085)
+
 1947.  [bug]           marcin
        Corrected a bug in the High Availablity hooks library that could
        cause a standby server not to synchronize its lease database

diff --git a/src/lib/http/client.cc b/src/lib/http/client.cc
index cfbf6630961b73295ce2bfa8ebeec30383184382..e844c58d211fdaca3c1b2cae4859fa8b9b610003 100644 (file)
--- a/src/lib/http/client.cc
+++ b/src/lib/http/client.cc
@@ -14,6 +14,7 @@
 #include <http/http_messages.h>
 #include <http/response_json.h>
 #include <http/response_parser.h>
+#include <util/boost_time_utils.h>
 #include <util/multi_threading_mgr.h>
 #include <util/unlock_guard.h>
 
@@ -34,6 +35,8 @@ using namespace isc;
 using namespace isc::asiolink;
 using namespace isc::http;
 using namespace isc::util;
+using namespace boost::posix_time;
+
 namespace ph = std::placeholders;
 
 namespace {
@@ -805,6 +808,11 @@ private:
     /// @brief Encapsulates connections and requests for a given URL
     class Destination {
     public:
+        /// @brief Number of queued requests allowed without warnings being emitted.
+        const size_t QUEUE_SIZE_THRESHOLD = 2048;
+        /// @brief Interval between queue size warnings.
+        const int QUEUE_WARN_SECS = 5;
+
         /// @brief Constructor
         ///
         /// @param url server URL of this destination
@@ -813,7 +821,8 @@ private:
         /// allowed for in the list URL
         Destination(Url url, TlsContextPtr tls_context, size_t max_connections)
             : url_(url), tls_context_(tls_context),
-              max_connections_(max_connections), connections_(), queue_() {
+              max_connections_(max_connections), connections_(), queue_(),
+             last_queue_warn_time_(min_date_time), last_queue_size_(0) {
         }
 
         /// @brief Destructor
@@ -976,9 +985,28 @@ private:
 
         /// @brief Adds a request to the end of the request queue.
         ///
+        /// If the size of the queue exceeds a threhsold and appears
+        /// to be growing it will emit a warning log.
+        ///
         /// @param desc RequestDescriptor to queue.
         void pushRequest(RequestDescriptor desc) {
             queue_.push(desc);
+            size_t size = queue_.size();
+            // If the queue size is larger than the threshold and growing, issue a
+            // periodic warning.
+            if ((size > QUEUE_SIZE_THRESHOLD) && (size > last_queue_size_)) {
+                ptime now = microsec_clock::universal_time();
+                if ((now - last_queue_warn_time_) > seconds(QUEUE_WARN_SECS)) {
+                    LOG_WARN(http_logger, HTTP_CLIENT_QUEUE_SIZE_GROWING)
+                             .arg(url_.toText())
+                             .arg(size);
+                    // Remember the last time we warned.
+                    last_queue_warn_time_ = now;
+                }
+            }
+
+            // Remember the previous size.
+            last_queue_size_ = size;
         }
 
         /// @brief Removes a request from the front of the request queue.
@@ -1009,6 +1037,12 @@ private:
 
         /// @brief Holds the queue of request for this destination.
         std::queue<RequestDescriptor> queue_;
+
+        /// @brief Time the last queue size warning was issued.
+        ptime last_queue_warn_time_;
+
+        /// @brief Size of the queue after last push.
+        size_t last_queue_size_;
     };
 
     /// @brief Pointer to a Destination.

diff --git a/src/lib/http/http_messages.cc b/src/lib/http/http_messages.cc
index dc24176ead3350d4fedff7fb1703e1c0e3308753..292d2d85d9f6299671ac4331e7a5971205d8a06b 100644 (file)
--- a/src/lib/http/http_messages.cc
+++ b/src/lib/http/http_messages.cc
@@ -13,6 +13,7 @@ extern const isc::log::MessageID HTTP_BAD_CLIENT_REQUEST_RECEIVED_DETAILS = "HTT
 extern const isc::log::MessageID HTTP_BAD_SERVER_RESPONSE_RECEIVED = "HTTP_BAD_SERVER_RESPONSE_RECEIVED";
 extern const isc::log::MessageID HTTP_BAD_SERVER_RESPONSE_RECEIVED_DETAILS = "HTTP_BAD_SERVER_RESPONSE_RECEIVED_DETAILS";
 extern const isc::log::MessageID HTTP_CLIENT_MT_STARTED = "HTTP_CLIENT_MT_STARTED";
+extern const isc::log::MessageID HTTP_CLIENT_QUEUE_SIZE_GROWING = "HTTP_CLIENT_QUEUE_SIZE_GROWING";
 extern const isc::log::MessageID HTTP_CLIENT_REQUEST_RECEIVED = "HTTP_CLIENT_REQUEST_RECEIVED";
 extern const isc::log::MessageID HTTP_CLIENT_REQUEST_RECEIVED_DETAILS = "HTTP_CLIENT_REQUEST_RECEIVED_DETAILS";
 extern const isc::log::MessageID HTTP_CLIENT_REQUEST_SEND = "HTTP_CLIENT_REQUEST_SEND";
@@ -46,6 +47,7 @@ const char* values[] = {
     "HTTP_BAD_SERVER_RESPONSE_RECEIVED", "bad response received when communicating with %1: %2",
     "HTTP_BAD_SERVER_RESPONSE_RECEIVED_DETAILS", "detailed information about bad response received from %1:\n%2",
     "HTTP_CLIENT_MT_STARTED", "HttpClient has been started in multi-threaded mode running %1 threads",
+    "HTTP_CLIENT_QUEUE_SIZE_GROWING", "queue for URL: %1, now has %2 entries and may be growing too quickly",
     "HTTP_CLIENT_REQUEST_RECEIVED", "received HTTP request from %1",
     "HTTP_CLIENT_REQUEST_RECEIVED_DETAILS", "detailed information about well-formed request received from %1:\n%2",
     "HTTP_CLIENT_REQUEST_SEND", "sending HTTP request %1 to %2",

diff --git a/src/lib/http/http_messages.h b/src/lib/http/http_messages.h
index d24a6ce4fdc5cce4e3bdac773e711b1fc32f62fc..4ac303081bfc74a0fdef1cf9a5f4ee310213684d 100644 (file)
--- a/src/lib/http/http_messages.h
+++ b/src/lib/http/http_messages.h
@@ -14,6 +14,7 @@ extern const isc::log::MessageID HTTP_BAD_CLIENT_REQUEST_RECEIVED_DETAILS;
 extern const isc::log::MessageID HTTP_BAD_SERVER_RESPONSE_RECEIVED;
 extern const isc::log::MessageID HTTP_BAD_SERVER_RESPONSE_RECEIVED_DETAILS;
 extern const isc::log::MessageID HTTP_CLIENT_MT_STARTED;
+extern const isc::log::MessageID HTTP_CLIENT_QUEUE_SIZE_GROWING;
 extern const isc::log::MessageID HTTP_CLIENT_REQUEST_RECEIVED;
 extern const isc::log::MessageID HTTP_CLIENT_REQUEST_RECEIVED_DETAILS;
 extern const isc::log::MessageID HTTP_CLIENT_REQUEST_SEND;

diff --git a/src/lib/http/http_messages.mes b/src/lib/http/http_messages.mes
index 7683162ab3c9a167b9681370fa34656ff7993d78..5d2b50771fc479f1827941d83749869952e9a09c 100644 (file)
--- a/src/lib/http/http_messages.mes
+++ b/src/lib/http/http_messages.mes
@@ -38,6 +38,15 @@ from the server. The first argument specifies an URL of the server. The
 second argument provides a response in the textual format. The request is
 truncated by the logger if it is too large to be printed.
 
+% HTTP_CLIENT_QUEUE_SIZE_GROWING queue for URL: %1, now has %2 entries and may be growing too quickly
+This warning message is issued when the queue of pending requests for the
+given URL appears to be growing more quickly than the requests can be handled.
+It will be emitted periodically as long as the queue size continues to grow.
+This may occur with a surge of client traffic creating a momemntary backlog
+which then subsides as the surge subsides.  If it happens continually then
+it most likely indicates a deployment configuration that cannot sustain the
+client load.
+
 % HTTP_CLIENT_MT_STARTED HttpClient has been started in multi-threaded mode running %1 threads
 This debug message is issued when a multi-threaded HTTP client instance has
 been created.  The argument specifies the maximum number of threads.