MongoDB – Re-evaluating Sync Source Log Entries When chainingAllowed is False

mongodbmongodb-3.2nosql

We have recently upgraded our 3 member replica set from 3.0 to 3.2.9. Since the upgrade, we are seeing log entries like below periodically on one of the secondaries.
As per the rs.conf() output below, we having chainingAllowed = false and all secondaries are syncing from the primary so I would not expect to see these log entries.

Primary – mongodb01
Secondaries – mongodb02 & mongodb03

The log entries seem to show that the secondary mongodb02 is syncing from the other secondary mongodb03. So is the chainingAllowed setting being observed? Does anyone know why we are seeing these messages?

Thanks.

Log Entries

2016-09-06T08:51:12.029+0100 I REPL     [ReplicationExecutor] re-evaluating sync source because our current sync source's most recent OpTime is (term: -1, timestamp: Sep  6 08:50:35:1) which is more than 30s behind member mongodb03:27017 whose most recent OpTime is (term: -1, timestamp: Sep  6 08:51:11:1)
2016-09-06T08:51:12.029+0100 I REPL     [ReplicationExecutor] syncing from primary: mongodb01:27017
2016-09-06T08:51:12.034+0100 I REPL     [ReplicationExecutor] re-evaluating sync source because our current sync source's most recent OpTime is (term: -1, timestamp: Sep  6 08:50:35:1) which is more than 30s behind member mongodb03:27017 whose most recent OpTime is (term: -1, timestamp: Sep  6 08:51:11:1)
2016-09-06T08:51:12.034+0100 I REPL     [ReplicationExecutor] syncing from primary: mongodb01:27017
2016-09-06T08:51:12.041+0100 I REPL     [ReplicationExecutor] re-evaluating sync source because our current sync source's most recent OpTime is (term: -1, timestamp: Sep  6 08:50:35:1) which is more than 30s behind member mongodb03:27017 whose most recent OpTime is (term: -1, timestamp: Sep  6 08:51:11:1)
2016-09-06T08:51:12.042+0100 I REPL     [ReplicationExecutor] syncing from primary: mongodb01:27017
2016-09-06T08:51:12.049+0100 I REPL     [ReplicationExecutor] re-evaluating sync source because our current sync source's most recent OpTime is (term: -1, timestamp: Sep  6 08:50:35:1) which is more than 30s behind member mongodb03:27017 whose most recent OpTime is (term: -1, timestamp: Sep  6 08:51:11:1)
2016-09-06T08:51:12.049+0100 I REPL     [ReplicationExecutor] syncing from primary: mongodb01:27017

rs.conf()

mongodbrepl:SECONDARY> rs.conf()
{
        "_id" : "mongodbrepl",
        "version" : 32,
        "members" : [
                {
                        "_id" : 2,
                        "host" : "mongodb03:27017",
                        "arbiterOnly" : false,
                        "buildIndexes" : true,
                        "hidden" : false,
                        "priority" : 1,
                        "tags" : {

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

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

                        },
                        "slaveDelay" : NumberLong(0),
                        "votes" : 1
                }
        ],
        "settings" : {
                "chainingAllowed" : false,
                "heartbeatIntervalMillis" : 2000,
                "heartbeatTimeoutSecs" : 10,
                "electionTimeoutMillis" : 10000,
                "getLastErrorModes" : {

                },
                "getLastErrorDefaults" : {
                        "w" : 1,
                        "wtimeout" : 0
                }
        }
}

rs.status()

