SERVER-36499 Add test coverage for prepared transaction duration in currOp

3 files changed, 181 insertions, 37 deletions

diff --git a/jstests/noPassthrough/currentop_active_transaction.js b/jstests/noPassthrough/currentop_active_transaction.js
index d5c66a7101b..5f3ebab3547 100644
--- a/jstests/noPassthrough/currentop_active_transaction.js
+++ b/jstests/noPassthrough/currentop_active_transaction.js
@@ -1,11 +1,84 @@
 /**
  * Confirms inclusion of a 'transaction' object containing lsid and txnNumber in
- * currentOp() for active transaction.
- * @tags: [uses_transactions]
+ * currentOp() for a prepared transaction and an active non-prepared transaction.
+ * @tags: [uses_transactions, uses_prepare_transaction]
  */
 
 (function() {
     'use strict';
+    load("jstests/libs/parallel_shell_helpers.js");
+
+    function transactionFn(isPrepared) {
+        const collName = 'currentop_active_transaction';
+        const session = db.getMongo().startSession({causalConsistency: false});
+        const sessionDB = session.getDatabase('test');
+
+        session.startTransaction({readConcern: {level: 'snapshot'}});
+        sessionDB[collName].update({}, {x: 2});
+        if (isPrepared) {
+            // Load the prepare helpers to be called in the parallel shell.
+            load('jstests/core/txns/libs/prepare_helpers.js');
+            const prepareTimestamp = PrepareHelpers.prepareTransaction(session);
+            PrepareHelpers.commitTransactionAfterPrepareTS(session, prepareTimestamp);
+        } else {
+            session.commitTransaction();
+        }
+    }
+
+    function checkCurrentOpFields(currentOp,
+                                  isPrepared,
+                                  operationTime,
+                                  timeBeforeTransactionStarts,
+                                  timeAfterTransactionStarts,
+                                  timeBeforeCurrentOp) {
+        const transactionDocument = currentOp[0].transaction;
+        assert.eq(transactionDocument.parameters.autocommit,
+                  false,
+                  "Expected 'autocommit' to be false but got " +
+                      transactionDocument.parameters.autocommit + " instead: " +
+                      tojson(transactionDocument));
+        assert.docEq(transactionDocument.parameters.readConcern,
+                     {level: 'snapshot'},
+                     "Expected 'readConcern' to be level: snapshot but got " +
+                         tojson(transactionDocument.parameters.readConcern) + " instead: " +
+                         tojson(transactionDocument));
+        assert.gte(transactionDocument.readTimestamp,
+                   operationTime,
+                   "Expected 'readTimestamp' to be at least " + operationTime + " but got " +
+                       transactionDocument.readTimestamp + " instead: " +
+                       tojson(transactionDocument));
+        assert.gte(ISODate(transactionDocument.startWallClockTime),
+                   timeBeforeTransactionStarts,
+                   "Expected 'startWallClockTime' to be at least" + timeBeforeTransactionStarts +
+                       " but got " + transactionDocument.startWallClockTime + " instead: " +
+                       tojson(transactionDocument));
+        const expectedTimeOpen = (timeBeforeCurrentOp - timeAfterTransactionStarts) * 1000;
+        assert.gt(transactionDocument.timeOpenMicros,
+                  expectedTimeOpen,
+                  "Expected 'timeOpenMicros' to be at least" + expectedTimeOpen + " but got " +
+                      transactionDocument.timeOpenMicros + " instead: " +
+                      tojson(transactionDocument));
+        assert.gte(transactionDocument.timeActiveMicros,
+                   0,
+                   "Expected 'timeActiveMicros' to be at least 0: " + tojson(transactionDocument));
+        assert.gte(
+            transactionDocument.timeInactiveMicros,
+            0,
+            "Expected 'timeInactiveMicros' to be at least 0: " + tojson(transactionDocument));
+        const actualExpiryTime = ISODate(transactionDocument.expiryTime).getTime();
+        const expectedExpiryTime =
+            ISODate(transactionDocument.startWallClockTime).getTime() + transactionLifeTime * 1000;
+        assert.eq(expectedExpiryTime,
+                  actualExpiryTime,
+                  "Expected 'expiryTime' to be " + expectedExpiryTime + " but got " +
+                      actualExpiryTime + " instead: " + tojson(transactionDocument));
+        if (isPrepared) {
+            assert.gte(
+                transactionDocument.timePreparedMicros,
+                0,
+                "Expected 'timePreparedMicros' to be at least 0: " + tojson(transactionDocument));
+        }
+    }
 
     const rst = new ReplSetTest({nodes: 1});
     rst.startSet();
@@ -20,8 +93,7 @@
     // Run an operation prior to starting the transaction and save its operation time. We will use
     // this later to assert that our subsequent transaction's readTimestamp is greater than or equal
     // to this operation time.
-    const res = assert.commandWorked(testDB.runCommand({insert: collName, documents: [{x: 1}]}));
-    const operationTime = res.operationTime;
+    let res = assert.commandWorked(testDB.runCommand({insert: collName, documents: [{x: 1}]}));
 
     // Set and save the transaction's lifetime. We will use this later to assert that our
     // transaction's expiry time is equal to its start time + lifetime.
@@ -31,28 +103,67 @@
 
     // This will make the transaction hang.
     assert.commandWorked(testDB.adminCommand(
-        {configureFailPoint: 'setInterruptOnlyPlansCheckForInterruptHang', mode: 'alwaysOn'}));
+        {configureFailPoint: 'hangAfterSettingPrepareStartTime', mode: 'alwaysOn'}));
     assert.commandWorked(
         testDB.adminCommand({setParameter: 1, internalQueryExecYieldIterations: 1}));
 
