[OAK-5545] Replica Set Info seems to close and open Mongo connections in a loop

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 1.5.18
• Fix Version/s: 1.6.0
• Component/s: mongomk
• Assignee: Tomek Rękawek
• Reporter: Tomek Rękawek
• Created: 30/Jan/17 09:06
• Updated: 13/Feb/17 14:32
• Resolved: 30/Jan/17 09:53

Description

The Replica Set Info should keep a pool of direct connections to each replica set member (so it can get the recent info about the replicated revisions). It’s maintained by NodeCollectionProvider. It seems that the connection are being closed, even though they are still used:

24.01.2017 13:33:42.238 *INFO* [MongoDocumentStore replica set info provider (0)] org.mongodb.driver.cluster Cluster created with settings {hosts=[10.40.66.214:27019], mode=SINGLE, requiredClusterType=UNKNOWN, serverSelectionTimeout='30000 ms', maxWaitQueueSize=500}
24.01.2017 13:33:42.239 *INFO* [MongoDocumentStore replica set info provider (0)] org.mongodb.driver.cluster No server chosen by ReadPreferenceServerSelector{readPreference=primary} from cluster description ClusterDescription{type=UNKNOWN, connectionMode=SINGLE, serverDescriptions=[ServerDescription{address=10.40.66.214:27019, type=UNKNOWN, state=CONNECTING}]}. Waiting for 30000 ms before timing out
24.01.2017 13:33:42.241 *INFO* [cluster-ClusterId{value='58870a5e30806985f2fc331e', description='null'}-10.40.66.214:27019] org.mongodb.driver.connection Opened connection [connectionId{localValue:3190, serverValue:32190}] to 10.40.66.214:27019
24.01.2017 13:33:42.241 *INFO* [cluster-ClusterId{value='58870a5e30806985f2fc331e', description='null'}-10.40.66.214:27019] org.mongodb.driver.cluster Monitor thread successfully connected to server with description ServerDescription{address=10.40.66.214:27019, type=REPLICA_SET_PRIMARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 2, 1]}, minWireVersion=0, maxWireVersion=4, maxDocumentSize=16777216, roundTripTimeNanos=452055, setName='replica', canonicalAddress=10.40.66.214:27019, hosts=[no1010040066196.corp.adobe.com:27019, 10.40.66.214:27019, 10.40.66.183:27019], passives=[], arbiters=[], primary='10.40.66.214:27019', tagSet=TagSet{[]}, electionId=57c968610000000000000005, setVersion=3, lastWriteDate=null, lastUpdateTimeNanos=14416412141118257}
24.01.2017 13:33:42.244 *INFO* [MongoDocumentStore replica set info provider (0)] org.mongodb.driver.connection Opened connection [connectionId{localValue:3191, serverValue:32191}] to 10.40.66.214:27019
24.01.2017 13:33:42.245 *INFO* [MongoDocumentStore replica set info provider (0)] org.mongodb.driver.connection Closed connection [connectionId{localValue:3191, serverValue:32191}] to 10.40.66.214:27019 because the pool has been closed.
24.01.2017 13:33:47.248 *INFO* [MongoDocumentStore replica set info provider (0)] org.mongodb.driver.cluster Cluster created with settings {hosts=[10.40.66.214:27019], mode=SINGLE, requiredClusterType=UNKNOWN, serverSelectionTimeout='30000 ms', maxWaitQueueSize=500}
24.01.2017 13:33:47.249 *INFO* [MongoDocumentStore replica set info provider (0)] org.mongodb.driver.cluster No server chosen by ReadPreferenceServerSelector{readPreference=primary} from cluster description ClusterDescription{type=UNKNOWN, connectionMode=SINGLE, serverDescriptions=[ServerDescription{address=10.40.66.214:27019, type=UNKNOWN, state=CONNECTING}]}. Waiting for 30000 ms before timing out
24.01.2017 13:33:47.264 *INFO* [cluster-ClusterId{value='58870a6330806985f2fc331f', description='null'}-10.40.66.214:27019] org.mongodb.driver.connection Opened connection [connectionId{localValue:3192, serverValue:32194}] to 10.40.66.214:27019
24.01.2017 13:33:47.265 *INFO* [cluster-ClusterId{value='58870a6330806985f2fc331f', description='null'}-10.40.66.214:27019] org.mongodb.driver.cluster Monitor thread successfully connected to server with description ServerDescription{address=10.40.66.214:27019, type=REPLICA_SET_PRIMARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 2, 1]}, minWireVersion=0, maxWireVersion=4, maxDocumentSize=16777216, roundTripTimeNanos=416028, setName='replica', canonicalAddress=10.40.66.214:27019, hosts=[no1010040066196.corp.adobe.com:27019, 10.40.66.214:27019, 10.40.66.183:27019], passives=[], arbiters=[], primary='10.40.66.214:27019', tagSet=TagSet{[]}, electionId=57c968610000000000000005, setVersion=3, lastWriteDate=null, lastUpdateTimeNanos=14416417164730588}
24.01.2017 13:33:47.268 *INFO* [MongoDocumentStore replica set info provider (0)] org.mongodb.driver.connection Opened connection [connectionId{localValue:3193, serverValue:32195}] to 10.40.66.214:27019
24.01.2017 13:33:47.269 *INFO* [MongoDocumentStore replica set info provider (0)] org.mongodb.driver.connection Closed connection [connectionId{localValue:3193, serverValue:32195}] to 10.40.66.214:27019 because the pool has been closed.

Issue Links

• breaks: OAK-5636 potential NPE in ReplicaSetInfo