From a251900874fcceb49bf7a8364fdfb2a97f98a9d0 Mon Sep 17 00:00:00 2001 From: Marcin Siodelski Date: Wed, 15 Feb 2017 20:58:55 +0100 Subject: [PATCH] [5107] Added more logging for HTTP lib. --- src/bin/agent/ctrl_agent_messages.mes | 7 +++- src/bin/agent/ctrl_agent_process.cc | 3 ++ src/lib/http/connection.cc | 31 ++++++++++++++++++ src/lib/http/connection.h | 3 ++ src/lib/http/http_messages.mes | 41 ++++++++++++++++++++++-- src/lib/http/response.cc | 10 +++++- src/lib/http/response.h | 3 ++ src/lib/http/tests/response_unittests.cc | 6 ++-- 8 files changed, 97 insertions(+), 7 deletions(-) diff --git a/src/bin/agent/ctrl_agent_messages.mes b/src/bin/agent/ctrl_agent_messages.mes index db6d17e9b1..d58e8727ef 100644 --- a/src/bin/agent/ctrl_agent_messages.mes +++ b/src/bin/agent/ctrl_agent_messages.mes @@ -1,4 +1,4 @@ -# Copyright (C) 2016 Internet Systems Consortium, Inc. ("ISC") +# Copyright (C) 2016-2017 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,11 @@ $NAMESPACE isc::agent +% CTRL_AGENT_HTTP_SERVICE_STARTED HTTP service bound to address %1:%2 +This informational message indicates that the server has started HTTP service +on the specified address and port. All control commands should be sent to this +address and port. + % CTRL_AGENT_FAILED application experienced a fatal error: %1 This is a debug message issued when the Control Agent application encounters an unrecoverable error from within the event loop. diff --git a/src/bin/agent/ctrl_agent_process.cc b/src/bin/agent/ctrl_agent_process.cc index 4f9b0c1764..4740ce1292 100644 --- a/src/bin/agent/ctrl_agent_process.cc +++ b/src/bin/agent/ctrl_agent_process.cc @@ -52,6 +52,9 @@ CtrlAgentProcess::run() { SERVER_PORT, rcf, REQUEST_TIMEOUT); http_listener.start(); + LOG_INFO(agent_logger, CTRL_AGENT_HTTP_SERVICE_STARTED) + .arg(SERVER_ADDRESS.toText()).arg(SERVER_PORT); + while (!shouldShutdown()) { getIoService()->run_one(); } diff --git a/src/lib/http/connection.cc b/src/lib/http/connection.cc index 6d7d28024a..27cd015ff3 100644 --- a/src/lib/http/connection.cc +++ b/src/lib/http/connection.cc @@ -7,6 +7,8 @@ #include #include #include +#include +#include #include using namespace isc::asiolink; @@ -58,8 +60,11 @@ HttpConnection::close() { void HttpConnection::stopThisConnection() { try { + LOG_DEBUG(http_logger, DBGLVL_TRACE_BASIC, HTTP_CONNECTION_STOP) + .arg(getRemoteEndpointAddressAsText()); connection_pool_.stop(shared_from_this()); } catch (...) { + LOG_ERROR(http_logger, HTTP_CONNECTION_STOP_FAILED); } } @@ -123,6 +128,9 @@ HttpConnection::acceptorCallback(const boost::system::error_code& ec) { acceptor_callback_(ec); if (!ec) { + LOG_DEBUG(http_logger, DBGLVL_TRACE_DETAIL, HTTP_REQUEST_RECEIVE_START) + .arg(getRemoteEndpointAddressAsText()) + .arg(static_cast(request_timeout_/1000)); request_timer_.setup(boost::bind(&HttpConnection::requestTimeoutCallback, this), request_timeout_, IntervalTimer::ONE_SHOT); doRead(); @@ -131,6 +139,11 @@ HttpConnection::acceptorCallback(const boost::system::error_code& ec) { void HttpConnection::socketReadCallback(boost::system::error_code ec, size_t length) { + if (length != 0) { + LOG_DEBUG(http_logger, DBGLVL_TRACE_DETAIL_DATA, HTTP_DATA_RECEIVED) + .arg(length) + .arg(getRemoteEndpointAddressAsText()); + } std::string s(&buf_[0], buf_[0] + length); parser_->postBuffer(static_cast(buf_.data()), length); parser_->poll(); @@ -138,12 +151,17 @@ HttpConnection::socketReadCallback(boost::system::error_code ec, size_t length) doRead(); } else { + LOG_DEBUG(http_logger, DBGLVL_TRACE_DETAIL, HTTP_REQUEST_RECEIVED) + .arg(getRemoteEndpointAddressAsText()); try { request_->finalize(); } catch (...) { } HttpResponsePtr response = response_creator_->createHttpResponse(request_); + LOG_DEBUG(http_logger, DBGLVL_TRACE_DETAIL, HTTP_RESPONSE_SEND) + .arg(response->toBriefString()) + .arg(getRemoteEndpointAddressAsText()); asyncSendResponse(response); } } @@ -163,12 +181,25 @@ HttpConnection::socketWriteCallback(boost::system::error_code ec, void HttpConnection::requestTimeoutCallback() { + LOG_DEBUG(http_logger, DBGLVL_TRACE_DETAIL, HTTP_REQUEST_TIMEOUT_OCCURRED) + .arg(getRemoteEndpointAddressAsText()); HttpResponsePtr response = response_creator_->createStockHttpResponse(request_, HttpStatusCode::REQUEST_TIMEOUT); asyncSendResponse(response); } +std::string +HttpConnection::getRemoteEndpointAddressAsText() const { + try { + if (socket_.getASIOSocket().is_open()) { + return (socket_.getASIOSocket().remote_endpoint().address().to_string()); + } + } catch (...) { + } + return ("(unknown address)"); +} + } // end of namespace isc::http } // end of namespace isc diff --git a/src/lib/http/connection.h b/src/lib/http/connection.h index 02b31b647d..f0854358ab 100644 --- a/src/lib/http/connection.h +++ b/src/lib/http/connection.h @@ -17,6 +17,7 @@ #include #include #include +#include namespace isc { namespace http { @@ -174,6 +175,8 @@ private: /// @brief Stops current connection. void stopThisConnection(); + std::string getRemoteEndpointAddressAsText() const; + /// @brief Timer used to detect Request Timeout. asiolink::IntervalTimer request_timer_; diff --git a/src/lib/http/http_messages.mes b/src/lib/http/http_messages.mes index 469c6acab1..4b8b691a4a 100644 --- a/src/lib/http/http_messages.mes +++ b/src/lib/http/http_messages.mes @@ -1,4 +1,4 @@ -# Copyright (C) 2016 Internet Systems Consortium, Inc. ("ISC") +# Copyright (C) 2016-2017 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,5 +6,40 @@ $NAMESPACE isc::http -% HTTP_DUMMY a dummy message for libkea-http -This is a dummy 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 +successful message exchange with a client. + +% HTTP_CONNECTION_STOP_FAILED stopping HTTP connection failed +This error message is issued when an error occurred during closing a +HTTP connection with a client. + +% HTTP_DATA_RECEIVED received %1 bytes from %2 +This debug message is issued when the server receives a chunk of data from +the remote endpoint. This may include the whole request or only a part +of the request. The first argument specifies the amount of received data. +The second argument specifies an address of the remote endpoint which +produced the data. + +% HTTP_REQUEST_RECEIVE_START start receiving request from %1 with timeout %2 +This debug message is issued when the server starts receiving new request +over the established connection. The first argument specifies the address +of the remote endpoint. The second argument specifies request timeout in +seconds. + +% 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 +specified as an argument. + +% 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 +about the response (HTTP version number and status code). The second +argument specifies an address of the remote endpoint. + +% HTTP_REQUEST_TIMEOUT_OCCURRED HTTP request timeout occurred when communicating with %1 +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. \ No newline at end of file diff --git a/src/lib/http/response.cc b/src/lib/http/response.cc index 7062795c22..5764b3c300 100644 --- a/src/lib/http/response.cc +++ b/src/lib/http/response.cc @@ -99,12 +99,20 @@ HttpResponse::getDateHeaderValue() const { } std::string -HttpResponse::toString() const { +HttpResponse::toBriefString() const { std::ostringstream s; // HTTP version number and status code. s << "HTTP/" << http_version_.major_ << "." << http_version_.minor_; s << " " << static_cast(status_code_); s << " " << statusCodeToString(status_code_) << crlf; + return (s.str()); +} + +std::string +HttpResponse::toString() const { + std::ostringstream s; + // HTTP version number and status code. + s << toBriefString(); // We need to at least insert "Date" header into the HTTP headers. This // method is const thus we can't insert it into the headers_ map. We'll diff --git a/src/lib/http/response.h b/src/lib/http/response.h index 68cc4ccc75..a69ecd87ae 100644 --- a/src/lib/http/response.h +++ b/src/lib/http/response.h @@ -152,6 +152,9 @@ public: /// @return Textual representation of the status code. static std::string statusCodeToString(const HttpStatusCode& status_code); + /// @brief Returns HTTP version and HTTP status as a string. + std::string toBriefString() const; + /// @brief Returns textual representation of the HTTP response. /// /// It includes the "Date" header with the current time in RFC 1123 format. diff --git a/src/lib/http/tests/response_unittests.cc b/src/lib/http/tests/response_unittests.cc index f6e510bf60..03b8dbb0f1 100644 --- a/src/lib/http/tests/response_unittests.cc +++ b/src/lib/http/tests/response_unittests.cc @@ -39,11 +39,13 @@ public: response.addHeader("Content-Type", "text/html"); std::ostringstream response_string; response_string << "HTTP/1.0 " << static_cast(status_code) - << " " << status_message << "\r\n" + << " " << status_message << "\r\n"; + EXPECT_EQ(response_string.str(), response.toBriefString()); + + response_string << "Content-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.3