-    const transactionFn = function() {
-        const collName = 'currentop_active_transaction';
-        const session = db.getMongo().startSession({causalConsistency: false});
-        const sessionDB = session.getDatabase('test');
+    let timeBeforeTransactionStarts = new ISODate();
+    let isPrepared = true;
+    const joinPreparedTransaction =
+        startParallelShell(funWithArgs(transactionFn, isPrepared), rst.ports[0]);
 
-        session.startTransaction({readConcern: {level: 'snapshot'}});
-        sessionDB[collName].update({}, {x: 2});
-        session.commitTransaction();
+    const prepareTransactionFilter = {
+        active: true,
+        'lsid': {$exists: true},
+        'transaction.parameters.txnNumber': {$eq: 0},
+        'transaction.parameters.autocommit': {$eq: false},
+        'transaction.timePreparedMicros': {$exists: true}
     };
 
-    const timeBeforeTransactionStarts = new ISODate();
-    const transactionProcess = startParallelShell(transactionFn, rst.ports[0]);
+    // Keep running currentOp() until we see the transaction subdocument.
+    assert.soon(function() {
+        return 1 ===
+            adminDB.aggregate([{$currentOp: {}}, {$match: prepareTransactionFilter}]).itcount();
+    });
+
+    let timeAfterTransactionStarts = new ISODate();
+    // Sleep here to allow some time between timeAfterTransactionStarts and timeBeforeCurrentOp to
+    // elapse.
+    sleep(100);
+    let timeBeforeCurrentOp = new ISODate();
+    // Check that the currentOp's transaction subdocument's fields align with our expectations.
+    let currentOp =
+        adminDB.aggregate([{$currentOp: {}}, {$match: prepareTransactionFilter}]).toArray();
+    checkCurrentOpFields(currentOp,
+                         isPrepared,
+                         res.operationTime,
+                         timeBeforeTransactionStarts,
+                         timeAfterTransactionStarts,
+                         timeBeforeCurrentOp);
+
+    // Now the transaction can proceed.
+    assert.commandWorked(
+        testDB.adminCommand({configureFailPoint: 'hangAfterSettingPrepareStartTime', mode: 'off'}));
+    joinPreparedTransaction();
+
+    // Conduct the same test but with a non-prepared transaction.
+    res = assert.commandWorked(testDB.runCommand({insert: collName, documents: [{x: 1}]}));
+
+    // This will make the transaction hang.
+    assert.commandWorked(testDB.adminCommand(
+        {configureFailPoint: 'setInterruptOnlyPlansCheckForInterruptHang', mode: 'alwaysOn'}));
+
+    timeBeforeTransactionStarts = new ISODate();
+    isPrepared = false;
+    const joinTransaction =
+        startParallelShell(funWithArgs(transactionFn, isPrepared), rst.ports[0]);
 
     const transactionFilter = {
         active: true,
         'lsid': {$exists: true},
         'transaction.parameters.txnNumber': {$eq: 0},
-        'transaction.parameters.autocommit': {$eq: false}
+        'transaction.parameters.autocommit': {$eq: false},
+        'transaction.timePreparedMicros': {$exists: false}
     };
 
     // Keep running currentOp() until we see the transaction subdocument.
@@ -60,30 +171,24 @@
         return 1 === adminDB.aggregate([{$currentOp: {}}, {$match: transactionFilter}]).itcount();
     });
 
