count/find query gives: MongoNotPrimaryException: The server is not the primary and did not execute the operation

XMLWordPrintableJSON

    • Type: Bug
    • Resolution: Done
    • Priority: Major - P3
    • 3.0.4
    • Affects Version/s: 3.0.3
    • Component/s: Async, Query Operations
    • None
    • Environment:
    • None
    • None
    • None
    • None
    • None
    • None
    • 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.

        1. async-mongodb-JAVA-1954.zip
          55 kB
        2. mongod-10.0.21.5-JAVA-1954.log
          10.46 MB
        3. mongodb-secondary-log.txt
          106 kB

            Assignee:
            Ross Lawley
            Reporter:
            Jens Geiregat
            None
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Created:
              Updated:
              Resolved: