I have spent this week to make Mongo 4.4 PSA replica created by a freelancer to work. I gave up, deleted the complete mongod from all three servers and install from scratch following the Mongo doc. The only change was to create new db and import data before the replica initialization.
It failed for the first time (connection timeout) and I revisited my firewalls rules. Then it connected immediately and mongo shell refreshed on all nodes:
rs_bud:SECONDARY> show collections
rs_bud:PRIMARY> use bud
But when I perfom any operation on secondaries, they fail with NotPrimaryNoSecondaryOk error.
rs_bud:SECONDARY> use bud
rs_bud:SECONDARY> show collections
uncaught exception: Error: listCollections failed: {
"topologyVersion" : {
"processId" : ObjectId("612bbc4940995c508859973a"),
"counter" : NumberLong(4)
},
"operationTime" : Timestamp(1630258863, 1),
"ok" : 0,
"errmsg" : "not master and slaveOk=false",
"code" : 13435,
"codeName" : "NotPrimaryNoSecondaryOk",
"$clusterTime" : {
"clusterTime" : Timestamp(1630258863, 1),
"signature" : {
"hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),
"keyId" : NumberLong(0)
}
}
} :
I cannot find any logs useful to me:
{"t":{"$date":"2021-08-29T19:41:41.550+02:00"},"s":"I", "c":"NETWORK", "id":23729, "ctx":"ReplicaSetMonitor-TaskExecutor","msg":"ServerPingMonitor is now monitoring host","attr":{"host":"10.0.0.4:27017","replicaSet":"rs_bud"}}
{"t":{"$date":"2021-08-29T19:41:41.550+02:00"},"s":"I", "c":"NETWORK", "id":4333213, "ctx":"ReplicaSetMonitor-TaskExecutor","msg":"RSM Topology Change","attr":{"replicaSet":"rs_bud","newTopologyDescription":"{ id: \"ad6bc985-50f4-4b01-9310-1457f8861f1f\", topologyType: \"ReplicaSetWithPrimary\", servers: { 10.0.0.2:27017: { address: \"10.0.0.2:27017\", topologyVersion: { processId: ObjectId('612bbc4940995c508859973a'), counter: 4 }, roundTripTime: 504, lastWriteDate: new Date(1630258890000), opTime: { ts: Timestamp(1630258890, 1), t: 1 }, type: \"RSSecondary\", minWireVersion: 9, maxWireVersion: 9, me: \"10.0.0.2:27017\", setName: \"rs_bud\", setVersion: 1, primary: \"10.0.0.4:27017\", lastUpdateTime: new Date(1630258901549), logicalSessionTimeoutMinutes: 30, hosts: { 0: \"10.0.0.2:27017\", 1: \"10.0.0.4:27017\", 2: \"10.0.0.5:27017\" }, arbiters: {}, passives: {} }, 10.0.0.4:27017: { address: \"10.0.0.4:27017\", topologyVersion: { processId: ObjectId('612bba160d5e82841e5c8fc2'), counter: 6 }, roundTripTime: 1153, lastWriteDate: new Date(1630258890000), opTime: { ts: Timestamp(1630258890, 1), t: 1 }, type: \"RSPrimary\", minWireVersion: 9, maxWireVersion: 9, me: \"10.0.0.4:27017\", setName: \"rs_bud\", setVersion: 1, electionId: ObjectId('7fffffff0000000000000001'), primary: \"10.0.0.4:27017\", lastUpdateTime: new Date(1630258901550), logicalSessionTimeoutMinutes: 30, hosts: { 0: \"10.0.0.2:27017\", 1: \"10.0.0.4:27017\", 2: \"10.0.0.5:27017\" }, arbiters: {}, passives: {} }, 10.0.0.5:27017: { address: \"10.0.0.5:27017\", type: \"Unknown\", minWireVersion: 0, maxWireVersion: 0, lastUpdateTime: new Date(-9223372036854775808), hosts: {}, arbiters: {}, passives: {} } }, logicalSessionTimeoutMinutes: 30, setName: \"rs_bud\", compatible: true, maxSetVersion: 1, maxElectionId: ObjectId('7fffffff0000000000000001') }","previousTopologyDescription":"{ id: \"ad6bc985-50f4-4b01-9310-1457f8861f1f\", topologyType: \"ReplicaSetNoPrimary\", servers: { 10.0.0.2:27017: { address: \"10.0.0.2:27017\", topologyVersion: { processId: ObjectId('612bbc4940995c508859973a'), counter: 4 }, roundTripTime: 504, lastWriteDate: new Date(1630258890000), opTime: { ts: Timestamp(1630258890, 1), t: 1 }, type: \"RSSecondary\", minWireVersion: 9, maxWireVersion: 9, me: \"10.0.0.2:27017\", setName: \"rs_bud\", setVersion: 1, primary: \"10.0.0.4:27017\", lastUpdateTime: new Date(1630258901549), logicalSessionTimeoutMinutes: 30, hosts: { 0: \"10.0.0.2:27017\", 1: \"10.0.0.4:27017\", 2: \"10.0.0.5:27017\" }, arbiters: {}, passives: {} }, 10.0.0.4:27017: { address: \"10.0.0.4:27017\", type: \"Unknown\", minWireVersion: 0, maxWireVersion: 0, lastUpdateTime: new Date(-9223372036854775808), hosts: {}, arbiters: {}, passives: {} }, 10.0.0.5:27017: { address: \"10.0.0.5:27017\", type: \"Unknown\", minWireVersion: 0, maxWireVersion: 0, lastUpdateTime: new Date(-9223372036854775808), hosts: {}, arbiters: {}, passives: {} } }, logicalSessionTimeoutMinutes: 30, setName: \"rs_bud\", compatible: true }"}}
{"t":{"$date":"2021-08-29T19:41:41.550+02:00"},"s":"I", "c":"NETWORK", "id":23729, "ctx":"ReplicaSetMonitor-TaskExecutor","msg":"ServerPingMonitor is now monitoring host","attr":{"host":"10.0.0.5:27017","replicaSet":"rs_bud"}}
{"t":{"$date":"2021-08-29T19:41:41.551+02:00"},"s":"I", "c":"NETWORK", "id":4333213, "ctx":"ReplicaSetMonitor-TaskExecutor","msg":"RSM Topology Change","attr":{"replicaSet":"rs_bud","newTopologyDescription":"{ id: \"ad6bc985-50f4-4b01-9310-1457f8861f1f\", topologyType: \"ReplicaSetWithPrimary\", servers: { 10.0.0.2:27017: { address: \"10.0.0.2:27017\", topologyVersion: { processId: ObjectId('612bbc4940995c508859973a'), counter: 4 }, roundTripTime: 504, lastWriteDate: new Date(1630258890000), opTime: { ts: Timestamp(1630258890, 1), t: 1 }, type: \"RSSecondary\", minWireVersion: 9, maxWireVersion: 9, me: \"10.0.0.2:27017\", setName: \"rs_bud\", setVersion: 1, primary: \"10.0.0.4:27017\", lastUpdateTime: new Date(1630258901549), logicalSessionTimeoutMinutes: 30, hosts: { 0: \"10.0.0.2:27017\", 1: \"10.0.0.4:27017\", 2: \"10.0.0.5:27017\" }, arbiters: {}, passives: {} }, 10.0.0.4:27017: { address: \"10.0.0.4:27017\", topologyVersion: { processId: ObjectId('612bba160d5e82841e5c8fc2'), counter: 6 }, roundTripTime: 1153, lastWriteDate: new Date(1630258890000), opTime: { ts: Timestamp(1630258890, 1), t: 1 }, type: \"RSPrimary\", minWireVersion: 9, maxWireVersion: 9, me: \"10.0.0.4:27017\", setName: \"rs_bud\", setVersion: 1, electionId: ObjectId('7fffffff0000000000000001'), primary: \"10.0.0.4:27017\", lastUpdateTime: new Date(1630258901550), logicalSessionTimeoutMinutes: 30, hosts: { 0: \"10.0.0.2:27017\", 1: \"10.0.0.4:27017\", 2: \"10.0.0.5:27017\" }, arbiters: {}, passives: {} }, 10.0.0.5:27017: { address: \"10.0.0.5:27017\", topologyVersion: { processId: ObjectId('612bbc3d5c7d3123b83eedf8'), counter: 4 }, roundTripTime: 1468, lastWriteDate: new Date(1630258890000), opTime: { ts: Timestamp(1630258890, 1), t: 1 }, type: \"RSSecondary\", minWireVersion: 9, maxWireVersion: 9, me: \"10.0.0.5:27017\", setName: \"rs_bud\", setVersion: 1, primary: \"10.0.0.4:27017\", lastUpdateTime: new Date(1630258901550), logicalSessionTimeoutMinutes: 30, hosts: { 0: \"10.0.0.2:27017\", 1: \"10.0.0.4:27017\", 2: \"10.0.0.5:27017\" }, arbiters: {}, passives: {} } }, logicalSessionTimeoutMinutes: 30, setName: \"rs_bud\", compatible: true, maxSetVersion: 1, maxElectionId: ObjectId('7fffffff0000000000000001') }","previousTopologyDescription":"{ id: \"ad6bc985-50f4-4b01-9310-1457f8861f1f\", topologyType: \"ReplicaSetWithPrimary\", servers: { 10.0.0.2:27017: { address: \"10.0.0.2:27017\", topologyVersion: { processId: ObjectId('612bbc4940995c508859973a'), counter: 4 }, roundTripTime: 504, lastWriteDate: new Date(1630258890000), opTime: { ts: Timestamp(1630258890, 1), t: 1 }, type: \"RSSecondary\", minWireVersion: 9, maxWireVersion: 9, me: \"10.0.0.2:27017\", setName: \"rs_bud\", setVersion: 1, primary: \"10.0.0.4:27017\", lastUpdateTime: new Date(1630258901549), logicalSessionTimeoutMinutes: 30, hosts: { 0: \"10.0.0.2:27017\", 1: \"10.0.0.4:27017\", 2: \"10.0.0.5:27017\" }, arbiters: {}, passives: {} }, 10.0.0.4:27017: { address: \"10.0.0.4:27017\", topologyVersion: { processId: ObjectId('612bba160d5e82841e5c8fc2'), counter: 6 }, roundTripTime: 1153, lastWriteDate: new Date(1630258890000), opTime: { ts: Timestamp(1630258890, 1), t: 1 }, type: \"RSPrimary\", minWireVersion: 9, maxWireVersion: 9, me: \"10.0.0.4:27017\", setName: \"rs_bud\", setVersion: 1, electionId: ObjectId('7fffffff0000000000000001'), primary: \"10.0.0.4:27017\", lastUpdateTime: new Date(1630258901550), logicalSessionTimeoutMinutes: 30, hosts: { 0: \"10.0.0.2:27017\", 1: \"10.0.0.4:27017\", 2: \"10.0.0.5:27017\" }, arbiters: {}, passives: {} }, 10.0.0.5:27017: { address: \"10.0.0.5:27017\", type: \"Unknown\", minWireVersion: 0, maxWireVersion: 0, lastUpdateTime: new Date(-9223372036854775808), hosts: {}, arbiters: {}, passives: {} } }, logicalSessionTimeoutMinutes: 30, setName: \"rs_bud\", compatible: true, maxSetVersion: 1, maxElectionId: ObjectId('7fffffff0000000000000001') }"}}
{"t":{"$date":"2021-08-29T19:41:41.552+02:00"},"s":"I", "c":"NETWORK", "id":20113, "ctx":"LogicalSessionCacheReap","msg":"Successfully connected to host","attr":{"connString":"10.0.0.4:27017","numOpenConns":1,"socketTimeoutSecs":0.0}}
{"t":{"$date":"2021-08-29T19:41:41.552+02:00"},"s":"I", "c":"NETWORK", "id":20113, "ctx":"LogicalSessionCacheRefresh","msg":"Successfully connected to host","attr":{"connString":"10.0.0.4:27017","numOpenConns":2,"socketTimeoutSecs":0.0}}
{"t":{"$date":"2021-08-29T19:41:54.623+02:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"WTCheckpointThread","msg":"WiredTiger message","attr":{"message":"[1630258914:623411][1811:0x7f64db1aa700], WT_SESSION.checkpoint: [WT_VERB_CHECKPOINT_PROGRESS] saving checkpoint snapshot min: 1607, snapshot max: 1607 snapshot count: 0, oldest timestamp: (1630258896, 1) , meta checkpoint timestamp: (1630258901, 1) base write gen: 325"}}
and this looks OK too:
rs_bud:SECONDARY> rs.printReplicationInfo()
configured oplog size: 1483.0916013717651MB
log length start to end: 981secs (0.27hrs)
oplog first event time: Sun Aug 29 2021 19:39:42 GMT+0200 (CEST)
oplog last event time: Sun Aug 29 2021 19:56:03 GMT+0200 (CEST)
now: Sun Aug 29 2021 19:56:04 GMT+0200 (CEST)
and
rs_bud:SECONDARY> rs.status()
{
"set" : "rs_bud",
"date" : ISODate("2021-08-29T17:56:58.119Z"),
"myState" : 2,
"term" : NumberLong(1),
"syncSourceHost" : "10.0.0.4:27017",
"syncSourceId" : 0,
"heartbeatIntervalMillis" : NumberLong(2000),
"majorityVoteCount" : 2,
"writeMajorityCount" : 2,
"votingMembersCount" : 3,
"writableVotingMembersCount" : 3,
"optimes" : {
"lastCommittedOpTime" : {
"ts" : Timestamp(1630259813, 1),
"t" : NumberLong(1)
},
"lastCommittedWallTime" : ISODate("2021-08-29T17:56:53.431Z"),
"readConcernMajorityOpTime" : {
"ts" : Timestamp(1630259813, 1),
"t" : NumberLong(1)
},
"readConcernMajorityWallTime" : ISODate("2021-08-29T17:56:53.431Z"),
"appliedOpTime" : {
"ts" : Timestamp(1630259813, 1),
"t" : NumberLong(1)
},
"durableOpTime" : {
"ts" : Timestamp(1630259813, 1),
"t" : NumberLong(1)
},
"lastAppliedWallTime" : ISODate("2021-08-29T17:56:53.431Z"),
"lastDurableWallTime" : ISODate("2021-08-29T17:56:53.431Z")
},
"lastStableRecoveryTimestamp" : Timestamp(1630259801, 2),
"electionParticipantMetrics" : {
"votedForCandidate" : true,
"electionTerm" : NumberLong(1),
"lastVoteDate" : ISODate("2021-08-29T17:39:53.358Z"),
"electionCandidateMemberId" : 0,
"voteReason" : "",
"lastAppliedOpTimeAtElection" : {
"ts" : Timestamp(1630258782, 1),
"t" : NumberLong(-1)
},
"maxAppliedOpTimeInSet" : {
"ts" : Timestamp(1630258782, 1),
"t" : NumberLong(-1)
},
"priorityAtElection" : 1,
"newTermStartDate" : ISODate("2021-08-29T17:39:53.386Z"),
"newTermAppliedDate" : ISODate("2021-08-29T17:39:54.485Z")
},
"members" : [
{
"_id" : 0,
"name" : "10.0.0.4:27017",
"health" : 1,
"state" : 1,
"stateStr" : "PRIMARY",
"uptime" : 1035,
"optime" : {
"ts" : Timestamp(1630259813, 1),
"t" : NumberLong(1)
},
"optimeDurable" : {
"ts" : Timestamp(1630259813, 1),
"t" : NumberLong(1)
},
"optimeDate" : ISODate("2021-08-29T17:56:53Z"),
"optimeDurableDate" : ISODate("2021-08-29T17:56:53Z"),
"lastHeartbeat" : ISODate("2021-08-29T17:56:57.415Z"),
"lastHeartbeatRecv" : ISODate("2021-08-29T17:56:57.901Z"),
"pingMs" : NumberLong(0),
"lastHeartbeatMessage" : "",
"syncSourceHost" : "",
"syncSourceId" : -1,
"infoMessage" : "",
"electionTime" : Timestamp(1630258793, 1),
"electionDate" : ISODate("2021-08-29T17:39:53Z"),
"configVersion" : 1,
"configTerm" : 1
},
{
"_id" : 1,
"name" : "10.0.0.5:27017",
"health" : 1,
"state" : 2,
"stateStr" : "SECONDARY",
"uptime" : 1035,
"optime" : {
"ts" : Timestamp(1630259813, 1),
"t" : NumberLong(1)
},
"optimeDurable" : {
"ts" : Timestamp(1630259813, 1),
"t" : NumberLong(1)
},
"optimeDate" : ISODate("2021-08-29T17:56:53Z"),
"optimeDurableDate" : ISODate("2021-08-29T17:56:53Z"),
"lastHeartbeat" : ISODate("2021-08-29T17:56:57.417Z"),
"lastHeartbeatRecv" : ISODate("2021-08-29T17:56:57.431Z"),
"pingMs" : NumberLong(0),
"lastHeartbeatMessage" : "",
"syncSourceHost" : "10.0.0.4:27017",
"syncSourceId" : 0,
"infoMessage" : "",
"configVersion" : 1,
"configTerm" : 1
},
{
"_id" : 2,
"name" : "10.0.0.2:27017",
"health" : 1,
"state" : 2,
"stateStr" : "SECONDARY",
"uptime" : 3617,
"optime" : {
"ts" : Timestamp(1630259813, 1),
"t" : NumberLong(1)
},
"optimeDate" : ISODate("2021-08-29T17:56:53Z"),
"syncSourceHost" : "10.0.0.4:27017",
"syncSourceId" : 0,
"infoMessage" : "",
"configVersion" : 1,
"configTerm" : 1,
"self" : true,
"lastHeartbeatMessage" : ""
}
],
"ok" : 1,
"$clusterTime" : {
"clusterTime" : Timestamp(1630259813, 1),
"signature" : {
"hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),
"keyId" : NumberLong(0)
}
},
"operationTime" : Timestamp(1630259813, 1)
}
What is wrong and how to fix it?