[5205] Improved logging in the HTTP client class.

src/lib/http/client.cc

@@ -8,6 +8,8 @@
 #include <asiolink/interval_timer.h>
 #include <asiolink/tcp_socket.h>
 #include <http/client.h>
+#include <http/http_log.h>
+#include <http/http_messages.h>
 #include <http/response_json.h>
 #include <http/response_parser.h>
 #include <boost/bind.hpp>
@@ -25,6 +27,11 @@ using namespace http;
 
 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;
+
 /// @brief TCP socket callback function type.
 typedef boost::function<void(boost::system::error_code ec, size_t length)>
 SocketCallbackFunction;
@@ -442,6 +449,17 @@ Connection::doTransaction(const HttpRequestPtr& request,
             socket_.close();
         }
 
+        LOG_DEBUG(http_logger, isc::log::DBGLVL_TRACE_DETAIL,
+                  HTTP_CLIENT_REQUEST_SEND)
+            .arg(request->toBriefString())
+            .arg(url_.toText());
+
+        LOG_DEBUG(http_logger, isc::log::DBGLVL_TRACE_DETAIL_DATA,
+                  HTTP_CLIENT_REQUEST_DETAILS)
+            .arg(url_.toText())
+            .arg(HttpMessageParserBase::logFormatHttpMessage(request->toString(),
+                                                             MAX_LOGGED_MESSAGE_SIZE));
+
         /// @todo We're getting a hostname but in fact it is expected to be an IP address.
         /// We should extend the TCPEndpoint to also accept names. Currently, it will fall
         /// over for names.
