I have the following MongoDB 4.0.2 cluster with the following information:
rs.conf()
{
IP:192.168.1.26, // Primary, in New York branch
priority:10
},
{
IP:192.168.1.24, // Second Secondary, in New Jersey branch
priority:3
},
{
IP:192.168.1.25, // First Secondary, in New York branch
priority:5
}
We have a server application located in 192.168.5.30 (in New York branch). This application was configured only to connect to MongoDB server 192.168.1.26. Its connection string was established that way. Something happened at 2022-08-15 13:06. There was a bad swtich core configuration that affected the MongoDB cluster. It also affected the connection to Branch New Jersey office PCs and servers. We didn't have Lan network nor Internet so I couldn't monitor what is happening between 13:06 and 13:32. I don't know if MongoDB node from 192.168.1.26 was available. The application couldn't connect to 192.168.1.26. According to application log, why the application tried to connect to 192.168.1.24. It seems that 192.168.1.26 and 192.168.1.25 weren't available. The network team solved the problem and the MongoDB cluster and application started to work again and also I could monitor.
MongoDB server log from 192.168.1.26 (Primary):
2022-08-15T13:06:37.290-0500 I NETWORK [conn130209] received client metadata from 192.168.1.25:56862 conn130209: { driver: { name: "MongoDB Internal Client", version: "4.0.2" }, os: { type: "Linux", name: "Red Hat Enterprise Linux release 8.1 (Ootpa)", architecture: "x86_64", version: "Kernel 4.18.0-147.el8.x86_64" } }
2022-08-15T13:06:37.292-0500 I ACCESS [conn130209] Successfully authenticated as principal __system on local
2022-08-15T13:06:37.292-0500 I NETWORK [conn130209] end connection 192.168.1.25:56862 (79 connections now open)
2022-08-15T13:06:37.294-0500 I NETWORK [listener] connection accepted from 192.168.1.25:56866 #130210 (80 connections now open)
2022-08-15T13:06:37.294-0500 I NETWORK [conn130210] received client metadata from 192.168.1.25:56866 conn130210: { driver: { name: "MongoDB Internal Client", version: "4.0.2" }, os: { type: "Linux", name: "Red Hat Enterprise Linux release 8.1 (Ootpa)", architecture: "x86_64", version: "Kernel 4.18.0-147.el8.x86_64" } }
2022-08-15T13:06:37.296-0500 I ACCESS [conn130210] Successfully authenticated as principal __system on local
2022-08-15T13:06:37.296-0500 I NETWORK [conn130210] end connection 192.168.1.25:56866 (79 connections now open)
2022-08-15T13:06:37.297-0500 I NETWORK [listener] connection accepted from 192.168.1.25:56868 #130211 (80 connections now open)
2022-08-15T13:06:37.297-0500 I NETWORK [conn130211] received client metadata from 192.168.1.25:56868 conn130211: { driver: { name: "MongoDB Internal Client", version: "4.0.2" }, os: { type: "Linux", name: "Red Hat Enterprise Linux release 8.1 (Ootpa)", architecture: "x86_64", version: "Kernel 4.18.0-147.el8.x86_64" } }
2022-08-15T13:06:37.298-0500 I ACCESS [conn130211] Successfully authenticated as principal __system on local
2022-08-15T13:06:37.299-0500 I NETWORK [conn130211] end connection 192.168.1.25:56868 (79 connections now open)
2022-08-15T13:06:37.300-0500 I NETWORK [listener] connection accepted from 192.168.1.25:56870 #130212 (80 connections now open)
2022-08-15T13:06:37.300-0500 I NETWORK [conn130212] received client metadata from 192.168.1.25:56870 conn130212: { driver: { name: "MongoDB Internal Client", version: "4.0.2" }, os: { type: "Linux", name: "Red Hat Enterprise Linux release 8.1 (Ootpa)", architecture: "x86_64", version: "Kernel 4.18.0-147.el8.x86_64" } }
2022-08-15T13:06:37.301-0500 I ACCESS [conn130212] Successfully authenticated as principal __system on local
2022-08-15T13:06:37.302-0500 I NETWORK [conn130212] end connection 192.168.1.25:56870 (79 connections now open)
2022-08-15T13:06:40.443-0500 I REPL_HB [replexec-5568] Error in heartbeat (requestId: 4308998) to 192.168.1.24:27017, response status: NetworkInterfaceExceededTimeLimit: Couldn't get a connection within the time limit
2022-08-15T13:06:44.151-0500 I ASIO [Replication] Failed to connect to 192.168.1.24:27017 - HostUnreachable: Error connecting to 192.168.1.24:27017 :: caused by :: No route to host
2022-08-15T13:06:44.151-0500 I ASIO [Replication] Dropping all pooled connections to 192.168.1.24:27017 due to HostUnreachable: Error connecting to 192.168.1.24:27017 :: caused by :: No route to host
2022-08-15T13:06:44.151-0500 I REPL_HB [replexec-5568] Error in heartbeat (requestId: 4309005) to 192.168.1.24:27017, response status: HostUnreachable: Error connecting to 192.168.1.24:27017 :: caused by :: No route to host
2022-08-15T13:06:44.151-0500 I ASIO [Replication] Connecting to 192.168.1.24:27017
2022-08-15T13:06:47.223-0500 I ASIO [Replication] Failed to connect to 192.168.1.24:27017 - HostUnreachable: Error connecting to 192.168.1.24:27017 :: caused by :: No route to host
MongoDB server log from 192.168.1.24 (second secondary):
2022-08-15T13:06:02.011-0500 I REPL [replication-32] Scheduled new oplog query Fetcher source: 192.168.1.26:27017 database: local query: { find: "oplog.rs", filter: { ts: { $gte: Timestamp(1666278346, 1) } }, tailable: true, oplogReplay: true, awaitData: true, maxTimeMS: 2000, batchSize: 13981010, term: 23, readConcern: { afterClusterTime: Timestamp(1666278346, 1) } } query metadata: { $replData: 1, $oplogQueryData: 1, $readPreference: { mode: "secondaryPreferred" } } active: 1 findNetworkTimeout: 7000ms getMoreNetworkTimeout: 10000ms shutting down?: 0 first: 1 firstCommandScheduler: RemoteCommandRetryScheduler request: RemoteCommand 5542419 -- target:192.168.1.26:27017 db:local cmd:{ find: "oplog.rs", filter: { ts: { $gte: Timestamp(1666278346, 1) } }, tailable: true, oplogReplay: true, awaitData: true, maxTimeMS: 2000, batchSize: 13981010, term: 23, readConcern: { afterClusterTime: Timestamp(1666278346, 1) } } active: 1 callbackHandle.valid: 1 callbackHandle.cancelled: 0 attempt: 1 retryPolicy: RetryPolicyImpl maxAttempts: 1 maxTimeMillis: -1ms
2022-08-15T13:06:02.011-0500 I ASIO [RS] Connecting to 192.168.1.26:27017
2022-08-15T13:06:02.984-0500 I REPL [replexec-5456] Starting an election, since we've seen no PRIMARY in the past 10000ms
2022-08-15T13:06:02.984-0500 I REPL [replexec-5456] conducting a dry run election to see if we could be elected. current term: 23
2022-08-15T13:06:02.984-0500 I ASIO [Replication] Connecting to 192.168.1.26:27017
2022-08-15T13:06:02.984-0500 I ASIO [Replication] Connecting to 192.168.1.25:27017
2022-08-15T13:06:04.084-0500 I REPL_HB [replexec-5469] Error in heartbeat (requestId: 5542416) to 192.168.1.25:27017, response status: NetworkInterfaceExceededTimeLimit: timed out
2022-08-15T13:06:04.084-0500 I ASIO [Replication] Ending connection to host 192.168.1.25:27017 due to bad connection status; 1 connections to that host remain open
2022-08-15T13:06:04.084-0500 I REPL [replexec-5469] Member 192.168.1.25:27017 is now in state RS_DOWN
2022-08-15T13:06:04.095-0500 I ASIO [Replication] Ending connection to host 192.168.1.26:27017 due to bad connection status; 1 connections to that host remain open
2022-08-15T13:06:04.095-0500 I REPL_HB [replexec-5456] Error in heartbeat (requestId: 5542417) to 192.168.1.26:27017, response status: NetworkInterfaceExceededTimeLimit: timed out
2022-08-15T13:06:04.095-0500 I REPL [replexec-5456] Member 192.168.1.26:27017 is now in state RS_DOWN
2022-08-15T13:06:06.084-0500 I ASIO [Replication] Connecting to 192.168.1.25:27017
2022-08-15T13:06:06.095-0500 I ASIO [Replication] Connecting to 192.168.1.26:27017
2022-08-15T13:06:09.012-0500 I REPL [replication-30] Error returned from oplog query (no more query restarts left): NetworkInterfaceExceededTimeLimit: error in fetcher batch callback :: caused by :: Couldn't get a connection within the time limit
2022-08-15T13:06:09.012-0500 W REPL [rsBackgroundSync] Fetcher stopped querying remote oplog with error: NetworkInterfaceExceededTimeLimit: error in fetcher batch callback :: caused by :: Couldn't get a connection within the time limit
2022-08-15T13:06:09.012-0500 I REPL [rsBackgroundSync] Clearing sync source 192.168.1.26:27017 to choose a new one.
2022-08-15T13:06:09.012-0500 I REPL [rsBackgroundSync] could not find member to sync from
2022-08-15T13:06:09.013-0500 I ASIO [Replication] Connecting to 192.168.1.25:27017
2022-08-15T13:06:09.013-0500 I ASIO [Replication] Connecting to 192.168.1.26:27017
2022-08-15T13:06:12.985-0500 I REPL [replexec-5456] VoteRequester(term 23 dry run) failed to receive response from 192.168.1.26:27017: NetworkInterfaceExceededTimeLimit: Couldn't get a connection within the time limit
2022-08-15T13:06:12.985-0500 I REPL [replexec-5469] VoteRequester(term 23 dry run) failed to receive response from 192.168.1.25:27017: NetworkInterfaceExceededTimeLimit: Couldn't get a connection within the time limit
2022-08-15T13:06:12.985-0500 I REPL [replexec-5469] not running for primary, we received insufficient votes
2022-08-15T13:06:14.052-0500 I REPL [replexec-5456] Not starting an election, since we are not electable due to: Not standing for election because I cannot see a majority (mask 0x1)
2022-08-15T13:06:16.084-0500 I REPL_HB [replexec-5469] Error in heartbeat (requestId: 5542422) to 192.168.1.25:27017, response status: NetworkInterfaceExceededTimeLimit: Couldn't get a connection within the time limit
2022-08-15T13:06:16.084-0500 I REPL_HB [replexec-5456] Error in heartbeat (requestId: 5542424) to 192.168.1.25:27017, response status: NetworkInterfaceExceededTimeLimit: Couldn't get a connection within the time limit
2022-08-15T13:06:16.095-0500 I REPL_HB [replexec-5469] Error in heartbeat (requestId: 5542423) to 192.168.1.26:27017, response status: NetworkInterfaceExceededTimeLimit: Couldn't get a connection within the time limit
2022-08-15T13:06:16.095-0500 I REPL_HB [replexec-5456] Error in heartbeat (requestId: 5542425) to 192.168.1.26:27017, response status: NetworkInterfaceExceededTimeLimit: Couldn't get a connection within the time limit
2022-08-15T13:06:24.896-0500 I REPL [replexec-5456] Not starting an election, since we are not electable due to: Not standing for election because I cannot see a majority (mask 0x1)
Server application log (192.168.5.30):
2022-08-15 13:06:36.184 INFO 3811 --- [cluster-ClusterId{value='631b577c819f670ee33436e6', description='null'}-192.168.1.24:27017] org.mongodb.driver.cluster Exception in monitor thread while connecting to server 192.168.1.24:27017
com.mongodb.MongoSocketOpenException: Exception opening socket
at com.mongodb.internal.connection.SocketStream.open(SocketStream.java:67) ~[mongodb-driver-core-3.8.2.jar!/:na]
at com.mongodb.internal.connection.InternalStreamConnection.open(InternalStreamConnection.java:126) ~[mongodb-driver-core-3.8.2.jar!/:na]
at com.mongodb.internal.connection.DefaultServerMonitor$ServerMonitorRunnable.run(DefaultServerMonitor.java:131) ~[mongodb-driver-core-3.8.2.jar!/:na]
at java.lang.Thread.run(Thread.java:748) [na:1.8.0_181]
Caused by: java.net.SocketTimeoutException: connect timed out
at java.net.PlainSocketImpl.socketConnect(Native Method) ~[na:1.8.0_181]
at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350) ~[na:1.8.0_181]
at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206) ~[na:1.8.0_181]
at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188) ~[na:1.8.0_181]
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) ~[na:1.8.0_181]
at java.net.Socket.connect(Socket.java:589) ~[na:1.8.0_181]
at com.mongodb.internal.connection.SocketStreamHelper.initialize(SocketStreamHelper.java:64) ~[mongodb-driver-core-3.8.2.jar!/:na]
at com.mongodb.internal.connection.SocketStream.open(SocketStream.java:62) ~[mongodb-driver-core-3.8.2.jar!/:na]
... 3 common frames omitted
2022-08-15 13:06:36.192 INFO 3811 --- [cluster-ClusterId{value='631b577d819f670ee33436e7', description='null'}-192.168.1.24:27017] org.mongodb.driver.cluster Exception in monitor thread while connecting to server 192.168.1.24:27017
com.mongodb.MongoSocketOpenException: Exception opening socket
at com.mongodb.internal.connection.SocketStream.open(SocketStream.java:67) ~[mongodb-driver-core-3.8.2.jar!/:na]
at com.mongodb.internal.connection.InternalStreamConnection.open(InternalStreamConnection.java:126) ~[mongodb-driver-core-3.8.2.jar!/:na]
at com.mongodb.internal.connection.DefaultServerMonitor$ServerMonitorRunnable.run(DefaultServerMonitor.java:131) ~[mongodb-driver-core-3.8.2.jar!/:na]
at java.lang.Thread.run(Thread.java:748) [na:1.8.0_181]
Caused by: java.net.SocketTimeoutException: connect timed out
at java.net.PlainSocketImpl.socketConnect(Native Method) ~[na:1.8.0_181]
at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350) ~[na:1.8.0_181]
at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206) ~[na:1.8.0_181]
at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188) ~[na:1.8.0_181]
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) ~[na:1.8.0_181]
at java.net.Socket.connect(Socket.java:589) ~[na:1.8.0_181]
at com.mongodb.internal.connection.SocketStreamHelper.initialize(SocketStreamHelper.java:64) ~[mongodb-driver-core-3.8.2.jar!/:na]
at com.mongodb.internal.connection.SocketStream.open(SocketStream.java:62) ~[mongodb-driver-core-3.8.2.jar!/:na]
... 3 common frames omitted
2022-08-15 13:32:25.239 INFO 3811 --- [cluster-ClusterId{value='631b577d819f670ee33436e7', description='null'}-192.168.1.24:27017] org.mongodb.driver.connection Opened connection [connectionId{localValue:138755, serverValue:20812866}] to 192.168.1.24:27017
2022-08-15 13:32:25.240 INFO 3811 --- [cluster-ClusterId{value='631b577c819f670ee33436e6', description='null'}-192.168.1.24:27017] org.mongodb.driver.connection Opened connection [connectionId{localValue:138756, serverValue:20812859}] to 192.168.1.24:27017
2022-08-15 13:32:25.241 INFO 3811 --- [cluster-ClusterId{value='631b577d819f670ee33436e7', description='null'}-192.168.1.24:27017] org.mongodb.driver.cluster Monitor thread successfully connected to server with description ServerDescription{address=192.168.1.24:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[4, 0, 2]}, minWireVersion=0, maxWireVersion=7, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=1031316, setName='clusterMongo', canonicalAddress=192.168.1.24:27017, hosts=[192.168.1.24:27017, 192.168.1.25:27017, 192.168.1.26:27017], passives=[], arbiters=[], primary='null', tagSet=TagSet{[]}, electionId=null, setVersion=5, lastWriteDate=Thu Oct 20 10:05:46 PET 2022, lastUpdateTimeNanos=3546597595403271}
The question are as follows:
Why MongoDB primary node was not available for application? I think the node 192.168.1.26 should have been responding.
Why when a secondary node is unreacheable the cluster is affected?
