-
Type:
Bug
-
Resolution: Done
-
Priority:
Major - P3
-
Affects Version/s: 3.0.3
-
Component/s: Async, Query Operations
-
Labels:None
I posted this to https://groups.google.com/forum/#!topic/mongodb-user/7pAm95sBjgY but no response came (so far). Since this appears to be an actual bug, I'm trying my luck here.
This logging is from a connection to a replica set of 3 members (10.0.{20,21,22}.5, 10.0.22.5 is primary and has been for more than a week).
A count query is executed:
{"$and":[{"tenant":"foo"},{"$and":[{"tenant":{"$regex":".*\\Qfoo\\E.*","$options":"i"}}]}]}
(uselessly complex, I know) with read preference 'secondary'. The query fails with MongoNotPrimaryException and the connection to the secondary is marked UNKNOWN. Trace logging:
13:18:36.530 [vert.x-eventloop-thread-0] TRACE org.mongodb.driver.cluster - Asynchronously selecting server with selector ReadPreferenceServerSelector{readPreference=secondary}
13:18:36.531 [vert.x-eventloop-thread-0] TRACE org.mongodb.driver.cluster - Asynchronously selected server 10.0.21.5:27017
13:18:36.531 [vert.x-eventloop-thread-0] TRACE org.mongodb.driver.connection - Asynchronously getting a connection from the pool for server ServerId{clusterId=ClusterId{value='55eec3134ce4b505fd7a76e8', description='null'}, address=10.0.
21.5:27017}
13:18:36.531 [vert.x-eventloop-thread-0] TRACE org.mongodb.driver.connection - Checked out connection [connectionId{localValue:14}] to server 10.0.21.5:27017
13:18:36.531 [vert.x-eventloop-thread-0] TRACE org.mongodb.driver.connection - Asynchronously opening pooled connection connectionId{localValue:14} to server ServerId{clusterId=ClusterId{value='55eec3134ce4b505fd7a76e8', description='nul
l'}, address=10.0.21.5:27017}
13:18:36.531 [vert.x-eventloop-thread-0] TRACE org.mongodb.driver.connection - Pooled connection connectionId{localValue:14} to server ServerId{clusterId=ClusterId{value='55eec3134ce4b505fd7a76e8', description='null'}, address=10.0.21.5:
27017} is not yet open
13:18:36.532 [Thread-6] TRACE org.mongodb.driver.connection - Queuing send message: 143. ([connectionId{localValue:14}])
13:18:36.532 [Thread-6] TRACE org.mongodb.driver.connection - Queuing read message: 143. ([connectionId{localValue:14}])
13:18:36.532 [Thread-6] TRACE org.mongodb.driver.connection - Start receiving response on connectionId{localValue:14}
13:18:36.533 [Thread-6] TRACE org.mongodb.driver.connection - Read response to message 143 on connectionId{localValue:14}
13:18:36.533 [Thread-6] TRACE org.mongodb.driver.connection - Executing callback for 143 on connectionId{localValue:14}
13:18:36.533 [Thread-6] TRACE org.mongodb.driver.connection - Queuing send message: 144. ([connectionId{localValue:14}])
13:18:36.533 [Thread-6] TRACE org.mongodb.driver.connection - Queuing read message: 144. ([connectionId{localValue:14}])
13:18:36.533 [Thread-6] TRACE org.mongodb.driver.connection - Start receiving response on connectionId{localValue:14}
13:18:36.534 [Thread-6] TRACE org.mongodb.driver.connection - Read response to message 144 on connectionId{localValue:14}
13:18:36.534 [Thread-6] TRACE org.mongodb.driver.connection - Executing callback for 144 on connectionId{localValue:14}
13:18:36.534 [Thread-6] TRACE org.mongodb.driver.connection - Queuing send message: 145. ([connectionId{localValue:14}])
13:18:36.534 [Thread-6] TRACE org.mongodb.driver.connection - Queuing read message: 145. ([connectionId{localValue:14}])
13:18:36.534 [Thread-6] TRACE org.mongodb.driver.connection - Start receiving response on connectionId{localValue:14}
13:18:36.534 [Thread-6] TRACE org.mongodb.driver.connection - Read response to message 145 on connectionId{localValue:14}
13:18:36.534 [Thread-6] TRACE org.mongodb.driver.connection - Executing callback for 145 on connectionId{localValue:14}
13:18:36.534 [Thread-6] INFO org.mongodb.driver.connection - Opened connection [connectionId{localValue:14, serverValue:983}] to 10.0.21.5:27017
13:18:36.534 [Thread-6] TRACE org.mongodb.driver.connection - Pooled connection connectionId{localValue:14, serverValue:983} to server ServerId{clusterId=ClusterId{value='55eec3134ce4b505fd7a76e8', description='null'}, address=10.0.21.5:
27017} is now open
13:18:36.536 [Thread-6] DEBUG org.mongodb.driver.protocol.command - Asynchronously sending command {count : BsonString{value='school'}} to database didditVle on connection [connectionId{localValue:14, serverValue:983}] to server 10.0.21.
5:27017
13:18:36.537 [Thread-6] TRACE org.mongodb.driver.connection - Queuing send message: 146. ([connectionId{localValue:14, serverValue:983}])
13:18:36.537 [Thread-6] TRACE org.mongodb.driver.connection - Queuing read message: 146. ([connectionId{localValue:14, serverValue:983}])
13:18:36.537 [Thread-6] TRACE org.mongodb.driver.connection - Start receiving response on connectionId{localValue:14, serverValue:983}
13:18:36.538 [Thread-5] TRACE org.mongodb.driver.connection - Read response to message 146 on connectionId{localValue:14, serverValue:983}
13:18:36.538 [Thread-5] TRACE org.mongodb.driver.connection - Executing callback for 146 on connectionId{localValue:14, serverValue:983}
13:18:36.538 [Thread-5] DEBUG org.mongodb.driver.protocol.command - Command execution completed with status false
13:18:36.545 [Thread-5] DEBUG org.mongodb.driver.cluster - Updating cluster description to {type=REPLICA_SET, servers=[{address=10.0.20.5:27017, type=REPLICA_SET_SECONDARY, roundTripTime=2.5 ms, state=CONNECTED}, {address=10.0.21.5:2701
7, type=UNKNOWN, state=CONNECTING}, {address=10.0.22.5:27017, type=REPLICA_SET_PRIMARY, roundTripTime=2.0 ms, state=CONNECTED}]
13:18:36.545 [Thread-5] DEBUG org.mongodb.driver.connection - Invalidating the connection pool
13:18:36.545 [cluster-ClusterId{value='55eec3134ce4b505fd7a76e8', description='null'}-10.0.21.5:27017] DEBUG org.mongodb.driver.connection - Closing connection connectionId{localValue:3, serverValue:965}
13:18:36.545 [Thread-5] TRACE org.mongodb.driver.connection - Checked in connection [connectionId{localValue:14, serverValue:983}] to server 10.0.21.5:27017
13:18:36.545 [Thread-5] INFO org.mongodb.driver.connection - Closed connection [connectionId{localValue:14, serverValue:983}] to 10.0.21.5:27017 because there was a socket exception raised on another connection from this pool.
13:18:36.545 [Thread-5] DEBUG org.mongodb.driver.connection - Closing connection connectionId{localValue:14, serverValue:983}
13:18:36.550 [vert.x-eventloop-thread-0] ERROR XXX.MongoConnector - An error occurred com.mongodb.MongoNotPrimaryException: The server is not the primary and did not execute the operation
at com.mongodb.connection.ProtocolHelper.createSpecialException(ProtocolHelper.java:121) ~[mongo-java-driver-3.0.3.jar:na]
Apart from the issue with the count query explained above, I have experienced the same issue with a find query today.
- is duplicated by
-
-
- Closed
-