@@ -482,6 +500,33 @@ Connection::terminate(const boost::system::error_code& ec,
 
     if (!ec && current_response_->isFinalized()) {
         response = current_response_;
+
+        LOG_DEBUG(http_logger, isc::log::DBGLVL_TRACE_BASIC,
+                  HTTP_SERVER_RESPONSE_RECEIVED)
+            .arg(url_.toText());
+
+        LOG_DEBUG(http_logger, isc::log::DBGLVL_TRACE_BASIC_DATA,
+                  HTTP_SERVER_RESPONSE_DETAILS)
+            .arg(url_.toText())
+            .arg(parser_->getBufferAsString(MAX_LOGGED_MESSAGE_SIZE));
+
+    } else {
+        std::string err = parsing_error.empty() ? ec.message() : parsing_error;
+
+        LOG_DEBUG(http_logger, isc::log::DBGLVL_TRACE_BASIC,
+                  HTTP_BAD_SERVER_RESPONSE_RECEIVED)
+            .arg(url_.toText())
+            .arg(err);
+
+        // Only log the details if we have received anything and tried
+        // to parse it.
+        if (!parsing_error.empty()) {
+            LOG_DEBUG(http_logger, isc::log::DBGLVL_TRACE_BASIC_DATA,
+                      HTTP_BAD_SERVER_RESPONSE_DETAILS)
+                .arg(url_.toText())
+                .arg(parser_->getBufferAsString());
+        }
+
     }
 
     try {

src/lib/http/connection.cc

@@ -237,12 +237,12 @@ HttpConnection::socketReadCallback(boost::system::error_code ec, size_t length)
         }
 
         HttpResponsePtr response = response_creator_->createHttpResponse(request_);
-        LOG_DEBUG(http_logger, isc::log::DBGLVL_TRACE_DETAIL,
+        LOG_DEBUG(http_logger, isc::log::DBGLVL_TRACE_BASIC,
                   HTTP_RESPONSE_SEND)
             .arg(response->toBriefString())
             .arg(getRemoteEndpointAddressAsText());
 
-        LOG_DEBUG(http_logger, isc::log::DBGLVL_TRACE_DETAIL_DATA,
+        LOG_DEBUG(http_logger, isc::log::DBGLVL_TRACE_BASIC_DATA,
                   HTTP_RESPONSE_DETAILS)
             .arg(getRemoteEndpointAddressAsText())
             .arg(HttpMessageParserBase::logFormatHttpMessage(response->toString(),

src/lib/http/http_messages.mes

@@ -21,6 +21,32 @@ 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_BAD_SERVER_RESPONSE_DETAILS detailed information about bad response received from %1:\n%2
+This debug message is issued when an HTTP client receives malformed response
+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_BAD_SERVER_RESPONSE_RECEIVED bad response received when communicating with %1: %2
+This debug message is issued when an HTTP client fails to receive a response
+from the server or when this response is malformed. The first argument
+specifies the server URL. The second argument provides a detailed error
+message.
+
+% HTTP_CLIENT_REQUEST_DETAILS detailed information about request sent to %1:\n%2
+This debug message is issued right before the client sends a HTTP request
+to the server. It includes detailed information about the request. The
+first argument specifies an URL of the server to which the request is
+being sent. The second argument provides the request in the textual form.
+The request is truncated by the logger if it is too large to be printed.
+
+% HTTP_CLIENT_REQUEST_SEND sending HTTP request %1 to %2
+This debug message is issued when the client is starting to send a HTTP
+request to a server. The first argument holds basic information
+about the request (HTTP version number and status code). The second
+argument specifies a URL of the server.
+
 % 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
@@ -77,3 +103,17 @@ 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
 about the response (HTTP version number and status code). The second
 argument specifies an address of the remote endpoint.
+
+% HTTP_SERVER_RESPONSE_DETAILS detailed information about well formed response received from %1:\n%2
+This debug message is issued when the HTTP client receives a well formed
+response from the server. It includes detailed information about the
+received response. The first argument specifies a URL of the server which
+sent the response. The second argument provides the response in the textual
+format. The response is truncated by the logger if it is too large to
+be printed.
+
+% HTTP_SERVER_RESPONSE_RECEIVED received HTTP response from %1
+This debug message is issued when the client finished receiving an HTTP
+response from the server. The URL of the server is specified as an argument.
+
+

src/lib/http/request.cc

@@ -147,12 +147,22 @@ HttpRequest::getBody() const {
 }
 
 std::string
-HttpRequest::toString() const {
+HttpRequest::toBriefString() const {
     checkFinalized();
 
     std::ostringstream s;
     s << methodToString(getMethod()) << " " << getUri() << " HTTP/" <<
-        getHttpVersion().major_ << "." << getHttpVersion().minor_ << crlf;
+        getHttpVersion().major_ << "." << getHttpVersion().minor_;
+    return (s.str());
+}
+
+std::string
+HttpRequest::toString() const {
+    checkFinalized();
+
+    std::ostringstream s;
+    // HTTP method, URI and version number.
+    s << toBriefString() << crlf;
 
     for (auto header_it = headers_.cbegin(); header_it != headers_.cend();
          ++header_it) {

src/lib/http/request.h

@@ -120,6 +120,9 @@ public:
     /// @brief Returns HTTP message body as string.
     std::string getBody() const;
 
+    /// @brief Returns HTTP method, URI and HTTP version as a string.
+    std::string toBriefString() const;
+
     /// @brief Returns HTTP message as string.
     ///
     /// This method is called to generate the outbound HTTP message. Make

src/lib/http/response.cc

@@ -202,7 +202,7 @@ HttpResponse::toBriefString() const {
     // HTTP version number and status code.
     s << "HTTP/" << http_version_.major_ << "." << http_version_.minor_;
     s << " " << context_->status_code_;
-    s << " " << statusCodeToString(static_cast<HttpStatusCode>(context_->status_code_)) << crlf;
+    s << " " << statusCodeToString(static_cast<HttpStatusCode>(context_->status_code_));
     return (s.str());
 }
 
@@ -211,7 +211,7 @@ HttpResponse::toString() const {
 
     std::ostringstream s;
     // HTTP version number and status code.
-    s << toBriefString();
+    s << toBriefString() << crlf;
 
     for (auto header_it = headers_.cbegin(); header_it != headers_.cend();
          ++header_it) {

src/lib/http/tests/request_unittests.cc

@@ -272,4 +272,15 @@ TEST_F(HttpRequestTest, clientRequestNoBody) {
               request_.toString());
 }
 
+TEST_F(HttpRequestTest, toBriefString) {
+    // Create the request.
+    setContextBasics("POST", "/isc/org", HttpVersion(1, 1));
+    // Add headers.
+    request_.context()->headers_.push_back(HttpHeaderContext("Content-Type", "application/json"));
+    // Must be finalized before can be used.
+    ASSERT_NO_THROW(request_.finalize());
+    // Check that the brief string is correct.
+    EXPECT_EQ("POST /isc/org HTTP/1.1", request_.toBriefString());
+}
+
 }

src/lib/http/tests/response_unittests.cc

@@ -40,11 +40,11 @@ public:
         ASSERT_NO_THROW(response.finalize());
         std::ostringstream response_string;
         response_string << "HTTP/1.0 " << static_cast<uint16_t>(status_code)
-            << " " << status_message << "\r\n";
+            << " " << status_message;
         EXPECT_EQ(response_string.str(), response.toBriefString());
 
         response_string
-            << "Content-Length: 0\r\n"
+            << "\r\nContent-Length: 0\r\n"
             << "Content-Type: text/html\r\n"
             << "Date: " << response.getDateHeaderValue() << "\r\n\r\n";
         EXPECT_EQ(response_string.str(), response.toString());