SERVER-55870 Add diagnostic information to killOp and killSessionXXX logging

12 files changed, 159 insertions, 2 deletions

diff --git a/jstests/auth/kill_sessions_logging.js b/jstests/auth/kill_sessions_logging.js
new file mode 100644
index 00000000000..a32517d40c2
--- /dev/null
+++ b/jstests/auth/kill_sessions_logging.js
@@ -0,0 +1,75 @@
+// Test that killing a session logs a message.
+//
+// @tags: [requires_sharding]
+
+"use strict";
+
+function testFixtureSimple(name) {
+    this.name = name + " (simple)";
+    jsTest.log("Starting test: " + this.name);
+
+    this.mongod = MongoRunner.runMongod();
+    this.db = this.mongod.getDB("admin");
+    this.db.createUser({user: 'user', pwd: 'pwd', roles: ['root']});
+
+    jsTest.log(this.name + " initialization complete");
+
+    this.check = function() {
+        checkLog.contains(this.db, '"msg":"Success: kill session"', 15000);
+        jsTest.log(this.name + " verified successfully");
+    };
+
+    this.stop = function() {
+        jsTest.log(this.name + " shutting down");
+        MongoRunner.stopMongod(this.mongod);
+        jsTest.log(this.name + " shutdown complete");
+    };
+}
+
+function testFixtureShard(name) {
+    this.name = name + " (shard)";
+    jsTest.log("Starting test: " + this.name);
+
+    this.mongos = new ShardingTest({});
+    this.db = this.mongos.getDB("admin");
+    this.db.createUser({user: 'user', pwd: 'pwd', roles: ['root']});
+
+    jsTest.log(this.name + " initialization complete");
+
+    this.check = function() {
+        checkLog.contains(this.db, '"msg":"Success: kill session"', 15000);
+        jsTest.log(this.name + " verified successfully");
+    };
+
+    this.stop = function() {
+        jsTest.log(this.name + " shutting down");
+        this.mongos.stop();
+        jsTest.log(this.name + " shutdown complete");
+    };
+}
+
+const testKillSessions = function(fixture) {
+    const randomSessionId = UUID("193bd705-3941-4be4-b463-5ca01f384e6f");
+    assert.commandWorked(fixture.db.runCommand({killSessions: [{id: randomSessionId}]}));
+    fixture.check();
+    fixture.stop();
+};
+
+const testKillAllSessions = function(fixture) {
+    assert.commandWorked(fixture.db.runCommand({killAllSessions: [{user: "user", db: "admin"}]}));
+    fixture.check();
+    fixture.stop();
+};
+
+const testKillAllSessionsByPattern = function(fixture) {
+    fixture.db.runCommand({killAllSessionsByPattern: [{users: [{user: "user", db: "admin"}]}]});
+    fixture.check();
+    fixture.stop();
+};
+
+testKillSessions(new testFixtureSimple("testKillSessions"));
+testKillAllSessions(new testFixtureSimple("testKillAllSessions"));
+testKillAllSessionsByPattern(new testFixtureSimple("testKillAllSessionsByPattern"));
+testKillSessions(new testFixtureShard("testKillSessions"));
+testKillAllSessions(new testFixtureShard("testKillAllSessions"));
+testKillAllSessionsByPattern(new testFixtureShard("testKillAllSessionsByPattern"));
diff --git a/jstests/auth/killop_own_ops.js b/jstests/auth/killop_own_ops.js
index 2d851f02697..ae1058bca46 100644
--- a/jstests/auth/killop_own_ops.js
+++ b/jstests/auth/killop_own_ops.js
@@ -18,7 +18,8 @@ function runTest(m, failPointName) {
 
     admin.createUser({user: 'admin', pwd: 'password', roles: jsTest.adminUserRoles});
     admin.auth('admin', 'password');
-    db.createUser({user: 'reader', pwd: 'reader', roles: [{db: 'foo', role: 'read'}]});
+    const logReader = {db: 'admin', role: 'clusterMonitor'};
+    db.createUser({user: 'reader', pwd: 'reader', roles: [{db: 'foo', role: 'read'}, logReader]});
     db.createUser({user: 'otherReader', pwd: 'otherReader', roles: [{db: 'foo', role: 'read'}]});
     admin.createRole({
         role: 'opAdmin',
@@ -90,6 +91,7 @@ function runTest(m, failPointName) {
     var start = new Date();
     db.auth('reader', 'reader');
     assert.commandWorked(db.killOp(o[0]));
+    checkLog.contains(db, '"msg":"Successful killOp"');
     assert.commandWorked(db.adminCommand({configureFailPoint: failPointName, mode: "off"}));
 
     jsTestLog("Waiting for ops to terminate");
diff --git a/src/mongo/db/SConscript b/src/mongo/db/SConscript
index 35d82f2606c..81d69af7443 100644
--- a/src/mongo/db/SConscript
+++ b/src/mongo/db/SConscript
@@ -1601,6 +1601,7 @@ env.Library(
         '$BUILD_DIR/mongo/db/auth/auth',
         '$BUILD_DIR/mongo/db/auth/authprivilege',
         '$BUILD_DIR/mongo/idl/idl_parser',
+        '$BUILD_DIR/mongo/rpc/client_metadata',
         'api_parameters',
     ],
 )
diff --git a/src/mongo/db/commands/kill_all_sessions_by_pattern_command.cpp b/src/mongo/db/commands/kill_all_sessions_by_pattern_command.cpp
index 220c585ae78..552b51b4080 100644
--- a/src/mongo/db/commands/kill_all_sessions_by_pattern_command.cpp
+++ b/src/mongo/db/commands/kill_all_sessions_by_pattern_command.cpp
@@ -123,6 +123,7 @@ public:
         }
 
         uassertStatusOK(killSessionsCmdHelper(opCtx, result, patterns));
+        killSessionsReport(opCtx, cmdObj);
         return true;
     }
 } killAllSessionsByPatternCommand;
