[JAVA-1954] count/find query gives: MongoNotPrimaryException: The server is not the primary and did not execute the operation Created: 09/Sep/15  Updated: 01/Apr/16  Resolved: 11/Sep/15

Status: Closed
Project: Java Driver
Component/s: Async, Query Operations
Affects Version/s: 3.0.3
Fix Version/s: 3.0.4

Type: Bug Priority: Major - P3
Reporter: Jens Geiregat Assignee: Ross Lawley
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Ubuntu Linux 14.04.1
$ java -version
java version "1.8.0_25"
Java(TM) SE Runtime Environment (build 1.8.0_25-b17)
Java HotSpot(TM) 64-Bit Server VM (build 25.25-b02, mixed mode)
MongoDB 3.0.6 in replica set (2 secondaries, 1 primary)


Attachments: Zip Archive async-mongodb-JAVA-1954.zip     File mongod-10.0.21.5-JAVA-1954.log     Text File mongodb-secondary-log.txt    
Issue Links:
Duplicate
is duplicated by JAVA-1944 Getting error when reading from secon... Closed

 Description   

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.



 Comments   
Comment by Jeffrey Yemin [ 14/Sep/15 ]

Fix release today in 3.0.4.

Comment by Ross Lawley [ 11/Sep/15 ]

After investigation we provided a more thorough fix and change.

This will be released in the forthcoming 3.0.4 and 3.1 drivers.

Comment by Githook User [ 11/Sep/15 ]

Author:

{u'username': u'rozza', u'name': u'Ross Lawley', u'email': u'ross.lawley@gmail.com'}

Message: Updated CommandOperationHelper so bindings must be provided

Ensures that readpreferences cannot accidentily default to primary()

Refs: JAVA-1954
Branch: master
https://github.com/mongodb/mongo-java-driver/commit/d779ceb7ef7e8fbc01d0c9422b125100ccf583dd

Comment by Githook User [ 11/Sep/15 ]

Author:

{u'username': u'rozza', u'name': u'Ross Lawley', u'email': u'ross.lawley@gmail.com'}

Message: Fixed readPreference for ReadBinding operations

JAVA-1954
Branch: master
https://github.com/mongodb/mongo-java-driver/commit/853fda551530ef1faaeb24bcddd5cbab19da2616

Comment by Githook User [ 11/Sep/15 ]

Author:

{u'username': u'rozza', u'name': u'Ross Lawley', u'email': u'ross.lawley@gmail.com'}

Message: Use the AsyncReadBinding's readPreference with the ReadConnectionSource

JAVA-1954 JAVA-1944
Branch: master
https://github.com/mongodb/mongo-java-driver/commit/54e67fb5879c3a1017cd13d24b0b29f4d22a9e47

Comment by Githook User [ 11/Sep/15 ]

Author:

{u'username': u'rozza', u'name': u'Ross Lawley', u'email': u'ross.lawley@gmail.com'}

Message: Updated CommandOperationHelper so bindings must be provided

Ensures that readpreferences cannot accidentily default to primary()

Refs: JAVA-1954
Branch: 3.0.x
https://github.com/mongodb/mongo-java-driver/commit/55b1e259b93f55641c3d2f80f894c24618f23221

Comment by Githook User [ 11/Sep/15 ]

Author:

{u'username': u'rozza', u'name': u'Ross Lawley', u'email': u'ross.lawley@gmail.com'}

Message: Fixed readPreference for ReadBinding operations

JAVA-1954
Branch: 3.0.x
https://github.com/mongodb/mongo-java-driver/commit/5557a3f91172650cff3bde10367816fb89dfbc10

Comment by Githook User [ 11/Sep/15 ]

Author:

{u'username': u'rozza', u'name': u'Ross Lawley', u'email': u'ross.lawley@gmail.com'}

Message: Use the AsyncReadBinding's readPreference with the ReadConnectionSource

JAVA-1954 JAVA-1944
Branch: 3.0.x
https://github.com/mongodb/mongo-java-driver/commit/0b95a2f70b751523112bc27a2747f70f04a82c6e

Comment by Ross Lawley [ 10/Sep/15 ]

jens.geiregat I have a fix in code review and it should be released shortly.

Currently, there isnt a work around other than to use ReadPreference.primary()

