2

I have a production replica set that went down for 3-4 minutes, apparently because the Primary could not connect to the Secondaries. I'm having a hard time understanding why a Secondary didn't take over until the connection was reestablished.

Here's the replica set structure and log:

PRIMARY: m4.mydomain.com (104.167.32.55) - Priority 10
SECONDARY: m2.mydomain.com (162.221.2.98) - Priority 5
SECONDARY: m1.mydomain.com (40.113.11.54) - Priority 1 

2019-04-11T05:09:30.998Z I ASIO     [NetworkInterfaceASIO-Replication-0] Ending connection to host m2.mydomain.com:40000 due to bad connection status; 0 connections to that host remain open
2019-04-11T05:09:30.998Z I REPL     [ReplicationExecutor] Error in heartbeat request to m2.mydomain.com:40000; ExceededTimeLimit: Operation timed out, request was RemoteCommand 761815 -- target:m2.mydomain.com:40000 db:admin expDate:2019-04-11T01:09:30.997-0400 cmd:{ replSetHeartbeat: "mydomain2", configVersion: 438342, from: "m4.mydomain.com:40000", fromId: 6, term: 631 }
2019-04-11T05:09:32.999Z I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to m2.mydomain.com:40000
2019-04-11T05:09:33.754Z I REPL     [ReplicationExecutor] stepping down from primary, because a new term has begun: 632
2019-04-11T05:09:33.754Z I REPL     [ReplicationExecutor] stepping down from primary, because a new term has begun: 632
2019-04-11T05:09:33.754Z I REPL     [replExecDBWorker-1] transition to SECONDARY
2019-04-11T05:09:33.754Z I NETWORK  [replExecDBWorker-1] legacy transport layer closing all connections
2019-04-11T05:09:33.754Z I NETWORK  [replExecDBWorker-1] Skip closing connection for connection # 15154
2019-04-11T05:09:33.754Z I NETWORK  [replExecDBWorker-1] Skip closing connection for connection # 15139
2019-04-11T05:09:33.754Z I NETWORK  [replExecDBWorker-1] Skip closing connection for connection # 14937
2019-04-11T05:09:33.754Z I NETWORK  [replExecDBWorker-1] Skip closing connection for connection # 8757
2019-04-11T05:09:33.754Z I NETWORK  [replExecDBWorker-1] Skip closing connection for connection # 5602
2019-04-11T05:09:33.755Z I -        [conn15140] end connection 104.167.32.55:53474 (22 connections now open)
2019-04-11T05:09:33.755Z I -        [conn15141] end connection 104.167.32.55:53476 (22 connections now open)
2019-04-11T05:09:33.755Z I -        [conn8126] end connection 104.167.32.55:49777 (22 connections now open)
2019-04-11T05:09:34.167Z I NETWORK  [thread1] connection accepted from 104.167.32.55:53707 #15155 (8 connections now open)
2019-04-11T05:09:34.235Z I ACCESS   [conn15155] Successfully authenticated as principal admin on mydomain
2019-04-11T05:09:39.785Z I NETWORK  [thread1] connection accepted from 104.167.32.55:53710 #15156 (9 connections now open)
2019-04-11T05:09:39.845Z I ACCESS   [conn15156] Successfully authenticated as principal admin on mydomain
2019-04-11T05:09:40.195Z I NETWORK  [thread1] connection accepted from 104.167.32.55:53711 #15157 (10 connections now open)
2019-04-11T05:09:40.254Z I ACCESS   [conn15157] Successfully authenticated as principal admin on mydomain
2019-04-11T05:09:41.497Z I -        [conn14937] end connection 162.221.2.98:55385 (10 connections now open)
2019-04-11T05:09:43.000Z I REPL     [ReplicationExecutor] Error in heartbeat request to m2.mydomain.com:40000; ExceededTimeLimit: Couldn't get a connection within the time limit
2019-04-11T05:09:46.426Z I REPL     [ReplicationExecutor] Starting an election, since we've seen no PRIMARY in the past 10000ms
2019-04-11T05:09:46.426Z I REPL     [ReplicationExecutor] conducting a dry run election to see if we could be elected. current term: 632
2019-04-11T05:09:46.475Z I REPL     [ReplicationExecutor] VoteRequester(term 632 dry run) received a yes vote from m1.mydomain.com:40000; response message: { term: 632, voteGranted: true, reason: "", ok: 1.0 }
2019-04-11T05:09:46.475Z I REPL     [ReplicationExecutor] dry election run succeeded, running for election in term 633
2019-04-11T05:09:46.476Z I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to m2.mydomain.com:40000
2019-04-11T05:09:46.530Z I REPL     [ReplicationExecutor] VoteRequester(term 633) received a yes vote from m1.mydomain.com:40000; response message: { term: 633, voteGranted: true, reason: "", ok: 1.0 }
2019-04-11T05:09:46.530Z I REPL     [ReplicationExecutor] election succeeded, assuming primary role in term 633
2019-04-11T05:09:46.530Z I REPL     [ReplicationExecutor] transition to PRIMARY
2019-04-11T05:09:46.530Z I REPL     [ReplicationExecutor] Entering primary catch-up mode.
2019-04-11T05:09:46.530Z I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to m2.mydomain.com:40000
2019-04-11T05:09:51.065Z I REPL     [rsBackgroundSync] sync source candidate: m1.mydomain.com:40000
2019-04-11T05:09:51.065Z I ASIO     [NetworkInterfaceASIO-RS-0] Connecting to m1.mydomain.com:40000
2019-04-11T05:09:51.332Z I ASIO     [NetworkInterfaceASIO-RS-0] Successfully connected to m1.mydomain.com:40000, took 267ms (1 connections now open to m1.mydomain.com:40000)
2019-04-11T05:09:51.483Z I REPL     [replication-2] Choosing new sync source because our current sync source, m1.mydomain.com:40000, has an OpTime ({ ts: Timestamp 1554959425000|1, t: 632 }) which is not ahead of ours ({ ts: Timestamp 1554959425000|1, t: 632 }), it does not have a sync source, and it's not the primary (m4.mydomain.com:40000 is)
2019-04-11T05:09:51.483Z I REPL     [replication-2] Canceling oplog query due to OplogQueryMetadata. We have to choose a new sync source. Current source: m1.mydomain.com:40000, OpTime { ts: Timestamp 1554959425000|1, t: 632 }, its sync source index:-1
2019-04-11T05:09:51.483Z W REPL     [rsBackgroundSync] Fetcher stopped querying remote oplog with error: InvalidSyncSource: sync source m1.mydomain.com:40000 (config version: 438342; last applied optime: { ts: Timestamp 1554959425000|1, t: 632 }; sync source index: -1; primary index: 2) is no longer valid
2019-04-11T05:09:51.483Z I REPL     [rsBackgroundSync] could not find member to sync from
2019-04-11T05:09:52.999Z I ASIO     [NetworkInterfaceASIO-Replication-0] Failed to connect to m2.mydomain.com:40000 - NetworkInterfaceExceededTimeLimit: Operation timed out, request was RemoteCommand 761830 -- target:m2.mydomain.com:40000 db:admin cmd:{ isMaster: 1 }
2019-04-11T05:09:52.999Z I ASIO     [NetworkInterfaceASIO-Replication-0] Dropping all pooled connections to m2.mydomain.com:40000 due to failed operation on a connection
2019-04-11T05:09:52.999Z I REPL     [ReplicationExecutor] Error in heartbeat request to m2.mydomain.com:40000; ExceededTimeLimit: Operation timed out, request was RemoteCommand 761830 -- target:m2.mydomain.com:40000 db:admin cmd:{ isMaster: 1 }
2019-04-11T05:09:52.999Z I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to m2.mydomain.com:40000
2019-04-11T05:09:56.530Z I REPL     [ReplicationExecutor] Error in heartbeat request to m2.mydomain.com:40000; ExceededTimeLimit: Couldn't get a connection within the time limit
2019-04-11T05:09:56.531Z I REPL     [ReplicationExecutor] Caught up to the latest optime known via heartbeats after becoming primary.
2019-04-11T05:09:56.531Z I REPL     [ReplicationExecutor] Exited primary catch-up mode.
2019-04-11T05:09:57.487Z I REPL     [rsSync] transition to primary complete; database writes are now permitted
2019-04-11T05:09:57.736Z I NETWORK  [thread1] connection accepted from 104.167.32.55:53719 #15158 (10 connections now open)
2019-04-11T05:09:57.736Z I NETWORK  [thread1] connection accepted from 104.167.32.55:53720 #15159 (11 connections now open)
2019-04-11T05:09:57.845Z I ACCESS   [conn15158] Successfully authenticated as principal admin on mydomain
2019-04-11T05:09:57.847Z I ACCESS   [conn15159] Successfully authenticated as principal admin on mydomain
2019-04-11T05:09:58.995Z I -        [conn15084] end connection 40.113.11.54:59286 (11 connections now open)
2019-04-11T05:10:00.114Z I REPL     [conn15154] stepping down from primary, because a new term has begun: 634
2019-04-11T05:10:00.114Z I REPL     [replExecDBWorker-2] transition to SECONDARY
2019-04-11T05:10:00.114Z I NETWORK  [replExecDBWorker-2] legacy transport layer closing all connections
2019-04-11T05:10:00.114Z I NETWORK  [replExecDBWorker-2] Skip closing connection for connection # 15154
2019-04-11T05:10:00.114Z I NETWORK  [replExecDBWorker-2] Skip closing connection for connection # 15139
2019-04-11T05:10:00.114Z I NETWORK  [replExecDBWorker-2] Skip closing connection for connection # 14938
2019-04-11T05:10:00.114Z I NETWORK  [replExecDBWorker-2] Skip closing connection for connection # 8757
2019-04-11T05:10:00.114Z I NETWORK  [replExecDBWorker-2] Skip closing connection for connection # 5602
2019-04-11T05:10:00.115Z I -        [conn15158] end connection 104.167.32.55:53719 (10 connections now open)
2019-04-11T05:10:00.115Z I -        [conn15159] end connection 104.167.32.55:53720 (10 connections now open)
2019-04-11T05:10:00.115Z I -        [conn15157] end connection 104.167.32.55:53711 (10 connections now open)
2019-04-11T05:10:00.115Z I -        [conn15156] end connection 104.167.32.55:53710 (10 connections now open)
2019-04-11T05:10:00.115Z I -        [conn15155] end connection 104.167.32.55:53707 (10 connections now open)
2019-04-11T05:10:00.198Z I NETWORK  [thread1] connection accepted from 104.167.32.55:53721 #15160 (6 connections now open)
2019-04-11T05:10:00.258Z I ACCESS   [conn15160] Successfully authenticated as principal admin on mydomain
2019-04-11T05:10:00.986Z I NETWORK  [thread1] connection accepted from 104.167.32.55:53722 #15161 (7 connections now open)
2019-04-11T05:10:00.986Z I NETWORK  [conn15161] received client metadata from 104.167.32.55:53722 conn15161: { driver: { name: "mongo-csharp-driver", version: "2.7.2.0" }, os: { type: "Windows", name: "Microsoft Windows 10.0.14393", architecture: "x86_32", version: "10.0.14393" }, platform: ".NET Framework 4.7.3394.0" }
2019-04-11T05:10:01.056Z I ACCESS   [conn15161] Successfully authenticated as principal admin on mydomain
2019-04-11T05:10:02.197Z I NETWORK  [thread1] connection accepted from 104.167.32.55:53723 #15162 (8 connections now open)
2019-04-11T05:10:02.377Z I ACCESS   [conn15162] Successfully authenticated as principal admin on mydomain
2019-04-11T05:10:06.476Z I ASIO     [NetworkInterfaceASIO-Replication-0] Failed to connect to m2.mydomain.com:40000 - NetworkInterfaceExceededTimeLimit: Operation timed out, request was RemoteCommand 761844 -- target:m2.mydomain.com:40000 db:admin cmd:{ isMaster: 1 }
2019-04-11T05:10:06.530Z I ASIO     [NetworkInterfaceASIO-Replication-0] Failed to connect to m2.mydomain.com:40000 - NetworkInterfaceExceededTimeLimit: Operation timed out, request was RemoteCommand 761847 -- target:m2.mydomain.com:40000 db:admin cmd:{ isMaster: 1 }
2019-04-11T05:10:08.531Z I REPL     [ReplicationExecutor] Error in heartbeat request to m2.mydomain.com:40000; ExceededTimeLimit: Couldn't get a connection within the time limit
2019-04-11T05:10:09.796Z I NETWORK  [thread1] connection accepted from 104.167.32.55:53729 #15163 (9 connections now open)
2019-04-11T05:10:09.796Z I NETWORK  [conn15163] received client metadata from 104.167.32.55:53729 conn15163: { driver: { name: "mongo-csharp-driver", version: "2.7.2.0" }, os: { type: "Windows", name: "Microsoft Windows 10.0.14393", architecture: "x86_64", version: "10.0.14393" }, platform: ".NET Framework 4.7.3394.0" }
2019-04-11T05:10:09.855Z I ACCESS   [conn15163] Successfully authenticated as principal admin on mydomain
2019-04-11T05:10:13.000Z I ASIO     [NetworkInterfaceASIO-Replication-0] Failed to connect to m2.mydomain.com:40000 - NetworkInterfaceExceededTimeLimit: Operation timed out, request was RemoteCommand 761867 -- target:m2.mydomain.com:40000 db:admin cmd:{ isMaster: 1 }
2019-04-11T05:10:13.000Z I ASIO     [NetworkInterfaceASIO-Replication-0] Dropping all pooled connections to m2.mydomain.com:40000 due to failed operation on a connection
2019-04-11T05:10:13.532Z I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to m2.mydomain.com:40000
2019-04-11T05:10:21.279Z I REPL     [ReplicationExecutor] Starting an election, since we've seen no PRIMARY in the past 10000ms
2019-04-11T05:10:21.279Z I REPL     [ReplicationExecutor] conducting a dry run election to see if we could be elected. current term: 635
2019-04-11T05:10:21.279Z I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to m2.mydomain.com:40000
2019-04-11T05:10:21.328Z I REPL     [ReplicationExecutor] VoteRequester(term 635 dry run) received a yes vote from m1.mydomain.com:40000; response message: { term: 635, voteGranted: true, reason: "", ok: 1.0 }
2019-04-11T05:10:21.328Z I REPL     [ReplicationExecutor] dry election run succeeded, running for election in term 636
2019-04-11T05:10:21.329Z I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to m2.mydomain.com:40000
2019-04-11T05:10:21.384Z I REPL     [ReplicationExecutor] VoteRequester(term 636) received a yes vote from m1.mydomain.com:40000; response message: { term: 636, voteGranted: true, reason: "", ok: 1.0 }
2019-04-11T05:10:21.384Z I REPL     [ReplicationExecutor] election succeeded, assuming primary role in term 636
2019-04-11T05:10:21.384Z I REPL     [ReplicationExecutor] transition to PRIMARY
2019-04-11T05:10:21.384Z I REPL     [ReplicationExecutor] Entering primary catch-up mode.
2019-04-11T05:10:21.384Z I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to m2.mydomain.com:40000
2019-04-11T05:10:23.532Z I REPL     [ReplicationExecutor] Error in heartbeat request to m2.mydomain.com:40000; ExceededTimeLimit: Couldn't get a connection within the time limit
2019-04-11T05:10:23.532Z I REPL     [ReplicationExecutor] Caught up to the latest optime known via heartbeats after becoming primary.
2019-04-11T05:10:23.532Z I REPL     [ReplicationExecutor] Exited primary catch-up mode.
2019-04-11T05:10:24.514Z I REPL     [rsSync] transition to primary complete; database writes are now permitted
2019-04-11T05:10:24.694Z I NETWORK  [thread1] connection accepted from 104.167.32.55:53739 #15164 (10 connections now open)
2019-04-11T05:10:24.764Z I ACCESS   [conn15164] Successfully authenticated as principal admin on mydomain
2019-04-11T05:10:24.827Z I NETWORK  [thread1] connection accepted from 104.167.32.55:53740 #15165 (11 connections now open)
2019-04-11T05:10:24.894Z I ACCESS   [conn15165] Successfully authenticated as principal admin on mydomain
2019-04-11T05:10:33.532Z I ASIO     [NetworkInterfaceASIO-Replication-0] Failed to connect to m2.mydomain.com:40000 - NetworkInterfaceExceededTimeLimit: Operation timed out, request was RemoteCommand 761882 -- target:m2.mydomain.com:40000 db:admin cmd:{ isMaster: 1 }
2019-04-11T05:10:33.532Z I ASIO     [NetworkInterfaceASIO-Replication-0] Dropping all pooled connections to m2.mydomain.com:40000 due to failed operation on a connection
2019-04-11T05:10:33.532Z I REPL     [ReplicationExecutor] Error in heartbeat request to m2.mydomain.com:40000; ExceededTimeLimit: Operation timed out, request was RemoteCommand 761882 -- target:m2.mydomain.com:40000 db:admin cmd:{ isMaster: 1 }
2019-04-11T05:10:33.532Z I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to m2.mydomain.com:40000
2019-04-11T05:10:35.533Z I REPL     [ReplicationExecutor] Error in heartbeat request to m2.mydomain.com:40000; ExceededTimeLimit: Couldn't get a connection within the time limit
2019-04-11T05:10:41.280Z I ASIO     [NetworkInterfaceASIO-Replication-0] Failed to connect to m2.mydomain.com:40000 - NetworkInterfaceExceededTimeLimit: Operation timed out, request was RemoteCommand 761889 -- target:m2.mydomain.com:40000 db:admin cmd:{ isMaster: 1 }
2019-04-11T05:10:41.329Z I ASIO     [NetworkInterfaceASIO-Replication-0] Failed to connect to m2.mydomain.com:40000 - NetworkInterfaceExceededTimeLimit: Operation timed out, request was RemoteCommand 761893 -- target:m2.mydomain.com:40000 db:admin cmd:{ isMaster: 1 }
2019-04-11T05:10:41.385Z I ASIO     [NetworkInterfaceASIO-Replication-0] Failed to connect to m2.mydomain.com:40000 - NetworkInterfaceExceededTimeLimit: Operation timed out, request was RemoteCommand 761896 -- target:m2.mydomain.com:40000 db:admin cmd:{ isMaster: 1 }
2019-04-11T05:10:43.976Z I REPL     [ReplicationExecutor] stepping down from primary, because a new term has begun: 637
2019-04-11T05:10:43.976Z I REPL     [ReplicationExecutor] stepping down from primary, because a new term has begun: 637
2019-04-11T05:10:43.976Z I REPL     [replExecDBWorker-0] transition to SECONDARY
2019-04-11T05:10:43.976Z I NETWORK  [replExecDBWorker-0] legacy transport layer closing all connections
2019-04-11T05:10:43.977Z I NETWORK  [replExecDBWorker-0] Skip closing connection for connection # 15154
2019-04-11T05:10:43.977Z I NETWORK  [replExecDBWorker-0] Skip closing connection for connection # 15139
2019-04-11T05:10:43.977Z I NETWORK  [replExecDBWorker-0] Skip closing connection for connection # 14938
2019-04-11T05:10:43.977Z I NETWORK  [replExecDBWorker-0] Skip closing connection for connection # 8757
2019-04-11T05:10:43.977Z I NETWORK  [replExecDBWorker-0] Skip closing connection for connection # 5602
2019-04-11T05:10:43.977Z I -        [conn15163] end connection 104.167.32.55:53729 (11 connections now open)
2019-04-11T05:10:43.977Z I -        [conn15164] end connection 104.167.32.55:53739 (11 connections now open)
2019-04-11T05:10:43.977Z I -        [conn15162] end connection 104.167.32.55:53723 (11 connections now open)
2019-04-11T05:10:43.977Z I -        [conn15161] end connection 104.167.32.55:53722 (11 connections now open)
2019-04-11T05:10:43.977Z I -        [conn15160] end connection 104.167.32.55:53721 (11 connections now open)
2019-04-11T05:10:43.978Z I NETWORK  [thread1] connection accepted from 104.167.32.55:53750 #15166 (6 connections now open)
2019-04-11T05:10:44.004Z I -        [conn15165] AssertionException handling request, closing client connection: 172 Operation attempted on a closed transport Session.
2019-04-11T05:10:44.004Z I -        [conn15165] end connection 104.167.32.55:53740 (7 connections now open)
2019-04-11T05:10:44.046Z I ACCESS   [conn15166] Successfully authenticated as principal admin on mydomain
2019-04-11T05:10:47.533Z I REPL     [ReplicationExecutor] Error in heartbeat request to m2.mydomain.com:40000; ExceededTimeLimit: Couldn't get a connection within the time limit
2019-04-11T05:10:48.421Z I NETWORK  [thread1] connection accepted from 104.167.32.55:53752 #15167 (7 connections now open)
2019-04-11T05:10:48.487Z I ACCESS   [conn15167] Successfully authenticated as principal admin on mydomain
2019-04-11T05:10:49.784Z I NETWORK  [thread1] connection accepted from 104.167.32.55:53755 #15168 (8 connections now open)
2019-04-11T05:10:49.856Z I ACCESS   [conn15168] Successfully authenticated as principal admin on mydomain
2019-04-11T05:10:50.196Z I NETWORK  [thread1] connection accepted from 104.167.32.55:53757 #15169 (9 connections now open)
2019-04-11T05:10:50.255Z I ACCESS   [conn15169] Successfully authenticated as principal admin on mydomain
2019-04-11T05:10:53.533Z I ASIO     [NetworkInterfaceASIO-Replication-0] Failed to connect to m2.mydomain.com:40000 - NetworkInterfaceExceededTimeLimit: Operation timed out, request was RemoteCommand 761911 -- target:m2.mydomain.com:40000 db:admin cmd:{ isMaster: 1 }
2019-04-11T05:10:53.533Z I ASIO     [NetworkInterfaceASIO-Replication-0] Dropping all pooled connections to m2.mydomain.com:40000 due to failed operation on a connection
2019-04-11T05:10:53.533Z I REPL     [ReplicationExecutor] Error in heartbeat request to m2.mydomain.com:40000; ExceededTimeLimit: Operation timed out, request was RemoteCommand 761911 -- target:m2.mydomain.com:40000 db:admin cmd:{ isMaster: 1 }
2019-04-11T05:10:53.533Z I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to m2.mydomain.com:40000
2019-04-11T05:10:56.545Z I REPL     [rsBackgroundSync] sync source candidate: m1.mydomain.com:40000
2019-04-11T05:10:56.644Z I ASIO     [NetworkInterfaceASIO-RS-0] Connecting to m1.mydomain.com:40000
2019-04-11T05:10:56.913Z I ASIO     [NetworkInterfaceASIO-RS-0] Successfully connected to m1.mydomain.com:40000, took 269ms (2 connections now open to m1.mydomain.com:40000)
2019-04-11T05:11:02.535Z I REPL     [ReplicationExecutor] Error in heartbeat request to m2.mydomain.com:40000; ExceededTimeLimit: Couldn't get a connection within the time limit
2019-04-11T05:11:13.534Z I ASIO     [NetworkInterfaceASIO-Replication-0] Failed to connect to m2.mydomain.com:40000 - NetworkInterfaceExceededTimeLimit: Operation timed out, request was RemoteCommand 761931 -- target:m2.mydomain.com:40000 db:admin cmd:{ isMaster: 1 }
2019-04-11T05:11:13.534Z I ASIO     [NetworkInterfaceASIO-Replication-0] Dropping all pooled connections to m2.mydomain.com:40000 due to failed operation on a connection
2019-04-11T05:11:13.535Z I REPL     [ReplicationExecutor] Error in heartbeat request to m2.mydomain.com:40000; ExceededTimeLimit: Operation timed out, request was RemoteCommand 761931 -- target:m2.mydomain.com:40000 db:admin cmd:{ isMaster: 1 }
2019-04-11T05:11:13.535Z I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to m2.mydomain.com:40000
2019-04-11T05:11:14.536Z I REPL     [ReplicationExecutor] Error in heartbeat request to m2.mydomain.com:40000; ExceededTimeLimit: Couldn't get a connection within the time limit
2019-04-11T05:11:26.425Z I -        [conn15154] end connection 40.113.11.54:59327 (9 connections now open)
2019-04-11T05:11:26.537Z I REPL     [ReplicationExecutor] Error in heartbeat request to m2.mydomain.com:40000; ExceededTimeLimit: Couldn't get a connection within the time limit
2019-04-11T05:11:33.536Z I ASIO     [NetworkInterfaceASIO-Replication-0] Failed to connect to m2.mydomain.com:40000 - NetworkInterfaceExceededTimeLimit: Operation timed out, request was RemoteCommand 761985 -- target:m2.mydomain.com:40000 db:admin cmd:{ isMaster: 1 }
2019-04-11T05:11:33.536Z I ASIO     [NetworkInterfaceASIO-Replication-0] Dropping all pooled connections to m2.mydomain.com:40000 due to failed operation on a connection
2019-04-11T05:11:33.536Z I REPL     [ReplicationExecutor] Error in heartbeat request to m2.mydomain.com:40000; ExceededTimeLimit: Operation timed out, request was RemoteCommand 761985 -- target:m2.mydomain.com:40000 db:admin cmd:{ isMaster: 1 }
2019-04-11T05:11:33.536Z I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to m2.mydomain.com:40000
2019-04-11T05:11:38.537Z I REPL     [ReplicationExecutor] Error in heartbeat request to m2.mydomain.com:40000; ExceededTimeLimit: Couldn't get a connection within the time limit
2019-04-11T05:11:50.538Z I REPL     [ReplicationExecutor] Error in heartbeat request to m2.mydomain.com:40000; ExceededTimeLimit: Couldn't get a connection within the time limit
2019-04-11T05:11:53.537Z I ASIO     [NetworkInterfaceASIO-Replication-0] Failed to connect to m2.mydomain.com:40000 - NetworkInterfaceExceededTimeLimit: Operation timed out, request was RemoteCommand 762027 -- target:m2.mydomain.com:40000 db:admin cmd:{ isMaster: 1 }
2019-04-11T05:11:53.537Z I ASIO     [NetworkInterfaceASIO-Replication-0] Dropping all pooled connections to m2.mydomain.com:40000 due to failed operation on a connection
2019-04-11T05:11:53.537Z I REPL     [ReplicationExecutor] Error in heartbeat request to m2.mydomain.com:40000; ExceededTimeLimit: Operation timed out, request was RemoteCommand 762027 -- target:m2.mydomain.com:40000 db:admin cmd:{ isMaster: 1 }
2019-04-11T05:11:53.537Z I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to m2.mydomain.com:40000
2019-04-11T05:12:02.538Z I REPL     [ReplicationExecutor] Error in heartbeat request to m2.mydomain.com:40000; ExceededTimeLimit: Couldn't get a connection within the time limit
2019-04-11T05:12:13.538Z I ASIO     [NetworkInterfaceASIO-Replication-0] Failed to connect to m2.mydomain.com:40000 - NetworkInterfaceExceededTimeLimit: Operation timed out, request was RemoteCommand 762071 -- target:m2.mydomain.com:40000 db:admin cmd:{ isMaster: 1 }
2019-04-11T05:12:13.538Z I ASIO     [NetworkInterfaceASIO-Replication-0] Dropping all pooled connections to m2.mydomain.com:40000 due to failed operation on a connection
2019-04-11T05:12:13.538Z I REPL     [ReplicationExecutor] Error in heartbeat request to m2.mydomain.com:40000; ExceededTimeLimit: Operation timed out, request was RemoteCommand 762071 -- target:m2.mydomain.com:40000 db:admin cmd:{ isMaster: 1 }
2019-04-11T05:12:13.538Z I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to m2.mydomain.com:40000
2019-04-11T05:12:13.998Z I ASIO     [NetworkInterfaceASIO-Replication-0] Successfully connected to m2.mydomain.com:40000, took 460ms (1 connections now open to m2.mydomain.com:40000)
2019-04-11T05:12:14.082Z I REPL     [ReplicationExecutor] Member m2.mydomain.com:40000 is now in state PRIMARY
2019-04-11T05:12:14.082Z I REPL     [ReplicationExecutor] Scheduling priority takeover at 2019-04-11T01:12:25.258-0400
2019-04-11T05:12:17.796Z I NETWORK  [thread1] connection accepted from 162.221.2.98:55758 #15170 (9 connections now open)
2019-04-11T05:12:19.133Z I ACCESS   [conn15170]  authenticate db: $external { authenticate: 1, mechanism: "MONGODB-X509", user: "CN=m2.mydomain.com,O=mydomain,ST=ON,C=CA" }
2019-04-11T05:12:19.336Z I NETWORK  [thread1] connection accepted from 99.249.14.184:54885 #15171 (10 connections now open)
2019-04-11T05:12:19.641Z I ACCESS   [conn15171] Successfully authenticated as principal admin on mydomain
2019-04-11T05:12:25.258Z I REPL     [ReplicationExecutor] Canceling priority takeover callback
2019-04-11T05:12:25.258Z I REPL     [ReplicationExecutor] Starting an election for a priority takeover
2019-04-11T05:12:25.258Z I REPL     [ReplicationExecutor] conducting a dry run election to see if we could be elected. current term: 637
2019-04-11T05:12:25.307Z I REPL     [ReplicationExecutor] VoteRequester(term 637 dry run) received a yes vote from m1.mydomain.com:40000; response message: { term: 637, voteGranted: true, reason: "", ok: 1.0 }
2019-04-11T05:12:25.307Z I REPL     [ReplicationExecutor] dry election run succeeded, running for election in term 638
2019-04-11T05:12:25.307Z I ASIO     [NetworkInterfaceASIO-Replication-0] Ending connection to host m2.mydomain.com:40000 due to bad connection status; 0 connections to that host remain open
2019-04-11T05:12:25.308Z I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to m2.mydomain.com:40000
2019-04-11T05:12:25.362Z I REPL     [ReplicationExecutor] VoteRequester(term 638) received a yes vote from m1.mydomain.com:40000; response message: { term: 638, voteGranted: true, reason: "", ok: 1.0 }
2019-04-11T05:12:25.362Z I REPL     [ReplicationExecutor] election succeeded, assuming primary role in term 638
2019-04-11T05:12:25.362Z I REPL     [ReplicationExecutor] transition to PRIMARY
2019-04-11T05:12:25.362Z I REPL     [ReplicationExecutor] Entering primary catch-up mode.
2019-04-11T05:12:25.362Z I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to m2.mydomain.com:40000
2019-04-11T05:12:25.600Z I ASIO     [NetworkInterfaceASIO-Replication-0] Failed to connect to m2.mydomain.com:40000 - HostUnreachable: short read
2019-04-11T05:12:25.600Z I ASIO     [NetworkInterfaceASIO-Replication-0] Dropping all pooled connections to m2.mydomain.com:40000 due to failed operation on a connection
2019-04-11T05:12:25.600Z I REPL     [ReplicationExecutor] Error in heartbeat request to m2.mydomain.com:40000; HostUnreachable: short read
2019-04-11T05:12:25.601Z I ASIO     [NetworkInterfaceASIO-Replication-0] Failed to connect to m2.mydomain.com:40000 - HostUnreachable: An existing connection was forcibly closed by the remote host.
2019-04-11T05:12:25.601Z I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to m2.mydomain.com:40000
2019-04-11T05:12:26.122Z I ASIO     [NetworkInterfaceASIO-Replication-0] Successfully connected to m2.mydomain.com:40000, took 521ms (1 connections now open to m2.mydomain.com:40000)
2019-04-11T05:12:26.216Z I REPL     [ReplicationExecutor] Member m2.mydomain.com:40000 is now in state SECONDARY
2019-04-11T05:12:26.216Z I REPL     [ReplicationExecutor] Caught up to the latest optime known via heartbeats after becoming primary.
2019-04-11T05:12:26.216Z I REPL     [ReplicationExecutor] Exited primary catch-up mode.
2019-04-11T05:12:26.216Z I ASIO     [NetworkInterfaceASIO-RS-0] Ending connection to host m1.mydomain.com:40000 due to bad connection status; 1 connections to that host remain open
2019-04-11T05:12:26.216Z I REPL     [rsBackgroundSync] Replication producer stopped after oplog fetcher finished returning a batch from our sync source.  Abandoning this batch of oplog entries and re-evaluating our sync source.
2019-04-11T05:12:27.150Z I REPL     [rsSync] transition to primary complete; database writes are now permitted