-    const timeAfterTransactionStarts = new ISODate();
+    timeAfterTransactionStarts = new ISODate();
     // Sleep here to allow some time between timeAfterTransactionStarts and timeBeforeCurrentOp to
     // elapse.
     sleep(100);
-    const timeBeforeCurrentOp = new ISODate();
+    timeBeforeCurrentOp = new ISODate();
     // Check that the currentOp's transaction subdocument's fields align with our expectations.
-    let currentOp = adminDB.aggregate([{$currentOp: {}}, {$match: transactionFilter}]).toArray();
-    let transactionDocument = currentOp[0].transaction;
-    assert.eq(transactionDocument.parameters.autocommit, false);
-    assert.eq(transactionDocument.parameters.readConcern, {level: 'snapshot'});
-    assert.gte(transactionDocument.readTimestamp, operationTime);
-    assert.gte(ISODate(transactionDocument.startWallClockTime), timeBeforeTransactionStarts);
-    assert.gt(transactionDocument.timeOpenMicros,
-              (timeBeforeCurrentOp - timeAfterTransactionStarts) * 1000);
-    assert.gte(transactionDocument.timeActiveMicros, 0);
-    assert.gte(transactionDocument.timeInactiveMicros, 0);
-    assert.eq(
-        ISODate(transactionDocument.expiryTime).getTime(),
-        ISODate(transactionDocument.startWallClockTime).getTime() + transactionLifeTime * 1000);
+    currentOp = adminDB.aggregate([{$currentOp: {}}, {$match: transactionFilter}]).toArray();
+    checkCurrentOpFields(currentOp,
+                         isPrepared,
+                         res.operationTime,
+                         timeBeforeTransactionStarts,
+                         timeAfterTransactionStarts,
+                         timeBeforeCurrentOp);
 
     // Now the transaction can proceed.
     assert.commandWorked(testDB.adminCommand(
         {configureFailPoint: 'setInterruptOnlyPlansCheckForInterruptHang', mode: 'off'}));
-    transactionProcess();
+    joinTransaction();
 
     rst.stopSet();
 })();
