[5107] Added more logging for HTTP lib.

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.

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();
         }

src/lib/http/connection.cc

@@ -7,6 +7,8 @@
 #include <asiolink/asio_wrapper.h>
 #include <http/connection.h>
 #include <http/connection_pool.h>
+#include <http/http_log.h>
+#include <http/http_messages.h>
 #include <boost/bind.hpp>
 
 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<unsigned>(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<void*>(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

src/lib/http/connection.h

@@ -17,6 +17,7 @@
 #include <boost/system/error_code.hpp>
 #include <boost/shared_ptr.hpp>
 #include <array>
+#include <string>
 
 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_;
 

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.

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<uint16_t>(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

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.

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<uint16_t>(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());
     }
 };