-
Type:
Bug
-
Resolution: Done
-
Priority:
Major - P3
-
None
-
Affects Version/s: 3.2.9
-
Component/s: Networking, Replication
-
Labels:None
-
ALL
-
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