|
I'm surprised that in remove_newly_added_field_after_finishing_initial_sync.js the lastVote gets stored before the stepdown stops killing operations. In primary_casts_vote_on_stepdown.js, the step down and processing the vote request happen on the same thread, but in remove_newly_added_field_after_finishing_initial_sync.js they happen on different threads. I wonder what's triggering the stepdown from a different thread:
[js_test:primary_casts_vote_on_stepdown] 2020-04-17T04:59:09.210+0000 d20020| 2020-04-17T04:59:09.209+00:00 I ELECTION 23980 [conn4] "Responding to vote request","attr":{"request":"{ replSetRequestVotes: 1, setName: \"primary_casts_vote_on_stepdown\", dryRun: true, term: 1, candidateIndex: 1, configVersion: 2, configTerm: 1, lastAppliedOpTime: { ts: Timestamp(1587099548, 10), t: 1 } }","response":"{ term: 1, voteGranted: true, reason: \"\" }","replicaSetStatus":"Current replSetGetStatus output: { set: \"primary_casts_vote_on_stepdown\", date: new Date(1587099549209), myState: 1, term: 1, syncSourceHost: \"\", syncSourceId: -1, heartbeatIntervalMillis: 2000, majorityVoteCount: 2, writeMajorityCount: 2, votingMembersCount: 2, writableVotingMembersCount: 2, optimes: { lastCommittedOpTime: { ts: Timestamp(1587099548, 10), t: 1 }, lastCommittedWallTime: new Date(1587099548899), appliedOpTime: { ts: Timestamp(1587099548, 10), t: 1 }, durableOpTime: { ts: Timestamp(1587099548, 8), t: 1 }, lastAppliedWallTime: new Date(1587099548899), lastDurableWallTime: new Date(1587099548648) }, members: [ { _id: 0, name: \"ip-10-122-19-61:20020\", health: 1.0, state: 1, stateStr: \"PRIMARY\", uptime: 0, optime: { ts: Timestamp(1587099548, 10), t: 1 }, optimeDate: new Date(1587099548000), syncSourceHost: \"\", syncSourceId: -1, infoMessage: \"Could not find member to sync from\", electionTime: Timestamp(1587099548, 2), electionDate: new Date(1587099548000), configVersion: 2, configTerm: 1, self: true, lastHeartbeatMessage: \"\" }, { _id: 1, name: \"ip-10-122-19-61:20021\", health: 1.0, state: 2, stateStr: \"SECONDARY\", uptime: 0, optime: { ts: Timestamp(1587099548, 10), t: 1 }, optimeDurable: { ts: Timestamp(0, 0), t: -1 }, optimeDate: new Date(1587099548000), optimeDurableDate: new Date(0), lastHeartbeat: new Date(1587099549082), lastHeartbeatRecv: new Date(1587099549199), pingMs: 0, lastHeartbeatMessage: \"\", syncSourceHost: \"ip-10-122-19-61:20020\", syncSourceId: 0, infoMessage: \"\", configVersion: 2, configTerm: 1 } ] }"}
|
...
|
[js_test:primary_casts_vote_on_stepdown] 2020-04-17T04:59:09.210+0000 d20020| 2020-04-17T04:59:09.210+00:00 I REPL 21402 [conn4] "Stepping down from primary, because a new term has begun","attr":{"term":2}
|
[js_test:primary_casts_vote_on_stepdown] 2020-04-17T04:59:09.211+0000 d20020| 2020-04-17T04:59:09.210+00:00 I REPL 21343 [RstlKillOpThread] "Starting to kill user operations"
|
[js_test:primary_casts_vote_on_stepdown] 2020-04-17T04:59:09.211+0000 d20020| 2020-04-17T04:59:09.210+00:00 I REPL 21344 [RstlKillOpThread] "Stopped killing user operations"
|
[js_test:primary_casts_vote_on_stepdown] 2020-04-17T04:59:09.211+0000 d20020| 2020-04-17T04:59:09.210+00:00 I REPL 21340 [RstlKillOpThread] "State transition ops metrics","attr":{"metrics":{"lastStateTransition":"stepDown","userOpsKilled":0,"userOpsRunning":3}}
|
[js_test:primary_casts_vote_on_stepdown] 2020-04-17T04:59:09.211+0000 d20020| 2020-04-17T04:59:09.211+00:00 I REPL 21358 [ReplCoord-0] "Replica set state transition","attr":{"newState":"SECONDARY","oldState":"PRIMARY"}
|
[js_test:primary_casts_vote_on_stepdown] 2020-04-17T04:59:09.211+0000 d20020| 2020-04-17T04:59:09.211+00:00 D4 ELECTION 4615651 [ReplCoord-0] "Scheduling election timeout callback","attr":{"when":{"$date":"2020-04-17T04:59:20.615Z"}}
|
[js_test:primary_casts_vote_on_stepdown] 2020-04-17T04:59:09.211+0000 d20020| 2020-04-17T04:59:09.211+00:00 I ELECTION 23980 [conn4] "Responding to vote request","attr":{"request":"{ replSetRequestVotes: 1, setName: \"primary_casts_vote_on_stepdown\", dryRun: false, term: 2, candidateIndex: 1, configVersion: 2, configTerm: 1, lastAppliedOpTime: { ts: Timestamp(1587099548, 10), t: 1 } }","response":"{ term: 2, voteGranted: true, reason: \"\" }","replicaSetStatus":"Current replSetGetStatus output: { set: \"primary_casts_vote_on_stepdown\", date: new Date(1587099549211), myState: 2, term: 2, syncSourceHost: \"\", syncSourceId: -1, heartbeatIntervalMillis: 2000, majorityVoteCount: 2, writeMajorityCount: 2, votingMembersCount: 2, writableVotingMembersCount: 2, optimes: { lastCommittedOpTime: { ts: Timestamp(1587099548, 10), t: 1 }, lastCommittedWallTime: new Date(1587099548899), appliedOpTime: { ts: Timestamp(1587099548, 10), t: 1 }, durableOpTime: { ts: Timestamp(1587099548, 10), t: 1 }, lastAppliedWallTime: new Date(1587099548899), lastDurableWallTime: new Date(1587099548899) }, members: [ { _id: 0, name: \"ip-10-122-19-61:20020\", health: 1.0, state: 2, stateStr: \"SECONDARY\", uptime: 0, optime: { ts: Timestamp(1587099548, 10), t: 1 }, optimeDate: new Date(1587099548000), syncSourceHost: \"\", syncSourceId: -1, infoMessage: \"Could not find member to sync from\", configVersion: 2, configTerm: 1, self: true, lastHeartbeatMessage: \"\" }, { _id: 1, name: \"ip-10-122-19-61:20021\", health: 1.0, state: 2, stateStr: \"SECONDARY\", uptime: 0, optime: { ts: Timestamp(1587099548, 10), t: 1 }, optimeDurable: { ts: Timestamp(0, 0), t: -1 }, optimeDate: new Date(1587099548000), optimeDurableDate: new Date(0), lastHeartbeat: new Date(1587099549082), lastHeartbeatRecv: new Date(1587099549199), pingMs: 0, lastHeartbeatMessage: \"\", syncSourceHost: \"ip-10-122-19-61:20020\", syncSourceId: 0, infoMessage: \"\", configVersion: 2, configTerm: 1 } ] }"}
|
vs.
[js_test:remove_newly_added_field_after_finishing_initial_sync] 2020-04-15T01:33:38.370+0000 d20030| 2020-04-15T01:33:38.369+00:00 I ELECTION 23980 [conn230] "Responding to vote request","attr":{"request":"{ replSetRequestVotes: 1, setName: \"remove_newly_added_field_after_finishing_initial_sync\", dryRun: true, term: 5, candidateIndex: 1, configVersion: 7, configTerm: 5, lastAppliedOpTime: { ts: Timestamp(1586914418, 1), t: 5 } }","response":"{ term: 5, voteGranted: true, reason: \"\" }","replicaSetStatus":"Current replSetGetStatus output: { set: \"remove_newly_added_field_after_finishing_initial_sync\", date: new Date(1586914418369), myState: 1, term: 5, syncSourceHost: \"\", syncSourceId: -1, heartbeatIntervalMillis: 2000, majorityVoteCount: 3, writeMajorityCount: 3, votingMembersCount: 4, writableVotingMembersCount: 4, optimes: { lastCommittedOpTime: { ts: Timestamp(1586914418, 1), t: 5 }, lastCommittedWallTime: new Date(1586914418364), appliedOpTime: { ts: Timestamp(1586914418, 1), t: 5 }, durableOpTime: { ts: Timestamp(1586914409, 3), t: 5 }, lastAppliedWallTime: new Date(1586914418364), lastDurableWallTime: new Date(1586914409638) }, members: [ { _id: 0, name: \"ip-10-122-66-210:20020\", health: 1.0, state: 1, stateStr: \"PRIMARY\", uptime: 0, optime: { ts: Timestamp(1586914418, 1), t: 5 }, optimeDate: new Date(1586914418000), syncSourceHost: \"\", syncSourceId: -1, infoMessage: \"syncing from primary: ip-10-122-66-210:20021\", electionTime: Timestamp(1586914409, 1), electionDate: new Date(1586914409000), configVersion: 7, configTerm: 5, self: true, lastHeartbeatMessage: \"\" }, { _id: 1, name: \"ip-10-122-66-210:20021\", health: 1.0, state: 2, stateStr: \"SECONDARY\", uptime: 28, optime: { ts: Timestamp(1586914409, 3), t: 5 }, optimeDurable: { ts: Timestamp(1586914409, 3), t: 5 }, optimeDate: new Date(1586914409000), optimeDurableDate: new Date(1586914409000), lastHeartbeat: new Date(1586914417739), lastHeartbeatRecv: new Date(1586914417971), pingMs: 0, lastHeartbeatMessage: \"\", syncSourceHost: \"ip-10-122-66-210:20020\", syncSourceId: 0, infoMessage: \"\", configVersion: 7, configTerm: 5 }, { _id: 2, name: \"ip-10-122-66-210:20022\", health: 1.0, state: 2, stateStr: \"SECONDARY\", uptime: 6, optime: { ts: Timestamp(1586914401, 1), t: 3 }, optimeDurable: { ts: Timestamp(1586914401, 1), t: 3 }, optimeDate: new Date(1586914401000), optimeDurableDate: new Date(1586914401000), lastHeartbeat: new Date(1586914417812), lastHeartbeatRecv: new Date(1586914418012), pingMs: 0, lastHeartbeatMessage: \"\", syncSourceHost: \"\", syncSourceId: -1, infoMessage: \"\", configVersion: 7, configTerm: 5 }, { _id: 3, name: \"ip-10-122-66-210:20033\", health: 1.0, state: 2, stateStr: \"SECONDARY\", uptime: 6, optime: { ts: Timestamp(1586914401, 1), t: 3 }, optimeDurable: { ts: Timestamp(1586914401, 1), t: 3 }, optimeDate: new Date(1586914401000), optimeDurableDate: new Date(1586914401000), lastHeartbeat: new Date(1586914417738), lastHeartbeatRecv: new Date(1586914417896), pingMs: 0, lastHeartbeatMessage: \"\", syncSourceHost: \"\", syncSourceId: -1, infoMessage: \"\", configVersion: 7, configTerm: 5 } ] }"}
|
...
|
[js_test:remove_newly_added_field_after_finishing_initial_sync] 2020-04-15T01:33:38.371+0000 d20030| 2020-04-15T01:33:38.371+00:00 I REPL 21402 [conn22] "Stepping down from primary, because a new term has begun","attr":{"term":6}
|
[js_test:remove_newly_added_field_after_finishing_initial_sync] 2020-04-15T01:33:38.371+0000 d20030| 2020-04-15T01:33:38.371+00:00 I ELECTION 23980 [conn230] "Responding to vote request","attr":{"request":"{ replSetRequestVotes: 1, setName: \"remove_newly_added_field_after_finishing_initial_sync\", dryRun: false, term: 6, candidateIndex: 1, configVersion: 7, configTerm: 5, lastAppliedOpTime: { ts: Timestamp(1586914418, 1), t: 5 } }","response":"{ term: 5, voteGranted: true, reason: \"\" }","replicaSetStatus":"Current replSetGetStatus output: { set: \"remove_newly_added_field_after_finishing_initial_sync\", date: new Date(1586914418371), myState: 1, term: 5, syncSourceHost: \"\", syncSourceId: -1, heartbeatIntervalMillis: 2000, majorityVoteCount: 3, writeMajorityCount: 3, votingMembersCount: 4, writableVotingMembersCount: 4, optimes: { lastCommittedOpTime: { ts: Timestamp(1586914418, 1), t: 5 }, lastCommittedWallTime: new Date(1586914418364), appliedOpTime: { ts: Timestamp(1586914418, 1), t: 5 }, durableOpTime: { ts: Timestamp(1586914409, 3), t: 5 }, lastAppliedWallTime: new Date(1586914418364), lastDurableWallTime: new Date(1586914409638) }, members: [ { _id: 0, name: \"ip-10-122-66-210:20020\", health: 1.0, state: 1, stateStr: \"PRIMARY\", uptime: 0, optime: { ts: Timestamp(1586914418, 1), t: 5 }, optimeDate: new Date(1586914418000), syncSourceHost: \"\", syncSourceId: -1, infoMessage: \"syncing from primary: ip-10-122-66-210:20021\", electionTime: Timestamp(1586914409, 1), electionDate: new Date(1586914409000), configVersion: 7, configTerm: 5, self: true, lastHeartbeatMessage: \"\" }, { _id: 1, name: \"ip-10-122-66-210:20021\", health: 1.0, state: 2, stateStr: \"SECONDARY\", uptime: 28, optime: { ts: Timestamp(1586914409, 3), t: 5 }, optimeDurable: { ts: Timestamp(1586914409, 3), t: 5 }, optimeDate: new Date(1586914409000), optimeDurableDate: new Date(1586914409000), lastHeartbeat: new Date(1586914417739), lastHeartbeatRecv: new Date(1586914417971), pingMs: 0, lastHeartbeatMessage: \"\", syncSourceHost: \"ip-10-122-66-210:20020\", syncSourceId: 0, infoMessage: \"\", configVersion: 7, configTerm: 5 }, { _id: 2, name: \"ip-10-122-66-210:20022\", health: 1.0, state: 2, stateStr: \"SECONDARY\", uptime: 6, optime: { ts: Timestamp(1586914401, 1), t: 3 }, optimeDurable: { ts: Timestamp(1586914401, 1), t: 3 }, optimeDate: new Date(1586914401000), optimeDurableDate: new Date(1586914401000), lastHeartbeat: new Date(1586914417812), lastHeartbeatRecv: new Date(1586914418012), pingMs: 0, lastHeartbeatMessage: \"\", syncSourceHost: \"\", syncSourceId: -1, infoMessage: \"\", configVersion: 7, configTerm: 5 }, { _id: 3, name: \"ip-10-122-66-210:20033\", health: 1.0, state: 2, stateStr: \"SECONDARY\", uptime: 6, optime: { ts: Timestamp(1586914401, 1), t: 3 }, optimeDurable: { ts: Timestamp(1586914401, 1), t: 3 }, optimeDate: new Date(1586914401000), optimeDurableDate: new Date(1586914401000), lastHeartbeat: new Date(1586914417738), lastHeartbeatRecv: new Date(1586914417896), pingMs: 0, lastHeartbeatMessage: \"\", syncSourceHost: \"\", syncSourceId: -1, infoMessage: \"\", configVersion: 7, configTerm: 5 } ] }"}
|
...
|
[js_test:remove_newly_added_field_after_finishing_initial_sync] 2020-04-15T01:33:38.371+0000 d20030| 2020-04-15T01:33:38.371+00:00 I REPL 21343 [RstlKillOpThread] "Starting to kill user operations"
|
[js_test:remove_newly_added_field_after_finishing_initial_sync] 2020-04-15T01:33:38.371+0000 d20030| 2020-04-15T01:33:38.371+00:00 E REPL 21428 [conn230] "replSetRequestVotes failed to store LastVote document","attr":{"error":{"code":11602,"codeName":"InterruptedDueToReplStateChange","errmsg":"operation was interrupted"}}
|
...
|
[js_test:remove_newly_added_field_after_finishing_initial_sync] 2020-04-15T01:33:38.372+0000 d20030| 2020-04-15T01:33:38.372+00:00 I REPL 21344 [RstlKillOpThread] "Stopped killing user operations"
|
...
|
[js_test:remove_newly_added_field_after_finishing_initial_sync] 2020-04-15T01:33:38.372+0000 d20030| 2020-04-15T01:33:38.372+00:00 I REPL 21340 [RstlKillOpThread] "State transition ops metrics","attr":{"metrics":{"lastStateTransition":"stepDown","userOpsKilled":1,"userOpsRunning":5}}
|
...
|
[js_test:remove_newly_added_field_after_finishing_initial_sync] 2020-04-15T01:33:38.372+0000 d20030| 2020-04-15T01:33:38.372+00:00 I REPL 21358 [ReplCoord-5] "Replica set state transition","attr":{"newState":"SECONDARY","oldState":"PRIMARY"}
|
[js_test:remove_newly_added_field_after_finishing_initial_sync] 2020-04-15T01:33:38.372+0000 d20030| 2020-04-15T01:33:38.372+00:00 D4 ELECTION 4615651 [ReplCoord-5] "Scheduling election timeout callback","attr":{"when":{"$date":"2020-04-16T04:37:44.202Z"}}
|
|