Comment by Jens Geiregat [ 10/Sep/15 ]

Ross: If you can provide a workaround (I'm assuming it's related to the query?) that would help us along for now...

Comment by Ross Lawley [ 10/Sep/15 ]

Thanks jens.geiregat,

I can now reproduce it reliably. Seems my tweaks to the code prevented the issue from happening which in itself is telling.

I will update once the core issue is identified and hopefully fixed.

Ross

Comment by Jens Geiregat [ 09/Sep/15 ]

Mongodb log during some failing counts on a secondary attached.

Edit: for clarity: I can reproduce the error every time I run my program.

Comment by Jeffrey Yemin [ 09/Sep/15 ]

Hi Jans,

Can you reproduce again but with a higher log verbosity on the secondary to which the count command is being sent, and then share the additional logs? I'd like to see these log messages (this is from my successful run).

2015-09-09T12:29:55.314-0400 D COMMAND  [conn132] run command test.$cmd { count: "JAVA-1955" }
2015-09-09T12:29:55.315-0400 I COMMAND  [conn132] command test.$cmd command: count { count: "JAVA-1955" } planSummary: COUNT keyUpdates:0 writeConflicts:0 numYields:0 reslen:44 locks:{} 0ms

See here for documentation on controlling server log levels.

Jeff

Comment by Ross Lawley [ 09/Sep/15 ]

Hi jens.geiregat, I ran your test code and was unable to reproduce (I just ran the project via intellij).

From your previous comment it makes it sound like you are able to reproduce the error, is that the case?

Ross

Comment by Jens Geiregat [ 09/Sep/15 ]

I did some more testing. I get the same issue while using secondaryPreferred as the read preference, and with client version 3.0.2, 3.0.1 and 3.0.0.

Replica set status:

replset0:PRIMARY> rs.status()
{
	"set" : "replset0",
	"date" : ISODate("2015-09-09T15:19:27.509Z"),
	"myState" : 1,
	"members" : [
		{
			"_id" : 2,
			"name" : "10.0.20.5:27017",
			"health" : 1,
			"state" : 2,
			"stateStr" : "SECONDARY",
			"uptime" : 787401,
			"optime" : Timestamp(1441809306, 1),
			"optimeDate" : ISODate("2015-09-09T14:35:06Z"),
			"lastHeartbeat" : ISODate("2015-09-09T15:19:26.856Z"),
			"lastHeartbeatRecv" : ISODate("2015-09-09T15:19:26.607Z"),
			"pingMs" : 0,
			"syncingTo" : "10.0.22.5:27017",
			"configVersion" : 123883
		},
		{
			"_id" : 3,
			"name" : "10.0.22.5:27017",
			"health" : 1,
			"state" : 1,
			"stateStr" : "PRIMARY",
			"uptime" : 787408,
			"optime" : Timestamp(1441809306, 1),
			"optimeDate" : ISODate("2015-09-09T14:35:06Z"),
			"electionTime" : Timestamp(1441025094, 1),
			"electionDate" : ISODate("2015-08-31T12:44:54Z"),
			"configVersion" : 123883,
			"self" : true
		},
		{
			"_id" : 4,
			"name" : "10.0.21.5:27017",
			"health" : 1,
			"state" : 2,
			"stateStr" : "SECONDARY",
			"uptime" : 75540,
			"optime" : Timestamp(1441809306, 1),
			"optimeDate" : ISODate("2015-09-09T14:35:06Z"),
			"lastHeartbeat" : ISODate("2015-09-09T15:19:26.805Z"),
			"lastHeartbeatRecv" : ISODate("2015-09-09T15:19:26.231Z"),
			"pingMs" : 1,
			"syncingTo" : "10.0.22.5:27017",
			"configVersion" : 123883
		}
	],
	"ok" : 1
}

Comment by Jens Geiregat [ 09/Sep/15 ]

I attached a zip of the gradle project to this issue. Just unzip it, then run:

./gradlew shadowJar

Then (for only localhost):

java -jar build/libs/async-mongodb-JAVA-1954-1.0-all.jar 127.0.0.1:27017

Note that I run this agains a replica set and I pass a comma-separated list of all cluster members on the command line, like in the snippet in my previous comment.

Comment by Jens Geiregat [ 09/Sep/15 ]

