[JAVA-2421] When setting readPreference=nearest arbiter can be selected and operation errors out Created: 30/Dec/16  Updated: 21/Jun/18  Resolved: 09/Jan/17

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

Type: Bug Priority: Major - P3
Reporter: Roy Rim Assignee: Jeffrey Yemin
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Related
is related to DRIVERS-2129 Replica set server selection tests sh... Closed
Case:

 Description   

When setting readPreference to nearest the driver can pick an arbiter and error out.

We have gotten this to happen using Java driver 3.4.0 and MongoDB 3.2.11. On my local mac running a replica set PSA, regardless of connection string I can get the arbiter to be used:

Start up PSA with mlaunch:

mlaunch init --dir ./repl --replicaset --arbiter 1 --nodes 2 --auth

Java code:

package mongodbjava;
 
import com.mongodb.MongoClient;
import com.mongodb.MongoClientURI;
import com.mongodb.ReadPreference;
import com.mongodb.client.MongoCollection;
import com.mongodb.client.MongoCursor;
import com.mongodb.client.MongoDatabase;
import static com.mongodb.client.model.Filters.eq;
import org.bson.Document;
 
public class MongoDBJava {
 
    public static void main(String[] args) {
 
        MongoClientURI uri = new MongoClientURI( args[0] );
        MongoClient mongoClient = new MongoClient( uri );
        MongoDatabase database = mongoClient.getDatabase("foo");
        MongoCollection collection = database.getCollection("blah").withReadPreference(ReadPreference.nearest());
        MongoCursor<Document> cursor = collection.find( eq( "name", "roy" ) ).iterator();
        try {
            while ( cursor.hasNext() ) {
                System.out.println( cursor.next().toJson() );
            }
        }
        finally {
            cursor.close();
        }
    }
    
}

Run java code with the primary and secondary in connection string:

java -cp lib/*:dist/MongoDBJava.jar mongodbjava.MongoDBJava "mongodb://user:password@localhost:27017,localhost:27018/?authSource=admin"

Error:

INFO: Monitor thread successfully connected to server with description ServerDescription{address=roys-macbook-pro-2.local:27018, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 2, 4]}, minWireVersion=0, maxWireVersion=4, maxDocumentSize=16777216, roundTripTimeNanos=1126490, setName='replset', canonicalAddress=Roys-MacBook-Pro-2.local:27018, hosts=[Roys-MacBook-Pro-2.local:27017, Roys-MacBook-Pro-2.local:27018], passives=[], arbiters=[Roys-MacBook-Pro-2.local:27019], primary='Roys-MacBook-Pro-2.local:27017', tagSet=TagSet{[]}, electionId=null, setVersion=1, lastWriteDate=null, lastUpdateTimeNanos=248383248908752}
Exception in thread "main" com.mongodb.MongoQueryException: Query failed with error code 13 and error message 'not authorized on foo to execute command { find: "blah", filter: { name: "roy" } }' on server roys-macbook-pro-2.local:27019
	at com.mongodb.operation.FindOperation$1.call(FindOperation.java:521)
	at com.mongodb.operation.FindOperation$1.call(FindOperation.java:510)
	at com.mongodb.operation.OperationHelper.withConnectionSource(OperationHelper.java:431)
	at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:404)
	at com.mongodb.operation.FindOperation.execute(FindOperation.java:510)
	at com.mongodb.operation.FindOperation.execute(FindOperation.java:81)
	at com.mongodb.Mongo.execute(Mongo.java:836)
	at com.mongodb.Mongo$2.execute(Mongo.java:823)
	at com.mongodb.OperationIterable.iterator(OperationIterable.java:47)
	at com.mongodb.FindIterableImpl.iterator(FindIterableImpl.java:151)
	at mongodbjava.MongoDBJava.main(MongoDBJava.java:48)

Weirdly I get a different error when running a PSA in Amazon using Cloud Manager. This setup has the arbiter on the west coast and the data bearing nodes on the east coast.
https://cloud.mongodb.com/v2/570551eee4b0360b09261739#deployment/topology

Running the code on the west coast server:

java -cp lib/*:MongoDBJava.jar mongodbjava.MongoDBJava "mongodb://joe:password@royrim-0.royrim.9512.mongodbdns.com:27000,royrim-1.royrim.9512.mongodbdns.com:27000,royrim-3.royrim.9512.mongodbdns.com:27000/?authSource=admin"

Error:

INFO: Closed connection [connectionId{localValue:4, serverValue:2547}] to royrim-3.royrim.9512.mongodbdns.com:27000 because there was a socket exception raised on another connection from this pool.
Exception in thread "main" com.mongodb.MongoNodeIsRecoveringException: The server is in recovery mode and did not execute the operation
	at com.mongodb.connection.ProtocolHelper.createSpecialException(ProtocolHelper.java:173)
	at com.mongodb.connection.ProtocolHelper.getCommandFailureException(ProtocolHelper.java:111)
	at com.mongodb.connection.CommandProtocol.execute(CommandProtocol.java:114)
	at com.mongodb.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:168)
	at com.mongodb.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:289)
	at com.mongodb.connection.DefaultServerConnection.command(DefaultServerConnection.java:176)
	at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:216)
	at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:207)
	at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:113)
	at com.mongodb.operation.FindOperation$1.call(FindOperation.java:516)
	at com.mongodb.operation.FindOperation$1.call(FindOperation.java:510)
	at com.mongodb.operation.OperationHelper.withConnectionSource(OperationHelper.java:431)
	at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:404)
	at com.mongodb.operation.FindOperation.execute(FindOperation.java:510)
	at com.mongodb.operation.FindOperation.execute(FindOperation.java:81)
	at com.mongodb.Mongo.execute(Mongo.java:836)
	at com.mongodb.Mongo$2.execute(Mongo.java:823)
	at com.mongodb.OperationIterable.iterator(OperationIterable.java:47)
	at com.mongodb.FindIterableImpl.iterator(FindIterableImpl.java:151)
	at mongodbjava.MongoDBJava.main(MongoDBJava.java:31)

Weirdly if I leave off the arbiter from the connection string I don't get an error:

java -cp lib/*:MongoDBJava.jar mongodbjava.MongoDBJava "mongodb://joe:password@royrim-0.royrim.9512.mongodbdns.com:27000,royrim-1.royrim.9512.mongodbdns.com:27000/?authSource=admin"

Regards,
Roy



 Comments   
Comment by Githook User [ 09/Jan/17 ]

Author:

{u'username': u'jyemin', u'name': u'Jeff Yemin', u'email': u'jeff.yemin@10gen.com'}

Message: JAVA-2421: Select only primaries and secondaries for nearest read preference
Branch: 3.4.x
https://github.com/mongodb/mongo-java-driver/commit/bac3f045d35e789796f69bd530a37aefb3cfa5c6

Comment by Githook User [ 09/Jan/17 ]

Author:

{u'username': u'jyemin', u'name': u'Jeff Yemin', u'email': u'jeff.yemin@10gen.com'}

Message: JAVA-2421: Select only primaries and secondaries for nearest read preference
Branch: master
https://github.com/mongodb/mongo-java-driver/commit/c934b6c4a19545e73b989f8c63c251767f968b21

Comment by Roy Rim [ 30/Dec/16 ]

I am not seeing the issue with driver version 3.2.0 and 3.3.0.

Comment by Roy Rim [ 30/Dec/16 ]

Ah sorry, for the test I ran locally I realized that I was passing localhost instead of the hostname that matches the rs.conf(). I tried a new test specifying set tags and got some more logs I did not get before.

Using "localhost" instead of the hostname seems to reject the servers from the cluster view and then eventually is left with just the arbiter.

INFO: Server localhost:27017 is no longer a member of the replica set.  Removing from client view of cluster.
Dec 30, 2016 2:36:42 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Server localhost:27018 is no longer a member of the replica set.  Removing from client view of cluster.
Dec 30, 2016 2:36:42 PM com.mongodb.diagnostics.logging.JULLogger log

At this point the driver seems to try to connect to the arbiter and then times out:

INFO: Monitor thread successfully connected to server with description ServerDescription{address=roys-macbook-pro-2.local:27018, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 2, 4]}, minWireVersion=0, maxWireVersion=4, maxDocumentSize=16777216, roundTripTimeNanos=1122940, setName='replset', canonicalAddress=Roys-MacBook-Pro-2.local:27018, hosts=[Roys-MacBook-Pro-2.local:27017, Roys-MacBook-Pro-2.local:27018], passives=[], arbiters=[Roys-MacBook-Pro-2.local:27019], primary='Roys-MacBook-Pro-2.local:27017', tagSet=TagSet{[Tag{name='use', value='pickme'}]}, electionId=null, setVersion=2, lastWriteDate=null, lastUpdateTimeNanos=253536488493318}
Exception in thread "main" com.mongodb.MongoTimeoutException: Timed out after 30000 ms while waiting for a server that matches ReadPreferenceServerSelector{readPreference=ReadPreference{name=nearest, tagSetList=[TagSet{[Tag{name='pick', value='useme'}]}]}}. Client view of cluster state is {type=REPLICA_SET, servers=[{address=roys-macbook-pro-2.local:27017, type=REPLICA_SET_PRIMARY, TagSet{[Tag{name='use', value='pickme'}]}, roundTripTime=0.9 ms, state=CONNECTED}, {address=roys-macbook-pro-2.local:27018, type=REPLICA_SET_SECONDARY, TagSet{[Tag{name='use', value='pickme'}]}, roundTripTime=1.0 ms, state=CONNECTED}, {address=roys-macbook-pro-2.local:27019, type=REPLICA_SET_ARBITER, roundTripTime=0.9 ms, state=CONNECTED}]
	at com.mongodb.connection.BaseCluster.createTimeoutException(BaseCluster.java:377)
	at com.mongodb.connection.BaseCluster.selectServer(BaseCluster.java:104)
	at com.mongodb.binding.ClusterBinding$ClusterBindingConnectionSource.<init>(ClusterBinding.java:75)
	at com.mongodb.binding.ClusterBinding$ClusterBindingConnectionSource.<init>(ClusterBinding.java:71)
	at com.mongodb.binding.ClusterBinding.getReadConnectionSource(ClusterBinding.java:63)
	at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:402)
	at com.mongodb.operation.FindOperation.execute(FindOperation.java:510)
	at com.mongodb.operation.FindOperation.execute(FindOperation.java:81)
	at com.mongodb.Mongo.execute(Mongo.java:836)
	at com.mongodb.Mongo$2.execute(Mongo.java:823)

Which is still odd behavior to me. If I fix my connection string to use the same hostnames in my rs.config() then all works as expected.

Now that I know that I'm not using the right hostname I tried again but when I include the arbiter back into the connection string I was still able to get the error again.

Roys-MacBook-Pro-2:MongoDBJava royrim$ java -cp lib/*:dist/MongoDBJava.jar mongodbjava.MongoDBJava "mongodb://user:password@Roys-MacBook-Pro-2.local:27017,Roys-MacBook-Pro-2.local:27018,Roys-MacBook-Pro-2.local:27019/?authSource=admin&replicaSet=replset&readPreference=nearest"
Dec 30, 2016 2:57:44 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Cluster created with settings {hosts=[roys-macbook-pro-2.local:27017, roys-macbook-pro-2.local:27018, roys-macbook-pro-2.local:27019], mode=MULTIPLE, requiredClusterType=REPLICA_SET, serverSelectionTimeout='30000 ms', maxWaitQueueSize=500, requiredReplicaSetName='replset'}
Dec 30, 2016 2:57:44 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Adding discovered server roys-macbook-pro-2.local:27017 to client view of cluster
Dec 30, 2016 2:57:44 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Adding discovered server roys-macbook-pro-2.local:27018 to client view of cluster
Dec 30, 2016 2:57:44 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Adding discovered server roys-macbook-pro-2.local:27019 to client view of cluster
Dec 30, 2016 2:57:45 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: No server chosen by ReadPreferenceServerSelector{readPreference=ReadPreference{name=nearest}} from cluster description ClusterDescription{type=REPLICA_SET, connectionMode=MULTIPLE, serverDescriptions=[ServerDescription{address=roys-macbook-pro-2.local:27017, type=UNKNOWN, state=CONNECTING}, ServerDescription{address=roys-macbook-pro-2.local:27018, type=UNKNOWN, state=CONNECTING}, ServerDescription{address=roys-macbook-pro-2.local:27019, type=UNKNOWN, state=CONNECTING}]}. Waiting for 30000 ms before timing out
Dec 30, 2016 2:57:45 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Opened connection [connectionId{localValue:3, serverValue:82}] to roys-macbook-pro-2.local:27019
Dec 30, 2016 2:57:45 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Monitor thread successfully connected to server with description ServerDescription{address=roys-macbook-pro-2.local:27019, type=REPLICA_SET_ARBITER, state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 2, 4]}, minWireVersion=0, maxWireVersion=4, maxDocumentSize=16777216, roundTripTimeNanos=5604590, setName='replset', canonicalAddress=Roys-MacBook-Pro-2.local:27019, hosts=[Roys-MacBook-Pro-2.local:27017, Roys-MacBook-Pro-2.local:27018], passives=[], arbiters=[Roys-MacBook-Pro-2.local:27019], primary='Roys-MacBook-Pro-2.local:27017', tagSet=TagSet{[]}, electionId=null, setVersion=2, lastWriteDate=null, lastUpdateTimeNanos=254799123231338}
Dec 30, 2016 2:57:45 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Opened connection [connectionId{localValue:4, serverValue:83}] to roys-macbook-pro-2.local:27019
Exception in thread "main" com.mongodb.MongoQueryException: Query failed with error code 13 and error message 'not authorized on test to execute command { find: "blah", filter: { name: "roy" } }' on server roys-macbook-pro-2.local:27019
	at com.mongodb.operation.FindOperation$1.call(FindOperation.java:521)
	at com.mongodb.operation.FindOperation$1.call(FindOperation.java:510)
	at com.mongodb.operation.OperationHelper.withConnectionSource(OperationHelper.java:431)
	at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:404)
	at com.mongodb.operation.FindOperation.execute(FindOperation.java:510)
	at com.mongodb.operation.FindOperation.execute(FindOperation.java:81)
	at com.mongodb.Mongo.execute(Mongo.java:836)
	at com.mongodb.Mongo$2.execute(Mongo.java:823)
	at com.mongodb.OperationIterable.iterator(OperationIterable.java:47)
	at com.mongodb.FindIterableImpl.iterator(FindIterableImpl.java:151)
	at mongodbjava.MongoDBJava.main(MongoDBJava.java:48)

Roy

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