|
Looking at cases of successful heartbeats from other nodes, it seems like they are also scheduling heartbeats for earlier times than expected. Nodes d20022 receives a hb from d20020 at 2020-06-25T09:24:10.111, yet it schedules the next heartbeat request for 2020-06-25T09:24:10.311.
[js_test:replsettest_control_12_nodes] 2020-06-25T09:24:10.111+0000 d20022| {"t":{"$date":"2020-06-25T09:24:10.110+00:00"},"s":"D2", "c":"REPL_HB", "id":4615620, "ctx":"ReplCoord-3","msg":"Received response to heartbeat","attr":{"requestId":28,"target":"ip-10-122-18-31:20020","response":{"ok":1.0,"electionTime":{"$date":{"$numberLong":"6842213799693385730"}},"config":{"_id":"replsettest_control_12_nodes","version":4,"term":1,"members":[{"_id":0,"host":"ip-10-122-18-31:20020","arbiterOnly":false,"buildIndexes":true,"hidden":false,"priority":1.0,"tags":{},"slaveDelay":0,"votes":1},{"_id":1,"host":"ip-10-122-18-31:20021","arbiterOnly":false,"buildIndexes":true,"hidden":false,"priority":1.0,"tags":{},"slaveDelay":0,"votes":1},{"_id":2,"host":"ip-10-122-18-31:20022","arbiterOnly":false,"buildIndexes":true,"hidden":false,"priority":1.0,"tags":{},"slaveDelay":0,"votes":1},{"_id":3,"host":"ip-10-122-18-31:20023","arbiterOnly":false,"buildIndexes":true,"hidden":false,"priority":1.0,"tags":{},"slaveDelay":0,"votes":1}],"protocolVersion":1,"writeConcernMajorityJournalDefault":true,"settings":{"chainingAllowed":true,"heartbeatIntervalMillis":2000,"heartbeatTimeoutSecs":10,"electionTimeoutMillis":10000,"catchUpTimeoutMillis":-1,"catchUpTakeoverDelayMillis":30000,"getLastErrorModes":{},"getLastErrorDefaults":{"w":1,"wtimeout":0},"replicaSetId":{"$oid":"5ef46d33558ff97d78e28cef"}}},"state":1,"v":4,"configTerm":1,"set":"replsettest_control_12_nodes","term":1,"primaryId":0,"durableOpTime":{"ts":{"$timestamp":{"t":1593077049,"i":1}},"t":1},"durableWallTime":{"$date":"2020-06-25T09:24:09.798Z"},"opTime":{"ts":{"$timestamp":{"t":1593077049,"i":1}},"t":1},"wallTime":{"$date":"2020-06-25T09:24:09.798Z"},"$replData":{"term":1,"lastOpCommitted":{"ts":{"$timestamp":{"t":1593077048,"i":1}},"t":1},"lastCommittedWall":{"$date":"2020-06-25T09:24:08.465Z"},"lastOpVisible":{"ts":{"$timestamp":{"t":1593077048,"i":1}},"t":1},"configVersion":4,"configTerm":1,"replicaSetId":{"$oid":"5ef46d33558ff97d78e28cef"},"syncSourceIndex":-1,"isPrimary":true},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1593077049,"i":1}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"operationTime":{"$timestamp":{"t":1593077049,"i":1}}}}}
|
[js_test:replsettest_control_12_nodes] 2020-06-25T09:24:10.111+0000 d20022| {"t":{"$date":"2020-06-25T09:24:10.111+00:00"},"s":"D2", "c":"REPL_HB", "id":4615618, "ctx":"ReplCoord-3","msg":"Scheduling heartbeat","attr":{"target":"ip-10-122-18-31:20020","when":{"$date":"2020-06-25T09:24:10.311Z"}}}
|
Here is the logic for scheduling the next hb. I'm not sure why it's calculating the interval to be 200ms, will continue taking a look.
|
|
The node cancelled its heartbeat at 2020-06-25T09:25:10.248
|
[js_test:replsettest_control_12_nodes] 2020-06-25T09:25:10.248+0000 d20031| {"t":{"$date":"2020-06-25T09:25:10.236+00:00"},"s":"D2", "c":"REPL_HB", "id":24096, "ctx":"conn4","msg":"Processing heartbeat request","attr":{"from":"ip-10-122-18-31:20020","cmdObj":{"replSetHeartbeat":"replsettest_control_12_nodes","configVersion":12,"configTerm":1,"hbv":1,"from":"ip-10-122-18-31:20020","fromId":0,"term":1,"primary Id":0,"$replData":1,"$clusterTime":{"clusterTime":{"$timestamp":{"t":1593077080,"i":1}},"signature":{"hash":{"$binary":{"base64":"LG7nPk4sox4OJi6DakIbWSqezOw=","subType":"0"}},"keyId":6842213799693385732}}," $db":"admin"}}}
|
[js_test:replsettest_control_12_nodes] 2020-06-25T09:25:10.248+0000 d20031| {"t":{"$date":"2020-06-25T09:25:10.237+00:00"},"s":"I", "c":"REPL", "id":2903000, "ctx":"conn4","msg":"Restarting heartbeats after learning of a new primary","attr":{"myPrimaryId":"none","senderAndPrimaryId":0,"senderTerm":1}}
|
[js_test:replsettest_control_12_nodes] 2020-06-25T09:25:10.248+0000 d20031| {"t":{"$date":"2020-06-25T09:25:10.237+00:00"},"s":"D2", "c":"REPL_HB", "id":4615630, "ctx":"conn4","msg":"Cancelling all heartbeats"}
|
[js_test:replsettest_control_12_nodes] 2020-06-25T09:25:10.249+0000 d20031| {"t":{"$date":"2020-06-25T09:25:10.240+00:00"},"s":"D2", "c":"REPL_HB", "id":4615618, "ctx":"conn4","msg":"Scheduling heartbeat"," attr":{"target":"ip-10-122-18-31:20020","when":{"$date":"2020-06-25T09:25:10.240Z"}}}
|
[js_test:replsettest_control_12_nodes] 2020-06-25T09:25:10.249+0000 d20031| {"t":{"$date":"2020-06-25T09:25:10.240+00:00"},"s":"D2", "c":"REPL_HB", "id":4615618, "ctx":"conn4","msg":"Scheduling heartbeat"," attr":{"target":"ip-10-122-18-31:20021","when":{"$date":"2020-06-25T09:25:10.240Z"}}}
|
[js_test:replsettest_control_12_nodes] 2020-06-25T09:25:10.249+0000 d20031| {"t":{"$date":"2020-06-25T09:25:10.241+00:00"},"s":"D2", "c":"REPL_HB", "id":4615618, "ctx":"conn4","msg":"Scheduling heartbeat"," attr":{"target":"ip-10-122-18-31:20022","when":{"$date":"2020-06-25T09:25:10.240Z"}}}
|
[js_test:replsettest_control_12_nodes] 2020-06-25T09:25:10.249+0000 d20031| {"t":{"$date":"2020-06-25T09:25:10.241+00:00"},"s":"D2", "c":"REPL_HB", "id":4615618, "ctx":"conn4","msg":"Scheduling heartbeat"," attr":{"target":"ip-10-122-18-31:20023","when":{"$date":"2020-06-25T09:25:10.240Z"}}}
|
[js_test:replsettest_control_12_nodes] 2020-06-25T09:25:10.249+0000 d20031| {"t":{"$date":"2020-06-25T09:25:10.242+00:00"},"s":"D2", "c":"REPL_HB", "id":4615618, "ctx":"conn4","msg":"Scheduling heartbeat"," attr":{"target":"ip-10-122-18-31:20024","when":{"$date":"2020-06-25T09:25:10.240Z"}}}
|
[js_test:replsettest_control_12_nodes] 2020-06-25T09:25:10.249+0000 d20031| {"t":{"$date":"2020-06-25T09:25:10.242+00:00"},"s":"D2", "c":"REPL_HB", "id":4615618, "ctx":"conn4","msg":"Scheduling heartbeat"," attr":{"target":"ip-10-122-18-31:20025","when":{"$date":"2020-06-25T09:25:10.240Z"}}}
|
[js_test:replsettest_control_12_nodes] 2020-06-25T09:25:10.249+0000 d20031| {"t":{"$date":"2020-06-25T09:25:10.242+00:00"},"s":"D2", "c":"REPL_HB", "id":4615618, "ctx":"conn4","msg":"Scheduling heartbeat"," attr":{"target":"ip-10-122-18-31:20026","when":{"$date":"2020-06-25T09:25:10.240Z"}}}
|
[js_test:replsettest_control_12_nodes] 2020-06-25T09:25:10.249+0000 d20031| {"t":{"$date":"2020-06-25T09:25:10.242+00:00"},"s":"D2", "c":"REPL_HB", "id":4615618, "ctx":"conn4","msg":"Scheduling heartbeat"," attr":{"target":"ip-10-122-18-31:20027","when":{"$date":"2020-06-25T09:25:10.240Z"}}}
|
[js_test:replsettest_control_12_nodes] 2020-06-25T09:25:10.249+0000 d20031| {"t":{"$date":"2020-06-25T09:25:10.243+00:00"},"s":"D2", "c":"REPL_HB", "id":4615618, "ctx":"conn4","msg":"Scheduling heartbeat"," attr":{"target":"ip-10-122-18-31:20028","when":{"$date":"2020-06-25T09:25:10.240Z"}}}
|
[js_test:replsettest_control_12_nodes] 2020-06-25T09:25:10.249+0000 d20031| {"t":{"$date":"2020-06-25T09:25:10.243+00:00"},"s":"D2", "c":"REPL_HB", "id":4615618, "ctx":"conn4","msg":"Scheduling heartbeat"," attr":{"target":"ip-10-122-18-31:20029","when":{"$date":"2020-06-25T09:25:10.240Z"}}}
|
[js_test:replsettest_control_12_nodes] 2020-06-25T09:25:10.249+0000 d20031| {"t":{"$date":"2020-06-25T09:25:10.243+00:00"},"s":"D2", "c":"REPL_HB", "id":4615618, "ctx":"conn4","msg":"Scheduling heartbeat"," attr":{"target":"ip-10-122-18-31:20030","when":{"$date":"2020-06-25T09:25:10.240Z"}}}
|
[js_test:replsettest_control_12_nodes] 2020-06-25T09:25:10.249+0000 d20031| {"t":{"$date":"2020-06-25T09:25:10.244+00:00"},"s":"D2", "c":"REPL_HB", "id":24097, "ctx":"conn4","msg":"Generated heartbeat response","attr":{"from":"ip-10-122-18-31:20020","response":{"ok":1.0,"state":5,"v":12,"configTerm":1,"set":"replsettest_control_12_nodes","term":1,"durableOpTime":{"ts":{"$timestamp":{"t":0,"i":0}},"t":-1},"durableWallTime":{"$date":"1970-01-01T00:00:00.000Z"},"opTime":{"ts":{"$timestamp":{"t":0,"i":0}},"t":-1},"wallTime":{"$date":"1970-01-01T00:00:00.000Z"}}}}
|
[js_test:replsettest_control_12_nodes] 2020-06-25T09:25:10.250+0000 d20031| {"t":{"$date":"2020-06-25T09:25:10.244+00:00"},"s":"D2", "c":"REPL_HB", "id":4615619, "ctx":"ReplCoord-17","msg":"Received response to heartbeat, but the heartbeat was cancelled","attr":{"requestId":1810,"target":"ip-10-122-18-31:20020"}}
|
[js_test:replsettest_control_12_nodes] 2020-06-25T09:25:10.250+0000 d20031| {"t":{"$date":"2020-06-25T09:25:10.244+00:00"},"s":"D2", "c":"REPL_HB", "id":4615619, "ctx":"ReplCoord-4","msg":"Received response to heartbeat, but the heartbeat was cancelled","attr":{"requestId":1811,"target":"ip-10-122-18-31:20021"}}
|
[js_test:replsettest_control_12_nodes] 2020-06-25T09:25:10.251+0000 d20031| {"t":{"$date":"2020-06-25T09:25:10.244+00:00"},"s":"D2", "c":"REPL_HB", "id":4615619, "ctx":"ReplCoord-6","msg":"Received response to heartbeat, but the heartbeat was cancelled","attr":{"requestId":1812,"target":"ip-10-122-18-31:20022"}}
|
[js_test:replsettest_control_12_nodes] 2020-06-25T09:25:10.251+0000 d20031| {"t":{"$date":"2020-06-25T09:25:10.245+00:00"},"s":"D2", "c":"REPL_HB", "id":4615619, "ctx":"ReplCoord-15","msg":"Received response to heartbeat, but the heartbeat was cancelled","attr":{"requestId":1813,"target":"ip-10-122-18-31:20024"}}
|
[js_test:replsettest_control_12_nodes] 2020-06-25T09:25:10.251+0000 d20031| {"t":{"$date":"2020-06-25T09:25:10.245+00:00"},"s":"D2", "c":"REPL_HB", "id":4615619, "ctx":"ReplCoord-22","msg":"Received response to heartbeat, but the heartbeat was cancelled","attr":{"requestId":1814,"target":"ip-10-122-18-31:20025"}}
|
[js_test:replsettest_control_12_nodes] 2020-06-25T09:25:10.251+0000 d20031| {"t":{"$date":"2020-06-25T09:25:10.246+00:00"},"s":"D2", "c":"REPL_HB", "id":4615619, "ctx":"ReplCoord-21","msg":"Received response to heartbeat, but the heartbeat was cancelled","attr":{"requestId":1815,"target":"ip-10-122-18-31:20026"}}
|
[js_test:replsettest_control_12_nodes] 2020-06-25T09:25:10.251+0000 d20031| {"t":{"$date":"2020-06-25T09:25:10.246+00:00"},"s":"D2", "c":"REPL_HB", "id":4615619, "ctx":"ReplCoord-9","msg":"Received response to heartbeat, but the heartbeat was cancelled","attr":{"requestId":1816,"target":"ip-10-122-18-31:20027"}}
|
[js_test:replsettest_control_12_nodes] 2020-06-25T09:25:10.251+0000 d20031| {"t":{"$date":"2020-06-25T09:25:10.246+00:00"},"s":"D2", "c":"REPL_HB", "id":4615619, "ctx":"ReplCoord-10","msg":"Received response to heartbeat, but the heartbeat was cancelled","attr":{"requestId":1817,"target":"ip-10-122-18-31:20028"}}
|
[js_test:replsettest_control_12_nodes] 2020-06-25T09:25:10.256+0000 d20031| {"t":{"$date":"2020-06-25T09:25:10.247+00:00"},"s":"D2", "c":"REPL_HB", "id":4615619, "ctx":"ReplCoord-13","msg":"Received response to heartbeat, but the heartbeat was cancelled","attr":{"requestId":1818,"target":"ip-10-122-18-31:20029"}}
|
[js_test:replsettest_control_12_nodes] 2020-06-25T09:25:10.256+0000 d20031| {"t":{"$date":"2020-06-25T09:25:10.247+00:00"},"s":"D2", "c":"REPL_HB", "id":4615619, "ctx":"ReplCoord-7","msg":"Received response to heartbeat, but the heartbeat was cancelled","attr":{"requestId":1819,"target":"ip-10-122-18-31:20030"}}
|
[js_test:replsettest_control_12_nodes] 2020-06-25T09:25:10.256+0000 d20031| {"t":{"$date":"2020-06-25T09:25:10.247+00:00"},"s":"D2", "c":"REPL_HB", "id":4615619, "ctx":"ReplCoord-12","msg":"Received response to heartbeat, but the heartbeat was cancelled","attr":{"requestId":1820,"target":"ip-10-122-18-31:20023"}}
|
The next occurrence of cancelling heartbeat requests happens at 2020-06-25T09:25:10.472:
[js_test:replsettest_control_12_nodes] 2020-06-25T09:25:10.472+0000 d20031| {"t":{"$date":"2020-06-25T09:25:10.459+00:00"},"s":"D2", "c":"REPL_HB", "id":24095, "ctx":"conn4","msg":"Received heartbeat request","attr":{"from":"ip-10 -122-18-31:20020","cmdObj":{"replSetHeartbeat":"replsettest_control_12_nodes","configVersion":12,"configTerm":1,"hbv":1,"from":"ip-10-122-18-31:20020","fromId":0,"term":1,"primaryId":0,"$replData":1,"$clusterTime":{"clusterTime":{"$timestamp":{"t":1593077080,"i":1}},"signature":{"hash":{"$binary":{"base64":"LG7nPk4sox4OJi6DakIbWSqezOw=","subType":"0"}},"keyId":6842213799693385732}},"$db":"admin"}}}
|
[js_test:replsettest_control_12_nodes] 2020-06-25T09:25:10.472+0000 d20031| {"t":{"$date":"2020-06-25T09:25:10.460+00:00"},"s":"I", "c":"REPL", "id":2903000, "ctx":"conn4","msg":"Restarting heartbeats after learning of a new primary","attr":{"myPrimaryId":"none","senderAndPrimaryId":0,"senderTerm":1}}
|
And the next occurrence after that is at 2020-06-25T09:25:10.674:
[js_test:replsettest_control_12_nodes] 2020-06-25T09:25:10.674+0000 d20031| {"t":{"$date":"2020-06-25T09:25:10.670+00:00"},"s":"D2", "c":"REPL_HB", "id":24095, "ctx":"conn4","msg":"Received heartbeat request","attr":{"from":"ip-10-122-18-31:20020","cmdObj":{"replSetHeartbeat":"replsettest_control_12_nodes","configVersion":12,"configTerm":1,"hbv":1,"from":"ip-10-122-18-31:20020","fromId":0,"term":1,"primaryId":0,"$replData":1,"$clusterTime":{"clusterTime":{"$timestamp":{"t":1593077080,"i":1}},"signature":{"hash":{"$binary":{"base64":"LG7nPk4sox4OJi6DakIbWSqezOw=","subType":"0"}},"keyId":6842213799693385732}},"$db":"admin"}}}
|
[js_test:replsettest_control_12_nodes] 2020-06-25T09:25:10.674+0000 d20031| {"t":{"$date":"2020-06-25T09:25:10.670+00:00"},"s":"I", "c":"REPL", "id":2903000, "ctx":"conn4","msg":"Restarting heartbeats after learning of a new primary","attr":{"myPrimaryId":"none","senderAndPrimaryId":0,"senderTerm":1}}
|
9003 [js_test:replsettest_control_12_nodes] 2020-06-25T09:25:10.674+0000 d20031| {"t":{"$date":"2020-06-25T09:25:10.671+00:00"},"s":"D2", "c":"REPL_HB", "id":4615630, "ctx":"conn4","msg":"Cancelling all heartbeats"}
|
|