[SERVER-10268] Network socket timeouts with heartbeatTimeoutSecs are different with a mongos vs plain replica set Created: 20/Jul/13  Updated: 06/Nov/17  Resolved: 26/May/15

Status: Closed
Project: Core Server
Component/s: Networking
Affects Version/s: None
Fix Version/s: 3.0.0

Type: Bug Priority: Minor - P4
Reporter: Henrik Ingo (Inactive) Assignee: Matt Dannenberg
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Dell XPS13 laptop, Ubuntu 12.04, MongoDB 2.4.5 (10gen repo)


Attachments: File heartbeatTimeoutSecs-with-mongos.log     File heartbeatTimeoutSecs-without-mongos.log    
Issue Links:
Depends
Related
Backwards Compatibility: Fully Compatible
Participants:

 Description   

We were playing with heartbeatTimeoutSecs with Edouard, and noticed that the behavior in socket timeouts is different when you have a mongos as part of the cluster vs when there is only a plain replica set (only mongod/arbitrator servers).

Consider the following test:

  • MongoD is running on ports 27001, 27002 and 27003 - it's easiest to run them in the foreground in a terminal (no --fork).
  • A MongoS is running on port 27000, connected to 1 config server. (config server isn't shown in attached logs as I didn't use --syslog for it)
  • Symptoms are the same whether i run some operations or if the cluster is completely idle.
  • Attached logs are with -vvvv verbosity

Tip: On a linux system I can use --syslog to get a single log of all processes. Apparently on a mac the syslog will not distinguish between the source of each log entry, so it becomes impossible to know which node wrote what.

The test is simply to stop the PRIMARY with Ctrl-Z and measure failover time until a new PRIMARY is active and writable. In this ticket, we focus on the time until we get network socket timeout, which looks like this in logs:

--> 27001 is PRIMARY. The last log entry from 27001 signifies the time I pressed Ctrl-Z:

Jul 16 17:05:29 hingo-sputnik mongod.27001[14713]: Tue Jul 16 17:05:29.845 [conn107] getmore local.oplog.rs query: { ts: { $gte: Timestamp 1373976850000|1 } } cursorid:6149432603763897 ntoreturn:0 keyUpdates:0 locks(micros) r:383 nreturned:0 reslen:20 5011ms

--> 27003 notices that 27001 is not responding:

Jul 16 17:05:33 hingo-sputnik mongod.27003[13420]: Tue Jul 16 17:05:33.472 [rsHealthPoll] Socket recv() timeout 127.0.1.1:27001

I have called out these occurences in the attached logs, so they are easy to find.

The default behavior is that this timeout is 10 seconds (plus some milliseconds).

Now, we configure heartbeatTimeoutSecs

myrs:PRIMARY> config = rs.config()
{
        "_id" : "myrs",
        "version" : 14,
        "members" : [
                {
                        "_id" : 0,
                        "host" : "hingo-sputnik:27001"
                },
                {
                        "_id" : 1,
                        "host" : "hingo-sputnik:27002"
                },
                {
                        "_id" : 2,
                        "host" : "hingo-sputnik:27003"
                }
        ]
}
myrs:PRIMARY> config["settings"] = { heartbeatTimeoutSecs : 2 }
{ "heartbeatTimeoutSecs" : 2 }
myrs:PRIMARY> config
{
        "_id" : "myrs",
        "version" : 14,
        "members" : [
                {
                        "_id" : 0,
                        "host" : "hingo-sputnik:27001"
                },
                {
                        "_id" : 1,
                        "host" : "hingo-sputnik:27002"
                },
                {
                        "_id" : 2,
                        "host" : "hingo-sputnik:27003"
                }
        ],
        "settings" : {
                "heartbeatTimeoutSecs" : 2
        }
}
myrs:PRIMARY> rs.reconfig(config)
{ "ok" : 1 }
// Just to verify it sticks:
myrs:PRIMARY> rs.config()
{
        "_id" : "myrs",
        "version" : 15,
        "members" : [
                {
                        "_id" : 0,
                        "host" : "hingo-sputnik:27001"
                },
                {
                        "_id" : 1,
                        "host" : "hingo-sputnik:27002"
                },
                {
                        "_id" : 2,
                        "host" : "hingo-sputnik:27003"
                }
        ],
        "settings" : {
                "heartbeatTimeoutSecs" : 2
        }
}
myrs:PRIMARY>

And then we repeat the test.

Actual result

We find that with a cluster that includes one mongos and one config server, the socket timeout becomes shorter, as expected. (3.5 secs in attached log, but still in the right ballpark.) If I shut down the mongos and config server, then the socket timeout remains at 10+ secs regardless of what I set heartbeatTimeoutSecs to be.

Expected result

Expected behavior would be that the socket timeout also becomes shorter when there is no mongos present.

Workarounds

