2

I have set up a MongoDB cluster using a 3-Member Primary-Secondary-Arbiter Architecture

Environment:

  • LXC containers
  • Linux Debian Stretch (9.8)
  • MongoDB server version: 4.0.6

MongoDB Containers:

  • lxc-mongodb-01 (primary)
  • lxc-mongodb-02 (secondary)
  • lxc-mongodb-03 (arbitrer)

Replication Status

Everything seems to work fine and replication is working:

np:PRIMARY> rs.printSlaveReplicationInfo()
source: lxc-mongodb-02:27017
    syncedTo: Wed Mar 06 2019 12:08:27 GMT+0100 (CET)
    0 secs (0 hrs) behind the primary 

Switchover fails

But when I try to switchover primary/secondary using rs.stepDown() it fails with a "No electable secondaries caught up" error message:

np:PRIMARY> rs.stepDown(60, 30)
{
    "operationTime" : Timestamp(1551870647, 1),
    "ok" : 0,
    "errmsg" : "No electable secondaries caught up as of 2019-03-06T12:11:19.140+0100Please use the replSetStepDown command with the argument {force: true} to force node to step down.",
    "code" : 262,
    "codeName" : "ExceededTimeLimit",
    "$clusterTime" : {
        "clusterTime" : Timestamp(1551870647, 1),
        "signature" : {
            "hash" : BinData(0,"+/jQR8cG+y/bPtoF7gnv2Pmn2BY="),
            "keyId" : NumberLong("6653042051040411649")
        }
    }
}

Note that this is a non-production cluster, so there is no transaction in progress.

Logs from server01 (primary) :

2019-03-06T12:08:07.709+0100 I ACCESS   [conn17] Successfully authenticated as principal root on admin
2019-03-06T12:10:49.140+0100 I COMMAND  [conn17] Attempting to step down in response to replSetStepDown command
2019-03-06T12:11:19.140+0100 I COMMAND  [conn17] command admin.$cmd appName: "MongoDB Shell" command: replSetStepDown { replSetStepDown: 60.0, secondaryCatchUpPeriodSecs: 30.0, lsid: { id: UUID("8941645a-c582-4353-b216-6e5ee91c08b0") }, $clusterTime: { clusterTime: Timestamp(1551870507, 1), signature: { hash: BinData(0, 484DDC04A03F9CBEDA0E5FA5E4F438F414E43E8F), keyId: 6653042051040411649 } }, $db: "admin" } numYields:0 ok:0 errMsg:"No electable secondaries caught up as of 2019-03-06T12:11:19.140+0100Please use the replSetStepDown command with the argument {force: true} to force node to step down." errName:ExceededTimeLimit errCode:262 reslen:385 locks:{ Global: { acquireCount: { r: 2, W: 2 } } } protocol:op_msg 29999ms

Logs from server02 (secondary) :

2019-03-06T12:10:52.278+0100 I REPL     [replication-1] Restarting oplog query due to error: InterruptedDueToReplStateChange: error in fetcher batch callback :: caused by :: operation was interrupted. Last fetched optime (with hash): { ts: Timestamp(1551870647, 1), t: 8 }[-3124663669138993987]. Restarts remaining: 1
2019-03-06T12:10:52.278+0100 I REPL     [replication-1] Scheduled new oplog query Fetcher source: lxc-mongodb-01:27017 database: local query: { find: "oplog.rs", filter: { ts: { $gte: Timestamp(1551870647, 1) } }, tailable: true, oplogReplay: true, awaitData: true, maxTimeMS: 2000, batchSize: 13981010, term: 8, readConcern: { afterClusterTime: Timestamp(1551870647, 1) } } query metadata: { $replData: 1, $oplogQueryData: 1, $readPreference: { mode: "secondaryPreferred" } } active: 1 findNetworkTimeout: 7000ms getMoreNetworkTimeout: 10000ms shutting down?: 0 first: 1 firstCommandScheduler: RemoteCommandRetryScheduler request: RemoteCommand 6603 -- target:lxc-mongodb-01:27017 db:local cmd:{ find: "oplog.rs", filter: { ts: { $gte: Timestamp(1551870647, 1) } }, tailable: true, oplogReplay: true, awaitData: true, maxTimeMS: 2000, batchSize: 13981010, term: 8, readConcern: { afterClusterTime: Timestamp(1551870647, 1) } } active: 1 callbackHandle.valid: 1 callbackHandle.cancelled: 0 attempt: 1 retryPolicy: RetryPolicyImpl maxAttempts: 1 maxTimeMillis: -1ms
2019-03-06T12:10:52.279+0100 W REPL     [rsBackgroundSync] Fetcher stopped querying remote oplog with error: InvalidSyncSource: Sync source cannot be behind me, and if I am up-to-date with the sync source, it must have a higher lastOpCommitted. My last fetched oplog optime: { ts: Timestamp(1551870647, 1), t: 8 }, latest oplog optime of sync source: { ts: Timestamp(1551870647, 1), t: 8 }, my lastOpCommitted: { ts: Timestamp(1551870647, 1), t: 8 }, lastOpCommitted of sync source: { ts: Timestamp(1551870647, 1), t: 8 }
2019-03-06T12:10:52.279+0100 I REPL     [rsBackgroundSync] Clearing sync source lxc-mongodb-01:27017 to choose a new one.
2019-03-06T12:10:52.279+0100 I REPL     [rsBackgroundSync] could not find member to sync from
2019-03-06T12:10:57.276+0100 I REPL     [SyncSourceFeedback] SyncSourceFeedback error sending update to lxc-mongodb-01:27017: InvalidSyncSource: Sync source was cleared. Was lxc-mongodb-01:27017
2019-03-06T12:11:27.284+0100 I REPL     [rsBackgroundSync] sync source candidate: lxc-mongodb-01:27017
2019-03-06T12:11:27.286+0100 I REPL     [rsBackgroundSync] Changed sync source from empty to lxc-mongodb-01:27017
2019-03-06T12:11:28.833+0100 I NETWORK  [LogicalSessionCacheRefresh] Starting new replica set monitor for np/lxc-mongodb-01:27017,lxc-mongodb-02:27017

