SERVER-25787 Clean up optime comparisons in ReplSetTest.awaitReplication()

2 files changed, 125 insertions, 78 deletions

diff --git a/src/mongo/shell/assert.js b/src/mongo/shell/assert.js
index 0bfffe59104..e9a3c69408e 100644
--- a/src/mongo/shell/assert.js
+++ b/src/mongo/shell/assert.js
@@ -149,7 +149,30 @@ assert.contains = function(o, arr, msg) {
     }
 };
 
-assert.soon = function(f, msg, timeout /*ms*/, interval) {
+/*
+ * This function transforms a given function, 'func', into a function 'safeFunc',
+ * where 'safeFunc' matches the behavior of 'func', except that it returns false
+ * in any instance where 'func' throws an exception. 'safeFunc' also prints
+ * message 'excMsg' upon catching such a thrown exception.
+ */
+function _convertExceptionToReturnStatus(func, excMsg) {
+    var safeFunc = () => {
+        try {
+            return func();
+        } catch (e) {
+            print(excMsg + ", exception: " + e);
+            return false;
+        }
+    };
+    return safeFunc;
+}
+
+/*
+ * Calls a function 'func' at repeated intervals until either func() returns true
+ * or more than 'timeout' milliseconds have elapsed. Throws an exception with
+ * message 'msg' after timing out.
+ */
+assert.soon = function(func, msg, timeout, interval) {
     if (assert._debug && msg)
         print("in assert for: " + msg);
 
@@ -158,7 +181,7 @@ assert.soon = function(f, msg, timeout /*ms*/, interval) {
             msg = "assert.soon failed, msg:" + msg;
         }
     } else {
-        msg = "assert.soon failed: " + f;
+        msg = "assert.soon failed: " + func;
     }
 
     var start = new Date();
@@ -166,11 +189,11 @@ assert.soon = function(f, msg, timeout /*ms*/, interval) {
     interval = interval || 200;
     var last;
     while (1) {
-        if (typeof(f) == "string") {
-            if (eval(f))
+        if (typeof(func) == "string") {
+            if (eval(func))
                 return;
         } else {
-            if (f())
+            if (func())
                 return;
         }
 
@@ -182,24 +205,43 @@ assert.soon = function(f, msg, timeout /*ms*/, interval) {
     }
 };
 
-/**
- * Wraps assert.soon to try...catch any function passed in.
+/*
+ * Calls a function 'func' at repeated intervals until either func() returns true without
+ * throwing an exception or more than 'timeout' milliseconds have elapsed. Throws an exception
+ * with message 'msg' after timing out.
  */
-assert.soonNoExcept = function(func, msg, timeout /*ms*/) {
-    /**
-     * Surrounds a function call by a try...catch to convert any exception to a print statement
-     * and return false.
-     */
-    function _convertExceptionToReturnStatus(func) {
-        try {
-            return func();
-        } catch (e) {
-            print("caught exception " + e);
-            return false;
+assert.soonNoExcept = function(func, msg, timeout) {
+    var safeFunc = _convertExceptionToReturnStatus(func, "assert.soonNoExcept caught exception");
+    assert.soon(safeFunc, msg, timeout);
+};
+
+/*
+ * Calls the given function 'func' repeatedly until either func() returns true
+ * or the number of attempted function calls is equal to 'num_attempts'.
+ * Throws an exception with message 'msg' after all attempts are used up.
+ */
+assert.retry = function(func, msg, num_attempts) {
+    var attempts_made = 0;
+    while (attempts_made < num_attempts) {
+        if (func()) {
+            return;
+        } else {
+            attempts_made += 1;
+            print("assert.retry failed on attempt " + attempts_made + " of " + num_attempts);
         }
     }
+    // Used up all attempts
+    doassert(msg);
+};
 
-    assert.soon((() => _convertExceptionToReturnStatus(func)), msg, timeout);
+/*
+ * Calls the given function 'func' repeatedly until either func() returns true without
+ * throwing an exception or the number of attempted function calls is equal to 'num_attempts'.
+ * Throws an exception with message 'msg' after all attempts are used up.
+ */
+assert.retryNoExcept = function(func, msg, num_attempts) {
+    var safeFunc = _convertExceptionToReturnStatus(func, "assert.retryNoExcept caught exception");
+    assert.retry(safeFunc, msg, num_attempts);
 };
 
 assert.time = function(f, msg, timeout /*ms*/) {
diff --git a/src/mongo/shell/replsettest.js b/src/mongo/shell/replsettest.js
index cd3f8c64b54..c5b0af553df 100644
--- a/src/mongo/shell/replsettest.js
+++ b/src/mongo/shell/replsettest.js
@@ -272,19 +272,6 @@ var ReplSetTest = function(opts) {
     }
 
     /**
-     * Returns the OpTime timestamp for the specified host by issuing replSetGetStatus.
-     */
-    function _getLastOpTimeTimestamp(conn) {
-        var myOpTime = _getLastOpTime(conn);
-        if (!myOpTime) {
-            // Must be an ARBITER
-            return undefined;
-        }
-
-        return myOpTime.ts ? myOpTime.ts : myOpTime;
-    }
-
-    /**
      * Returns the {readConcern: majority} OpTime for the host.
      * This is the OpTime of the host's "majority committed" snapshot.
      * This function may return an OpTime with Timestamp(0,0) and Term(0) if read concern majority
@@ -298,10 +285,10 @@ var ReplSetTest = function(opts) {
     }
 
     /**
-     * Returns the last durable OpTime timestamp for the host if running with journaling.
-     * Returns the last applied OpTime timestamp otherwise.
+     * Returns the last durable OpTime for the host if running with journaling.
+     * Returns the last applied OpTime otherwise.
      */
-    function _getDurableOpTimeTimestamp(conn) {
+    function _getDurableOpTime(conn) {
         var replSetStatus =
             assert.commandWorked(conn.getDB("admin").runCommand({replSetGetStatus: 1}));
 
@@ -311,9 +298,23 @@ var ReplSetTest = function(opts) {
         if (runningWithoutJournaling) {
             opTimeType = "appliedOpTime";
         }
-        return replSetStatus.optimes[opTimeType].ts;
+        return replSetStatus.optimes[opTimeType];
+    }
+
+    /*
+     * Checks if given optime object conforms to Protocol Version 1 optime format.
+     *
+     * PV1 Format:
+     * {ts:Timestamp, t:NumberLong}
+     *
+     */
+    function _isOptimeV1(optime) {
+        return (optime.hasOwnProperty("ts") && optime.hasOwnProperty("t"));
     }
 
+    /*
+     * Compares Timestamp objects. Returns true if ts1 is 'earlier' than ts2, else false.
+     */
     function _isEarlierTimestamp(ts1, ts2) {
         if (ts1.getTime() == ts2.getTime()) {
             return ts1.getInc() < ts2.getInc();
@@ -321,10 +322,22 @@ var ReplSetTest = function(opts) {
         return ts1.getTime() < ts2.getTime();
     }
 
+    /*
+     * Compares optimes. Returns true if ot1 is 'earlier' than ot2, else false.
+     *
+     * Note: Since Protocol Version 1 was introduced for replication, 'optimes'
+     * can come in two different formats. This function checks for this and changes
+     * any timestamps of PV0 format to PV1 format, by adding a default term number of -1,
+     * to make comparison logic generic for both formats.
+     *
+     * Optime Formats:
+     * PV0: Timestamp
+     * PV1: {ts:Timestamp, t:NumberLong}
+     */
     function _isEarlierOpTime(ot1, ot2) {
         // Make sure both optimes have a timestamp and a term.
-        ot1 = ot1.t ? ot1 : {ts: ot1, t: NumberLong(-1)};
-        ot2 = ot2.t ? ot2 : {ts: ot2, t: NumberLong(-1)};
+        var ot1 = _isOptimeV1(ot1) ? ot1 : {ts: ot1, t: NumberLong(-1)};
+        var ot2 = _isOptimeV1(ot2) ? ot2 : {ts: ot2, t: NumberLong(-1)};
 
         // If both optimes have a term that's not -1 and one has a lower term, return that optime.
         if (!friendlyEqual(ot1.t, NumberLong(-1)) && !friendlyEqual(ot2.t, NumberLong(-1))) {
@@ -714,7 +727,7 @@ var ReplSetTest = function(opts) {
             var master = self.getPrimary();
             assert.soonNoExcept(function() {
                 try {
-                    masterLatestOpTime = _getLastOpTimeTimestamp(master);
+                    masterLatestOpTime = _getLastOpTime(master);
                 } catch (e) {
                     print("ReplSetTest caught exception " + e);
                     return false;
@@ -726,33 +739,26 @@ var ReplSetTest = function(opts) {
 
         awaitLastOpTimeWrittenFn();
 
-        // get the latest config version from master. if there is a problem, grab master and try
-        // again
-        var configVersion;
-        var masterOpTime;
+        // get the latest config version from master (with a few retries in case of error)
+        var masterConfigVersion;
         var masterName;
         var master;
+        var num_attempts = 3;
 
-        try {
+        assert.retryNoExcept(() => {
             master = this.getPrimary();
-            configVersion = this.getReplSetConfigFromNode().version;
-            masterOpTime = _getLastOpTimeTimestamp(master);
+            masterConfigVersion = this.getReplSetConfigFromNode().version;
             masterName = master.toString().substr(14);  // strip "connection to "
-        } catch (e) {
-            master = this.getPrimary();
-            configVersion = this.getReplSetConfigFromNode().version;
-            masterOpTime = _getLastOpTimeTimestamp(master);
-            masterName = master.toString().substr(14);  // strip "connection to "
-        }
+            return true;
+        }, "ReplSetTest awaitReplication: couldnt get repl set config.", num_attempts);
 
-        print("ReplSetTest awaitReplication: starting: timestamp for primary, " + masterName +
-              ", is " + tojson(masterLatestOpTime) + ", last oplog entry is " +
-              tojsononeline(masterOpTime));
+        print("ReplSetTest awaitReplication: starting: optime for primary, " + masterName +
+              ", is " + tojson(masterLatestOpTime));
 
         assert.soonNoExcept(function() {
             try {
-                print("ReplSetTest awaitReplication: checking secondaries against timestamp " +
-                      tojson(masterLatestOpTime));
+                print("ReplSetTest awaitReplication: checking secondaries " +
+                      "against latest primary optime " + tojson(masterLatestOpTime));
                 var secondaryCount = 0;
                 for (var i = 0; i < self.liveNodes.slaves.length; i++) {
                     var slave = self.liveNodes.slaves[i];
@@ -761,21 +767,19 @@ var ReplSetTest = function(opts) {
                     var slaveConfigVersion =
                         slave.getDB("local")['system.replset'].findOne().version;
 
-                    if (configVersion != slaveConfigVersion) {
+                    if (masterConfigVersion != slaveConfigVersion) {
                         print("ReplSetTest awaitReplication: secondary #" + secondaryCount + ", " +
                               slaveName + ", has config version #" + slaveConfigVersion +
-                              ", but expected config version #" + configVersion);
+                              ", but expected config version #" + masterConfigVersion);
 
-                        if (slaveConfigVersion > configVersion) {
+                        if (slaveConfigVersion > masterConfigVersion) {
                             master = this.getPrimary();
-                            configVersion =
+                            masterConfigVersion =
                                 master.getDB("local")['system.replset'].findOne().version;
-                            masterOpTime = _getLastOpTimeTimestamp(master);
                             masterName = master.toString().substr(14);  // strip "connection to "
 
-                            print("ReplSetTest awaitReplication: timestamp for primary, " +
-                                  masterName + ", is " + tojson(masterLatestOpTime) +
-                                  ", last oplog entry is " + tojsononeline(masterOpTime));
+                            print("ReplSetTest awaitReplication: optime for primary, " +
+                                  masterName + ", is " + tojson(masterLatestOpTime));
                         }
 
                         return false;
@@ -793,23 +797,24 @@ var ReplSetTest = function(opts) {
 
                     slave.getDB("admin").getMongo().setSlaveOk();
 
-                    var getSecondaryTimestampFn = _getLastOpTimeTimestamp;
+                    var slaveOpTime;
                     if (secondaryOpTimeType == ReplSetTest.OpTimeType.LAST_DURABLE) {
-                        getSecondaryTimestampFn = _getDurableOpTimeTimestamp;
+                        slaveOpTime = _getDurableOpTime(slave);
+                    } else {
+                        slaveOpTime = _getLastOpTime(slave);
                     }
 
-                    var ts = getSecondaryTimestampFn(slave);
-                    if (masterLatestOpTime.t < ts.t ||
-                        (masterLatestOpTime.t == ts.t && masterLatestOpTime.i < ts.i)) {
-                        masterLatestOpTime = _getLastOpTimeTimestamp(master);
-                        print("ReplSetTest awaitReplication: timestamp for " + slaveName +
-                              " is newer, resetting latest to " + tojson(masterLatestOpTime));
+                    if (_isEarlierOpTime(masterLatestOpTime, slaveOpTime)) {
+                        masterLatestOpTime = _getLastOpTime(master);
+                        print("ReplSetTest awaitReplication: optime for " + slaveName +
+                              " is newer, resetting latest primary optime to " +
+                              tojson(masterLatestOpTime));
                         return false;
                     }
 
-                    if (!friendlyEqual(masterLatestOpTime, ts)) {
-                        print("ReplSetTest awaitReplication: timestamp for secondary #" +
-                              secondaryCount + ", " + slaveName + ", is " + tojson(ts) +
+                    if (!friendlyEqual(masterLatestOpTime, slaveOpTime)) {
+                        print("ReplSetTest awaitReplication: optime for secondary #" +
+                              secondaryCount + ", " + slaveName + ", is " + tojson(slaveOpTime) +
                               " but latest is " + tojson(masterLatestOpTime));
                         print("ReplSetTest awaitReplication: secondary #" + secondaryCount + ", " +
                               slaveName + ", is NOT synced");
@@ -821,7 +826,7 @@ var ReplSetTest = function(opts) {
                 }
 
                 print("ReplSetTest awaitReplication: finished: all " + secondaryCount +
-                      " secondaries synced at timestamp " + tojson(masterLatestOpTime));
+                      " secondaries synced at optime " + tojson(masterLatestOpTime));
                 return true;
             } catch (e) {
                 print("ReplSetTest awaitReplication: caught exception " + e + ';\n' + e.stack);
@@ -829,7 +834,7 @@ var ReplSetTest = function(opts) {
                 // We might have a new master now
                 awaitLastOpTimeWrittenFn();
 
-                print("ReplSetTest awaitReplication: resetting: timestamp for primary " +
+                print("ReplSetTest awaitReplication: resetting: optime for primary " +
                       self.liveNodes.master + " is " + tojson(masterLatestOpTime));
 
                 return false;