-
Type:
Improvement
-
Resolution: Unresolved
-
Priority:
Major - P3
-
None
-
Affects Version/s: None
-
Component/s: None
-
Labels:None
-
Replication
While debugging a server serverless BF, I found that the election log doesn't show the complete response, which is arguably the most important information in the log message.
"response":"{ term: 3, voteGranted: false, reason: \"candidate's data is staler than mine. candidate's last applied OpTime: { ts: Timestamp(1654601256, 2), t: 2 }, my last applied OpTime: { ts: Timestamp...\" }"
The entire log line is following.
[j7:rs12:n0] | 2022-06-07T11:27:37.063+00:00 I ELECTION 23980 [conn28] "Responding to vote request","attr":{"request":"{ replSetRequestVotes: 1, setName: \"rs12\", dryRun: false, term: 3, candidateIndex: 2, configVersion: 1, configTerm: 1, lastAppliedOpTime: { ts: Timestamp(1654601256, 2), t: 2 } }","response":"{ term: 3, voteGranted: false, reason: \"candidate's data is staler than mine. candidate's last applied OpTime: { ts: Timestamp(1654601256, 2), t: 2 }, my last applied OpTime: { ts: Timestamp...\" }","replicaSetStatus":"Current replSetGetStatus output: { set: \"rs12\", date: new Date(1654601257063), myState: 2, term: 3, syncSourceHost: \"localhost:21754\", syncSourceId: -1, heartbeatIntervalMillis: 2000, majorityVoteCount: 2, writeMajorityCount: 2, votingMembersCount: 3, writableVotingMembersCount: 3, optimes: { lastCommittedOpTime: { ts: Timestamp(1654601256, 3), t: 2 }, lastCommittedWallTime: new Date(1654601256744), appliedOpTime: { ts: Timestamp(1654601256, 3), t: 2 }, durableOpTime: { ts: Timestamp(1654601256, 3), t: 2 }, lastAppliedWallTime: new Date(1654601256744), lastDurableWallTime: new Date(1654601256744) }, members: [ { _id: 0, name: \"localhost:21750\", health: 1.0, state: 2, stateStr: \"SECONDARY\", uptime: 0, optime: { ts: Timestamp(1654601256, 3), t: 2 }, optimeDate: new Date(1654601256000), lastAppliedWallTime: new Date(1654601256744), lastDurableWallTime: new Date(1654601256744), syncSourceHost: \"localhost:21754\", syncSourceId: -1, infoMessage: \"\", configVersion: 1, configTerm: 1, self: true, lastHeartbeatMessage: \"\" }, { _id: 1, name: \"localhost:21751\", health: 1.0, state: 2, stateStr: \"SECONDARY\", uptime: 0, optime: { ts: Timestamp(1654601256, 2), t: 2 }, optimeDurable: { ts: Timestamp(1654601256, 2), t: 2 }, optimeDate: new Date(1654601256000), optimeDurableDate: new Date(1654601256000), lastAppliedWallTime: new Date(1654601256682), lastDurableWallTime: new Date(1654601256682), lastHeartbeat: new Date(1654601256813), lastHeartbeatRecv: new Date(1654601256802), pingMs: 2, lastHeartbeatMessage: \"\", syncSourceHost: \"\", syncSourceId: -1, infoMessage: \"\", configVersion: 1, configTerm: 1 }, { _id: 2, name: \"localhost:21752\", health: 1.0, state: 2, stateStr: \"SECONDARY\", uptime: 0, optime: { ts: Timestamp(1654601256, 2), t: 2 }, optimeDurable: { ts: Timestamp(1654601256, 2), t: 2 }, optimeDate: new Date(1654601256000), optimeDurableDate: new Date(1654601256000), lastAppliedWallTime: new Date(1654601256682), lastDurableWallTime: new Date(1654601256682), lastHeartbeat: new Date(1654601256819), lastHeartbeatRecv: new Date(1654601256810), pingMs: 1, lastHeartbeatMessage: \"\", syncSourceHost: \"\", syncSourceId: -1, infoMessage: \"\", configVersion: 1, configTerm: 1 } ] }"}