Logs from server03 (arbitrer) :

2019-03-06T12:11:29.428+0100 I NETWORK  [LogicalSessionCacheRefresh] Starting new replica set monitor for np/lxc-mongodb-01:27017,lxc-mongodb-02:27017
2019-03-06T12:11:29.429+0100 I NETWORK  [LogicalSessionCacheRefresh] Starting new replica set monitor for np/lxc-mongodb-01:27017,lxc-mongodb-02:27017

Looking at the documentation and some threads, I tried tuned a few settings, with no success:

replication.enableMajorityReadConcern = false
writeConcernMajorityJournalDefault = false

Question

So, what am I missing to make stepDown work as expected?

EDIT 07/03/2019

Here is rs.status() output from the primary:

np:PRIMARY> rs.status()
{
    "set" : "np",
    "date" : ISODate("2019-03-07T08:08:17.623Z"),
    "myState" : 1,
    "term" : NumberLong(8),
    "syncingTo" : "",
    "syncSourceHost" : "",
    "syncSourceId" : -1,
    "heartbeatIntervalMillis" : NumberLong(2000),
    "optimes" : {
        "lastCommittedOpTime" : {
            "ts" : Timestamp(1551946089, 1),
            "t" : NumberLong(8)
        },
        "readConcernMajorityOpTime" : {
            "ts" : Timestamp(1551946089, 1),
            "t" : NumberLong(8)
        },
        "appliedOpTime" : {
            "ts" : Timestamp(1551946089, 1),
            "t" : NumberLong(8)
        },
        "durableOpTime" : {
            "ts" : Timestamp(1551946089, 1),
            "t" : NumberLong(8)
        }
    },
    "members" : [
        {
            "_id" : 0,
            "name" : "lxc-mongodb-01:27017",
            "health" : 1,
            "state" : 1,
            "stateStr" : "PRIMARY",
            "uptime" : 75954,
            "optime" : {
                "ts" : Timestamp(1551946089, 1),
                "t" : NumberLong(8)
            },
            "optimeDate" : ISODate("2019-03-07T08:08:09Z"),
            "syncingTo" : "",
            "syncSourceHost" : "",
            "syncSourceId" : -1,
            "infoMessage" : "",
            "electionTime" : Timestamp(1551870155, 1),
            "electionDate" : ISODate("2019-03-06T11:02:35Z"),
            "configVersion" : 4,
            "self" : true,
            "lastHeartbeatMessage" : ""
        },
        {
            "_id" : 1,
            "name" : "lxc-mongodb-03:27017",
            "health" : 1,
            "state" : 7,
            "stateStr" : "ARBITER",
            "uptime" : 75952,
            "lastHeartbeat" : ISODate("2019-03-07T08:08:16.005Z"),
            "lastHeartbeatRecv" : ISODate("2019-03-07T08:08:17.410Z"),
            "pingMs" : NumberLong(0),
            "lastHeartbeatMessage" : "",
            "syncingTo" : "",
            "syncSourceHost" : "",
            "syncSourceId" : -1,
            "infoMessage" : "",
            "configVersion" : 4
        },
        {
            "_id" : 2,
            "name" : "lxc-mongodb-02:27017",
            "health" : 1,
            "state" : 2,
            "stateStr" : "SECONDARY",
            "uptime" : 75952,
            "optime" : {
                "ts" : Timestamp(1551946089, 1),
                "t" : NumberLong(8)
            },
            "optimeDurable" : {
                "ts" : Timestamp(1551946089, 1),
                "t" : NumberLong(8)
            },
            "optimeDate" : ISODate("2019-03-07T08:08:09Z"),
            "optimeDurableDate" : ISODate("2019-03-07T08:08:09Z"),
            "lastHeartbeat" : ISODate("2019-03-07T08:08:16.008Z"),
            "lastHeartbeatRecv" : ISODate("2019-03-07T08:08:15.798Z"),
            "pingMs" : NumberLong(0),
            "lastHeartbeatMessage" : "",
            "syncingTo" : "lxc-mongodb-01:27017",
            "syncSourceHost" : "lxc-mongodb-01:27017",
            "syncSourceId" : 0,
            "infoMessage" : "",
            "configVersion" : 4
        }
    ],
    "ok" : 1,
    "operationTime" : Timestamp(1551946089, 1),
    "$clusterTime" : {
        "clusterTime" : Timestamp(1551946089, 1),
        "signature" : {
            "hash" : BinData(0,"ZPnNWVwjB1K9jdaSHlnfnmRPqqM="),
            "keyId" : NumberLong("6653042051040411649")
        }
    }
}

