[#2662] Added more logs

diff --git a/src/lib/tcp/tcp_connection.cc b/src/lib/tcp/tcp_connection.cc
index 22c8934f6890c3dc64317aac9c8bcefa3dc836ff..f0a8d5d51620aefc6b3a230b1fc664d625d1316a 100644 (file)
--- a/src/lib/tcp/tcp_connection.cc
+++ b/src/lib/tcp/tcp_connection.cc
@@ -239,21 +239,27 @@ void
 TcpConnection::doWrite(TcpResponsePtr response) {
     try {
         if (response->wireDataAvail()) {
-            // Create instance of the callback. It is safe to pass the local instance
-            // of the callback, because the underlying std functions make copies
-            // as needed.
+            // Create instance of the callback. It is safe to pass the
+            // local instance of the callback, because the underlying
+            // std functions make copies as needed.
             SocketCallback cb(std::bind(&TcpConnection::socketWriteCallback,
                                         shared_from_this(),
                                         response,
                                         ph::_1,   // error
                                         ph::_2)); // bytes_transferred
             if (tcp_socket_) {
+                LOG_DEBUG(tcp_logger, isc::log::DBGLVL_TRACE_BASIC,
+                          TCP_SERVER_RESPONSE_SEND)
+                    .arg(getRemoteEndpointAddressAsText());
                 tcp_socket_->asyncSend(response->getWireData(),
                                        response->getWireDataSize(),
                                        cb);
                 return;
             }
             if (tls_socket_) {
+                LOG_DEBUG(tcp_logger, isc::log::DBGLVL_TRACE_BASIC,
+                          TLS_SERVER_RESPONSE_SEND)
+                    .arg(getRemoteEndpointAddressAsText());
                 tls_socket_->asyncSend(response->getWireData(),
                                        response->getWireDataSize(),
                                        cb);
@@ -312,7 +318,7 @@ TcpConnection::acceptorCallback(const boost::system::error_code& ec) {
                 .arg(static_cast<unsigned>(idle_timeout_/1000));
         } else {
             LOG_DEBUG(tcp_logger, isc::log::DBGLVL_TRACE_DETAIL,
-                      TCP_CONNECTION_HANDSHAKE_START)
+                      TLS_CONNECTION_HANDSHAKE_START)
                 .arg(getRemoteEndpointAddressAsText())
                 .arg(static_cast<unsigned>(idle_timeout_/1000));
         }
@@ -324,13 +330,13 @@ TcpConnection::acceptorCallback(const boost::system::error_code& ec) {
 void
 TcpConnection::handshakeCallback(const boost::system::error_code& ec) {
     if (ec) {
-        LOG_INFO(tcp_logger, TCP_CONNECTION_HANDSHAKE_FAILED)
+        LOG_INFO(tcp_logger, TLS_CONNECTION_HANDSHAKE_FAILED)
             .arg(getRemoteEndpointAddressAsText())
             .arg(ec.message());
         stopThisConnection();
     } else {
         LOG_DEBUG(tcp_logger, isc::log::DBGLVL_TRACE_DETAIL,
-                  TCP_REQUEST_RECEIVE_START)
+                  TLS_REQUEST_RECEIVE_START)
             .arg(getRemoteEndpointAddressAsText());
 
         doRead();
@@ -366,7 +372,8 @@ TcpConnection::socketReadCallback(TcpRequestPtr request,
 
     TcpRequestPtr next_request = request;
     if (length) {
-        LOG_DEBUG(tcp_logger, isc::log::DBGLVL_TRACE_DETAIL_DATA, TCP_DATA_RECEIVED)
+        LOG_DEBUG(tcp_logger, isc::log::DBGLVL_TRACE_DETAIL_DATA,
+                  TCP_DATA_RECEIVED)
             .arg(length)
             .arg(getRemoteEndpointAddressAsText());
         WireData input_data(input_buf_.begin(), input_buf_.begin() + length);
@@ -445,6 +452,10 @@ TcpConnection::socketWriteCallback(TcpResponsePtr response,
         }
     }
 
+    LOG_DEBUG(tcp_logger, isc::log::DBGLVL_TRACE_DETAIL_DATA, TCP_DATA_SENT)
+        .arg(length)
+        .arg(getRemoteEndpointAddressAsText());
+
     // Since each response has its own wire data, it is not really
     // possible that the number of bytes written is larger than the size
     // of the buffer. But, let's be safe and set the length to the size

diff --git a/src/lib/tcp/tcp_messages.cc b/src/lib/tcp/tcp_messages.cc
index 281ac58df6f3d6d71df070c82b8997d250cf62ac..5dc70ea18f04f220078be7de0b8544342fdc3196 100644 (file)
--- a/src/lib/tcp/tcp_messages.cc
+++ b/src/lib/tcp/tcp_messages.cc
@@ -12,20 +12,23 @@ extern const isc::log::MessageID MT_TCP_LISTENER_MGR_STOPPED = "MT_TCP_LISTENER_
 extern const isc::log::MessageID MT_TCP_LISTENER_MGR_STOPPING = "MT_TCP_LISTENER_MGR_STOPPING";
 extern const isc::log::MessageID TCP_CLIENT_REQUEST_RECEIVED = "TCP_CLIENT_REQUEST_RECEIVED";
 extern const isc::log::MessageID TCP_CONNECTION_CLOSE_CALLBACK_FAILED = "TCP_CONNECTION_CLOSE_CALLBACK_FAILED";
-extern const isc::log::MessageID TCP_CONNECTION_HANDSHAKE_FAILED = "TCP_CONNECTION_HANDSHAKE_FAILED";
-extern const isc::log::MessageID TCP_CONNECTION_HANDSHAKE_START = "TCP_CONNECTION_HANDSHAKE_START";
 extern const isc::log::MessageID TCP_CONNECTION_REJECTED_BY_FILTER = "TCP_CONNECTION_REJECTED_BY_FILTER";
 extern const isc::log::MessageID TCP_CONNECTION_SHUTDOWN = "TCP_CONNECTION_SHUTDOWN";
 extern const isc::log::MessageID TCP_CONNECTION_SHUTDOWN_FAILED = "TCP_CONNECTION_SHUTDOWN_FAILED";
 extern const isc::log::MessageID TCP_CONNECTION_STOP = "TCP_CONNECTION_STOP";
 extern const isc::log::MessageID TCP_CONNECTION_STOP_FAILED = "TCP_CONNECTION_STOP_FAILED";
 extern const isc::log::MessageID TCP_DATA_RECEIVED = "TCP_DATA_RECEIVED";
+extern const isc::log::MessageID TCP_DATA_SENT = "TCP_DATA_SENT";
 extern const isc::log::MessageID TCP_IDLE_CONNECTION_TIMEOUT_OCCURRED = "TCP_IDLE_CONNECTION_TIMEOUT_OCCURRED";
 extern const isc::log::MessageID TCP_PREMATURE_CONNECTION_TIMEOUT_OCCURRED = "TCP_PREMATURE_CONNECTION_TIMEOUT_OCCURRED";
 extern const isc::log::MessageID TCP_REQUEST_RECEIVED_FAILED = "TCP_REQUEST_RECEIVED_FAILED";
 extern const isc::log::MessageID TCP_REQUEST_RECEIVE_START = "TCP_REQUEST_RECEIVE_START";
 extern const isc::log::MessageID TCP_SERVER_RESPONSE_SEND = "TCP_SERVER_RESPONSE_SEND";
 extern const isc::log::MessageID TCP_SERVER_RESPONSE_SEND_DETAILS = "TCP_SERVER_RESPONSE_SEND_DETAILS";
+extern const isc::log::MessageID TLS_CONNECTION_HANDSHAKE_FAILED = "TLS_CONNECTION_HANDSHAKE_FAILED";
+extern const isc::log::MessageID TLS_CONNECTION_HANDSHAKE_START = "TLS_CONNECTION_HANDSHAKE_START";
+extern const isc::log::MessageID TLS_REQUEST_RECEIVE_START = "TLS_REQUEST_RECEIVE_START";
+extern const isc::log::MessageID TLS_SERVER_RESPONSE_SEND = "TLS_SERVER_RESPONSE_SEND";
 
 } // namespace tcp
 } // namespace isc
@@ -38,20 +41,23 @@ const char* values[] = {
     "MT_TCP_LISTENER_MGR_STOPPING", "Stopping MtTcpListenerMgr for %1:%2",
     "TCP_CLIENT_REQUEST_RECEIVED", "received TCP request from %1",
     "TCP_CONNECTION_CLOSE_CALLBACK_FAILED", "Connection close callback threw an exception",
-    "TCP_CONNECTION_HANDSHAKE_FAILED", "TLS handshake with %1 failed with %2",
-    "TCP_CONNECTION_HANDSHAKE_START", "start TLS handshake with %1 with timeout %2",
     "TCP_CONNECTION_REJECTED_BY_FILTER", "connection from %1 has been denied by the connection filter.",
     "TCP_CONNECTION_SHUTDOWN", "shutting down TCP connection from %1",
     "TCP_CONNECTION_SHUTDOWN_FAILED", "shutting down TCP connection failed",
     "TCP_CONNECTION_STOP", "stopping TCP connection from %1",
     "TCP_CONNECTION_STOP_FAILED", "stopping TCP connection failed",
     "TCP_DATA_RECEIVED", "received %1 bytes from %2",
+    "TCP_DATA_SENT", "send %1 bytes to %2",
     "TCP_IDLE_CONNECTION_TIMEOUT_OCCURRED", "closing connection with %1 as a result of a timeout",
     "TCP_PREMATURE_CONNECTION_TIMEOUT_OCCURRED", "premature connection timeout occurred: in transaction ? %1, transid: %2, current_transid: %3",
     "TCP_REQUEST_RECEIVED_FAILED", "An unexpected error occurred processing a request from %1, error: %2",
     "TCP_REQUEST_RECEIVE_START", "start receiving request from %1 with timeout %2",
-    "TCP_SERVER_RESPONSE_SEND", "sending TCP response %1 to %2",
+    "TCP_SERVER_RESPONSE_SEND", "sending TCP response to %1",
     "TCP_SERVER_RESPONSE_SEND_DETAILS", "detailed information about response sent to %1:\n%2",
+    "TLS_CONNECTION_HANDSHAKE_FAILED", "TLS handshake with %1 failed with %2",
+    "TLS_CONNECTION_HANDSHAKE_START", "start TLS handshake with %1 with timeout %2",
+    "TLS_REQUEST_RECEIVE_START", "start receiving request from %1 with timeout %2",
+    "TLS_SERVER_RESPONSE_SEND", "sending TLS response to %1",
     NULL
 };
 

diff --git a/src/lib/tcp/tcp_messages.h b/src/lib/tcp/tcp_messages.h
index a312b7c3717d1cc3a2008b96c3eea5e9bbf47153..7dc458cbb73f2ad268137f09042991864b0a03d8 100644 (file)
--- a/src/lib/tcp/tcp_messages.h
+++ b/src/lib/tcp/tcp_messages.h
@@ -13,20 +13,23 @@ extern const isc::log::MessageID MT_TCP_LISTENER_MGR_STOPPED;
 extern const isc::log::MessageID MT_TCP_LISTENER_MGR_STOPPING;
 extern const isc::log::MessageID TCP_CLIENT_REQUEST_RECEIVED;
 extern const isc::log::MessageID TCP_CONNECTION_CLOSE_CALLBACK_FAILED;
-extern const isc::log::MessageID TCP_CONNECTION_HANDSHAKE_FAILED;
-extern const isc::log::MessageID TCP_CONNECTION_HANDSHAKE_START;
 extern const isc::log::MessageID TCP_CONNECTION_REJECTED_BY_FILTER;
 extern const isc::log::MessageID TCP_CONNECTION_SHUTDOWN;
 extern const isc::log::MessageID TCP_CONNECTION_SHUTDOWN_FAILED;
 extern const isc::log::MessageID TCP_CONNECTION_STOP;
 extern const isc::log::MessageID TCP_CONNECTION_STOP_FAILED;
 extern const isc::log::MessageID TCP_DATA_RECEIVED;
+extern const isc::log::MessageID TCP_DATA_SENT;
 extern const isc::log::MessageID TCP_IDLE_CONNECTION_TIMEOUT_OCCURRED;
 extern const isc::log::MessageID TCP_PREMATURE_CONNECTION_TIMEOUT_OCCURRED;
 extern const isc::log::MessageID TCP_REQUEST_RECEIVED_FAILED;
 extern const isc::log::MessageID TCP_REQUEST_RECEIVE_START;
 extern const isc::log::MessageID TCP_SERVER_RESPONSE_SEND;
 extern const isc::log::MessageID TCP_SERVER_RESPONSE_SEND_DETAILS;
+extern const isc::log::MessageID TLS_CONNECTION_HANDSHAKE_FAILED;
+extern const isc::log::MessageID TLS_CONNECTION_HANDSHAKE_START;
+extern const isc::log::MessageID TLS_REQUEST_RECEIVE_START;
+extern const isc::log::MessageID TLS_SERVER_RESPONSE_SEND;
 
 } // namespace tcp
 } // namespace isc

diff --git a/src/lib/tcp/tcp_messages.mes b/src/lib/tcp/tcp_messages.mes
index 7c97369c7a91bd95a8a45bb2d93c827430838d64..6b6c77e53456d3542f2f4265198e99d42e7378f4 100644 (file)
--- a/src/lib/tcp/tcp_messages.mes
+++ b/src/lib/tcp/tcp_messages.mes
@@ -30,16 +30,6 @@ This is an error message emitted when the close connection callback
 registered on the connection failed unexpectedly.  This is a programmatic
 error that should be submitted as a bug.
 
-% TCP_CONNECTION_HANDSHAKE_FAILED TLS handshake with %1 failed with %2
-This information message is issued when the TLS handshake failed at the
-server side. The client address and the error message are displayed.
-
-% TCP_CONNECTION_HANDSHAKE_START start TLS handshake with %1 with timeout %2
-This debug message is issued when the server starts the TLS handshake
-with the remote endpoint. The first argument specifies the address
-of the remote endpoint. The second argument specifies request timeout in
-seconds.
-
 % TCP_CONNECTION_REJECTED_BY_FILTER connection from %1 has been denied by the connection filter.
 This debug message is issued when the server's connection filter rejects
 a new connection based on the client's ip address.
@@ -69,6 +59,12 @@ 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.
 
+% TCP_DATA_SENT send %1 bytes to %2
+This debug message is issued when the server sends a chunk of data to
+the remote endpoint. This may include the whole response or only a part
+of the response. The first argument specifies the amount of sent data.
+The second argument specifies an address of the remote endpoint.
+
 % TCP_IDLE_CONNECTION_TIMEOUT_OCCURRED closing connection with %1 as a result of a timeout
 This debug message is issued when the TCP connection is being closed as a
 result of being idle.
@@ -91,11 +87,10 @@ over the established connection. The first argument specifies the address
 of the remote endpoint. The second argument specifies request timeout in
 seconds.
 
-% TCP_SERVER_RESPONSE_SEND sending TCP response %1 to %2
+% TCP_SERVER_RESPONSE_SEND sending TCP response to %1
 This debug message is issued when the server is starting to send a TCP
-response to a remote endpoint. The first argument holds basic information
-about the response (TCP version number and status code). The second
-argument specifies an address of the remote endpoint.
+response to a remote endpoint. The argument specifies an address of
+the remote endpoint.
 
 % TCP_SERVER_RESPONSE_SEND_DETAILS detailed information about response sent to %1:\n%2
 This debug message is issued right before the server sends a TCP response
@@ -104,3 +99,24 @@ 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.
+
+% TLS_CONNECTION_HANDSHAKE_FAILED TLS handshake with %1 failed with %2
+This information message is issued when the TLS handshake failed at the
+server side. The client address and the error message are displayed.
+
+% TLS_CONNECTION_HANDSHAKE_START start TLS handshake with %1 with timeout %2
+This debug message is issued when the server starts the TLS handshake
+with the remote endpoint. The first argument specifies the address
+of the remote endpoint. The second argument specifies request timeout in
+seconds.
+
+% TLS_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.
+
+% TLS_SERVER_RESPONSE_SEND sending TLS response to %1
+This debug message is issued when the server is starting to send a TLS
+response to a remote endpoint. The argument specifies an address of
+the remote endpoint.