Loading...

Type: Bug
Resolution: Done
Priority: Major - P3
Fix Version/s: None
Affects Version/s: 3.2.9
Component/s: Networking, Replication
Labels:
None

Operating System:
ALL
Steps To Reproduce:

Hide

Take a running RS with 5 members in two networks of 3 (including arbiter) and 2 nodes. Cut the network for a while. Then re-establish it with delaying the network process on the non-arbiters machines (especially the primary), one of the other nodes will become PRIMARY even if the arbiter is still able to communicate with the PRIMARY

Show
Take a running RS with 5 members in two networks of 3 (including arbiter) and 2 nodes. Cut the network for a while. Then re-establish it with delaying the network process on the non-arbiters machines (especially the primary), one of the other nodes will become PRIMARY even if the arbiter is still able to communicate with the PRIMARY
Confidence Status:
None
Work Order:
3

Aha! Reference:
None
Tracking Level:
None
Risk Status:
None
Exec Notes:
None
Goal Name:
None
Goal Link:
None

Hi guys,

We recently had some serious troubles after a failure due to network handling in the mongo replication process.

The config is the following. 3 Replica sets made of 5 servers, two barebone plus 1 arbiter on one datacenter, two other barebones in another datacenter.

At some point, we had a connectivity problem between the datacenters, for a couple of hours. We expected everything to get back to normal later on, with a sync of the oplog.

Unfortunately one of the three replica sets failed, the two disconnected servers managed to get a majority and a big rollback started.

On the datacenter A, all three nodes were running smoothly. On datacenter B, the two nodes were able to see each other, but lost connection to the primary. One of the node then tried to issue an election, that it couldn't win because it had no majority.

Unfortunately, when the connection was established again, the node first saw the arbiter and only some milliseconds later the other members. But where it should have resetted the replicationTimeout to 10s at the moment where there is a majority, it just started a replication within the few milliseconds, without waiting to connect to the other members. This node got 2 votes and was then able to become a primary, even with several hours of data less... -> Big Rollback

I see two possible fixes (maybe both good):

Make sure to reset the heartbeat timeout to 10s when an election becomes possible again (majority of nodes visible)
Prevent the arbiter to vote in favour of another node when it is seeing a PRIMARY

Here the logs on this node:

2016-09-10T14:17:08.511+0200 I NETWORK  [conn297067] end connection 10.0.0.32:57132 (49 connections now open)
2016-09-10T14:17:22.788+0200 I REPL     [ReplicationExecutor] could not find member to sync from
2016-09-10T14:17:23.508+0200 I REPL     [ReplicationExecutor] Starting an election, since we've seen no PRIMARY in the past 10000ms
2016-09-10T14:17:23.508+0200 I REPL     [ReplicationExecutor] conducting a dry run election to see if we could be elected
2016-09-10T14:17:24.267+0200 I REPL     [ReplicationExecutor] Error in heartbeat request to mongo-rs0-2:27017; ExceededTimeLimit: Operation timed out
2016-09-10T14:17:24.550+0200 I REPL     [ReplicationExecutor] Error in heartbeat request to mongo-rs0-arb:27017; ExceededTimeLimit: Couldn't get a connection within the tim
e limit
2016-09-10T14:17:24.802+0200 I REPL     [ReplicationExecutor] Error in heartbeat request to mongo-rs0-1:27017; ExceededTimeLimit: Couldn't get a connection within the time
limit
2016-09-10T14:17:33.508+0200 I REPL     [ReplicationExecutor] VoteRequester: Got failed response from mongo-rs0-arb:27017: ExceededTimeLimit: Couldn't get a connection with
in the time limit
2016-09-10T14:17:33.508+0200 I REPL     [ReplicationExecutor] VoteRequester: Got failed response from mongo-rs0-1:27017: ExceededTimeLimit: Couldn't get a connection within
 the time limit
2016-09-10T14:17:33.508+0200 I REPL     [ReplicationExecutor] VoteRequester: Got failed response from mongo-rs0-2:27017: ExceededTimeLimit: Couldn't get a connection within
 the time limit
2016-09-10T14:17:33.508+0200 I REPL     [ReplicationExecutor] not running for primary, we received insufficient votes
2016-09-10T14:17:34.223+0200 I REPL     [ReplicationExecutor] Not starting an election, since we are not electable

### connection broken between the datacenters in the meanwhile

2016-09-10T20:52:52.925+0200 I REPL     [ReplicationExecutor] Not starting an election, since we are not electable
2016-09-10T20:52:59.574+0200 I REPL     [ReplicationExecutor] Error in heartbeat request to mongo-rs0-2:27017; ExceededTimeLimit: Operation timed out
2016-09-10T20:53:00.072+0200 I REPL     [ReplicationExecutor] Error in heartbeat request to mongo-rs0-1:27017; ExceededTimeLimit: Couldn't get a connection within the time limit
2016-09-10T20:53:03.259+0200 I REPL     [ReplicationExecutor] Not starting an election, since we are not electable
2016-09-10T20:53:04.576+0200 I REPL     [ReplicationExecutor] Error in heartbeat request to mongo-rs0-2:27017; ExceededTimeLimit: Couldn't get a connection within the time limit
2016-09-10T20:53:04.987+0200 I REPL     [ReplicationExecutor] Error in heartbeat request to mongo-rs0-arb:27017; ExceededTimeLimit: Couldn't get a connection within the time limit
2016-09-10T20:53:10.072+0200 I REPL     [ReplicationExecutor] Error in heartbeat request to mongo-rs0-1:27017; ExceededTimeLimit: Operation timed out
2016-09-10T20:53:12.752+0200 I NETWORK  [initandlisten] connection accepted from 10.0.0.190:60202 #302216 (3 connections now open)
2016-09-10T20:53:12.770+0200 I NETWORK  [conn302216] end connection 10.0.0.190:60202 (2 connections now open)
2016-09-10T20:53:13.027+0200 I ASIO     [NetworkInterfaceASIO-Replication-0] Successfully connected to mongo-rs0-arb:27017
2016-09-10T20:53:13.044+0200 I REPL     [ReplicationExecutor] Member mongo-rs0-arb:27017 is now in state ARBITER
2016-09-10T20:53:13.111+0200 I ASIO     [NetworkInterfaceASIO-Replication-0] Successfully connected to mongo-rs0-1:27017
2016-09-10T20:53:13.128+0200 I REPL     [ReplicationExecutor] Member mongo-rs0-1:27017 is now in state SECONDARY
2016-09-10T20:53:13.236+0200 I NETWORK  [initandlisten] connection accepted from 10.0.0.32:49440 #302217 (3 connections now open)
2016-09-10T20:53:13.324+0200 I REPL     [ReplicationExecutor] Starting an election, since we've seen no PRIMARY in the past 10000ms
2016-09-10T20:53:13.324+0200 I REPL     [ReplicationExecutor] conducting a dry run election to see if we could be elected
2016-09-10T20:53:13.341+0200 I REPL     [ReplicationExecutor] VoteRequester: Got no vote from mongo-rs0-1:27017 because: candidate's data is staler than mine, resp:{ term: 39, voteGranted: false, reason: "candidate's data is staler than mine", ok: 1.0 }
2016-09-10T20:53:13.358+0200 I ASIO     [NetworkInterfaceASIO-Replication-0] Successfully connected to mongo-rs0-2:27017
2016-09-10T20:53:13.364+0200 I REPL     [ReplicationExecutor] dry election run succeeded, running for election
2016-09-10T20:53:13.375+0200 I REPL     [ReplicationExecutor] Member mongo-rs0-2:27017 is now in state PRIMARY
2016-09-10T20:53:13.381+0200 I REPL     [ReplicationExecutor] VoteRequester: Got no vote from mongo-rs0-1:27017 because: candidate's data is staler than mine, resp:{ term: 40, voteGranted: false, reason: "candidate's data is staler than mine", ok: 1.0 }
2016-09-10T20:53:13.381+0200 I REPL     [ReplicationExecutor] election succeeded, assuming primary role in term 40
2016-09-10T20:53:13.381+0200 I REPL     [ReplicationExecutor] transition to PRIMARY
2016-09-10T20:53:13.411+0200 I ASIO     [NetworkInterfaceASIO-Replication-0] Successfully connected to mongo-rs0-2:27017
2016-09-10T20:53:13.428+0200 I REPL     [ReplicationExecutor] Member mongo-rs0-2:27017 is now in state SECONDARY

Details

Description

Attachments

Activity

People

Dates