SERVER-20752 improve NetworkInterfaceASIO logging

- add a log component for ASIO, make it a subcomponent of Network
- add additional LOG(2), and LOG(3) messages for tracing
- remove a few redundant log messages

A previous version of this patch had a bug where we could access the
state of a freed AsyncOp.

15 files changed, 52 insertions, 19 deletions

diff --git a/src/mongo/executor/async_mock_stream_factory.cpp b/src/mongo/executor/async_mock_stream_factory.cpp
index dceb5069910..3132bab52b7 100644
--- a/src/mongo/executor/async_mock_stream_factory.cpp
+++ b/src/mongo/executor/async_mock_stream_factory.cpp
@@ -26,7 +26,7 @@
  *    it in the license file.
  */
 
-#define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kNetwork
+#define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kASIO
 
 #include "mongo/platform/basic.h"
 
diff --git a/src/mongo/executor/async_secure_stream.cpp b/src/mongo/executor/async_secure_stream.cpp
index e40fc61fbee..964f805d07d 100644
--- a/src/mongo/executor/async_secure_stream.cpp
+++ b/src/mongo/executor/async_secure_stream.cpp
@@ -26,7 +26,7 @@
  *    it in the license file.
  */
 
-#define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kNetwork
+#define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kASIO
 
 #include "mongo/platform/basic.h"
 
@@ -88,7 +88,8 @@ void AsyncSecureStream::_handleHandshake(std::error_code ec, const std::string&
     auto certStatus =
         getSSLManager()->parseAndValidatePeerCertificate(_stream.native_handle(), hostName);
     if (!certStatus.isOK()) {
-        warning() << certStatus.getStatus();
+        warning() << "Failed to validate peer certificate during SSL handshake: "
+                  << certStatus.getStatus();
     }
     _userHandler(make_error_code(certStatus.getStatus().code()));
 }
diff --git a/src/mongo/executor/async_stream.cpp b/src/mongo/executor/async_stream.cpp
index 0b7f5289c38..1ac8a47470f 100644
--- a/src/mongo/executor/async_stream.cpp
+++ b/src/mongo/executor/async_stream.cpp
@@ -26,7 +26,7 @@
  *    it in the license file.
  */
 
-#define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kExecutor
+#define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kASIO
 
 #include "mongo/platform/basic.h"
 
diff --git a/src/mongo/executor/async_stream_common.cpp b/src/mongo/executor/async_stream_common.cpp
index d27ea5cbaaa..a7878865341 100644
--- a/src/mongo/executor/async_stream_common.cpp
+++ b/src/mongo/executor/async_stream_common.cpp
@@ -26,7 +26,7 @@
  *    it in the license file.
  */
 
-#define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kExecutor
+#define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kASIO
 
 #include "mongo/platform/basic.h"
 
