[JAVA-1622] Possible race in async server selection Created: 15/Jan/15  Updated: 04/Nov/16  Resolved: 16/Mar/15

Status: Closed
Project: Java Driver
Component/s: Cluster Management
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Jeffrey Yemin Assignee: Unassigned
Resolution: Cannot Reproduce Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified


 Description   

An async test is timing out waiting for a server to be selected, yet, the logs show that the primary is found milliseconds after the server selection first fails to find the primary.

15:55:23.260 [Test worker] INFO  org.mongodb.driver.cluster - Cluster created with settings {hosts=[localhost:27017, localhost:27018], mode=MULTIPLE, requiredClusterType=UNKNOWN, serverSelectionTimeout='30000 ms', maxWaitQueueSize=500}
15:55:23.263 [Test worker] INFO  org.mongodb.driver.cluster - Adding discovered server localhost:27017 to client view of cluster
15:55:23.332 [Test worker] INFO  org.mongodb.driver.cluster - Adding discovered server localhost:27018 to client view of cluster
15:55:23.407 [Test worker] INFO  org.mongodb.driver.cluster - No server chosen by PrimaryServerSelector from cluster description ClusterDescription{type=UNKNOWN, connectionMode=MULTIPLE, all=[ServerDescription{address=localhost:27017, type=UNKNOWN, state=CONNECTING}, ServerDescription{address=localhost:27018, type=UNKNOWN, state=CONNECTING}]}. Waiting for 30000 ms before timing out
15:55:23.429 [cluster-ClusterId{value='54b7e2eb3de4fc41ba90c82b', description='null'}-localhost:27018] INFO  org.mongodb.driver.connection - Opened connection [connectionId{localValue:2, serverValue:24}] to localhost:27018
15:55:23.429 [cluster-ClusterId{value='54b7e2eb3de4fc41ba90c82b', description='null'}-localhost:27017] INFO  org.mongodb.driver.connection - Opened connection [connectionId{localValue:1, serverValue:43}] to localhost:27017
15:55:23.435 [cluster-ClusterId{value='54b7e2eb3de4fc41ba90c82b', description='null'}-localhost:27018] INFO  org.mongodb.driver.cluster - Monitor thread successfully connected to server with description ServerDescription{address=localhost:27018, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[2, 8, 0]}, minWireVersion=0, maxWireVersion=3, maxDocumentSize=16777216, roundTripTimeNanos=1880397, setName='repl0', hosts=[localhost:27017, localhost:27018, localhost:27019], passives=[], arbiters=[], primary='localhost:27017', tagSet=TagSet{[Tag{name='dc', value='BsonString{value='pa'}'}, Tag{name='ordinal', value='BsonString{value='two'}'}]}}
15:55:23.435 [cluster-ClusterId{value='54b7e2eb3de4fc41ba90c82b', description='null'}-localhost:27017] INFO  org.mongodb.driver.cluster - Monitor thread successfully connected to server with description ServerDescription{address=localhost:27017, type=REPLICA_SET_PRIMARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[2, 8, 0]}, minWireVersion=0, maxWireVersion=3, maxDocumentSize=16777216, roundTripTimeNanos=1614667, setName='repl0', hosts=[localhost:27017, localhost:27018, localhost:27019], passives=[], arbiters=[], primary='localhost:27017', tagSet=TagSet{[Tag{name='dc', value='BsonString{value='ny'}'}, Tag{name='ordinal', value='BsonString{value='one'}'}]}}
15:55:23.436 [cluster-ClusterId{value='54b7e2eb3de4fc41ba90c82b', description='null'}-localhost:27018] INFO  org.mongodb.driver.cluster - Discovered cluster type of REPLICA_SET
15:55:23.438 [cluster-ClusterId{value='54b7e2eb3de4fc41ba90c82b', description='null'}-localhost:27018] INFO  org.mongodb.driver.cluster - Adding discovered server localhost:27019 to client view of cluster
15:55:23.439 [cluster-ClusterId{value='54b7e2eb3de4fc41ba90c82b', description='null'}-localhost:27017] INFO  org.mongodb.driver.cluster - Discovered replica set primary localhost:27017
15:55:23.454 [cluster-ClusterId{value='54b7e2eb3de4fc41ba90c82b', description='null'}-localhost:27019] INFO  org.mongodb.driver.connection - Opened connection [connectionId{localValue:3, serverValue:23}] to localhost:27019
15:55:23.459 [cluster-ClusterId{value='54b7e2eb3de4fc41ba90c82b', description='null'}-localhost:27019] INFO  org.mongodb.driver.cluster - Monitor thread successfully connected to server with description ServerDescription{address=localhost:27019, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[2, 8, 0]}, minWireVersion=0, maxWireVersion=3, maxDocumentSize=16777216, roundTripTimeNanos=2047180, setName='repl0', hosts=[localhost:27017, localhost:27018, localhost:27019], passives=[], arbiters=[], primary='localhost:27017', tagSet=TagSet{[]}}
15:55:33.477 [Thread-6] INFO  org.mongodb.driver.connection - Opened connection [connectionId{localValue:5, serverValue:45}] to localhost:27017



 Comments   
Comment by Jeffrey Yemin [ 21/Jan/15 ]

I'm not able to reproduce this locally yet.

Generated at Thu Feb 08 08:55:04 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.