Apparently most of our users are using sharding, so they would see the correct behavior (should they ever try to use heartbeatTimeoutSecs). Also, for someone for whom this timeout is important, it is feasible to simply add a mongos process to the cluster as a workaround. Hence I set priority to minor.

More importantly, as a first step we would just want to understand why mongos has any influence over what is happening.



 Comments   
Comment by Andy Schwerin [ 27/May/15 ]

Thanks for the thorough testing, henrik.ingo@10gen.com .

Comment by Henrik Ingo (Inactive) [ 26/May/15 ]

This has been fixed in 3.0. (And works very nicely!)

Comment by Henrik Ingo (Inactive) [ 26/May/15 ]

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

Comment by Henrik Ingo (Inactive) [ 26/May/15 ]

Reproducing on 2.4.5 on Ubuntu 14.04, with mongos attached to the replica set.
Socket timeout for rsHealthPoll now happens faster, again just like in description.

As above, but in addition:

bin/mongod --configsvr --port 27010 --dbpath /data/config1/
bin/mongos --port 27000 --configdb hingo-sputnik:27010
 
mongos> sh.addShard("SERVER10268/hingo-sputnik:27001,hingo-sputnik:27002,hingo-sputnik:27003")
{ "shardAdded" : "SERVER10268", "ok" : 1 }
mongos> sh.status()
--- Sharding Status --- 
  sharding version: {
	"_id" : 1,
	"version" : 3,
	"minCompatibleVersion" : 3,
	"currentVersion" : 4,
	"clusterId" : ObjectId("55644c36c81c0d354e87da02")
}
  shards:
	{  "_id" : "SERVER10268",  "host" : "SERVER10268/hingo-sputnik:27001,hingo-sputnik:27002,hingo-sputnik:27003" }
  databases:
	{  "_id" : "admin",  "partitioned" : false,  "primary" : "config" }
	{  "_id" : "test",  "partitioned" : false,  "primary" : "SERVER10268" }
 
