mongo/jstests/replsets/stepdown.js

/**
 * Check that on a loss of primary, another node doesn't assume primary if it is stale. We force a
 * stepDown to test this.
 *
 * This test also checks that the serverStatus command metrics replSetStepDown and
 * replSetStepDownWithForce are incremented correctly.
 *
 * This test requires the fsync command to force a secondary to be stale.
 * @tags: [requires_fsync]
 */

import {ReplSetTest} from "jstests/libs/replsettest.js";
import {verifyServerStatusChange} from "jstests/replsets/libs/election_metrics.js";

// We are bypassing collection validation because this test runs "shutdown" command so the server is
// expected to be down when MongoRunner.stopMongod is called.
TestData.skipCollectionAndIndexValidation = true;

let replTest = new ReplSetTest({
    name: "testSet",
    nodes: {"n0": {rsConfig: {priority: 2}}, "n1": {}, "n2": {rsConfig: {votes: 1, priority: 0}}},
    nodeOptions: {verbose: 1},
});
let nodes = replTest.startSet();
replTest.initiate(null, null, {initiateWithDefaultElectionTimeout: true});
replTest.waitForState(nodes[0], ReplSetTest.State.PRIMARY);
let primary = replTest.getPrimary();

// The default WC is majority and this test can't satisfy majority writes.
assert.commandWorked(
    primary.adminCommand({setDefaultRWConcern: 1, defaultWriteConcern: {w: 1}, writeConcern: {w: "majority"}}),
);

// do a write
print("\ndo a write");
assert.commandWorked(primary.getDB("foo").bar.insert({x: 1}));
replTest.awaitReplication();

// In the event of any error, we have to unlock any nodes that we have fsyncLocked.
function unlockNodes(nodes) {
    jsTestLog("Unlocking nodes: " + tojson(nodes));
    nodes.forEach(function (node) {
        try {
            jsTestLog("Unlocking node: " + node);
            assert.commandWorked(node.getDB("admin").fsyncUnlock());
        } catch (e) {
            jsTestLog(
                "Failed to unlock node: " +
                    node +
                    ": " +
                    tojson(e) +
                    ". Ignoring unlock error and moving on to next node.",
            );
        }
    });
}