I couldn't fit the whole outage log here, but it sort of was repeating the same events over and over.

Improve this question
2
  • 1
    what is your rs.status() value ?
    – Mani
    Commented Apr 11, 2019 at 15:15
  • @Mani I didn't execute rs.status() during the outage. Right now it looks normal.
    – perfect_element
    Commented Apr 11, 2019 at 17:29

1 Answer 1

Reset to default
2

Based on your log entries(I believe the log entry is taken from m4.mydomain.com) please find below some findings.

The node m4.mydomain.com is able to connect to m1.mydomain.com node but not to m2.mydomain.com node because of some network issue and this caused the election.

The m4.mydomain.com node has been selected as primary two times in the given period of logs.

2019-04-11T05:09:57.487Z I REPL     [rsSync] transition to primary complete; database writes are now permitted 
2019-04-11T05:10:24.514Z I REPL     [rsSync] transition to primary complete; database writes are now permitted

Also, it looks like the connection failure happened more than one time so that the repeated events.

The logs from m2.mydomain.com (162.221.2.98) also may help you with what has happened.

Improve this answer
4
  • So the Primary could not connect to one of the Secondaries. Why would this make the Primary step down? It would still have received the vote from the other secondary and should remain the primary, but it looks like it kept stepping down and being elected again several times, which caused the replica to be unresponsive for a few minutes.
    – perfect_element
    Commented Apr 12, 2019 at 18:03
  • What version of MongoDB you are running? Because it looks like the issue of triggering when secondary goes down exists in the older versions of MongoDB. Refer jira.mongodb.org/browse/SERVER-33350
    – Mani
    Commented Apr 12, 2019 at 18:29
  • Currently I'm on version 3.4.16.
    – perfect_element
    Commented Apr 14, 2019 at 23:26
  • By any chance did you manipulate the log records before posting? Also if it possible please update rs.conf() value as well.
    – Mani
    Commented Apr 15, 2019 at 15:56

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.