(Note: it's also important to restart all nodes. I start mongos first, that may be significant?)

27003 is primary, hitting Ctrl-Z

Last log line from 27003

May 26 13:57:19 hingo-sputnik mongod.27003[28963]: Tue May 26 13:57:19.961 [conn5] getmore local.oplog.rs query: { ts: { $gte: Timestamp 14326330
88000|1 } } cursorid:36688667200293 ntoreturn:0 keyUpdates:0 locks(micros) r:200 nreturned:0 reslen:20 5011ms

27001 sees first SocketException 0.36 secs later, and first rsHealthPoll at 59.963 = 2.8 secs later. Still takes until 13:58:28.269 (31 secs) until it really is primary.

May 26 13:57:20 hingo-sputnik mongod.27001[29102]: Tue May 26 13:57:20.321 [conn4] Socket recv() conn closed? 127.0.0.1:36602
May 26 13:57:20 hingo-sputnik mongod.27001[29102]: Tue May 26 13:57:20.321 [conn4] SocketException: remote: 127.0.0.1:36602 error: 9001 socket exception [0] server [127.0.0.1:36602] 
May 26 13:57:20 hingo-sputnik mongod.27001[29102]: Tue May 26 13:57:20.322 [conn4] end connection 127.0.0.1:36602 (3 connections now open)
...
May 26 13:57:59 hingo-sputnik mongod.27002[29026]: Tue May 26 13:57:59.963 [rsHealthPoll] Socket recv() timeout  127.0.1.1:27003
May 26 13:57:59 hingo-sputnik mongod.27002[29026]: Tue May 26 13:57:59.963 [rsHealthPoll] SocketException: remote: 127.0.1.1:27003 error: 9001 socket exception [3] server [127.0.1.1:27003] 
May 26 13:57:59 hingo-sputnik mongod.27002[29026]: Tue May 26 13:57:59.963 [rsHealthPoll] DBClientCursor::init call() failed
May 26 13:57:59 hingo-sputnik mongod.27002[29026]: Tue May 26 13:57:59.963 [rsHealthPoll] User Assertion: 10276:DBClientBase::findN: transport error: hingo-sputnik:27003 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", v: 4, pv: 1, checkEmpty: false, from: "hingo-sputnik:27002" }
May 26 13:57:59 hingo-sputnik mongod.27002[29026]: Tue May 26 13:57:59.964 [rsHealthPoll] replset info hingo-sputnik:27003 heartbeat failed, retrying
May 26 13:57:59 hingo-sputnik mongod.27002[29026]: Tue May 26 13:57:59.964 [rsHealthPoll] trying reconnect to hingo-sputnik:27003
May 26 13:57:59 hingo-sputnik mongod.27002[29026]: Tue May 26 13:57:59.964 BackgroundJob starting: ConnectBG
May 26 13:57:59 hingo-sputnik mongod.27002[29026]: Tue May 26 13:57:59.964 [rsHealthPoll] reconnect hingo-sputnik:27003 ok
...
May 26 13:58:00 hingo-sputnik mongod.27002[29026]: Tue May 26 13:58:00.963 [rsHealthPoll] Socket recv() timeout  127.0.1.1:27003
May 26 13:58:00 hingo-sputnik mongod.27002[29026]: Tue May 26 13:58:00.963 [rsHealthPoll] SocketException: remote: 127.0.1.1:27003 error: 9001 socket exception [3] server [127.0.1.1:27003] 
May 26 13:58:00 hingo-sputnik mongod.27002[29026]: Tue May 26 13:58:00.963 [rsHealthPoll] DBClientCursor::init call() failed
May 26 13:58:00 hingo-sputnik mongod.27002[29026]: Tue May 26 13:58:00.963 [rsHealthPoll] User Assertion: 10276:DBClientBase::findN: transport error: hingo-sputnik:27003 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", v: 4, pv: 1, checkEmpty: false, from: "hingo-sputnik:27002" }
May 26 13:58:00 hingo-sputnik mongod.27002[29026]: Tue May 26 13:58:00.964 [rsHealthPoll] replSet info hingo-sputnik:27003 is down (or slow to respond): 
May 26 13:58:00 hingo-sputnik mongod.27002[29026]: Tue May 26 13:58:00.964 [rsHealthPoll] replSet member hingo-sputnik:27003 is now in state DOWN
May 26 13:58:00 hingo-sputnik mongod.27002[29026]: Tue May 26 13:58:00.964 BackgroundJob starting: MultiCommandJob
...
May 26 13:58:01 hingo-sputnik mongod.27001[29102]: Tue May 26 13:58:01.379 [rsHealthPoll] Socket recv() timeout  127.0.1.1:27003
May 26 13:58:01 hingo-sputnik mongod.27001[29102]: Tue May 26 13:58:01.379 [rsHealthPoll] SocketException: remote: 127.0.1.1:27003 error: 9001 socket exception [3] server [127.0.1.1:27003] 
May 26 13:58:01 hingo-sputnik mongod.27001[29102]: Tue May 26 13:58:01.379 [rsHealthPoll] DBClientCursor::init call() failed
May 26 13:58:01 hingo-sputnik mongod.27001[29102]: Tue May 26 13:58:01.379 [rsHealthPoll] User Assertion: 10276:DBClientBase::findN: transport error: hingo-sputnik:27003 ns: admin.$cmd query: { replSetHeartbeat: "SERVER10268", v: 4, pv: 1, checkEmpty: false, from: "hingo-sputnik:27001" }
May 26 13:58:01 hingo-sputnik mongod.27001[29102]: Tue May 26 13:58:01.379 [rsHealthPoll] replSet info hingo-sputnik:27003 is down (or slow to respond): 
May 26 13:58:01 hingo-sputnik mongod.27001[29102]: Tue May 26 13:58:01.379 [rsHealthPoll] replSet member hingo-sputnik:27003 is now in state DOWN
May 26 13:58:01 hingo-sputnik mongod.27001[29102]: Tue May 26 13:58:01.380 BackgroundJob starting: MultiCommandJob
...
May 26 13:58:01 hingo-sputnik mongod.27001[29102]: Tue May 26 13:58:01.380 [rsMgr] replSet dev we are freshest of up nodes, nok:1 nTies:1
May 26 13:58:01 hingo-sputnik mongod.27001[29102]: Tue May 26 13:58:01.380 [rsMgr] replSet info electSelf 0
May 26 13:58:01 hingo-sputnik mongod.27001[29102]: Tue May 26 13:58:01.381 BackgroundJob starting: MultiCommandJob
May 26 13:58:01 hingo-sputnik mongod.27002[29026]: Tue May 26 13:58:01.381 [conn8] runQuery called admin.$cmd { replSetElect: 1, set: "SERVER10268", who: "hingo-sputnik:27001", whoid: 0, cfgver: 4, round: ObjectId('556451b92550334649ed14b9') }
May 26 13:58:01 hingo-sputnik mongod.27002[29026]: Tue May 26 13:58:01.381 [conn8] run command admin.$cmd { replSetElect: 1, set: "SERVER10268", who: "hingo-sputnik:27001", whoid: 0, cfgver: 4, round: ObjectId('556451b92550334649ed14b9') }
May 26 13:58:01 hingo-sputnik mongod.27002[29026]: Tue May 26 13:58:01.381 [conn8] command: { replSetElect: 1, set: "SERVER10268", who: "hingo-sputnik:27001", whoid: 0, cfgver: 4, round: ObjectId('556451b92550334649ed14b9') }
May 26 13:58:01 hingo-sputnik mongod.27002[29026]: Tue May 26 13:58:01.381 [conn8] replSet received elect msg { replSetElect: 1, set: "SERVER10268", who: "hingo-sputnik:27001", whoid: 0, cfgver: 4, round: ObjectId('556451b92550334649ed14b9') }
May 26 13:58:01 hingo-sputnik mongod.27002[29026]: Tue May 26 13:58:01.381 [conn8] replSet attempting to relinquish
May 26 13:58:01 hingo-sputnik mongod.27002[29026]: Tue May 26 13:58:01.381 [conn8] replSet info voting yea for hingo-sputnik:27001 (0)
May 26 13:58:01 hingo-sputnik mongod.27002[29026]: Tue May 26 13:58:01.381 [conn8] command admin.$cmd command: { replSetElect: 1, set: "SERVER10268", who: "hingo-sputnik:27001", whoid: 0, cfgver: 4, round: ObjectId('556451b92550334649ed14b9') } ntoreturn:1 keyUpdates:0 locks(micros) W:46 reslen:66 0ms
May 26 13:58:01 hingo-sputnik mongod.27001[29102]: Tue May 26 13:58:01.381 [rsMgr] replSet election succeeded, assuming primary role
May 26 13:58:01 hingo-sputnik mongod.27001[29102]: Tue May 26 13:58:01.382 [rsMgr] replSet assuming primary
May 26 13:58:01 hingo-sputnik mongod.27001[29102]: Tue May 26 13:58:01.382 [rsMgr] replSet waiting for replication to finish before becoming primary
...
May 26 13:58:05 hingo-sputnik mongod.27002[29026]: Tue May 26 13:58:05.983 [rsMgr] replSet dev we are freshest of up nodes, nok:1 nTies:1
May 26 13:58:06 hingo-sputnik mongod.27002[29026]: Tue May 26 13:58:06.297 [journal] _groupCommit 
May 26 13:58:06 hingo-sputnik mongod.27002[29026]: Tue May 26 13:58:06.297 [journal] _groupCommit upgrade
May 26 13:58:06 hingo-sputnik mongod.27002[29026]: Tue May 26 13:58:06.297 [journal] journal REMAPPRIVATEVIEW
May 26 13:58:06 hingo-sputnik mongod.27002[29026]: Tue May 26 13:58:06.297 [journal] journal REMAPPRIVATEVIEW done startedAt: 0 n:2 0ms
May 26 13:58:06 hingo-sputnik mongod.27002[29026]: Tue May 26 13:58:06.297 [journal] groupCommit end
May 26 13:58:06 hingo-sputnik mongod.27002[29026]: Tue May 26 13:58:06.384 BackgroundJob starting: MultiCommandJob
May 26 13:58:06 hingo-sputnik mongod.27001[29102]: Tue May 26 13:58:06.384 [conn10] runQuery called admin.$cmd { replSetFresh: 1, set: "SERVER10268", opTime: new Date(6153132725646655489), who: "hingo-sputnik:27002", cfgver: 4, id: 1 }
May 26 13:58:06 hingo-sputnik mongod.27001[29102]: Tue May 26 13:58:06.384 [conn10] run command admin.$cmd { replSetFresh: 1, set: "SERVER10268", opTime: new Date(6153132725646655489), who: "hingo-sputnik:27002", cfgver: 4, id: 1 }
May 26 13:58:06 hingo-sputnik mongod.27001[29102]: Tue May 26 13:58:06.384 [conn10] command: { replSetFresh: 1, set: "SERVER10268", opTime: new Date(6153132725646655489), who: "hingo-sputnik:27002", cfgver: 4, id: 1 }
May 26 13:58:06 hingo-sputnik mongod.27001[29102]: Tue May 26 13:58:06.384 [conn10] command admin.$cmd command: { replSetFresh: 1, set: "SERVER10268", opTime: new Date(6153132725646655489), who: "hingo-sputnik:27002", cfgver: 4, id: 1 } ntoreturn:1 keyUpdates:0  reslen:70 0ms
May 26 13:58:06 hingo-sputnik mongod.27002[29026]: Tue May 26 13:58:06.384 [rsMgr] replSet dev we are freshest of up nodes, nok:1 nTies:1
May 26 13:58:06 hingo-sputnik mongod.27002[29026]: Tue May 26 13:58:06.384 [rsMgr] replSet not voting yea for 1 voted for 0 5 secs ago
May 26 13:58:06 hingo-sputnik mongod.27002[29026]: Tue May 26 13:58:06.384 [rsMgr] replSet not trying to elect self as responded yea to someone else recently
...
May 26 13:58:28 hingo-sputnik mongod.27001[29102]: Tue May 26 13:58:28.269 [rsMgr] replSet PRIMARY

Comment by Henrik Ingo (Inactive) [ 26/May/15 ]

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

Generated at Thu Feb 08 03:22:43 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.