let lockedNodes = [];
try {
    // lock secondaries
    jsTestLog("Locking nodes: " + tojson(replTest.getSecondaries()));
    replTest.getSecondaries().forEach(function (node) {
        jsTestLog("Locking node: " + node);
        jsTestLog(
            "fsync lock " +
                node +
                " result: " +
                tojson(assert.commandWorked(node.getDB("admin").runCommand({fsync: 1, lock: 1}))),
        );
        lockedNodes.push(node);
    });

    jsTestLog("Stepping down primary: " + primary);

    for (let i = 0; i < 11; i++) {
        // do another write
        assert.commandWorked(primary.getDB("foo").bar.insert({x: i}));
    }

    let res = assert.commandWorked(primary.adminCommand({replSetGetStatus: 1}));
    assert(
        res.electionCandidateMetrics,
        () => "Response should have an 'electionCandidateMetrics' field: " + tojson(res),
    );
    let intitialServerStatus = assert.commandWorked(primary.adminCommand({serverStatus: 1}));

    jsTestLog("Do stepdown of primary " + primary + " that should not work");

    // this should fail, so we don't need to try/catch
    jsTestLog(
        "Step down " +
            primary +
            " expected error: " +
            tojson(assert.commandFailed(primary.getDB("admin").runCommand({replSetStepDown: 10}))),
    );

    // Check that the 'total' and 'failed' fields of 'replSetStepDown' have been incremented in
    // serverStatus and that they have not been incremented for 'replSetStepDownWithForce'.
    let newServerStatus = assert.commandWorked(primary.adminCommand({serverStatus: 1}));
    verifyServerStatusChange(
        intitialServerStatus.metrics.commands.replSetStepDown,
        newServerStatus.metrics.commands.replSetStepDown,
        "total",
        1,
    );
    verifyServerStatusChange(
        intitialServerStatus.metrics.commands.replSetStepDown,
        newServerStatus.metrics.commands.replSetStepDown,
        "failed",
        1,
    );
    verifyServerStatusChange(
        intitialServerStatus.metrics.commands.replSetStepDownWithForce,
        newServerStatus.metrics.commands.replSetStepDownWithForce,
        "total",
        0,
    );
    verifyServerStatusChange(
        intitialServerStatus.metrics.commands.replSetStepDownWithForce,
        newServerStatus.metrics.commands.replSetStepDownWithForce,
        "failed",
        0,
    );

    // This section checks that the metrics are incremented accurately when the command fails due to
    // an error occurring before stepDown is called in the replication coordinator, such as due to
    // bad values or type mismatches in the arguments, or checkReplEnabledForCommand returning a bad
    // status. The stepdown period being negative is one example of such an error, but success in
    // this case gives us confidence that the behavior in the other cases is the same.

    // Stepdown should fail because the stepdown period is negative
    jsTestLog("Do stepdown of primary " + primary + " that should not work");
    assert.commandFailedWithCode(
        primary.getDB("admin").runCommand({replSetStepDown: -1, force: true}),
        ErrorCodes.BadValue,
    );

    // Check that the 'total' and 'failed' fields of 'replSetStepDown' and
    // 'replSetStepDownWithForce' have been incremented in serverStatus.
    intitialServerStatus = newServerStatus;
    newServerStatus = assert.commandWorked(primary.adminCommand({serverStatus: 1}));
    verifyServerStatusChange(
        intitialServerStatus.metrics.commands.replSetStepDown,
        newServerStatus.metrics.commands.replSetStepDown,
        "total",
        1,
    );
    verifyServerStatusChange(
        intitialServerStatus.metrics.commands.replSetStepDown,
        newServerStatus.metrics.commands.replSetStepDown,
        "failed",
        1,
    );
    verifyServerStatusChange(
        intitialServerStatus.metrics.commands.replSetStepDownWithForce,
        newServerStatus.metrics.commands.replSetStepDownWithForce,
        "total",
        1,
    );
    verifyServerStatusChange(
        intitialServerStatus.metrics.commands.replSetStepDownWithForce,
        newServerStatus.metrics.commands.replSetStepDownWithForce,
        "failed",
        1,
    );

    jsTestLog("Do stepdown of primary " + primary + " that should work");
    assert.commandWorked(primary.adminCommand({replSetStepDown: ReplSetTest.kDefaultTimeoutMS, force: true}));

    // Check that the 'total' fields of 'replSetStepDown' and 'replSetStepDownWithForce' have been
    // incremented in serverStatus and that their 'failed' fields have not been incremented.
    intitialServerStatus = newServerStatus;
    newServerStatus = assert.commandWorked(primary.adminCommand({serverStatus: 1}));
    verifyServerStatusChange(
        intitialServerStatus.metrics.commands.replSetStepDown,
        newServerStatus.metrics.commands.replSetStepDown,
        "total",
        1,
    );
    verifyServerStatusChange(
        intitialServerStatus.metrics.commands.replSetStepDown,
        newServerStatus.metrics.commands.replSetStepDown,
        "failed",
        0,
    );
    verifyServerStatusChange(
        intitialServerStatus.metrics.commands.replSetStepDownWithForce,
        newServerStatus.metrics.commands.replSetStepDownWithForce,
        "total",
        1,
    );
    verifyServerStatusChange(
        intitialServerStatus.metrics.commands.replSetStepDownWithForce,
        newServerStatus.metrics.commands.replSetStepDownWithForce,
        "failed",
        0,
    );

    jsTestLog("Checking hello on " + primary);
    let r2 = assert.commandWorked(primary.getDB("admin").runCommand({hello: 1}));
    jsTestLog("Result from running hello on " + primary + ": " + tojson(r2));
    assert.eq(r2.isWritablePrimary, false);
    assert.eq(r2.secondary, true);

    // Check that the 'electionCandidateMetrics' section of the replSetGetStatus response has been
    // cleared, since the node is no longer primary.
    res = assert.commandWorked(primary.adminCommand({replSetGetStatus: 1}));
    assert(
        !res.electionCandidateMetrics,
        () => "Response should not have an 'electionCandidateMetrics' field: " + tojson(res),
    );

    // This section checks that the metrics are incremented accurately when the command fails due to
    // an error while stepping down. This is one reason the replSetStepDown command could fail once
    // we call stepDown in the replication coordinator, but success in this case gives us confidence
    // that the behavior in the other cases is the same.

    // Stepdown should fail because the node is no longer primary
    jsTestLog("Do stepdown of primary " + primary + " that should not work");
    assert.commandFailedWithCode(
        primary.getDB("admin").runCommand({replSetStepDown: ReplSetTest.kDefaultTimeoutMS, force: true}),
        ErrorCodes.NotWritablePrimary,
    );

    // Check that the 'total' and 'failed' fields of 'replSetStepDown' and
    // 'replSetStepDownWithForce' have been incremented in serverStatus.
    intitialServerStatus = newServerStatus;
    newServerStatus = assert.commandWorked(primary.adminCommand({serverStatus: 1}));
    verifyServerStatusChange(
        intitialServerStatus.metrics.commands.replSetStepDown,
        newServerStatus.metrics.commands.replSetStepDown,
        "total",
        1,
    );
    verifyServerStatusChange(
        intitialServerStatus.metrics.commands.replSetStepDown,
        newServerStatus.metrics.commands.replSetStepDown,
        "failed",
        1,
    );
    verifyServerStatusChange(
        intitialServerStatus.metrics.commands.replSetStepDownWithForce,
        newServerStatus.metrics.commands.replSetStepDownWithForce,
        "total",
        1,
    );
    verifyServerStatusChange(
        intitialServerStatus.metrics.commands.replSetStepDownWithForce,
        newServerStatus.metrics.commands.replSetStepDownWithForce,
        "failed",
        1,
    );
} finally {
    unlockNodes(lockedNodes);
}

