SERVER-36414 Add readConcern to slow transaction logging

(cherry picked from commit 17f64a621f5dc1431e663bdaa46208432f67c441)

3 files changed, 85 insertions, 20 deletions

diff --git a/src/mongo/db/session.cpp b/src/mongo/db/session.cpp
index c66d99ea214..8c2b7c51805 100644
--- a/src/mongo/db/session.cpp
+++ b/src/mongo/db/session.cpp
@@ -886,7 +886,8 @@ void Session::abortActiveTransaction(OperationContext* opCtx) {
     // Log the transaction if its duration is longer than the slowMS command threshold.
     _logSlowTransaction(lock,
                         &(opCtx->lockState()->getLockerInfo())->stats,
-                        MultiDocumentTransactionState::kAborted);
+                        MultiDocumentTransactionState::kAborted,
+                        repl::ReadConcernArgs::get(opCtx));
 }
 
 void Session::_abortTransaction(WithLock wl) {
@@ -910,7 +911,8 @@ void Session::_abortTransaction(WithLock wl) {
     if (_txnResourceStash) {
         _logSlowTransaction(wl,
                             &(_txnResourceStash->locker()->getLockerInfo())->stats,
-                            MultiDocumentTransactionState::kAborted);
+                            MultiDocumentTransactionState::kAborted,
+                            _txnResourceStash->getReadConcernArgs());
         ServerTransactionsMetrics::get(getGlobalServiceContext())->decrementCurrentInactive();
     } else {
         ServerTransactionsMetrics::get(getGlobalServiceContext())->decrementCurrentActive();
@@ -1090,7 +1092,8 @@ void Session::_commitTransaction(stdx::unique_lock<stdx::mutex> lk, OperationCon
     // Log the transaction if its duration is longer than the slowMS command threshold.
     _logSlowTransaction(lk,
                         &(opCtx->lockState()->getLockerInfo())->stats,
-                        MultiDocumentTransactionState::kCommitted);
+                        MultiDocumentTransactionState::kCommitted,
+                        repl::ReadConcernArgs::get(opCtx));
 }
 
 BSONObj Session::reportStashedState() const {
@@ -1174,7 +1177,8 @@ void Session::_reportTransactionStats(WithLock wl,
 }
 
 std::string Session::_transactionInfoForLog(const SingleThreadedLockStats* lockStats,
-                                            MultiDocumentTransactionState terminationCause) {
+                                            MultiDocumentTransactionState terminationCause,
+                                            repl::ReadConcernArgs readConcernArgs) {
     invariant(lockStats);
     invariant(terminationCause == MultiDocumentTransactionState::kCommitted ||
               terminationCause == MultiDocumentTransactionState::kAborted);
@@ -1187,8 +1191,8 @@ std::string Session::_transactionInfoForLog(const SingleThreadedLockStats* lockS
     _sessionId.serialize(&lsidBuilder);
     lsidBuilder.doneFast();
     parametersBuilder.append("txnNumber", _activeTxnNumber);
-    // TODO: SERVER-35174 Add readConcern to parameters here once pushed.
     parametersBuilder.append("autocommit", _autocommit);
+    readConcernArgs.appendInfo(&parametersBuilder);
     s << "parameters:" << parametersBuilder.obj().toString() << ",";
 
     s << " readTimestamp:" << _speculativeTransactionReadOpTime.getTimestamp().toString() << ",";
@@ -1223,14 +1227,15 @@ std::string Session::_transactionInfoForLog(const SingleThreadedLockStats* lockS
 
 void Session::_logSlowTransaction(WithLock wl,
                                   const SingleThreadedLockStats* lockStats,
-                                  MultiDocumentTransactionState terminationCause) {
+                                  MultiDocumentTransactionState terminationCause,
+                                  repl::ReadConcernArgs readConcernArgs) {
     // Only log multi-document transactions.
     if (_txnState != MultiDocumentTransactionState::kNone) {
         // Log the transaction if its duration is longer than the slowMS command threshold.
         if (_singleTransactionStats->getDuration(curTimeMicros64()) >
             serverGlobalParams.slowMS * 1000ULL) {
             log(logger::LogComponent::kCommand)
-                << _transactionInfoForLog(lockStats, terminationCause);
+                << _transactionInfoForLog(lockStats, terminationCause, readConcernArgs);
         }
     }
 }
diff --git a/src/mongo/db/session.h b/src/mongo/db/session.h
index 7ae41455d49..7c10b3b8825 100644
--- a/src/mongo/db/session.h
+++ b/src/mongo/db/session.h
@@ -360,12 +360,13 @@ public:
     BSONObj reportStashedState() const;
 
     std::string transactionInfoForLogForTest(const SingleThreadedLockStats* lockStats,
-                                             bool committed) {
+                                             bool committed,
+                                             repl::ReadConcernArgs readConcernArgs) {
         stdx::lock_guard<stdx::mutex> lk(_mutex);
         MultiDocumentTransactionState terminationCause = committed
             ? MultiDocumentTransactionState::kCommitted
             : MultiDocumentTransactionState::kAborted;
-        return _transactionInfoForLog(lockStats, terminationCause);
+        return _transactionInfoForLog(lockStats, terminationCause, readConcernArgs);
     }
 
     void addMultikeyPathInfo(MultikeyPathInfo info) {
@@ -481,14 +482,16 @@ private:
     // transaction must be committed or aborted when this function is called.
     void _logSlowTransaction(WithLock wl,
                              const SingleThreadedLockStats* lockStats,
-                             MultiDocumentTransactionState terminationCause);
+                             MultiDocumentTransactionState terminationCause,
+                             repl::ReadConcernArgs readConcernArgs);
 
     // This method returns a string with information about a slow transaction. The format of the
     // logging string produced should match the format used for slow operation logging. A
     // transaction must be completed (committed or aborted) and a valid LockStats reference must be
     // passed in order for this method to be called.
     std::string _transactionInfoForLog(const SingleThreadedLockStats* lockStats,
-                                       MultiDocumentTransactionState terminationCause);
+                                       MultiDocumentTransactionState terminationCause,
+                                       repl::ReadConcernArgs readConcernArgs);
 
     // Reports transaction stats for both active and inactive transactions using the provided
     // builder.
diff --git a/src/mongo/db/session_test.cpp b/src/mongo/db/session_test.cpp
index 8d976fa9251..85fe5393633 100644
--- a/src/mongo/db/session_test.cpp
+++ b/src/mongo/db/session_test.cpp
@@ -2270,11 +2270,13 @@ void setupAdditiveMetrics(const int metricValue, OperationContext* opCtx) {
  */
 void buildParametersInfoString(StringBuilder* sb,
                                LogicalSessionId sessionId,
-                               const TxnNumber txnNum) {
+                               const TxnNumber txnNum,
+                               const repl::ReadConcernArgs readConcernArgs) {
     BSONObjBuilder lsidBuilder;
     sessionId.serialize(&lsidBuilder);
     (*sb) << "parameters:{ lsid: " << lsidBuilder.done().toString() << ", txnNumber: " << txnNum
-          << ", autocommit: false },";
+          << ", autocommit: false"
+          << ", readConcern: " << readConcernArgs.toBSON().getObjectField("readConcern") << " },";
 }
 
 /*
@@ -2321,7 +2323,8 @@ std::string buildTransactionInfoString(OperationContext* opCtx,
 
     // Building expected transaction info string.
     StringBuilder parametersInfo;
-    buildParametersInfoString(&parametersInfo, sessionId, txnNum);
+    buildParametersInfoString(
+        &parametersInfo, sessionId, txnNum, repl::ReadConcernArgs::get(opCtx));
 
     StringBuilder readTimestampInfo;
     readTimestampInfo
@@ -2372,6 +2375,15 @@ TEST_F(TransactionsMetricsTest, TestTransactionInfoForLogAfterCommit) {
     const TxnNumber txnNum = 1;
     opCtx()->setLogicalSessionId(sessionId);
     opCtx()->setTxnNumber(txnNum);
+
+    repl::ReadConcernArgs readConcernArgs;
+    ASSERT_OK(readConcernArgs.initialize(BSON("find"
+                                              << "test"
+                                              << repl::ReadConcernArgs::kReadConcernFieldName
+                                              << BSON(repl::ReadConcernArgs::kLevelFieldName
+                                                      << "snapshot"))));
+    repl::ReadConcernArgs::get(opCtx()) = readConcernArgs;
+
     session.beginOrContinueTxn(opCtx(), txnNum, false, true, "admin", "commitTransaction");
 
     // Initialize SingleTransactionStats AdditiveMetrics objects.
@@ -2384,7 +2396,7 @@ TEST_F(TransactionsMetricsTest, TestTransactionInfoForLogAfterCommit) {
     const auto lockerInfo = opCtx()->lockState()->getLockerInfo();
     ASSERT(lockerInfo);
     std::string testTransactionInfo =
-        session.transactionInfoForLogForTest(&lockerInfo->stats, true);
+        session.transactionInfoForLogForTest(&lockerInfo->stats, true, readConcernArgs);
 
     std::string expectedTransactionInfo =
         buildTransactionInfoString(opCtx(), &session, "committed", sessionId, txnNum, metricValue);
@@ -2399,6 +2411,15 @@ TEST_F(TransactionsMetricsTest, TestTransactionInfoForLogAfterAbort) {
     const TxnNumber txnNum = 1;
     opCtx()->setLogicalSessionId(sessionId);
     opCtx()->setTxnNumber(txnNum);
+
+    repl::ReadConcernArgs readConcernArgs;
+    ASSERT_OK(readConcernArgs.initialize(BSON("find"
+                                              << "test"
+                                              << repl::ReadConcernArgs::kReadConcernFieldName
+                                              << BSON(repl::ReadConcernArgs::kLevelFieldName
+                                                      << "snapshot"))));
+    repl::ReadConcernArgs::get(opCtx()) = readConcernArgs;
+
     session.beginOrContinueTxn(opCtx(), txnNum, false, true, "admin", "abortTransaction");
 
     // Initialize SingleTransactionStats AdditiveMetrics objects.
@@ -2411,7 +2432,7 @@ TEST_F(TransactionsMetricsTest, TestTransactionInfoForLogAfterAbort) {
     const auto lockerInfo = opCtx()->lockState()->getLockerInfo();
     ASSERT(lockerInfo);
     std::string testTransactionInfo =
-        session.transactionInfoForLogForTest(&lockerInfo->stats, false);
+        session.transactionInfoForLogForTest(&lockerInfo->stats, false, readConcernArgs);
 
     std::string expectedTransactionInfo =
         buildTransactionInfoString(opCtx(), &session, "aborted", sessionId, txnNum, metricValue);
@@ -2426,12 +2447,21 @@ DEATH_TEST_F(TransactionsMetricsTest, TestTransactionInfoForLogWithNoLockerInfoS
     const TxnNumber txnNum = 1;
     opCtx()->setLogicalSessionId(sessionId);
     opCtx()->setTxnNumber(txnNum);
+
+    repl::ReadConcernArgs readConcernArgs;
+    ASSERT_OK(readConcernArgs.initialize(BSON("find"
+                                              << "test"
+                                              << repl::ReadConcernArgs::kReadConcernFieldName
+                                              << BSON(repl::ReadConcernArgs::kLevelFieldName
+                                                      << "snapshot"))));
+    repl::ReadConcernArgs::get(opCtx()) = readConcernArgs;
+
     session.beginOrContinueTxn(opCtx(), txnNum, false, true, "testDB", "insert");
 
     session.unstashTransactionResources(opCtx(), "commitTransaction");
     session.commitTransaction(opCtx());
 
-    session.transactionInfoForLogForTest(nullptr, true);
+    session.transactionInfoForLogForTest(nullptr, true, readConcernArgs);
 }
 
 TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterSlowCommit) {
@@ -2442,6 +2472,15 @@ TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterSlowCommit) {
     const TxnNumber txnNum = 1;
     opCtx()->setLogicalSessionId(sessionId);
     opCtx()->setTxnNumber(txnNum);
+
+    repl::ReadConcernArgs readConcernArgs;
+    ASSERT_OK(readConcernArgs.initialize(BSON("find"
+                                              << "test"
+                                              << repl::ReadConcernArgs::kReadConcernFieldName
+                                              << BSON(repl::ReadConcernArgs::kLevelFieldName
+                                                      << "snapshot"))));
+    repl::ReadConcernArgs::get(opCtx()) = readConcernArgs;
+
     session.beginOrContinueTxn(opCtx(), txnNum, false, true, "admin", "commitTransaction");
     // Initialize SingleTransactionStats AdditiveMetrics objects.
     const int metricValue = 1;
@@ -2459,7 +2498,7 @@ TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterSlowCommit) {
     const auto lockerInfo = opCtx()->lockState()->getLockerInfo();
     ASSERT(lockerInfo);
     std::string expectedTransactionInfo =
-        session.transactionInfoForLogForTest(&lockerInfo->stats, true);
+        session.transactionInfoForLogForTest(&lockerInfo->stats, true, readConcernArgs);
     ASSERT_EQUALS(1, countLogLinesContaining(expectedTransactionInfo));
 }
 
@@ -2471,6 +2510,15 @@ TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterSlowAbort) {
     const TxnNumber txnNum = 1;
     opCtx()->setLogicalSessionId(sessionId);
     opCtx()->setTxnNumber(txnNum);
+
+    repl::ReadConcernArgs readConcernArgs;
+    ASSERT_OK(readConcernArgs.initialize(BSON("find"
+                                              << "test"
+                                              << repl::ReadConcernArgs::kReadConcernFieldName
+                                              << BSON(repl::ReadConcernArgs::kLevelFieldName
+                                                      << "snapshot"))));
+    repl::ReadConcernArgs::get(opCtx()) = readConcernArgs;
+
     session.beginOrContinueTxn(opCtx(), txnNum, false, true, "admin", "abortTransaction");
     // Initialize SingleTransactionStats AdditiveMetrics objects.
     const int metricValue = 1;
@@ -2488,7 +2536,7 @@ TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterSlowAbort) {
     const auto lockerInfo = opCtx()->lockState()->getLockerInfo();
     ASSERT(lockerInfo);
     std::string expectedTransactionInfo =
-        session.transactionInfoForLogForTest(&lockerInfo->stats, false);
+        session.transactionInfoForLogForTest(&lockerInfo->stats, false, readConcernArgs);
     ASSERT_EQUALS(1, countLogLinesContaining(expectedTransactionInfo));
 }
 
@@ -2500,6 +2548,15 @@ TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterSlowStashedAbort) {
     const TxnNumber txnNum = 1;
     opCtx()->setLogicalSessionId(sessionId);
     opCtx()->setTxnNumber(txnNum);
+
+    repl::ReadConcernArgs readConcernArgs;
+    ASSERT_OK(readConcernArgs.initialize(BSON("find"
+                                              << "test"
+                                              << repl::ReadConcernArgs::kReadConcernFieldName
+                                              << BSON(repl::ReadConcernArgs::kLevelFieldName
+                                                      << "snapshot"))));
+    repl::ReadConcernArgs::get(opCtx()) = readConcernArgs;
+
     session.beginOrContinueTxn(opCtx(), txnNum, false, true, "admin", "abortTransaction");
     // Initialize SingleTransactionStats AdditiveMetrics objects.
     const int metricValue = 1;
@@ -2520,7 +2577,7 @@ TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterSlowStashedAbort) {
     stopCapturingLogMessages();
 
     std::string expectedTransactionInfo =
-        session.transactionInfoForLogForTest(&lockerInfo->stats, false);
+        session.transactionInfoForLogForTest(&lockerInfo->stats, false, readConcernArgs);
     ASSERT_EQUALS(1, countLogLinesContaining(expectedTransactionInfo));
 }