The linked JAVA-1944 is most likely the same issue indeed. We also use Vert.x... I went a slightly different route with the reproducer and started from https://github.com/jyemin/async-mongodb-example After some hacking, I made a project that creates an all-in-one jar that reproduces the issue for me. This is the output:

$ java -jar async-mongodb-JAVA-1954-1.0-all.jar 10.0.20.5:27017,10.0.21.5:27017,10.0.22.5:27017
ERROR! com.mongodb.MongoNotPrimaryException: The server is not the primary and did not execute the operationException in thread "main" com.mongodb.MongoNotPrimaryException: The server is not the primary and did not execute the operation
	at com.mongodb.connection.ProtocolHelper.createSpecialException(ProtocolHelper.java:121)
	at com.mongodb.connection.ProtocolHelper.getCommandFailureException(ProtocolHelper.java:73)
	at com.mongodb.connection.CommandResultCallback.callCallback(CommandResultCallback.java:51)
	at com.mongodb.connection.CommandResultCallback.callCallback(CommandResultCallback.java:29)
	at com.mongodb.connection.CommandResultBaseCallback.callCallback(CommandResultBaseCallback.java:39)
	at com.mongodb.connection.ResponseCallback.onResult(ResponseCallback.java:48)
	at com.mongodb.connection.ResponseCallback.onResult(ResponseCallback.java:23)
	at com.mongodb.connection.DefaultConnectionPool$PooledConnection$2.onResult(DefaultConnectionPool.java:450)
	at com.mongodb.connection.DefaultConnectionPool$PooledConnection$2.onResult(DefaultConnectionPool.java:444)
	at com.mongodb.connection.UsageTrackingInternalConnection$3.onResult(UsageTrackingInternalConnection.java:127)
	at com.mongodb.connection.UsageTrackingInternalConnection$3.onResult(UsageTrackingInternalConnection.java:123)
	at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:53)
	at com.mongodb.connection.InternalStreamConnection.executeCallbackAndReceiveResponse(InternalStreamConnection.java:375)
	at com.mongodb.connection.InternalStreamConnection.access$1700(InternalStreamConnection.java:65)
	at com.mongodb.connection.InternalStreamConnection$ResponseBuffersCallback.onResult(InternalStreamConnection.java:417)
	at com.mongodb.connection.InternalStreamConnection$ResponseBuffersCallback.onResult(InternalStreamConnection.java:386)
	at com.mongodb.connection.InternalStreamConnection$ResponseHeaderCallback.onSuccess(InternalStreamConnection.java:555)
	at com.mongodb.connection.InternalStreamConnection$ResponseHeaderCallback.access$2200(InternalStreamConnection.java:514)
	at com.mongodb.connection.InternalStreamConnection$ResponseHeaderCallback$ResponseBodyCallback.onResult(InternalStreamConnection.java:577)
	at com.mongodb.connection.InternalStreamConnection$ResponseHeaderCallback$ResponseBodyCallback.onResult(InternalStreamConnection.java:561)
	at com.mongodb.connection.InternalStreamConnection$3.completed(InternalStreamConnection.java:444)
	at com.mongodb.connection.InternalStreamConnection$3.completed(InternalStreamConnection.java:441)
	at com.mongodb.connection.AsynchronousSocketChannelStream$BasicCompletionHandler.completed(AsynchronousSocketChannelStream.java:221)
	at com.mongodb.connection.AsynchronousSocketChannelStream$BasicCompletionHandler.completed(AsynchronousSocketChannelStream.java:205)
	at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:126)
	at sun.nio.ch.Invoker.invokeDirect(Invoker.java:157)
	at sun.nio.ch.UnixAsynchronousSocketChannelImpl.implRead(UnixAsynchronousSocketChannelImpl.java:553)
	at sun.nio.ch.AsynchronousSocketChannelImpl.read(AsynchronousSocketChannelImpl.java:276)
	at sun.nio.ch.AsynchronousSocketChannelImpl.read(AsynchronousSocketChannelImpl.java:297)
	at com.mongodb.connection.AsynchronousSocketChannelStream.readAsync(AsynchronousSocketChannelStream.java:138)
	at com.mongodb.connection.InternalStreamConnection.readAsync(InternalStreamConnection.java:441)
	at com.mongodb.connection.InternalStreamConnection.access$2000(InternalStreamConnection.java:65)
	at com.mongodb.connection.InternalStreamConnection$ResponseHeaderCallback.onResult(InternalStreamConnection.java:537)
	at com.mongodb.connection.InternalStreamConnection$ResponseHeaderCallback.onResult(InternalStreamConnection.java:514)
	at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:53)
	at com.mongodb.connection.InternalStreamConnection$3.completed(InternalStreamConnection.java:444)
	at com.mongodb.connection.InternalStreamConnection$3.completed(InternalStreamConnection.java:441)
	at com.mongodb.connection.AsynchronousSocketChannelStream$BasicCompletionHandler.completed(AsynchronousSocketChannelStream.java:221)
	at com.mongodb.connection.AsynchronousSocketChannelStream$BasicCompletionHandler.completed(AsynchronousSocketChannelStream.java:205)
	at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:126)
	at sun.nio.ch.Invoker.invokeDirect(Invoker.java:157)
	at sun.nio.ch.UnixAsynchronousSocketChannelImpl.implRead(UnixAsynchronousSocketChannelImpl.java:553)
	at sun.nio.ch.AsynchronousSocketChannelImpl.read(AsynchronousSocketChannelImpl.java:276)
	at sun.nio.ch.AsynchronousSocketChannelImpl.read(AsynchronousSocketChannelImpl.java:297)
	at com.mongodb.connection.AsynchronousSocketChannelStream.readAsync(AsynchronousSocketChannelStream.java:138)
	at com.mongodb.connection.InternalStreamConnection.readAsync(InternalStreamConnection.java:441)
	at com.mongodb.connection.InternalStreamConnection.receiveResponseAsync(InternalStreamConnection.java:430)
	at com.mongodb.connection.InternalStreamConnection.executeCallbackAndReceiveResponse(InternalStreamConnection.java:382)
	at com.mongodb.connection.InternalStreamConnection.receiveMessageAsync(InternalStreamConnection.java:366)
	at com.mongodb.connection.UsageTrackingInternalConnection.receiveMessageAsync(UsageTrackingInternalConnection.java:130)
	at com.mongodb.connection.DefaultConnectionPool$PooledConnection.receiveMessageAsync(DefaultConnectionPool.java:444)
	at com.mongodb.connection.SendMessageCallback.onResult(SendMessageCallback.java:45)
	at com.mongodb.connection.SendMessageCallback.onResult(SendMessageCallback.java:22)
	at com.mongodb.connection.DefaultConnectionPool$PooledConnection$1.onResult(DefaultConnectionPool.java:436)
	at com.mongodb.connection.DefaultConnectionPool$PooledConnection$1.onResult(DefaultConnectionPool.java:430)
	at com.mongodb.connection.UsageTrackingInternalConnection$2.onResult(UsageTrackingInternalConnection.java:114)
	at com.mongodb.connection.UsageTrackingInternalConnection$2.onResult(UsageTrackingInternalConnection.java:110)
	at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:53)
	at com.mongodb.connection.InternalStreamConnection$2.completed(InternalStreamConnection.java:309)
	at com.mongodb.connection.InternalStreamConnection$2.completed(InternalStreamConnection.java:294)
	at com.mongodb.connection.AsynchronousSocketChannelStream$2.completed(AsynchronousSocketChannelStream.java:124)
	at com.mongodb.connection.AsynchronousSocketChannelStream$2.completed(AsynchronousSocketChannelStream.java:118)
	at com.mongodb.connection.AsynchronousSocketChannelStream$3.completed(AsynchronousSocketChannelStream.java:177)
	at com.mongodb.connection.AsynchronousSocketChannelStream$3.completed(AsynchronousSocketChannelStream.java:171)
	at com.mongodb.connection.AsynchronousSocketChannelStream$AsyncWritableByteChannelAdapter$1.completed(AsynchronousSocketChannelStream.java:194)
	at com.mongodb.connection.AsynchronousSocketChannelStream$AsyncWritableByteChannelAdapter$1.completed(AsynchronousSocketChannelStream.java:191)
	at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:126)
	at sun.nio.ch.Invoker.invokeDirect(Invoker.java:157)
	at sun.nio.ch.UnixAsynchronousSocketChannelImpl.implWrite(UnixAsynchronousSocketChannelImpl.java:736)
	at sun.nio.ch.AsynchronousSocketChannelImpl.write(AsynchronousSocketChannelImpl.java:382)
	at sun.nio.ch.AsynchronousSocketChannelImpl.write(AsynchronousSocketChannelImpl.java:399)
	at java.nio.channels.AsynchronousSocketChannel.write(AsynchronousSocketChannel.java:577)
	at com.mongodb.connection.AsynchronousSocketChannelStream$AsyncWritableByteChannelAdapter.write(AsynchronousSocketChannelStream.java:191)
	at com.mongodb.connection.AsynchronousSocketChannelStream.pipeOneBuffer(AsynchronousSocketChannelStream.java:171)
	at com.mongodb.connection.AsynchronousSocketChannelStream.writeAsync(AsynchronousSocketChannelStream.java:118)
	at com.mongodb.connection.InternalStreamConnection.writeAsync(InternalStreamConnection.java:294)
	at com.mongodb.connection.InternalStreamConnection.sendMessageAsync(InternalStreamConnection.java:288)
	at com.mongodb.connection.UsageTrackingInternalConnection.sendMessageAsync(UsageTrackingInternalConnection.java:117)
	at com.mongodb.connection.DefaultConnectionPool$PooledConnection.sendMessageAsync(DefaultConnectionPool.java:430)
	at com.mongodb.connection.CommandProtocol.executeAsync(CommandProtocol.java:107)
	at com.mongodb.connection.DefaultServer$DefaultServerProtocolExecutor.executeAsync(DefaultServer.java:165)
	at com.mongodb.connection.DefaultServerConnection.executeProtocolAsync(DefaultServerConnection.java:225)
	at com.mongodb.connection.DefaultServerConnection.commandAsync(DefaultServerConnection.java:154)
	at com.mongodb.operation.CommandOperationHelper$CommandProtocolExecutingCallback$1.onResult(CommandOperationHelper.java:376)
	at com.mongodb.operation.CommandOperationHelper$CommandProtocolExecutingCallback$1.onResult(CommandOperationHelper.java:369)
	at com.mongodb.connection.DefaultServer$1.onResult(DefaultServer.java:88)
	at com.mongodb.connection.DefaultServer$1.onResult(DefaultServer.java:79)
	at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:53)
	at com.mongodb.connection.DefaultConnectionPool$2.onResult(DefaultConnectionPool.java:198)
	at com.mongodb.connection.DefaultConnectionPool$2.onResult(DefaultConnectionPool.java:183)
	at com.mongodb.connection.UsageTrackingInternalConnection$1.onResult(UsageTrackingInternalConnection.java:62)
	at com.mongodb.connection.UsageTrackingInternalConnection$1.onResult(UsageTrackingInternalConnection.java:54)
	at com.mongodb.connection.InternalStreamConnection$1$1.onResult(InternalStreamConnection.java:155)
	at com.mongodb.connection.InternalStreamConnection$1$1.onResult(InternalStreamConnection.java:142)
	at com.mongodb.connection.InternalStreamConnectionInitializer$3.onResult(InternalStreamConnectionInitializer.java:146)
	at com.mongodb.connection.InternalStreamConnectionInitializer$3.onResult(InternalStreamConnectionInitializer.java:140)
	at com.mongodb.connection.CommandHelper$1$1.onResult(CommandHelper.java:53)
	at com.mongodb.connection.CommandHelper$1$1.onResult(CommandHelper.java:43)
	at com.mongodb.connection.CommandHelper$3.onResult(CommandHelper.java:155)
	at com.mongodb.connection.CommandHelper$3.onResult(CommandHelper.java:148)
	at com.mongodb.connection.InternalStreamConnection.executeCallbackAndReceiveResponse(InternalStreamConnection.java:375)
	at com.mongodb.connection.InternalStreamConnection.access$1700(InternalStreamConnection.java:65)
	at com.mongodb.connection.InternalStreamConnection$ResponseBuffersCallback.onResult(InternalStreamConnection.java:417)
	at com.mongodb.connection.InternalStreamConnection$ResponseBuffersCallback.onResult(InternalStreamConnection.java:386)
	at com.mongodb.connection.InternalStreamConnection$ResponseHeaderCallback.onSuccess(InternalStreamConnection.java:555)
	at com.mongodb.connection.InternalStreamConnection$ResponseHeaderCallback.access$2200(InternalStreamConnection.java:514)
	at com.mongodb.connection.InternalStreamConnection$ResponseHeaderCallback$ResponseBodyCallback.onResult(InternalStreamConnection.java:577)
	at com.mongodb.connection.InternalStreamConnection$ResponseHeaderCallback$ResponseBodyCallback.onResult(InternalStreamConnection.java:561)
	at com.mongodb.connection.InternalStreamConnection$3.completed(InternalStreamConnection.java:444)
	at com.mongodb.connection.InternalStreamConnection$3.completed(InternalStreamConnection.java:441)
	at com.mongodb.connection.AsynchronousSocketChannelStream$BasicCompletionHandler.completed(AsynchronousSocketChannelStream.java:221)
	at com.mongodb.connection.AsynchronousSocketChannelStream$BasicCompletionHandler.completed(AsynchronousSocketChannelStream.java:205)
	at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:126)
	at sun.nio.ch.Invoker.invokeDirect(Invoker.java:157)
	at sun.nio.ch.UnixAsynchronousSocketChannelImpl.implRead(UnixAsynchronousSocketChannelImpl.java:553)
	at sun.nio.ch.AsynchronousSocketChannelImpl.read(AsynchronousSocketChannelImpl.java:276)
	at sun.nio.ch.AsynchronousSocketChannelImpl.read(AsynchronousSocketChannelImpl.java:297)
	at com.mongodb.connection.AsynchronousSocketChannelStream.readAsync(AsynchronousSocketChannelStream.java:138)
	at com.mongodb.connection.InternalStreamConnection.readAsync(InternalStreamConnection.java:441)
	at com.mongodb.connection.InternalStreamConnection.access$2000(InternalStreamConnection.java:65)
	at com.mongodb.connection.InternalStreamConnection$ResponseHeaderCallback.onResult(InternalStreamConnection.java:537)
	at com.mongodb.connection.InternalStreamConnection$ResponseHeaderCallback.onResult(InternalStreamConnection.java:514)
	at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:53)
	at com.mongodb.connection.InternalStreamConnection$3.completed(InternalStreamConnection.java:444)
	at com.mongodb.connection.InternalStreamConnection$3.completed(InternalStreamConnection.java:441)
	at com.mongodb.connection.AsynchronousSocketChannelStream$BasicCompletionHandler.completed(AsynchronousSocketChannelStream.java:221)
	at com.mongodb.connection.AsynchronousSocketChannelStream$BasicCompletionHandler.completed(AsynchronousSocketChannelStream.java:205)
	at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:126)
	at sun.nio.ch.Invoker$2.run(Invoker.java:218)
	at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)

