mongodb/jstests/replsets/optime.js

// Tests tracking of latestOptime and earliestOptime in serverStatus.oplog
// Also tests tracking of wall clock times in replSetGetStatus

import {FeatureFlagUtil} from "jstests/libs/feature_flag_util.js";
import {ReplSetTest} from "jstests/libs/replsettest.js";

function timestampCompare(o1, o2) {
    if (o1.t < o2.t) {
        return -1;
    } else if (o1.t > o2.t) {
        return 1;
    } else {
        if (o1.i < o2.i) {
            return -1;
        } else if (o1.i > o2.i) {
            return 1;
        } else {
            return 0;
        }
    }
}

function wallTimeCompare(d1, d2) {
    if (d1 < d2) {
        return -1;
    } else if (d1 > d2) {
        return 1;
    } else {
        return 0;
    }
}

function optimesAndWallTimesAreEqual(replTest, isPersistent) {
    const reduceMajorityWriteLatency =
        FeatureFlagUtil.isPresentAndEnabled(replTest.getPrimary(), "ReduceMajorityWriteLatency");
    let prevReplStatus = replTest.nodes[0].getDB('admin').runCommand({replSetGetStatus: 1});
    let prevOptime = prevReplStatus.optimes.appliedOpTime.ts;
    let prevAppliedWallTime = prevReplStatus.optimes.lastAppliedWallTime;
    let prevDurableWallTime = prevReplStatus.optimes.lastDurableWallTime;
    let prevWrittenWallTime =
        (reduceMajorityWriteLatency) ? prevReplStatus.optimes.lastWrittenWallTime : null;
    for (var i = 1; i < replTest.nodes.length; i++) {
        let currentReplStatus = replTest.nodes[i].getDB('admin').runCommand({replSetGetStatus: 1});
        let currOptime = currentReplStatus.optimes.appliedOpTime.ts;
        let currAppliedWallTime = currentReplStatus.optimes.lastAppliedWallTime;
        let currDurableWallTime = currentReplStatus.optimes.lastDurableWallTime;
        let currWrittenWallTime =
            (reduceMajorityWriteLatency) ? currentReplStatus.optimes.lastWrittenWallTime : null;
        if (timestampCompare(prevOptime, currOptime) != 0 ||
            wallTimeCompare(prevAppliedWallTime, currAppliedWallTime) != 0 ||
            // If ReduceMajorityWriteLatency is set, the prevWrittenWallTime and
            // currWrittenWallTime will not be null, so they'll be truthy.
            (prevWrittenWallTime && currWrittenWallTime &&
             wallTimeCompare(prevWrittenWallTime, currWrittenWallTime) != 0) ||
            (isPersistent && wallTimeCompare(prevDurableWallTime, currDurableWallTime) != 0)) {
            jsTest.log("optimesAndWallTimesAreEqual returning false match, prevOptime: " +
                       tojson(prevOptime) + " latestOptime: " + tojson(currOptime) +
                       " prevAppliedWallTime: " + tojson(prevAppliedWallTime) +
                       " latestAppliedWallTime: " + tojson(currAppliedWallTime) +
                       " prevWrittenAppliedWallTime: " + tojson(prevWrittenWallTime) +
                       " latestWrittenWallTime: " + tojson(currWrittenWallTime) +
                       " prevDurableWallTime: " + tojson(prevDurableWallTime) +
                       " latestDurableWallTime: " + tojson(currDurableWallTime));
            replTest.dumpOplog(replTest.nodes[i], {}, 20);
            replTest.dumpOplog(replTest.nodes[i - 1], {}, 20);
            return false;
        }
        prevReplStatus = currentReplStatus;
    }
    return true;
}

// This test has a part that rolls over the oplog. Doing so requires a fresh stable
// checkpoint. Set the syncdelay to a small value to increase checkpoint frequency.
var replTest = new ReplSetTest(
    {name: "replStatus", nodes: 3, oplogSize: 1, waitForKeys: true, nodeOptions: {syncdelay: 1}});

const nodes = replTest.startSet();

// Tests that serverStatus oplog returns null timestamps if the oplog collection doesn't exist.
const zeroTs = new Timestamp(0, 0);
const oplogStatus = nodes[0].getDB('admin').serverStatus({oplog: true}).oplog;
assert.eq(oplogStatus.earliestOptime, zeroTs);
assert.eq(oplogStatus.latestOptime, zeroTs);

replTest.initiate();
var primary = replTest.getPrimary();
replTest.awaitReplication();
replTest.awaitSecondaryNodes();

const isPersistent = primary.getDB('admin').serverStatus().storageEngine.persistent;

// Check initial optimes
assert.soon(function() {
    return optimesAndWallTimesAreEqual(replTest, isPersistent);
});
var initialInfo = primary.getDB('admin').serverStatus({oplog: true}).oplog;
let initialReplStatusInfo = primary.getDB('admin').runCommand({replSetGetStatus: 1});

// Do an insert to increment optime, but without rolling the oplog
// latestOptime should be updated, but earliestOptime should be unchanged
var options = {writeConcern: {w: replTest.nodes.length}};
if (isPersistent) {
    // Ensure the durable optime is advanced.
    options.writeConcern.j = true;
}
assert.commandWorked(primary.getDB('test').foo.insert({a: 1}, options));
assert.soon(function() {
    return optimesAndWallTimesAreEqual(replTest, isPersistent);
});

var info = primary.getDB('admin').serverStatus({oplog: true}).oplog;
var entry = primary.getDB('local').oplog.rs.findOne().ts;
jsTest.log("First entry's timestamp is " + tojson(entry));
let replStatusInfo = primary.getDB('admin').runCommand({replSetGetStatus: 1});

const dumpInfoFn = function() {
    jsTestLog("Initial server status: " + tojsononeline(initialInfo));
    jsTestLog("Initial replSetGetStatus: " + tojsononeline(initialReplStatusInfo));
    jsTestLog("Final server status: " + tojsononeline(info));
    jsTestLog("Final replSetGetStatus: " + tojsononeline(replStatusInfo));
};

assert.gt(timestampCompare(info.latestOptime, initialInfo.latestOptime), 0, dumpInfoFn);
assert.eq(timestampCompare(info.earliestOptime, initialInfo.earliestOptime), 0, dumpInfoFn);

// Insert some large documents to force the oplog to roll over
var largeString = new Array(1024 * 10).toString();
for (var i = 0; i < 2000; i++) {
    primary.getDB('test').foo.insert({largeString: largeString}, options);
}
assert.soon(function() {
    return optimesAndWallTimesAreEqual(replTest, isPersistent);
});
entry = primary.getDB('local').oplog.rs.findOne().ts;
jsTest.log("First entry's timestamp is now " + tojson(entry) + " after oplog rollover");

// This block requires a fresh stable checkpoint.
assert.soon(function() {
    // Test that earliestOptime was updated
    info = primary.getDB('admin').serverStatus({oplog: true}).oplog;
    jsTest.log("Earliest optime is now " + tojson(info.earliestOptime) +
               "; looking for it to be different from " + tojson(initialInfo.earliestOptime));
    replStatusInfo = primary.getDB('admin').runCommand({replSetGetStatus: 1});
    return timestampCompare(info.latestOptime, initialInfo.latestOptime) > 0 &&
        timestampCompare(info.earliestOptime, initialInfo.earliestOptime) > 0;
});

replTest.stopSet();