mongodbrepl:SECONDARY> rs.status()
{
        "set" : "mongodbrepl",
        "date" : ISODate("2016-09-06T08:24:13.763Z"),
        "myState" : 2,
        "term" : NumberLong(-1),
        "syncingTo" : "mongodb01:27017",
        "heartbeatIntervalMillis" : NumberLong(2000),
        "members" : [
                {
                        "_id" : 0,
                        "name" : "mongodb01:27017",
                        "health" : 1,
                        "state" : 1,
                        "stateStr" : "PRIMARY",
                        "uptime" : 412082,
                        "optime" : Timestamp(1473150251, 1),
                        "optimeDate" : ISODate("2016-09-06T08:24:11Z"),
                        "lastHeartbeat" : ISODate("2016-09-06T08:24:13.461Z"),
                        "lastHeartbeatRecv" : ISODate("2016-09-06T08:24:13.462Z"),
                        "pingMs" : NumberLong(0),
                        "electionTime" : Timestamp(1472738228, 1),
                        "electionDate" : ISODate("2016-09-01T13:57:08Z"),
                        "configVersion" : 32
                },
                {
                        "_id" : 1,
                        "name" : "mongodb02:27017",
                        "health" : 1,
                        "state" : 2,
                        "stateStr" : "SECONDARY",
                        "uptime" : 412280,
                        "optime" : Timestamp(1473150251, 1),
                        "optimeDate" : ISODate("2016-09-06T08:24:11Z"),
                        "syncingTo" : "mongodb01:27017",
                        "configVersion" : 32,
                        "self" : true
                },
                {
                        "_id" : 2,
                        "name" : "mongodb03:27017",
                        "health" : 1,
                        "state" : 2,
                        "stateStr" : "SECONDARY",
                        "uptime" : 412273,
                        "optime" : Timestamp(1473150251, 1),
                        "optimeDate" : ISODate("2016-09-06T08:24:11Z"),
                        "lastHeartbeat" : ISODate("2016-09-06T08:24:12.395Z"),
                        "lastHeartbeatRecv" : ISODate("2016-09-06T08:24:13.757Z"),
                        "pingMs" : NumberLong(0),
                        "syncingTo" : "mongodb01:27017",
                        "configVersion" : 32
                }
        ],
        "ok" : 1
}

Best Answer

It's hard to say without seeing all the logs, but I suspect you are seeing changes to your primary. The primary is listed in the log messages as primary: mongodb01 and it is (at the time syncing from mongodb03). It's the kind of thing I would expect to see if you were stepping down the primary (mongodb03), then locking it (or similar) that causes it to fall behind and mongodb02 notices and switches to the new primary (mongodb01).

Your status indicates that mongodb03 is once again the primary when you ran it, but the logs clearly show that mongodb01 has been the primary in the past.

Related Solutions

Mongodb data sync between primary and secondary node even when port is closed

Have you closed that path both ways...

If primary cannot "ping" secondary, it's not reachable/healthy, but if secondary can connect primary, it can replicate opLog...

MongoDB – Replica Set with One Primary and Two Secondary Instances

Given your current replica set configuration, this behaviour is expected.

In order to be elected (and remain) primary, a replica set member must have connectivity with a majority of voting replica set members.

Your configuration has two members which have priority 0 and cannot be elected as primary, so there is only one candidate for primary (the member _id:0 ). However, all of the members in your replica set are voting so the required majority to elect a primary is 2/3 configured replica set members.

Based on the log information you have provided from the member you prefer as primary, the replica set member state timeline looks like:

Member with _id: 0 is started and performs WiredTiger consistency checks for the data files. The mongod transitions from replica set STARTUP (reading configuration) to STARTUP2 (enabling replication threads).
STARTUP2 completes and the member briefly transitions to RECOVERING and then SECONDARY state, where it is now ready to connect to other members of the replica set based on the last saved replica set configuration.
Network connectivity to the other members is not available (Connection refused), so the member transitions into a SECONDARY state and marks the other members of the replica set as unreachable: Member mongo2:27017 is now in state RS_DOWN. Since there is only 1 voting member available out of the 3 configured, a primary cannot be elected so this member will remain SECONDARY and will not propose an election.
When network connectivity issues are resolved, the status of other members of the replica set can now be determined: Member mongo2:27017 is now in state SECONDARY.
The replica set now has connectivity between enough members to start an election. The reason for the election is also noted: Starting an election, since we've seen no PRIMARY in the past 10000ms.
The election succeeds (election succeeded, assuming primary role in term 42) and this member transitions from SECONDARY to PRIMARY state.

I need primary to be write to access at all times - I can't have it switch to secondary in case one of the secondary fails and has to reconnect.

The default configuration for a replica set is designed for automatic failover: if the current primary becomes isolated from a majority of replica set members, a new primary can be elected to continue write availability.

If you do not want automatic failover, set the votes for your secondaries to 0:

var conf=rs.conf()
conf.members[1].votes = 0
conf.members[2].votes = 0
rs.reconfig(conf)

With only one voting member in the replica set configuration, the primary is now able to elect itself irrespective of the connectivity or health of the other replica set members.

There are a few obvious caveats with this configuration:

Since you only have a single voting node, a w:majority write concern is equivalent to w:1 and will only request acknowledgement from the primary.
If the primary remains disconnected from the other replica set members for any significant duration, the secondaries may become stale and require a full resync. You can mitigate this by increasing the size of the replication oplog for each of your replica set members in order to provide an appropriate buffer.

Best Answer

Related Solutions

Mongodb data sync between primary and secondary node even when port is closed

MongoDB – Replica Set with One Primary and Two Secondary Instances

Related Question