|
Reproducing on 3.0.3 on Ubuntu 14.04, without mongos. This works correctly now.
(Also: Nice work guys, the whole election process is much more streamlined and most importantly, very prompt.)
Steps as above. Note that rs.config() no longer hides the available settings if they are set to default, such as heartbeatTimeoutSecs:
SERVER10268:PRIMARY> c = rs.config()
|
{
|
"_id" : "SERVER10268",
|
"version" : 3,
|
"members" : [
|
{
|
"_id" : 0,
|
"host" : "hingo-sputnik:27001",
|
"arbiterOnly" : false,
|
"buildIndexes" : true,
|
"hidden" : false,
|
"priority" : 1,
|
"tags" : {
|
|
},
|
"slaveDelay" : 0,
|
"votes" : 1
|
},
|
{
|
"_id" : 1,
|
"host" : "hingo-sputnik:27002",
|
"arbiterOnly" : false,
|
"buildIndexes" : true,
|
"hidden" : false,
|
"priority" : 1,
|
"tags" : {
|
|
},
|
"slaveDelay" : 0,
|
"votes" : 1
|
},
|
{
|
"_id" : 2,
|
"host" : "hingo-sputnik:27003",
|
"arbiterOnly" : false,
|
"buildIndexes" : true,
|
"hidden" : false,
|
"priority" : 1,
|
"tags" : {
|
|
},
|
"slaveDelay" : 0,
|
"votes" : 1
|
}
|
],
|
"settings" : {
|
"chainingAllowed" : true,
|
"heartbeatTimeoutSecs" : 10,
|
"getLastErrorModes" : {
|
|
},
|
"getLastErrorDefaults" : {
|
"w" : 1,
|
"wtimeout" : 0
|
}
|
}
|
}
|
27001 is primary, hitting Ctrl-Z
Last log line from 27001
May 26 14:41:04 hingo-sputnik mongod.27001[30376]: [durability] groupCommit end
|
The first Socket timeout exactly 10 secs later, immediately followed by an election (which is lost, this is normal). 27002 reacts in roughly 11 seconds, stands for election and assumes primary.
May 26 14:41:04 hingo-sputnik mongod.27003[30384]: [ReplicationExecutor] Scheduling replSetHeartbeat to hingo-sputnik:27002
|
May 26 14:41:04 hingo-sputnik mongod.27003[30384]: [ReplExecNetThread-3] polling for status of connection to 127.0.1.1:27002, no events
|
May 26 14:41:04 hingo-sputnik mongod.27003[30384]: [ReplicationExecutor] Scheduling replSetHeartbeat to hingo-sputnik:27001
|
May 26 14:41:04 hingo-sputnik mongod.27003[30384]: [ReplExecNetThread-2] polling for status of connection to 127.0.1.1:27001, no events
|
May 26 14:41:04 hingo-sputnik mongod.27002[30380]: [conn36] run command admin.$cmd { replSetHeartbeat: "SERVER10268", pv: 1, v: 3, from: "hingo-sputnik:27003", fromId: 2, checkEmpty: false }
|
May 26 14:41:04 hingo-sputnik mongod.27002[30380]: [conn36] command: { replSetHeartbeat: "SERVER10268", pv: 1, v: 3, from: "hingo-sputnik:27003", fromId: 2, checkEmpty: false }
|
May 26 14:41:04 hingo-sputnik mongod.27002[30380]: [conn36] command admin.$cmd command: replSetHeartbeat { replSetHeartbeat: "SERVER10268", pv: 1, v: 3, from: "hingo-sputnik:27003", fromId: 2, checkEmpty: false } ntoreturn:1 keyUpdates:0 writeConflicts:0 numYields:0 reslen:158 locks:{} 0ms
|
May 26 14:41:04 hingo-sputnik mongod.27003[30384]: [ReplExecNetThread-3] Network status of sending replSetHeartbeat to hingo-sputnik:27002 was OK
|
May 26 14:41:04 hingo-sputnik mongod.27003[30384]: [ReplicationExecutor] setUpValues: heartbeat response good for member _id:1, msg:
|
May 26 14:41:04 hingo-sputnik mongod.27003[30384]: [ReplicationExecutor] Scheduling heartbeat to hingo-sputnik:27002 at 2015-05-26T11:41:06.509Z
|
...
|
the above repeats several times, also from 27002 to 27003.
|
...
|
May 26 14:41:14 hingo-sputnik mongod.27003[30384]: [ReplExecNetThread-2] Socket recv() timeout 127.0.1.1:27001
|
May 26 14:41:14 hingo-sputnik mongod.27003[30384]: [ReplExecNetThread-2] SocketException: remote: 127.0.1.1:27001 error: 9001 socket exception [RECV_TIMEOUT] server [127.0.1.1:27001]
|
May 26 14:41:14 hingo-sputnik mongod.27003[30384]: [ReplExecNetThread-2] DBClientCursor::init call() failed
|
May 26 14:41:14 hingo-sputnik mongod.27003[30384]: [ReplExecNetThread-2] User Assertion: 10276:DBClientBase::findN: transport error: hingo-sputnik:27001 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", pv: 1, v: 3, from: "hingo-sputnik:27003", fromId: 2, checkEmpty: false }
|
May 26 14:41:14 hingo-sputnik mongod.27003[30384]: [ReplExecNetThread-2] Network status of sending replSetHeartbeat to hingo-sputnik:27001 was Location10276 DBClientBase::findN: transport error: hingo-sputnik:27001 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", pv: 1, v: 3, from: "hingo-sputnik:27003", fromId: 2, checkEmpty: false }
|
May 26 14:41:14 hingo-sputnik mongod.27003[30384]: [ReplicationExecutor] Error in heartbeat request to hingo-sputnik:27001; Location10276 DBClientBase::findN: transport error: hingo-sputnik:27001 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", pv: 1, v: 3, from: "hingo-sputnik:27003", fromId: 2, checkEmpty: false }
|
May 26 14:41:14 hingo-sputnik mongod.27003[30384]: [ReplicationExecutor] setDownValues: heartbeat response failed for member _id:0, msg: DBClientBase::findN: transport error: hingo-sputnik:27001 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", pv: 1, v: 3, from: "hingo-sputnik:27003", fromId: 2, checkEmpty: false }
|
May 26 14:41:14 hingo-sputnik mongod.27003[30384]: [ReplicationExecutor] Scheduling heartbeat to hingo-sputnik:27001 at 2015-05-26T11:41:16.510Z
|
May 26 14:41:14 hingo-sputnik mongod.27003[30384]: [ReplicationExecutor] Standing for election
|
May 26 14:41:14 hingo-sputnik mongod.27003[30384]: [ReplicationExecutor] Scheduling replSetFresh to hingo-sputnik:27002
|
May 26 14:41:14 hingo-sputnik mongod.27002[30380]: [conn36] run command admin.$cmd { replSetFresh: 1, set: "SERVER10268", opTime: new Date(6153143364280647682), who: "hingo-sputnik:27003", cfgver: 3, id: 2 }
|
May 26 14:41:14 hingo-sputnik mongod.27002[30380]: [conn36] command: { replSetFresh: 1, set: "SERVER10268", opTime: new Date(6153143364280647682), who: "hingo-sputnik:27003", cfgver: 3, id: 2 }
|
May 26 14:41:14 hingo-sputnik mongod.27002[30380]: [conn36] command admin.$cmd command: replSetFresh { replSetFresh: 1, set: "SERVER10268", opTime: new Date(6153143364280647682), who: "hingo-sputnik:27003", cfgver: 3, id: 2 } ntoreturn:1 keyUpdates:0 writeConflicts:0 numYields:0 reslen:191 locks:{} 0ms
|
May 26 14:41:14 hingo-sputnik mongod.27003[30384]: [ReplExecNetThread-3] Network status of sending replSetFresh to hingo-sputnik:27002 was OK
|
May 26 14:41:14 hingo-sputnik mongod.27003[30384]: [ReplicationExecutor] FreshnessChecker: Got response from hingo-sputnik:27002 of { opTime: new Date(6153143364280647682), fresher: false, veto: true, errmsg: "hingo-sputnik:27003 is trying to elect itself but hingo-sputnik:27001 is already primary and more up-to-date", ok: 1.0 }
|
May 26 14:41:14 hingo-sputnik mongod.27003[30384]: [ReplicationExecutor] not electing self, hingo-sputnik:27002 would veto with 'hingo-sputnik:27003 is trying to elect itself but hingo-sputnik:27001 is already primary and more up-to-date'
|
May 26 14:41:14 hingo-sputnik mongod.27003[30384]: [ReplicationExecutor] not electing self, we are not freshest
|
May 26 14:41:14 hingo-sputnik mongod.27002[30380]: [durability] groupCommit begin
|
May 26 14:41:14 hingo-sputnik mongod.27002[30380]: [durability] Processing commit number 5193
|
May 26 14:41:14 hingo-sputnik mongod.27002[30380]: [durability] groupCommit end
|
May 26 14:41:14 hingo-sputnik mongod.27003[30384]: [ReplicationExecutor] Scheduling replSetHeartbeat to hingo-sputnik:27002
|
May 26 14:41:14 hingo-sputnik mongod.27002[30380]: [conn36] run command admin.$cmd { replSetHeartbeat: "SERVER10268", pv: 1, v: 3, from: "hingo-sputnik:27003", fromId: 2, checkEmpty: false }
|
May 26 14:41:14 hingo-sputnik mongod.27002[30380]: [conn36] command: { replSetHeartbeat: "SERVER10268", pv: 1, v: 3, from: "hingo-sputnik:27003", fromId: 2, checkEmpty: false }
|
May 26 14:41:14 hingo-sputnik mongod.27002[30380]: [conn36] command admin.$cmd command: replSetHeartbeat { replSetHeartbeat: "SERVER10268", pv: 1, v: 3, from: "hingo-sputnik:27003", fromId: 2, checkEmpty: false } ntoreturn:1 keyUpdates:0 writeConflicts:0 numYields:0 reslen:158 locks:{} 0ms
|
May 26 14:41:14 hingo-sputnik mongod.27003[30384]: [ReplExecNetThread-2] Network status of sending replSetHeartbeat to hingo-sputnik:27002 was OK
|
May 26 14:41:14 hingo-sputnik mongod.27003[30384]: [ReplicationExecutor] setUpValues: heartbeat response good for member _id:1, msg:
|
May 26 14:41:14 hingo-sputnik mongod.27003[30384]: [ReplicationExecutor] Scheduling heartbeat to hingo-sputnik:27002 at 2015-05-26T11:41:16.516Z
|
May 26 14:41:14 hingo-sputnik mongod.27003[30384]: [ReplicationExecutor] Standing for election
|
May 26 14:41:14 hingo-sputnik mongod.27003[30384]: [ReplicationExecutor] Scheduling replSetFresh to hingo-sputnik:27002
|
May 26 14:41:14 hingo-sputnik mongod.27002[30380]: [conn36] run command admin.$cmd { replSetFresh: 1, set: "SERVER10268", opTime: new Date(6153143364280647682), who: "hingo-sputnik:27003", cfgver: 3, id: 2 }
|
May 26 14:41:14 hingo-sputnik mongod.27002[30380]: [conn36] command: { replSetFresh: 1, set: "SERVER10268", opTime: new Date(6153143364280647682), who: "hingo-sputnik:27003", cfgver: 3, id: 2 }
|
May 26 14:41:14 hingo-sputnik mongod.27002[30380]: [conn36] command admin.$cmd command: replSetFresh { replSetFresh: 1, set: "SERVER10268", opTime: new Date(6153143364280647682), who: "hingo-sputnik:27003", cfgver: 3, id: 2 } ntoreturn:1 keyUpdates:0 writeConflicts:0 numYields:0 reslen:191 locks:{} 0ms
|
May 26 14:41:14 hingo-sputnik mongod.27003[30384]: [ReplExecNetThread-3] Network status of sending replSetFresh to hingo-sputnik:27002 was OK
|
May 26 14:41:14 hingo-sputnik mongod.27003[30384]: [ReplicationExecutor] FreshnessChecker: Got response from hingo-sputnik:27002 of { opTime: new Date(6153143364280647682), fresher: false, veto: true, errmsg: "hingo-sputnik:27003 is trying to elect itself but hingo-sputnik:27001 is already primary and more up-to-date", ok: 1.0 }
|
May 26 14:41:14 hingo-sputnik mongod.27003[30384]: [ReplicationExecutor] not electing self, hingo-sputnik:27002 would veto with 'hingo-sputnik:27003 is trying to elect itself but hingo-sputnik:27001 is already primary and more up-to-date'
|
May 26 14:41:14 hingo-sputnik mongod.27003[30384]: [ReplicationExecutor] not electing self, we are not freshest
|
...
|
May 26 14:41:15 hingo-sputnik mongod.27002[30380]: [ReplExecNetThread-1] Socket recv() timeout 127.0.1.1:27001
|
May 26 14:41:15 hingo-sputnik mongod.27002[30380]: [ReplExecNetThread-1] SocketException: remote: 127.0.1.1:27001 error: 9001 socket exception [RECV_TIMEOUT] server [127.0.1.1:27001]
|
May 26 14:41:15 hingo-sputnik mongod.27002[30380]: [ReplExecNetThread-1] DBClientCursor::init call() failed
|
May 26 14:41:15 hingo-sputnik mongod.27002[30380]: [ReplExecNetThread-1] User Assertion: 10276:DBClientBase::findN: transport error: hingo-sputnik:27001 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", pv: 1, v: 3, from: "hingo-sputnik:27002", fromId: 1, checkEmpty: false }
|
May 26 14:41:15 hingo-sputnik mongod.27002[30380]: [ReplExecNetThread-1] Network status of sending replSetHeartbeat to hingo-sputnik:27001 was Location10276 DBClientBase::findN: transport error: hingo-sputnik:27001 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", pv: 1, v: 3, from: "hingo-sputnik:27002", fromId: 1, checkEmpty: false }
|
May 26 14:41:15 hingo-sputnik mongod.27002[30380]: [ReplicationExecutor] Error in heartbeat request to hingo-sputnik:27001; Location10276 DBClientBase::findN: transport error: hingo-sputnik:27001 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", pv: 1, v: 3, from: "hingo-sputnik:27002", fromId: 1, checkEmpty: false }
|
May 26 14:41:15 hingo-sputnik mongod.27002[30380]: [ReplicationExecutor] Bad heartbeat response from hingo-sputnik:27001; trying again; Retries left: 1; 9999ms have already elapsed
|
May 26 14:41:15 hingo-sputnik mongod.27002[30380]: [ReplicationExecutor] setDownValues: heartbeat response failed for member _id:0, msg: DBClientBase::findN: transport error: hingo-sputnik:27001 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", pv: 1, v: 3, from: "hingo-sputnik:27002", fromId: 1, checkEmpty: false }
|
May 26 14:41:15 hingo-sputnik mongod.27002[30380]: [ReplicationExecutor] Scheduling heartbeat to hingo-sputnik:27001 at 2015-05-26T11:41:15.712Z
|
May 26 14:41:15 hingo-sputnik mongod.27002[30380]: [ReplicationExecutor] Standing for election
|
May 26 14:41:15 hingo-sputnik mongod.27002[30380]: [ReplicationExecutor] Scheduling replSetFresh to hingo-sputnik:27003
|
May 26 14:41:15 hingo-sputnik mongod.27002[30380]: [ReplicationExecutor] Scheduling replSetHeartbeat to hingo-sputnik:27001
|
May 26 14:41:15 hingo-sputnik mongod.27002[30380]: [ConnectBG] BackgroundJob starting: ConnectBG
|
May 26 14:41:15 hingo-sputnik mongod.27002[30380]: [ReplExecNetThread-1] connected to server hingo-sputnik:27001 (127.0.1.1)
|
May 26 14:41:15 hingo-sputnik mongod.27003[30384]: [conn37] run command admin.$cmd { replSetFresh: 1, set: "SERVER10268", opTime: new Date(6153143364280647682), who: "hingo-sputnik:27002", cfgver: 3, id: 1 }
|
May 26 14:41:15 hingo-sputnik mongod.27003[30384]: [conn37] command: { replSetFresh: 1, set: "SERVER10268", opTime: new Date(6153143364280647682), who: "hingo-sputnik:27002", cfgver: 3, id: 1 }
|
May 26 14:41:15 hingo-sputnik mongod.27003[30384]: [conn37] command admin.$cmd command: replSetFresh { replSetFresh: 1, set: "SERVER10268", opTime: new Date(6153143364280647682), who: "hingo-sputnik:27002", cfgver: 3, id: 1 } ntoreturn:1 keyUpdates:0 writeConflicts:0 numYields:0 reslen:70 locks:{} 0ms
|
May 26 14:41:15 hingo-sputnik mongod.27002[30380]: [ReplExecNetThread-3] Network status of sending replSetFresh to hingo-sputnik:27003 was OK
|
May 26 14:41:15 hingo-sputnik mongod.27002[30380]: [ReplicationExecutor] FreshnessChecker: Got response from hingo-sputnik:27003 of { opTime: new Date(6153143364280647682), fresher: false, veto: false, ok: 1.0 }
|
May 26 14:41:15 hingo-sputnik mongod.27002[30380]: [ReplicationExecutor] replSet possible election tie; sleeping 516ms until 2015-05-26T14:41:16.231+0300
|
May 26 14:41:15 hingo-sputnik mongod.27002[30380]: [ReplicationExecutor] Scheduling replSetHeartbeat to hingo-sputnik:27003
|
May 26 14:41:15 hingo-sputnik mongod.27002[30380]: [ReplicationExecutor] Scheduling replSetHeartbeat to hingo-sputnik:27003
|
May 26 14:41:15 hingo-sputnik mongod.27003[30384]: [conn37] run command admin.$cmd { replSetHeartbeat: "SERVER10268", pv: 1, v: 3, from: "hingo-sputnik:27002", fromId: 1, checkEmpty: false }
|
May 26 14:41:15 hingo-sputnik mongod.27003[30384]: [conn37] command: { replSetHeartbeat: "SERVER10268", pv: 1, v: 3, from: "hingo-sputnik:27002", fromId: 1, checkEmpty: false }
|
May 26 14:41:15 hingo-sputnik mongod.27003[30384]: [conn37] command admin.$cmd command: replSetHeartbeat { replSetHeartbeat: "SERVER10268", pv: 1, v: 3, from: "hingo-sputnik:27002", fromId: 1, checkEmpty: false } ntoreturn:1 keyUpdates:0 writeConflicts:0 numYields:0 reslen:158 locks:{} 0ms
|
May 26 14:41:15 hingo-sputnik mongod.27002[30380]: [ReplExecNetThread-3] Network status of sending replSetHeartbeat to hingo-sputnik:27003 was OK
|
May 26 14:41:15 hingo-sputnik mongod.27002[30380]: [ReplicationExecutor] setUpValues: heartbeat response good for member _id:2, msg:
|
May 26 14:41:15 hingo-sputnik mongod.27002[30380]: [ReplicationExecutor] Not standing for election before 2015-05-26T14:41:16.231+0300 because I stood too recently
|
May 26 14:41:15 hingo-sputnik mongod.27002[30380]: [ReplicationExecutor] Scheduling heartbeat to hingo-sputnik:27003 at 2015-05-26T11:41:17.727Z
|
...
|
May 26 14:41:16 hingo-sputnik mongod.27002[30380]: [ReplicationExecutor] Standing for election
|
May 26 14:41:16 hingo-sputnik mongod.27002[30380]: [ReplicationExecutor] Scheduling replSetFresh to hingo-sputnik:27003
|
May 26 14:41:16 hingo-sputnik mongod.27002[30380]: [ReplExecNetThread-3] polling for status of connection to 127.0.1.1:27003, no events
|
May 26 14:41:16 hingo-sputnik mongod.27003[30384]: [conn37] run command admin.$cmd { replSetFresh: 1, set: "SERVER10268", opTime: new Date(6153143364280647682), who: "hingo-sputnik:27002", cfgver: 3, id: 1 }
|
May 26 14:41:16 hingo-sputnik mongod.27003[30384]: [conn37] command: { replSetFresh: 1, set: "SERVER10268", opTime: new Date(6153143364280647682), who: "hingo-sputnik:27002", cfgver: 3, id: 1 }
|
May 26 14:41:16 hingo-sputnik mongod.27003[30384]: [conn37] command admin.$cmd command: replSetFresh { replSetFresh: 1, set: "SERVER10268", opTime: new Date(6153143364280647682), who: "hingo-sputnik:27002", cfgver: 3, id: 1 } ntoreturn:1 keyUpdates:0 writeConflicts:0 numYields:0 reslen:70 locks:{} 0ms
|
May 26 14:41:16 hingo-sputnik mongod.27002[30380]: [ReplExecNetThread-3] Network status of sending replSetFresh to hingo-sputnik:27003 was OK
|
May 26 14:41:16 hingo-sputnik mongod.27002[30380]: [ReplicationExecutor] FreshnessChecker: Got response from hingo-sputnik:27003 of { opTime: new Date(6153143364280647682), fresher: false, veto: false, ok: 1.0 }
|
May 26 14:41:16 hingo-sputnik mongod.27002[30380]: [ReplicationExecutor] replSet info electSelf
|
May 26 14:41:16 hingo-sputnik mongod.27002[30380]: [ReplicationExecutor] Scheduling replSetElect to hingo-sputnik:27003
|
May 26 14:41:16 hingo-sputnik mongod.27003[30384]: [conn37] run command admin.$cmd { replSetElect: 1, set: "SERVER10268", who: "hingo-sputnik:27002", whoid: 1, cfgver: 3, round: ObjectId('55645bdc7b252803ef1c0d61') }
|
May 26 14:41:16 hingo-sputnik mongod.27003[30384]: [conn37] command: { replSetElect: 1, set: "SERVER10268", who: "hingo-sputnik:27002", whoid: 1, cfgver: 3, round: ObjectId('55645bdc7b252803ef1c0d61') }
|
May 26 14:41:16 hingo-sputnik mongod.27003[30384]: [conn37] replSet received elect msg { replSetElect: 1, set: "SERVER10268", who: "hingo-sputnik:27002", whoid: 1, cfgver: 3, round: ObjectId('55645bdc7b252803ef1c0d61') }
|
May 26 14:41:16 hingo-sputnik mongod.27003[30384]: [ReplicationExecutor] replSetElect voting yea for hingo-sputnik:27002 (1)
|
May 26 14:41:16 hingo-sputnik mongod.27003[30384]: [conn37] command admin.$cmd command: replSetElect { replSetElect: 1, set: "SERVER10268", who: "hingo-sputnik:27002", whoid: 1, cfgver: 3, round: ObjectId('55645bdc7b252803ef1c0d61') } ntoreturn:1 keyUpdates:0 writeConflicts:0 numYields:0 reslen:66 locks:{} 0ms
|
May 26 14:41:16 hingo-sputnik mongod.27002[30380]: [ReplExecNetThread-3] Network status of sending replSetElect to hingo-sputnik:27003 was OK
|
May 26 14:41:16 hingo-sputnik mongod.27002[30380]: [ReplicationExecutor] replSet elect res: { vote: 1, round: ObjectId('55645bdc7b252803ef1c0d61'), ok: 1.0 }
|
May 26 14:41:16 hingo-sputnik mongod.27002[30380]: [ReplicationExecutor] replSet election succeeded, assuming primary role
|
May 26 14:41:16 hingo-sputnik mongod.27002[30380]: [ReplicationExecutor] transition to PRIMARY
|
Set heartbeatTimeoutSecs to 2 and restart everything (just in case).
SERVER10268:PRIMARY> c.settings.heartbeatTimeoutSecs = 2
|
2
|
SERVER10268:PRIMARY> rs.reconfig(c)
|
{ "ok" : 1 }
|
SERVER10268:PRIMARY> rs.config()
|
{
|
"_id" : "SERVER10268",
|
"version" : 4,
|
"members" : [
|
{
|
"_id" : 0,
|
"host" : "hingo-sputnik:27001",
|
"arbiterOnly" : false,
|
"buildIndexes" : true,
|
"hidden" : false,
|
"priority" : 1,
|
"tags" : {
|
|
},
|
"slaveDelay" : 0,
|
"votes" : 1
|
},
|
{
|
"_id" : 1,
|
"host" : "hingo-sputnik:27002",
|
"arbiterOnly" : false,
|
"buildIndexes" : true,
|
"hidden" : false,
|
"priority" : 1,
|
"tags" : {
|
|
},
|
"slaveDelay" : 0,
|
"votes" : 1
|
},
|
{
|
"_id" : 2,
|
"host" : "hingo-sputnik:27003",
|
"arbiterOnly" : false,
|
"buildIndexes" : true,
|
"hidden" : false,
|
"priority" : 1,
|
"tags" : {
|
|
},
|
"slaveDelay" : 0,
|
"votes" : 1
|
}
|
],
|
"settings" : {
|
"chainingAllowed" : true,
|
"heartbeatTimeoutSecs" : 2,
|
"getLastErrorModes" : {
|
|
},
|
"getLastErrorDefaults" : {
|
"w" : 1,
|
"wtimeout" : 0
|
}
|
}
|
}
|
27001 is primary. Hitting Ctrl-Z.
Last log entry is:
May 26 15:04:06 hingo-sputnik mongod.27001[31988]: [durability] groupCommit end
|
First socket timeout at 15:04:09 = 3 secs later, correct within rounding margin of error!
Successfully standing for election also at 15:04:09 = still within 3 secs later!
May 26 15:04:07 hingo-sputnik mongod.27002[32048]: [ReplicationExecutor] Scheduling replSetHeartbeat to hingo-sputnik:27003
|
May 26 15:04:07 hingo-sputnik mongod.27002[32048]: [ReplicationExecutor] Scheduling replSetHeartbeat to hingo-sputnik:27001
|
May 26 15:04:07 hingo-sputnik mongod.27003[32114]: [conn7] run command admin.$cmd { replSetHeartbeat: "SERVER10268", pv: 1, v: 4, from: "hingo-sputnik:27002", fromId: 1, checkEmpty: false }
|
May 26 15:04:07 hingo-sputnik mongod.27003[32114]: [conn7] command: { replSetHeartbeat: "SERVER10268", pv: 1, v: 4, from: "hingo-sputnik:27002", fromId: 1, checkEmpty: false }
|
May 26 15:04:07 hingo-sputnik mongod.27003[32114]: [conn7] command admin.$cmd command: replSetHeartbeat { replSetHeartbeat: "SERVER10268", pv: 1, v: 4, from: "hingo-sputnik:27002", fromId: 1, checkEmpty: false } ntoreturn:1 keyUpdates:0 writeConflicts:0 numYields:0 reslen:123 locks:{} 0ms
|
May 26 15:04:07 hingo-sputnik mongod.27002[32048]: [ReplExecNetThread-2] Network status of sending replSetHeartbeat to hingo-sputnik:27003 was OK
|
May 26 15:04:07 hingo-sputnik mongod.27002[32048]: [ReplicationExecutor] setUpValues: heartbeat response good for member _id:2, msg:
|
May 26 15:04:07 hingo-sputnik mongod.27002[32048]: [ReplicationExecutor] Scheduling heartbeat to hingo-sputnik:27003 at 2015-05-26T12:04:09.179Z
|
...
|
May 26 15:04:07 hingo-sputnik mongod.27003[32114]: [ReplicationExecutor] Scheduling replSetHeartbeat to hingo-sputnik:27002
|
May 26 15:04:07 hingo-sputnik mongod.27003[32114]: [ReplExecNetThread-1] polling for status of connection to 127.0.1.1:27002, no events
|
May 26 15:04:07 hingo-sputnik mongod.27002[32048]: [conn9] run command admin.$cmd { replSetHeartbeat: "SERVER10268", pv: 1, v: 4, from: "hingo-sputnik:27003", fromId: 2, checkEmpty: false }
|
May 26 15:04:07 hingo-sputnik mongod.27002[32048]: [conn9] command: { replSetHeartbeat: "SERVER10268", pv: 1, v: 4, from: "hingo-sputnik:27003", fromId: 2, checkEmpty: false }
|
May 26 15:04:07 hingo-sputnik mongod.27002[32048]: [conn9] command admin.$cmd command: replSetHeartbeat { replSetHeartbeat: "SERVER10268", pv: 1, v: 4, from: "hingo-sputnik:27003", fromId: 2, checkEmpty: false } ntoreturn:1 keyUpdates:0 writeConflicts:0 numYields:0 reslen:123 locks:{} 0ms
|
May 26 15:04:07 hingo-sputnik mongod.27003[32114]: [ReplExecNetThread-1] Network status of sending replSetHeartbeat to hingo-sputnik:27002 was OK
|
May 26 15:04:07 hingo-sputnik mongod.27003[32114]: [ReplicationExecutor] setUpValues: heartbeat response good for member _id:1, msg:
|
May 26 15:04:07 hingo-sputnik mongod.27003[32114]: [ReplicationExecutor] Scheduling heartbeat to hingo-sputnik:27002 at 2015-05-26T12:04:09.501Z
|
May 26 15:04:07 hingo-sputnik mongod.27003[32114]: [ReplicationExecutor] Scheduling replSetHeartbeat to hingo-sputnik:27001
|
May 26 15:04:07 hingo-sputnik mongod.27003[32114]: [ReplExecNetThread-0] polling for status of connection to 127.0.1.1:27001, no events
|
...
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplExecNetThread-0] Socket recv() timeout 127.0.1.1:27001
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplExecNetThread-0] SocketException: remote: 127.0.1.1:27001 error: 9001 socket exception [RECV_TIMEOUT] server [127.0.1.1:27001]
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplExecNetThread-0] DBClientCursor::init call() failed
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplExecNetThread-0] User Assertion: 10276:DBClientBase::findN: transport error: hingo-sputnik:27001 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", pv: 1, v: 4, from: "hingo-sputnik:27002", fromId: 1, checkEmpty: false }
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplExecNetThread-0] Network status of sending replSetHeartbeat to hingo-sputnik:27001 was Location10276 DBClientBase::findN: transport error: hingo-sputnik:27001 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", pv: 1, v: 4, from: "hingo-sputnik:27002", fromId: 1, checkEmpty: false }
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplicationExecutor] Error in heartbeat request to hingo-sputnik:27001; Location10276 DBClientBase::findN: transport error: hingo-sputnik:27001 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", pv: 1, v: 4, from: "hingo-sputnik:27002", fromId: 1, checkEmpty: false }
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplicationExecutor] Bad heartbeat response from hingo-sputnik:27001; trying again; Retries left: 1; 1998ms have already elapsed
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplicationExecutor] setDownValues: heartbeat response failed for member _id:0, msg: DBClientBase::findN: transport error: hingo-sputnik:27001 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", pv: 1, v: 4, from: "hingo-sputnik:27002", fromId: 1, checkEmpty: false }
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplicationExecutor] Scheduling heartbeat to hingo-sputnik:27001 at 2015-05-26T12:04:09.176Z
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplicationExecutor] Standing for election
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplicationExecutor] Scheduling replSetFresh to hingo-sputnik:27003
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplicationExecutor] Scheduling replSetHeartbeat to hingo-sputnik:27001
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplExecNetThread-2] polling for status of connection to 127.0.1.1:27003, no events
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [conn7] run command admin.$cmd { replSetFresh: 1, set: "SERVER10268", opTime: new Date(6153149063702249473), who: "hingo-sputnik:27002", cfgver: 4, id: 1 }
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [conn7] command: { replSetFresh: 1, set: "SERVER10268", opTime: new Date(6153149063702249473), who: "hingo-sputnik:27002", cfgver: 4, id: 1 }
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ConnectBG] BackgroundJob starting: ConnectBG
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [conn7] command admin.$cmd command: replSetFresh { replSetFresh: 1, set: "SERVER10268", opTime: new Date(6153149063702249473), who: "hingo-sputnik:27002", cfgver: 4, id: 1 } ntoreturn:1 keyUpdates:0 writeConflicts:0 numYields:0 reslen:191 locks:{} 0ms
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplExecNetThread-0] connected to server hingo-sputnik:27001 (127.0.1.1)
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplExecNetThread-2] Network status of sending replSetFresh to hingo-sputnik:27003 was OK
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplicationExecutor] FreshnessChecker: Got response from hingo-sputnik:27003 of { opTime: new Date(6153149063702249473), fresher: false, veto: true, errmsg: "hingo-sputnik:27002 is trying to elect itself but hingo-sputnik:27001 is already primary and more up-to-date", ok: 1.0 }
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplicationExecutor] not electing self, hingo-sputnik:27003 would veto with 'hingo-sputnik:27002 is trying to elect itself but hingo-sputnik:27001 is already primary and more up-to-date'
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplicationExecutor] not electing self, we are not freshest
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplExecNetThread-0] Socket recv() timeout 127.0.1.1:27001
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplExecNetThread-0] SocketException: remote: 127.0.1.1:27001 error: 9001 socket exception [RECV_TIMEOUT] server [127.0.1.1:27001]
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplExecNetThread-0] DBClientCursor::init call() failed
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplExecNetThread-0] User Assertion: 10276:DBClientBase::findN: transport error: hingo-sputnik:27001 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", pv: 1, v: 4, from: "hingo-sputnik:27002", fromId: 1, checkEmpty: false }
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplExecNetThread-0] Network status of sending replSetHeartbeat to hingo-sputnik:27001 was Location10276 DBClientBase::findN: transport error: hingo-sputnik:27001 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", pv: 1, v: 4, from: "hingo-sputnik:27002", fromId: 1, checkEmpty: false }
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplicationExecutor] Scheduling replSetHeartbeat to hingo-sputnik:27003
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplicationExecutor] Error in heartbeat request to hingo-sputnik:27001; Location10276 DBClientBase::findN: transport error: hingo-sputnik:27001 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", pv: 1, v: 4, from: "hingo-sputnik:27002", fromId: 1, checkEmpty: false }
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [conn7] run command admin.$cmd { replSetHeartbeat: "SERVER10268", pv: 1, v: 4, from: "hingo-sputnik:27002", fromId: 1, checkEmpty: false }
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplicationExecutor] setDownValues: heartbeat response failed for member _id:0, msg: DBClientBase::findN: transport error: hingo-sputnik:27001 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", pv: 1, v: 4, from: "hingo-sputnik:27002", fromId: 1, checkEmpty: false }
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [conn7] command: { replSetHeartbeat: "SERVER10268", pv: 1, v: 4, from: "hingo-sputnik:27002", fromId: 1, checkEmpty: false }
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplicationExecutor] Scheduling heartbeat to hingo-sputnik:27001 at 2015-05-26T12:04:11.180Z
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplicationExecutor] Standing for election
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [conn7] command admin.$cmd command: replSetHeartbeat { replSetHeartbeat: "SERVER10268", pv: 1, v: 4, from: "hingo-sputnik:27002", fromId: 1, checkEmpty: false } ntoreturn:1 keyUpdates:0 writeConflicts:0 numYields:0 reslen:123 locks:{} 0ms
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplicationExecutor] Scheduling replSetFresh to hingo-sputnik:27003
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplExecNetThread-2] Network status of sending replSetHeartbeat to hingo-sputnik:27003 was OK
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplicationExecutor] setUpValues: heartbeat response good for member _id:2, msg:
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ConnectBG] BackgroundJob starting: ConnectBG
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplicationExecutor] Not standing for election again; already candidate
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplicationExecutor] Scheduling heartbeat to hingo-sputnik:27003 at 2015-05-26T12:04:11.180Z
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [initandlisten] connection accepted from 127.0.0.1:52583 #8 (3 connections now open)
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplExecNetThread-0] connected to server hingo-sputnik:27003 (127.0.1.1)
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [conn8] run command admin.$cmd { replSetFresh: 1, set: "SERVER10268", opTime: new Date(6153149063702249473), who: "hingo-sputnik:27002", cfgver: 4, id: 1 }
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [conn8] command: { replSetFresh: 1, set: "SERVER10268", opTime: new Date(6153149063702249473), who: "hingo-sputnik:27002", cfgver: 4, id: 1 }
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [conn8] command admin.$cmd command: replSetFresh { replSetFresh: 1, set: "SERVER10268", opTime: new Date(6153149063702249473), who: "hingo-sputnik:27002", cfgver: 4, id: 1 } ntoreturn:1 keyUpdates:0 writeConflicts:0 numYields:0 reslen:191 locks:{} 0ms
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplExecNetThread-0] Network status of sending replSetFresh to hingo-sputnik:27003 was OK
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplicationExecutor] FreshnessChecker: Got response from hingo-sputnik:27003 of { opTime: new Date(6153149063702249473), fresher: false, veto: true, errmsg: "hingo-sputnik:27002 is trying to elect itself but hingo-sputnik:27001 is already primary and more up-to-date", ok: 1.0 }
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplicationExecutor] not electing self, hingo-sputnik:27003 would veto with 'hingo-sputnik:27002 is trying to elect itself but hingo-sputnik:27001 is already primary and more up-to-date'
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplicationExecutor] not electing self, we are not freshest
|
...
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplExecNetThread-0] Socket recv() timeout 127.0.1.1:27001
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplExecNetThread-0] SocketException: remote: 127.0.1.1:27001 error: 9001 socket exception [RECV_TIMEOUT] server [127.0.1.1:27001]
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplExecNetThread-0] DBClientCursor::init call() failed
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplExecNetThread-0] User Assertion: 10276:DBClientBase::findN: transport error: hingo-sputnik:27001 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", pv: 1, v: 4, from: "hingo-sputnik:27003", fromId: 2, checkEmpty: false }
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplExecNetThread-0] Network status of sending replSetHeartbeat to hingo-sputnik:27001 was Location10276 DBClientBase::findN: transport error: hingo-sputnik:27001 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", pv: 1, v: 4, from: "hingo-sputnik:27003", fromId: 2, checkEmpty: false }
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplicationExecutor] Error in heartbeat request to hingo-sputnik:27001; Location10276 DBClientBase::findN: transport error: hingo-sputnik:27001 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", pv: 1, v: 4, from: "hingo-sputnik:27003", fromId: 2, checkEmpty: false }
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplicationExecutor] Bad heartbeat response from hingo-sputnik:27001; trying again; Retries left: 1; 1999ms have already elapsed
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplicationExecutor] setDownValues: heartbeat response failed for member _id:0, msg: DBClientBase::findN: transport error: hingo-sputnik:27001 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", pv: 1, v: 4, from: "hingo-sputnik:27003", fromId: 2, checkEmpty: false }
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplicationExecutor] Scheduling heartbeat to hingo-sputnik:27001 at 2015-05-26T12:04:09.500Z
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplicationExecutor] Standing for election
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplicationExecutor] Scheduling replSetFresh to hingo-sputnik:27002
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplicationExecutor] Scheduling replSetHeartbeat to hingo-sputnik:27001
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplicationExecutor] Scheduling replSetHeartbeat to hingo-sputnik:27002
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [conn9] run command admin.$cmd { replSetFresh: 1, set: "SERVER10268", opTime: new Date(6153149063702249473), who: "hingo-sputnik:27003", cfgver: 4, id: 2 }
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [conn9] command: { replSetFresh: 1, set: "SERVER10268", opTime: new Date(6153149063702249473), who: "hingo-sputnik:27003", cfgver: 4, id: 2 }
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplExecNetThread-2] thread starting
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [conn9] command admin.$cmd command: replSetFresh { replSetFresh: 1, set: "SERVER10268", opTime: new Date(6153149063702249473), who: "hingo-sputnik:27003", cfgver: 4, id: 2 } ntoreturn:1 keyUpdates:0 writeConflicts:0 numYields:0 reslen:70 locks:{} 0ms
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplExecNetThread-1] Network status of sending replSetFresh to hingo-sputnik:27002 was OK
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplicationExecutor] FreshnessChecker: Got response from hingo-sputnik:27002 of { opTime: new Date(6153149063702249473), fresher: false, veto: false, ok: 1.0 }
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ConnectBG] BackgroundJob starting: ConnectBG
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ConnectBG] BackgroundJob starting: ConnectBG
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplicationExecutor] replSet possible election tie; sleeping 317ms until 2015-05-26T15:04:09.819+0300
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplExecNetThread-0] connected to server hingo-sputnik:27001 (127.0.1.1)
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [initandlisten] connection accepted from 127.0.0.1:60834 #10 (3 connections now open)
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplExecNetThread-2] connected to server hingo-sputnik:27002 (127.0.1.1)
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [conn10] run command admin.$cmd { replSetHeartbeat: "SERVER10268", pv: 1, v: 4, from: "hingo-sputnik:27003", fromId: 2, checkEmpty: false }
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [conn10] command: { replSetHeartbeat: "SERVER10268", pv: 1, v: 4, from: "hingo-sputnik:27003", fromId: 2, checkEmpty: false }
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [conn10] command admin.$cmd command: replSetHeartbeat { replSetHeartbeat: "SERVER10268", pv: 1, v: 4, from: "hingo-sputnik:27003", fromId: 2, checkEmpty: false } ntoreturn:1 keyUpdates:0 writeConflicts:0 numYields:0 reslen:123 locks:{} 0ms
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplExecNetThread-2] Network status of sending replSetHeartbeat to hingo-sputnik:27002 was OK
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplicationExecutor] setUpValues: heartbeat response good for member _id:1, msg:
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplicationExecutor] Not standing for election before 2015-05-26T15:04:09.819+0300 because I stood too recently
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplicationExecutor] Scheduling heartbeat to hingo-sputnik:27002 at 2015-05-26T12:04:11.503Z
|
...
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplicationExecutor] Standing for election
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplicationExecutor] Scheduling replSetFresh to hingo-sputnik:27002
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [conn10] run command admin.$cmd { replSetFresh: 1, set: "SERVER10268", opTime: new Date(6153149063702249473), who: "hingo-sputnik:27003", cfgver: 4, id: 2 }
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [conn10] command: { replSetFresh: 1, set: "SERVER10268", opTime: new Date(6153149063702249473), who: "hingo-sputnik:27003", cfgver: 4, id: 2 }
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [conn10] command admin.$cmd command: replSetFresh { replSetFresh: 1, set: "SERVER10268", opTime: new Date(6153149063702249473), who: "hingo-sputnik:27003", cfgver: 4, id: 2 } ntoreturn:1 keyUpdates:0 writeConflicts:0 numYields:0 reslen:70 locks:{} 0ms
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplExecNetThread-1] Network status of sending replSetFresh to hingo-sputnik:27002 was OK
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplicationExecutor] FreshnessChecker: Got response from hingo-sputnik:27002 of { opTime: new Date(6153149063702249473), fresher: false, veto: false, ok: 1.0 }
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplicationExecutor] replSet info electSelf
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplicationExecutor] Scheduling replSetElect to hingo-sputnik:27002
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [conn10] run command admin.$cmd { replSetElect: 1, set: "SERVER10268", who: "hingo-sputnik:27003", whoid: 2, cfgver: 4, round: ObjectId('556461394400a54cbc733d8c') }
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [conn10] command: { replSetElect: 1, set: "SERVER10268", who: "hingo-sputnik:27003", whoid: 2, cfgver: 4, round: ObjectId('556461394400a54cbc733d8c') }
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [conn10] replSet received elect msg { replSetElect: 1, set: "SERVER10268", who: "hingo-sputnik:27003", whoid: 2, cfgver: 4, round: ObjectId('556461394400a54cbc733d8c') }
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [ReplicationExecutor] replSetElect voting yea for hingo-sputnik:27003 (2)
|
May 26 15:04:09 hingo-sputnik mongod.27002[32048]: [conn10] command admin.$cmd command: replSetElect { replSetElect: 1, set: "SERVER10268", who: "hingo-sputnik:27003", whoid: 2, cfgver: 4, round: ObjectId('556461394400a54cbc733d8c') } ntoreturn:1 keyUpdates:0 writeConflicts:0 numYields:0 reslen:66 locks:{} 0ms
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplExecNetThread-2] Network status of sending replSetElect to hingo-sputnik:27002 was OK
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplicationExecutor] replSet elect res: { vote: 1, round: ObjectId('556461394400a54cbc733d8c'), ok: 1.0 }
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplicationExecutor] replSet election succeeded, assuming primary role
|
May 26 15:04:09 hingo-sputnik mongod.27003[32114]: [ReplicationExecutor] transition to PRIMARY
|
|
|
Reproducing with 2.4.5 on Ubuntu 14.04 without a mongos. heartbeatTimeoutSecs is ineffective just as in original description.
bin/mongod --port 27001 --dbpath /data/db1 --syslog --replSet SERVER10268 -vvvv
|
bin/mongod --port 27002 --dbpath /data/db2 --syslog --replSet SERVER10268 -vvvv
|
bin/mongod --port 27003 --dbpath /data/db3 --syslog --replSet SERVER10268 -vvvv
|
|
rs.initiate()
|
rs.add("hingo-sputnik:27002")
|
rs.add("hingo-sputnik:27003")
|
|
db.testdata.insert({foo:"bar"})
|
|
|
Syslog snippet from 2.4.5 with above setup follows.
27003 is primary: hit Ctrl-Z. Last log line seen from 27003
May 26 11:48:05 hingo-sputnik mongod.27003[22035]: Tue May 26 11:48:05.985 [conn12] command admin.$cmd command: { replSetHeartbeat: "SERVER10268", v: 3, pv: 1, checkEmpty: false, from: "hingo-sputnik:27002" } ntoreturn:1 keyUpdates:0 reslen:127 0ms
|
First symptom on 27001 are 10.025 seconds later, but rsHealthPoll only notices this after a total of 11.3 seconds. And 27002 a bit after that. 27002 arrives at electSelf at 11:48:19.664 and assumes PRIMARY at 11:48:44.981.
May 26 11:48:16 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:16.010 [conn10] Socket recv() conn closed? 127.0.0.1:33058
|
May 26 11:48:16 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:16.010 [conn10] SocketException: remote: 127.0.0.1:33058 error: 9001 socket exception [0] server [127.0.0.1:33058]
|
May 26 11:48:16 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:16.010 [conn10] end connection 127.0.0.1:33058 (1 connection now open)
|
...
|
May 26 11:48:17 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:17.331 [rsHealthPoll] Socket recv() timeout 127.0.1.1:27003
|
May 26 11:48:17 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:17.331 [rsHealthPoll] SocketException: remote: 127.0.1.1:27003 error: 9001 socket exception [3] server [127.0.1.1:27003]
|
May 26 11:48:17 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:17.331 [rsHealthPoll] DBClientCursor::init call() failed
|
May 26 11:48:17 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:17.331 [rsHealthPoll] User Assertion: 10276:DBClientBase::findN: transport error: hingo-sputnik:27003 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", v: 3, pv: 1, checkEmpty: false, from: "hingo-sputnik:27001" }
|
May 26 11:48:17 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:17.332 [rsHealthPoll] replset info hingo-sputnik:27003 heartbeat failed, retrying
|
May 26 11:48:17 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:17.332 [rsHealthPoll] trying reconnect to hingo-sputnik:27003
|
May 26 11:48:17 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:17.332 BackgroundJob starting: ConnectBG
|
May 26 11:48:17 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:17.333 [rsHealthPoll] reconnect hingo-sputnik:27003 ok
|
.......................................
|
May 26 11:48:17 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:17.983 [rsHealthPoll] Socket recv() timeout 127.0.1.1:27003
|
May 26 11:48:17 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:17.983 [rsHealthPoll] SocketException: remote: 127.0.1.1:27003 error: 9001 socket exception [3] server [127.0.1.1:27003]
|
May 26 11:48:17 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:17.983 [rsHealthPoll] DBClientCursor::init call() failed
|
May 26 11:48:17 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:17.983 [rsHealthPoll] User Assertion: 10276:DBClientBase::findN: transport error: hingo-sputnik:27003 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", v: 3, pv: 1, checkEmpty: false, from: "hingo-sputnik:27002" }
|
May 26 11:48:17 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:17.984 [rsHealthPoll] replset info hingo-sputnik:27003 heartbeat failed, retrying
|
May 26 11:48:17 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:17.984 [rsHealthPoll] trying reconnect to hingo-sputnik:27003
|
May 26 11:48:17 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:17.984 BackgroundJob starting: ConnectBG
|
May 26 11:48:17 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:17.984 [rsHealthPoll] reconnect hingo-sputnik:27003 ok
|
............................................................................................
|
May 26 11:48:18 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:18.331 [rsHealthPoll] Socket recv() timeout 127.0.1.1:27003
|
May 26 11:48:18 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:18.331 [rsHealthPoll] SocketException: remote: 127.0.1.1:27003 error: 9001 socket exception [3] server [127.0.1.1:27003]
|
May 26 11:48:18 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:18.331 [rsHealthPoll] DBClientCursor::init call() failed
|
May 26 11:48:18 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:18.331 [rsHealthPoll] User Assertion: 10276:DBClientBase::findN: transport error: hingo-sputnik:27003 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", v: 3, pv: 1, checkEmpty: false, from: "hingo-sputnik:27001" }
|
May 26 11:48:18 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:18.332 [rsHealthPoll] replSet info hingo-sputnik:27003 is down (or slow to respond):
|
May 26 11:48:18 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:18.332 [rsHealthPoll] replSet member hingo-sputnik:27003 is now in state DOWN
|
May 26 11:48:18 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:18.332 BackgroundJob starting: MultiCommandJob
|
...
|
May 26 11:48:18 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:18.333 [rsMgr] not electing self, hingo-sputnik:27002 would veto with 'hingo-sputnik:27001 is trying to elect itself but hingo-sputnik:27003 is already primary and more up-to-date'
|
...
|
May 26 11:48:18 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:18.983 [rsHealthPoll] Socket recv() timeout 127.0.1.1:27003
|
May 26 11:48:18 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:18.983 [rsHealthPoll] SocketException: remote: 127.0.1.1:27003 error: 9001 socket exception [3] server [127.0.1.1:27003]
|
May 26 11:48:18 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:18.983 [rsHealthPoll] DBClientCursor::init call() failed
|
May 26 11:48:18 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:18.984 [rsHealthPoll] User Assertion: 10276:DBClientBase::findN: transport error: hingo-sputnik:27003 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", v: 3, pv: 1, checkEmpty: false, from: "hingo-sputnik:27002" }
|
May 26 11:48:18 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:18.984 [rsHealthPoll] replSet info hingo-sputnik:27003 is down (or slow to respond):
|
May 26 11:48:18 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:18.984 [rsHealthPoll] replSet member hingo-sputnik:27003 is now in state DOWN
|
May 26 11:48:18 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:18.984 BackgroundJob starting: MultiCommandJob
|
...
|
May 26 11:48:18 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:18.985 [rsMgr] replSet dev we are freshest of up nodes, nok:1 nTies:1
|
...
|
May 26 11:48:19 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:19.664 [rsMgr] replSet dev we are freshest of up nodes, nok:1 nTies:1
|
May 26 11:48:19 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:19.664 [rsMgr] replSet info electSelf 1
|
May 26 11:48:19 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:19.664 BackgroundJob starting: MultiCommandJob
|
...
|
May 26 11:48:19 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:19.665 [conn11] replSet info voting yea for hingo-sputnik:27002 (1)
|
...
|
May 26 11:48:19 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:19.665 [rsMgr] replSet election succeeded, assuming primary role
|
May 26 11:48:19 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:19.665 [rsMgr] replSet assuming primary
|
May 26 11:48:19 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:19.665 [rsMgr] replSet waiting for replication to finish before becoming primary
|
...
|
May 26 11:48:23 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:23.344 [rsMgr] replSet dev we are freshest of up nodes, nok:1 nTies:1
|
May 26 11:48:23 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:23.344 [rsMgr] replSet not voting yea for 0 voted for 1 4 secs ago
|
May 26 11:48:23 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:23.344 [rsMgr] replSet not trying to elect self as responded yea to someone else recently
|
...
|
May 26 11:48:27 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:27.345 [conn9] Socket recv() conn closed? 127.0.0.1:56159
|
May 26 11:48:27 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:27.345 [conn9] SocketException: remote: 127.0.0.1:56159 error: 9001 socket exception [0] server [127.0.0.1:56159]
|
May 26 11:48:27 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:27.345 [conn9] end connection 127.0.0.1:56159 (1 connection now open)
|
...
|
May 26 11:48:29 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:29.348 [rsMgr] replSet dev we are freshest of up nodes, nok:1 nTies:1
|
May 26 11:48:29 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:29.348 [rsMgr] replSet not voting yea for 0 voted for 1 10 secs ago
|
May 26 11:48:29 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:29.348 [rsMgr] replSet not trying to elect self as responded yea to someone else recently
|
...
|
May 26 11:48:30 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:30.331 [rsHealthPoll] Socket recv() timeout 127.0.1.1:27003
|
May 26 11:48:30 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:30.331 [rsHealthPoll] SocketException: remote: 127.0.1.1:27003 error: 9001 socket exception [3] server [127.0.1.1:27003]
|
May 26 11:48:30 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:30.331 [rsHealthPoll] DBClientCursor::init call() failed
|
May 26 11:48:30 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:30.331 [rsHealthPoll] User Assertion: 10276:DBClientBase::findN: transport error: hingo-sputnik:27003 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", v: 3, pv: 1, checkEmpty: false, from: "hingo-sputnik:27001" }
|
May 26 11:48:30 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:30.332 [rsHealthPoll] replset info hingo-sputnik:27003 heartbeat failed, retrying
|
...
|
May 26 11:48:30 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:30.983 [rsHealthPoll] Socket recv() timeout 127.0.1.1:27003
|
May 26 11:48:30 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:30.983 [rsHealthPoll] SocketException: remote: 127.0.1.1:27003 error: 9001 socket exception [3] server [127.0.1.1:27003]
|
May 26 11:48:30 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:30.983 [rsHealthPoll] DBClientCursor::init call() failed
|
May 26 11:48:30 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:30.983 [rsHealthPoll] User Assertion: 10276:DBClientBase::findN: transport error: hingo-sputnik:27003 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", v: 3, pv: 1, checkEmpty: false, from: "hingo-sputnik:27002" }
|
May 26 11:48:30 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:30.983 [rsHealthPoll] replset info hingo-sputnik:27003 heartbeat failed, retrying
|
May 26 11:48:30 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:30.983 [rsHealthPoll] trying reconnect to hingo-sputnik:27003
|
May 26 11:48:30 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:30.984 BackgroundJob starting: ConnectBG
|
May 26 11:48:30 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:30.984 [rsHealthPoll] reconnect hingo-sputnik:27003 ok
|
May 26 11:48:31 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:31.331 [rsHealthPoll] Socket recv() timeout 127.0.1.1:27003
|
May 26 11:48:31 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:31.331 [rsHealthPoll] SocketException: remote: 127.0.1.1:27003 error: 9001 socket exception [3] server [127.0.1.1:27003]
|
May 26 11:48:31 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:31.331 [rsHealthPoll] DBClientCursor::init call() failed
|
May 26 11:48:31 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:31.332 [rsHealthPoll] User Assertion: 10276:DBClientBase::findN: transport error: hingo-sputnik:27003 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", v: 3, pv: 1, checkEmpty: false, from: "hingo-sputnik:27001" }
|
...
|
...
|
May 26 11:48:35 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:35.350 [rsMgr] replSet dev we are freshest of up nodes, nok:1 nTies:1
|
May 26 11:48:35 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:35.350 [rsMgr] replSet not voting yea for 0 voted for 1 16 secs ago
|
May 26 11:48:35 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:35.350 [rsMgr] replSet not trying to elect self as responded yea to someone else recently
|
...
|
May 26 11:48:41 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:41.353 [rsMgr] replSet dev we are freshest of up nodes, nok:1 nTies:1
|
May 26 11:48:41 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:41.353 [rsMgr] replSet not voting yea for 0 voted for 1 22 secs ago
|
May 26 11:48:41 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:41.353 [rsMgr] replSet not trying to elect self as responded yea to someone else recently
|
...
|
yadayadayada
|
...
|
May 26 11:48:41 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:41.353 [rsMgr] replSet dev we are freshest of up nodes, nok:1 nTies:1
|
May 26 11:48:41 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:41.353 [rsMgr] replSet not voting yea for 0 voted for 1 22 secs ago
|
May 26 11:48:41 hingo-sputnik mongod.27001[22264]: Tue May 26 11:48:41.353 [rsMgr] replSet not trying to elect self as responded yea to someone else recently
|
...
|
May 26 11:48:44 hingo-sputnik mongod.27002[22124]: Tue May 26 11:48:44.981 [rsMgr] replSet PRIMARY
|
Set heartbeatTimeoutSecs as in the description, then hit Ctrl-Z on 27002.
Last log line from 27002:
May 26 12:38:40 hingo-sputnik mongod.27002[22124]: Tue May 26 12:38:40.704 [conn118] command admin.$cmd command: { replSetHeartbeat: "SERVER10268", v: 4, pv: 1, checkEmpty: false, from: "hingo-sputnik:27001" } ntoreturn:1 keyUpdates:0 reslen:127 0ms
|
27003 sees first symptoms 7.6 seconds later, rsHealthPoll 11.2 seconds later. So apparently heartbeatTimeoutSecs had no effect?
May 26 12:38:48 hingo-sputnik mongod.27003[22035]: Tue May 26 12:38:48.386 [conn163] Socket recv() conn closed? 127.0.0.1:49258
|
May 26 12:38:48 hingo-sputnik mongod.27003[22035]: Tue May 26 12:38:48.386 [conn163] SocketException: remote: 127.0.0.1:49258 error: 9001 socket exception [0] server [127.0.0.1:49258]
|
May 26 12:38:48 hingo-sputnik mongod.27003[22035]: Tue May 26 12:38:48.386 [conn163] end connection 127.0.0.1:49258 (2 connections now open)
|
...
|
May 26 12:38:49 hingo-sputnik mongod.27001[22264]: Tue May 26 12:38:49.942 [conn115] Socket recv() conn closed? 127.0.0.1:34410
|
May 26 12:38:49 hingo-sputnik mongod.27001[22264]: Tue May 26 12:38:49.943 [conn115] SocketException: remote: 127.0.0.1:34410 error: 9001 socket exception [0] server [127.0.0.1:34410]
|
May 26 12:38:49 hingo-sputnik mongod.27001[22264]: Tue May 26 12:38:49.943 [conn115] end connection 127.0.0.1:34410 (1 connection now open)
|
...
|
May 26 12:38:51 hingo-sputnik mongod.27003[22035]: Tue May 26 12:38:51.939 [rsHealthPoll] Socket recv() timeout 127.0.1.1:27002
|
May 26 12:38:51 hingo-sputnik mongod.27003[22035]: Tue May 26 12:38:51.939 [rsHealthPoll] SocketException: remote: 127.0.1.1:27002 error: 9001 socket exception [3] server [127.0.1.1:27002]
|
May 26 12:38:51 hingo-sputnik mongod.27003[22035]: Tue May 26 12:38:51.939 [rsHealthPoll] DBClientCursor::init call() failed
|
May 26 12:38:51 hingo-sputnik mongod.27003[22035]: Tue May 26 12:38:51.939 [rsHealthPoll] User Assertion: 10276:DBClientBase::findN: transport error: hingo-sputnik:27002 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", v: 4, pv: 1, checkEmpty: false, from: "hingo-sputnik:27003" }
|
May 26 12:38:51 hingo-sputnik mongod.27003[22035]: Tue May 26 12:38:51.939 [rsHealthPoll] replSet info hingo-sputnik:27002 is down (or slow to respond):
|
May 26 12:38:51 hingo-sputnik mongod.27003[22035]: Tue May 26 12:38:51.940 [rsHealthPoll] replSet member hingo-sputnik:27002 is now in state DOWN
|
May 26 12:38:51 hingo-sputnik mongod.27003[22035]: Tue May 26 12:38:51.940 BackgroundJob starting: MultiCommandJob
|
...
|
May 26 12:38:52 hingo-sputnik mongod.27001[22264]: Tue May 26 12:38:52.703 [rsHealthPoll] Socket recv() timeout 127.0.1.1:27002
|
May 26 12:38:52 hingo-sputnik mongod.27001[22264]: Tue May 26 12:38:52.703 [rsHealthPoll] SocketException: remote: 127.0.1.1:27002 error: 9001 socket exception [3] server [127.0.1.1:27002]
|
May 26 12:38:52 hingo-sputnik mongod.27001[22264]: Tue May 26 12:38:52.703 [rsHealthPoll] DBClientCursor::init call() failed
|
May 26 12:38:52 hingo-sputnik mongod.27001[22264]: Tue May 26 12:38:52.703 [rsHealthPoll] User Assertion: 10276:DBClientBase::findN: transport error: hingo-sputnik:27002 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", v: 4, pv: 1, checkEmpty: false, from: "hingo-sputnik:27001" }
|
May 26 12:38:52 hingo-sputnik mongod.27001[22264]: Tue May 26 12:38:52.704 [rsHealthPoll] replset info hingo-sputnik:27002 heartbeat failed, retrying
|
May 26 12:38:52 hingo-sputnik mongod.27001[22264]: Tue May 26 12:38:52.704 [rsHealthPoll] trying reconnect to hingo-sputnik:27002
|
May 26 12:38:52 hingo-sputnik mongod.27001[22264]: Tue May 26 12:38:52.704 BackgroundJob starting: ConnectBG
|
May 26 12:38:52 hingo-sputnik mongod.27001[22264]: Tue May 26 12:38:52.704 [rsHealthPoll] reconnect hingo-sputnik:27002 ok
|
...
|
May 26 12:38:53 hingo-sputnik mongod.27001[22264]: Tue May 26 12:38:53.703 [rsHealthPoll] Socket recv() timeout 127.0.1.1:27002
|
May 26 12:38:53 hingo-sputnik mongod.27001[22264]: Tue May 26 12:38:53.703 [rsHealthPoll] SocketException: remote: 127.0.1.1:27002 error: 9001 socket exception [3] server [127.0.1.1:27002]
|
May 26 12:38:53 hingo-sputnik mongod.27001[22264]: Tue May 26 12:38:53.703 [rsHealthPoll] DBClientCursor::init call() failed
|
May 26 12:38:53 hingo-sputnik mongod.27001[22264]: Tue May 26 12:38:53.704 [rsHealthPoll] User Assertion: 10276:DBClientBase::findN: transport error: hingo-sputnik:27002 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", v: 4, pv: 1, checkEmpty: false, from: "hingo-sputnik:27001" }
|
May 26 12:38:53 hingo-sputnik mongod.27001[22264]: Tue May 26 12:38:53.704 [rsHealthPoll] replSet info hingo-sputnik:27002 is down (or slow to respond):
|
May 26 12:38:53 hingo-sputnik mongod.27001[22264]: Tue May 26 12:38:53.704 [rsHealthPoll] replSet member hingo-sputnik:27002 is now in state DOWN
|
May 26 12:38:53 hingo-sputnik mongod.27001[22264]: Tue May 26 12:38:53.704 BackgroundJob starting: MultiCommandJob
|
...
|
May 26 12:38:53 hingo-sputnik mongod.27001[22264]: Tue May 26 12:38:53.705 [rsMgr] replSet dev we are freshest of up nodes, nok:1 nTies:1
|
May 26 12:38:53 hingo-sputnik mongod.27001[22264]: Tue May 26 12:38:53.705 [rsMgr] replSet info electSelf 0
|
May 26 12:38:53 hingo-sputnik mongod.27001[22264]: Tue May 26 12:38:53.705 BackgroundJob starting: MultiCommandJob
|
...
|
May 26 12:38:53 hingo-sputnik mongod.27003[22035]: Tue May 26 12:38:53.706 [conn165] runQuery called admin.$cmd { replSetElect: 1, set: "SERVER10268", who: "hingo-sputnik:27001", whoid: 0, cfgver: 4, round: ObjectId('55643f2d625330bdfcbaee3b') }
|
May 26 12:38:53 hingo-sputnik mongod.27003[22035]: Tue May 26 12:38:53.706 [conn165] run command admin.$cmd { replSetElect: 1, set: "SERVER10268", who: "hingo-sputnik:27001", whoid: 0, cfgver: 4, round: ObjectId('55643f2d625330bdfcbaee3b') }
|
May 26 12:38:53 hingo-sputnik mongod.27003[22035]: Tue May 26 12:38:53.706 [conn165] command: { replSetElect: 1, set: "SERVER10268", who: "hingo-sputnik:27001", whoid: 0, cfgver: 4, round: ObjectId('55643f2d625330bdfcbaee3b') }
|
May 26 12:38:53 hingo-sputnik mongod.27003[22035]: Tue May 26 12:38:53.706 [conn165] replSet received elect msg { replSetElect: 1, set: "SERVER10268", who: "hingo-sputnik:27001", whoid: 0, cfgver: 4, round: ObjectId('55643f2d625330bdfcbaee3b') }
|
May 26 12:38:53 hingo-sputnik mongod.27003[22035]: Tue May 26 12:38:53.706 [conn165] replSet attempting to relinquish
|
May 26 12:38:53 hingo-sputnik mongod.27003[22035]: Tue May 26 12:38:53.706 [conn165] replSet info voting yea for hingo-sputnik:27001 (0)
|
May 26 12:38:53 hingo-sputnik mongod.27003[22035]: Tue May 26 12:38:53.706 [conn165] command admin.$cmd command: { replSetElect: 1, set: "SERVER10268", who: "hingo-sputnik:27001", whoid: 0, cfgver: 4, round: ObjectId('55643f2d625330bdfcbaee3b') } ntoreturn:1 keyUpdates:0 locks(micros) W:37 reslen:66 0ms
|
May 26 12:38:53 hingo-sputnik mongod.27001[22264]: Tue May 26 12:38:53.706 [rsMgr] replSet election succeeded, assuming primary role
|
May 26 12:38:53 hingo-sputnik mongod.27001[22264]: Tue May 26 12:38:53.707 [rsMgr] replSet assuming primary
|
May 26 12:38:53 hingo-sputnik mongod.27001[22264]: Tue May 26 12:38:53.707 [rsMgr] replSet waiting for replication to finish before becoming primary
|
May 26 12:38:53 hingo-sputnik mongod.27003[22035]: Tue May 26 12:38:53.940 [rsHealthPoll] trying reconnect to hingo-sputnik:27002
|
May 26 12:38:53 hingo-sputnik mongod.27003[22035]: Tue May 26 12:38:53.941 BackgroundJob starting: ConnectBG
|
May 26 12:38:53 hingo-sputnik mongod.27003[22035]: Tue May 26 12:38:53.941 [rsHealthPoll] reconnect hingo-sputnik:27002 ok
|
May 26 12:38:53 hingo-sputnik mongod.27001[22264]: Tue May 26 12:38:53.945 [conn116] runQuery called admin.$cmd { replSetHeartbeat: "SERVER10268", v: 4, pv: 1, checkEmpty: false, from: "hingo-sputnik:27003" }
|
May 26 12:38:53 hingo-sputnik mongod.27001[22264]: Tue May 26 12:38:53.945 [conn116] run command admin.$cmd { replSetHeartbeat: "SERVER10268", v: 4, pv: 1, checkEmpty: false, from: "hingo-sputnik:27003" }
|
May 26 12:38:53 hingo-sputnik mongod.27001[22264]: Tue May 26 12:38:53.945 [conn116] command: { replSetHeartbeat: "SERVER10268", v: 4, pv: 1, checkEmpty: false, from: "hingo-sputnik:27003" }
|
May 26 12:38:53 hingo-sputnik mongod.27001[22264]: Tue May 26 12:38:53.946 [conn116] command admin.$cmd command: { replSetHeartbeat: "SERVER10268", v: 4, pv: 1, checkEmpty: false, from: "hingo-sputnik:27003" } ntoreturn:1 keyUpdates:0 reslen:162 0ms
|
...
|
May 26 12:38:57 hingo-sputnik mongod.27003[22035]: Tue May 26 12:38:57.949 [rsMgr] replSet dev we are freshest of up nodes, nok:1 nTies:1
|
...
|
May 26 12:38:58 hingo-sputnik mongod.27003[22035]: Tue May 26 12:38:58.771 [rsMgr] replSet dev we are freshest of up nodes, nok:1 nTies:1
|
May 26 12:38:58 hingo-sputnik mongod.27003[22035]: Tue May 26 12:38:58.771 [rsMgr] replSet not voting yea for 2 voted for 0 5 secs ago
|
May 26 12:38:58 hingo-sputnik mongod.27003[22035]: Tue May 26 12:38:58.771 [rsMgr] replSet not trying to elect self as responded yea to someone else recently
|
...
|
yadayada (lots of it)
|
...
|
May 26 12:39:19 hingo-sputnik mongod.27001[22264]: Tue May 26 12:39:19.020 [rsMgr] replSet PRIMARY
|
|