[5205] Improved HTTP server side logging.

src/lib/http/connection.cc

@@ -13,6 +13,15 @@
 
 using namespace isc::asiolink;
 
+namespace {
+
+/// @brief Maximum size of the HTTP message that can be logged.
+///
+/// The part of the HTTP message beyond this value is truncated.
+constexpr size_t MAX_LOGGED_MESSAGE_SIZE = 1024;
+
+}
+
 namespace isc {
 namespace http {
 
@@ -203,12 +212,28 @@ HttpConnection::socketReadCallback(boost::system::error_code ec, size_t length)
         doRead();
 
     } else {
-        LOG_DEBUG(http_logger, isc::log::DBGLVL_TRACE_DETAIL,
-                  HTTP_REQUEST_RECEIVED)
-            .arg(getRemoteEndpointAddressAsText());
         try {
             request_->finalize();
-        } catch (...) {
+
+            LOG_DEBUG(http_logger, isc::log::DBGLVL_TRACE_BASIC,
+                      HTTP_REQUEST_RECEIVED)
+                .arg(getRemoteEndpointAddressAsText());
+
+            LOG_DEBUG(http_logger, isc::log::DBGLVL_TRACE_BASIC_DATA,
+                      HTTP_REQUEST_DETAILS)
+                .arg(getRemoteEndpointAddressAsText())
+                .arg(parser_->getBufferAsString(MAX_LOGGED_MESSAGE_SIZE));
+
+        } catch (const std::exception& ex) {
+            LOG_DEBUG(http_logger, isc::log::DBGLVL_TRACE_BASIC,
+                      HTTP_BAD_REQUEST_RECEIVED)
+                .arg(getRemoteEndpointAddressAsText())
+                .arg(ex.what());
+
+            LOG_DEBUG(http_logger, isc::log::DBGLVL_TRACE_BASIC_DATA,
+                      HTTP_BAD_REQUEST_DETAILS)
+                .arg(getRemoteEndpointAddressAsText())
+                .arg(parser_->getBufferAsString(MAX_LOGGED_MESSAGE_SIZE));
         }
 
         HttpResponsePtr response = response_creator_->createHttpResponse(request_);
@@ -216,6 +241,13 @@ HttpConnection::socketReadCallback(boost::system::error_code ec, size_t length)
                   HTTP_RESPONSE_SEND)
             .arg(response->toBriefString())
             .arg(getRemoteEndpointAddressAsText());
+
+        LOG_DEBUG(http_logger, isc::log::DBGLVL_TRACE_DETAIL_DATA,
+                  HTTP_RESPONSE_DETAILS)
+            .arg(getRemoteEndpointAddressAsText())
+            .arg(HttpMessageParserBase::logFormatHttpMessage(response->toString(),
+                                                             MAX_LOGGED_MESSAGE_SIZE));
+
         asyncSendResponse(response);
     }
 }

src/lib/http/http_message_parser_base.cc

@@ -6,6 +6,7 @@
 
 #include <http/http_message_parser_base.h>
 #include <boost/bind.hpp>
+#include <sstream>
 
 using namespace isc::util;
 
@@ -23,7 +24,8 @@ const int HttpMessageParserBase::HTTP_PARSE_FAILED_EVT;
 
 
 HttpMessageParserBase::HttpMessageParserBase(HttpMessage& message)
-    : StateModel(), message_(message), buffer_(), error_message_() {
+    : StateModel(), message_(message), buffer_(), buffer_pos_(0),
+      error_message_() {
 }
 
 void
@@ -68,6 +70,33 @@ HttpMessageParserBase::postBuffer(const void* buf, const size_t buf_size) {
     }
 }
 