diff --git a/jstests/noPassthrough/currentop_transaction_metrics.js b/jstests/noPassthrough/currentop_transaction_metrics.js
index db975a9dac7..1a023e10cf5 100644
--- a/jstests/noPassthrough/currentop_transaction_metrics.js
+++ b/jstests/noPassthrough/currentop_transaction_metrics.js
@@ -1,17 +1,18 @@
 /**
  * Tests that the time-tracking metrics in the 'transaction' object in currentOp() are being tracked
  * correctly.
- * @tags: [uses_transactions]
+ * @tags: [uses_transactions, uses_prepare_transaction]
  */
 
 (function() {
     'use strict';
+    load("jstests/core/txns/libs/prepare_helpers.js");
 
     const rst = new ReplSetTest({nodes: 1});
     rst.startSet();
     rst.initiate();
 
-    const collName = 'currentop_active_transaction';
+    const collName = 'currentop_transaction_metrics';
     const testDB = rst.getPrimary().getDB('test');
     const adminDB = rst.getPrimary().getDB('admin');
     testDB.runCommand({drop: collName, writeConcern: {w: "majority"}});
@@ -32,6 +33,7 @@
         'lsid': {$exists: true},
         'transaction.parameters.txnNumber': {$eq: 0},
         'transaction.parameters.autocommit': {$eq: false},
+        'transaction.timePreparedMicros': {$exists: false}
     };
 
     let currentOp = adminDB.aggregate([{$currentOp: {}}, {$match: transactionFilter}]).toArray();
@@ -42,7 +44,28 @@
     assert.gte(transactionDocument.timeOpenMicros,
                transactionDocument.timeActiveMicros + transactionDocument.timeInactiveMicros);
 
-    session.commitTransaction();
+    // Check that preparing the transaction enables the 'timePreparedMicros' field in currentOp.
+    const prepareTimestamp = PrepareHelpers.prepareTransaction(session);
+
+    const prepareTransactionFilter = {
+        active: false,
+        'lsid': {$exists: true},
+        'transaction.parameters.txnNumber': {$eq: 0},
+        'transaction.parameters.autocommit': {$eq: false},
+        'transaction.timePreparedMicros': {$exists: true}
+    };
+
+    currentOp = adminDB.aggregate([{$currentOp: {}}, {$match: prepareTransactionFilter}]).toArray();
+    assert.eq(currentOp.length, 1);
+
+    // Check that the currentOp's transaction subdocument's fields align with our expectations.
+    const prepareTransactionDocument = currentOp[0].transaction;
+    assert.gte(prepareTransactionDocument.timeOpenMicros,
+               prepareTransactionDocument.timeActiveMicros +
+                   prepareTransactionDocument.timeInactiveMicros);
+    assert.gte(prepareTransactionDocument.timePreparedMicros, 0);
+
+    PrepareHelpers.commitTransactionAfterPrepareTS(session, prepareTimestamp);
     session.endSession();
 
     rst.stopSet();
diff --git a/jstests/sharding/aggregation_currentop.js b/jstests/sharding/aggregation_currentop.js
index 9db8c772495..f6f114f1e82 100644
--- a/jstests/sharding/aggregation_currentop.js
+++ b/jstests/sharding/aggregation_currentop.js
@@ -13,7 +13,7 @@
  * applicable.
  *
  * This test requires replica set configuration and user credentials to persist across a restart.
- * @tags: [requires_persistence, uses_transactions]
+ * @tags: [requires_persistence, uses_transactions, uses_prepare_transaction]
  */
 
 // Restarts cause issues with authentication for awaiting replication.
@@ -765,6 +765,17 @@ TestData.skipAwaitingReplicationOnShardsBeforeCheckingUUIDs = true;
             .itcount(),
         0);
 
+    // Prepare the transaction and ensure the prepareTimestamp is valid.
+    const prepareRes = assert.commandWorked(sessionDB.adminCommand(
+        {prepareTransaction: 1, txnNumber: NumberLong(0), autocommit: false}));
+    assert(prepareRes.prepareTimestamp,
+           "prepareTransaction did not return a 'prepareTimestamp': " + tojson(prepareRes));
+    assert(prepareRes.prepareTimestamp instanceof Timestamp,
+           'prepareTimestamp was not a Timestamp: ' + tojson(prepareRes));
+    assert.neq(prepareRes.prepareTimestamp,
+               Timestamp(0, 0),
+               "prepareTimestamp cannot be null: " + tojson(prepareRes));
+
     const timeBeforeCurrentOp = new ISODate();
 
     // Check that the currentOp's transaction subdocument's fields align with our expectations.
@@ -783,16 +794,21 @@ TestData.skipAwaitingReplicationOnShardsBeforeCheckingUUIDs = true;
                (timeBeforeCurrentOp - timeAfterTransactionStarts) * 1000);
     assert.gte(transactionDocument.timeActiveMicros, 0);
     assert.gte(transactionDocument.timeInactiveMicros, 0);
+    assert.gte(transactionDocument.timePreparedMicros, 0);
     assert.eq(
         ISODate(transactionDocument.expiryTime).getTime(),
         ISODate(transactionDocument.startWallClockTime).getTime() + transactionLifeTime * 1000);
 
-    // Allow the transactions to complete and close the session.
+    // Allow the transactions to complete and close the session. We must commit prepared
+    // transactions at a timestamp greater than the prepare timestamp.
+    const commitTimestamp =
+        Timestamp(prepareRes.prepareTimestamp.getTime(), prepareRes.prepareTimestamp.getInc() + 1);
     assert.commandWorked(sessionDB.adminCommand({
         commitTransaction: 1,
         txnNumber: NumberLong(0),
         autocommit: false,
-        writeConcern: {w: 'majority'}
+        writeConcern: {w: 'majority'},
+        commitTimestamp: commitTimestamp
     }));
     session.endSession();