Details
-
Bug
-
Resolution: Done
-
Major - P3
-
None
-
3.2.9
-
None
-
ALL
-
Description
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
|