path: root/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]
 */

load("jstests/replsets/libs/election_metrics.js");
load("jstests/replsets/rslib.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;

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

// 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.');
        }
    });
}

var 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 (var 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);
    var 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);
} catch (e) {
    throw e;
} 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 {
        var 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();
var firstPrimary = primary;
print("\nprimary is now " + firstPrimary);

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

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

assert.soon(function() {
    var 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();
var secondary = replTest.getSecondary();

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

primary = replTest.getPrimary();
assert.soon(function() {
    try {
        var result = primary.getDB("admin").runCommand({replSetGetStatus: 1});
        for (var 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)
var 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");

var 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");