Comment by Ross Lawley [ 09/Sep/15 ]

Thanks jens.geiregat, could you also attach the logs for 10.0.22.5?

Comment by Jens Geiregat [ 09/Sep/15 ]

Attached log from one of the secondaries: 10.0.21.5. I snipped out some parts that mention internal names etc. But the useful information should still be there...

Comment by Ross Lawley [ 09/Sep/15 ]

Possibly related to JAVA-1944 - still awaiting feedback on that issue.

When running a simplified test program we were unable to reproduce (see Jeffs comment in JAVA-1944). Could you provide some sample code and check the status of your replicaSet for the time shown in the logs?

From the logs provided I can see the following chain of events:

  • 13:18:36.534 : connectionId{localValue:14, serverValue:983} relates to 10.0.21.5:27017 opened at:
  • 13:18:36.536 : A count command is issued to: connectionId{localValue:14, serverValue:983}
  • 13:18:36.538 : Command execution completed with status false
  • 13:18:36.545 : Updated cluster description - 10.0.21.5:27017 is now in an UNKNOWN state.
  • 13:18:36.545 : Closing connection connectionId {localValue:14, serverValue:983}
  • 13:18:36.550 : An error occurred com.mongodb.MongoNotPrimaryException

Ross

Comment by Ross Lawley [ 09/Sep/15 ]

Hi jens.geiregat do you have any of the MongoDB logs for this time period as well?

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