SERVER-21854 Add request id to RemoteCommandRequest

Having identifier associated with each request allows us to trace requests
throughout the ASIO network threads.

This change doesn't fix the bug, but makes investigation easier.

5 files changed, 82 insertions, 37 deletions

diff --git a/src/mongo/executor/network_interface_asio.cpp b/src/mongo/executor/network_interface_asio.cpp
index b609c368269..cf2f7f36d94 100644
--- a/src/mongo/executor/network_interface_asio.cpp
+++ b/src/mongo/executor/network_interface_asio.cpp
@@ -189,7 +189,8 @@ void NetworkInterfaceASIO::startCommand(const TaskExecutor::CallbackHandle& cbHa
         StatusWith<ConnectionPool::ConnectionHandle> swConn) {
 
         if (!swConn.isOK()) {
-            LOG(2) << "Failed to get connection from pool: " << swConn.getStatus();
+            LOG(2) << "Failed to get connection from pool for request " << request.id << ": "
+                   << swConn.getStatus();
 
             bool wasPreviouslyCanceled = false;
             {
@@ -265,7 +266,8 @@ void NetworkInterfaceASIO::startCommand(const TaskExecutor::CallbackHandle& cbHa
 
                 // The above conditional guarantees that the adjusted timeout will never underflow.
                 invariant(op->_request.timeout > getConnectionDuration);
-                auto adjustedTimeout = op->_request.timeout - getConnectionDuration;
+                const auto adjustedTimeout = op->_request.timeout - getConnectionDuration;
+                const auto requestId = op->_request.id;
 
                 op->_timeoutAlarm = op->_owner->_timerFactory->make(&op->_strand, adjustedTimeout);
 
@@ -277,28 +279,31 @@ void NetworkInterfaceASIO::startCommand(const TaskExecutor::CallbackHandle& cbHa
                     generation = access->id;
                 }
 
-                op->_timeoutAlarm->asyncWait([this, op, access, generation](std::error_code ec) {
-                    if (!ec) {
-                        // We must pass a check for safe access before using op inside the
-                        // callback or we may attempt access on an invalid pointer.
-                        stdx::lock_guard<stdx::mutex> lk(access->mutex);
-                        if (generation != access->id) {
-                            // The operation has been cleaned up, do not access.
-                            return;
+                op->_timeoutAlarm->asyncWait(
+                    [this, op, access, generation, requestId](std::error_code ec) {
+                        if (!ec) {
+                            // We must pass a check for safe access before using op inside the
+                            // callback or we may attempt access on an invalid pointer.
+                            stdx::lock_guard<stdx::mutex> lk(access->mutex);
+                            if (generation != access->id) {
+                                // The operation has been cleaned up, do not access.
+                                return;
+                            }
+
+                            LOG(2) << "Operation " << requestId << " timed out.";
+
+                            // 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.
+                            op->_timedOut = 1;
+                            if (op->_connection) {
+                                op->_connection->cancel();
+                            }
+                        } else {
+                            LOG(2) << "Failed to time operation " << requestId
+                                   << " out: " << ec.message();
                         }
-
-                        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.
-                        op->_timedOut = 1;
-                        if (op->_connection) {
-                            op->_connection->cancel();
-                        }
-                    } else {
-                        LOG(4) << "failed to time operation out: " << ec.message();
-                    }
-                });
+                    });
             }
 
             _beginCommunication(op);
diff --git a/src/mongo/executor/network_interface_asio_command.cpp b/src/mongo/executor/network_interface_asio_command.cpp
index 9e21021d70e..2abb09f321f 100644
--- a/src/mongo/executor/network_interface_asio_command.cpp
+++ b/src/mongo/executor/network_interface_asio_command.cpp
@@ -340,7 +340,8 @@ 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();
+    LOG(2) << "Starting asynchronous command " << op->request().id << " 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/remote_command_request.cpp b/src/mongo/executor/remote_command_request.cpp
index f9b2bb10533..d1c10cdd1f9 100644
--- a/src/mongo/executor/remote_command_request.cpp
+++ b/src/mongo/executor/remote_command_request.cpp
@@ -30,17 +30,52 @@
 
 #include "mongo/executor/remote_command_request.h"
 
+#include "mongo/platform/atomic_word.h"
 #include "mongo/util/mongoutils/str.h"
 
 namespace mongo {
 namespace executor {
+namespace {
+
+// Used to generate unique identifiers for requests so they can be traced throughout the
+// asynchronous networking logs
+AtomicUInt64 requestIdCounter(0);
+
+}  // namespace
 
 const Milliseconds RemoteCommandRequest::kNoTimeout{-1};
 const Date_t RemoteCommandRequest::kNoExpirationDate{Date_t::max()};
 
+RemoteCommandRequest::RemoteCommandRequest() : id(requestIdCounter.addAndFetch(1)) {}
+
+RemoteCommandRequest::RemoteCommandRequest(RequestId requestId,
+                                           const HostAndPort& theTarget,
+                                           const std::string& theDbName,
+                                           const BSONObj& theCmdObj,
+                                           const BSONObj& metadataObj,
+                                           Milliseconds timeoutMillis)
+    : id(requestId),
+      target(theTarget),
+      dbname(theDbName),
+      metadata(metadataObj),
+      cmdObj(theCmdObj),
+      timeout(timeoutMillis) {}
+
+RemoteCommandRequest::RemoteCommandRequest(const HostAndPort& theTarget,
+                                           const std::string& theDbName,
+                                           const BSONObj& theCmdObj,
+                                           const BSONObj& metadataObj,
+                                           Milliseconds timeoutMillis)
+    : RemoteCommandRequest(requestIdCounter.addAndFetch(1),
+                           theTarget,
+                           theDbName,
+                           theCmdObj,
+                           metadataObj,
+                           timeoutMillis) {}
+
 std::string RemoteCommandRequest::toString() const {
     str::stream out;
-    out << "RemoteCommand -- target:" << target.toString() << " db:" << dbname;
+    out << "RemoteCommand " << id << " -- target:" << target.toString() << " db:" << dbname;
 
     if (expirationDate != kNoExpirationDate) {
         out << " expDate:" << expirationDate.toString();
diff --git a/src/mongo/executor/remote_command_request.h b/src/mongo/executor/remote_command_request.h
index bcc8d4a1daf..7e5b96618af 100644
--- a/src/mongo/executor/remote_command_request.h
+++ b/src/mongo/executor/remote_command_request.h
@@ -49,22 +49,23 @@ struct RemoteCommandRequest {
     // Indicates that there is no expiration time by when the request needs to complete
     static const Date_t kNoExpirationDate;
 
-    RemoteCommandRequest() = default;
+    // Type to represent the internal id of this request
+    typedef uint64_t RequestId;
+
+    RemoteCommandRequest();
+
+    RemoteCommandRequest(RequestId requestId,
+                         const HostAndPort& theTarget,
+                         const std::string& theDbName,
+                         const BSONObj& theCmdObj,
+                         const BSONObj& metadataObj,
+                         Milliseconds timeoutMillis);
 
     RemoteCommandRequest(const HostAndPort& theTarget,
                          const std::string& theDbName,
                          const BSONObj& theCmdObj,
                          const BSONObj& metadataObj,
-                         Milliseconds timeoutMillis = kNoTimeout)
-        : target(theTarget),
-          dbname(theDbName),
-          metadata(metadataObj),
-          cmdObj(theCmdObj),
-          timeout(timeoutMillis) {
-        if (timeoutMillis == kNoTimeout) {
-            expirationDate = kNoExpirationDate;
-        }
-    }
+                         Milliseconds timeoutMillis = kNoTimeout);
 
     RemoteCommandRequest(const HostAndPort& theTarget,
                          const std::string& theDbName,
@@ -84,6 +85,9 @@ struct RemoteCommandRequest {
 
     std::string toString() const;
 
+    // Internal id of this request. Not interpereted and used for tracing purposes only.
+    RequestId id;
+
     HostAndPort target;
     std::string dbname;
     BSONObj metadata{rpc::makeEmptyMetadata()};
diff --git a/src/mongo/executor/thread_pool_task_executor.cpp b/src/mongo/executor/thread_pool_task_executor.cpp
index 79b8f3309c4..c45bce684cf 100644
--- a/src/mongo/executor/thread_pool_task_executor.cpp
+++ b/src/mongo/executor/thread_pool_task_executor.cpp
@@ -306,7 +306,7 @@ StatusWith<TaskExecutor::CallbackHandle> ThreadPoolTaskExecutor::scheduleRemoteC
     if (!cbHandle.isOK())
         return cbHandle;
     const auto cbState = _networkInProgressQueue.back();
-    LOG(4) << "Scheduling remote command request: " << scheduledRequest.toString();
+    LOG(3) << "Scheduling remote command request: " << scheduledRequest.toString();
     lk.unlock();
     _net->startCommand(
         cbHandle.getValue(),