diff --git a/src/mongo/db/commands/kill_all_sessions_command.cpp b/src/mongo/db/commands/kill_all_sessions_command.cpp
index 27c201e6b1b..e1520f39f36 100644
--- a/src/mongo/db/commands/kill_all_sessions_command.cpp
+++ b/src/mongo/db/commands/kill_all_sessions_command.cpp
@@ -108,6 +108,7 @@ public:
         }
 
         uassertStatusOK(killSessionsCmdHelper(opCtx, result, patterns));
+        killSessionsReport(opCtx, cmdObj);
         return true;
     }
 } killAllSessionsCommand;
diff --git a/src/mongo/db/commands/kill_op.cpp b/src/mongo/db/commands/kill_op.cpp
index 0f792e21f09..ae190aa2a2a 100644
--- a/src/mongo/db/commands/kill_op.cpp
+++ b/src/mongo/db/commands/kill_op.cpp
@@ -60,6 +60,7 @@ public:
         result.append("info", "attempting to kill op");
         LOGV2(20482, "Going to kill op: {opId}", "Going to kill op", "opId"_attr = opId);
         KillOpCmdBase::killLocalOperation(opCtx, opId);
+        reportSuccessfulCompletion(opCtx, db, cmdObj);
 
         // killOp always reports success once past the auth check.
         return true;
diff --git a/src/mongo/db/commands/kill_op_cmd_base.cpp b/src/mongo/db/commands/kill_op_cmd_base.cpp
index 020d740bc92..f57fe108040 100644
--- a/src/mongo/db/commands/kill_op_cmd_base.cpp
+++ b/src/mongo/db/commands/kill_op_cmd_base.cpp
@@ -26,17 +26,51 @@
  *    exception statement from all source files in the program, then also delete
  *    it in the license file.
  */
+#include "mongo/db/auth/authorization_session.h"
+#define MONGO_LOGV2_DEFAULT_COMPONENT ::mongo::logv2::LogComponent::kCommand
 
 #include "mongo/platform/basic.h"
 
 #include "mongo/db/commands/kill_op_cmd_base.h"
 
 #include "mongo/bson/util/bson_extract.h"
+#include "mongo/db/auth/authentication_session.h"
 #include "mongo/db/operation_killer.h"