@@ -37,9 +37,9 @@
 namespace mongo {
 namespace executor {
 
-void warnCloseFailed(std::error_code ec) {
+void logCloseFailed(std::error_code ec) {
     invariant(ec);
-    warning() << "failed to close stream:" << ec.message();
+    LOG(1) << "failed to close stream: " << ec.message();
 }
 
 }  // namespace executor
diff --git a/src/mongo/executor/async_stream_common.h b/src/mongo/executor/async_stream_common.h
index aacb5c8f089..7b06881551c 100644
--- a/src/mongo/executor/async_stream_common.h
+++ b/src/mongo/executor/async_stream_common.h
@@ -35,7 +35,7 @@
 namespace mongo {
 namespace executor {
 
-void warnCloseFailed(std::error_code ec);
+void logCloseFailed(std::error_code ec);
 
 template <typename ASIOStream>
 void destroyStream(ASIOStream* stream, bool connected) {
@@ -46,7 +46,7 @@ void destroyStream(ASIOStream* stream, bool connected) {
     stream->shutdown(asio::ip::tcp::socket::shutdown_both, ec);
     stream->close();
     if (ec) {
-        warnCloseFailed(ec);
+        logCloseFailed(ec);
     }
 }
 
diff --git a/src/mongo/executor/network_interface_asio.cpp b/src/mongo/executor/network_interface_asio.cpp
index c490b81b439..0379738ee93 100644
--- a/src/mongo/executor/network_interface_asio.cpp
+++ b/src/mongo/executor/network_interface_asio.cpp
@@ -26,7 +26,7 @@
  *    it in the license file.
  */
 
-#define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kExecutor
+#define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kASIO
 
 #include "mongo/platform/basic.h"
 
@@ -98,6 +98,7 @@ void NetworkInterfaceASIO::startup() {
     _serviceRunner = stdx::thread([this]() {
         setThreadName("NetworkInterfaceASIO");
         try {
+            LOG(2) << "The NetworkInterfaceASIO worker thread is spinning up";
             asio::io_service::work work(_io_service);
             _io_service.run();
         } catch (...) {
@@ -113,6 +114,7 @@ void NetworkInterfaceASIO::shutdown() {
     _state.store(State::kShutdown);
     _io_service.stop();
     _serviceRunner.join();
+    LOG(2) << "NetworkInterfaceASIO shutdown successfully";
 }
 
 void NetworkInterfaceASIO::waitForWork() {
@@ -164,12 +166,16 @@ void NetworkInterfaceASIO::startCommand(const TaskExecutor::CallbackHandle& cbHa
         invariant(insertResult.second);
     }
 
+    LOG(2) << "startCommand: " << request.toString();
+
     auto startTime = now();
 
     auto nextStep = [this, startTime, cbHandle, request, onFinish](
         StatusWith<ConnectionPool::ConnectionHandle> swConn) {
 
         if (!swConn.isOK()) {
+            LOG(2) << "Failed to get connection from pool: " << swConn.getStatus();
+
             bool wasPreviouslyCanceled = false;
             {
                 stdx::lock_guard<stdx::mutex> lk(_inProgressMutex);
@@ -239,6 +245,8 @@ void NetworkInterfaceASIO::startCommand(const TaskExecutor::CallbackHandle& cbHa
                         return;
                     }
 
+                    LOG(2) << "Operation timed out: " << op->request().toString();
+
                     // An operation may be in mid-flight when it times out, so we
                     // cancel any in-progress async calls but do not complete the operation now.
                     if (op->_connection) {
diff --git a/src/mongo/executor/network_interface_asio_auth.cpp b/src/mongo/executor/network_interface_asio_auth.cpp
index c3e915d8d80..9202fbaf51e 100644
--- a/src/mongo/executor/network_interface_asio_auth.cpp
+++ b/src/mongo/executor/network_interface_asio_auth.cpp
@@ -26,7 +26,7 @@
  *    it in the license file.
  */
 
-#define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kExecutor
+#define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kASIO
 
 #include "mongo/platform/basic.h"
 
diff --git a/src/mongo/executor/network_interface_asio_command.cpp b/src/mongo/executor/network_interface_asio_command.cpp
index 66a4dcf8045..0100c91f50d 100644
--- a/src/mongo/executor/network_interface_asio_command.cpp
+++ b/src/mongo/executor/network_interface_asio_command.cpp
@@ -26,7 +26,7 @@
  *    it in the license file.
  */
 
-#define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kExecutor
+#define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kASIO
 
 #include "mongo/platform/basic.h"
 
@@ -237,11 +237,14 @@ void NetworkInterfaceASIO::_beginCommunication(AsyncOp* op) {
     // codepath.
 
     if (op->_inSetup) {
+        log() << "Successfully connected to " << op->request().target.toString();
         op->_inSetup = false;
         op->finish(RemoteCommandResponse());
         return;
     }
 
+    LOG(3) << "Initiating asynchronous command: " << op->request().toString();
+
     auto beginStatus = op->beginCommand(op->request(), _metadataHook.get());
     if (!beginStatus.isOK()) {
         return _completeOperation(op, beginStatus);
@@ -259,7 +262,6 @@ void NetworkInterfaceASIO::_completedOpCallback(AsyncOp* op) {
 }
 
 void NetworkInterfaceASIO::_networkErrorCallback(AsyncOp* op, const std::error_code& ec) {
-    LOG(3) << "networking error occurred";
     if (ec.category() == mongoErrorCategory()) {
         // If we get a Mongo error code, we can preserve it.
         _completeOperation(op, Status(ErrorCodes::fromInt(ec.value()), ec.message()));
@@ -278,6 +280,12 @@ void NetworkInterfaceASIO::_completeOperation(AsyncOp* op, const ResponseStatus&
         op->_timeoutAlarm->cancel();
     }
 
+    if (op->_inSetup) {
+        // If we fail during connection, we won't be able to access any of our members after calling
+        // op->finish().
+        log() << "Failed to connect to " << op->request().target << " - " << resp.getStatus();
+    }
+
     op->finish(resp);
 
     std::unique_ptr<AsyncOp> ownedOp;
@@ -288,13 +296,19 @@ void NetworkInterfaceASIO::_completeOperation(AsyncOp* op, const ResponseStatus&
         auto iter = _inProgress.find(op);
 
         // This can happen if we fail during setup.
-        if (iter == _inProgress.end())
+        if (iter == _inProgress.end()) {
             return;
+        }
 
         ownedOp = std::move(iter->second);
         _inProgress.erase(iter);
     }
 
+    if (!resp.isOK()) {
+        LOG(2) << "Failed to execute command: " << op->request().toString()
+               << " reason: " << resp.getStatus();
+    }
+
     invariant(ownedOp);
 
     auto conn = std::move(op->_connectionPoolHandle);
@@ -324,6 +338,7 @@ void NetworkInterfaceASIO::_completeOperation(AsyncOp* op, const ResponseStatus&
 }
 
 void NetworkInterfaceASIO::_asyncRunCommand(AsyncOp* op, NetworkOpHandler handler) {
+    LOG(2) << "Starting asynchronous command on host " << op->request().target.toString();
     // We invert the following steps below to run a command:
     // 1 - send the given command
     // 2 - receive a header for the response
diff --git a/src/mongo/executor/network_interface_asio_connect.cpp b/src/mongo/executor/network_interface_asio_connect.cpp
index 9d1634f47e8..696ee271a63 100644
--- a/src/mongo/executor/network_interface_asio_connect.cpp
+++ b/src/mongo/executor/network_interface_asio_connect.cpp
@@ -26,7 +26,7 @@
  *    it in the license file.
  */
 
-#define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kExecutor
+#define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kASIO
 
 #include "mongo/platform/basic.h"
 
@@ -88,6 +88,8 @@ void NetworkInterfaceASIO::AsyncConnection::setServerProtocols(rpc::ProtocolSet
 }
 
 void NetworkInterfaceASIO::_connect(AsyncOp* op) {
+    LOG(1) << "Connecting to " << op->request().target.toString();
+
     tcp::resolver::query query(op->request().target.host(),
                                std::to_string(op->request().target.port()));
     // TODO: Investigate how we might hint or use shortcuts to resolve when possible.
diff --git a/src/mongo/executor/network_interface_asio_integration_test.cpp b/src/mongo/executor/network_interface_asio_integration_test.cpp
index d48883903f3..a4cbf4a69eb 100644
--- a/src/mongo/executor/network_interface_asio_integration_test.cpp
+++ b/src/mongo/executor/network_interface_asio_integration_test.cpp
@@ -26,7 +26,7 @@
  *    it in the license file.
  */
 
-#define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kExecutor
+#define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kASIO
 
 #include "mongo/platform/basic.h"
 
diff --git a/src/mongo/executor/network_interface_asio_operation.cpp b/src/mongo/executor/network_interface_asio_operation.cpp
index d5ca86d8cc8..e890c7c4e5f 100644
--- a/src/mongo/executor/network_interface_asio_operation.cpp
+++ b/src/mongo/executor/network_interface_asio_operation.cpp
@@ -26,7 +26,7 @@
  *    it in the license file.
  */
 
-#define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kExecutor
+#define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kASIO
 
 #include "mongo/platform/basic.h"
 
@@ -105,6 +105,7 @@ NetworkInterfaceASIO::AsyncOp::AsyncOp(NetworkInterfaceASIO* const owner,
       _inSetup(true) {}
 
 void NetworkInterfaceASIO::AsyncOp::cancel() {
+    LOG(2) << "Canceling operation; original request was: " << request().toString();
     std::shared_ptr<AsyncOp::AccessControl> access;
     std::size_t generation;
     {
diff --git a/src/mongo/executor/network_interface_asio_test.cpp b/src/mongo/executor/network_interface_asio_test.cpp
index ef21dcc30cb..ceabe364287 100644
--- a/src/mongo/executor/network_interface_asio_test.cpp
+++ b/src/mongo/executor/network_interface_asio_test.cpp
@@ -26,7 +26,7 @@
  *    it in the license file.
  */
 
-#define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kNetwork
+#define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kASIO
 
 #include "mongo/platform/basic.h"
 
diff --git a/src/mongo/executor/network_interface_perf_test.cpp b/src/mongo/executor/network_interface_perf_test.cpp
index 90926f9ade9..0c79cdb727a 100644
--- a/src/mongo/executor/network_interface_perf_test.cpp
+++ b/src/mongo/executor/network_interface_perf_test.cpp
@@ -26,7 +26,7 @@
  *    it in the license file.
  */
 
-#define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kNetwork
+#define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kASIO
 
 #include "mongo/platform/basic.h"
 
diff --git a/src/mongo/logger/log_component.cpp b/src/mongo/logger/log_component.cpp
index 0382abb8692..8f3c82b49b6 100644
--- a/src/mongo/logger/log_component.cpp
+++ b/src/mongo/logger/log_component.cpp
@@ -81,6 +81,7 @@ LogComponent LogComponent::parent() const {
         case kDefault:
             return kNumLogComponents;
             DECLARE_LOG_COMPONENT_PARENT(kJournal, kStorage);
+            DECLARE_LOG_COMPONENT_PARENT(kASIO, kNetwork);
         case kNumLogComponents:
             return kNumLogComponents;
         default:
@@ -121,6 +122,8 @@ StringData LogComponent::toStringData() const {
             return createStringData("write");
         case kFTDC:
             return createStringData("ftdc");
+        case kASIO:
+            return createStringData("asio");
         case kNumLogComponents:
             return createStringData("total");
             // No default. Compiler should complain if there's a log component that's not handled.
@@ -187,6 +190,8 @@ StringData LogComponent::getNameForLog() const {
             return createStringData("WRITE   ");
         case kFTDC:
             return createStringData("FTDC    ");
+        case kASIO:
+            return createStringData("ASIO    ");
         case kNumLogComponents:
             return createStringData("TOTAL   ");
             // No default. Compiler should complain if there's a log component that's not handled.
diff --git a/src/mongo/logger/log_component.h b/src/mongo/logger/log_component.h
index 4fdac77e12d..a771e20558a 100644
--- a/src/mongo/logger/log_component.h
+++ b/src/mongo/logger/log_component.h
@@ -58,6 +58,7 @@ public:
         kJournal,
         kWrite,
         kFTDC,
+        kASIO,
         kNumLogComponents
     };