Here is rs.conf() output from the primary:

np:PRIMARY> rs.conf()
{
    "_id" : "np",
    "version" : 4,
    "protocolVersion" : NumberLong(1),
    "writeConcernMajorityJournalDefault" : false,
    "members" : [
        {
            "_id" : 0,
            "host" : "lxc-mongodb-01:27017",
            "arbiterOnly" : false,
            "buildIndexes" : true,
            "hidden" : false,
            "priority" : 1,
            "tags" : {

            },
            "slaveDelay" : NumberLong(0),
            "votes" : 1
        },
        {
            "_id" : 1,
            "host" : "lxc-mongodb-03:27017",
            "arbiterOnly" : true,
            "buildIndexes" : true,
            "hidden" : false,
            "priority" : 0,
            "tags" : {

            },
            "slaveDelay" : NumberLong(0),
            "votes" : 1
        },
        {
            "_id" : 2,
            "host" : "lxc-mongodb-02:27017",
            "arbiterOnly" : false,
            "buildIndexes" : true,
            "hidden" : false,
            "priority" : 0,
            "tags" : {

            },
            "slaveDelay" : NumberLong(0),
            "votes" : 0
        }
    ],
    "settings" : {
        "chainingAllowed" : true,
        "heartbeatIntervalMillis" : 2000,
        "heartbeatTimeoutSecs" : 10,
        "electionTimeoutMillis" : 10000,
        "catchUpTimeoutMillis" : -1,
        "catchUpTakeoverDelayMillis" : 30000,
        "getLastErrorModes" : {

        },
        "getLastErrorDefaults" : {
            "w" : 1,
            "wtimeout" : 0
        },
        "replicaSetId" : ObjectId("5c545a7d4e358716c8129ac6")
    }
}
4

There is No electable secondaries because priority of secondary node is set to 0 (see rs.conf() in the original post. Thanks to Mani for his suggestion!).

I updated priority (and votes) for lxc-mongodb-02 (_id = 2):

cfg = rs.conf();
cfg.members[0].priority = 2;
cfg.members[2].votes = 1;
cfg.members[2].priority = 1;
rs.reconfig(cfg);

lxc-mongodb-02 is now electable as a PRIMARY.

That being said, I just realized that a permanent switchover will be performed by changing the priority rather than using rs.stepDown() command.

So to promote lxc-mongodb-02 as the primary, I run:

cfg = rs.conf();
cfg.members[2].priority = 3;
np:PRIMARY> rs.reconfig(cfg);
{
    "ok" : 1,
    "operationTime" : Timestamp(1551953687, 1),
    "$clusterTime" : {
        "clusterTime" : Timestamp(1551953687, 1),
        "signature" : {
            "hash" : BinData(0,"r4jVzPM1nUnJ44THZ3E+cJA1SDU="),
            "keyId" : NumberLong("6653042051040411649")
        }
    }
}

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.