-
Type:
Bug
-
Resolution: Duplicate
-
Priority:
Major - P3
-
None
-
Affects Version/s: None
-
Component/s: Cluster Management, Error Handling
-
Labels:None
-
Environment:Running against MongoDB 3.0.9
My assumptions about how the (java) driver is modeled
Creating a MongoClient that connects to a replica set, a shared state object is created which contains all of the seeded/discovered members and the last known state of each member.
The state for each member is monitored by a thread e.g:
"cluster-ClusterId{value='57bdbb382f53757a079b2616', description='scrubbedReplName'}-scrubbedHostname:scrubbedPort" #96 daemon prio=5 os_prio=0 tid=0x00007f73cd07f800 nid=0x7a8a waiting on condition [0x00007f7321248000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000003c04d48e8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
at com.mongodb.connection.DefaultServerMonitor$ServerMonitorRunnable.waitForSignalOrTimeout(DefaultServerMonitor.java:238)
at com.mongodb.connection.DefaultServerMonitor$ServerMonitorRunnable.waitForNext(DefaultServerMonitor.java:219)
at com.mongodb.connection.DefaultServerMonitor$ServerMonitorRunnable.run(DefaultServerMonitor.java:168)
- locked <0x00000003c04d4408> (a com.mongodb.connection.DefaultServerMonitor$ServerMonitorRunnable)
at java.lang.Thread.run(Thread.java:745)
If one of those threads were to exit, that member's state would no longer be updated on replica set object's state.
What we observed
While our java application was running, the following log appeared:
2016-08-26T03:25:33.561+0000 [scrubbedThreadName] WARN org.mongodb.driver.connection [SLF4JLogger.java.warn:86] - Got socket exception on connection [connectionId{localValue:3565883, serverValue:689402}] to scubbedHostname:scrubbedPort. All connections to scrubbedHostname:scrubbedPort will be closed.
That was immediately followed by some threads receiving the error:
com.mongodb.MongoSocketReadException: Prematurely reached end of stream at com.mongodb.connection.SocketStream.read(SocketStream.java:88) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.connection.InternalStreamConnection.receiveResponseBuffers(InternalStreamConnection.java:491) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.connection.InternalStreamConnection.receiveMessage(InternalStreamConnection.java:221) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.connection.UsageTrackingInternalConnection.receiveMessage(UsageTrackingInternalConnection.java:102) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.connection.DefaultConnectionPool$PooledConnection.receiveMessage(DefaultConnectionPool.java:435) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.connection.QueryProtocol.execute(QueryProtocol.java:297) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.connection.QueryProtocol.execute(QueryProtocol.java:54) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:159) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:286) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.connection.DefaultServerConnection.query(DefaultServerConnection.java:209) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.operation.FindOperation$1.call(FindOperation.java:496) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.operation.FindOperation$1.call(FindOperation.java:482) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.operation.OperationHelper.withConnectionSource(OperationHelper.java:239) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:212) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.operation.FindOperation.execute(FindOperation.java:482) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.operation.FindOperation.execute(FindOperation.java:79) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.Mongo.execute(Mongo.java:772) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.Mongo$2.execute(Mongo.java:759) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.DBCursor.initializeCursor(DBCursor.java:851) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.DBCursor.hasNext(DBCursor.java:152) ~[mongo-java-driver-3.2.2.jar:na] at <ourcode> ~[classes/:na] java.lang.IllegalThreadStateException: null at java.lang.Thread.start(Thread.java:705) ~[na:1.8.0_25] at com.mongodb.connection.DefaultServerMonitor.invalidate(DefaultServerMonitor.java:88) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.connection.DefaultServer.invalidate(DefaultServer.java:120) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.connection.DefaultServer.handleThrowable(DefaultServer.java:150) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.connection.DefaultServer.access$500(DefaultServer.java:38) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:161) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:286) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.connection.DefaultServerConnection.query(DefaultServerConnection.java:209) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.operation.FindOperation$1.call(FindOperation.java:496) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.operation.FindOperation$1.call(FindOperation.java:482) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.operation.OperationHelper.withConnectionSource(OperationHelper.java:239) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:212) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.operation.FindOperation.execute(FindOperation.java:482) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.operation.FindOperation.execute(FindOperation.java:79) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.Mongo.execute(Mongo.java:772) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.Mongo$2.execute(Mongo.java:759) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.DBCursor.initializeCursor(DBCursor.java:851) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.DBCursor.hasNext(DBCursor.java:152) ~[mongo-java-driver-3.2.2.jar:na] at <our code> com.mongodb.MongoSocketReadException: Prematurely reached end of stream at com.mongodb.connection.SocketStream.read(SocketStream.java:88) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.connection.InternalStreamConnection.receiveResponseBuffers(InternalStreamConnection.java:491) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.connection.InternalStreamConnection.receiveMessage(InternalStreamConnection.java:221) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.connection.UsageTrackingInternalConnection.receiveMessage(UsageTrackingInternalConnection.java:102) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.connection.DefaultConnectionPool$PooledConnection.receiveMessage(DefaultConnectionPool.java:435) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.connection.QueryProtocol.execute(QueryProtocol.java:297) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.connection.QueryProtocol.execute(QueryProtocol.java:54) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:159) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:286) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.connection.DefaultServerConnection.query(DefaultServerConnection.java:209) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.operation.FindOperation$1.call(FindOperation.java:496) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.operation.FindOperation$1.call(FindOperation.java:482) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.operation.OperationHelper.withConnectionSource(OperationHelper.java:239) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:212) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.operation.FindOperation.execute(FindOperation.java:482) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.operation.FindOperation.execute(FindOperation.java:79) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.Mongo.execute(Mongo.java:772) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.Mongo$2.execute(Mongo.java:759) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.DBCursor.initializeCursor(DBCursor.java:851) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.DBCursor.hasNext(DBCursor.java:152) ~[mongo-java-driver-3.2.2.jar:na] at <our code> java.lang.IllegalThreadStateException: null at java.lang.Thread.start(Thread.java:705) ~[na:1.8.0_25] at com.mongodb.connection.DefaultServerMonitor.invalidate(DefaultServerMonitor.java:88) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.connection.DefaultServer.invalidate(DefaultServer.java:120) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.connection.DefaultServer.handleThrowable(DefaultServer.java:150) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.connection.DefaultServer.access$500(DefaultServer.java:38) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:161) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:286) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.connection.DefaultServerConnection.query(DefaultServerConnection.java:209) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.operation.FindOperation$1.call(FindOperation.java:496) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.operation.FindOperation$1.call(FindOperation.java:482) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.operation.OperationHelper.withConnectionSource(OperationHelper.java:239) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:212) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.operation.FindOperation.execute(FindOperation.java:482) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.operation.FindOperation.execute(FindOperation.java:79) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.Mongo.execute(Mongo.java:772) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.Mongo$2.execute(Mongo.java:759) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.DBCursor.initializeCursor(DBCursor.java:851) ~[mongo-java-driver-3.2.2.jar:na] at com.mongodb.DBCursor.hasNext(DBCursor.java:152) ~[mongo-java-driver-3.2.2.jar:na] at <our code>
Subsequent attempts to reach the primary resulted in the following:
com.mongodb.MongoTimeoutException: Timed out after 30000 ms while waiting for a server that matches WritableServerSelector. Client view of cluster state is {type=REPLICA_SET, servers=[{address=scrubbedProblemHost:scrubbedPort, type=UNKNOWN, state=CONNECTING}, {address=scrubbedArbiter, type=REPLICA_SET_ARBITER, roundTripTime=7.8 ms, state=CONNECTED}, {address=scrubbedWorkingHost, type=REPLICA_SET_SECONDARY, roundTripTime=1.0 ms, state=CONNECTED}, {address=scrubbedWorkingHost, type=REPLICA_SET_SECONDARY, roundTripTime=0.9 ms, state=CONNECTED}]
at com.mongodb.connection.BaseCluster.createTimeoutException(BaseCluster.java:369) ~[mongo-java-driver-3.2.2.jar:na]
at com.mongodb.connection.BaseCluster.selectServer(BaseCluster.java:101) ~[mongo-java-driver-3.2.2.jar:na]
at com.mongodb.binding.ClusterBinding$ClusterBindingConnectionSource.<init>(ClusterBinding.java:75) ~[mongo-java-driver-3.2.2.jar:na]
at com.mongodb.binding.ClusterBinding$ClusterBindingConnectionSource.<init>(ClusterBinding.java:71) ~[mongo-java-driver-3.2.2.jar:na]
at com.mongodb.binding.ClusterBinding.getWriteConnectionSource(ClusterBinding.java:68) ~[mongo-java-driver-3.2.2.jar:na]
at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:219) ~[mongo-java-driver-3.2.2.jar:na]
at com.mongodb.operation.CreateIndexesOperation.execute(CreateIndexesOperation.java:111) ~[mongo-java-driver-3.2.2.jar:na]
at com.mongodb.operation.CreateIndexesOperation.execute(CreateIndexesOperation.java:66) ~[mongo-java-driver-3.2.2.jar:na]
at com.mongodb.Mongo.execute(Mongo.java:781) ~[mongo-java-driver-3.2.2.jar:na]
at com.mongodb.Mongo$2.execute(Mongo.java:764) ~[mongo-java-driver-3.2.2.jar:na]
at com.mongodb.DBCollection.createIndex(DBCollection.java:1541) ~[mongo-java-driver-3.2.2.jar:na]
Server logs at the time of the first error shows:
2016-08-26T03:25:26.527+0000 I QUERY [conn689402] assertion 13435 not master and slaveOk=false <query information> 2016-08-26T03:25:26.528+0000 I NETWORK [conn689402] SocketException handling request, closing client connection: 9001 socket exception [SEND_ERROR] server [10.20.0.204:48093]
Before restarting the application we got a thread dump which does not seem to show any threads for the problem host. We're conjecturing that server monitoring thread allowed an exception to escape, causing it to die and it was not replaced.
I can provide fuller logs upon request.
- duplicates
-
-
- Closed
-