+std::string
+HttpMessageParserBase::getBufferAsString(const size_t limit) const {
+    std::string message(buffer_.begin(), buffer_.end());
+    return (logFormatHttpMessage(message, limit));
+}
+
+std::string
+HttpMessageParserBase::logFormatHttpMessage(const std::string& message,
+                                            const size_t limit) {
+    if (!message.empty()) {
+        if (limit < message.size()) {
+            std::ostringstream s;
+            s << ".........\n(truncating HTTP message larger than "
+              << limit << " characters)\n";
+            s << message.substr(0, limit)
+              << ".........\n(truncating HTTP message larger than "
+              << limit << " characters)\n";
+            return (s.str());
+        }
+    }
+
+    // Return original message if it is empty or does not exceed the
+    // limit.
+    return (message);
+}
+
+
 void
 HttpMessageParserBase::defineEvents() {
     StateModel::defineEvents();
@@ -197,9 +226,8 @@ HttpMessageParserBase::parseEndedHandler() {
 bool
 HttpMessageParserBase::popNextFromBuffer(char& next) {
     // If there are any characters in the buffer, pop next.
-    if (!buffer_.empty()) {
-        next = buffer_.front();
-        buffer_.pop_front();
+    if (buffer_pos_ < buffer_.size()) {
+        next = buffer_[buffer_pos_++];
         return (true);
     }
     return (false);

src/lib/http/http_message_parser_base.h

@@ -11,8 +11,8 @@
 #include <http/http_message.h>
 #include <util/state_model.h>
 #include <boost/function.hpp>
-#include <list>
 #include <string>
+#include <vector>
 
 namespace isc {
 namespace http {
@@ -142,6 +142,27 @@ public:
     /// @param buf_size Size of the data within the buffer.
     void postBuffer(const void* buf, const size_t buf_size);
 
+    /// @brief Returns parser's input buffer as string.
+    ///
+    /// @param limit Maximum length of the buffer to be output. If the limit is 0,
+    /// the length of the output is unlimited.
+    /// @return Textual representation of the input buffer.
+    std::string getBufferAsString(const size_t limit = 0) const;
+
+    /// @brief Formats provided HTTP message for logging.
+    ///
+    /// This method is useful in cases when there is a need to log a HTTP message
+    /// (as text). If the @c limit is specified the message output is limited to
+    /// this size. If the @c limit is set to 0 (default), the whole message is
+    /// output. The @c getBufferAsString method calls this method internally.
+    ///
+    /// @param message HTTP message to be logged.
+    /// @param limit Maximum length of the buffer to be output. If the limit is 0,
+    /// the length of the output is unlimited.
+    /// @return HTTP message formatted for logging.
+    static std::string logFormatHttpMessage(const std::string& message,
+                                            const size_t limit = 0);
+
 private:
 
     /// @brief Make @ref runModel private to make sure that the caller uses
@@ -257,7 +278,10 @@ protected:
     HttpMessage& message_;
 
     /// @brief Internal buffer from which parser reads data.
-    std::list<char> buffer_;
+    std::vector<char> buffer_;
+
+    /// @brief Position of the next character to read from the buffer.
+    size_t buffer_pos_;
 
     /// @brief Error message set by @ref onModelFailure.
     std::string error_message_;

src/lib/http/http_messages.mes

-# Copyright (C) 2016-2017 Internet Systems Consortium, Inc. ("ISC")
+# Copyright (C) 2016-2018 Internet Systems Consortium, Inc. ("ISC")
 #
 # This Source Code Form is subject to the terms of the Mozilla Public
 # License, v. 2.0. If a copy of the MPL was not distributed with this
@@ -6,6 +6,21 @@
 
 $NAMESPACE isc::http
 
+% HTTP_BAD_REQUEST_DETAILS detailed information about bad request received from %1:\n%2
+This debug message is issued when a HTTP client sends malformed request to
+the server. It includes detailed information about the received request
+rejected by the server. The first argument specifies an address of
+the remote endpoint which sent the request. The second argument provides
+a request in the textual format. The request is truncated by the logger
+if it is too large to be printed.
+
+% HTTP_BAD_REQUEST_RECEIVED bad request received from %1: %2
+This debug message is issued when a HTTP client sends malformed request to
+the server. This includes HTTP requests using unexpected content types,
+including malformed JSON etc. The first argument specifies an address of
+the remote endpoint which sent the request. The second argument provides
+a detailed error message.
+
 % HTTP_CONNECTION_STOP stopping HTTP connection from %1
 This debug message is issued when one of the HTTP connections is stopped.
 The connection can be stopped as a result of an error or after the
@@ -26,6 +41,13 @@ produced the data.
 This debug message is issued when the persistent HTTP connection is being
 closed as a result of being idle.
 
+% HTTP_REQUEST_DETAILS detailed information about well formed request received from %1:\n%2
+This debug message is issued when the HTTP server receives a well formed
+request. It includes detailed information about the received request. The
+first argument specifies an address of the remote endpoint which sent the
+request. The second argument provides the request in the textual format.
+The request is truncated by the logger if it is too large to be printed.
+
 % HTTP_REQUEST_RECEIVED received HTTP request from %1
 This debug message is issued when the server finished receiving a HTTP
 request from the remote endpoint. The address of the remote endpoint is
@@ -42,6 +64,14 @@ This debug message is issued when the HTTP request timeout has occurred and
 the server is going to send a response with Http Request timeout status
 code.
 
+% HTTP_RESPONSE_DETAILS detailed information about response sent to %1:\n%2
+This debug message is issued right before the server sends a HTTP response
+to the client. It includes detailed information about the response. The
+first argument specifies an address of the remote endpoint to which the
+response is being sent. The second argument provides a response in the
+textual form. The response is truncated by the logger if it is too large
+to be printed.
+
 % HTTP_RESPONSE_SEND sending HTTP response %1 to %2
 This debug message is issued when the server is starting to send a HTTP
 response to a remote endpoint. The first argument holds basic information