+#include "mongo/logv2/log.h"
+#include "mongo/rpc/metadata/client_metadata.h"
 #include "mongo/util/str.h"
 
 namespace mongo {
 
+void KillOpCmdBase::reportSuccessfulCompletion(OperationContext* opCtx,
+                                               const std::string& db,
+                                               const BSONObj& cmdObj) {
+
+    logv2::DynamicAttributes attr;
+
+    auto client = opCtx->getClient();
+    if (client) {
+        if (AuthorizationManager::get(client->getServiceContext())->isAuthEnabled()) {
+            auto user = AuthorizationSession::get(client)->getAuthenticatedUserNames();
+            attr.add("user", user->toBSON());
+        }
+
+        if (client->session()) {
+            attr.add("remote", client->session()->remote());
+        }
+
+        if (auto metadata = ClientMetadata::get(client)) {
+            attr.add("metadata", metadata->getDocument());
+        }
+    }
+
+    attr.add("db", db);
+    attr.add("command", cmdObj);
+
+    LOGV2(558700, "Successful killOp", attr);
+}
+
+
 Status KillOpCmdBase::checkAuthForCommand(Client* worker,
                                           const std::string& dbname,
                                           const BSONObj& cmdObj) const {
diff --git a/src/mongo/db/commands/kill_op_cmd_base.h b/src/mongo/db/commands/kill_op_cmd_base.h
index a68def842d4..57c914eb182 100644
--- a/src/mongo/db/commands/kill_op_cmd_base.h
+++ b/src/mongo/db/commands/kill_op_cmd_base.h
@@ -72,6 +72,10 @@ protected:
      */
     static unsigned int parseOpId(const BSONObj& cmdObj);
 
+    static void reportSuccessfulCompletion(OperationContext* opCtx,
+                                           const std::string& db,
+                                           const BSONObj& cmdObj);
+
     /**
      * Return whether the operation being killed is "local" or not. All operations on a mongod are
      * local. On a mongos, killOp may may kill an operation on a shard, or an operation "local" to
diff --git a/src/mongo/db/commands/kill_sessions_command.cpp b/src/mongo/db/commands/kill_sessions_command.cpp
index 1bb9c2e3a08..80d26ef32e7 100644
--- a/src/mongo/db/commands/kill_sessions_command.cpp
+++ b/src/mongo/db/commands/kill_sessions_command.cpp
@@ -134,6 +134,7 @@ public:
         }
 
         uassertStatusOK(killSessionsCmdHelper(opCtx, result, patterns));
+        killSessionsReport(opCtx, cmdObj);
         return true;
     }
 } killSessionsCommand;
diff --git a/src/mongo/db/kill_sessions_common.cpp b/src/mongo/db/kill_sessions_common.cpp
index 75fbc30ab65..0433935f5d5 100644
--- a/src/mongo/db/kill_sessions_common.cpp
+++ b/src/mongo/db/kill_sessions_common.cpp
@@ -38,6 +38,7 @@
 #include "mongo/db/service_context.h"
 #include "mongo/db/session_killer.h"
 #include "mongo/logv2/log.h"
+#include "mongo/rpc/metadata/client_metadata.h"
 
 namespace mongo {
 
@@ -92,4 +93,29 @@ Status killSessionsCmdHelper(OperationContext* opCtx,
     return Status::OK();
 }
 
+void killSessionsReport(OperationContext* opCtx, const BSONObj& cmdObj) {
+
+    logv2::DynamicAttributes attr;
+
+    auto client = opCtx->getClient();
+    if (client) {
+        if (AuthorizationManager::get(client->getServiceContext())->isAuthEnabled()) {
+            auto user = AuthorizationSession::get(client)->getAuthenticatedUserNames();
+            attr.add("user", user->toBSON());
+        }
+
+        if (client->session()) {
+            attr.add("remote", client->session()->remote());
+        }
+
+        if (auto metadata = ClientMetadata::get(client)) {
+            attr.add("metadata", metadata->getDocument());
+        }
+    }
+
+    attr.add("command", cmdObj);
+
+    LOGV2(558701, "Success: kill session", attr);
+}
+
 }  // namespace mongo
diff --git a/src/mongo/db/kill_sessions_common.h b/src/mongo/db/kill_sessions_common.h
index 5e749709a1b..44fb96857e9 100644
--- a/src/mongo/db/kill_sessions_common.h
+++ b/src/mongo/db/kill_sessions_common.h
@@ -56,6 +56,11 @@ Status killSessionsCmdHelper(OperationContext* opCtx,
                              BSONObjBuilder& result,
                              const KillAllSessionsByPatternSet& patterns);
 
+/**
+ * Helper for logging kill sessions command.
+ */
+void killSessionsReport(OperationContext* opCtx, const BSONObj& cmdObj);
+
 class ScopedKillAllSessionsByPatternImpersonator {
 public:
     ScopedKillAllSessionsByPatternImpersonator(OperationContext* opCtx,
diff --git a/src/mongo/s/commands/cluster_kill_op.cpp b/src/mongo/s/commands/cluster_kill_op.cpp
index 2ce1ecf79ef..08047081c5d 100644
--- a/src/mongo/s/commands/cluster_kill_op.cpp
+++ b/src/mongo/s/commands/cluster_kill_op.cpp
@@ -65,12 +65,18 @@ public:
         if (isKillingLocalOp(element)) {
             const unsigned int opId = KillOpCmdBase::parseOpId(cmdObj);
             killLocalOperation(opCtx, opId);
+            reportSuccessfulCompletion(opCtx, db, cmdObj);
 
             // killOp always reports success once past the auth check.
             return true;
         } else if (element.type() == BSONType::String) {
             // It's a string. Should be of the form shardid:opid.
-            return _killShardOperation(opCtx, element.str(), result);
+            if (_killShardOperation(opCtx, element.str(), result)) {
+                reportSuccessfulCompletion(opCtx, db, cmdObj);
+                return true;
+            } else {
+                return false;
+            }
         }
 
         uasserted(50760,