print("\nreset stepped down time");
assert.commandWorked(primary.getDB("admin").runCommand({replSetFreeze: 0}));
primary = replTest.getPrimary();

print("\nawait");
replTest.awaitSecondaryNodes(90000);
replTest.awaitReplication();

// 'n0' may have just voted for 'n1', preventing it from becoming primary for the first 30 seconds
// of this assert.soon
assert.soon(
    function () {
        try {
            let result = primary.getDB("admin").runCommand({hello: 1});
            return new RegExp(":" + replTest.nodes[0].port + "$").test(result.primary);
        } catch (x) {
            return false;
        }
    },
    "wait for n0 to be primary",
    60000,
);

primary = replTest.getPrimary();
let firstPrimary = primary;
print("\nprimary is now " + firstPrimary);

assert.adminCommandWorkedAllowingNetworkError(primary, {replSetStepDown: 100, force: true});

print("\nget a primary");
replTest.getPrimary();

assert.soon(
    function () {
        let secondPrimary = replTest.getPrimary();
        return firstPrimary.host !== secondPrimary.host;
    },
    "making sure " + firstPrimary.host + " isn't still primary",
    60000,
);

// Add arbiter for shutdown tests
replTest.add();
print("\ncheck shutdown command");

primary = replTest.getPrimary();
let secondary = replTest.getSecondary();

try {
    secondary.adminCommand({shutdown: 1});
} catch (e) {
    print(e);
}

primary = replTest.getPrimary();
assert.soon(function () {
    try {
        let result = primary.getDB("admin").runCommand({replSetGetStatus: 1});
        for (let i in result.members) {
            if (result.members[i].self) {
                continue;
            }

            return result.members[i].health == 0;
        }
    } catch (e) {
        print("error getting status from primary: " + e);
        primary = replTest.getPrimary();
        return false;
    }
}, "make sure primary knows that secondary is down before proceeding");

print("\nrunning shutdown without force on primary: " + primary);

// this should fail because the primary can't reach an up-to-date secondary (because the only
// secondary is down)
let now = new Date();
assert.commandFailed(primary.getDB("admin").runCommand({shutdown: 1, timeoutSecs: 3}));
// on windows, javascript and the server perceive time differently, to compensate here we use 2750ms
assert.gte(new Date() - now, 2750);

print("\nsend shutdown command");

let currentPrimary = replTest.getPrimary();
try {
    printjson(currentPrimary.getDB("admin").runCommand({shutdown: 1, force: true}));
} catch (e) {
    if (!isNetworkError(e)) {
        throw e;
    }
}

print("checking " + currentPrimary + " is actually shutting down");
assert.soon(function () {
    try {
        currentPrimary.findOne();
    } catch (e) {
        return true;
    }
    return false;
});

print("\nOK 1");

replTest.stopSet();

print("OK 2");