From 2be44af3e8fe4419308c5c6b79c3a7c3490949d2 Mon Sep 17 00:00:00 2001 From: Marcin Siodelski Date: Wed, 30 May 2018 11:00:50 +0200 Subject: [PATCH] [5205] Improved logging in the HTTP client class. --- src/lib/http/client.cc | 45 ++++++++++++++++++++++++ src/lib/http/connection.cc | 4 +-- src/lib/http/http_messages.mes | 40 +++++++++++++++++++++ src/lib/http/request.cc | 14 ++++++-- src/lib/http/request.h | 3 ++ src/lib/http/response.cc | 4 +-- src/lib/http/tests/request_unittests.cc | 11 ++++++ src/lib/http/tests/response_unittests.cc | 4 +-- 8 files changed, 117 insertions(+), 8 deletions(-) diff --git a/src/lib/http/client.cc b/src/lib/http/client.cc index 5b0da858e2..ed026acc1d 100644 --- a/src/lib/http/client.cc +++ b/src/lib/http/client.cc @@ -8,6 +8,8 @@ #include #include #include +#include +#include #include #include #include @@ -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 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 { diff --git a/src/lib/http/connection.cc b/src/lib/http/connection.cc index 11a272a03a..d9ce80b2cd 100644 --- a/src/lib/http/connection.cc +++ b/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(), diff --git a/src/lib/http/http_messages.mes b/src/lib/http/http_messages.mes index a22f42f1be..5a9ae1a5be 100644 --- a/src/lib/http/http_messages.mes +++ b/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. + + diff --git a/src/lib/http/request.cc b/src/lib/http/request.cc index 678f8b605d..dcb498111d 100644 --- a/src/lib/http/request.cc +++ b/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) { diff --git a/src/lib/http/request.h b/src/lib/http/request.h index 387a109519..945483d443 100644 --- a/src/lib/http/request.h +++ b/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 diff --git a/src/lib/http/response.cc b/src/lib/http/response.cc index 13fd4a5b2c..500bd6db96 100644 --- a/src/lib/http/response.cc +++ b/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(context_->status_code_)) << crlf; + s << " " << statusCodeToString(static_cast(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) { diff --git a/src/lib/http/tests/request_unittests.cc b/src/lib/http/tests/request_unittests.cc index 51b692c6ac..dc350cdc27 100644 --- a/src/lib/http/tests/request_unittests.cc +++ b/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()); +} + } diff --git a/src/lib/http/tests/response_unittests.cc b/src/lib/http/tests/response_unittests.cc index d6d1529be9..fc07dd27b9 100644 --- a/src/lib/http/tests/response_unittests.cc +++ b/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(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()); -- 2.47.2